Bug report logs 4fb777d851fd4c6497da658702794505.log

logs/4fb777d851fd4c6497da658702794505.log

@@ -0,0 +1,200 @@
+Error opening input file rtsp://[CREDENTIALS]@[IP]:35923/streaming/live/1.
+Error opening input files: Invalid data found when processing input
+2026-10-05 22:12:58,078 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-10-05 22:12:58,079 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-10-05 22:12:58,205 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): [rtsp @ 0x562f857a3080] Failed reading RTSP data: End of file
+[in#0 @ 0x562f857a2dc0] Error opening input: Invalid data found when processing input
+Error opening input file rtsp://[CREDENTIALS]@[IP]:44341/streaming/live/1.
+Error opening input files: Invalid data found when processing input
+2026-10-05 22:13:09,948 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-10-05 22:13:09,950 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-10-05 22:13:10,077 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): [rtsp @ 0x5601904e6080] Failed reading RTSP data: End of file
+[in#0 @ 0x5601904e5dc0] Error opening input: Invalid data found when processing input
+Error opening input file rtsp://[CREDENTIALS]@[IP]:41303/streaming/live/1.
+Error opening input files: Invalid data found when processing input
+2026-10-05 22:13:19,672 INFO [backend.app.main] [-] Recorded 4 AMS sensor history entries
+2026-10-05 22:13:35,617 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] PRINT COMPLETE detected - state: FINISH, status: completed, file: /data/Metadata/plate_1.gcode, subtask: MASTER Bambu File w Settings, was_running: True, timelapse_during_print: True
+2026-10-05 22:13:35,617 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] FINISH PHOTO MOMENT (FINISH fallback) — stage-22 never fired; capturing at FINISH-state transition
+2026-10-05 22:13:35,618 INFO [backend.app.main] [-] [FINISH-PHOTO-MOMENT] printer=1 trigger=finish_state timelapse_active=True
+2026-10-05 22:13:35,618 INFO [backend.app.main] [-] [FINISH-PHOTO-MOMENT] timelapse active for printer 1 — skipping pre-capture (last-frame extraction will run post-completion)
+2026-10-05 22:13:35,618 INFO [backend.app.main] [-] [CALLBACK] on_print_complete started for printer 1
+2026-10-05 22:13:35,618 INFO [backend.app.main] [-] [TIMING] WebSocket send_print_complete: 0.000s elapsed
+2026-10-05 22:13:35,619 INFO [backend.app.main] [-] Print complete - filename: /data/Metadata/plate_1.gcode, subtask: MASTER Bambu File w Settings, status: completed
+2026-10-05 22:13:35,619 INFO [backend.app.main] [-] Looking for archive in _active_prints, keys to try: [(1, 'MASTER Bambu File w Settings.3mf'), (1, 'MASTER Bambu File w Settings.gcode.3mf'), (1, 'MASTER Bambu File w Settings'), (1, 'plate_1.gcode.3mf'), (1, 'plate_1.3mf')]...
+2026-10-05 22:13:35,619 INFO [backend.app.main] [-] Current _active_prints: [(1, '/data/Metadata/plate_1.gcode'), (1, 'MASTER Bambu File w Settings.3mf'), (1, 'MASTER Bambu File w Settings')]
+2026-10-05 22:13:35,619 INFO [backend.app.main] [-] Found archive 519 with key (1, 'MASTER Bambu File w Settings.3mf')
+2026-10-05 22:13:35,996 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:36,148 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:36,302 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:36,314 INFO [backend.app.main] [-] [TIMING] SD card cleanup: 0.696s elapsed
+2026-10-05 22:13:36,317 INFO [backend.app.main] [-] [TIMING] Queue item update: 0.698s elapsed
+2026-10-05 22:13:36,330 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] on_print_complete: printer=1, archive=519, session=yes, ams_mapping=[-1, 0, -1, -1, -1, -1, -1, -1, -1]
+2026-10-05 22:13:36,330 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT COMPLETE printer 1: mapping=[65535, 0], tray_now=255, last_loaded_tray=0
+2026-10-05 22:13:36,338 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] 3MF: no file available for archive 519, skipping
+2026-10-05 22:13:36,338 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] AMS0-T0: no valid remain% at print start, nothing to charge for printer 1
+2026-10-05 22:13:36,339 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] VT254: not in print mapping/tray_change_log — skipping fallback for printer 1
+2026-10-05 22:13:36,339 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] VT255: not in print mapping/tray_change_log — skipping fallback for printer 1
+2026-10-05 22:13:36,344 INFO [backend.app.services.spoolman_tracking] [-] [SPOOLMAN] No tracking data for print (printer=1, archive=519)
+2026-10-05 22:13:36,345 INFO [backend.app.main] [-] [TIMING] Spoolman usage report: 0.726s elapsed
+2026-10-05 22:13:36,345 INFO [backend.app.main] [-] [TIMING] Filament usage tracking: 0.727s elapsed
+2026-10-05 22:13:36,345 INFO [backend.app.main] [-] [TIMING] Archive lookup: 0.727s elapsed
+2026-10-05 22:13:36,345 INFO [backend.app.main] [-] [ARCHIVE] Updating archive 519 status...
+2026-10-05 22:13:36,354 INFO [backend.app.main] [-] [ARCHIVE] Archive 519 status updated to completed, failure_reason=None
+2026-10-05 22:13:36,355 INFO [backend.app.main] [-] [ARCHIVE] WebSocket notification sent for archive 519
+2026-10-05 22:13:36,355 INFO [backend.app.main] [-] [TIMING] Archive status update: 0.737s elapsed
+2026-10-05 22:13:36,360 INFO [backend.app.services.finance_billing] [-] Billing is disabled; skipping print charge for archive ID 519.
+2026-10-05 22:13:36,361 INFO [backend.app.main] [-] [TIMING] Finance charge update: 0.743s elapsed
+2026-10-05 22:13:36,369 INFO [backend.app.main] [-] [PRINT_LOG] Log entry written for archive 519
+2026-10-05 22:13:36,370 INFO [backend.app.main] [-] [TIMING] Print log entry: 0.752s elapsed
+2026-10-05 22:13:36,370 INFO [backend.app.main] [-] [TIMING] Background tasks scheduled (energy, photo): 0.752s elapsed
+2026-10-05 22:13:36,370 INFO [backend.app.main] [-] [TIMING] All background tasks scheduled: 0.752s elapsed
+2026-10-05 22:13:36,371 INFO [backend.app.main] [-] [TIMELAPSE] Timelapse was active during print, scheduling auto-scan for archive 519
+2026-10-05 22:13:36,371 INFO [backend.app.main] [-] [TIMING] Timelapse scan scheduled: 0.753s elapsed
+2026-10-05 22:13:36,371 INFO [backend.app.main] [-] [CALLBACK] on_print_complete finished for printer 1, archive 519
+2026-10-05 22:13:36,372 INFO [backend.app.main] [-] [ENERGY-BG] Starting energy calculation for archive 519
+2026-10-05 22:13:36,372 INFO [backend.app.main] [-] [PHOTO-BG] Starting finish photo capture for archive 519
+2026-10-05 22:13:36,373 INFO [backend.app.main] [-] [AUTO-OFF-BG] Starting smart plug automation for printer 1
+2026-10-05 22:13:36,374 INFO [backend.app.main] [-] [MAINT-BG] Starting maintenance check for printer 1
+2026-10-05 22:13:36,375 INFO [backend.app.main] [-] [LAYER-TL] Stitching layer timelapse for printer 1
+2026-10-05 22:13:36,381 INFO [backend.app.main] [-] [AUTO-OFF-BG] Completed
+2026-10-05 22:13:36,384 WARNING [backend.app.main] [-] [PHOTO-BG] Archive 519 has no file_path, using fallback dir
+2026-10-05 22:13:36,394 INFO [backend.app.main] [-] [TIMELAPSE] Using print-start baseline: 391 existing video files for archive 519
+2026-10-05 22:13:36,464 INFO [backend.app.services.notification_service] [-] Found 1 providers for maintenance_due: ['Discord']
+2026-10-05 22:13:36,566 INFO [backend.app.main] [-] [ENERGY-BG] Energy response from plug '[PRINTER]': {'power': 52.72, 'voltage': None, 'current': None, 'today': None, 'total': 70.405471, 'yesterday': None, 'factor': None, 'apparent_power': None, 'reactive_power': None}
+2026-10-05 22:13:36,566 INFO [backend.app.main] [-] [ENERGY-BG] Per-print energy: 2.3174 kWh
+2026-10-05 22:13:36,576 INFO [backend.app.main] [-] [ENERGY-BG] Saved: 2.3174 kWh, cost=0.232
+2026-10-05 22:13:36,851 INFO [backend.app.services.notification_service] [-] Sent notification via Discord
+2026-10-05 22:13:36,852 INFO [backend.app.main] [-] [MAINT-BG] Sent notification: 5 items need attention
+2026-10-05 22:13:42,065 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:42,158 INFO [backend.app.main] [-] [TIMELAPSE] Attempt 1: Found 392 video files in /timelapse
+2026-10-05 22:13:42,158 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-08_17-44-29.mp4
+2026-10-05 22:13:42,159 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-08_22-11-28.mp4
+2026-10-05 22:13:42,159 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_00-04-18.mp4
+2026-10-05 22:13:42,159 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_13-59-36.mp4
+2026-10-05 22:13:42,159 INFO [backend.app.main] [-] [TIMELAPSE]   - video_2026-01-09_22-55-15.mp4
+2026-10-05 22:13:42,159 INFO [backend.app.main] [-] [TIMELAPSE] Attempt 1: New file detected: video_2026-10-05_14-44-59.mp4 (downloading for archive 519)
+2026-10-05 22:13:42,304 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:44,156 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:44,229 INFO [backend.app.main] [-] [TIMELAPSE] Successfully attached timelapse to archive 519
+2026-10-05 22:13:44,358 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:13:44,372 INFO [backend.app.services.bambu_ftp] [-] [TIMELAPSE] Deleted /timelapse/video_2026-10-05_14-44-59.mp4 from printer [PRINTER] after archiving
+2026-10-05 22:13:50,847 INFO [backend.app.main] [-] [Printer 1] Broadcasting AMS change via WebSocket
+2026-10-05 22:13:59,603 INFO [backend.app.main] [-] [PHOTO-BG] Extracted finish photo from timelapse video_2026-10-05_14-44-59.mp4 for archive 519
+2026-10-05 22:13:59,608 INFO [backend.app.main] [-] [PHOTO-BG] Saved: finish_20261005_221345_da8f5523.jpg
+2026-10-05 22:13:59,609 INFO [backend.app.main] [-] [PHOTO-NOTIFY] Photo task returned: finish_20261005_221345_da8f5523.jpg
+2026-10-05 22:13:59,609 INFO [backend.app.main] [-] [NOTIFY-BG] Starting notifications for printer 1, photo=finish_20261005_221345_da8f5523.jpg
+2026-10-05 22:13:59,618 INFO [backend.app.main] [-] [NOTIFY-BG] Loaded finish photo bytes: 276889 bytes
+2026-10-05 22:13:59,618 INFO [backend.app.services.notification_service] [-] on_print_complete called for printer 1 ([PRINTER]), status=completed
+2026-10-05 22:13:59,620 INFO [backend.app.services.notification_service] [-] Found 1 providers for on_print_complete: ['Discord']
+2026-10-05 22:14:00,253 INFO [backend.app.services.notification_service] [-] Sent notification via Discord
+2026-10-05 22:14:00,256 INFO [backend.app.main] [-] [NOTIFY-BG] Completed
+2026-10-05 22:16:41,107 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Print destination from the report topic: https://or-cloud-upload-prod.s3.us-west-2.amazonaws.com/users/3266820743/models/20261006101639.4/US4469a831bd6703_1047122019_1.3mf?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAXY6FH2ERKZDBWCUW%2F20261006%2Fus-west-2%2Fs3%2Faws4_request&X-Amz-Date=20261006T021640Z&X-Amz-Expires=3600&X-Amz-SignedHeaders=host&X-Amz-Signature=5ba12f642300218be92495418ec532909f290e46296a3b6cec289c8f9025a5c7
+2026-10-05 22:16:41,108 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Captured ams_mapping from print response: [-1, -1, -1, -1, 3, -1, -1, -1, -1]
+2026-10-05 22:16:45,379 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] PRINT START detected - file: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5, is_new: True, is_file_change: False
+2026-10-05 22:16:45,380 INFO [backend.app.main] [-] [CALLBACK] on_print_start called for printer 1, data keys: ['filename', 'subtask_name', 'remaining_time', 'raw_data', 'ams_mapping']
+2026-10-05 22:16:45,389 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-10-05 22:16:45,390 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1: mapping=[65535, 65535, 65535, 65535, 3], tray_now=255, last_loaded_tray=0
+2026-10-05 22:16:45,390 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-10-05 22:16:45,390 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 0: T0(type=ASA, color=D3C5A3FF, now=?, tar=?), T1(type=PLA, color=0ACC38FF, now=?, tar=?), T2(type=PLA, color=A03CF7FF, now=?, tar=?), T3(type=ASA, color=7C4B00FF, now=?, tar=?)
+2026-10-05 22:16:45,390 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 1: T0(type=PLA, color=FFFFFFFF, now=?, tar=?), T1(type=PLA, color=FFFFFFFF, now=?, tar=?), T2(type=PLA, color=161616FF, now=?, tar=?), T3(type=PLA, color=161616FF, now=?, tar=?)
+2026-10-05 22:16:45,390 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 128: T0(type=, color=, now=?, tar=?)
+2026-10-05 22:16:45,390 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 129: T0(type=, color=, now=?, tar=?)
+2026-10-05 22:16:45,395 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] Captured start remain% for printer 1 (2 trays): {'255-0': 0, '255-1': 0}
+2026-10-05 22:16:45,398 INFO [backend.app.main] [-] [PLATE CHECK] printer_id=1, plate_detection_enabled=False
+2026-10-05 22:16:45,398 INFO [backend.app.main] [-] [CALLBACK] Print start detected - filename: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5
+2026-10-05 22:16:45,405 INFO [backend.app.main] [-] Trying filenames: ['InstaGoMountCurve_v5.gcode.3mf', 'InstaGoMountCurve_v5.3mf', 'plate_1.gcode.3mf', 'plate_1.3mf']
+2026-10-05 22:16:45,410 INFO [backend.app.main] [-] Skipping the 3MF lookup for printer 1: internal_storage — the print file is not on storage Bambuddy can read over FTPS, so no path would find it
+2026-10-05 22:16:45,410 WARNING [backend.app.main] [-] Could not find 3MF file for print: /data/Metadata/plate_1.gcode
+2026-10-05 22:16:45,417 INFO [backend.app.main] [-] Created fallback archive 520 for InstaGoMountCurve_v5 (no 3MF available)
+2026-10-05 22:16:45,595 INFO [backend.app.main] [-] [ENERGY] Recorded starting energy (fallback) for archive 520 from plug '[PRINTER]': 70.407734 kWh
+2026-10-05 22:16:45,600 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-10-05 22:16:45,601 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-10-05 22:16:45,716 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): [rtsp @ 0x55ea5c2ca080] Failed reading RTSP data: End of file
+[in#0 @ 0x55ea5c2c9dc0] Error opening input: Invalid data found when processing input
+Error opening input file rtsp://[CREDENTIALS]@[IP]:43185/streaming/live/1.
+Error opening input files: Invalid data found when processing input
+2026-10-05 22:16:45,716 INFO [backend.app.services.notification_service] [-] on_print_start called for printer 1 ([PRINTER])
+2026-10-05 22:16:45,718 INFO [backend.app.services.notification_service] [-] No notification providers configured for print_start event on printer 1
+2026-10-05 22:16:45,851 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-10-05 22:16:45,905 INFO [backend.app.main] [-] [TIMELAPSE] Baseline at print start: 391 video files for printer 1
+2026-10-05 22:18:19,689 INFO [backend.app.main] [-] Recorded 4 AMS sensor history entries
+2026-10-05 22:19:05,490 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-10-05 22:19:05,490 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Tray change during print: tray=3 at layer=0
+2026-10-05 22:23:17,369 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-10-05 22:23:17,371 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-10-05 22:23:17,522 ERROR [backend.app.services.camera] [-] ffmpeg frame bytes capture failed (code 183): [rtsp @ 0x5622f412a080] Failed reading RTSP data: End of file
+[in#0 @ 0x5622f4129dc0] Error opening input: Invalid data found when processing input
+Error opening input file rtsp://[CREDENTIALS]@[IP]:37739/streaming/live/1.
+Error opening input files: Invalid data found when processing input
+2026-10-05 22:23:19,701 INFO [backend.app.main] [-] Recorded 4 AMS sensor history entries
+2026-10-05 22:23:41,174 INFO [backend.app.api.routes.websocket] [-] WebSocket client disconnected normally
+2026-10-05 22:23:41,460 INFO [uvicorn.access] [-] [IP]:40742 - "POST /api/v1/printers/camera/stream-token HTTP/1.1" 200
+2026-10-05 22:23:41,561 INFO [uvicorn.access] [-] [IP]:40740 - "POST /api/v1/auth/media-token HTTP/1.1" 200
+2026-10-05 22:23:42,460 INFO [uvicorn.access] [-] [IP]:40780 - "POST /api/v1/auth/ws-token HTTP/1.1" 200
+2026-10-05 22:23:42,516 INFO [backend.app.api.routes.websocket] [-] WebSocket client connecting (principal=[USER])
+2026-10-05 22:23:42,538 INFO [backend.app.api.routes.websocket] [-] WebSocket client connected
+2026-10-05 22:23:42,539 INFO [backend.app.api.routes.websocket] [-] Sent initial status for 1 printers
+2026-10-05 22:25:04,682 INFO [backend.app.api.routes.support] [9ed8a945] Log level changed to DEBUG
+2026-10-05 22:25:04,682 INFO [backend.app.api.routes.bug_report] [9ed8a945] Bug report: enabled debug logging
+2026-10-05 22:25:04,682 DEBUG [backend.app.services.bambu_mqtt] [9ed8a945] [[SERIAL]] Requesting status update (pushall)
+2026-10-05 22:25:04,683 INFO [uvicorn.access] [-] [IP]:41430 - "POST /api/v1/bug-report/start-logging HTTP/1.1" 200
+2026-10-05 22:25:04,894 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Found xcam inside print data: {'allow_skip_parts': False, 'buildplate_marker_detector': False, 'cfg': 1797543, 'first_layer_inspector': True, 'halt_print_sensitivity': 'medium', 'print_halt': True, 'printing_monitor': True, 'spaghetti_detector': True}
+2026-10-05 22:25:04,894 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-10-05 22:25:04,894 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1797543 (binary: 0b110110110110110100111)
+2026-10-05 22:25:04,894 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_1.gcode, subtask_name: InstaGoMountCurve_v5
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '3', 'ams_exist_bits_raw': '3', 'cali_id': 255, 'cali_stat': 0, 'cfs': [2, 9, 5, 7], 'insert_flag': True, 'power_on_flag': False, 'tray_exist_bits': 'ff', 'tray_hall_out_bits': '8', 'tray_is_bbl_bits': 'ff', 'tray_now': '3', 'tray_pre': '3', 'tray_read_done_bits': 'ff', 'tray_reading_bits': '0', 'tray_tar': '3', 'unbind_ams_stat': 0, 'version': 14230}
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] tray_now updated: 3
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Merged AMS data: 2 new units, 4 total
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 0 info=0x10001003 -> extruder 0
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 1 info=0x10001003 -> extruder 0
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 128 info=0x11001104 -> extruder 1
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 129 info=0x11001104 -> extruder 1
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '128': 1, '129': 1}
+2026-10-05 22:25:04,895 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_status: 768 (main=3, sub=0)
+2026-10-05 22:25:04,896 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-10-05 22:25:04,896 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] device.extruder.state=2 (switch_state bits 12-14: 0)
+2026-10-05 22:25:04,896 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp encoded: 3932220 -> current=60, decoded_target=60
+2026-10-05 22:25:04,896 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ctc_info keys: ['temp']
+2026-10-05 22:25:04,896 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber heating calculated: target=60.0, current=60.0, heating=False, respect_local=False
+2026-10-05 22:25:04,897 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber temp updated to: 60.0, target: 60.0, heating: False
+2026-10-05 22:25:04,897 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: [{'attr': 83887616, 'code': 131078}, {'attr': 83887616, 'code': 131077}]
+2026-10-05 22:25:04,897 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-10-05 22:25:04,897 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -77dBm
+2026-10-05 22:25:04,897 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-10-05 22:25:04,897 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [65535, 65535, 65535, 65535, 3]
+2026-10-05 22:25:04,897 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5
+2026-10-05 22:25:06,171 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Found xcam inside print data: {'allow_skip_parts': False, 'buildplate_marker_detector': False, 'cfg': 1797543, 'first_layer_inspector': True, 'halt_print_sensitivity': 'medium', 'print_halt': True, 'printing_monitor': True, 'spaghetti_detector': True}
+2026-10-05 22:25:06,171 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-10-05 22:25:06,171 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1797543 (binary: 0b110110110110110100111)
+2026-10-05 22:25:06,171 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_1.gcode, subtask_name: InstaGoMountCurve_v5
+2026-10-05 22:25:06,171 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '3', 'ams_exist_bits_raw': '3', 'cali_id': 255, 'cali_stat': 0, 'cfs': [2, 9, 5, 7], 'insert_flag': True, 'power_on_flag': False, 'tray_exist_bits': 'ff', 'tray_hall_out_bits': '8', 'tray_is_bbl_bits': 'ff', 'tray_now': '3', 'tray_pre': '3', 'tray_read_done_bits': 'ff', 'tray_reading_bits': '0', 'tray_tar': '3', 'unbind_ams_stat': 0, 'version': 14231}
+2026-10-05 22:25:06,172 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '128': 1, '129': 1}
+2026-10-05 22:25:06,172 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-10-05 22:25:06,172 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp encoded: 3932220 -> current=60, decoded_target=60
+2026-10-05 22:25:06,172 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: [{'attr': 83887616, 'code': 131078}, {'attr': 83887616, 'code': 131077}]
+2026-10-05 22:25:06,173 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-10-05 22:25:06,173 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [65535, 65535, 65535, 65535, 3]
+2026-10-05 22:25:06,173 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5
+2026-10-05 22:25:07,332 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Found xcam inside print data: {'allow_skip_parts': False, 'buildplate_marker_detector': False, 'cfg': 1797543, 'first_layer_inspector': True, 'halt_print_sensitivity': 'medium', 'print_halt': True, 'printing_monitor': True, 'spaghetti_detector': True}
+2026-10-05 22:25:07,332 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-10-05 22:25:07,332 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1797543 (binary: 0b110110110110110100111)
+2026-10-05 22:25:07,333 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_1.gcode, subtask_name: InstaGoMountCurve_v5
+2026-10-05 22:25:07,333 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '128': 1, '129': 1}
+2026-10-05 22:25:07,333 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-10-05 22:25:07,333 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp encoded: 3932220 -> current=60, decoded_target=60
+2026-10-05 22:25:07,333 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: [{'attr': 83887616, 'code': 131078}, {'attr': 83887616, 'code': 131077}]
+2026-10-05 22:25:07,334 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-10-05 22:25:07,334 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [65535, 65535, 65535, 65535, 3]
+2026-10-05 22:25:07,334 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5
+2026-10-05 22:25:08,809 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Found xcam inside print data: {'allow_skip_parts': False, 'buildplate_marker_detector': False, 'cfg': 1797543, 'first_layer_inspector': True, 'halt_print_sensitivity': 'medium', 'print_halt': True, 'printing_monitor': True, 'spaghetti_detector': True}
+2026-10-05 22:25:08,809 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-10-05 22:25:08,810 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1797543 (binary: 0b110110110110110100111)
+2026-10-05 22:25:08,810 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_1.gcode, subtask_name: InstaGoMountCurve_v5
+2026-10-05 22:25:08,810 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '3', 'ams_exist_bits_raw': '3', 'cali_id': 255, 'cali_stat': 0, 'cfs': [2, 9, 5, 7], 'insert_flag': True, 'power_on_flag': False, 'tray_exist_bits': 'ff', 'tray_hall_out_bits': '8', 'tray_is_bbl_bits': 'ff', 'tray_now': '3', 'tray_pre': '3', 'tray_read_done_bits': 'ff', 'tray_reading_bits': '0', 'tray_tar': '3', 'unbind_ams_stat': 0, 'version': 14232}
+2026-10-05 22:25:08,810 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '128': 1, '129': 1}
+2026-10-05 22:25:08,810 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-10-05 22:25:08,811 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp encoded: 3932220 -> current=60, decoded_target=60
+2026-10-05 22:25:08,811 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: [{'attr': 83887616, 'code': 131078}, {'attr': 83887616, 'code': 131077}]
+2026-10-05 22:25:08,811 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-10-05 22:25:08,811 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [65535, 65535, 65535, 65535, 3]
+2026-10-05 22:25:08,812 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_1.gcode, subtask: InstaGoMountCurve_v5