Bug report logs 5a1b8028a6554fafb1c07fafe7fca9b5.log

logs/5a1b8028a6554fafb1c07fafe7fca9b5.log

@@ -0,0 +1,200 @@
+2026-08-22 03:01:51,740 INFO [backend.app.api.routes.printers] [eada4dd8] Cover: resolved plate 1 before download (subtask=0.24mm layer, 2 walls, 5% infill)
+2026-08-22 03:01:51,797 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:01:51,801 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:01:52,025 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:02:21,082 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:02:21,089 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:02:21,321 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:02:46,459 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:02:46,461 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:02:46,860 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:03:12,933 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:03:12,940 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:03:13,218 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:03:17,017 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:03:17,021 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:03:17,248 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:03:45,379 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] PRINT COMPLETE detected - state: FINISH, status: completed, file: /data/Metadata/plate_1.gcode, subtask: 0.24mm layer, 2 walls, 5% infill, was_running: True, timelapse_during_print: True
+2026-08-22 03:03:45,381 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] FINISH PHOTO MOMENT (FINISH fallback) — stage-22 never fired; capturing at FINISH-state transition
+2026-08-22 03:03:45,388 INFO [backend.app.main] [-] [FINISH-PHOTO-MOMENT] printer=1 trigger=finish_state timelapse_active=True
+2026-08-22 03:03:45,390 INFO [backend.app.main] [-] [FINISH-PHOTO-MOMENT] timelapse active for printer 1 — skipping pre-capture (last-frame extraction will run post-completion)
+2026-08-22 03:03:45,392 INFO [backend.app.main] [-] [CALLBACK] on_print_complete started for printer 1
+2026-08-22 03:03:45,393 INFO [backend.app.main] [-] [TIMING] WebSocket send_print_complete: 0.002s elapsed
+2026-08-22 03:03:45,395 INFO [backend.app.main] [-] Print complete - filename: /data/Metadata/plate_1.gcode, subtask: 0.24mm layer, 2 walls, 5% infill, status: completed
+2026-08-22 03:03:45,398 INFO [backend.app.main] [-] Looking for archive in _active_prints, keys to try: [(1, '0.24mm layer, 2 walls, 5% infill.3mf'), (1, '0.24mm layer, 2 walls, 5% infill.gcode.3mf'), (1, '0.24mm layer, 2 walls, 5% infill'), (1, 'plate_1.gcode.3mf'), (1, 'plate_1.3mf')]...
+2026-08-22 03:03:45,402 INFO [backend.app.main] [-] Current _active_prints: []
+2026-08-22 03:03:45,518 INFO [backend.app.main] [-] Found archive 383 by subtask_name match: 0.24mm layer, 2 walls, 5% infill
+2026-08-22 03:03:45,718 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:45,892 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:46,080 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:46,100 INFO [backend.app.main] [-] [TIMING] SD card cleanup: 0.708s elapsed
+2026-08-22 03:03:46,110 INFO [backend.app.main] [-] [TIMING] Queue item update: 0.719s elapsed
+2026-08-22 03:03:46,141 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] on_print_complete: printer=1, archive=383, session=yes, ams_mapping=None
+2026-08-22 03:03:46,144 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT COMPLETE printer 1: mapping=[65535, 65535, 1, 3, 256], tray_now=255, last_loaded_tray=1
+2026-08-22 03:03:46,173 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: archive 383, plate_id=None, filament_usage=[{'slot_id': 3, 'used_g': 153.29, 'type': 'PLA', 'color': '#F72323'}, {'slot_id': 4, 'used_g': 4.03, 'type': 'PLA', 'color': '#46A8F9'}, {'slot_id': 5, 'used_g': 9.89, 'type': 'PLA', 'color': '#FFFFFF'}]
+2026-08-22 03:03:46,183 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: slot_to_tray=[-1, -1, 1, 3, 4] (source: mqtt)
+2026-08-22 03:03:46,187 WARNING [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: 129 tray changes observed but 3 filament slots used — splitting needs a single slot, attributing by mapping alone (printer 1, archive 383)
+2026-08-22 03:03:46,192 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: slot_id=3 -> global_tray=1 -> AMS0-T1 (used_g=153.3, tray_now_override=None)
+2026-08-22 03:03:46,218 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: no spool assignment at printer 1 AMS0-T1
+2026-08-22 03:03:46,222 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: slot_id=4 -> global_tray=3 -> AMS0-T3 (used_g=4.0, tray_now_override=None)
+2026-08-22 03:03:46,228 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: no spool assignment at printer 1 AMS0-T3
+2026-08-22 03:03:46,236 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: slot_id=5 -> global_tray=4 -> AMS1-T0 (used_g=9.9, tray_now_override=None)
+2026-08-22 03:03:46,247 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: no spool assignment at printer 1 AMS1-T0
+2026-08-22 03:03:46,260 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] VT254: not in print mapping/tray_change_log — skipping fallback for printer 1
+2026-08-22 03:03:46,268 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] VT255: not in print mapping/tray_change_log — skipping fallback for printer 1
+2026-08-22 03:03:46,302 INFO [backend.app.services.spoolman_tracking] [-] [SPOOLMAN] No tracking data for print (printer=1, archive=383)
+2026-08-22 03:03:46,313 INFO [backend.app.main] [-] [TIMING] Spoolman usage report: 0.921s elapsed
+2026-08-22 03:03:46,319 INFO [backend.app.main] [-] [TIMING] Filament usage tracking: 0.928s elapsed
+2026-08-22 03:03:46,329 INFO [backend.app.main] [-] [TIMING] Archive lookup: 0.938s elapsed
+2026-08-22 03:03:46,334 INFO [backend.app.main] [-] [ARCHIVE] Updating archive 383 status...
+2026-08-22 03:03:46,559 INFO [backend.app.main] [-] [ARCHIVE] Archive 383 status updated to completed, failure_reason=None
+2026-08-22 03:03:46,568 INFO [backend.app.main] [-] [ARCHIVE] WebSocket notification sent for archive 383
+2026-08-22 03:03:46,574 INFO [backend.app.main] [-] [TIMING] Archive status update: 1.183s elapsed
+2026-08-22 03:03:46,601 INFO [backend.app.services.finance_billing] [-] Billing is disabled; skipping print charge for archive ID 383.
+2026-08-22 03:03:46,606 INFO [backend.app.main] [-] [TIMING] Finance charge update: 1.215s elapsed
+2026-08-22 03:03:46,645 INFO [backend.app.main] [-] [PRINT_LOG] Log entry written for archive 383
+2026-08-22 03:03:46,656 INFO [backend.app.main] [-] [TIMING] Print log entry: 1.264s elapsed
+2026-08-22 03:03:46,674 INFO [backend.app.main] [-] [TIMING] Background tasks scheduled (energy, photo): 1.283s elapsed
+2026-08-22 03:03:46,682 INFO [backend.app.main] [-] [TIMING] All background tasks scheduled: 1.290s elapsed
+2026-08-22 03:03:46,692 INFO [backend.app.main] [-] [TIMELAPSE] Timelapse was active during print, scheduling auto-scan for archive 383
+2026-08-22 03:03:46,701 INFO [backend.app.main] [-] [TIMING] Timelapse scan scheduled: 1.309s elapsed
+2026-08-22 03:03:46,704 INFO [backend.app.main] [-] [CALLBACK] on_print_complete finished for printer 1, archive 383
+2026-08-22 03:03:46,711 INFO [backend.app.main] [-] [ENERGY-BG] Starting energy calculation for archive 383
+2026-08-22 03:03:46,719 INFO [backend.app.main] [-] [PHOTO-BG] Starting finish photo capture for archive 383
+2026-08-22 03:03:46,724 INFO [backend.app.main] [-] [AUTO-OFF-BG] Starting smart plug automation for printer 1
+2026-08-22 03:03:46,732 INFO [backend.app.main] [-] [MAINT-BG] Starting maintenance check for printer 1
+2026-08-22 03:03:46,738 INFO [backend.app.main] [-] [LAYER-TL] Stitching layer timelapse for printer 1
+2026-08-22 03:03:46,753 INFO [backend.app.main] [-] [ENERGY-BG] No start kWh recorded for archive 383
+2026-08-22 03:03:46,760 INFO [backend.app.main] [-] [TIMELAPSE] Using print-start baseline: 375 existing video files for archive 383
+2026-08-22 03:03:46,788 INFO [backend.app.main] [-] [AUTO-OFF-BG] Completed
+2026-08-22 03:03:46,829 INFO [backend.app.main] [-] [MAINT-BG] Completed (no items need attention)
+2026-08-22 03:03:51,962 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:52,037 INFO [backend.app.main] [-] [TIMELAPSE] Attempt 1: Found 376 video files in /timelapse
+2026-08-22 03:03:52,040 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-08_17-44-29.mp4
+2026-08-22 03:03:52,043 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-08_22-11-28.mp4
+2026-08-22 03:03:52,050 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_00-04-18.mp4
+2026-08-22 03:03:52,073 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_13-59-36.mp4
+2026-08-22 03:03:52,084 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_22-55-15.mp4
+2026-08-22 03:03:52,088 INFO [backend.app.main] [-] [TIMELAPSE] Attempt 1: New file detected: video_2026-08-21_20-05-54.mp4 (downloading for archive 383)
+2026-08-22 03:03:52,226 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:53,008 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:53,402 INFO [backend.app.main] [-] [TIMELAPSE] Successfully attached timelapse to archive 383
+2026-08-22 03:03:53,563 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:03:53,591 INFO [backend.app.services.bambu_ftp] [-] [TIMELAPSE] Deleted /timelapse/video_2026-08-21_20-05-54.mp4 from printer [PRINTER] after archiving
+2026-08-22 03:04:04,298 INFO [backend.app.main] [-] [PHOTO-BG] Extracted finish photo from timelapse video_2026-08-21_20-05-54.mp4 for archive 383
+2026-08-22 03:04:04,502 INFO [backend.app.main] [-] [PHOTO-BG] Saved: finish_20260822_030355_452e26ec.jpg
+2026-08-22 03:04:04,508 INFO [backend.app.main] [-] [PHOTO-NOTIFY] Photo task returned: finish_20260822_030355_452e26ec.jpg
+2026-08-22 03:04:04,513 INFO [backend.app.main] [-] [NOTIFY-BG] Starting notifications for printer 1, photo=finish_20260822_030355_452e26ec.jpg
+2026-08-22 03:04:04,528 INFO [backend.app.main] [-] [NOTIFY-BG] Loaded finish photo bytes: 282449 bytes
+2026-08-22 03:04:04,533 INFO [backend.app.services.notification_service] [-] on_print_complete called for printer 1 ([PRINTER]), status=completed
+2026-08-22 03:04:04,547 INFO [backend.app.services.notification_service] [-] Found 1 providers for on_print_complete: ['Discord']
+2026-08-22 03:04:05,399 INFO [backend.app.services.notification_service] [-] Sent notification via Discord
+2026-08-22 03:04:05,406 INFO [backend.app.main] [-] [NOTIFY-BG] Completed
+2026-08-22 03:05:05,245 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS 0500050000010007 cleared — re-probing developer mode
+2026-08-22 03:05:33,016 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS Filament Backup: OFF
+2026-08-22 03:05:35,541 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS Filament Backup: ON
+2026-08-22 03:05:37,371 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] PRINT START detected - file: /data/Metadata/plate_1.gcode, subtask: Large (9cm) - 0.2mm layer, 2 walls, 15% infill, is_new: True, is_file_change: False
+2026-08-22 03:05:37,375 INFO [backend.app.main] [-] [CALLBACK] on_print_start called for printer 1, data keys: ['filename', 'subtask_name', 'remaining_time', 'raw_data', 'ams_mapping']
+2026-08-22 03:05:37,462 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] Skipped trays with invalid remain% for printer 1: AMS0-T0(remain=-1), AMS0-T1(remain=-1), AMS0-T2(remain=-1), AMS0-T3(remain=-1), AMS1-T0(remain=-1), AMS1-T1(remain=-1), AMS1-T2(remain=-1), AMS1-T3(remain=-1), AMS128-T0(remain=-1), AMS129-T0(remain=-1)
+2026-08-22 03:05:37,473 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1: mapping=[65535, 65535, 65535, 65535, 3], tray_now=255, last_loaded_tray=1
+2026-08-22 03:05:37,499 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1: mapping-related keys: {'mapping': [65535, 65535, 65535, 65535, 3], 'ams_extruder_map': {'0': 0, '1': 0, '128': 1, '129': 1}}
+2026-08-22 03:05:37,514 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 0: T0(type=PLA, color=F330F9FF, now=?, tar=?), T1(type=PLA, color=F72323FF, now=?, tar=?), T2(type=PLA, color=0D6284FF, now=?, tar=?), T3(type=PLA, color=46A8F9FF, now=?, tar=?)
+2026-08-22 03:05:37,520 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 1: T0(type=PLA, color=FFFFFFFF, now=?, tar=?), T1(type=, color=, now=?, tar=?), T2(type=, color=, now=?, tar=?), T3(type=PLA, color=161616FF, now=?, tar=?)
+2026-08-22 03:05:37,523 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 128: T0(type=, color=, now=?, tar=?)
+2026-08-22 03:05:37,528 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 129: T0(type=, color=, now=?, tar=?)
+2026-08-22 03:05:37,575 INFO [backend.app.api.routes.printers] [c55fd839] Cover: resolved plate 1 before download (subtask=Large (9cm) - 0.2mm layer, 2 walls, 15% infill)
+2026-08-22 03:05:37,579 INFO [backend.app.api.routes.printers] [c55fd839] Trying to download cover for 'Large (9cm) - 0.2mm layer, 2 walls, 15% infill' from [IP] (trying 16 paths)
+2026-08-22 03:05:37,727 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] Captured start remain% for printer 1 (2 trays): {'255-0': 0, '255-1': 0}
+2026-08-22 03:05:37,764 INFO [backend.app.main] [-] [PLATE CHECK] printer_id=1, plate_detection_enabled=False
+2026-08-22 03:05:37,772 INFO [backend.app.main] [-] [CALLBACK] Print start detected - filename: /data/Metadata/plate_1.gcode, subtask: Large (9cm) - 0.2mm layer, 2 walls, 15% infill
+2026-08-22 03:05:37,776 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:05:37,848 INFO [backend.app.services.bambu_ftp] [-] FTP download failed for /Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf: 550 Failed to open file. (not on printer)
+2026-08-22 03:05:37,882 INFO [backend.app.main] [-] Trying filenames: ['Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf', 'Large (9cm) - 0.2mm layer, 2 walls, 15% infill.3mf', 'plate_1.gcode.3mf', 'plate_1.3mf', 'Large_(9cm)_-_0.2mm_layer,_2_walls,_15%_infill.gcode.3mf', 'Large_(9cm)_-_0.2mm_layer,_2_walls,_15%_infill.3mf']
+2026-08-22 03:05:38,082 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:05:38,106 INFO [backend.app.services.bambu_ftp] [-] FTP download failed for /Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf: 550 Failed to open file. (not on printer)
+2026-08-22 03:05:38,318 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:05:38,749 INFO [backend.app.services.bambu_ftp] [-] Successfully downloaded /cache/Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf to /app/data/archive/temp/cover_1_Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf (1088296 bytes)
+2026-08-22 03:05:38,759 INFO [backend.app.api.routes.printers] [c55fd839] Downloaded file size: 1088296 bytes
+2026-08-22 03:05:39,391 INFO [backend.app.services.bambu_ftp] [-] Successfully downloaded /cache/Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf to /app/data/archive/temp/Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf (1088296 bytes)
+2026-08-22 03:05:39,401 INFO [backend.app.services.bambu_ftp] [-] FTP mode cached for [IP]: prot_p
+2026-08-22 03:05:39,412 INFO [backend.app.main] [-] Downloaded: /cache/Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf
+2026-08-22 03:05:39,770 INFO [backend.app.main] [-] Created archive 384 for Large (9cm) - 0.2mm layer, 2 walls, 15% infill.gcode.3mf
+2026-08-22 03:05:39,777 INFO [backend.app.main] [-] [ENERGY] No smart plug for printer 1 (archive 384)
+2026-08-22 03:05:39,799 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:05:39,807 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:05:40,080 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:05:40,090 INFO [backend.app.services.notification_service] [-] on_print_start called for printer 1 ([PRINTER])
+2026-08-22 03:05:40,106 INFO [backend.app.services.notification_service] [-] No notification providers configured for print_start event on printer 1
+2026-08-22 03:05:40,116 INFO [backend.app.main] [-] Loaded 3 printable objects for printer 1
+2026-08-22 03:05:40,642 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-08-22 03:05:40,725 INFO [backend.app.main] [-] [TIMELAPSE] Baseline at print start: 375 video files for printer 1
+2026-08-22 03:06:09,467 INFO [backend.app.main] [-] Recorded 4 AMS sensor history entries
+2026-08-22 03:07:50,896 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Unnamed print stage 72 on model [PRINTER], entered from 74 (Preparing); state=RUNNING progress=0.0% layer=0/90
+2026-08-22 03:08:04,756 WARNING [backend.app.services.bambu_mqtt] [-] [[SERIAL]] H2D tray_now: multiple AMS [0, 1] on extruder 0, no snow field, using slot 3 (may be incorrect)
+2026-08-22 03:08:04,758 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Tray change during print: tray=3 at layer=0
+2026-08-22 03:08:20,740 INFO [backend.app.api.routes.cloud] [aab57238] get_filament_info called with 2 IDs: ['GFL99', 'GFN98']
+2026-08-22 03:08:21,115 INFO [uvicorn.access] [-] [IP]:45846 - "POST /api/v1/cloud/filament-info HTTP/1.1" 200
+2026-08-22 03:09:00,925 INFO [backend.app.services.bambu_cloud] [3623e3a5] Bambu Cloud returned 401 without the expiry signature — treating as transient, not signing the stored token out
+2026-08-22 03:09:17,672 INFO [backend.app.api.routes.notifications] [e278fc26] Updated notification provider: Discord
+2026-08-22 03:09:17,679 INFO [uvicorn.access] [-] [IP]:46564 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:18,756 INFO [backend.app.api.routes.notifications] [4e85e5f2] Updated notification provider: Discord
+2026-08-22 03:09:18,769 INFO [uvicorn.access] [-] [IP]:46580 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:19,172 INFO [backend.app.api.routes.notifications] [56f34ac0] Updated notification provider: Discord
+2026-08-22 03:09:19,176 INFO [uvicorn.access] [-] [IP]:46588 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:19,910 INFO [backend.app.api.routes.notifications] [7eb459b2] Updated notification provider: Discord
+2026-08-22 03:09:19,920 INFO [uvicorn.access] [-] [IP]:46608 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:21,924 INFO [backend.app.api.routes.notifications] [084eb6c2] Updated notification provider: Discord
+2026-08-22 03:09:21,939 INFO [uvicorn.access] [-] [IP]:46628 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:22,251 INFO [backend.app.api.routes.notifications] [6494ff7c] Updated notification provider: Discord
+2026-08-22 03:09:22,256 INFO [uvicorn.access] [-] [IP]:46640 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:24,768 INFO [backend.app.api.routes.notifications] [46cb7d96] Updated notification provider: Discord
+2026-08-22 03:09:24,781 INFO [uvicorn.access] [-] [IP]:46670 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:09:25,555 INFO [backend.app.api.routes.notifications] [902b6a85] Updated notification provider: Discord
+2026-08-22 03:09:25,562 INFO [uvicorn.access] [-] [IP]:46682 - "PATCH /api/v1/notifications/1 HTTP/1.1" 200
+2026-08-22 03:10:06,568 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-08-22 03:10:06,575 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-08-22 03:10:06,920 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): ffmpeg version 7.1.5-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
+  built with gcc 14 (Debian 14.2.0-19)
+  configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --libd
+2026-08-22 03:10:13,768 INFO [backend.app.services.bambu_cloud] [f3e7be55] Bambu Cloud returned 401 without the expiry signature — treating as transient, not signing the stored token out
+2026-08-22 03:10:31,466 INFO [backend.app.api.routes.support] [2b967c05] Log level changed to DEBUG
+2026-08-22 03:10:31,471 INFO [backend.app.api.routes.bug_report] [2b967c05] Bug report: enabled debug logging
+2026-08-22 03:10:31,476 DEBUG [backend.app.services.bambu_mqtt] [2b967c05] [[SERIAL]] Requesting status update (pushall)
+2026-08-22 03:10:31,479 INFO [uvicorn.access] [-] [IP]:47600 - "POST /api/v1/bug-report/start-logging HTTP/1.1" 200
+2026-08-22 03:10:32,459 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Found xcam inside print data: {'allow_skip_parts': False, 'buildplate_marker_detector': False, 'cfg': 1780871, 'first_layer_inspector': True, 'halt_print_sensitivity': 'medium', 'print_halt': True, 'printing_monitor': True, 'spaghetti_detector': True}
+2026-08-22 03:10:32,463 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Parsing xcam data - all fields: ['allow_skip_parts', 'buildplate_marker_detector', 'cfg', 'first_layer_inspector', 'halt_print_sensitivity', 'print_halt', 'printing_monitor', 'spaghetti_detector']
+2026-08-22 03:10:32,468 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1780871 (binary: 0b110110010110010000111)
+2026-08-22 03:10:32,473 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_1.gcode, subtask_name: Large (9cm) - 0.2mm layer, 2 walls, 15% infill
+2026-08-22 03:10:32,474 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '33', 'ams_exist_bits_raw': '33', 'cali_id': 255, 'cali_stat': 0, 'cfs': [2, 9, 5, 7], 'insert_flag': True, 'power_on_flag': False, 'tray_exist_bits': '9f', 'tray_hall_out_bits': '8', 'tray_is_bbl_bits': '9f', 'tray_now': '3', 'tray_pre': '3', 'tray_read_done_bits': '9f', 'tray_reading_bits': '0', 'tray_tar': '3', 'unbind_ams_stat': 0, 'version': 4953}
+2026-08-22 03:10:32,476 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] tray_now updated: 3
+2026-08-22 03:10:32,479 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Merged AMS data: 4 new units, 4 total
+2026-08-22 03:10:32,484 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 0 info=0x10001003 -> extruder 0
+2026-08-22 03:10:32,486 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 1 info=0x10001003 -> extruder 0
+2026-08-22 03:10:32,488 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 128 info=0x11002104 -> extruder 1
+2026-08-22 03:10:32,490 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 129 info=0x11002104 -> extruder 1
+2026-08-22 03:10:32,494 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '128': 1, '129': 1}
+2026-08-22 03:10:32,496 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_status: 768 (main=3, sub=0)
+2026-08-22 03:10:32,499 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-22 03:10:32,501 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] device.extruder.state=2 (switch_state bits 12-14: 0)
+2026-08-22 03:10:32,505 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp direct: 31°C (heater OFF)
+2026-08-22 03:10:32,511 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ctc_info keys: ['temp']
+2026-08-22 03:10:32,515 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber heating calculated: target=0.0, current=31.0, heating=False, respect_local=False
+2026-08-22 03:10:32,517 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber temp updated to: 31.0, target: 0.0, heating: False
+2026-08-22 03:10:32,522 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: []
+2026-08-22 03:10:32,523 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ipcam field: {'agora_service': 'disable', 'brtc_service': 'enable', 'bs_state': 0, 'cap_pic_enable': 'enable', 'ipcam_dev': '1', 'ipcam_record': 'enable', 'laser_preview_res': 6, 'mode_bits': 2, 'resolution': '1080p', 'rtsp_url': 'disable', 'timelapse': 'disable', 'tl_store_hpd_type': 2, 'tl_store_path_type': 2, 'tutk_server': 'enable'}
+2026-08-22 03:10:32,527 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -59dBm
+2026-08-22 03:10:32,533 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] lights_report: [{'mode': 'on', 'node': 'chamber_light'}, {'mode': 'flashing', 'node': 'work_light'}, {'mode': 'on', 'node': 'chamber_light2'}]
+2026-08-22 03:10:32,536 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [65535, 65535, 65535, 65535, 3]
+2026-08-22 03:10:32,539 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_1.gcode, subtask: Large (9cm) - 0.2mm layer, 2 walls, 15% infill