Bug report logs 51a2aa39bea04476989c99df74243e28.log

logs/51a2aa39bea04476989c99df74243e28.log

@@ -0,0 +1,200 @@
+2026-08-25 21:06:38,210 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:06:44,054 INFO [backend.app.api.routes.print_queue] [9abb997f] Created batch 7 'Skadis PRO Pegboard System · 2 plates' with 0 assigned items
+2026-08-25 21:06:44,056 INFO [uvicorn.access] [-] [IP]:47286 - "POST /api/v1/queue/batches HTTP/1.1" 200
+2026-08-25 21:06:44,072 INFO [backend.app.api.routes.print_queue] [e89a47dd] Added archive 150 to queue for 1 (×8)
+2026-08-25 21:06:44,073 INFO [uvicorn.access] [-] [IP]:47298 - "POST /api/v1/queue/ HTTP/1.1" 200
+2026-08-25 21:06:44,088 INFO [backend.app.api.routes.print_queue] [f0f1189e] Added archive 150 to queue for 1 (×8)
+2026-08-25 21:06:44,090 INFO [uvicorn.access] [-] [IP]:47302 - "POST /api/v1/queue/ HTTP/1.1" 200
+2026-08-25 21:06:48,485 INFO [backend.app.api.routes.print_queue] [09f6c914] Reordered 31 queue items
+2026-08-25 21:06:48,486 INFO [uvicorn.access] [-] [IP]:50296 - "POST /api/v1/queue/reorder HTTP/1.1" 200
+2026-08-25 21:06:57,361 INFO [backend.app.main] [-] Evicted 1 stale expected-print entries (TTL=7200s)
+2026-08-25 21:07:08,221 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:07:08,223 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:07:08,223 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:07:10,357 INFO [backend.app.main] [-] Recorded 1 AMS sensor history entries
+2026-08-25 21:07:11,659 INFO [backend.app.api.routes.printers] [830aa988] Cover: resolved plate 2 before download (subtask=Skadis+PRO+Medium+3MF)
+2026-08-25 21:07:38,234 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:07:38,236 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:07:38,236 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:08:08,247 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:08:08,249 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:08:08,249 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:08:38,261 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:08:38,263 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:08:38,263 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:09:05,567 INFO [backend.app.api.routes.print_queue] [1b7ee24f] Updated queue item 186
+2026-08-25 21:09:05,568 INFO [uvicorn.access] [-] [IP]:49112 - "PATCH /api/v1/queue/186 HTTP/1.1" 200
+2026-08-25 21:09:08,274 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:09:08,275 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:09:08,276 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:09:38,288 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (186, 1, 148, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:09:38,289 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:09:38,290 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:10:00,786 INFO [backend.app.api.routes.print_queue] [65747892] Cancelled queue item 186
+2026-08-25 21:10:00,786 INFO [uvicorn.access] [-] [IP]:48162 - "POST /api/v1/queue/186/cancel HTTP/1.1" 200
+2026-08-25 21:10:08,301 INFO [backend.app.services.print_scheduler] [-] Queue check: found 30 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:10:08,302 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 14}
+2026-08-25 21:10:08,303 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:10:38,314 INFO [backend.app.services.print_scheduler] [-] Queue check: found 30 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (187, 1, 148, None), (188, 1, 148, None), (189, 1, 148, None), (190, 1, 148, None), (191, 1, 148, None), (193, 1, 148, None), (195, 1, 148, None), (192, 1, 148, None), (200, 1, 148, None), (196, 1, 148, None), (197, 1, 148, None), (198, 1, 148, None), (199, 1, 148, None)]
+2026-08-25 21:10:38,316 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 14}
+2026-08-25 21:10:38,316 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:10:59,182 INFO [backend.app.api.routes.print_queue] [5cf80d95] Cancelled queue item 187
+2026-08-25 21:10:59,182 INFO [uvicorn.access] [-] [IP]:52388 - "POST /api/v1/queue/187/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,191 INFO [backend.app.api.routes.print_queue] [1d6266b1] Cancelled queue item 188
+2026-08-25 21:10:59,191 INFO [uvicorn.access] [-] [IP]:52390 - "POST /api/v1/queue/188/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,198 INFO [backend.app.api.routes.print_queue] [098bc50c] Cancelled queue item 189
+2026-08-25 21:10:59,199 INFO [uvicorn.access] [-] [IP]:52394 - "POST /api/v1/queue/189/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,205 INFO [backend.app.api.routes.print_queue] [2fbb830c] Cancelled queue item 190
+2026-08-25 21:10:59,206 INFO [uvicorn.access] [-] [IP]:52408 - "POST /api/v1/queue/190/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,212 INFO [backend.app.api.routes.print_queue] [509af523] Cancelled queue item 191
+2026-08-25 21:10:59,213 INFO [uvicorn.access] [-] [IP]:52416 - "POST /api/v1/queue/191/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,229 INFO [backend.app.api.routes.print_queue] [f4cc23b0] Cancelled queue item 193
+2026-08-25 21:10:59,229 INFO [uvicorn.access] [-] [IP]:52432 - "POST /api/v1/queue/193/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,238 INFO [backend.app.api.routes.print_queue] [6e0aea97] Cancelled queue item 195
+2026-08-25 21:10:59,239 INFO [uvicorn.access] [-] [IP]:52446 - "POST /api/v1/queue/195/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,245 INFO [backend.app.api.routes.print_queue] [f55ded4b] Cancelled queue item 192
+2026-08-25 21:10:59,246 INFO [uvicorn.access] [-] [IP]:52458 - "POST /api/v1/queue/192/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,253 INFO [backend.app.api.routes.print_queue] [d6fa0f60] Cancelled queue item 200
+2026-08-25 21:10:59,253 INFO [uvicorn.access] [-] [IP]:52472 - "POST /api/v1/queue/200/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,260 INFO [backend.app.api.routes.print_queue] [01ba3271] Cancelled queue item 196
+2026-08-25 21:10:59,260 INFO [uvicorn.access] [-] [IP]:52474 - "POST /api/v1/queue/196/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,267 INFO [backend.app.api.routes.print_queue] [1b4e02c7] Cancelled queue item 197
+2026-08-25 21:10:59,267 INFO [uvicorn.access] [-] [IP]:52490 - "POST /api/v1/queue/197/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,274 INFO [backend.app.api.routes.print_queue] [13bdfc1a] Cancelled queue item 198
+2026-08-25 21:10:59,274 INFO [uvicorn.access] [-] [IP]:52492 - "POST /api/v1/queue/198/cancel HTTP/1.1" 200
+2026-08-25 21:10:59,281 INFO [backend.app.api.routes.print_queue] [72a68a81] Cancelled queue item 199
+2026-08-25 21:10:59,281 INFO [uvicorn.access] [-] [IP]:52508 - "POST /api/v1/queue/199/cancel HTTP/1.1" 200
+2026-08-25 21:11:08,327 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:11:08,329 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:11:08,329 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:11:38,342 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:11:38,343 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:11:38,343 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:12:08,354 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:12:08,356 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:12:08,356 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:12:10,362 INFO [backend.app.main] [-] Recorded 1 AMS sensor history entries
+2026-08-25 21:12:38,367 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:12:38,369 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:12:38,369 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:13:08,380 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:13:08,382 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:13:08,382 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:13:38,392 INFO [backend.app.services.print_scheduler] [-] Queue check: found 17 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None)]
+2026-08-25 21:13:38,394 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 1}
+2026-08-25 21:13:38,394 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:13:53,435 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] MQTT TLS connection from ('[IP]', 62278) - cipher=('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256), version=TLSv1.3
+2026-08-25 21:13:53,435 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] MQTT client connected: [IP]:62278
+2026-08-25 21:13:53,435 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] MQTT client authenticated successfully
+2026-08-25 21:13:53,435 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] MQTT client [IP]:62278 authenticated (negotiated keepalive=60s, idle disconnect disabled)
+2026-08-25 21:13:53,435 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] MQTT subscribe: device/[SERIAL]/report QoS=0
+2026-08-25 21:13:53,460 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT publish to device/[SERIAL]/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20016","version":1}}...
+2026-08-25 21:13:53,460 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT pushing command: pushall
+2026-08-25 21:13:53,460 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] Sending status report in response to pushall
+2026-08-25 21:13:53,460 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20017"}}...
+2026-08-25 21:13:53,461 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT info command: get_version
+2026-08-25 21:13:53,461 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] Sent version response (product_name=[PRINTER])
+2026-08-25 21:13:53,461 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20018"}}...
+2026-08-25 21:13:53,461 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT info command: get_version
+2026-08-25 21:13:53,461 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] Sent version response (product_name=[PRINTER])
+2026-08-25 21:13:57,213 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT publish to device/[SERIAL]/request: {"info":{"command":"get_version","sequence_id":"20019"}}...
+2026-08-25 21:13:57,213 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT info command: get_version
+2026-08-25 21:13:57,213 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] Sent version response (product_name=[PRINTER])
+2026-08-25 21:13:57,213 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT publish to device/[SERIAL]/request: {"pushing":{"command":"pushall","push_target":1,"sequence_id":"20020","version":1}}...
+2026-08-25 21:13:57,214 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] MQTT pushing command: pushall
+2026-08-25 21:13:57,214 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] Sending status report in response to pushall
+2026-08-25 21:14:01,318 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP connection from ('[IP]', 62296)
+2026-08-25 21:14:01,319 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP login from [IP]
+2026-08-25 21:14:01,321 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP EPSV listening on port 50002
+2026-08-25 21:14:01,322 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP receiving file: verify_job from [IP]
+2026-08-25 21:14:01,323 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-08-25 21:14:01,324 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP data connection established from [IP]
+2026-08-25 21:14:01,426 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP saved file: /app/data/virtual_printer/uploads/1/verify_job (16 bytes)
+2026-08-25 21:14:01,426 INFO [backend.app.services.virtual_printer.manager] [169087c0] [VP [PRINTER] Queue] Received file: verify_job from [IP]
+2026-08-25 21:14:01,427 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP session cancelled from [IP]
+2026-08-25 21:14:01,427 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP session ended from [IP]
+2026-08-25 21:14:01,433 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP connection from ('[IP]', 62300)
+2026-08-25 21:14:01,434 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP login from [IP]
+2026-08-25 21:14:01,434 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP EPSV listening on port 50004
+2026-08-25 21:14:01,446 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP receiving file: Truck+&+Trailer+3mf.gcode.3mf from [IP]
+2026-08-25 21:14:01,447 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP data TLS from [IP]: cipher=('ECDHE-RSA-AES256-GCM-SHA384', 'TLSv1.2', 256), version=TLSv1.2, session_reused=True
+2026-08-25 21:14:01,447 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP data connection established from [IP]
+2026-08-25 21:14:01,946 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] FTP saved file: /app/data/virtual_printer/uploads/1/Truck+&+Trailer+3mf.gcode.3mf (45785927 bytes)
+2026-08-25 21:14:01,946 INFO [backend.app.services.virtual_printer.manager] [169087c0] [VP [PRINTER] Queue] Received file: Truck+&+Trailer+3mf.gcode.3mf from [IP]
+2026-08-25 21:14:07,079 INFO [backend.app.services.virtual_printer.manager] [169087c0] [VP [PRINTER] Queue] Archived: 151 - DIY RC Semi Truck
+2026-08-25 21:14:07,120 INFO [backend.app.services.virtual_printer.manager] [169087c0] [VP [PRINTER] Queue] Added 15 queue items for multi-plate upload (plates [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15]): [238, 239, 240, 241, 242, 243, 244, 245, 246, 247, 248, 249, 250, 251, 252]
+2026-08-25 21:14:07,125 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP session cancelled from [IP]
+2026-08-25 21:14:07,125 INFO [backend.app.services.virtual_printer.ftp_server] [169087c0] [[PRINTER] Queue] FTP session ended from [IP]
+2026-08-25 21:14:08,405 INFO [backend.app.services.print_scheduler] [-] Queue check: found 32 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (246, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:14:08,407 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 16}
+2026-08-25 21:14:08,407 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:14:25,785 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] 1Hz status push: 33 pushes/min to [IP]:62278
+2026-08-25 21:14:29,320 INFO [backend.app.api.routes.print_queue] [acbb725e] Created batch 8 'DIY RC Semi Truck' with 15 assigned items
+2026-08-25 21:14:29,322 INFO [uvicorn.access] [-] [IP]:49644 - "POST /api/v1/queue/batches HTTP/1.1" 200
+2026-08-25 21:14:38,418 INFO [backend.app.services.print_scheduler] [-] Queue check: found 32 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (246, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:14:38,420 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 16}
+2026-08-25 21:14:38,420 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:14:44,592 INFO [backend.app.api.routes.print_queue] [1ce12813] Cancelled queue item 246
+2026-08-25 21:14:44,592 INFO [uvicorn.access] [-] [IP]:46274 - "POST /api/v1/queue/246/cancel HTTP/1.1" 200
+2026-08-25 21:15:08,430 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:15:08,432 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:15:08,432 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:15:20,621 INFO [backend.app.api.routes.print_queue] [d8b595f6] Updated queue item 238
+2026-08-25 21:15:20,622 INFO [uvicorn.access] [-] [IP]:37840 - "PATCH /api/v1/queue/238 HTTP/1.1" 200
+2026-08-25 21:15:25,857 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] 1Hz status push: 60 pushes/min to [IP]:62278
+2026-08-25 21:15:32,084 INFO [backend.app.api.routes.print_queue] [320e57c3] Updated queue item 238
+2026-08-25 21:15:32,085 INFO [uvicorn.access] [-] [IP]:56612 - "PATCH /api/v1/queue/238 HTTP/1.1" 200
+2026-08-25 21:15:38,443 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:15:38,445 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:15:38,445 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:16:08,456 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:16:08,458 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:16:08,458 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:16:25,929 INFO [backend.app.services.virtual_printer.mqtt_server] [169087c0] [[PRINTER] Queue] 1Hz status push: 60 pushes/min to [IP]:62278
+2026-08-25 21:16:38,471 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:16:38,472 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:16:38,473 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:17:01,696 INFO [backend.app.api.routes.support] [2182b6f4] Log level changed to DEBUG
+2026-08-25 21:17:01,696 INFO [backend.app.api.routes.bug_report] [2182b6f4] Bug report: enabled debug logging
+2026-08-25 21:17:01,696 DEBUG [backend.app.services.bambu_mqtt] [2182b6f4] [[SERIAL]] Requesting status update (pushall)
+2026-08-25 21:17:01,697 INFO [uvicorn.access] [-] [IP]:48754 - "POST /api/v1/bug-report/start-logging HTTP/1.1" 200
+2026-08-25 21:17:01,845 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received gcode_state: RUNNING, gcode_file: Skadis+PRO+Medium+3MF.3mf, subtask_name: Skadis+PRO+Medium+3MF
+2026-08-25 21:17:01,845 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS dict fields: {'ams_exist_bits': '1', 'tray_exist_bits': 'f', 'tray_is_bbl_bits': 'f', 'tray_tar': '1', 'tray_now': '1', 'tray_pre': '1', 'tray_read_done_bits': 'f', 'tray_reading_bits': '0', 'version': 115, 'insert_flag': True, 'power_on_flag': False}
+2026-08-25 21:17:01,845 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] tray_now updated: 1
+2026-08-25 21:17:01,845 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Merged AMS data: 1 new units, 1 total
+2026-08-25 21:17:01,845 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] AMS 0 info=0x1001 -> extruder 0
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_extruder_map: {'0': 0}
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ams_status: 768 (main=3, sub=0)
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] chamber_temper raw value: 5.0
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] chamber_temper direct value: 5.0°C (heater OFF)
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber heating calculated: target=0.0, current=5.0, heating=False, respect_local=False
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Chamber temp updated to: 5.0, target: 0.0, heating: False
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] HMS data received: []
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] ipcam field: {'ipcam_dev': '1', 'ipcam_record': 'disable', 'timelapse': 'disable', 'resolution': '', 'tutk_server': 'disable', 'mode_bits': 3}
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -39dBm
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] lights_report: [{'node': 'chamber_light', 'mode': 'on'}]
+2026-08-25 21:17:01,846 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] gcode_state: RUNNING -> RUNNING, file: Skadis+PRO+Medium+3MF.3mf, subtask: Skadis+PRO+Medium+3MF
+2026-08-25 21:17:03,874 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:03,874 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -32dBm
+2026-08-25 21:17:04,065 DEBUG [backend.app.api.routes.printers] [506fbbc6] API returning ams_mapping: [], ams_extruder_map: {'0': 0}
+2026-08-25 21:17:04,065 DEBUG [backend.app.api.routes.printers] [506fbbc6] Using tray_now directly as global ID: 1
+2026-08-25 21:17:04,628 DEBUG [backend.app.api.routes.printers] [d8bbc26e] API returning ams_mapping: [], ams_extruder_map: {'0': 0}
+2026-08-25 21:17:04,628 DEBUG [backend.app.api.routes.printers] [d8bbc26e] Using tray_now directly as global ID: 1
+2026-08-25 21:17:05,945 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:05,945 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -31dBm
+2026-08-25 21:17:06,754 INFO [backend.app.api.routes.print_queue] [0f4a6ea8] Updated queue item 238
+2026-08-25 21:17:06,755 INFO [uvicorn.access] [-] [IP]:54250 - "PATCH /api/v1/queue/238 HTTP/1.1" 200
+2026-08-25 21:17:08,483 INFO [backend.app.services.print_scheduler] [-] Queue check: found 31 pending items: [(201, 1, 142, None), (222, 1, 150, None), (223, 1, 150, None), (224, 1, 150, None), (225, 1, 150, None), (226, 1, 150, None), (227, 1, 150, None), (228, 1, 150, None), (229, 1, 150, None), (230, 1, 150, None), (231, 1, 150, None), (232, 1, 150, None), (233, 1, 150, None), (234, 1, 150, None), (235, 1, 150, None), (236, 1, 150, None), (237, 1, 150, None), (238, 1, 151, None), (239, 1, 151, None), (240, 1, 151, None), (241, 1, 151, None), (242, 1, 151, None), (243, 1, 151, None), (244, 1, 151, None), (245, 1, 151, None), (247, 1, 151, None), (248, 1, 151, None), (249, 1, 151, None), (250, 1, 151, None), (251, 1, 151, None), (252, 1, 151, None)]
+2026-08-25 21:17:08,485 INFO [backend.app.services.print_scheduler] [-] Queue skip summary: {'manual_start': 15}
+2026-08-25 21:17:08,485 INFO [backend.app.services.print_scheduler] [-] Queue: printer 1 not available — connected=True, state=RUNNING, awaiting_plate_clear=False
+2026-08-25 21:17:09,993 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:09,993 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -32dBm
+2026-08-25 21:17:10,201 DEBUG [backend.app.services.virtual_printer.ssdp_server] [169087c0] Sent SSDP NOTIFY for [PRINTER] Queue (Location=[IP], USN=[SERIAL], bind=[IP])
+2026-08-25 21:17:10,366 INFO [backend.app.main] [-] Recorded 1 AMS sensor history entries
+2026-08-25 21:17:11,417 INFO [backend.app.api.routes.print_queue] [64f73583] Updated queue item 238
+2026-08-25 21:17:11,418 INFO [uvicorn.access] [-] [IP]:54284 - "PATCH /api/v1/queue/238 HTTP/1.1" 200
+2026-08-25 21:17:12,036 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:12,036 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -36dBm
+2026-08-25 21:17:14,096 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] Received command response: push_status
+2026-08-25 21:17:14,096 DEBUG [backend.app.services.bambu_mqtt] [-] [[SERIAL]] wifi_signal received: -40dBm