Browse Source

feat(usage-tracker): add diagnostic logging for slot-to-tray mapping investigation

Usage tracking works on X1E but fails on H2D Pro — the wrong tray
is identified, attributing usage to the wrong spool. The root cause
is unknown because we don't know what MQTT mapping data each printer
model reports.

Adds INFO-level logging at print start and completion:
- state.raw_data["mapping"] (unknown format, preserved but never parsed)
- tray_now, last_loaded_tray values
- All raw_data keys containing "map" (discovery)
- Per-AMS-tray summary: tray_type, tray_color, tray_now, tray_tar

This enables comparing MQTT behavior across printer models without
requiring DEBUG mode, so testers can send normal logs.
maziggy 3 months ago
parent
commit
ca9ffbba5d
3 changed files with 41 additions and 1 deletions
  1. 1 0
      CHANGELOG.md
  2. 38 1
      backend/app/services/usage_tracker.py
  3. 2 0
      backend/tests/unit/test_usage_tracker.py

+ 1 - 0
CHANGELOG.md

@@ -51,6 +51,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **Spool Assignments Falsely Unlinked After Print Due to Color Variation** — The auto-unlink logic compared AMS tray colors against saved fingerprints using exact hex match. RFID sensors report slightly different color values across reads (e.g. `7CC4D5FF` vs `56B7E6FF` for the same spool, Euclidean distance ~43.6). Now uses a color similarity function with a tolerance threshold of 50, preventing false unlinks from minor RFID/firmware color variations while still detecting genuinely different spools.
 - **Spool Assignments Falsely Unlinked After Print Due to Color Variation** — The auto-unlink logic compared AMS tray colors against saved fingerprints using exact hex match. RFID sensors report slightly different color values across reads (e.g. `7CC4D5FF` vs `56B7E6FF` for the same spool, Euclidean distance ~43.6). Now uses a color similarity function with a tolerance threshold of 50, preventing false unlinks from minor RFID/firmware color variations while still detecting genuinely different spools.
 
 
 ### Improved
 ### Improved
+- **Usage Tracking Diagnostic Logging** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — Added INFO-level logging at print start and completion that dumps the printer's MQTT `mapping` field, `tray_now`, `last_loaded_tray`, all mapping-related raw data keys, and per-AMS-tray summaries (type, color, tray_now, tray_tar). Enables investigating the slot-to-tray mapping behavior across different printer models (X1E, H2D Pro, P1S, etc.) without requiring DEBUG mode.
 - **Skip Objects: Click-to-Enlarge Lightbox** ([#396](https://github.com/maziggy/bambuddy/issues/396)) — The skip objects modal's small 208px image panel made it difficult to distinguish object markers when parts are small or close together. Clicking the image now opens a fullscreen lightbox overlay with the same image and markers at a much larger size (up to 600px). The 24px marker circles are proportionally smaller relative to the enlarged image, solving the overlap problem. Close via X button, Escape key, or clicking the backdrop. Escape cascades correctly — closes lightbox first, then the modal.
 - **Skip Objects: Click-to-Enlarge Lightbox** ([#396](https://github.com/maziggy/bambuddy/issues/396)) — The skip objects modal's small 208px image panel made it difficult to distinguish object markers when parts are small or close together. Clicking the image now opens a fullscreen lightbox overlay with the same image and markers at a much larger size (up to 600px). The 24px marker circles are proportionally smaller relative to the enlarged image, solving the overlap problem. Close via X button, Escape key, or clicking the backdrop. Escape cascades correctly — closes lightbox first, then the modal.
 - **Phantom Print Investigation — Logging & Hardening** ([#374](https://github.com/maziggy/bambuddy/issues/374)) — Added targeted logging and hardening to help diagnose reports of prints starting automatically without user input. Debug log volume reduced ~90% by suppressing `sqlalchemy.engine` (changed from INFO to WARNING) and `aiosqlite` (new WARNING suppression) noise that previously filled 2.5MB in 16 minutes. Every `start_print()` call now logs a `PRINT COMMAND` trace with the caller's file, line, and function name. The print scheduler logs pending queue items when found. `on_print_complete` warns when multiple queue items are in "printing" status for the same printer, which signals a state inconsistency.
 - **Phantom Print Investigation — Logging & Hardening** ([#374](https://github.com/maziggy/bambuddy/issues/374)) — Added targeted logging and hardening to help diagnose reports of prints starting automatically without user input. Debug log volume reduced ~90% by suppressing `sqlalchemy.engine` (changed from INFO to WARNING) and `aiosqlite` (new WARNING suppression) noise that previously filled 2.5MB in 16 minutes. Every `start_print()` call now logs a `PRINT COMMAND` trace with the caller's file, line, and function name. The print scheduler logs pending queue items when found. `on_print_complete` warns when multiple queue items are in "printing" status for the same printer, which signals a state inconsistency.
 - **Reduce Log Noise from MQTT Diagnostics** ([#365](https://github.com/maziggy/bambuddy/issues/365)) — Downgraded 58 high-frequency MQTT diagnostic messages from INFO to DEBUG level. Payload dumps, detector state changes, field discovery logs, H2D disambiguation, and periodic status updates no longer flood the log at the default INFO level. Also suppresses paho-mqtt library INFO messages in production. User-initiated actions (print start/stop, AMS load/unload, calibration) remain at INFO. All diagnostic detail is still available when debug logging is enabled.
 - **Reduce Log Noise from MQTT Diagnostics** ([#365](https://github.com/maziggy/bambuddy/issues/365)) — Downgraded 58 high-frequency MQTT diagnostic messages from INFO to DEBUG level. Payload dumps, detector state changes, field discovery logs, H2D disambiguation, and periodic status updates no longer flood the log at the default INFO level. Also suppresses paho-mqtt library INFO messages in production. User-initiated actions (print start/stop, AMS load/unload, calibration) remain at INFO. All diagnostic detail is still available when debug logging is enabled.

+ 38 - 1
backend/app/services/usage_tracker.py

@@ -63,6 +63,33 @@ async def on_print_start(printer_id: int, data: dict, printer_manager) -> None:
     # Capture tray_now at print start (reliable, unlike at completion where it's 255)
     # Capture tray_now at print start (reliable, unlike at completion where it's 255)
     tray_now_at_start = state.tray_now if state else -1
     tray_now_at_start = state.tray_now if state else -1
 
 
+    # --- Diagnostic logging: dump mapping-related MQTT fields at print start ---
+    # This helps us understand what each printer model reports for slot-to-tray mapping.
+    mapping_field = state.raw_data.get("mapping")
+    logger.info(
+        "[UsageTracker] PRINT START printer %d: mapping=%s, tray_now=%d, last_loaded_tray=%s",
+        printer_id,
+        mapping_field,
+        tray_now_at_start,
+        getattr(state, "last_loaded_tray", "N/A"),
+    )
+    # Log all raw_data keys containing "map" or "ams" for discovery
+    map_keys = {k: state.raw_data[k] for k in state.raw_data if "map" in k.lower()}
+    if map_keys:
+        logger.info("[UsageTracker] PRINT START printer %d: mapping-related keys: %s", printer_id, map_keys)
+    # Log per-tray summary: tray_now, tray_tar, tray_type, tray_color for each slot
+    for ams_unit in ams_data:
+        ams_id = int(ams_unit.get("id", 0))
+        tray_summary = []
+        for tray in ams_unit.get("tray", []):
+            tray_summary.append(
+                f"T{tray.get('id', '?')}(type={tray.get('tray_type', '')}, "
+                f"color={tray.get('tray_color', '')}, "
+                f"now={ams_raw.get('tray_now', '?') if isinstance(ams_raw, dict) else '?'}, "
+                f"tar={ams_raw.get('tray_tar', '?') if isinstance(ams_raw, dict) else '?'})"
+            )
+        logger.info("[UsageTracker] PRINT START printer %d AMS %d: %s", printer_id, ams_id, ", ".join(tray_summary))
+
     # Always create session (even without valid remain data) so print_name
     # Always create session (even without valid remain data) so print_name
     # is available at completion for 3MF-based tracking
     # is available at completion for 3MF-based tracking
     session = PrintSession(
     session = PrintSession(
@@ -73,7 +100,6 @@ async def on_print_start(printer_id: int, data: dict, printer_manager) -> None:
         tray_now_at_start=tray_now_at_start,
         tray_now_at_start=tray_now_at_start,
     )
     )
     _active_sessions[printer_id] = session
     _active_sessions[printer_id] = session
-    logger.info("[UsageTracker] Captured tray_now=%d at print start for printer %d", tray_now_at_start, printer_id)
 
 
     if tray_remain_start:
     if tray_remain_start:
         logger.info(
         logger.info(
@@ -115,6 +141,17 @@ async def on_print_complete(
         ams_mapping,
         ams_mapping,
     )
     )
 
 
+    # --- Diagnostic logging: dump mapping-related MQTT fields at print completion ---
+    state = printer_manager.get_status(printer_id)
+    if state and state.raw_data:
+        logger.info(
+            "[UsageTracker] PRINT COMPLETE printer %d: mapping=%s, tray_now=%s, last_loaded_tray=%s",
+            printer_id,
+            state.raw_data.get("mapping"),
+            state.tray_now,
+            getattr(state, "last_loaded_tray", "N/A"),
+        )
+
     # --- Path 1 (PRIMARY): 3MF per-filament estimates ---
     # --- Path 1 (PRIMARY): 3MF per-filament estimates ---
     if archive_id:
     if archive_id:
         print_name = (
         print_name = (

+ 2 - 0
backend/tests/unit/test_usage_tracker.py

@@ -235,6 +235,8 @@ class TestOnPrintComplete:
         printer_manager = MagicMock()
         printer_manager = MagicMock()
         printer_manager.get_status.return_value = SimpleNamespace(
         printer_manager.get_status.return_value = SimpleNamespace(
             raw_data={"ams": [{"id": 0, "tray": [{"id": 0, "remain": 70}]}]},
             raw_data={"ams": [{"id": 0, "tray": [{"id": 0, "remain": 70}]}]},
+            tray_now=0,
+            last_loaded_tray=-1,
         )
         )
 
 
         # db returns assignment then spool
         # db returns assignment then spool