Compare commits

..
Author SHA1 Message Date
ChuckBuildsandClaude Opus 5 cbfb0e035d fix(web): stop the installer chmod stripping exec bits on every update
git tracks five scripts as mode 644 that first_time_install.sh then chmods to
755 (start_display.sh, stop_display.sh, the two install_*_service.sh, and
one-shot-install.sh does the same to first_time_install.sh). With
core.fileMode true, the default on Linux, git reports all five as modified
from then on, in files the user never touched.

The update button stashes local changes before pulling, so it is not blocked
by this. But it never pops that stash -- stash pop and stash apply appear
nowhere in the update flow -- so the mode change is stashed away and left
there, and the files revert:

    === file modes after the update button's stash ===
      664  first_time_install.sh      <- installer had made these 755
      664  start_display.sh
      664  stop_display.sh
      664  scripts/install/install_service.sh

So every web-UI update silently strips the executable bit from the installer's
own scripts, and leaves a stash entry holding the difference. start_display.sh
and stop_display.sh stop working from the shell afterwards.

A manual `git pull --rebase` over SSH fails outright, since nothing stashes for
it: "cannot pull with rebase: You have unstaged changes". That is the likely
source of the reports, since plenty of people update that way.

Tracking the five as 755 -- what they should always have been, as the
installer chmodding them attests -- removes the spurious mode change
entirely: nothing to stash, nothing stripped, no stash entry, and manual
pulls work.

The pull also passes --autostash, for the case the code explicitly tolerates:
when the stash fails it logs a warning and pulls anyway, and that pull is what
then fails. Autostash also pops what it stashes, which the manual stash does
not.

Note that `git add -A` after `git update-index --chmod=+x` silently reverts
the index to the on-disk mode, so the modes here were set by chmodding the
files themselves.

Regression test asserts the five stay tracked executable; reverting any one
of them fails it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
2026-08-20 13:53:50 -04:00
10 changed files with 103 additions and 123 deletions
Regular → Executable
View File
View File
View File
+1 -1
View File
@@ -328,7 +328,7 @@ class ScrollHelper:
elapsed_time = current_time - (self.scroll_start_time or current_time)
# The image already includes display_width padding, so we only need total_scroll_width
required_total_distance = self.total_scroll_width
self.logger.debug(
self.logger.info(
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
elapsed_time,
self.calculated_duration,
+54 -54
View File
@@ -83,7 +83,7 @@ class PluginAdapter:
# into unrelated headlines once the strip refreshed to 9,505px.
self._offset_shapes: dict = {}
logger.debug(
logger.info(
"PluginAdapter initialized: display=%dx%d",
self.display_width, self.display_height
)
@@ -109,7 +109,7 @@ class PluginAdapter:
Returns:
List of PIL Images representing plugin content, or None if no content
"""
logger.debug(
logger.info(
"[%s] Getting content (class=%s)",
plugin_id, plugin.__class__.__name__
)
@@ -118,7 +118,7 @@ class PluginAdapter:
cached = self._get_cached(plugin_id)
if cached is not None:
total_width = sum(img.width for img in cached)
logger.debug(
logger.info(
"[%s] Using cached content: %d images, %dpx total",
plugin_id, len(cached), total_width
)
@@ -126,46 +126,46 @@ class PluginAdapter:
# Try native Vegas content method first
has_native = hasattr(plugin, 'get_vegas_content')
logger.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native)
logger.info("[%s] Has get_vegas_content: %s", plugin_id, has_native)
if has_native:
content = self._get_native_content(plugin, plugin_id, offscreen_only)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] Native content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
return self._finalize(content, plugin_id, 'native', plugin)
logger.debug("[%s] Native content returned None", plugin_id)
logger.info("[%s] Native content returned None", plugin_id)
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
has_scroll_helper = hasattr(plugin, 'scroll_helper')
logger.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
logger.info("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
if has_scroll_helper:
logger.debug("[%s] ScrollHelper content returned None", plugin_id)
logger.info("[%s] ScrollHelper content returned None", plugin_id)
if offscreen_only:
# Display capture needs the shared canvas; leave it to the caller.
logger.debug(
logger.info(
"[%s] Needs display capture, deferring to the render thread",
plugin_id
)
return None
# Fall back to display capture
logger.debug("[%s] Trying fallback display capture...", plugin_id)
logger.info("[%s] Trying fallback display capture...", plugin_id)
content = self._capture_display_content(plugin, plugin_id)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
@@ -226,7 +226,7 @@ class PluginAdapter:
kept.append(result.image)
if not kept:
logger.debug(
logger.info(
"[%s] All %d image(s) from %s were blank — contributing nothing",
plugin_id, len(images), source
)
@@ -235,14 +235,14 @@ class PluginAdapter:
trimmed_width = sum(img.width for img in kept)
if trimmed_width < self.config.min_plugin_width:
logger.debug(
logger.info(
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
plugin_id, trimmed_width, self.config.min_plugin_width
)
return None
if trimmed_width != original_width or dropped_blank:
logger.debug(
logger.info(
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
"%d image(s) kept, %d blank dropped",
plugin_id, source, original_width, trimmed_width,
@@ -431,7 +431,7 @@ class PluginAdapter:
"""
if self._offset_shapes.get(plugin_id) != shape:
if plugin_id in self._item_offsets:
logger.debug(
logger.info(
"[%s] Content is %s now, was %s — restarting the rotation "
"rather than resuming at a position that no longer means "
"anything", plugin_id, shape,
@@ -579,7 +579,7 @@ class PluginAdapter:
consumed += 1
if mode == 'truncate':
logger.debug(
logger.info(
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
plugin_id, budget, len(selected), len(images), used
@@ -587,7 +587,7 @@ class PluginAdapter:
else:
self._record_offset(
plugin_id, (start + consumed) % len(images), shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
"from offset %d; remainder deferred to a later cycle",
plugin_id, budget, len(selected), len(images), used, start
@@ -636,7 +636,7 @@ class PluginAdapter:
if mode != 'truncate':
self._record_offset(
plugin_id, 0 if end >= img.width else end, shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: cropped continuous %dpx image to "
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
plugin_id, budget, img.width, offset, end, min_run,
@@ -674,7 +674,7 @@ class PluginAdapter:
self._record_offset(
plugin_id, 0 if end >= img.width else end_index, shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
"(%dpx) at item boundaries %d-%d of %d, %s",
plugin_id, budget, img.width, start, end, end - start,
@@ -698,7 +698,7 @@ class PluginAdapter:
List of images or None
"""
try:
logger.debug("[%s] Native: calling get_vegas_content()", plugin_id)
logger.info("[%s] Native: calling get_vegas_content()", plugin_id)
# Tell the plugin how much width the ticker wants it to use, and
# narrow the canvas for the duration of the call. A plugin that
@@ -707,7 +707,7 @@ class PluginAdapter:
# be explicit can read get_vegas_render_width().
render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width:
logger.debug(
logger.info(
"[%s] Native: requesting %dpx instead of %dpx",
plugin_id, render_width, self.display_width
)
@@ -735,19 +735,19 @@ class PluginAdapter:
plugin._vegas_render_width = None
if result is None:
logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
return None
# Normalize to list
if isinstance(result, Image.Image):
images = [result]
logger.debug(
logger.info(
"[%s] Native: got single Image %dx%d",
plugin_id, result.width, result.height
)
elif isinstance(result, (list, tuple)):
images = list(result)
logger.debug(
logger.info(
"[%s] Native: got %d items in list/tuple",
plugin_id, len(images)
)
@@ -768,14 +768,14 @@ class PluginAdapter:
)
continue
logger.debug(
logger.info(
"[%s] Native: item[%d] is %dx%d, mode=%s",
plugin_id, i, img.width, img.height, img.mode
)
# Ensure correct height
if img.height != self.display_height:
logger.debug(
logger.info(
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
plugin_id, i, img.width, img.height,
img.width, self.display_height
@@ -793,13 +793,13 @@ class PluginAdapter:
if valid_images:
total_width = sum(img.width for img in valid_images)
logger.debug(
logger.info(
"[%s] Native: SUCCESS - %d images, %dpx total width",
plugin_id, len(valid_images), total_width
)
return valid_images
logger.debug("[%s] Native: no valid images after validation", plugin_id)
logger.info("[%s] Native: no valid images after validation", plugin_id)
return None
except (AttributeError, TypeError, ValueError, OSError) as e:
@@ -833,20 +833,20 @@ class PluginAdapter:
logger.debug("[%s] No scroll_helper attribute", plugin_id)
return None
logger.debug(
logger.info(
"[%s] Found scroll_helper: %s",
plugin_id, type(scroll_helper).__name__
)
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is None:
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image is None, triggering content generation",
plugin_id
)
if offscreen_only:
# Generating it calls display(), which needs the canvas.
logger.debug(
logger.info(
"[%s] scroll_helper cache empty; deferring generation "
"to the render thread", plugin_id
)
@@ -859,13 +859,13 @@ class PluginAdapter:
return None
if not isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image is not an Image: %s",
plugin_id, type(cached_image).__name__
)
return None
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
plugin_id, cached_image.width, cached_image.height, cached_image.mode
)
@@ -888,7 +888,7 @@ class PluginAdapter:
# Ensure correct height
if img.height != self.display_height:
logger.debug(
logger.info(
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
plugin_id, img.width, img.height,
img.width, self.display_height
@@ -902,7 +902,7 @@ class PluginAdapter:
if img.mode != 'RGB':
img = img.convert('RGB')
logger.debug(
logger.info(
"[%s] ScrollHelper content ready: %dx%d",
plugin_id, img.width, img.height
)
@@ -1002,7 +1002,7 @@ class PluginAdapter:
with self._capture():
# Method 1: Try _create_scrolling_display (stocks pattern)
if hasattr(plugin, '_create_scrolling_display'):
logger.debug(
logger.info(
"[%s] Triggering via _create_scrolling_display()",
plugin_id
)
@@ -1010,7 +1010,7 @@ class PluginAdapter:
plugin._create_scrolling_display()
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height
)
@@ -1022,7 +1022,7 @@ class PluginAdapter:
# Method 2: Try display(force_clear=True) which typically builds scroll content
if hasattr(plugin, 'display'):
logger.debug(
logger.info(
"[%s] Triggering via display(force_clear=True)",
plugin_id
)
@@ -1031,12 +1031,12 @@ class PluginAdapter:
plugin.display(force_clear=True)
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] display(force_clear=True) SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height
)
return cached_image
logger.debug(
logger.info(
"[%s] display(force_clear=True) did not populate cached_image",
plugin_id
)
@@ -1045,7 +1045,7 @@ class PluginAdapter:
"[%s] display(force_clear=True) failed", plugin_id
)
logger.debug(
logger.info(
"[%s] Could not trigger scroll content generation",
plugin_id
)
@@ -1077,15 +1077,15 @@ class PluginAdapter:
try:
# Save current display state
original_image = self.display_manager.image.copy()
logger.debug("[%s] Fallback: saved original display state", plugin_id)
logger.info("[%s] Fallback: saved original display state", plugin_id)
# Ensure plugin has fresh data before capturing
has_update_data = hasattr(plugin, 'update_data')
logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
if has_update_data:
try:
plugin.update_data()
logger.debug("[%s] Fallback: update_data() called", plugin_id)
logger.info("[%s] Fallback: update_data() called", plugin_id)
except (AttributeError, RuntimeError, OSError):
logger.exception("[%s] Fallback: update_data() failed", plugin_id)
@@ -1097,41 +1097,41 @@ class PluginAdapter:
# arrangement rather than one that has to be cropped afterwards.
render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width:
logger.debug(
logger.info(
"[%s] Fallback: rendering at %dpx instead of %dpx",
plugin_id, render_width, self.display_width
)
with self._capture(), self._render_at(render_width):
self.display_manager.clear()
logger.debug("[%s] Fallback: display cleared, calling display()", plugin_id)
logger.info("[%s] Fallback: display cleared, calling display()", plugin_id)
# First try without force_clear (some plugins behave better this way)
try:
plugin.display()
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
logger.info("[%s] Fallback: display() called successfully", plugin_id)
except TypeError:
# Plugin may require force_clear argument
logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
logger.info("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
plugin.display(force_clear=True)
# Capture the result
captured = self.display_manager.image.copy()
logger.debug(
logger.info(
"[%s] Fallback: captured frame %dx%d, mode=%s",
plugin_id, captured.width, captured.height, captured.mode
)
# Check if captured image has content (not all black)
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
logger.debug(
logger.info(
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
plugin_id, bright_ratio * 100
)
if is_blank:
logger.debug(
logger.info(
"[%s] Fallback: first capture blank, retrying with force_clear",
plugin_id
)
@@ -1142,7 +1142,7 @@ class PluginAdapter:
captured = self.display_manager.image.copy()
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
logger.debug(
logger.info(
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
plugin_id, bright_ratio * 100
)
@@ -1159,7 +1159,7 @@ class PluginAdapter:
if captured.mode != 'RGB':
captured = captured.convert('RGB')
logger.debug(
logger.info(
"[%s] Fallback: SUCCESS - captured %dx%d",
plugin_id, captured.width, captured.height
)
Regular → Executable
View File
Regular → Executable
View File
+37 -3
View File
@@ -58,7 +58,7 @@ def repos(tmp_path):
def test_branch_with_upstream_uses_a_plain_pull(repos):
args, note, error = resolve_pull_command(str(repos))
assert error is None
assert args == ['git', 'pull', '--rebase']
assert args == ['git', 'pull', '--rebase', '--autostash']
assert note == ''
@@ -73,7 +73,7 @@ def test_branch_without_upstream_falls_back_to_origin_branch(repos):
args, note, error = resolve_pull_command(str(repos))
assert error is None
assert args == ['git', 'pull', '--rebase', 'origin', 'audit']
assert args == ['git', 'pull', '--rebase', '--autostash', 'origin', 'audit']
assert 'audit' in note
@@ -155,7 +155,7 @@ def test_switching_attaches_tracking_so_pull_needs_no_fallback(repos):
args, note, error = resolve_pull_command(str(repos))
assert error is None
assert args == ['git', 'pull', '--rebase']
assert args == ['git', 'pull', '--rebase', '--autostash']
assert note == ''
@@ -200,3 +200,37 @@ def test_stash_option_lets_the_switch_through_and_keeps_the_work(repos):
assert _git('branch', '--show-current', cwd=repos).stdout.strip() == 'other'
# The edit is not lost — it is on the stash.
assert 'switch to other' in _git('stash', 'list', cwd=repos).stdout
class TestInstallerDoesNotBlockTheUpdateButton:
"""first_time_install.sh chmods scripts that git tracked as 644.
With core.fileMode true -- the default on Linux -- that leaves five
permanently modified tracked files on every machine that ran the
installer, and `git pull --rebase` refuses to start:
error: cannot pull with rebase: You have unstaged changes.
Tracking them as executable makes the installer's chmod a no-op.
"""
CHMODDED = [
'first_time_install.sh',
'start_display.sh',
'stop_display.sh',
'scripts/install/install_service.sh',
'scripts/install/install_web_service.sh',
]
def test_scripts_the_installer_chmods_are_tracked_executable(self):
import subprocess
from pathlib import Path
root = Path(__file__).resolve().parent.parent
out = subprocess.run(['git', 'ls-files', '-s', *self.CHMODDED],
capture_output=True, text=True, cwd=str(root)).stdout
modes = {line.split()[3]: line.split()[0] for line in out.strip().split('\n') if line}
non_exec = sorted(f for f, m in modes.items() if m != '100755')
assert not non_exec, (
f"{non_exec} are chmodded by the installer but tracked non-executable, "
"so every install leaves the working tree dirty and the update "
"button cannot pull")
-63
View File
@@ -1,63 +0,0 @@
"""The Vegas content path must trace at DEBUG, not INFO.
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native content
returned None", "Has scroll_helper", the per-item sizes -- and it does that for
each plugin on each cycle.
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO and
35 were WARNING. plugin_adapter alone produced 2,457 of them. That is ~223
lines a minute of string formatting on a Pi that is also driving the panel, all
of it written through journald to the SD card, and it buries the 35 lines that
actually indicate a problem.
Nothing is lost by moving it to DEBUG: the 19 warning/error/exception calls in
the module are untouched, so real failures still surface at their own level.
One INFO call is deliberate and stays -- the padding-strip message chooses its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins it.
"""
import ast
from pathlib import Path
import pytest
ADAPTER = (Path(__file__).resolve().parent.parent / "src" / "vegas_mode"
/ "plugin_adapter.py")
def _info_calls(path):
"""Direct logger.info(...) call sites in a module."""
tree = ast.parse(path.read_text(encoding="utf-8"))
found = []
for node in ast.walk(tree):
if (isinstance(node, ast.Call)
and isinstance(node.func, ast.Attribute)
and node.func.attr == "info"
and getattr(node.func.value, "id", None) == "logger"):
found.append(node.lineno)
return found
def test_the_content_path_does_not_trace_at_info():
calls = _info_calls(ADAPTER)
assert not calls, (
"plugin_adapter should trace at DEBUG; found logger.info at lines "
f"{calls}. This path runs per plugin per cycle and its output goes to "
"the SD card via journald."
)
def test_real_failures_still_have_a_level_of_their_own():
"""Demoting the trace must not have swept up the error reporting."""
source = ADAPTER.read_text(encoding="utf-8")
loud = sum(source.count(f"logger.{level}(")
for level in ("warning", "error", "exception"))
assert loud >= 15, f"only {loud} warning/error/exception calls remain"
def test_the_deliberate_runtime_chosen_level_survives():
"""The padding-strip message picks its level at runtime; leave it alone."""
source = ADAPTER.read_text(encoding="utf-8")
assert "logger.warning if (left and right) else logger.info" in source
+11 -2
View File
@@ -1657,13 +1657,22 @@ def resolve_pull_command(project_dir):
backup, or following an install guide that names one. The update button
then reports a failure the user cannot act on.
``--autostash`` is passed for the same reason. Rebase refuses to start
when any tracked file is modified, and on these installs something always
is: first_time_install.sh chmods five scripts that git tracked as 644, so
every machine that ran the installer carries five permanent mode changes
and the update button reports "cannot pull with rebase: You have unstaged
changes". Those modes are corrected in this commit, but a user cannot pull
the correction while the pull is what is blocked, and any other local edit
would reproduce it anyway. Autostash reapplies the changes afterwards.
Returns ``(args, note, error)``. When ``origin/<branch>`` exists the pull
is made explicit against it, so the update proceeds and the branch is
given tracking information afterwards.
"""
upstream = _git_upstream(project_dir)
if upstream:
return ['git', 'pull', '--rebase'], '', None
return ['git', 'pull', '--rebase', '--autostash'], '', None
branch = _git_current_branch(project_dir)
if not branch:
@@ -1673,7 +1682,7 @@ def resolve_pull_command(project_dir):
)
if _git_remote_branch_exists(project_dir, branch):
return (
['git', 'pull', '--rebase', 'origin', branch],
['git', 'pull', '--rebase', '--autostash', 'origin', branch],
f"Branch '{branch}' had no upstream; pulled from origin/{branch} and set it as the upstream.",
None,
)