mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-20 18:09:05 +00:00
Compare commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
cbfb0e035d |
Regular → Executable
Regular → Executable
Regular → Executable
@@ -328,7 +328,7 @@ class ScrollHelper:
|
|||||||
elapsed_time = current_time - (self.scroll_start_time or current_time)
|
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
|
# The image already includes display_width padding, so we only need total_scroll_width
|
||||||
required_total_distance = self.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%%)",
|
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
|
||||||
elapsed_time,
|
elapsed_time,
|
||||||
self.calculated_duration,
|
self.calculated_duration,
|
||||||
|
|||||||
+1
-66
@@ -130,12 +130,7 @@ def setup_logging(
|
|||||||
# Console handler (always add)
|
# Console handler (always add)
|
||||||
console_handler = logging.StreamHandler(sys.stdout)
|
console_handler = logging.StreamHandler(sys.stdout)
|
||||||
console_handler.setLevel(level)
|
console_handler.setLevel(level)
|
||||||
# Under systemd, tag each line so the journal records the real severity
|
console_handler.setFormatter(formatter)
|
||||||
# rather than filing everything as informational. The file handler below
|
|
||||||
# keeps the plain formatter: the prefix is meaningful to journald and noise
|
|
||||||
# anywhere else.
|
|
||||||
console_handler.setFormatter(
|
|
||||||
JournalPriorityFormatter(formatter) if _under_systemd() else formatter)
|
|
||||||
root_logger.addHandler(console_handler)
|
root_logger.addHandler(console_handler)
|
||||||
|
|
||||||
# File handler (if specified)
|
# File handler (if specified)
|
||||||
@@ -150,66 +145,6 @@ def setup_logging(
|
|||||||
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
|
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
|
||||||
|
|
||||||
|
|
||||||
#: syslog priorities, which is what systemd parses from a "<N>" prefix on
|
|
||||||
#: stdout. Mapped from Python's levels.
|
|
||||||
_SYSLOG_PRIORITY = {
|
|
||||||
logging.CRITICAL: 2, # LOG_CRIT
|
|
||||||
logging.ERROR: 3, # LOG_ERR
|
|
||||||
logging.WARNING: 4, # LOG_WARNING
|
|
||||||
logging.INFO: 6, # LOG_INFO
|
|
||||||
logging.DEBUG: 7, # LOG_DEBUG
|
|
||||||
}
|
|
||||||
|
|
||||||
|
|
||||||
class JournalPriorityFormatter(logging.Formatter):
|
|
||||||
"""Wraps a formatter, prefixing each line with its syslog priority.
|
|
||||||
|
|
||||||
Under systemd everything this process writes to stdout lands in the journal
|
|
||||||
as PRIORITY=6, whatever the Python level was. Measured on a live rig: 55
|
|
||||||
ERROR lines and 13 WARNING lines in a day, every one of them recorded as
|
|
||||||
informational, so `journalctl -p err -u ledmatrix` returned nothing at all
|
|
||||||
while errors were being logged. Anyone triaging has to grep the message
|
|
||||||
text instead, which is both slower and wrong -- a search for "oom" matches
|
|
||||||
the radar logging "zoom=9".
|
|
||||||
|
|
||||||
systemd reads a leading "<N>" on each line and uses it as the priority
|
|
||||||
(sd-daemon(3)), so this needs no extra dependency. Multi-line records get
|
|
||||||
the prefix on every line, since the journal splits them and an unprefixed
|
|
||||||
continuation would fall back to the default.
|
|
||||||
"""
|
|
||||||
|
|
||||||
def __init__(self, inner: logging.Formatter):
|
|
||||||
super().__init__()
|
|
||||||
self._inner = inner
|
|
||||||
|
|
||||||
@property
|
|
||||||
def inner(self) -> logging.Formatter:
|
|
||||||
"""The formatter doing the actual work.
|
|
||||||
|
|
||||||
Whether journald tagging is applied depends on JOURNAL_STREAM, so it is
|
|
||||||
on under systemd and off in a terminal -- and anything asserting which
|
|
||||||
formatter setup_logging() selected would otherwise get a different
|
|
||||||
answer in CI than on a developer's machine. Exposing the inner one lets
|
|
||||||
those checks stay about format_type, which is what they mean.
|
|
||||||
"""
|
|
||||||
return self._inner
|
|
||||||
|
|
||||||
def format(self, record: logging.LogRecord) -> str:
|
|
||||||
text = self._inner.format(record)
|
|
||||||
prefix = f"<{_SYSLOG_PRIORITY.get(record.levelno, 6)}>"
|
|
||||||
return "\n".join(prefix + line for line in text.split("\n"))
|
|
||||||
|
|
||||||
|
|
||||||
def _under_systemd() -> bool:
|
|
||||||
"""True when stdout is the journal.
|
|
||||||
|
|
||||||
systemd sets JOURNAL_STREAM for services whose output it captures. Without
|
|
||||||
this check the "<N>" prefixes would show up as literal noise when the
|
|
||||||
program is run from a terminal, in the emulator, or in tests.
|
|
||||||
"""
|
|
||||||
return bool(os.environ.get("JOURNAL_STREAM"))
|
|
||||||
|
|
||||||
|
|
||||||
class PluginLoggerAdapter(logging.LoggerAdapter):
|
class PluginLoggerAdapter(logging.LoggerAdapter):
|
||||||
"""LoggerAdapter that stamps every record with its plugin_id.
|
"""LoggerAdapter that stamps every record with its plugin_id.
|
||||||
|
|
||||||
|
|||||||
@@ -178,21 +178,11 @@ class PluginHealthTracker:
|
|||||||
)
|
)
|
||||||
return self._health_state[plugin_id]
|
return self._health_state[plugin_id]
|
||||||
|
|
||||||
# Fields the circuit breaker is rebuilt from after a restart. Everything
|
|
||||||
# else in a health record is reporting, read only for display.
|
|
||||||
_DURABLE_FIELDS = ('consecutive_failures', 'circuit_state',
|
|
||||||
'circuit_opened_time', 'half_open_start_time')
|
|
||||||
|
|
||||||
def _durable(self, state: Dict[str, Any]) -> tuple:
|
|
||||||
"""The part of a health record whose loss would change behaviour."""
|
|
||||||
return tuple(state.get(field) for field in self._DURABLE_FIELDS)
|
|
||||||
|
|
||||||
def record_success(self, plugin_id: str) -> None:
|
def record_success(self, plugin_id: str) -> None:
|
||||||
"""Record a successful plugin execution."""
|
"""Record a successful plugin execution."""
|
||||||
state = self.get_health_state(plugin_id)
|
state = self.get_health_state(plugin_id)
|
||||||
current_time = time.time()
|
current_time = time.time()
|
||||||
durable_before = self._durable(state)
|
|
||||||
|
|
||||||
# Reset consecutive failures
|
# Reset consecutive failures
|
||||||
state['consecutive_failures'] = 0
|
state['consecutive_failures'] = 0
|
||||||
state['total_successes'] = state.get('total_successes', 0) + 1
|
state['total_successes'] = state.get('total_successes', 0) + 1
|
||||||
@@ -208,20 +198,9 @@ class PluginHealthTracker:
|
|||||||
# Shouldn't happen, but handle it
|
# Shouldn't happen, but handle it
|
||||||
state['circuit_state'] = CircuitState.CLOSED.value
|
state['circuit_state'] = CircuitState.CLOSED.value
|
||||||
state['circuit_opened_time'] = None
|
state['circuit_opened_time'] = None
|
||||||
|
|
||||||
# A healthy plugin reports success every cycle, and in that steady state
|
self._save_health_state(plugin_id, state)
|
||||||
# the only fields changed above are a counter and a timestamp that
|
|
||||||
# nothing reads back after a restart. Persisting them anyway rewrites a
|
|
||||||
# small file per plugin per cycle: on a rig running 24 plugins, a
|
|
||||||
# five-minute sample measured 22 rewrites, about 4.4 a minute or 6,300 a
|
|
||||||
# day. Those land on an SD card, where the cost is an erase-block cycle
|
|
||||||
# rather than the 400 bytes involved, and where wear is what eventually
|
|
||||||
# kills the card.
|
|
||||||
# In-memory state is still updated every time, so the health API and web
|
|
||||||
# UI show exactly what they did before; only the write is skipped.
|
|
||||||
if self._durable(state) != durable_before:
|
|
||||||
self._save_health_state(plugin_id, state)
|
|
||||||
|
|
||||||
def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None:
|
def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None:
|
||||||
"""Record a failed plugin execution."""
|
"""Record a failed plugin execution."""
|
||||||
state = self.get_health_state(plugin_id)
|
state = self.get_health_state(plugin_id)
|
||||||
|
|||||||
@@ -83,7 +83,7 @@ class PluginAdapter:
|
|||||||
# into unrelated headlines once the strip refreshed to 9,505px.
|
# into unrelated headlines once the strip refreshed to 9,505px.
|
||||||
self._offset_shapes: dict = {}
|
self._offset_shapes: dict = {}
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"PluginAdapter initialized: display=%dx%d",
|
"PluginAdapter initialized: display=%dx%d",
|
||||||
self.display_width, self.display_height
|
self.display_width, self.display_height
|
||||||
)
|
)
|
||||||
@@ -109,7 +109,7 @@ class PluginAdapter:
|
|||||||
Returns:
|
Returns:
|
||||||
List of PIL Images representing plugin content, or None if no content
|
List of PIL Images representing plugin content, or None if no content
|
||||||
"""
|
"""
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Getting content (class=%s)",
|
"[%s] Getting content (class=%s)",
|
||||||
plugin_id, plugin.__class__.__name__
|
plugin_id, plugin.__class__.__name__
|
||||||
)
|
)
|
||||||
@@ -118,7 +118,7 @@ class PluginAdapter:
|
|||||||
cached = self._get_cached(plugin_id)
|
cached = self._get_cached(plugin_id)
|
||||||
if cached is not None:
|
if cached is not None:
|
||||||
total_width = sum(img.width for img in cached)
|
total_width = sum(img.width for img in cached)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Using cached content: %d images, %dpx total",
|
"[%s] Using cached content: %d images, %dpx total",
|
||||||
plugin_id, len(cached), total_width
|
plugin_id, len(cached), total_width
|
||||||
)
|
)
|
||||||
@@ -126,46 +126,46 @@ class PluginAdapter:
|
|||||||
|
|
||||||
# Try native Vegas content method first
|
# Try native Vegas content method first
|
||||||
has_native = hasattr(plugin, 'get_vegas_content')
|
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:
|
if has_native:
|
||||||
content = self._get_native_content(plugin, plugin_id, offscreen_only)
|
content = self._get_native_content(plugin, plugin_id, offscreen_only)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native content SUCCESS: %d images, %dpx total",
|
"[%s] Native content SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
return self._finalize(content, plugin_id, 'native', plugin)
|
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)
|
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
|
||||||
has_scroll_helper = hasattr(plugin, 'scroll_helper')
|
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)
|
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
|
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
|
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
|
||||||
if has_scroll_helper:
|
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:
|
if offscreen_only:
|
||||||
# Display capture needs the shared canvas; leave it to the caller.
|
# Display capture needs the shared canvas; leave it to the caller.
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Needs display capture, deferring to the render thread",
|
"[%s] Needs display capture, deferring to the render thread",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
# Fall back to display capture
|
# 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)
|
content = self._capture_display_content(plugin, plugin_id)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
|
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
@@ -226,7 +226,7 @@ class PluginAdapter:
|
|||||||
kept.append(result.image)
|
kept.append(result.image)
|
||||||
|
|
||||||
if not kept:
|
if not kept:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] All %d image(s) from %s were blank — contributing nothing",
|
"[%s] All %d image(s) from %s were blank — contributing nothing",
|
||||||
plugin_id, len(images), source
|
plugin_id, len(images), source
|
||||||
)
|
)
|
||||||
@@ -235,14 +235,14 @@ class PluginAdapter:
|
|||||||
trimmed_width = sum(img.width for img in kept)
|
trimmed_width = sum(img.width for img in kept)
|
||||||
|
|
||||||
if trimmed_width < self.config.min_plugin_width:
|
if trimmed_width < self.config.min_plugin_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
|
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
|
||||||
plugin_id, trimmed_width, self.config.min_plugin_width
|
plugin_id, trimmed_width, self.config.min_plugin_width
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
if trimmed_width != original_width or dropped_blank:
|
if trimmed_width != original_width or dropped_blank:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
|
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
|
||||||
"%d image(s) kept, %d blank dropped",
|
"%d image(s) kept, %d blank dropped",
|
||||||
plugin_id, source, original_width, trimmed_width,
|
plugin_id, source, original_width, trimmed_width,
|
||||||
@@ -431,7 +431,7 @@ class PluginAdapter:
|
|||||||
"""
|
"""
|
||||||
if self._offset_shapes.get(plugin_id) != shape:
|
if self._offset_shapes.get(plugin_id) != shape:
|
||||||
if plugin_id in self._item_offsets:
|
if plugin_id in self._item_offsets:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Content is %s now, was %s — restarting the rotation "
|
"[%s] Content is %s now, was %s — restarting the rotation "
|
||||||
"rather than resuming at a position that no longer means "
|
"rather than resuming at a position that no longer means "
|
||||||
"anything", plugin_id, shape,
|
"anything", plugin_id, shape,
|
||||||
@@ -579,7 +579,7 @@ class PluginAdapter:
|
|||||||
consumed += 1
|
consumed += 1
|
||||||
|
|
||||||
if mode == 'truncate':
|
if mode == 'truncate':
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
|
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
|
||||||
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
|
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
|
||||||
plugin_id, budget, len(selected), len(images), used
|
plugin_id, budget, len(selected), len(images), used
|
||||||
@@ -587,7 +587,7 @@ class PluginAdapter:
|
|||||||
else:
|
else:
|
||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, (start + consumed) % len(images), shape)
|
plugin_id, (start + consumed) % len(images), shape)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
|
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
|
||||||
"from offset %d; remainder deferred to a later cycle",
|
"from offset %d; remainder deferred to a later cycle",
|
||||||
plugin_id, budget, len(selected), len(images), used, start
|
plugin_id, budget, len(selected), len(images), used, start
|
||||||
@@ -636,7 +636,7 @@ class PluginAdapter:
|
|||||||
if mode != 'truncate':
|
if mode != 'truncate':
|
||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, 0 if end >= img.width else end, shape)
|
plugin_id, 0 if end >= img.width else end, shape)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: cropped continuous %dpx image to "
|
"[%s] Width budget %dpx: cropped continuous %dpx image to "
|
||||||
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
|
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
|
||||||
plugin_id, budget, img.width, offset, end, min_run,
|
plugin_id, budget, img.width, offset, end, min_run,
|
||||||
@@ -674,7 +674,7 @@ class PluginAdapter:
|
|||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, 0 if end >= img.width else end_index, shape)
|
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] "
|
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
|
||||||
"(%dpx) at item boundaries %d-%d of %d, %s",
|
"(%dpx) at item boundaries %d-%d of %d, %s",
|
||||||
plugin_id, budget, img.width, start, end, end - start,
|
plugin_id, budget, img.width, start, end, end - start,
|
||||||
@@ -698,7 +698,7 @@ class PluginAdapter:
|
|||||||
List of images or None
|
List of images or None
|
||||||
"""
|
"""
|
||||||
try:
|
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
|
# 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
|
# 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().
|
# be explicit can read get_vegas_render_width().
|
||||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||||
if render_width != self.display_width:
|
if render_width != self.display_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: requesting %dpx instead of %dpx",
|
"[%s] Native: requesting %dpx instead of %dpx",
|
||||||
plugin_id, render_width, self.display_width
|
plugin_id, render_width, self.display_width
|
||||||
)
|
)
|
||||||
@@ -735,19 +735,19 @@ class PluginAdapter:
|
|||||||
plugin._vegas_render_width = None
|
plugin._vegas_render_width = None
|
||||||
|
|
||||||
if result is 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
|
return None
|
||||||
|
|
||||||
# Normalize to list
|
# Normalize to list
|
||||||
if isinstance(result, Image.Image):
|
if isinstance(result, Image.Image):
|
||||||
images = [result]
|
images = [result]
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: got single Image %dx%d",
|
"[%s] Native: got single Image %dx%d",
|
||||||
plugin_id, result.width, result.height
|
plugin_id, result.width, result.height
|
||||||
)
|
)
|
||||||
elif isinstance(result, (list, tuple)):
|
elif isinstance(result, (list, tuple)):
|
||||||
images = list(result)
|
images = list(result)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: got %d items in list/tuple",
|
"[%s] Native: got %d items in list/tuple",
|
||||||
plugin_id, len(images)
|
plugin_id, len(images)
|
||||||
)
|
)
|
||||||
@@ -768,14 +768,14 @@ class PluginAdapter:
|
|||||||
)
|
)
|
||||||
continue
|
continue
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: item[%d] is %dx%d, mode=%s",
|
"[%s] Native: item[%d] is %dx%d, mode=%s",
|
||||||
plugin_id, i, img.width, img.height, img.mode
|
plugin_id, i, img.width, img.height, img.mode
|
||||||
)
|
)
|
||||||
|
|
||||||
# Ensure correct height
|
# Ensure correct height
|
||||||
if img.height != self.display_height:
|
if img.height != self.display_height:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
|
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
|
||||||
plugin_id, i, img.width, img.height,
|
plugin_id, i, img.width, img.height,
|
||||||
img.width, self.display_height
|
img.width, self.display_height
|
||||||
@@ -793,13 +793,13 @@ class PluginAdapter:
|
|||||||
|
|
||||||
if valid_images:
|
if valid_images:
|
||||||
total_width = sum(img.width for img in valid_images)
|
total_width = sum(img.width for img in valid_images)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: SUCCESS - %d images, %dpx total width",
|
"[%s] Native: SUCCESS - %d images, %dpx total width",
|
||||||
plugin_id, len(valid_images), total_width
|
plugin_id, len(valid_images), total_width
|
||||||
)
|
)
|
||||||
return valid_images
|
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
|
return None
|
||||||
|
|
||||||
except (AttributeError, TypeError, ValueError, OSError) as e:
|
except (AttributeError, TypeError, ValueError, OSError) as e:
|
||||||
@@ -833,20 +833,20 @@ class PluginAdapter:
|
|||||||
logger.debug("[%s] No scroll_helper attribute", plugin_id)
|
logger.debug("[%s] No scroll_helper attribute", plugin_id)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Found scroll_helper: %s",
|
"[%s] Found scroll_helper: %s",
|
||||||
plugin_id, type(scroll_helper).__name__
|
plugin_id, type(scroll_helper).__name__
|
||||||
)
|
)
|
||||||
|
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is None:
|
if cached_image is None:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image is None, triggering content generation",
|
"[%s] scroll_helper.cached_image is None, triggering content generation",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
if offscreen_only:
|
if offscreen_only:
|
||||||
# Generating it calls display(), which needs the canvas.
|
# Generating it calls display(), which needs the canvas.
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper cache empty; deferring generation "
|
"[%s] scroll_helper cache empty; deferring generation "
|
||||||
"to the render thread", plugin_id
|
"to the render thread", plugin_id
|
||||||
)
|
)
|
||||||
@@ -859,13 +859,13 @@ class PluginAdapter:
|
|||||||
return None
|
return None
|
||||||
|
|
||||||
if not isinstance(cached_image, Image.Image):
|
if not isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image is not an Image: %s",
|
"[%s] scroll_helper.cached_image is not an Image: %s",
|
||||||
plugin_id, type(cached_image).__name__
|
plugin_id, type(cached_image).__name__
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
|
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
|
||||||
plugin_id, cached_image.width, cached_image.height, cached_image.mode
|
plugin_id, cached_image.width, cached_image.height, cached_image.mode
|
||||||
)
|
)
|
||||||
@@ -888,7 +888,7 @@ class PluginAdapter:
|
|||||||
|
|
||||||
# Ensure correct height
|
# Ensure correct height
|
||||||
if img.height != self.display_height:
|
if img.height != self.display_height:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
|
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
|
||||||
plugin_id, img.width, img.height,
|
plugin_id, img.width, img.height,
|
||||||
img.width, self.display_height
|
img.width, self.display_height
|
||||||
@@ -902,7 +902,7 @@ class PluginAdapter:
|
|||||||
if img.mode != 'RGB':
|
if img.mode != 'RGB':
|
||||||
img = img.convert('RGB')
|
img = img.convert('RGB')
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] ScrollHelper content ready: %dx%d",
|
"[%s] ScrollHelper content ready: %dx%d",
|
||||||
plugin_id, img.width, img.height
|
plugin_id, img.width, img.height
|
||||||
)
|
)
|
||||||
@@ -1002,7 +1002,7 @@ class PluginAdapter:
|
|||||||
with self._capture():
|
with self._capture():
|
||||||
# Method 1: Try _create_scrolling_display (stocks pattern)
|
# Method 1: Try _create_scrolling_display (stocks pattern)
|
||||||
if hasattr(plugin, '_create_scrolling_display'):
|
if hasattr(plugin, '_create_scrolling_display'):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Triggering via _create_scrolling_display()",
|
"[%s] Triggering via _create_scrolling_display()",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1010,7 +1010,7 @@ class PluginAdapter:
|
|||||||
plugin._create_scrolling_display()
|
plugin._create_scrolling_display()
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
|
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
|
||||||
plugin_id, cached_image.width, cached_image.height
|
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
|
# Method 2: Try display(force_clear=True) which typically builds scroll content
|
||||||
if hasattr(plugin, 'display'):
|
if hasattr(plugin, 'display'):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Triggering via display(force_clear=True)",
|
"[%s] Triggering via display(force_clear=True)",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1031,12 +1031,12 @@ class PluginAdapter:
|
|||||||
plugin.display(force_clear=True)
|
plugin.display(force_clear=True)
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] display(force_clear=True) SUCCESS: %dx%d",
|
"[%s] display(force_clear=True) SUCCESS: %dx%d",
|
||||||
plugin_id, cached_image.width, cached_image.height
|
plugin_id, cached_image.width, cached_image.height
|
||||||
)
|
)
|
||||||
return cached_image
|
return cached_image
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] display(force_clear=True) did not populate cached_image",
|
"[%s] display(force_clear=True) did not populate cached_image",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1045,7 +1045,7 @@ class PluginAdapter:
|
|||||||
"[%s] display(force_clear=True) failed", plugin_id
|
"[%s] display(force_clear=True) failed", plugin_id
|
||||||
)
|
)
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Could not trigger scroll content generation",
|
"[%s] Could not trigger scroll content generation",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1077,15 +1077,15 @@ class PluginAdapter:
|
|||||||
try:
|
try:
|
||||||
# Save current display state
|
# Save current display state
|
||||||
original_image = self.display_manager.image.copy()
|
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
|
# Ensure plugin has fresh data before capturing
|
||||||
has_update_data = hasattr(plugin, 'update_data')
|
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:
|
if has_update_data:
|
||||||
try:
|
try:
|
||||||
plugin.update_data()
|
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):
|
except (AttributeError, RuntimeError, OSError):
|
||||||
logger.exception("[%s] Fallback: update_data() failed", plugin_id)
|
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.
|
# arrangement rather than one that has to be cropped afterwards.
|
||||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||||
if render_width != self.display_width:
|
if render_width != self.display_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: rendering at %dpx instead of %dpx",
|
"[%s] Fallback: rendering at %dpx instead of %dpx",
|
||||||
plugin_id, render_width, self.display_width
|
plugin_id, render_width, self.display_width
|
||||||
)
|
)
|
||||||
|
|
||||||
with self._capture(), self._render_at(render_width):
|
with self._capture(), self._render_at(render_width):
|
||||||
self.display_manager.clear()
|
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)
|
# First try without force_clear (some plugins behave better this way)
|
||||||
try:
|
try:
|
||||||
plugin.display()
|
plugin.display()
|
||||||
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
|
logger.info("[%s] Fallback: display() called successfully", plugin_id)
|
||||||
except TypeError:
|
except TypeError:
|
||||||
# Plugin may require force_clear argument
|
# 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)
|
plugin.display(force_clear=True)
|
||||||
|
|
||||||
# Capture the result
|
# Capture the result
|
||||||
captured = self.display_manager.image.copy()
|
captured = self.display_manager.image.copy()
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: captured frame %dx%d, mode=%s",
|
"[%s] Fallback: captured frame %dx%d, mode=%s",
|
||||||
plugin_id, captured.width, captured.height, captured.mode
|
plugin_id, captured.width, captured.height, captured.mode
|
||||||
)
|
)
|
||||||
|
|
||||||
# Check if captured image has content (not all black)
|
# Check if captured image has content (not all black)
|
||||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
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%%)",
|
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
|
||||||
plugin_id, bright_ratio * 100
|
plugin_id, bright_ratio * 100
|
||||||
)
|
)
|
||||||
|
|
||||||
if is_blank:
|
if is_blank:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: first capture blank, retrying with force_clear",
|
"[%s] Fallback: first capture blank, retrying with force_clear",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1142,7 +1142,7 @@ class PluginAdapter:
|
|||||||
captured = self.display_manager.image.copy()
|
captured = self.display_manager.image.copy()
|
||||||
|
|
||||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
|
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
|
||||||
plugin_id, bright_ratio * 100
|
plugin_id, bright_ratio * 100
|
||||||
)
|
)
|
||||||
@@ -1159,7 +1159,7 @@ class PluginAdapter:
|
|||||||
if captured.mode != 'RGB':
|
if captured.mode != 'RGB':
|
||||||
captured = captured.convert('RGB')
|
captured = captured.convert('RGB')
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: SUCCESS - captured %dx%d",
|
"[%s] Fallback: SUCCESS - captured %dx%d",
|
||||||
plugin_id, captured.width, captured.height
|
plugin_id, captured.width, captured.height
|
||||||
)
|
)
|
||||||
|
|||||||
Regular → Executable
Regular → Executable
@@ -58,7 +58,7 @@ def repos(tmp_path):
|
|||||||
def test_branch_with_upstream_uses_a_plain_pull(repos):
|
def test_branch_with_upstream_uses_a_plain_pull(repos):
|
||||||
args, note, error = resolve_pull_command(str(repos))
|
args, note, error = resolve_pull_command(str(repos))
|
||||||
assert error is None
|
assert error is None
|
||||||
assert args == ['git', 'pull', '--rebase']
|
assert args == ['git', 'pull', '--rebase', '--autostash']
|
||||||
assert note == ''
|
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))
|
args, note, error = resolve_pull_command(str(repos))
|
||||||
assert error is None
|
assert error is None
|
||||||
assert args == ['git', 'pull', '--rebase', 'origin', 'audit']
|
assert args == ['git', 'pull', '--rebase', '--autostash', 'origin', 'audit']
|
||||||
assert 'audit' in note
|
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))
|
args, note, error = resolve_pull_command(str(repos))
|
||||||
assert error is None
|
assert error is None
|
||||||
assert args == ['git', 'pull', '--rebase']
|
assert args == ['git', 'pull', '--rebase', '--autostash']
|
||||||
assert note == ''
|
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'
|
assert _git('branch', '--show-current', cwd=repos).stdout.strip() == 'other'
|
||||||
# The edit is not lost — it is on the stash.
|
# The edit is not lost — it is on the stash.
|
||||||
assert 'switch to other' in _git('stash', 'list', cwd=repos).stdout
|
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")
|
||||||
|
|||||||
@@ -1,110 +0,0 @@
|
|||||||
"""A healthy plugin must not rewrite its health record every cycle.
|
|
||||||
|
|
||||||
Every successful plugin update called record_success(), which persisted the
|
|
||||||
record unconditionally. In steady state the only fields that had changed were
|
|
||||||
total_successes and last_success_time -- a counter and a timestamp that
|
|
||||||
health_monitor reads for display and that nothing reads back after a restart.
|
|
||||||
|
|
||||||
Measured on a rig running 24 plugins: about 17 health-file rewrites a minute,
|
|
||||||
roughly 25,000 a day. Each is ~400 bytes, but they land on an SD card where
|
|
||||||
the unit of cost is an erase-block cycle, not the byte count, and where wear is
|
|
||||||
what eventually kills the card.
|
|
||||||
|
|
||||||
The circuit breaker still needs its own state to survive a restart, so the
|
|
||||||
write is kept for exactly the fields it is rebuilt from -- and a failure, a
|
|
||||||
circuit opening, or a recovery must still be written the moment it happens.
|
|
||||||
"""
|
|
||||||
import time
|
|
||||||
|
|
||||||
import pytest
|
|
||||||
|
|
||||||
from src.plugin_system.plugin_health import PluginHealthTracker, CircuitState
|
|
||||||
|
|
||||||
|
|
||||||
class _Cache:
|
|
||||||
"""Counts writes; serves back whatever was last written."""
|
|
||||||
|
|
||||||
def __init__(self):
|
|
||||||
self.store = {}
|
|
||||||
self.writes = 0
|
|
||||||
|
|
||||||
def set(self, key, data, ttl=None, **kwargs):
|
|
||||||
self.writes += 1
|
|
||||||
self.store[key] = data
|
|
||||||
|
|
||||||
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
|
|
||||||
return self.store.get(key)
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.fixture
|
|
||||||
def tracker():
|
|
||||||
cache = _Cache()
|
|
||||||
t = PluginHealthTracker(cache_manager=cache)
|
|
||||||
return t, cache
|
|
||||||
|
|
||||||
|
|
||||||
def test_steady_state_success_stops_writing(tracker):
|
|
||||||
"""The regression: 100 healthy cycles used to be 100 SD writes."""
|
|
||||||
t, cache = tracker
|
|
||||||
t.record_success("weather")
|
|
||||||
first = cache.writes
|
|
||||||
for _ in range(100):
|
|
||||||
t.record_success("weather")
|
|
||||||
assert cache.writes == first, (
|
|
||||||
f"{cache.writes - first} redundant writes across 100 healthy cycles"
|
|
||||||
)
|
|
||||||
|
|
||||||
|
|
||||||
def test_the_counters_are_still_accurate_in_memory(tracker):
|
|
||||||
"""Skipping the write must not skip the bookkeeping."""
|
|
||||||
t, _ = tracker
|
|
||||||
for _ in range(10):
|
|
||||||
t.record_success("weather")
|
|
||||||
state = t.get_health_state("weather")
|
|
||||||
assert state["total_successes"] == 10
|
|
||||||
assert state["last_success_time"] is not None
|
|
||||||
assert state["last_success_time"] <= time.time()
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_failure_is_written_immediately(tracker):
|
|
||||||
t, cache = tracker
|
|
||||||
t.record_success("weather")
|
|
||||||
before = cache.writes
|
|
||||||
t.record_failure("weather", RuntimeError("boom"))
|
|
||||||
assert cache.writes > before, "a failure must reach disk"
|
|
||||||
|
|
||||||
|
|
||||||
def test_recovery_after_failure_is_written(tracker):
|
|
||||||
"""consecutive_failures returning to 0 is durable state changing."""
|
|
||||||
t, cache = tracker
|
|
||||||
t.record_failure("weather", RuntimeError("boom"))
|
|
||||||
before = cache.writes
|
|
||||||
t.record_success("weather")
|
|
||||||
assert cache.writes > before, "recovery must reach disk"
|
|
||||||
assert t.get_health_state("weather")["consecutive_failures"] == 0
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_closing_circuit_is_written(tracker):
|
|
||||||
"""Success in half-open closes the circuit -- that must survive a restart."""
|
|
||||||
t, cache = tracker
|
|
||||||
state = t.get_health_state("weather")
|
|
||||||
state["circuit_state"] = CircuitState.HALF_OPEN.value
|
|
||||||
state["half_open_start_time"] = time.time()
|
|
||||||
before = cache.writes
|
|
||||||
t.record_success("weather")
|
|
||||||
assert cache.writes > before, "a circuit transition must reach disk"
|
|
||||||
assert t.get_health_state("weather")["circuit_state"] == CircuitState.CLOSED.value
|
|
||||||
|
|
||||||
|
|
||||||
def test_durable_state_survives_a_restart(tracker):
|
|
||||||
"""What is skipped must genuinely not matter to the breaker."""
|
|
||||||
t, cache = tracker
|
|
||||||
for _ in range(3):
|
|
||||||
t.record_failure("weather", RuntimeError("boom"))
|
|
||||||
for _ in range(50):
|
|
||||||
t.record_success("weather")
|
|
||||||
|
|
||||||
revived = PluginHealthTracker(cache_manager=cache)
|
|
||||||
state = revived.get_health_state("weather")
|
|
||||||
assert state["consecutive_failures"] == 0
|
|
||||||
assert state["circuit_state"] == CircuitState.CLOSED.value
|
|
||||||
@@ -1,101 +0,0 @@
|
|||||||
"""Log lines must reach the journal with their real severity.
|
|
||||||
|
|
||||||
Everything this process writes to stdout lands in the journal as PRIORITY=6,
|
|
||||||
whatever the Python level was, because journald has no other signal. Measured
|
|
||||||
on a live rig over 24 hours: 55 lines containing " - ERROR - " and 13
|
|
||||||
containing " - WARNING - ", every one of them recorded as informational. So
|
|
||||||
|
|
||||||
journalctl -p err -u ledmatrix
|
|
||||||
|
|
||||||
returned nothing while errors were being logged, and anyone triaging has to
|
|
||||||
grep the message text instead. That is slower and it is wrong: a search for
|
|
||||||
"oom" also matches the radar logging "zoom=9", which is exactly the false
|
|
||||||
positive it produced during this audit.
|
|
||||||
|
|
||||||
systemd reads a leading "<N>" on each stdout line and uses it as the priority
|
|
||||||
(sd-daemon(3)), so this needs no extra dependency -- and it must only be
|
|
||||||
applied when systemd is actually reading, or the prefixes become literal noise
|
|
||||||
in a terminal, the emulator, and test output.
|
|
||||||
"""
|
|
||||||
import logging
|
|
||||||
import os
|
|
||||||
from unittest.mock import patch
|
|
||||||
|
|
||||||
import pytest
|
|
||||||
|
|
||||||
from src.logging_config import JournalPriorityFormatter, _SYSLOG_PRIORITY, _under_systemd
|
|
||||||
|
|
||||||
|
|
||||||
class _Plain(logging.Formatter):
|
|
||||||
def format(self, record):
|
|
||||||
return record.getMessage()
|
|
||||||
|
|
||||||
|
|
||||||
def _record(level, msg="hello"):
|
|
||||||
return logging.LogRecord("t", level, "f.py", 1, msg, None, None)
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.parametrize("level,expected", [
|
|
||||||
(logging.CRITICAL, 2),
|
|
||||||
(logging.ERROR, 3),
|
|
||||||
(logging.WARNING, 4),
|
|
||||||
(logging.INFO, 6),
|
|
||||||
(logging.DEBUG, 7),
|
|
||||||
])
|
|
||||||
def test_each_level_maps_to_its_syslog_priority(level, expected):
|
|
||||||
out = JournalPriorityFormatter(_Plain()).format(_record(level))
|
|
||||||
assert out.startswith(f"<{expected}>"), out
|
|
||||||
assert _SYSLOG_PRIORITY[level] == expected
|
|
||||||
|
|
||||||
|
|
||||||
def test_error_and_info_are_distinguishable():
|
|
||||||
"""The whole point: journalctl -p err must be able to tell them apart."""
|
|
||||||
fmt = JournalPriorityFormatter(_Plain())
|
|
||||||
assert fmt.format(_record(logging.ERROR))[:3] != fmt.format(_record(logging.INFO))[:3]
|
|
||||||
|
|
||||||
|
|
||||||
def test_every_line_of_a_multiline_record_is_tagged():
|
|
||||||
"""The journal splits them, and an untagged continuation loses its level.
|
|
||||||
|
|
||||||
A traceback is the case that matters -- it is the most important thing in
|
|
||||||
the log and the longest.
|
|
||||||
"""
|
|
||||||
out = JournalPriorityFormatter(_Plain()).format(
|
|
||||||
_record(logging.ERROR, "Traceback:\nline one\nline two"))
|
|
||||||
lines = out.split("\n")
|
|
||||||
assert len(lines) == 3
|
|
||||||
assert all(line.startswith("<3>") for line in lines), lines
|
|
||||||
|
|
||||||
|
|
||||||
def test_the_message_survives_intact():
|
|
||||||
out = JournalPriorityFormatter(_Plain()).format(_record(logging.WARNING, "disk full"))
|
|
||||||
assert out == "<4>disk full"
|
|
||||||
|
|
||||||
|
|
||||||
def test_an_unknown_level_falls_back_to_info():
|
|
||||||
out = JournalPriorityFormatter(_Plain()).format(_record(25))
|
|
||||||
assert out.startswith("<6>")
|
|
||||||
|
|
||||||
|
|
||||||
def test_prefixing_is_off_outside_systemd():
|
|
||||||
"""Otherwise a terminal run, the emulator and pytest all show `<6>`."""
|
|
||||||
with patch.dict(os.environ, {}, clear=True):
|
|
||||||
assert not _under_systemd()
|
|
||||||
with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}):
|
|
||||||
assert _under_systemd()
|
|
||||||
|
|
||||||
|
|
||||||
def test_setup_uses_the_wrapper_only_under_systemd():
|
|
||||||
from src.logging_config import setup_logging
|
|
||||||
|
|
||||||
for env, expect_wrapped in (({}, False), ({"JOURNAL_STREAM": "8:1"}, True)):
|
|
||||||
with patch.dict(os.environ, env, clear=True):
|
|
||||||
setup_logging()
|
|
||||||
handlers = [h for h in logging.getLogger().handlers
|
|
||||||
if isinstance(h, logging.StreamHandler)]
|
|
||||||
assert handlers, "no stream handler installed"
|
|
||||||
wrapped = any(isinstance(h.formatter, JournalPriorityFormatter)
|
|
||||||
for h in handlers)
|
|
||||||
assert wrapped is expect_wrapped, (
|
|
||||||
f"JOURNAL_STREAM={env}: wrapped={wrapped}, expected {expect_wrapped}")
|
|
||||||
logging.getLogger().handlers.clear()
|
|
||||||
@@ -183,27 +183,15 @@ class TestSetupLogging:
|
|||||||
setup_logging()
|
setup_logging()
|
||||||
assert len(logging.getLogger().handlers) == 1
|
assert len(logging.getLogger().handlers) == 1
|
||||||
|
|
||||||
@staticmethod
|
|
||||||
def _selected_formatter():
|
|
||||||
"""The formatter setup_logging() chose, past any journald wrapper.
|
|
||||||
|
|
||||||
Under systemd the console handler's formatter is wrapped so each line
|
|
||||||
carries its syslog priority. That wrapper is applied only when
|
|
||||||
JOURNAL_STREAM is set, which is true in CI and false in a terminal, so
|
|
||||||
asserting on the handler's formatter directly passes locally and fails
|
|
||||||
on the runner. These tests are about which formatter format_type
|
|
||||||
selects, so they look through the wrapper.
|
|
||||||
"""
|
|
||||||
formatter = logging.getLogger().handlers[0].formatter
|
|
||||||
return getattr(formatter, "inner", formatter)
|
|
||||||
|
|
||||||
def test_json_format_selects_structured_formatter(self):
|
def test_json_format_selects_structured_formatter(self):
|
||||||
setup_logging(format_type="json")
|
setup_logging(format_type="json")
|
||||||
assert isinstance(self._selected_formatter(), StructuredFormatter)
|
assert isinstance(
|
||||||
|
logging.getLogger().handlers[0].formatter, StructuredFormatter)
|
||||||
|
|
||||||
def test_readable_format_selects_contextual_formatter(self):
|
def test_readable_format_selects_contextual_formatter(self):
|
||||||
setup_logging(format_type="readable")
|
setup_logging(format_type="readable")
|
||||||
assert isinstance(self._selected_formatter(), ContextualFormatter)
|
assert isinstance(
|
||||||
|
logging.getLogger().handlers[0].formatter, ContextualFormatter)
|
||||||
|
|
||||||
def test_log_file_adds_file_handler(self, tmp_path):
|
def test_log_file_adds_file_handler(self, tmp_path):
|
||||||
log_file = tmp_path / "test.log"
|
log_file = tmp_path / "test.log"
|
||||||
|
|||||||
@@ -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
|
|
||||||
@@ -1657,13 +1657,22 @@ def resolve_pull_command(project_dir):
|
|||||||
backup, or following an install guide that names one. The update button
|
backup, or following an install guide that names one. The update button
|
||||||
then reports a failure the user cannot act on.
|
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
|
Returns ``(args, note, error)``. When ``origin/<branch>`` exists the pull
|
||||||
is made explicit against it, so the update proceeds and the branch is
|
is made explicit against it, so the update proceeds and the branch is
|
||||||
given tracking information afterwards.
|
given tracking information afterwards.
|
||||||
"""
|
"""
|
||||||
upstream = _git_upstream(project_dir)
|
upstream = _git_upstream(project_dir)
|
||||||
if upstream:
|
if upstream:
|
||||||
return ['git', 'pull', '--rebase'], '', None
|
return ['git', 'pull', '--rebase', '--autostash'], '', None
|
||||||
|
|
||||||
branch = _git_current_branch(project_dir)
|
branch = _git_current_branch(project_dir)
|
||||||
if not branch:
|
if not branch:
|
||||||
@@ -1673,7 +1682,7 @@ def resolve_pull_command(project_dir):
|
|||||||
)
|
)
|
||||||
if _git_remote_branch_exists(project_dir, branch):
|
if _git_remote_branch_exists(project_dir, branch):
|
||||||
return (
|
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.",
|
f"Branch '{branch}' had no upstream; pulled from origin/{branch} and set it as the upstream.",
|
||||||
None,
|
None,
|
||||||
)
|
)
|
||||||
|
|||||||
Reference in New Issue
Block a user