[Bug] New total usage sensor incorrectly added 23.7 hours

[AdrianGarside]

Describe the bug

The logs show the integration believed it observed two print starts back to back (<4s) and the first one was registered as 23.7 hours in duration!

To Reproduce

.

Expected Behaviour

.

What device are you using?

P1P

Diagnostic Output

.

Log Extracts

2024-01-15 21:18:59.854 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] EVENT: event_print_started: {'device_id': '78189ca5fe5e1c28683002a8cdacb55d', 'type': 'event_print_started'}
2024-01-15 21:18:59.855 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting latest task from Bambu Cloud for Printer: REDACTED
2024-01-15 21:18:59.856 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting task list from Bambu Cloud for Printer: REDACTED
2024-01-15 21:18:59.865 INFO (MainThread) [homeassistant.components.automation.print_started_2] P1P print started: Running automation actions
2024-01-15 21:18:59.865 INFO (MainThread) [homeassistant.components.automation.print_started_2] P1P print started: Executing step call service
2024-01-15 21:18:59.871 DEBUG (SyncWorker_7) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:18:59.877 DEBUG (SyncWorker_7) [custom_components.bambu_lab.pybambu] Sent {'system': {'sequence_id': '0', 'command': 'ledctrl', 'led_node': 'chamber_light', 'led_mode': 'on', 'led_on_time': 500, >2024-01-15 21:19:00.069 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Updating bambu cloud task data found for printer.
2024-01-15 21:19:00.069 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Downloading cover image: https://makerworld.bblmw.com/makerworld/cache/1/US1bdb1b427bbb00/41883278/3mf/13/%23...
2024-01-15 21:19:00.126 DEBUG (Thread-10) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:00.410 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:00.750 DEBUG (Thread-4 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: X1C
2024-01-15 21:19:01.107 DEBUG (Thread-21) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:01.131 DEBUG (Thread-10) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:01.773 DEBUG (Thread-4 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: X1C
2024-01-15 21:19:01.893 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: P1P
2024-01-15 21:19:01.894 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] NEW USAGE HOURS: 23.7
2024-01-15 21:19:01.894 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:01.896 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] OVERWRITING USAGE_HOURS WITH : 806.3
2024-01-15 21:19:02.137 DEBUG (Thread-10) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:02.790 DEBUG (Thread-4 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: X1C
2024-01-15 21:19:03.115 DEBUG (Thread-21) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:03.140 DEBUG (Thread-10) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:03.776 DEBUG (Thread-4 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: X1C
2024-01-15 21:19:03.943 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Received data from: P1P
2024-01-15 21:19:03.944 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] EVENT: event_print_started: {'device_id': '78189ca5fe5e1c28683002a8cdacb55d', 'type': 'event_print_started'}
2024-01-15 21:19:03.944 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting latest task from Bambu Cloud for Printer: REDACTED
2024-01-15 21:19:03.944 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting task list from Bambu Cloud for Printer: REDACTED
2024-01-15 21:19:03.964 INFO (MainThread) [homeassistant.components.automation.print_started_2] P1P print started: Running automation actions
2024-01-15 21:19:03.966 INFO (MainThread) [homeassistant.components.automation.print_started_2] P1P print started: Executing step call service
2024-01-15 21:19:03.975 DEBUG (SyncWorker_9) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:03.984 DEBUG (SyncWorker_9) [custom_components.bambu_lab.pybambu] Sent {'system': {'sequence_id': '0', 'command': 'ledctrl', 'led_node': 'chamber_light', 'led_mode': 'on', 'led_on_time': 500, >2024-01-15 21:19:04.121 DEBUG (Thread-21) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:04.143 DEBUG (Thread-10) [custom_components.bambu_lab] Manually updated bambu_lab data
2024-01-15 21:19:04.151 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Updating bambu cloud task data found for printer.
2024-01-15 21:19:04.152 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Downloading cover image: https://makerworld.bblmw.com/makerworld/cache/1/US1bdb1b427bbb00/41883278/3mf/13/%23...
2024-01-15 21:19:04.273 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] Manually updated bambu_lab data

Other Information

No response

[AdrianGarside]

2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: FINISH -> PREPARE 2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: FINISH -> PREPARE 2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] EVENT: event_print_started: {'device_id': 'a6d44b8813b975f182f9d070ae9e5208', 'type': 'event_print_started'} 2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GENERATED START TIME: 2024-01-19 14:20:00 2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting latest task from Bambu Cloud for Printer: SERIAL 2024-01-19 14:20:10.149 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting task list from Bambu Cloud for Printer: SERIAL 2024-01-19 14:20:10.367 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Updating bambu cloud task data found for printer. 2024-01-19 14:20:10.367 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Downloading cover image: https://bbl-prod-us-model.s3.dualstack.us-west-1.amazonaws.com/...e7abc 2024-01-19 14:20:10.658 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD START TIME1: 2024-01-19 14:20:00 2024-01-19 14:20:10.658 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD START TIME2: 2024-01-19 14:20:04 2024-01-19 14:20:10.658 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD END TIME1: 2024-01-19 14:06:00 2024-01-19 14:20:10.658 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD END TIME2: 2024-01-19 14:20:05 2024-01-19 14:20:31.084 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: PREPARE -> IDLE 2024-01-19 14:20:31.084 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: PREPARE -> IDLE 2024-01-19 14:20:31.084 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] NEW USAGE HOURS: 0.0002777777777777778 2024-01-19 14:20:31.085 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] OVERWRITING USAGE_HOURS WITH : 285.9827777777778 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: IDLE -> PREPARE 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: IDLE -> PREPARE 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab] EVENT: event_print_started: {'device_id': 'a6d44b8813b975f182f9d070ae9e5208', 'type': 'event_print_started'} 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GENERATED START TIME: 2024-01-19 14:20:00 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting latest task from Bambu Cloud for Printer: SERIAL 2024-01-19 14:20:35.189 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Getting task list from Bambu Cloud for Printer: SERIAL 2024-01-19 14:20:35.336 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Updating bambu cloud task data found for printer. 2024-01-19 14:20:35.336 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] Downloading cover image: https://bbl-prod-us-model.s3.dualstack.us-west-1.amazonaws.com/...bca91 2024-01-19 14:20:35.616 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD START TIME1: 2024-01-19 14:20:00 2024-01-19 14:20:35.616 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD START TIME2: 2024-01-19 14:20:04 2024-01-19 14:20:35.616 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD END TIME1: 2024-01-19 14:20:05 2024-01-19 14:20:35.616 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] CLOUD END TIME2: 2024-01-19 14:20:28 2024-01-19 14:20:40.422 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: PREPARE -> RUNNING 2024-01-19 14:20:40.422 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] GCODE_STATE: PREPARE -> RUNNING 2024-01-19 14:20:40.422 DEBUG (Thread-3 (mqtt_listen_thread)) [custom_components.bambu_lab.pybambu] END TIME2: 2024-01-19 16:23:00

The cause was a PREPARE -> IDLE transition shortly into the print process and not uniformly setting the start/end time for P1/A1 printers where we generate the start time (by observing the print starting) because, unlike the X1, it's not in the mqtt payload. That left us with an updated start time and the end time for the previous print (almost a day ago in my original repro). The fix I made was to fully use the cloud start/end time when it's available preferentially over the generated time. Which will fix the behavior with a bambu cloud connected integration. But printers that are connected to local mqtt and bambu credentials haven't been provided are likely still going to be exposed to this. So I probably need to set end time = start_time when generating the start time but the mqtt data might still overwrite that.