diff --git a/.github/workflows/memory-diff.yml b/.github/workflows/memory-diff.yml index d56aba108..766e178a8 100644 --- a/.github/workflows/memory-diff.yml +++ b/.github/workflows/memory-diff.yml @@ -77,17 +77,17 @@ jobs: - name: Checkout base branch into side worktree run: | - # Stash the memory_diff helpers so the worktree still has them if - # the base branch predates this commit. The helpers are standalone - # scripts so this is safe. + # Stash the memory_diff helpers from the PR and use the same helper + # version for both measurements. The helper is measurement tooling; + # using the base branch's older helper can make the diff compare two + # different sampling methods (for example base top-20 vs PR top-500). mkdir -p /tmp/memdiff-scripts cp scripts/memory_diff.py /tmp/memdiff-scripts/ cp scripts/format_memory_diff.py /tmp/memdiff-scripts/ git worktree add --detach /tmp/base-tree "origin/${{ github.base_ref }}" - if [ ! -f /tmp/base-tree/scripts/memory_diff.py ]; then - echo "Base branch does not have memory_diff.py yet — copying from PR" - cp /tmp/memdiff-scripts/memory_diff.py /tmp/base-tree/scripts/ - fi + mkdir -p /tmp/base-tree/scripts + cp /tmp/memdiff-scripts/memory_diff.py /tmp/base-tree/scripts/ + cp /tmp/memdiff-scripts/format_memory_diff.py /tmp/base-tree/scripts/ - name: Measure base branch startup env: diff --git a/pytest.ini b/pytest.ini index 33822b95b..6ea718761 100644 --- a/pytest.ini +++ b/pytest.ini @@ -7,6 +7,7 @@ addopts = filterwarnings = ignore::DeprecationWarning markers = + flaky: rerun integration tests that are timing-sensitive in browser or device-adjacent flows integration: mark integration tests that may require browser automation or slower flows plugin_sweep: click-sweep parametrized over every registered plugin (JTN-698). Runs a bounded set of clicks against /plugin/ for each plugin to catch handler regressions. CI may route this to a dedicated job if runtime grows. journey: multi-step user-journey tests (JTN-719 epic). Each test drives a full end-to-end flow (e.g. first-run setup, edit settings, recover from error) with step-level assertions, going beyond the click-sweep's "handlers fire without error" guarantee. Gated by SKIP_BROWSER/SKIP_UI. diff --git a/scripts/format_memory_diff.py b/scripts/format_memory_diff.py index 9e25e45c1..76b72fcf2 100644 --- a/scripts/format_memory_diff.py +++ b/scripts/format_memory_diff.py @@ -27,10 +27,11 @@ # workflow that looks for it. STICKY_MARKER = "" -# Delta (in bytes) above which we flag a row with a warning emoji. 1 MiB is a -# reasonable "noticeable but not alarming" threshold on the Pi Zero 2 W -# envelope (total budget is 200 MB idle). -WARN_DELTA_BYTES = 1 * 1024 * 1024 +# Delta (in bytes) above which we flag a row with a warning emoji. Keep this +# high enough that allocator arena churn does not turn the whole table yellow. +WARN_DELTA_BYTES = 5 * 1024 * 1024 +DETAIL_DELTA_FLOOR_BYTES = 256 * 1024 +GROUP_TOP_N = 10 def _fmt_bytes(n: int) -> str: @@ -74,6 +75,45 @@ def _short_location(loc: str, max_len: int = 60) -> str: return tail.replace("|", "\\|") +def _location_group(loc: str) -> str: + """Return a reviewer-friendly bucket for a source allocator location.""" + if not loc: + return "" + normalized = loc.replace("\\", "/") + if normalized.startswith(""): + return "profile harness" + if normalized.startswith(" bool: + """Drop profiler-wrapper rows that are not actionable app attribution.""" + loc = str(entry.get("location", "")) + return not loc.startswith("") + + def _load(path: Path) -> dict: """Load a JSON summary, returning an empty shell if the file is missing. @@ -135,6 +175,31 @@ def _merge_allocators(base: list[dict], pr: list[dict]) -> list[dict]: return rows +def _merge_allocator_groups(base: list[dict], pr: list[dict]) -> list[dict]: + """Aggregate allocator rows into package/module buckets before diffing.""" + index: dict[str, dict] = {} + for side, entries in (("base_bytes", base), ("pr_bytes", pr)): + for entry in entries: + group = _location_group(str(entry.get("location", ""))) + bucket = index.setdefault( + group, + {"location": group, "base_bytes": 0, "pr_bytes": 0}, + ) + bucket[side] += int(entry.get("bytes", 0)) + rows = list(index.values()) + for row in rows: + row["delta"] = row["pr_bytes"] - row["base_bytes"] + rows.sort(key=lambda r: abs(r["delta"]), reverse=True) + return rows + + +def _significant_rows(rows: list[dict], top: int) -> list[dict]: + """Return rows worth showing, suppressing zero-delta allocator noise.""" + return [ + row for row in rows if abs(int(row.get("delta", 0))) >= DETAIL_DELTA_FLOOR_BYTES + ][:top] + + def format_comment(base: dict, pr: dict, top: int = 20) -> str: """Build the full Markdown comment body. @@ -157,10 +222,31 @@ def format_comment(base: dict, pr: dict, top: int = 20) -> str: pr_mods = int(pr.get("module_count", 0) or 0) mod_delta = pr_mods - base_mods - rows = _merge_allocators( - list(base.get("allocators", [])), - list(pr.get("allocators", [])), - )[:top] + base_allocators = [ + entry + for entry in list(base.get("allocators", [])) + if _is_displayable_allocator(entry) + ] + pr_allocators = [ + entry + for entry in list(pr.get("allocators", [])) + if _is_displayable_allocator(entry) + ] + rows = _significant_rows(_merge_allocators(base_allocators, pr_allocators), top) + group_rows = _significant_rows( + _merge_allocator_groups(base_allocators, pr_allocators), + GROUP_TOP_N, + ) + base_sample_count = int( + base.get("allocator_sample_limit") + or base.get("sampled_allocator_count") + or len(base_allocators) + ) + pr_sample_count = int( + pr.get("allocator_sample_limit") + or pr.get("sampled_allocator_count") + or len(pr_allocators) + ) lines: list[str] = [] lines.append(STICKY_MARKER) @@ -190,15 +276,41 @@ def format_comment(base: dict, pr: dict, top: int = 20) -> str: ) lines.append("") + lines.append("### Largest grouped allocator deltas") + lines.append("") + lines.append("| Group | Base | PR | Delta |") + lines.append("|---|---|---|---|") + if not group_rows: + lines.append("| _(no significant grouped allocator deltas)_ | — | — | — |") + else: + lines.extend( + ( + f"| `{row['location']}` " + f"| {_fmt_bytes(row['base_bytes'])} " + f"| {_fmt_bytes(row['pr_bytes'])} " + f"| {_fmt_delta(row['delta'])} |" + ) + for row in group_rows + ) + lines.append("") + # Collapse the long allocator table by default so the PR conversation # stays skimmable. GitHub renders
nicely in comments. lines.append("
") - lines.append(f"Top {len(rows)} startup allocators") + detail_summary = ( + f"Source-location detail: top {len(rows)} deltas" + if rows + else "Source-location detail: no significant deltas" + ) + lines.append( + f"{detail_summary} " + f"(sampled base={base_sample_count}, PR={pr_sample_count})" + ) lines.append("") lines.append("| # | Location | Base | PR | Delta |") lines.append("|---|---|---|---|---|") if not rows: - lines.append("| — | _(no allocators sampled)_ | — | — | — |") + lines.append("| — | _(no significant source-location deltas)_ | — | — | — |") else: for i, row in enumerate(rows, 1): lines.append( @@ -213,7 +325,8 @@ def format_comment(base: dict, pr: dict, top: int = 20) -> str: lines.append( f"JTN-610 · backend=base:{base_backend}, pr:{pr_backend} · " "informational only, does not block merge. Hard RSS budgets are enforced " - "separately by JTN-608." + "separately by JTN-608. Source-location rows are sampled allocator " + "attribution, not exact module ownership." ) return "\n".join(lines) + "\n" diff --git a/scripts/memory_diff.py b/scripts/memory_diff.py index 3ad1c1129..1dd8ded7b 100644 --- a/scripts/memory_diff.py +++ b/scripts/memory_diff.py @@ -49,9 +49,10 @@ REPO_ROOT = Path(__file__).resolve().parent.parent SRC_DIR = REPO_ROOT / "src" -# Cap on how many allocators we surface in the diff comment. Matches the -# acceptance criteria in JTN-610 ("top 20 allocators"). -TOP_N = 20 +# Capture more than the comment displays. Comparing only each side's top 20 +# makes the diff lie with "0 B" whenever a location merely fell out of the +# other side's top 20. The formatter still keeps the PR comment short. +DEFAULT_ALLOCATOR_SAMPLE_LIMIT = 500 def _startup_env() -> dict[str, str]: @@ -62,25 +63,58 @@ def _startup_env() -> dict[str, str]: checks. ``INKYPI_NO_REFRESH=1`` keeps plugin side-effects quiet. """ env = os.environ.copy() - env["PYTHONPATH"] = str(SRC_DIR) + existing_pythonpath = env.get("PYTHONPATH") + env["PYTHONPATH"] = ( + str(SRC_DIR) + if not existing_pythonpath + else str(SRC_DIR) + os.pathsep + existing_pythonpath + ) env["INKYPI_ENV"] = "dev" env["INKYPI_NO_REFRESH"] = "1" env["PYTHONWARNINGS"] = "ignore" return env -def _read_rss_bytes() -> int: - """Best-effort RSS read — returns 0 when psutil/resource are unavailable.""" - try: - import resource # noqa: PLC0415 — stdlib, Linux/macOS only +def _run_plain_import_stats() -> dict[str, int]: + """Measure RSS and module count in a plain child process. + + Keep this separate from memray/tracemalloc. Profilers add their own import + and allocation overhead, which makes the summary row look precise while + measuring the tool rather than InkyPi startup. + """ + code = textwrap.dedent(""" + import json + import resource + import sys + + import inkypi # noqa: F401 rusage = resource.getrusage(resource.RUSAGE_SELF) - # Linux reports ru_maxrss in kilobytes; macOS reports in bytes. - if sys.platform == "darwin": - return int(rusage.ru_maxrss) - return int(rusage.ru_maxrss) * 1024 - except Exception: - return 0 + rss = int(rusage.ru_maxrss) + if sys.platform != "darwin": + rss *= 1024 + + print(json.dumps({ + "module_count": len(sys.modules), + "total_rss_bytes": rss, + })) + """) + proc = subprocess.run( # noqa: S603 — fixed argv + [sys.executable, "-c", code], + env=_startup_env(), + capture_output=True, + text=True, + timeout=60, + check=False, + ) + if proc.returncode != 0: + return {"module_count": 0, "total_rss_bytes": 0} + last = [line for line in proc.stdout.splitlines() if line.strip()][-1] + raw = json.loads(last) + return { + "module_count": int(raw.get("module_count", 0) or 0), + "total_rss_bytes": int(raw.get("total_rss_bytes", 0) or 0), + } def _run_tracemalloc() -> dict: @@ -96,24 +130,16 @@ def _run_tracemalloc() -> dict: snapshot = tracemalloc.take_snapshot() stats = snapshot.statistics("filename") allocators = [ - {"location": str(s.traceback[0]), "bytes": int(s.size)} - for s in stats[:100] + {{"location": str(s.traceback[0]), "bytes": int(s.size)}} + for s in stats[:{limit}] ] - # Best-effort RSS — tracemalloc size is the tracked Python heap, not RSS. - rss = 0 - try: - import resource - r = resource.getrusage(resource.RUSAGE_SELF) - rss = r.ru_maxrss * (1 if sys.platform == "darwin" else 1024) - except Exception: - pass - print(json.dumps({ + print(json.dumps({{ "backend": "tracemalloc", - "total_rss_bytes": rss, - "module_count": len(sys.modules), + "total_rss_bytes": 0, + "module_count": 0, "allocators": allocators, - })) - """) + }})) + """).format(limit=DEFAULT_ALLOCATOR_SAMPLE_LIMIT) proc = subprocess.run( # noqa: S603 — trusted stdlib-only snippet [sys.executable, "-c", code], env=_startup_env(), @@ -130,7 +156,9 @@ def _run_tracemalloc() -> dict: # The subprocess may emit warnings / log lines before the JSON; take the # last non-empty line. last = [line for line in proc.stdout.splitlines() if line.strip()][-1] - return json.loads(last) + result = json.loads(last) + result.update(_run_plain_import_stats()) + return result def _run_memray() -> dict: @@ -210,32 +238,15 @@ def _run_memray() -> dict: {"location": loc, "bytes": total} for loc, total in sorted( by_location.items(), key=lambda kv: kv[1], reverse=True - )[:100] + ) ] - # Also count modules loaded after import to feed the summary row. - module_code = textwrap.dedent(""" - import json, sys - import inkypi # noqa: F401 - print(json.dumps({"count": len(sys.modules)})) - """) - mod_proc = subprocess.run( # noqa: S603 — fixed argv - [sys.executable, "-c", module_code], - env=_startup_env(), - capture_output=True, - text=True, - timeout=60, - check=False, - ) - module_count = 0 - if mod_proc.returncode == 0: - last = [line for line in mod_proc.stdout.splitlines() if line.strip()][-1] - module_count = int(json.loads(last)["count"]) + plain_stats = _run_plain_import_stats() return { "backend": "memray", - "total_rss_bytes": _read_rss_bytes(), - "module_count": module_count, + "total_rss_bytes": plain_stats["total_rss_bytes"], + "module_count": plain_stats["module_count"], "allocators": allocators, } @@ -284,8 +295,12 @@ def main(argv: list[str] | None = None) -> int: parser.add_argument( "--top", type=int, - default=TOP_N, - help="Number of top allocators to keep in the output JSON.", + default=DEFAULT_ALLOCATOR_SAMPLE_LIMIT, + help=( + "Number of top allocators to keep in the output JSON. Keep this " + "larger than the comment display limit so base/PR comparison is " + "not distorted by top-N truncation." + ), ) args = parser.parse_args(argv) @@ -309,13 +324,17 @@ def main(argv: list[str] | None = None) -> int: else: result = _run_tracemalloc() - # Trim to the top-N allocators by bytes before writing. + # Trim to the sampled allocator limit before writing. The formatter applies + # its own smaller display limit after merging base + PR locations. + sampled_allocator_count = len(result.get("allocators", [])) allocators = sorted( result.get("allocators", []), key=lambda a: int(a.get("bytes", 0)), reverse=True, )[: args.top] result["allocators"] = allocators + result["sampled_allocator_count"] = sampled_allocator_count + result["allocator_sample_limit"] = args.top out_path = Path(args.output) out_path.parent.mkdir(parents=True, exist_ok=True) diff --git a/src/app_setup/logging_setup.py b/src/app_setup/logging_setup.py index 7cda52bb5..882749634 100644 --- a/src/app_setup/logging_setup.py +++ b/src/app_setup/logging_setup.py @@ -17,9 +17,11 @@ import logging.config import logging.handlers import os +import time from typing import NamedTuple +from zoneinfo import ZoneInfo, ZoneInfoNotFoundError -from utils.logging_utils import SecretRedactionFilter +from utils.logging_utils import SecretRedactionFilter, set_log_timezone _LOGGING_CONF_PATH = os.path.join( os.path.dirname(os.path.dirname(__file__)), "config", "logging.conf" @@ -35,12 +37,51 @@ class RotationConfig(NamedTuple): formatter: str +class ExpectedSSEDisconnectFilter(logging.Filter): + """Drop normal browser disconnect chatter from Waitress SSE streams.""" + + _PATHS = ("/api/events", "/api/progress/stream") + + def filter(self, record: logging.LogRecord) -> bool: + message = record.getMessage() + if "Client disconnected while serving" not in message: + return True + return not any(path in message for path in self._PATHS) + + def use_json_logging() -> bool: """Return True when INKYPI_LOG_FORMAT=json is set.""" fmt = (os.getenv("INKYPI_LOG_FORMAT") or "").strip().lower() return fmt == "json" +def configure_log_timezone(tz_name: str | None) -> None: + """Align process and structured-log timestamps with the device timezone.""" + try: + ZoneInfo(str(tz_name)) if tz_name else ZoneInfo("UTC") + except (ZoneInfoNotFoundError, ValueError): + set_log_timezone("UTC") + os.environ["TZ"] = "UTC" + if hasattr(time, "tzset"): + time.tzset() + return + + selected = str(tz_name or "UTC") + set_log_timezone(selected) + os.environ["TZ"] = selected + if hasattr(time, "tzset"): + time.tzset() + + +def install_waitress_disconnect_filter() -> None: + """Suppress expected SSE client-close lines from the Waitress logger.""" + waitress_logger = logging.getLogger("waitress") + if not any( + isinstance(f, ExpectedSSEDisconnectFilter) for f in waitress_logger.filters + ): + waitress_logger.addFilter(ExpectedSSEDisconnectFilter()) + + def read_rotation_config(conf_path: str = _LOGGING_CONF_PATH) -> RotationConfig: """Parse [rotating_file] from logging.conf and return rotation params. @@ -154,6 +195,7 @@ def setup_logging() -> None: # Attach the secret-redaction filter to the root logger so it applies to # ALL handlers (console, file, dev-mode buffer) and both log formats. logging.getLogger().addFilter(SecretRedactionFilter()) + install_waitress_disconnect_filter() # Optional rotating file output — only attached when an explicit path is # provided via env var, preserving the default console-only behavior. diff --git a/src/blueprints/settings/__init__.py b/src/blueprints/settings/__init__.py index a789c42f8..50b13a367 100644 --- a/src/blueprints/settings/__init__.py +++ b/src/blueprints/settings/__init__.py @@ -17,6 +17,7 @@ ) from utils.http_utils import http_get +from utils.logging_utils import log_datetime_from_timestamp from utils.progress_events import get_progress_bus from utils.rate_limiter import CooldownLimiter, SlidingWindowLimiter from utils.time_utils import get_timezone, now_device_tz @@ -180,7 +181,7 @@ class DevModeLogHandler(logging.Handler): def emit(self, record: logging.LogRecord) -> None: try: msg = self.format(record) - timestamp = datetime.fromtimestamp(record.created, tz=UTC).strftime( + timestamp = log_datetime_from_timestamp(record.created).strftime( LOG_TIMESTAMP_FORMAT ) log_line = f"{timestamp} [{record.levelname}] {record.name}: {msg}" @@ -214,6 +215,14 @@ def _format_journal_line(formatted_ts: str, data: dict[str, Any]) -> str: return f"{formatted_ts} [{level}] {msg}" +def _device_log_timezone() -> Any: + try: + device_config = current_app.config["DEVICE_CONFIG"] + return get_timezone(device_config.get_config("timezone", default="UTC")) + except Exception: + return get_timezone("UTC") + + def _read_log_lines(hours: int) -> list[str]: """Read service logs for the last N hours and return as list of formatted lines.""" # Use device timezone for consistency in all time computations @@ -247,6 +256,8 @@ def _read_log_lines(hours: int) -> list[str]: lines.append("(No logs captured in buffer yet)") return lines + log_tz = _device_log_timezone() + # Journal available path reader = JournalReader() try: @@ -259,7 +270,9 @@ def _read_log_lines(hours: int) -> list[str]: timestamp = datetime.fromtimestamp( record.get_realtime_usec() / 1_000_000, tz=UTC ) - formatted_ts = timestamp.strftime(LOG_TIMESTAMP_FORMAT) + formatted_ts = timestamp.astimezone(log_tz).strftime( + LOG_TIMESTAMP_FORMAT + ) except Exception: formatted_ts = "??? ?? ??:??:??" @@ -304,6 +317,7 @@ def _read_units_log_lines(hours: int, units: list[str]) -> list[str]: dev_lines.append("(No logs captured in buffer yet)") return dev_lines + log_tz = _device_log_timezone() merged: list[tuple[float, str]] = [] reader = JournalReader() try: @@ -317,7 +331,7 @@ def _read_units_log_lines(hours: int, units: list[str]) -> list[str]: continue ts_usec = record.get_realtime_usec() log_ts = datetime.fromtimestamp(ts_usec / 1_000_000, tz=UTC) - formatted_ts = log_ts.strftime(LOG_TIMESTAMP_FORMAT) + formatted_ts = log_ts.astimezone(log_tz).strftime(LOG_TIMESTAMP_FORMAT) line = _format_journal_line(formatted_ts, data) merged.append((log_ts.timestamp(), line)) except Exception: diff --git a/src/blueprints/settings/_config.py b/src/blueprints/settings/_config.py index b381bd143..441f63280 100644 --- a/src/blueprints/settings/_config.py +++ b/src/blueprints/settings/_config.py @@ -7,6 +7,7 @@ from flask import current_app, redirect, render_template, request import blueprints.settings as _mod +from app_setup.logging_setup import configure_log_timezone from utils.backend_errors import ClientInputError, route_error_boundary from utils.http_utils import json_error, json_success from utils.time_utils import calculate_seconds @@ -617,6 +618,7 @@ def save_settings() -> Any: form_data, normalized_device_name ) device_config.update_config(settings) + configure_log_timezone(settings.get("timezone")) if plugin_cycle_interval_seconds != previous_interval_seconds: # wake the background thread up to signal interval config change diff --git a/src/inkypi.py b/src/inkypi.py index c59f0085c..281419a0c 100755 --- a/src/inkypi.py +++ b/src/inkypi.py @@ -29,7 +29,11 @@ register_health_endpoints as _register_health_endpoints, ) from app_setup.http_metrics import setup_http_metrics -from app_setup.logging_setup import install_dev_log_handler, setup_logging +from app_setup.logging_setup import ( + configure_log_timezone, + install_dev_log_handler, + setup_logging, +) from app_setup.schema_validator import register as register_schema_validator from app_setup.security_middleware import ( _extract_csrf_token_from_request, @@ -339,6 +343,7 @@ def _init_core_services(app: Flask) -> Config: except ConfigValidationError as exc: logger.error("Config invalid: %s", exc) raise SystemExit(1) from exc + configure_log_timezone(device_config.get_config("timezone", default="UTC")) display_manager = DisplayManager(device_config) refresh_task = RefreshTask(device_config, display_manager) diff --git a/src/services/playlist_workflows.py b/src/services/playlist_workflows.py index 5829498f2..6be2accdf 100644 --- a/src/services/playlist_workflows.py +++ b/src/services/playlist_workflows.py @@ -182,6 +182,28 @@ def validate_plugin_settings_security( device_config: Any, plugin_id: str, plugin_settings: dict[str, Any] ) -> WorkflowError | None: """Run plugin-specific validation for settings that are about to be added.""" + if plugin_id == "ai_image": + provider = str(plugin_settings.get("provider") or "openai").strip().lower() + required_key = { + "openai": ("OpenAI", "OPEN_AI_SECRET"), + "google": ("Google", "GOOGLE_AI_SECRET"), + }.get(provider) + if required_key is not None: + service_name, env_key = required_key + try: + if device_config.load_env_key(env_key) is None: + return WorkflowError( + f"{service_name} AI API Key not configured.", + status=400, + field="provider", + ) + except Exception: + logger.debug( + "Could not validate AI image provider key for %s", + sanitize_log_field(provider), + exc_info=True, + ) + if not plugin_settings: return None plugin_config = None diff --git a/src/static/scripts/plugin_schema.js b/src/static/scripts/plugin_schema.js index 61354af97..dcb0ca8d3 100644 --- a/src/static/scripts/plugin_schema.js +++ b/src/static/scripts/plugin_schema.js @@ -183,6 +183,23 @@ button.addEventListener("click", async () => { const provider = document.querySelector("[name='provider']")?.value || "openai"; + const services = window.__INKYPI_PLUGIN_BOOT__?.apiKeyServices || []; + if (Array.isArray(services) && services.length) { + const providerName = provider === "google" ? "Google" : "OpenAI"; + const providerKeyLabel = provider === "google" ? "Google AI" : "OpenAI"; + const service = services.find( + (item) => String(item?.name || "").toLowerCase() === providerName.toLowerCase() + ); + if (service && !service.present) { + if (window.showResponseModal) { + window.showResponseModal( + "failure", + `${providerKeyLabel} API Key not configured.` + ); + } + return; + } + } const originalText = button.textContent; button.disabled = true; button.textContent = "Thinking..."; diff --git a/src/templates/base.html b/src/templates/base.html index aaa86e2e3..20eddd6ed 100644 --- a/src/templates/base.html +++ b/src/templates/base.html @@ -5,6 +5,31 @@ {% block title %}InkyPi{% endblock %} + {% if bundled_assets_enabled %} diff --git a/src/templates/plugin.html b/src/templates/plugin.html index ab5eb9102..1837b0a02 100644 --- a/src/templates/plugin.html +++ b/src/templates/plugin.html @@ -506,6 +506,7 @@

Leave page? Unsaved changes will be lost

refreshInfoUrl: {{ url_for("main.refresh_info") | tojson }}, resolution: {{ resolution | tojson }}, styleSettings: {{ style_settings | default(false) | tojson }}, + apiKeyServices: {{ (api_key.services if api_key is defined and api_key and api_key.services else []) | tojson }}, urls: { add_to_playlist: {{ url_for('playlist.add_plugin') | tojson }}, random_prompt: {{ url_for("plugin.ai_image_random_prompt") | tojson }}, diff --git a/src/utils/logging_utils.py b/src/utils/logging_utils.py index 1ac1c1094..c3758c96e 100644 --- a/src/utils/logging_utils.py +++ b/src/utils/logging_utils.py @@ -12,8 +12,9 @@ import json import logging import re -from datetime import UTC, datetime +from datetime import UTC, datetime, tzinfo from typing import Any +from zoneinfo import ZoneInfo, ZoneInfoNotFoundError # All keys that exist on a bare LogRecord. Extras are anything in # record.__dict__ that is NOT in this set and does NOT start with "_". @@ -46,6 +47,7 @@ _REDACTED = "***REDACTED***" +_LOG_TIMEZONE: tzinfo = UTC # Sensitive key names used in pattern 0. _SECRET_KEY_NAMES = r"api[_-]?key|token|password|secret|pin" @@ -91,6 +93,26 @@ def redact_secrets(value: object) -> str: return _redact(value if isinstance(value, str) else str(value)) +def set_log_timezone(tz_name: str | None) -> tzinfo: + """Set the timezone used by structured log timestamps. + + Plain-text logging uses the process ``TZ`` setting configured in + ``app_setup.logging_setup``. JSON logs do their own timestamp formatting, + so they keep a small module-level timezone instead. + """ + global _LOG_TIMEZONE + try: + _LOG_TIMEZONE = ZoneInfo(str(tz_name)) if tz_name else UTC + except (ZoneInfoNotFoundError, ValueError): + _LOG_TIMEZONE = UTC + return _LOG_TIMEZONE + + +def log_datetime_from_timestamp(created: float) -> datetime: + """Return a log timestamp in the configured device timezone.""" + return datetime.fromtimestamp(created, tz=_LOG_TIMEZONE) + + def _redact_value(value: object) -> object: """Redact *value* if it is a string; leave all other types untouched.""" if isinstance(value, str): @@ -171,7 +193,7 @@ def format(self, record: logging.LogRecord) -> str: # ------------------------------------------------------------------ def _build_payload(self, record: logging.LogRecord) -> dict[str, Any]: - ts = datetime.fromtimestamp(record.created, tz=UTC).isoformat() + ts = log_datetime_from_timestamp(record.created).isoformat() payload: dict[str, Any] = { "ts": ts, diff --git a/tests/integration/test_time_freeze.py b/tests/integration/test_time_freeze.py index e6113091a..986d5259e 100644 --- a/tests/integration/test_time_freeze.py +++ b/tests/integration/test_time_freeze.py @@ -130,3 +130,47 @@ def __iter__(self): expected_usec = int(since_et * 1_000_000) assert captured["since_usec"] == expected_usec + + +def test_logs_api_formats_journal_timestamps_in_device_timezone( + client, flask_app, monkeypatch +): + dc = flask_app.config["DEVICE_CONFIG"] + dc.update_value("timezone", "America/Los_Angeles", write=True) + + import blueprints.settings as settings_mod + + class FakeRecord: + data = {"PRIORITY": "6", "MESSAGE": "hello from journal"} + + def get_realtime_usec(self): + return 1735693200 * 1_000_000 # 2025-01-01T01:00:00Z + + class FakeJR: + def open(self, mode): + return None + + def add_filter(self, rule): + return None + + def seek_realtime_usec(self, usec): + return None + + def __iter__(self): + return iter([FakeRecord()]) + + def close(self): + return None + + monkeypatch.setattr(settings_mod, "JOURNAL_AVAILABLE", True, raising=True) + monkeypatch.setattr(settings_mod, "JournalReader", FakeJR, raising=True) + monkeypatch.setattr( + settings_mod, "JournalOpenMode", type("M", (), {"SYSTEM": object()}) + ) + monkeypatch.setattr(settings_mod, "Rule", lambda *a, **k: (a, k)) + + resp = client.get("/api/logs?hours=2") + + assert resp.status_code == 200 + lines = resp.get_json()["lines"] + assert lines == ["Dec 31 17:00:00 [INFO] hello from journal"] diff --git a/tests/static/test_js_api_contracts.py b/tests/static/test_js_api_contracts.py index 9f0b776a6..852fcd91b 100644 --- a/tests/static/test_js_api_contracts.py +++ b/tests/static/test_js_api_contracts.py @@ -109,6 +109,24 @@ def test_enhanced_progress_script_exists(client): assert "enhanced-progress-log" in js +def test_plugin_and_playlist_progress_keep_ms_metric_labels(client): + """Progress summaries keep millisecond timing labels visible in the UI.""" + plugin_resp = client.get("/static/scripts/plugin_form.js") + playlist_resp = client.get("/static/scripts/playlist/progress.js") + assert plugin_resp.status_code == 200 + assert playlist_resp.status_code == 200 + + plugin_js = plugin_resp.get_data(as_text=True) + playlist_js = playlist_resp.get_data(as_text=True) + + assert "fmtElapsed(elapsedMs)" in plugin_js + assert "${step.elapsed_ms} ms" in plugin_js + assert "${label} ${val} ms" in plugin_js + assert "formatElapsed(Date.now() - startedAt)" in playlist_js + assert "${name} ${ms} ms" in playlist_js + assert "${label} ${value} ms" in playlist_js + + # --- Icons Loader --- diff --git a/tests/static/test_theme_bootstrap.py b/tests/static/test_theme_bootstrap.py new file mode 100644 index 000000000..db739db5a --- /dev/null +++ b/tests/static/test_theme_bootstrap.py @@ -0,0 +1,28 @@ +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[2] +BASE_HTML = ROOT / "src" / "templates" / "base.html" +PLUGIN_HTML = ROOT / "src" / "templates" / "plugin.html" +PLUGIN_SCHEMA_JS = ROOT / "src" / "static" / "scripts" / "plugin_schema.js" + + +def test_base_inlines_theme_and_tweaks_before_css() -> None: + html = BASE_HTML.read_text(encoding="utf-8") + + inline_theme = html.index('localStorage.getItem("theme")') + stylesheet = html.index('rel="stylesheet"') + + assert inline_theme < stylesheet + assert "inkypi_tweaks_v1" in html + assert 'root.setAttribute("data-aesthetic"' in html + assert 'root.style.setProperty("--accent"' in html + + +def test_ai_image_prompt_tool_checks_selected_provider_key() -> None: + js = PLUGIN_SCHEMA_JS.read_text(encoding="utf-8") + html = PLUGIN_HTML.read_text(encoding="utf-8") + + assert "apiKeyServices" in html + assert "window.__INKYPI_PLUGIN_BOOT__?.apiKeyServices" in js + assert 'provider === "google" ? "Google AI" : "OpenAI"' in js + assert "API Key not configured." in js diff --git a/tests/test_json_logging.py b/tests/test_json_logging.py index f288fcac4..f78a7720e 100644 --- a/tests/test_json_logging.py +++ b/tests/test_json_logging.py @@ -7,12 +7,24 @@ import json import logging +import os import sys - -from utils.logging_utils import JsonFormatter - - -def _record(msg="hello", level=logging.INFO, name="root", exc_info=None, **extras): +from typing import Any + +from utils.logging_utils import ( + JsonFormatter, + log_datetime_from_timestamp, + set_log_timezone, +) + + +def _record( + msg: object = "hello", + level: int = logging.INFO, + name: str = "root", + exc_info: Any = None, + **extras: object, +) -> logging.LogRecord: r = logging.LogRecord( name=name, level=level, @@ -61,7 +73,51 @@ class _Blob: assert "blob" in data["extra"] -def test_env_var_detection(monkeypatch): +def test_json_formatter_uses_configured_log_timezone(): + try: + set_log_timezone("America/Los_Angeles") + record = _record() + record.created = 1735693200.0 # 2025-01-01T01:00:00Z + + data = json.loads(JsonFormatter().format(record)) + + assert data["ts"].endswith("-08:00") + assert data["ts"].startswith("2024-12-31T17:00:00") + finally: + set_log_timezone("UTC") + + +def test_invalid_log_timezone_falls_back_to_utc(monkeypatch: Any) -> None: + calls: list[str] = [] + + monkeypatch.setattr( + "app_setup.logging_setup.time.tzset", lambda: calls.append("tzset") + ) + from app_setup.logging_setup import configure_log_timezone + + configure_log_timezone("Not/A_Zone") + + try: + assert os.environ["TZ"] == "UTC" + assert calls == ["tzset"] + assert log_datetime_from_timestamp(0).isoformat().endswith("+00:00") + finally: + set_log_timezone("UTC") + os.environ["TZ"] = "UTC" + + +def test_waitress_disconnect_filter_only_drops_expected_sse_disconnects() -> None: + from app_setup.logging_setup import ExpectedSSEDisconnectFilter + + log_filter = ExpectedSSEDisconnectFilter() + ordinary = _record("Client disconnected while serving /api/health") + expected_sse = _record("Client disconnected while serving /api/events") + + assert log_filter.filter(ordinary) is True + assert log_filter.filter(expected_sse) is False + + +def test_env_var_detection(monkeypatch: Any) -> None: """Root logger must use JsonFormatter when INKYPI_LOG_FORMAT=json.""" monkeypatch.setenv("INKYPI_LOG_FORMAT", "json") diff --git a/tests/test_log_redaction.py b/tests/test_log_redaction.py index 89fd80fd3..026a20938 100644 --- a/tests/test_log_redaction.py +++ b/tests/test_log_redaction.py @@ -258,6 +258,21 @@ def test_root_logger_has_redaction_filter_after_setup(self, monkeypatch): root.filters = saved_filters root.level = saved_level + def test_expected_sse_disconnect_filter_drops_waitress_noise(self): + from app_setup.logging_setup import ExpectedSSEDisconnectFilter + + flt = ExpectedSSEDisconnectFilter() + + progress = _make_record( + "Client disconnected while serving /api/progress/stream" + ) + events = _make_record("Client disconnected while serving /api/events") + other = _make_record("Client disconnected while serving /settings") + + assert flt.filter(progress) is False + assert flt.filter(events) is False + assert flt.filter(other) is True + def test_root_logger_has_redaction_filter_plain_text(self, monkeypatch, tmp_path): """Filter is wired for plain-text mode too.""" monkeypatch.delenv("INKYPI_LOG_FORMAT", raising=False) diff --git a/tests/unit/test_install_scripts.py b/tests/unit/test_install_scripts.py index a1950a7ac..983c90e4e 100644 --- a/tests/unit/test_install_scripts.py +++ b/tests/unit/test_install_scripts.py @@ -2712,60 +2712,69 @@ class TestMemoryDiffWorkflow: SCRIPTS_DIR = REPO_ROOT / "scripts" @pytest.fixture(autouse=True) - def _load(self): + def _load(self) -> None: assert self.WORKFLOW_PATH.exists(), ( f"Expected memory-diff workflow at {self.WORKFLOW_PATH}. " "See JTN-610 for the per-PR memory diff comment design." ) self.content = self.WORKFLOW_PATH.read_text() - def test_workflow_runs_on_pull_requests(self): + def test_workflow_runs_on_pull_requests(self) -> None: assert "pull_request:" in self.content - def test_workflow_cancels_superseded_runs(self): + def test_workflow_cancels_superseded_runs(self) -> None: assert "concurrency:" in self.content assert "cancel-in-progress: true" in self.content - def test_workflow_references_memray(self): + def test_workflow_references_memray(self) -> None: assert "memray" in self.content - def test_workflow_is_non_blocking(self): + def test_workflow_is_non_blocking(self) -> None: assert "continue-on-error: true" in self.content - def test_workflow_invokes_helper_scripts(self): + def test_workflow_invokes_helper_scripts(self) -> None: assert "scripts/memory_diff.py" in self.content assert "scripts/format_memory_diff.py" in self.content - def test_workflow_posts_sticky_comment(self): + def test_workflow_posts_sticky_comment(self) -> None: assert "github-script" in self.content or "comment-pull-request" in self.content assert "memory-diff:jtn-610" in self.content - def test_workflow_grants_pr_write_permission(self): + def test_workflow_grants_pr_write_permission(self) -> None: assert "pull-requests: write" in self.content - def test_workflow_checks_out_base_branch(self): + def test_workflow_checks_out_base_branch(self) -> None: assert "github.base_ref" in self.content - def test_capture_helper_exists_and_is_valid_python(self): + def test_workflow_uses_same_helper_for_base_and_pr_measurements(self) -> None: + assert "cp /tmp/memdiff-scripts/memory_diff.py /tmp/base-tree/scripts/" in ( + self.content + ) + assert ( + "cp /tmp/memdiff-scripts/format_memory_diff.py /tmp/base-tree/scripts/" + in self.content + ) + + def test_capture_helper_exists_and_is_valid_python(self) -> None: helper = self.SCRIPTS_DIR / "memory_diff.py" assert helper.exists(), f"Missing {helper}" compile(helper.read_text(), str(helper), "exec") - def test_formatter_helper_exists_and_is_valid_python(self): + def test_formatter_helper_exists_and_is_valid_python(self) -> None: helper = self.SCRIPTS_DIR / "format_memory_diff.py" assert helper.exists(), f"Missing {helper}" compile(helper.read_text(), str(helper), "exec") - def test_formatter_uses_stable_sticky_marker(self): + def test_formatter_uses_stable_sticky_marker(self) -> None: formatter = (self.SCRIPTS_DIR / "format_memory_diff.py").read_text() assert 'STICKY_MARKER = ""' in formatter - def test_capture_helper_supports_both_backends(self): + def test_capture_helper_supports_both_backends(self) -> None: capture = (self.SCRIPTS_DIR / "memory_diff.py").read_text() assert "memray" in capture assert "tracemalloc" in capture - def test_memray_listed_in_requirements_dev_in(self): + def test_memray_listed_in_requirements_dev_in(self) -> None: content = (INSTALL_DIR / "requirements-dev.in").read_text() assert "memray" in content, ( "memray must be declared in install/requirements-dev.in so the " diff --git a/tests/unit/test_memory_diff_format.py b/tests/unit/test_memory_diff_format.py new file mode 100644 index 000000000..eca99fe37 --- /dev/null +++ b/tests/unit/test_memory_diff_format.py @@ -0,0 +1,100 @@ +"""Tests for the PR memory-diff comment formatter.""" + +from scripts.format_memory_diff import format_comment + + +def test_format_comment_groups_allocator_noise_by_package(): + base = { + "backend": "memray", + "total_rss_bytes": 10 * 1024 * 1024, + "module_count": 100, + "allocator_sample_limit": 500, + "allocators": [ + { + "location": "/opt/python/lib/python3.12/site-packages/lark/tree.py:67", + "bytes": 2 * 1024 * 1024, + }, + { + "location": "/opt/python/lib/python3.12/site-packages/lark/lexer.py:215", + "bytes": 1 * 1024 * 1024, + }, + ], + } + pr = { + "backend": "memray", + "total_rss_bytes": 11 * 1024 * 1024, + "module_count": 100, + "allocator_sample_limit": 500, + "allocators": [ + { + "location": "/opt/python/lib/python3.12/site-packages/lark/tree.py:67", + "bytes": 4 * 1024 * 1024, + }, + { + "location": "/opt/python/lib/python3.12/site-packages/lark/lexer.py:215", + "bytes": 2 * 1024 * 1024, + }, + ], + } + + comment = format_comment(base, pr) + + assert "### Largest grouped allocator deltas" in comment + assert "| `lark` | 3.00 MB | 6.00 MB | +3.00 MB |" in comment + assert "Source-location detail" in comment + + +def test_format_comment_does_not_invent_zero_for_sampled_shared_location(): + base = { + "backend": "memray", + "total_rss_bytes": 0, + "module_count": 0, + "allocator_sample_limit": 500, + "allocators": [ + { + "location": "/opt/python/lib/python3.12/site-packages/werkzeug/http.py:1", + "bytes": 512 * 1024, + } + ], + } + pr = { + "backend": "memray", + "total_rss_bytes": 0, + "module_count": 0, + "allocator_sample_limit": 500, + "allocators": [ + { + "location": "/opt/python/lib/python3.12/site-packages/werkzeug/http.py:1", + "bytes": 768 * 1024, + } + ], + } + + comment = format_comment(base, pr) + + assert "| `werkzeug/http.py:1` | 512.0 KB | 768.0 KB | +256.0 KB |" in comment + assert "| `werkzeug/http.py:1` | 0 B |" not in comment + assert "| `werkzeug/http.py:1` | 512.0 KB | 0 B |" not in comment + + +def test_format_comment_hides_memray_command_string_allocator(): + base = { + "backend": "memray", + "total_rss_bytes": 0, + "module_count": 0, + "allocator_sample_limit": 500, + "allocators": [{"location": ":1", "bytes": 2 * 1024 * 1024}], + } + pr = { + "backend": "memray", + "total_rss_bytes": 0, + "module_count": 0, + "allocator_sample_limit": 500, + "allocators": [], + } + + comment = format_comment(base, pr) + + assert ":1" not in comment + assert "profile harness" not in comment + assert "no significant grouped allocator deltas" in comment diff --git a/tests/unit/test_playlist_workflows.py b/tests/unit/test_playlist_workflows.py index 23a2b5278..51bf1659c 100644 --- a/tests/unit/test_playlist_workflows.py +++ b/tests/unit/test_playlist_workflows.py @@ -92,14 +92,18 @@ def to_dict(self): class _DeviceConfig: - def __init__(self, plugin_config=None): + def __init__(self, plugin_config=None, env_keys: dict[str, str] | None = None): self.plugin_config = plugin_config + self.env_keys = env_keys or {} self.playlist_manager = _PlaylistManager() self.update_calls: list[dict[str, Any]] = [] def get_plugin(self, plugin_id: str): return self.plugin_config + def load_env_key(self, key: str): + return self.env_keys.get(key) + def update_atomic(self, update_fn): payload: dict[str, Any] = {} update_fn(payload) @@ -306,3 +310,83 @@ def test_prepare_add_plugin_workflow_rejects_security_error(monkeypatch): assert result.ok is False assert result.error is not None assert result.error.message == "bad input" + + +def test_prepare_add_plugin_workflow_allows_ai_image_provider_with_key(): + playlist_workflows_mod = _playlist_workflows_mod() + device_config = _DeviceConfig( + plugin_config={"id": "ai_image"}, + env_keys={"OPEN_AI_SECRET": "configured"}, + ) + manager = device_config.playlist_manager + manager.add_playlist("Rotation") + + result = playlist_workflows_mod.prepare_add_plugin_workflow( + "ai_image", + { + "textPrompt": "a glass city", + "provider": "openai", + "imageModel": "gpt-image-2", + "quality": "medium", + }, + { + "playlist": "Rotation", + "instance_name": "AI Surprise", + "refreshType": "interval", + "unit": "hour", + "interval": "1", + }, + playlist_manager=manager, + device_config=device_config, + ) + + assert result.ok is True + instance = manager.find_plugin("ai_image", "AI Surprise") + assert instance is not None + assert instance.settings["textPrompt"] == "a glass city" + + +def test_prepare_add_plugin_workflow_rejects_ai_image_provider_without_key(): + playlist_workflows_mod = _playlist_workflows_mod() + device_config = _DeviceConfig(plugin_config={"id": "ai_image"}) + manager = device_config.playlist_manager + manager.add_playlist("Rotation") + + result = playlist_workflows_mod.prepare_add_plugin_workflow( + "ai_image", + { + "textPrompt": "a glass city", + "provider": "google", + "imageModel": "imagen-4.0-generate-001", + }, + { + "playlist": "Rotation", + "instance_name": "AI Surprise", + "refreshType": "interval", + "unit": "hour", + "interval": "1", + }, + playlist_manager=manager, + device_config=device_config, + ) + + assert result.ok is False + assert result.error is not None + assert result.error.field == "provider" + assert result.error.message == "Google AI API Key not configured." + + +def test_validate_ai_image_provider_key_lookup_failures_are_non_blocking() -> None: + playlist_workflows_mod = _playlist_workflows_mod() + + class _ExplodingDeviceConfig(_DeviceConfig): + def load_env_key(self, key: str) -> str | None: + raise RuntimeError(f"cannot read {key}") + + err = playlist_workflows_mod.validate_plugin_settings_security( + _ExplodingDeviceConfig(plugin_config=None), + "ai_image", + {"provider": "openai"}, + ) + + assert err is None diff --git a/tests/unit/test_settings_logs.py b/tests/unit/test_settings_logs.py index 4fd9c4e8b..c3d24b02d 100644 --- a/tests/unit/test_settings_logs.py +++ b/tests/unit/test_settings_logs.py @@ -175,3 +175,36 @@ def test_log_lines_exclude_internal_details(client, monkeypatch): assert not re.search( r"\w+\[\d+\]:", line ), f"Found identifier[pid] pattern in: {line}" + + +def test_dev_mode_log_handler_uses_configured_timezone() -> None: + import logging + + import blueprints.settings as mod + from utils.logging_utils import set_log_timezone + + set_log_timezone("America/Los_Angeles") + mod._dev_log_buffer.clear() + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="hello", + args=(), + exc_info=None, + ) + record.created = 1735693200.0 # 2025-01-01T01:00:00Z + + try: + mod.DevModeLogHandler().emit(record) + assert mod._dev_log_buffer[-1][1].startswith("Dec 31 17:00:00") + finally: + mod._dev_log_buffer.clear() + set_log_timezone("UTC") + + +def test_device_log_timezone_falls_back_without_app_context() -> None: + import blueprints.settings as mod + + assert mod._device_log_timezone().key == "UTC" diff --git a/tests/unit/test_settings_save.py b/tests/unit/test_settings_save.py index 23f2c2f1a..da62b1f15 100644 --- a/tests/unit/test_settings_save.py +++ b/tests/unit/test_settings_save.py @@ -228,6 +228,24 @@ def test_save_settings_success(self, client, device_config_dev): assert data["success"] is True assert device_config_dev.get_config("name") == "TestDevice" + def test_save_settings_reconfigures_log_timezone(self, client, monkeypatch): + import blueprints.settings._config as settings_config + + configured: list[str | None] = [] + monkeypatch.setattr( + settings_config, + "configure_log_timezone", + lambda tz_name: configured.append(tz_name), + ) + + resp = client.post( + "/save_settings", + data={**self.VALID_FORM, "timezoneName": "America/Los_Angeles"}, + ) + + assert resp.status_code == 200 + assert configured == ["America/Los_Angeles"] + def test_save_settings_missing_unit(self, client): form = {**self.VALID_FORM} del form["unit"] diff --git a/tests/unit/test_template_snapshots.py b/tests/unit/test_template_snapshots.py index 017986a9a..e17bd9409 100644 --- a/tests/unit/test_template_snapshots.py +++ b/tests/unit/test_template_snapshots.py @@ -94,6 +94,42 @@ def test_all_pages_include_theme_toggle(client, path): assert "themeToggle" in html or "theme-toggle" in html +@pytest.mark.parametrize( + "path", + [ + "/", + "/settings", + "/playlist", + "/plugin/clock", + "/api-keys", + ], +) +def test_all_pages_include_sidebar_system_footer(client, monkeypatch, path): + """All main pages keep the bottom-left online/load footer visible.""" + monkeypatch.setattr("os.getloadavg", lambda: (0.0, 0.0, 0.0), raising=False) + + resp = client.get(path) + assert resp.status_code == 200 + html = resp.get_data(as_text=True) + + assert 'class="sys-row"' in html + assert 'class="sys-stats"' in html + assert 'id="sidebarOnlineLabel">online' in html + assert 'class="sys-load" aria-label="Load average">0.00 avg' in html + + +def test_plugin_page_keeps_progress_timer_contract(client): + """Plugin pages keep the elapsed timer and progress log hooks present.""" + resp = client.get("/plugin/clock") + assert resp.status_code == 200 + html = resp.get_data(as_text=True) + + assert 'id="requestProgress"' in html + assert 'id="requestProgressClock" class="value">—' in html + assert 'id="requestProgressElapsed" class="value">0s' in html + assert 'id="requestProgressList" class="progress-log" aria-live="polite"' in html + + @pytest.mark.parametrize( "path", [