MQTT dropped off 3 days ago - but CLI prints motion events. #46
Comments
|
Can you post the logs from the logging directory? I don't think this is related to to #43 because that issue he wasn't seeing any events at all, even with the CLI tool. If you restart the service does it begin to work again? If not, please change file logging level to debug and restart + trigger the devices. With a logging level of debug it will print is message payload to the file as it would publish it to the broker. |
|
Sure thing @AK5snowman ! I have tried reloading, then restarting with the below commands. Logs:
While doing the stop/start/status dance, I "manually" subscribed/listened to topic |
|
Are you sure you are in debug mode for file logging? There are two sections in the logging.yaml file that you can set the debug level. I ask because I don’t see any debug messages and if you are truly in debug then it’s failing silently in about 9 line of code. Can you post your sensor.yaml contents as well as your config.yaml contents (remove your credentials if you care) |
|
I was not in DEBUG - thank you. I did not realize there were two log level settings; switched it to DEBUG now, logs at the bottom. To clarify, I am looking at log files at cd /etc/wyzesense2mqtt/wyzesense2mqtt/logs - which I believe is correct. Here is my config: Here is my logging.yaml: Here are the DEBUG logs: |
|
Hmm okay. Yeah the two 'handlers', one for when you are watching logs via the console and one for the messages you want to write to disk.
So this is the MQTT message that it is attempting to publish. Either the message doesn't get delivered or it fails to send. To test out the first one lets change your mqtt_qos to either 1 or 2, so that it is guaranteed to get to the broker. e: Lets modify a second of your code to enable some better logs for MQTT. Open up /etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense2mqtt.py in your favorite editor and make the following changes. Then restart the service, trigger your sensors, and post the logs |
|
EDIT:: I noticed in the logs in the Mosquito add on, that it was (or at least looks like it was) assigning an "auto" MQTT client id - like this: I thought this was odd, bc this is supposed to be set in the config.yaml - and mine was defined as Rather than quit now, I'd like to understand what in the heck just happened... ======== Original ======== OK, mqtt_qos is now set to 2, and I made the edits to wyzesense2mqtt.py. Below are the logs after restart - the same logs here if they are easier for you to read outside of GH. Device being trigger by me for testing is MAC 779B23A7. I don't really understand everything in the log - but it looks like its trying to send it over and over. But is also looks like its being received, based on the lines that say |
|
Wait a second, you updated the client ID and restarted wyzesense2mqtt and it all started working for you? As in problem fixed? If so, do you have any other clients writing to this same broker with the same client ID? Seems like HA shouldn't care (and doesn't know?) what the client ID of the publishing client is. |
|
@AK5nowman yes - I am confused as you are. When I was in the So I switched the name to wyzesenseCLIENT and restarted the service - and all five devices that were paired previously was auto-discovered by Mosquito, and are currently working. "wyzesenseCLIENT" showed up one time in the Mosquito log however... What confuses me the most: The "new" clientID I set in the config.yaml (wyzesenseCLIENT) never shows up in this log except right after I first restarted and everything came online last night. Here is the Mosquito log, with all the auto client IDs. My rudimentary understanding of MQTT is that client ID is not required, and if its missing, one is auto generated every time a client connects: |
|
I took the docker route and I ran into the same issue couple of days ago. I repairing the devices did not fix the issue. So I decided to delete the docker images and start over. Downloading fresh images fixed the issue. I did not change anything in the configuration file. It continues to work without any issues. |
|
@PeterSelvaraj did you try changing the mqtt client ID and restarting before reinstalling? |
|
@AK5nowman No I didn't. |
|
A quick note I can add here is that I've occasionally had similar issues. Each time, I restart Mosquitto and things seem to solve themselves. I haven't taken the time to figure out if there is some sort of glitch in Mosquitto, Paho MQTT , or the way I'm using the Paho library to connect to MQTT. I believe I'm following "best practices" from Paho, but this stuff was brand new to me when I wrote it. So if anyone out there sees anything that looks off, let me know, or submit a PR. But you can probably correct this particular issue just by restarting Mosquitto. |
|
Chiming in to say this happens to me quite often as well. I have two instances of wyze2mqtt running, both with different client_ids, both running in docker. The next time it happens, I'll try changing client_id to see if it helps. |
|
As far as best practices for Paho MQTT goes, there are a few things to be aware of.
Before connecting use After connecting publish 'connected' to that same topic. MQTT will handle the rest.
If these changes are agreeable to you, it's probably easier for you to write and test them since I don't have a spare WyzeSense dongle to test with. However, if needed, I can disable part of my home temporarily in order to code, test, and issue a PR for this. |
|
I have a suspicion that it is Paho not respecting the client ID specified when it tries to reconnect. Haven't had the chance to troubleshoot this issue though as it hasn't happened after I added a bunch of logging |
I just wrote a short test script that uses the Paho "reconnect" method. It respected the client_id. You can see the code and the logs in this gist. |
|
@dlashua Appreciate the suggestions for improvement. Responses below by same number you used.
|
Merged
|
@raetha excellent! I didn't realize the other methods automatically reconnected, so, TIL. I'll pull your new code now and see if it keep me from having to manually restart every few days. thanks! |
|
I had the same issues as OP. Changing the mqtt_client_id kicked it in the pants and got the messages to update in HA. The wyzesense2mqtt logs were showing the motion/contact the entire time. |
|
@raetha I made it 10 days, which is a vast improvement from before. But, finally, today, both instances of wyze2mqtt that I run were no longer connected to MQTT, yet still running (and indicating in the logs with each attempted publish that it was not connected). Looking deeper in the past, I see other disconnections, retries, and eventual reconnections. But, this last time, it didn't manage to reconnect on it's own. A simple restart (I run wyzesense2mqtt in docker, so I just restarted the container) and everything is back up and running. Perhaps a config option to not reconnect, but, instead, just exit? At least, this way, docker/supervisord could restart and, perhaps, it'll manage to recover on its own that way? I wish I could figure out WHY it eventually fails. There's nothing in the code that looks incorrect or out of place. So, I'm thinking it must be something in Paho. |
|
@dlashua do your broker logs show anything funky going on during this period of time? Snippets of logs around the key points in time can be helpful as well. Curious, what is between your broker and wyzesense2mqtt? Are they on the same hardware device or separate? Mine are in separate VMs running on the same host and I have been running for months without this sort of issue now |
|
I have two instances of wyzesense2mqtt running. One runs in docker on a host called "iceman". In that same docker I run mosquitto, zigbee2mqtt, and homeassistant, which all use MQTT. The is connected by wired LAN. The second instance of wyzesense2mqtt also runs in docker on a RaspberryPi 4 (called "goose") along with another instance of zigbee2mqtt and rtl_433tomqtt (all of which use the same MQTT server on the previously mentioned docker host). I have yet another docker host connected by wired LAN which runs a service called "viserson" that also connected to MQTT. I have 8 or so other wireless ESP devices that connect to MQTT. And my workstation which is connected by wired LAN run MQTT-Explorer fairly regularly. Looking in the Mosquitto logs at one of these time periods, both wyzesense2mqtt clients disconnected, as did MQTT-Explorer. Everything else stayed connected. The logs provide this timeline: 00:32:44 I see a PUBLISH from wyzesense2mqtt on iceman . This is preceded by MANY publishes at regular intervals so I have to assume it was working fine before this point. However, 00:32:44 is the LAST publish I see for a while. 00:45:56 I see a PUBLISH from wyzesense2mqtt on goose. Same as above, it's the LAST publish I see for a while. 01:21:59 wyze on goose logs that it connected to MQTT. I believe I restarted it at this time because I also see "Connecting to dongle." in the logs. 02:04:38 wyze on iceman connects to MQTT. Same as above, I believe this is when I restarted it. 02:05:29 mosquitto logs show wyze on both goose and iceman connecting. The timestamps I'm using come from docker. I think, perhaps, Mosquitto buffers its logs so, at this time point, it's outputting the logs from both of the previous connections. Some observations. Since neither wyze instance shows "MQTT publish error: The client is not currently connected" until AFTER it reconnects to the dongle and all in the same second that it successfully connects to MQTT (likely after a manual restart), it's possible the host is losing connection with the wyze dongle. However, because it's happening on two different hosts, one wireless and one wired, one with an Intel processor and one a Raspberry Pi, it seems unlikely that it's host related. So, it's either IP network related or both of these dongles are receiving some RF that causes them to stop doing what they are supposed to do. The wyzesense2mqtt code looks like it would continue to publish even when not connected to MQTT (and log that each time), so if the MQTT server just went away (due to network issues or whatever) I should still see some publish attempts. The largest gap I have in logs of "publish" during normal operation is about 45 minutes. It seems wyzesense2mqtt doesn't ever log a "disconnected from MQTT". So, perhaps my issue is not MQTT related at all and, instead, has to do with the dongles. That's progress! So thanks for having me dig through the logs. I'll keep sifting through them to see if I can find anything else that's interesting. |
|
For further diagnosis here are my complete logs from one host just before the outage until just after (though, possibly this needs a new thread as I'm not sure it's related to MQTT any more): |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Describe the Bug
A clear and concise description of what the bug is.
Almost identical to #43 except A) I'm running it via Systemd and B) I've had this up and running for weeks with no issues - and it just stopped sending new MQTT messages.
Steps To Reproduce
Steps to reproduce the behavior:
Start the service, and check it's status - all running normally with no errors.
Launch the CLI tool, L to list the sensors to verify all 5 are still paired - they are.
Manually trip sensors - JSON appears under the CLI tool.
Checked the log, looks exactly like the CLI output
--- At this point, I'm pretty sure it IS sending a MQTT message----
So I head over to HA to see if I can subscribe/listen via topic
wyzesense2mqtt/<MAC of sensor>When I hit listen in HA, it prints the last msg it received (from ~ 3 days ago)
I trip the sensor, and no new msgs appear.
Double check topic subscription in device more info menu. Topic is correct
wyzesense2mqtt/<MAC of sensor>I checked the Mosquitto broker log - and the client is connecting and disconnecting normally.
Ran out of troubleshooting ideas and came here looking for assistance. :)
Expected Behavior
Back to working smoothly as it has for weeks
Screenshots
See above - can add more if needed.
Desktop
Please complete the following information:
Smartphone
N/A
Additional Context
Add any other context about the problem here.
The text was updated successfully, but these errors were encountered: