Bug report logs d22bda1789af4e17a8acf1a60488026f.log

logs/d22bda1789af4e17a8acf1a60488026f.log

@@ -0,0 +1,200 @@
+2026-06-22 20:59:07,611 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:50161
+2026-06-22 20:59:07,611 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:50161: {'login': {'command': 'detect', 'sequence_id': '20002'}}
+2026-06-22 20:59:07,611 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:50161 (serial=[SERIAL])
+2026-06-22 20:59:08,622 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:53622
+2026-06-22 20:59:08,623 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:53622: {'login': {'command': 'detect', 'sequence_id': '20003'}}
+2026-06-22 20:59:08,623 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:53622 (serial=[SERIAL])
+2026-06-22 20:59:10,044 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT TLS connection from ('[IP]', 51248) - cipher=('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256), version=TLSv1.3
+2026-06-22 20:59:10,045 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client connected: [IP]:51248
+2026-06-22 20:59:10,045 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client authenticated successfully
+2026-06-22 20:59:10,045 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client [IP]:51248 authenticated (negotiated keepalive=60s, idle disconnect disabled)
+2026-06-22 20:59:10,046 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT subscribe: device/[SERIAL]/report QoS=0
+2026-06-22 20:59:10,093 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT publish to device/[SERIAL]/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20001","version":1}}...
+2026-06-22 20:59:10,094 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT pushing command: pushall
+2026-06-22 20:59:10,094 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] Sending status report in response to pushall
+2026-06-22 20:59:10,094 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20002"}}...
+2026-06-22 20:59:10,094 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT info command: get_version
+2026-06-22 20:59:10,094 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] Sent version response (product_name=P1S)
+2026-06-22 20:59:10,097 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20003"}}...
+2026-06-22 20:59:10,097 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT info command: get_version
+2026-06-22 20:59:10,097 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] Sent version response (product_name=P1S)
+2026-06-22 20:59:11,743 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:55425
+2026-06-22 20:59:11,743 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:55425: {'login': {'command': 'detect', 'sequence_id': '20004'}}
+2026-06-22 20:59:11,743 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:55425 (serial=[SERIAL])
+2026-06-22 20:59:12,760 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:51755
+2026-06-22 20:59:12,760 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:51755: {'login': {'command': 'detect', 'sequence_id': '20005'}}
+2026-06-22 20:59:12,760 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:51755 (serial=[SERIAL])
+2026-06-22 20:59:17,270 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 20:59:17,271 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 20:59:17,271 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 20:59:47,278 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 20:59:47,278 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 20:59:47,278 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:00:03,990 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] 1Hz status push: 40 pushes/min to [IP]:51248
+2026-06-22 21:00:17,295 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:00:17,296 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:00:17,296 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:00:18,742 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:61768
+2026-06-22 21:00:18,742 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:61768: {'login': {'command': 'detect', 'sequence_id': '20006'}}
+2026-06-22 21:00:18,742 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:61768 (serial=[SERIAL])
+2026-06-22 21:00:19,751 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:61769
+2026-06-22 21:00:19,751 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:61769: {'login': {'command': 'detect', 'sequence_id': '20007'}}
+2026-06-22 21:00:19,751 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:61769 (serial=[SERIAL])
+2026-06-22 21:00:22,977 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:61770
+2026-06-22 21:00:22,978 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:61770: {'login': {'command': 'detect', 'sequence_id': '20008'}}
+2026-06-22 21:00:22,978 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:61770 (serial=[SERIAL])
+2026-06-22 21:00:23,987 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: client connected from [IP]:61771
+2026-06-22 21:00:23,987 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: received from [IP]:61771: {'login': {'command': 'detect', 'sequence_id': '20009'}}
+2026-06-22 21:00:23,987 INFO [backend.app.services.virtual_printer.bind_server] [3e217fc1] Bind server: sent detect response to [IP]:61771 (serial=[SERIAL])
+2026-06-22 21:00:47,306 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:00:47,307 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:00:47,307 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:01:17,518 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:01:17,519 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:01:17,519 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:01:47,537 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:01:47,538 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:01:47,538 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:02:03,848 INFO [backend.app.main] [-] Recorded 3 AMS sensor history entries
+2026-06-22 21:02:17,551 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:02:17,552 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:02:17,552 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:02:29,898 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Tray change during print: tray=2 at layer=1
+2026-06-22 21:02:38,057 INFO [backend.app.main] [-] [Printer 2] Broadcasting AMS change via WebSocket
+2026-06-22 21:02:47,574 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:02:47,575 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:02:47,575 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:03:17,585 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:03:17,586 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:03:17,586 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:03:47,599 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:03:47,600 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:03:47,600 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:04:17,615 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:04:17,615 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:04:17,615 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:04:47,633 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:04:47,634 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:04:47,634 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:05:17,649 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:05:17,650 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:05:17,650 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:05:19,308 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT TLS connection from ('[IP]', 62391) - cipher=('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256), version=TLSv1.3
+2026-06-22 21:05:19,308 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client connected: [IP]:62391
+2026-06-22 21:05:19,308 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client authenticated successfully
+2026-06-22 21:05:19,308 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT client [IP]:62391 authenticated (negotiated keepalive=60s, idle disconnect disabled)
+2026-06-22 21:05:19,309 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] MQTT subscribe: device/[SERIAL]/report QoS=0
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT publish to device/[SERIAL]/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20015","version":1}}...
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT pushing command: pushall
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] Sending status report in response to pushall
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20016"}}...
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] MQTT info command: get_version
+2026-06-22 21:05:19,315 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] Sent version response (product_name=P1S)
+2026-06-22 21:05:32,547 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP connection from ('[IP]', 62396)
+2026-06-22 21:05:32,548 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP login from [IP]
+2026-06-22 21:05:32,548 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP EPSV listening on port 50018
+2026-06-22 21:05:32,549 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP receiving file: verify_job from [IP]
+2026-06-22 21:05:32,549 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-06-22 21:05:32,550 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP data connection established from [IP]
+2026-06-22 21:05:32,662 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP saved file: C:\ProgramData\Bambuddy\data\virtual_printer\uploads\2\verify_job (16 bytes)
+2026-06-22 21:05:32,663 INFO [backend.app.services.virtual_printer.manager] [3e217fc1] [VP Review] Received file: verify_job from [IP]
+2026-06-22 21:05:32,663 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP session cancelled from [IP]
+2026-06-22 21:05:32,663 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP session ended from [IP]
+2026-06-22 21:05:32,667 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP connection from ('[IP]', 62400)
+2026-06-22 21:05:32,667 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP login from [IP]
+2026-06-22 21:05:32,668 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP EPSV listening on port 50016
+2026-06-22 21:05:32,668 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP receiving file: Untitled.gcode.3mf from [IP]
+2026-06-22 21:05:32,669 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-06-22 21:05:32,669 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP data connection established from [IP]
+2026-06-22 21:05:33,569 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] FTP saved file: C:\ProgramData\Bambuddy\data\virtual_printer\uploads\2\Untitled.gcode.3mf (117443066 bytes)
+2026-06-22 21:05:33,569 INFO [backend.app.services.virtual_printer.manager] [3e217fc1] [VP Review] Received file: Untitled.gcode.3mf from [IP]
+2026-06-22 21:05:33,577 INFO [backend.app.services.virtual_printer.manager] [3e217fc1] [VP Review] Queued: 13 - Untitled.gcode.3mf
+2026-06-22 21:05:36,608 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP session cancelled from [IP]
+2026-06-22 21:05:36,608 INFO [backend.app.services.virtual_printer.ftp_server] [3e217fc1] [Review] FTP session ended from [IP]
+2026-06-22 21:05:38,585 INFO [backend.app.api.routes.cloud] [136b981a] get_filament_info called with 1 IDs: ['GFA01']
+2026-06-22 21:05:38,590 INFO [uvicorn.access] [-] [IP]:62238 - "POST /api/v1/cloud/filament-info HTTP/1.1" 200
+2026-06-22 21:05:38,605 INFO [backend.app.api.routes.cloud] [d7bca33b] get_filament_info called with 1 IDs: ['GFA00']
+2026-06-22 21:05:38,610 INFO [uvicorn.access] [-] [IP]:62238 - "POST /api/v1/cloud/filament-info HTTP/1.1" 200
+2026-06-22 21:05:40,262 INFO [backend.app.api.routes.camera] [e099c1f5] Camera viewer detached from printer-2 (subscribers=0)
+2026-06-22 21:05:40,265 INFO [backend.app.api.routes.camera] [e099c1f5] Chamber image stream cancelled (stream_id=2-fanout)
+2026-06-22 21:05:40,277 INFO [backend.app.api.routes.camera] [e099c1f5] Chamber image stream stopped for [IP] (stream_id=2-fanout)
+2026-06-22 21:05:40,277 INFO [backend.app.api.routes.camera] [f63cdc10] Shut down camera fan-out broadcaster for printer 2
+2026-06-22 21:05:40,277 INFO [backend.app.api.routes.camera] [f63cdc10] Stopped 0 camera stream(s) for printer 2
+2026-06-22 21:05:40,278 INFO [uvicorn.access] [-] [IP]:58564 - "POST /api/v1/printers/2/camera/stop HTTP/1.1" 200
+2026-06-22 21:05:45,801 INFO [uvicorn.access] [-] [IP]:53254 - "POST /api/v1/pending-uploads/13/archive HTTP/1.1" 200
+2026-06-22 21:05:47,660 INFO [backend.app.services.print_scheduler] [-] Queue check: found 60 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None)]
+2026-06-22 21:05:47,661 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 60}
+2026-06-22 21:05:47,661 INFO [backend.app.services.print_scheduler] [-] Queue: printer 2 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-06-22 21:06:02,820 INFO [uvicorn.access] [-] [IP]:63122 - "PATCH /api/v1/archives/16 HTTP/1.1" 200
+2026-06-22 21:06:07,964 INFO [backend.app.api.routes.print_queue] [74b90f47] Created batch 7 'Plant Pot · 2 plates' with 0 assigned items
+2026-06-22 21:06:07,965 INFO [uvicorn.access] [-] [IP]:58583 - "POST /api/v1/queue/batches HTTP/1.1" 200
+2026-06-22 21:06:07,970 INFO [backend.app.api.routes.print_queue] [e73f5e3f] Extracted filament types for model-based queue: ['PLA']
+2026-06-22 21:06:07,974 INFO [backend.app.api.routes.print_queue] [e73f5e3f] Added archive 16 to queue for model P1S
+2026-06-22 21:06:07,975 INFO [uvicorn.access] [-] [IP]:58583 - "POST /api/v1/queue/ HTTP/1.1" 200
+2026-06-22 21:06:07,981 INFO [backend.app.api.routes.print_queue] [d4489a6d] Extracted filament types for model-based queue: ['PLA']
+2026-06-22 21:06:07,985 INFO [backend.app.api.routes.print_queue] [d4489a6d] Added archive 16 to queue for model P1S
+2026-06-22 21:06:07,986 INFO [uvicorn.access] [-] [IP]:58583 - "POST /api/v1/queue/ HTTP/1.1" 200
+2026-06-22 21:06:08,545 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] 1Hz status push: 49 pushes/min to [IP]:62391
+2026-06-22 21:06:10,083 INFO [backend.app.api.routes.printers] [2d180d12] Cover: resolved plate 1 before download (subtask=NEW_Rowan_Coin_Test_1_5_10_25)
+2026-06-22 21:06:17,677 INFO [backend.app.services.print_scheduler] [-] Queue check: found 62 pending items: [(76, None, 1, None), (77, None, 1, None), (78, None, 1, None), (79, None, 1, None), (80, None, 1, None), (81, None, 1, None), (82, None, 1, None), (83, None, 1, None), (84, None, 2, None), (85, None, 2, None), (86, None, 2, None), (87, None, 2, None), (88, None, 2, None), (89, None, 2, None), (90, None, 2, None), (91, None, 2, None), (92, None, 2, None), (93, None, 2, None), (94, None, 2, None), (95, None, 2, None), (96, None, 2, None), (97, None, 2, None), (98, None, 2, None), (99, None, 2, None), (100, None, 2, None), (101, None, 2, None), (102, None, 3, None), (103, None, 3, None), (104, None, 3, None), (105, None, 3, None), (106, None, 3, None), (107, None, 3, None), (108, None, 3, None), (109, None, 3, None), (110, None, 3, None), (111, None, 3, None), (112, None, 3, None), (113, None, 3, None), (114, None, 3, None), (115, None, 3, None), (116, None, 3, None), (117, None, 3, None), (118, None, 3, None), (119, None, 3, None), (120, None, 3, None), (121, None, 3, None), (122, None, 3, None), (123, None, 3, None), (124, None, 3, None), (125, None, 3, None), (126, None, 3, None), (127, None, 3, None), (128, None, 3, None), (129, None, 3, None), (130, None, 3, None), (131, None, 3, None), (132, None, 3, None), (133, None, 3, None), (134, None, 3, None), (135, None, 3, None), (139, None, 16, None), (140, None, 16, None)]
+2026-06-22 21:06:17,679 INFO [backend.app.services.print_scheduler] [-] Model-based assignment: queue item 139 assigned to printer 1
+2026-06-22 21:06:17,682 INFO [backend.app.services.print_scheduler] [-] [prefer-lowest] skipped (AMS Backup OFF on printer 1)
+2026-06-22 21:06:17,683 INFO [backend.app.services.print_scheduler] [-] Queue item 139: Computed AMS mapping for printer 1: [0]
+2026-06-22 21:06:17,687 INFO [backend.app.services.print_scheduler] [-] Starting queue item 139
+2026-06-22 21:06:17,690 INFO [backend.app.services.print_scheduler] [-] Queue item 139: FTP upload starting - printer=[PRINTER] (P1S), ip=[IP], file=Untitled.3mf, local_path=C:\ProgramData\Bambuddy\data\archive\unassigned\20260622_210545_Untitled\Untitled.gcode.3mf, retry_enabled=True, retry_count=3, timeout=30.0
+2026-06-22 21:06:18,602 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=P1S, prot_c=False)
+2026-06-22 21:06:18,734 INFO [backend.app.services.bambu_ftp] [-] FTP connecting to [IP] for upload (model=P1S, mode=prot_p, socket_timeout=30.0s)...
+2026-06-22 21:06:19,666 INFO [backend.app.services.bambu_ftp] [-] FTP connected successfully to [IP] (model=P1S, prot_c=False)
+2026-06-22 21:06:19,666 INFO [backend.app.services.bambu_ftp] [-] FTP connected to [IP]
+2026-06-22 21:06:19,666 INFO [backend.app.services.bambu_ftp] [-] FTP uploading C:\ProgramData\Bambuddy\data\archive\unassigned\20260622_210545_Untitled\Untitled.gcode.3mf (117443066 bytes) to /Untitled.3mf
+2026-06-22 21:06:19,817 INFO [backend.app.services.bambu_ftp] [-] FTP data channel ready in 0.2s (PASV + TLS handshake)
+2026-06-22 21:07:03,854 INFO [backend.app.main] [-] Recorded 3 AMS sensor history entries
+2026-06-22 21:07:10,318 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] 1Hz status push: 60 pushes/min to [IP]:62391
+2026-06-22 21:07:17,447 INFO [backend.app.api.routes.print_queue] [66810461] Reordered 62 queue items
+2026-06-22 21:07:17,447 INFO [uvicorn.access] [-] [IP]:56378 - "POST /api/v1/queue/reorder HTTP/1.1" 200
+2026-06-22 21:07:28,193 WARNING [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Connection stale - no message for 71.2s, forcing reconnect
+2026-06-22 21:07:28,194 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Disconnect callback after stale reconnect (expected), rc=Normal disconnection
+2026-06-22 21:07:28,203 INFO [backend.app.main] [-] [#1752] Printer 1 connected→disconnected edge; scheduling offline notification in 60s
+2026-06-22 21:07:30,776 INFO [backend.app.main] [-] [#1752] Printer 1 reconnected before debounce; cancelling pending offline notification
+2026-06-22 21:07:32,553 INFO [backend.app.api.routes.printers] [9e357d58] Cover: resolved plate 1 before download (subtask=NEW_Rowan_Coin_Test_1_5_10_25)
+2026-06-22 21:07:50,017 INFO [backend.app.api.routes.printers] [80d3cdeb] Cover: resolved plate 1 before download (subtask=NEW_Rowan_Coin_Test_1_5_10_25)
+2026-06-22 21:08:12,572 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] 1Hz status push: 60 pushes/min to [IP]:62391
+2026-06-22 21:08:19,881 INFO [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Tray change during print: tray=4 at layer=1
+2026-06-22 21:09:15,523 INFO [backend.app.services.virtual_printer.mqtt_server] [3e217fc1] [Review] 1Hz status push: 60 pushes/min to [IP]:62391
+2026-06-22 21:09:48,067 INFO [backend.app.api.routes.support] [5e5261d8] Log level changed to DEBUG
+2026-06-22 21:09:48,067 INFO [backend.app.api.routes.bug_report] [5e5261d8] Bug report: enabled debug logging
+2026-06-22 21:09:48,068 DEBUG [backend.app.services.bambu_mqtt] [5e5261d8] [[SERIAL]] Requesting status update (pushall)
+2026-06-22 21:09:48,068 DEBUG [backend.app.services.bambu_mqtt] [5e5261d8] [[SERIAL]] Requesting status update (pushall)
+2026-06-22 21:09:48,068 INFO [uvicorn.access] [-] [IP]:51873 - "POST /api/v1/bug-report/start-logging HTTP/1.1" 200
+2026-06-22 21:09:48,332 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 28966912/117443066 bytes
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: NEW_Rowan_Coin_Test_1_5_10_25.3mf, subtask_name: NEW_Rowan_Coin_Test_1_5_10_25
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '3', 'tray_exist_bits': 'bf', 'tray_is_bbl_bits': 'bf', 'tray_tar': '4', 'tray_now': '4', 'tray_pre': '2', 'tray_read_done_bits': 'bf', 'tray_reading_bits': '0', 'version': 321, 'insert_flag': True, 'power_on_flag': True}
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] tray_now updated: 4
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Merged AMS data: 2 new units, 2 total
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 0 info=0x1001 -> extruder 0
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 1 info=0x1001 -> extruder 0
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0, '1': 0}
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_status: 263 (main=1, sub=7)
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] chamber_temper raw value: 5.0
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] chamber_temper direct value: 5.0°C (heater OFF)
+2026-06-22 21:09:48,379 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber heating calculated: target=0.0, current=5.0, heating=False, respect_local=False
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber temp updated to: 5.0, target: 0.0, heating: False
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: []
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ipcam field: {'ipcam_dev': '1', 'ipcam_record': 'enable', 'timelapse': 'enable', 'resolution': '', 'tutk_server': 'disable', 'mode_bits': 3}
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Timelapse detected during print (from ipcam)
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -36dBm
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] lights_report: [{'node': 'chamber_light', 'mode': 'on'}]
+2026-06-22 21:09:48,380 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: NEW_Rowan_Coin_Test_1_5_10_25.3mf, subtask: NEW_Rowan_Coin_Test_1_5_10_25
+2026-06-22 21:09:48,726 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29032448/117443066 bytes
+2026-06-22 21:09:49,141 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29097984/117443066 bytes
+2026-06-22 21:09:49,525 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29163520/117443066 bytes
+2026-06-22 21:09:49,915 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29229056/117443066 bytes
+2026-06-22 21:09:50,308 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29294592/117443066 bytes
+2026-06-22 21:09:50,395 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-06-22 21:09:50,395 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -37dBm
+2026-06-22 21:09:50,703 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29360128/117443066 bytes
+2026-06-22 21:09:51,018 DEBUG [backend.app.api.routes.printers] [53a0a463] API returning ams_mapping: [], ams_extruder_map: {'0': 0}
+2026-06-22 21:09:51,018 DEBUG [backend.app.api.routes.printers] [53a0a463] Using tray_now directly as global ID: 255
+2026-06-22 21:09:51,091 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29425664/117443066 bytes
+2026-06-22 21:09:51,469 DEBUG [backend.app.services.bambu_ftp] [-] FTP upload progress: 29491200/117443066 bytes