Bug report logs c5a0b339cda44d1c862ab4362e1eacd3.log

logs/c5a0b339cda44d1c862ab4362e1eacd3.log

@@ -0,0 +1,200 @@
+2026-07-01 16:44:50,259 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:45:04,312 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:45:09,232 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:45:12,613 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] MQTT TLS connection from ('[IP]', 56439) - cipher=('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256), version=TLSv1.3
+2026-07-01 16:45:12,614 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] MQTT client connected: [IP]:56439
+2026-07-01 16:45:12,614 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] MQTT client authenticated successfully
+2026-07-01 16:45:12,615 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] MQTT client [IP]:56439 authenticated (negotiated keepalive=60s, idle disconnect disabled)
+2026-07-01 16:45:12,618 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] MQTT subscribe: device/09400A391800001/report QoS=0
+2026-07-01 16:45:12,628 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20049","version":1}}...
+2026-07-01 16:45:12,628 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT pushing command: pushall
+2026-07-01 16:45:12,628 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sending status report in response to pushall
+2026-07-01 16:45:12,629 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"info":{"command":"get_version","sequence_id":"20050"}}...
+2026-07-01 16:45:12,629 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT info command: get_version
+2026-07-01 16:45:12,629 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sent version response (product_name=[PRINTER])
+2026-07-01 16:45:12,631 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"info":{"command":"get_version","sequence_id":"20051"}}...
+2026-07-01 16:45:12,632 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT info command: get_version
+2026-07-01 16:45:12,632 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sent version response (product_name=[PRINTER])
+2026-07-01 16:45:12,632 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"info":{"command":"get_version","sequence_id":"20052"}}...
+2026-07-01 16:45:12,632 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT info command: get_version
+2026-07-01 16:45:12,632 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sent version response (product_name=[PRINTER])
+2026-07-01 16:45:14,649 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:45:23,756 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 58 pushes/min to [IP]:56096
+2026-07-01 16:45:23,756 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 4 pushes/min to [IP]:56439
+2026-07-01 16:45:24,884 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:45:29,701 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:46:18,282 INFO [backend.app.api.routes.websocket] [-] WebSocket client disconnected normally
+2026-07-01 16:46:20,653 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"info":{"command":"get_version","sequence_id":"20053"}}...
+2026-07-01 16:46:20,653 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT info command: get_version
+2026-07-01 16:46:20,653 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sent version response (product_name=[PRINTER])
+2026-07-01 16:46:20,654 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20054","version":1}}...
+2026-07-01 16:46:20,654 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT pushing command: pushall
+2026-07-01 16:46:20,654 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sending status report in response to pushall
+2026-07-01 16:46:23,842 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:46:27,026 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP connection from ('[IP]', 56561)
+2026-07-01 16:46:27,027 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP login from [IP]
+2026-07-01 16:46:27,029 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP EPSV listening on port 50001
+2026-07-01 16:46:27,032 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP receiving file: verify_job from [IP]
+2026-07-01 16:46:27,044 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-07-01 16:46:27,044 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP data connection established from [IP]
+2026-07-01 16:46:27,145 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP saved file: /app/data/virtual_printer/uploads/1/verify_job (16 bytes)
+2026-07-01 16:46:27,145 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Received file: verify_job from [IP]
+2026-07-01 16:46:27,148 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP session cancelled from [IP]
+2026-07-01 16:46:27,148 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP session ended from [IP]
+2026-07-01 16:46:28,224 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP connection from ('[IP]', 56571)
+2026-07-01 16:46:28,225 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP login from [IP]
+2026-07-01 16:46:28,226 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP EPSV listening on port 50001
+2026-07-01 16:46:28,228 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP receiving file: _V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf from [IP]
+2026-07-01 16:46:28,236 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-07-01 16:46:28,236 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP data connection established from [IP]
+2026-07-01 16:46:28,353 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] FTP saved file: /app/data/virtual_printer/uploads/1/_V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf (1554059 bytes)
+2026-07-01 16:46:28,353 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Received file: _V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf from [IP]
+2026-07-01 16:46:28,367 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Archived: 3 - [V2] AM4xS - AMS SLIDING Stacking System - Plate 11
+2026-07-01 16:46:28,370 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Added to queue: 3
+2026-07-01 16:46:28,371 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP session cancelled from [IP]
+2026-07-01 16:46:28,371 INFO [backend.app.services.virtual_printer.ftp_server] [b278c72d] [BamBuddySRV] FTP session ended from [IP]
+2026-07-01 16:46:28,376 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"print":{"ams_mapping":[10,-1],"ams_mapping2":[{"ams_id":2,"slot_id":2},{"ams_id":255,"slot_id":255...
+2026-07-01 16:46:28,376 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT print command: project_file for _V2_AM4xS_-_AMS_SLIDING_Stacking_System
+2026-07-01 16:46:28,376 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sent project_file acknowledgment for _V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf
+2026-07-01 16:46:28,376 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Print command for: _V2_AM4xS_-_AMS_SLIDING_Stacking_System
+2026-07-01 16:46:28,378 INFO [backend.app.services.virtual_printer.manager] [b278c72d] [VP BamBuddySRV] Late slicer MQTT for _V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf — retroactively stamped ['bed_levelling', 'flow_cali', 'layer_inspect', 'timelapse', 'use_ams', 'vibration_cali'] onto queue item(s) [3]
+2026-07-01 16:46:45,400 INFO [backend.app.services.print_scheduler] [-] Queue check: found 1 pending items: [(3, 1, 3, None)]
+2026-07-01 16:46:45,403 INFO [backend.app.services.print_scheduler] [-] Queue item 3: Computed AMS mapping for printer 1: [10]
+2026-07-01 16:46:45,409 INFO [backend.app.services.print_scheduler] [-] Starting queue item 3
+2026-07-01 16:46:45,412 INFO [backend.app.services.print_scheduler] [-] Queue item 3: FTP upload starting - printer=[PRINTER] ([PRINTER]), ip=[IP], file=_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf, local_path=/app/data/archive/unassigned/20260701_164628__V2_AM4xS_-_AMS_SLIDING_Stacking_System/_V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf, retry_enabled=True, retry_count=3, timeout=30.0
+2026-07-01 16:46:45,556 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-07-01 16:46:45,563 INFO [backend.app.services.bambu_ftp] [-] FTP connecting to [IP] for upload (model=[PRINTER], mode=prot_p, socket_timeout=30.0s)...
+2026-07-01 16:46:45,685 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-07-01 16:46:45,686 INFO [backend.app.services.bambu_ftp] [-] FTP connected to [IP]
+2026-07-01 16:46:45,686 INFO [backend.app.services.bambu_ftp] [-] FTP uploading /app/data/archive/unassigned/20260701_164628__V2_AM4xS_-_AMS_SLIDING_Stacking_System/_V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf (1554059 bytes) to /_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf
+2026-07-01 16:46:45,727 INFO [backend.app.services.bambu_ftp] [-] FTP data channel ready in 0.0s (PASV + TLS handshake)
+2026-07-01 16:46:45,887 WARNING [backend.app.services.bambu_ftp] [-] FTP STOR returned error_temp for /_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf but file is intact on the printer (1554059 bytes match) — proceeding: 426 Failure reading network stream.
+2026-07-01 16:46:45,887 INFO [backend.app.services.bambu_ftp] [-] FTP upload complete: /_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf (1554059 bytes in 0.2s, 7528 KB/s)
+2026-07-01 16:46:45,887 INFO [backend.app.services.bambu_ftp] [-] FTP mode cached for [IP]: prot_p
+2026-07-01 16:46:45,891 INFO [backend.app.main] [-] Registered expected print: printer=1, file=_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf, archive=3, ams_mapping=[10], plate_id=11
+2026-07-01 16:46:45,892 INFO [backend.app.services.print_scheduler] [-] Queue item 3: Status set to 'printing', sending print command...
+2026-07-01 16:46:45,893 INFO [backend.app.services.printer_manager] [-] PRINT COMMAND: printer=1, file=_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf, caller=print_scheduler.py:321:check_queue
+2026-07-01 16:46:45,893 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Sending print command: {"print": {"sequence_id": "20000", "command": "project_file", "param": "Metadata/plate_11.gcode", "url": "ftp://_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf", "file": "_V2_AM4xS_-_AMS_SLIDING_Stacking_System.3mf", "md5": "", "bed_type": "auto", "timelapse": false, "bed_leveling": false, "auto_bed_leveling": 0, "flow_cali": false, "vibration_cali": false, "layer_inspect": true, "use_ams": true, "cfg": "0", "extrude_cali_flag": 0, "extrude_cali_manual_mode": 0, "nozzle_offset_cali": 1, "subtask_name": "_V2_AM4xS_-_AMS_SLIDING_Stacking_System", "profile_id": "0", "project_id": "512978883", "subtask_id": "512978883", "task_id": "512978883", "ams_mapping": [10], "ams_mapping2": [{"ams_id": 2, "slot_id": 2}]}}
+2026-07-01 16:46:45,893 INFO [backend.app.services.print_scheduler] [-] Queue item 3: Print started successfully - _V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf
+2026-07-01 16:46:45,895 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=FINISH, awaiting_plate_clear=False
+2026-07-01 16:46:45,899 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Captured ams_mapping from print command: [10]
+2026-07-01 16:46:46,032 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS Filament Backup: OFF
+2026-07-01 16:46:47,382 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS Filament Backup: ON
+2026-07-01 16:46:49,016 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] PRINT START detected - file: /data/Metadata/plate_11.gcode, subtask: _V2_AM4xS_-_AMS_SLIDING_Stacking_System, is_new: True, is_file_change: False
+2026-07-01 16:46:49,016 INFO [backend.app.main] [-] [CALLBACK] on_print_start called for printer 1, data keys: ['filename', 'subtask_name', 'remaining_time', 'raw_data', 'ams_mapping']
+2026-07-01 16:46:49,023 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), AMS2-T0(remain=-1), AMS2-T1(remain=-1), AMS2-T2(remain=-1), AMS2-T3(remain=-1)
+2026-07-01 16:46:49,023 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1: mapping=[514], tray_now=255, last_loaded_tray=10
+2026-07-01 16:46:49,023 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1: mapping-related keys: {'mapping': [514], 'ams_extruder_map': {'0': 0, '1': 0, '2': 1}}
+2026-07-01 16:46:49,023 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 0: T0(type=PETG, color=F98C36FF, now=?, tar=?), T1(type=, color=, now=?, tar=?), T2(type=, color=, now=?, tar=?), T3(type=, color=, now=?, tar=?)
+2026-07-01 16:46:49,023 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 1: T0(type=, color=, now=?, tar=?), T1(type=, color=, now=?, tar=?), T2(type=, color=, now=?, tar=?), T3(type=, color=, now=?, tar=?)
+2026-07-01 16:46:49,023 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] PRINT START printer 1 AMS 2: T0(type=, color=, now=?, tar=?), T1(type=, color=, now=?, tar=?), T2(type=PETG, color=898989FF, now=?, tar=?), T3(type=, color=, now=?, tar=?)
+2026-07-01 16:46:49,024 INFO [backend.app.services.usage_tracker] [-] [UsageTracker] Captured start remain% for printer 1 (2 trays): {'255-0': 0, '255-1': 0}
+2026-07-01 16:46:49,025 INFO [backend.app.main] [-] [PLATE CHECK] printer_id=1, plate_detection_enabled=False
+2026-07-01 16:46:49,025 INFO [backend.app.main] [-] [CALLBACK] Print start detected - filename: /data/Metadata/plate_11.gcode, subtask: _V2_AM4xS_-_AMS_SLIDING_Stacking_System
+2026-07-01 16:46:49,025 INFO [backend.app.main] [-] Using expected archive 3 for print (skipping duplicate)
+2026-07-01 16:46:49,028 INFO [backend.app.main] [-] [ENERGY] No smart plug for printer 1 (archive 3)
+2026-07-01 16:46:49,032 INFO [backend.app.main] [-] [SNAPSHOT] Capturing fresh frame for printer 1
+2026-07-01 16:46:49,032 INFO [backend.app.services.camera] [-] Capturing camera frame bytes from [IP] using RTSP (model: [PRINTER])
+2026-07-01 16:46:49,042 INFO [backend.app.api.routes.printers] [d6da06c9] Cover: resolved plate 11 before download (subtask=_V2_AM4xS_-_AMS_SLIDING_Stacking_System)
+2026-07-01 16:46:49,042 INFO [backend.app.api.routes.printers] [d6da06c9] Cover using cached 3MF from /app/data/archive/unassigned/20260701_164628__V2_AM4xS_-_AMS_SLIDING_Stacking_System/_V2_AM4xS_-_AMS_SLIDING_Stacking_System.gcode.3mf (avoided duplicate FTP)
+2026-07-01 16:46:49,042 INFO [backend.app.api.routes.printers] [d6da06c9] Downloaded file size: 1554059 bytes
+2026-07-01 16:46:50,230 INFO [backend.app.services.camera] [-] Successfully captured camera frame bytes: 276865 bytes
+2026-07-01 16:46:50,230 INFO [backend.app.main] [-] [SNAPSHOT] Fresh camera frame: 276865 bytes
+2026-07-01 16:46:50,230 INFO [backend.app.services.notification_service] [-] on_print_start called for printer 1 ([PRINTER])
+2026-07-01 16:46:50,231 INFO [backend.app.services.notification_service] [-] No notification providers configured for print_start event on printer 1
+2026-07-01 16:46:50,232 INFO [backend.app.main] [-] Loaded 1 printable objects for printer 1
+2026-07-01 16:46:50,363 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=[PRINTER], prot_c=False)
+2026-07-01 16:46:50,400 INFO [backend.app.main] [-] [TIMELAPSE] Baseline at print start: 5 video files for printer 1
+2026-07-01 16:47:23,926 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:47:28,008 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:47:32,930 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:47:35,214 INFO [uvicorn.access] [-] [IP]:62315 - "POST /api/v1/auth/ws-token HTTP/1.1" 200
+2026-07-01 16:47:35,230 INFO [backend.app.api.routes.websocket] [-] WebSocket client connecting (principal=<anonymous>)
+2026-07-01 16:47:35,230 INFO [backend.app.api.routes.websocket] [-] WebSocket client connected
+2026-07-01 16:47:35,231 INFO [backend.app.api.routes.websocket] [-] Sent initial status for 1 printers
+2026-07-01 16:47:38,352 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:48:01,542 INFO [backend.app.main] [-] Recorded 3 AMS sensor history entries
+2026-07-01 16:48:24,008 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:48:25,234 INFO [backend.app.api.routes.websocket] [-] WebSocket client disconnected normally
+2026-07-01 16:49:24,093 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:50:12,582 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20055","version":1}}...
+2026-07-01 16:50:12,582 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT pushing command: pushall
+2026-07-01 16:50:12,582 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sending status report in response to pushall
+2026-07-01 16:50:19,810 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:24,175 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:50:24,826 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:30,050 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:35,470 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:40,991 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:46,010 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:47,876 INFO [uvicorn.access] [-] [IP]:62323 - "POST /api/v1/auth/ws-token HTTP/1.1" 200
+2026-07-01 16:50:47,899 INFO [backend.app.api.routes.websocket] [-] WebSocket client connecting (principal=<anonymous>)
+2026-07-01 16:50:47,899 INFO [backend.app.api.routes.websocket] [-] WebSocket client connected
+2026-07-01 16:50:47,900 INFO [backend.app.api.routes.websocket] [-] Sent initial status for 1 printers
+2026-07-01 16:50:51,331 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:50:56,750 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:01,769 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:06,886 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:12,010 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:17,228 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:22,247 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:24,252 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:51:27,667 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:32,887 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:51:38,108 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:52:09,885 INFO [backend.app.api.routes.camera] [4f2a3e8c] Using RTSP protocol for [PRINTER]
+2026-07-01 16:52:09,885 INFO [backend.app.api.routes.camera] [4f2a3e8c] Camera viewer attached to printer-1 (subscribers=1)
+2026-07-01 16:52:09,886 INFO [backend.app.api.routes.camera] [4f2a3e8c] Starting RTSP camera stream for [IP] (stream_id=1-fanout, model=[PRINTER], fps=15, probesize=32, analyzeduration=0)
+2026-07-01 16:52:09,893 INFO [uvicorn.access] [-] [IP]:53736 - "POST /api/v1/printers/camera/stream-token HTTP/1.1" 200
+2026-07-01 16:52:09,909 INFO [backend.app.api.routes.camera] [67313a08] Using RTSP protocol for [PRINTER]
+2026-07-01 16:52:09,909 INFO [backend.app.api.routes.camera] [67313a08] Camera viewer attached to printer-1 (subscribers=2)
+2026-07-01 16:52:17,917 INFO [backend.app.api.routes.websocket] [-] WebSocket client disconnected normally
+2026-07-01 16:52:18,592 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:52:23,629 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:52:24,334 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:53:01,548 INFO [backend.app.main] [-] Recorded 3 AMS sensor history entries
+2026-07-01 16:53:24,420 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:53:43,728 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:53:45,330 INFO [uvicorn.access] [-] [IP]:62332 - "POST /api/v1/auth/ws-token HTTP/1.1" 200
+2026-07-01 16:53:45,345 INFO [backend.app.api.routes.websocket] [-] WebSocket client connecting (principal=<anonymous>)
+2026-07-01 16:53:45,345 INFO [backend.app.api.routes.websocket] [-] WebSocket client connected
+2026-07-01 16:53:45,346 INFO [backend.app.api.routes.websocket] [-] Sent initial status for 1 printers
+2026-07-01 16:53:48,666 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:54:24,509 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:54:25,840 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:54:30,574 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:54:35,347 INFO [backend.app.api.routes.websocket] [-] WebSocket client disconnected normally
+2026-07-01 16:54:37,539 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:54:42,174 INFO [backend.app.services.virtual_printer.ssdp_server] [b278c72d] Sent SSDP response to [IP] for 'BamBuddySRV' (Location=[IP], USN=09400A391800001)
+2026-07-01 16:55:12,585 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT publish to device/09400A391800001/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20056","version":1}}...
+2026-07-01 16:55:12,585 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] MQTT pushing command: pushall
+2026-07-01 16:55:12,585 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] Sending status report in response to pushall
+2026-07-01 16:55:24,598 INFO [backend.app.services.virtual_printer.mqtt_server] [b278c72d] [BamBuddySRV] 1Hz status push: 60 pushes/min to [IP]:56439
+2026-07-01 16:55:44,264 INFO [backend.app.api.routes.support] [7c1afc42] Log level changed to DEBUG
+2026-07-01 16:55:44,264 INFO [backend.app.api.routes.bug_report] [7c1afc42] Bug report: enabled debug logging
+2026-07-01 16:55:44,264 DEBUG [backend.app.services.bambu_mqtt] [7c1afc42] [[SERIAL]] Requesting status update (pushall)
+2026-07-01 16:55:44,265 INFO [uvicorn.access] [-] [IP]:54854 - "POST /api/v1/bug-report/start-logging HTTP/1.1" 200
+2026-07-01 16:55:44,981 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-07-01 16:55:44,981 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-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] xcam cfg bitmask: 1797543 (binary: 0b110110110110110100111)
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: /data/Metadata/plate_11.gcode, subtask_name: _V2_AM4xS_-_AMS_SLIDING_Stacking_System
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '7', 'ams_exist_bits_raw': '7', 'cali_id': 0, 'cali_stat': 0, 'cfs': [2, 9, 5, 7], 'insert_flag': True, 'power_on_flag': False, 'tray_exist_bits': '401', 'tray_hall_out_bits': '400', 'tray_is_bbl_bits': '401', 'tray_now': '2', 'tray_pre': '2', 'tray_read_done_bits': '401', 'tray_reading_bits': '0', 'tray_tar': '2', 'unbind_ams_stat': 0, 'version': 5403}
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] tray_now updated: 10
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Merged AMS data: 3 new units, 3 total
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 0 info=0x10001003 -> extruder 0
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 1 info=0x10002003 -> extruder 0
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 2 info=0x11001103 -> extruder 1
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0, '2': 1}
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_status: 768 (main=3, sub=0)
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] device.extruder.state=33042 (switch_state bits 12-14: 0)
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] info.temp direct: 33°C (heater OFF)
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ctc_info keys: ['temp']
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber heating calculated: target=0.0, current=33.0, heating=False, respect_local=False
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber temp updated to: 33.0, target: 0.0, heating: False
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: [{'attr': 117522432, 'code': 131073}]
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ipcam field: {'agora_service': 'disable', 'brtc_service': 'enable', 'bs_state': 0, 'cap_pic_enable': 'invalid', 'ipcam_dev': '1', 'ipcam_record': 'enable', 'laser_preview_res': 6, 'mode_bits': 2, 'resolution': '1080p', 'rtsp_url': 'rtsps://[IP]:322/streaming/live/1', 'timelapse': 'disable', 'tl_store_hpd_type': 2, 'tl_store_path_type': 2, 'tutk_server': 'disable'}
+2026-07-01 16:55:44,982 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -58dBm
+2026-07-01 16:55:44,982 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-07-01 16:55:44,983 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] MQTT mapping field: [514]
+2026-07-01 16:55:44,983 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: /data/Metadata/plate_11.gcode, subtask: _V2_AM4xS_-_AMS_SLIDING_Stacking_System