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

A service that queries the data from an MG iSMART account and publishes the data over MQTT and to other sources
MIT License
71 stars 21 forks source link

MQTT failure, throwing TRYING TO WRITE TO CLOSED SOCKET for every discovery subtopic #212

Closed ZionFox closed 6 months ago

ZionFox commented 6 months ago

I found the fix to this, it's at the bottom of this report.

I've attempted to set up as instructed in the guide, but am hitting a wall with the warning TRYING TO WRITE TO CLOSED SOCKET being thrown for every topic update, except for the saic/_internal one.

Environment:

Debian 12 bookworm running Docker 25 Home assistant 2024.4.3 running in Docker Mosquitto 2.0.18 MQTT broker running in Docker

I've tried both the 5.15 release, and the 0.6.0rc25 pre release versions of the saic-mqtt-gateway, via the docker image offered. I've tried pulling the :latest image, and also building the image from the Dockerfile.

Logs:

2024-04-14 17:58:13,668 [  INFO  ] [CONNECTION MADE] - gmqtt.mqtt.protocol
2024-04-14 17:58:13,672 [ DEBUG  ] [CMD 0x20] b'\x00\x00' - gmqtt
2024-04-14 17:58:13,673 [ DEBUG  ] [CONNACK] flags: 0x0, result: 0x0 - gmqtt
2024-04-14 17:58:13,673 [  INFO  ] Connected to MQTT broker - publisher.mqtt_publisher
2024-04-14 17:58:13,673 [ DEBUG  ] NEW ID: 1 - gmqtt.mqtt.utils
2024-04-14 17:58:13,673 [  INFO  ] [SEND SUB] 1 [b'saic/ziontristan_mg@gmail.com/vehicles/+/+/+/set'] - gmqtt.mqtt.package
2024-04-14 17:58:13,673 [ DEBUG  ] NEW ID: 2 - gmqtt.mqtt.utils
2024-04-14 17:58:13,673 [  INFO  ] [SEND SUB] 2 [b'saic/ziontristan_mg@gmail.com/vehicles/+/+/+/+/set'] - gmqtt.mqtt.package
2024-04-14 17:58:13,674 [ DEBUG  ] NEW ID: 3 - gmqtt.mqtt.utils
2024-04-14 17:58:13,674 [  INFO  ] [SEND SUB] 3 [b'saic/ziontristan_mg@gmail.com/vehicles/+/refresh/mode/set'] - gmqtt.mqtt.package
2024-04-14 17:58:13,674 [ DEBUG  ] NEW ID: 4 - gmqtt.mqtt.utils
2024-04-14 17:58:13,674 [  INFO  ] [SEND SUB] 4 [b'saic/ziontristan_mg@gmail.com/vehicles/+/refresh/period/+/set'] - gmqtt.mqtt.package
2024-04-14 17:58:13,674 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/lwt'', ... (6 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:13,679 [  INFO  ] Scheduler started - apscheduler.scheduler
2024-04-14 17:58:13,679 [  INFO  ] Logging in to SAIC API - __main__
2024-04-14 17:58:13,681 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/oauth/token/request'', ... (583 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:13,690 [ DEBUG  ] Looking for jobs to run - apscheduler.scheduler
2024-04-14 17:58:13,691 [ DEBUG  ] No jobs; waiting until a job is added - apscheduler.scheduler
2024-04-14 17:58:13,698 [ DEBUG  ] [CMD 0x90] b'\x00\x01\x00' - gmqtt
2024-04-14 17:58:13,699 [  INFO  ] [SUBACK] 1 (0,) - gmqtt
2024-04-14 17:58:13,699 [ DEBUG  ] FREE MID: 1 - gmqtt.mqtt.utils
2024-04-14 17:58:13,699 [ DEBUG  ] [CMD 0x90] b'\x00\x02\x00' - gmqtt
2024-04-14 17:58:13,699 [  INFO  ] [SUBACK] 2 (0,) - gmqtt
2024-04-14 17:58:13,699 [ DEBUG  ] FREE MID: 2 - gmqtt.mqtt.utils
2024-04-14 17:58:13,699 [ DEBUG  ] [CMD 0x90] b'\x00\x03\x00' - gmqtt
2024-04-14 17:58:13,699 [  INFO  ] [SUBACK] 3 (0,) - gmqtt
2024-04-14 17:58:13,699 [ DEBUG  ] FREE MID: 3 - gmqtt.mqtt.utils
2024-04-14 17:58:13,699 [ DEBUG  ] [CMD 0x90] b'\x00\x04\x00' - gmqtt
2024-04-14 17:58:13,699 [  INFO  ] [SUBACK] 4 (0,) - gmqtt
2024-04-14 17:58:13,700 [ DEBUG  ] FREE MID: 4 - gmqtt.mqtt.utils
2024-04-14 17:58:15,488 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/oauth/token/response'', ... (2618 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,490 [  INFO  ] Logged in as ziontristan+mg@gmail.com - __main__
2024-04-14 17:58:15,490 [  INFO  ] Fetching vehicle list - __main__
2024-04-14 17:58:15,491 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/vehicle/list/request'', ... (118 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,644 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/vehicle/list/response'', ... (4453 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,649 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/vehicle/alarmSwitch/request'', ... (589 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,732 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/_internal/api/vehicle/alarmSwitch/response'', ... (492 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,733 [  INFO  ] Registering for ['ALARM_TYPE_VEHICLE_FAULT', 'ALARM_TYPE_GEOFENCE', 'ALARM_TYPE_VEHICLE_START'] messages. vin=LSJW*********2049 - __main__
2024-04-14 17:58:15,734 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/_internal/configuration/raw'', ... (1681 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,734 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/brand'', ... (2 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,734 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/model'', ... (5 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,735 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/year'', ... (4 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,735 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,735 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/series'', ... (7 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,736 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,736 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/color'', ... (11 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,736 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,736 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/J17'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,736 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,736 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Tire'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,737 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,737 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Q00'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,737 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,737 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Airbag'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,737 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,737 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Q01'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,738 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,738 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/FAirbag'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,738 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,738 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Q09'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,738 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,738 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/AirbagS'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,739 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,739 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/S35'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,739 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,739 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Sunroof'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,739 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,739 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/S61'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,740 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,740 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/Remote control'', ... (1 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,740 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,740 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/configuration/T11'', ... (1 bytes) - gmqtt.mqtt.package

This continues until it hits an exception, and dumps the following stacktrace:

2024-04-14 17:58:15,865 [  INFO  ] Added job "Check for new messages" to job store "default" - apscheduler.scheduler
2024-04-14 17:58:15,866 [ DEBUG  ] Starting process for car LSJW*********2049 - __main__
2024-04-14 17:58:15,867 [WARNING ] Executing <Task cancelling name='Task-2' coro=<MqttGateway.run() running at /usr/src/app/./mqtt_gateway.py:490> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.12/asyncio/base_events.py:449> cb=[_run_until_complete_cb() at /usr/local/lib/python3.12/asyncio/base_events.py:182] created at /usr/local/lib/python3.12/asyncio/runners.py:100> took 0.136 seconds - asyncio
2024-04-14 17:58:15,867 [WARNING ] [EXC: CONN LOST] - gmqtt.mqtt.protocol
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1075, in write
    n = self._sock.send(data)
        ^^^^^^^^^^^^^^^^^^^^^
ConnectionResetError: [Errno 104] Connection reset by peer
2024-04-14 17:58:15,868 [ DEBUG  ] [CMD 0xe0] b'' - gmqtt
2024-04-14 17:58:15,869 [ DEBUG  ] Looking for jobs to run - apscheduler.scheduler
2024-04-14 17:58:15,869 [ DEBUG  ] Next wakeup is due at 2024-04-14 17:59:15.865299+00:00 (in 59.995849 seconds) - apscheduler.scheduler
2024-04-14 17:58:15,870 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/_internal/configuration/raw'', ... (1681 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,870 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,870 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/brand'', ... (2 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,870 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,870 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/model'', ... (5 bytes) - gmqtt.mqtt.package
2024-04-14 17:58:15,870 [WARNING ] [TRYING WRITE TO CLOSED SOCKET] - gmqtt.mqtt.protocol
2024-04-14 17:58:15,870 [ DEBUG  ] Sending PUBLISH (q0), 'b'saic/ziontristan+mg@gmail.com/vehicles/LSJW*********2049/info/year'', ... (4 bytes) - gmqtt.mqtt.package

Then it continues.

Key notes:

I use a special character in my email address for the SAIC account. The + is appearing differently in the logs. At the start when publishing the SEND SUB messages, it's replaced with an underscore, yet for all subsequent messages, it displays correctly in the logs.

However, the saic/_internal topic is being published and regularly updated to MQTT, which can be verified by an explorer. It does seem to understand details about my car, it just doesn't seem to be making this auto-discoverable in Home Assistant, possibly due to the symbol in my email address?

Fix

I dove deeper into the code for this, and done some debugging.

It turns out that when doing the MQTT subscriptions, the input string is being cleaned up with the method remove_special_mqtt_characters() located in mqtt_publisher.py line 60, and the result of that cleaned up string is being placed in a variable that is then used when subscribing to topics. This seems to be an "initialise" of four topics, relating to the vehicles VIN.

However, when looking to publish this data in mqtt_gateway.py line 418 (of the 5.15 codebase, it's in a similar location in the 6.0 rc) the account_prefix variable is just taking the siac_user object key as is, and not doing any clean-up of it. I updated my own internal version of the 6.0 code base to a crude fix, and it now works, publishing the data to the broker.

mqtt_account_prefix = f'{self.configuration.saic_user}'.replace('+', '_').replace('#', '_').replace('*', '_') \
            .replace('>', '_').replace('$', '_')
            account_prefix = f'{mqtt_account_prefix}/{mqtt_topics.VEHICLES}/{vin_info.vin}'

This removed all of the TRYING TO WRITE TO CLOSED SOCKETS errors, an the data is now properly formed in the MQTT broker. I highly suggest performing this fix (and ensuring other character escaping is done in key places) before releasing 6.0.

tosate commented 6 months ago

Hi @ZionFox,

thank you for your analysis. Since email addresses can contain special characters like the plus sign (+) which has a special meaning in MQTT topics we had to introduce a method that removes those special characters.

Without this method the gateway crashes right on the start when it tries to subscribe to some topics.

Of course we have to do the same special character removal when we publish something. Unfortunately, this is still missing.

Sorry for that. This is hard to test without a SAIC user name that contains a special character.

ZionFox commented 6 months ago

I'm glad I can be the edge case for testing, then. I figured it was, fortunately the debug level of logging correctly showed the string being used for the requests, so I could identify the difference in character difference.

I understand MQTT requires string santiation, it just seems it was implemented when subscribing to topics, and overlooked when publishing. I'm looking forward to the patch, but if the PR has that patch I'll test it now.

ZionFox commented 6 months ago

Can confirm that PR https://github.com/SAIC-iSmart-API/saic-python-mqtt-gateway/pull/214 does indeed resolve this issue. String sanitation that was omitted was not playing nicely when publishing or fetching data to MQTT.