SAIC-iSmart-API / saic-python-mqtt-gateway

MIT License
67 stars 20 forks source link

0.7.0-rc3 - handle_vehicle loop failed with unexpected exception: Vehicle status time drifted too much #263

Open ZionFox opened 9 hours ago

ZionFox commented 9 hours ago

Fairly recently been getting an exception when attempting to do the polling loop, where it says that the time has drifted too far by 4,859 days.

Not entirely sure what caused this. When restarting the container it will sometimes work, and then fail on the next loop with the same issue. This exception is critical, and causes the controls and sensors to return Unavailable.

Log from restart to several exceptions:

2024-09-29 12:50:11,525 [  INFO  ] Logging in to SAIC API - __main__
2024-09-29 12:50:13,805 [  INFO  ] Logged in as [REDACTED] - __main__
2024-09-29 12:50:13,806 [  INFO  ] Fetching vehicle list - __main__
2024-09-29 12:50:13,968 [  INFO  ] Registering for ['ALARM_TYPE_VEHICLE_FAULT', 'ALARM_TYPE_GEOFENCE', 'ALARM_TYPE_VEHICLE_START'] messages. vin=[REDACTED]- __main__
2024-09-29 12:50:14,064 [  INFO  ] Registered for ['ALARM_TYPE_VEHICLE_FAULT', 'ALARM_TYPE_GEOFENCE', 'ALARM_TYPE_VEHICLE_START'] messages. vin=[REDACTED]- __main__
2024-09-29 12:50:14,268 [  INFO  ] Adding job tentatively -- it will be properly scheduled when the scheduler starts - apscheduler.scheduler
2024-09-29 12:50:14,270 [  INFO  ] [CONNECTION MADE] - gmqtt.mqtt.protocol
2024-09-29 12:50:14,272 [  INFO  ] Connected to MQTT broker - publisher.mqtt_publisher
2024-09-29 12:50:14,272 [  INFO  ] [SEND SUB] 1 [b'saic/[REDACTED]/vehicles/+/+/+/set'] - gmqtt.mqtt.package
2024-09-29 12:50:14,272 [  INFO  ] [SEND SUB] 2 [b'saic/[REDACTED]/vehicles/+/+/+/+/set'] - gmqtt.mqtt.package
2024-09-29 12:50:14,272 [  INFO  ] [SEND SUB] 3 [b'saic/[REDACTED]/vehicles/+/refresh/mode/set'] - gmqtt.mqtt.package
2024-09-29 12:50:14,273 [  INFO  ] [SEND SUB] 4 [b'saic/[REDACTED]/vehicles/+/refresh/period/+/set'] - gmqtt.mqtt.package
2024-09-29 12:50:14,275 [  INFO  ] Added job "Check for new messages" to job store "default" - apscheduler.scheduler
2024-09-29 12:50:14,275 [  INFO  ] Scheduler started - apscheduler.scheduler
2024-09-29 12:50:14,276 [  INFO  ] Publishing vehicle info to MQTT - vehicle
2024-09-29 12:50:14,280 [  INFO  ] [SUBACK] 1 (0,) - gmqtt
2024-09-29 12:50:14,280 [  INFO  ] [SUBACK] 2 (0,) - gmqtt
2024-09-29 12:50:14,280 [  INFO  ] [SUBACK] 3 (0,) - gmqtt
2024-09-29 12:50:14,280 [  INFO  ] [SUBACK] 4 (0,) - gmqtt
2024-09-29 12:50:24,295 [  INFO  ] Setting active query interval in vehicle handler for VIN [REDACTED] to 0:00:30 - vehicle
2024-09-29 12:50:24,295 [  INFO  ] Setting after shutdown query interval in vehicle handler for VIN [REDACTED] to 0:02:00 - vehicle
2024-09-29 12:50:24,296 [  INFO  ] Setting inactive query interval in vehicle handler for VIN [REDACTED] to 1 day, 0:00:00 - vehicle
2024-09-29 12:50:24,296 [  INFO  ] Updating remote AC temperature to 22 - vehicle
2024-09-29 12:50:24,296 [  INFO  ] Setting refresh mode to periodic due to initial gateway startup from an invalid state RefreshMode.OFF - vehicle
2024-09-29 12:50:34,659 [ ERROR  ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle
Traceback (most recent call last):
  File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle
    await self.__polling()
  File "/usr/src/app/handlers/vehicle.py", line 106, in __polling
    vehicle_status = await self.update_vehicle_status()
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status
    self.vehicle_state.handle_vehicle_status(vehicle_status_response)
  File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status
    raise MqttGatewayException(
exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:23:32.341149
2024-09-29 12:51:08,991 [ ERROR  ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle
Traceback (most recent call last):
  File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle
    await self.__polling()
  File "/usr/src/app/handlers/vehicle.py", line 106, in __polling
    vehicle_status = await self.update_vehicle_status()
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status
    self.vehicle_state.handle_vehicle_status(vehicle_status_response)
  File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status
    raise MqttGatewayException(
exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:22:58.009230
2024-09-29 12:51:14,270 [  INFO  ] Running job "Check for new messages (trigger: interval[0:01:00], next run at: 2024-09-29 12:52:14 UTC)" (scheduled at 2024-09-29 12:51:14.268203+00:00) - apscheduler.executors.default
2024-09-29 12:51:14,483 [  INFO  ] Job "Check for new messages (trigger: interval[0:01:00], next run at: 2024-09-29 12:52:14 UTC)" executed successfully - apscheduler.executors.default
2024-09-29 12:51:18,703 [ ERROR  ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle
Traceback (most recent call last):
  File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle
    await self.__polling()
  File "/usr/src/app/handlers/vehicle.py", line 106, in __polling
    vehicle_status = await self.update_vehicle_status()
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status
    self.vehicle_state.handle_vehicle_status(vehicle_status_response)
  File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status
    raise MqttGatewayException(
exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:22:48.296769
nanomad commented 9 hours ago

Hi,

This happens because the car or the mg servers report a message date that is too far into the future (or the past). It usually gets solved by checking the clock time on the car or driving it around.

For the debugging purposes you can reach out to me on telegram. Then handle is the same as my username here

Il Dom 29 Set 2024, 15:02 Zion Fox @.***> ha scritto:

Fairly recently been getting an exception when attempting to do the polling loop, where it says that the time has drifted too far by 4,859 days.

Not entirely sure what caused this. When restarting the container it will sometimes work, and then fail on the next loop with the same issue. This exception is critical, and causes the controls and sensors to return Unavailable.

Log from restart to several exceptions:

2024-09-29 12:50:11,525 [ INFO ] Logging in to SAIC API - main 2024-09-29 12:50:13,805 [ INFO ] Logged in as [REDACTED] - main 2024-09-29 12:50:13,806 [ INFO ] Fetching vehicle list - main 2024-09-29 12:50:13,968 [ INFO ] Registering for ['ALARM_TYPE_VEHICLE_FAULT', 'ALARM_TYPE_GEOFENCE', 'ALARM_TYPE_VEHICLE_START'] messages. vin=[REDACTED]- main 2024-09-29 12:50:14,064 [ INFO ] Registered for ['ALARM_TYPE_VEHICLE_FAULT', 'ALARM_TYPE_GEOFENCE', 'ALARM_TYPE_VEHICLE_START'] messages. vin=[REDACTED]- main 2024-09-29 12:50:14,268 [ INFO ] Adding job tentatively -- it will be properly scheduled when the scheduler starts - apscheduler.scheduler 2024-09-29 12:50:14,270 [ INFO ] [CONNECTION MADE] - gmqtt.mqtt.protocol 2024-09-29 12:50:14,272 [ INFO ] Connected to MQTT broker - publisher.mqtt_publisher 2024-09-29 12:50:14,272 [ INFO ] [SEND SUB] 1 [b'saic/[REDACTED]/vehicles/+/+/+/set'] - gmqtt.mqtt.package 2024-09-29 12:50:14,272 [ INFO ] [SEND SUB] 2 [b'saic/[REDACTED]/vehicles/+/+/+/+/set'] - gmqtt.mqtt.package 2024-09-29 12:50:14,272 [ INFO ] [SEND SUB] 3 [b'saic/[REDACTED]/vehicles/+/refresh/mode/set'] - gmqtt.mqtt.package 2024-09-29 12:50:14,273 [ INFO ] [SEND SUB] 4 [b'saic/[REDACTED]/vehicles/+/refresh/period/+/set'] - gmqtt.mqtt.package 2024-09-29 12:50:14,275 [ INFO ] Added job "Check for new messages" to job store "default" - apscheduler.scheduler 2024-09-29 12:50:14,275 [ INFO ] Scheduler started - apscheduler.scheduler 2024-09-29 12:50:14,276 [ INFO ] Publishing vehicle info to MQTT - vehicle 2024-09-29 12:50:14,280 [ INFO ] [SUBACK] 1 (0,) - gmqtt 2024-09-29 12:50:14,280 [ INFO ] [SUBACK] 2 (0,) - gmqtt 2024-09-29 12:50:14,280 [ INFO ] [SUBACK] 3 (0,) - gmqtt 2024-09-29 12:50:14,280 [ INFO ] [SUBACK] 4 (0,) - gmqtt 2024-09-29 12:50:24,295 [ INFO ] Setting active query interval in vehicle handler for VIN [REDACTED] to 0:00:30 - vehicle 2024-09-29 12:50:24,295 [ INFO ] Setting after shutdown query interval in vehicle handler for VIN [REDACTED] to 0:02:00 - vehicle 2024-09-29 12:50:24,296 [ INFO ] Setting inactive query interval in vehicle handler for VIN [REDACTED] to 1 day, 0:00:00 - vehicle 2024-09-29 12:50:24,296 [ INFO ] Updating remote AC temperature to 22 - vehicle 2024-09-29 12:50:24,296 [ INFO ] Setting refresh mode to periodic due to initial gateway startup from an invalid state RefreshMode.OFF - vehicle 2024-09-29 12:50:34,659 [ ERROR ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle Traceback (most recent call last): File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle await self.polling() File "/usr/src/app/handlers/vehicle.py", line 106, in polling vehicle_status = await self.update_vehicle_status() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status self.vehicle_state.handle_vehicle_status(vehicle_status_response) File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status raise MqttGatewayException( exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:23:32.341149 2024-09-29 12:51:08,991 [ ERROR ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle Traceback (most recent call last): File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle await self.polling() File "/usr/src/app/handlers/vehicle.py", line 106, in polling vehicle_status = await self.update_vehicle_status() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status self.vehicle_state.handle_vehicle_status(vehicle_status_response) File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status raise MqttGatewayException( exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:22:58.009230 2024-09-29 12:51:14,270 [ INFO ] Running job "Check for new messages (trigger: interval[0:01:00], next run at: 2024-09-29 12:52:14 UTC)" (scheduled at 2024-09-29 12:51:14.268203+00:00) - apscheduler.executors.default 2024-09-29 12:51:14,483 [ INFO ] Job "Check for new messages (trigger: interval[0:01:00], next run at: 2024-09-29 12:52:14 UTC)" executed successfully - apscheduler.executors.default 2024-09-29 12:51:18,703 [ ERROR ] handle_vehicle loop failed with an unexpected exception - handlers.vehicle Traceback (most recent call last): File "/usr/src/app/handlers/vehicle.py", line 83, in handle_vehicle await self.polling() File "/usr/src/app/handlers/vehicle.py", line 106, in polling vehicle_status = await self.update_vehicle_status() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/app/handlers/vehicle.py", line 156, in update_vehicle_status self.vehicle_state.handle_vehicle_status(vehicle_status_response) File "/usr/src/app/vehicle.py", line 209, in handle_vehicle_status raise MqttGatewayException( exceptions.MqttGatewayException: Vehicle status time drifted too much from current time: 4859 days, 14:22:48.296769

— Reply to this email directly, view it on GitHub https://github.com/SAIC-iSmart-API/saic-python-mqtt-gateway/issues/263, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAIT3RV4HHLJHWEFT52NKNLZY727JAVCNFSM6AAAAABPBWJF4SVHI2DSMVQWIX3LMV43ASLTON2WKOZSGU2TIOJSGYYTQMI . You are receiving this because you are subscribed to this thread.Message ID: @.***>

ZionFox commented 9 hours ago

It's fine that the car or servers are reporting an incorrect time, the unhandled exception is not exactly a great way of handling this edge case however. Perhaps it can be handled, and either reported as a "last poll error" flag, or perhaps there can be an error message sensor that's returned to HA, that can then be used to automate sending the error messages to the user?

I'll verify the clock of the car, but I've just stopped driving it to this issue. If it's the server that's wrong, I suppose I just have to wait.

nanomad commented 9 hours ago

I'll double check the logic but the expectation is

If you are comfortable with python you can download the saic python api ng code from GitHub. Inside the docs folder there's a simple main you can run to dump server responses. I'd love to see your reported car state in this scenario.

Il Dom 29 Set 2024, 15:18 Zion Fox @.***> ha scritto:

It's fine that the car or servers are reporting an incorrect time, the unhandled exception is not exactly a great way of handling this edge case however. Perhaps it can be handled, and either reported as a "last poll error" flag, or perhaps there can be an error message sensor that's returned to HA, that can then be used to automate sending the error messages to the user?

I'll verify the clock of the car, but I've just stopped driving it to this issue. If it's the server that's wrong, I suppose I just have to wait.

— Reply to this email directly, view it on GitHub https://github.com/SAIC-iSmart-API/saic-python-mqtt-gateway/issues/263#issuecomment-2381354811, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAIT3RTB2UUQYWA2XSUADKLZY7437AVCNFSM6AAAAABPBWJF4SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGOBRGM2TIOBRGE . You are receiving this because you commented.Message ID: @.*** com>

nanomad commented 8 hours ago

@ZionFox just to add: