search

raetha / wyzesense2mqtt

Configurable WyzeSense to MQTT Gateway intended for use with Home Assistant or other platforms that use MQTT discovery mechanisms.
MIT License
80 stars 22 forks source link

Service randomly drops off and requires a restart to work again #17

Closed dale3h closed 3 years ago

dale3h commented 4 years ago

Describe the Bug

I installed wyzesense2mqtt about a week ago, and have been experiencing an issue with it dropping off after a while (many hours). It works great for a while, and then all of a sudden, it just stops, with no error output to the logs.

To Reproduce

Steps to reproduce the behavior:

  1. Start the systemd service.
  2. Wait many hours.
  3. Sensors stop responding.
  4. Check logs via journactl (see below) and notice that it's been a while since it (wyzesense2mqtt) stopped reporting to the log.

Expected Behavior

The service to run continually until stopped.

Screenshots

N/A

Desktop

Smartphone

Additional Context

Server/Node Information

Related Logs

Jun 08 05:41:41 wyzesense2mqtt python3[1494]: sensor_mac: 77A5FBD4
Jun 08 05:41:41 wyzesense2mqtt python3[1494]: Non-state event data: [2020-06-08 11:41:32][77A5FBD4]RawEvent: type=raw_AB, data=b'020000000100000003000000034500'
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:41:46][778780B7]StateEvent: sensor_type=motion, state=inactive, battery=90, signal=90
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 0, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:41:46.710000', 'signal_strength': -90, 'battery': 90}
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:41:46][778780B7]StateEvent: sensor_type=motion, state=inactive, battery=90, signal=90
Jun 08 05:41:57 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 0, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:41:46.710000', 'signal_strength': -90, 'battery': 90}
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:41:51][778780B7]StateEvent: sensor_type=motion, state=active, battery=90, signal=89
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 1, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:41:51.888000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:41:51][778780B7]StateEvent: sensor_type=motion, state=active, battery=90, signal=89
Jun 08 05:42:02 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 1, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:41:51.888000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:42:12 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:42:12 wyzesense2mqtt python3[1494]: Non-state event data: [2020-06-08 11:42:01][778780B7]RawEvent: type=raw_AB, data=b'020904030400000002030806085900'
Jun 08 05:42:58 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:42:58 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:42:45][778780B7]StateEvent: sensor_type=motion, state=inactive, battery=90, signal=89
Jun 08 05:42:58 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 0, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:42:45.657000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:43:18][778780B7]StateEvent: sensor_type=motion, state=active, battery=90, signal=89
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 1, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:43:18.012000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:43:18][778780B7]StateEvent: sensor_type=motion, state=active, battery=90, signal=89
Jun 08 05:43:32 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 1, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:43:18.012000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:44:12 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:44:12 wyzesense2mqtt python3[1494]: State event data: [2020-06-08 11:43:56][778780B7]StateEvent: sensor_type=motion, state=inactive, battery=90, signal=89
Jun 08 05:44:12 wyzesense2mqtt python3[1494]: {'available': True, 'mac': '778780B7', 'state': 0, 'device_class': 'motion', 'device_class_timestamp': '2020-06-08T11:43:56.161000', 'signal_strength': -89, 'battery': 90}
Jun 08 05:44:12 wyzesense2mqtt python3[1494]: sensor_mac: 778780B7
Jun 08 05:44:12 wyzesense2mqtt python3[1494]: Non-state event data: [2020-06-08 11:43:56][778780B7]RawEvent: type=raw_AB, data=b'020100000400000002010000005900'

# Notice the ~30 minute gap here (and lack of errors) before I logged into the node and restarted the service with the command `sudo systemctl restart wyzesense2mqtt`

Jun 08 06:17:39 wyzesense2mqtt systemd[1]: Stopping wyzesense2mqtt...
Jun 08 06:17:39 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=killed, status=15/TERM
Jun 08 06:17:39 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Succeeded.
Jun 08 06:17:39 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jun 08 06:17:39 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jun 08 06:17:49 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jun 08 06:17:50 wyzesense2mqtt python3[2600]: Logging initialized...
Jun 08 06:17:50 wyzesense2mqtt python3[2600]: Reading configuration...
Jun 08 06:17:50 wyzesense2mqtt python3[2600]: Connecting to MQTT host mqtt.starbase.me
Jun 08 06:17:50 wyzesense2mqtt python3[2600]: Connecting to dongle /dev/hidraw0
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   MAC: 77865404,  VER: 0.0.0.30 V1.4 Dongle UD3U,  ENR: b'J\xfb\xc5\xa1\r\xcf\x86D$6\xd3\xae\x17`&\xd5'
Jun 08 06:17:51 wyzesense2mqtt python3[2600]: Reading sensors configuration...
Jun 08 06:17:51 wyzesense2mqtt python3[2600]: sensor_mac: 77800DFB
Jun 08 06:17:51 wyzesense2mqtt python3[2600]: Publishing discovery topics for 77800DFB
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   homeassistant/binary_sensor/wyzesense_77800DFB/state/config
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   {"name": "Garage Motion", "dev_cla": "motion", "pl_on": "1", "pl_off": "0", "json_attr_t": "wyzesense2mqtt/77800DFB", "val_tpl": "{{ value_json.state }}", "uniq_id": "wyzesense_77800DFB_state", "stat_t": "wyzesense2mqtt/77800DFB", "dev": {"identifiers": ["wyzesense_77800DFB", "77800DFB"], "manufacturer": "Wyze", "model": "Sense Motion Sensor", "name": "Garage Motion", "sw_version": ""}}
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   homeassistant/sensor/wyzesense_77800DFB/signal_strength/config
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   {"name": "Garage Motion Signal Strength", "dev_cla": "signal_strength", "unit_of_meas": "dBm", "val_tpl": "{{ value_json.signal_strength }}", "uniq_id": "wyzesense_77800DFB_signal_strength", "stat_t": "wyzesense2mqtt/77800DFB", "dev": {"identifiers": ["wyzesense_77800DFB", "77800DFB"], "manufacturer": "Wyze", "model": "Sense Motion Sensor", "name": "Garage Motion", "sw_version": ""}}
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   homeassistant/sensor/wyzesense_77800DFB/battery/config
Jun 08 06:17:51 wyzesense2mqtt python3[2600]:   {"name": "Garage Motion Battery", "dev_cla": "battery", "unit_of_meas": "%", "val_tpl": "{{ value_json.battery }}", "uniq_id": "wyzesense_77800DFB_battery", "stat_t": "wyzesense2mqtt/77800DFB", "dev": {"identifiers": ["wyzesense_77800DFB", "77800DFB"], "manufacturer": "Wyze", "model": "Sense Motion Sensor", "name": "Garage Motion", "sw_version": ""}}
raetha commented 4 years ago

@dale3h, I think it's finally time to fork the original WyzeSensePy library. I myself have seen this issue a couple times, as well as at least one other person that I'm aware of. It appears to be a signal that the library doesn't handle directly, but the code is set to crash rather than ignore. I've been hoping the original author would fix, as that would help all upstream projects, but so far no response there.

Hopefully I can get to this tonight. Thanks for letting me know. I'll update as soon as a fix is in place so you can let help test.

raetha commented 4 years ago

@dale3h I believe I've worked around the assertion error in a way that will avoid the worker thread crashing. I've chosen a slightly different option from Kevin Vincent, as his fix seemed to mask the problem rather than ignore the bad packets. Ultimately, I think as a sensors battery dies, it is sending an unknown packet to the bridge, and the library we all base off doesn't know how to handle it. I've had this happen, and every time I'm finding a sensor with a low battery, when I replace the battery, all seems well.

If you could, update to the devel branch, and let me know if it actually seems to resolve for you. I'd like to validate before I actually close this and push to master.

Thanks!

dale3h commented 4 years ago

I have updated to latest devel branch and will let you know how things go over the next week.

dale3h commented 4 years ago

@raetha I seem to still be experiencing issues with wyzesense2mqtt randomly dropping out without any error messages. Though it is certainly happening less, only 3 or 4 times in the past 2 weeks.

raetha commented 4 years ago

Glad to hear that it is better, but annoyed that it's not solved. I'm not sure if I've got enough debug code in place for this, but could you try setting the logging to capture all debug messages, and then see if you can capture the snippet right before things die? I'd like to at least narrow down to what function is having an issue if we can, and then maybe adding some more debugging there. I personally haven't noticed issues since I forked the library, but my docker containers also tend to get restarted frequently as I'm messing with various things, so it might just not be staying running long enough.

dale3h commented 4 years ago

I currently have the logger level set as default (DEBUG for console, I believe, which should be piped to systemd), and didn't see any error messages. Is it possible that the error line didn't get piped to systemd before the crash? I am going to go ahead and change the default for the file handler to DEBUG and increase backupCount to 21 just to be safe.

Thank you again for all of your hard work and dedication to this project. So far, even with the trouble of initially getting it setup and the few crashes I've experienced, this project has proven to be far more stable than the custom integration (which was crashing hourly it seemed). I wasn't entirely fond of having to restart Home Assistant every time it crashed, so this was what I stumbled upon as an alternative. And a very good alternative, might I add.

Anyhow, I will try my best to report back in the next time it crashes. Until then!

dale3h commented 4 years ago

It dropped out again today, and again with no errors to systemd nor log files. This happened on the current latest commit from devel branch.

Last 10 lines of /opt/wyzesense2mqtt/logs/wyzesense2mqtt.log:

2020-07-03 18:31:21 INFO     wyzesense2mqtt  State event data: [2020-07-03 18:30:51][77A5E27A]StateEvent: sensor_type=motion, state=inactive, battery=98, signal=101
2020-07-03 18:31:21 DEBUG    wyzesense2mqtt  {'available': True, 'mac': '77A5E27A', 'device_class': 'motion', 'timestamp': '2020-07-03T18:30:51.841000', 'signal_strength': -101, 'battery': 98, 'state': 0}
2020-07-03 18:31:58 DEBUG    wyzesense2mqtt  sensor_mac: 7784FDA3
2020-07-03 18:31:58 DEBUG    wyzesense2mqtt  Non-state event data: [2020-07-03 18:31:26][7784FDA3]RawEvent: type=raw_A1, data=b'0114550001012ddc46'
2020-07-03 18:32:17 DEBUG    wyzesense2mqtt  sensor_mac: 77A5ECA3
2020-07-03 18:32:17 INFO     wyzesense2mqtt  State event data: [2020-07-03 18:31:45][77A5ECA3]StateEvent: sensor_type=motion, state=active, battery=98, signal=104
2020-07-03 18:32:17 DEBUG    wyzesense2mqtt  {'available': True, 'mac': '77A5ECA3', 'device_class': 'motion', 'timestamp': '2020-07-03T18:31:45.201000', 'signal_strength': -104, 'battery': 98, 'state': 1}
2020-07-03 18:32:17 DEBUG    wyzesense2mqtt  sensor_mac: 77A5ECA3
2020-07-03 18:32:17 INFO     wyzesense2mqtt  State event data: [2020-07-03 18:31:45][77A5ECA3]StateEvent: sensor_type=motion, state=active, battery=98, signal=104
2020-07-03 18:32:17 DEBUG    wyzesense2mqtt  {'available': True, 'mac': '77A5ECA3', 'device_class': 'motion', 'timestamp': '2020-07-03T18:31:45.201000', 'signal_strength': -104, 'battery': 98, 'state': 1}

Last 10 lines from journalctl -fu wyzesense2mqtt:

Jul 03 18:31:21 wyzesense2mqtt python3[2632]: State event data: [2020-07-03 18:30:51][77A5E27A]StateEvent: sensor_type=motion, state=inactive, battery=98, signal=101
Jul 03 18:31:21 wyzesense2mqtt python3[2632]: {'available': True, 'mac': '77A5E27A', 'device_class': 'motion', 'timestamp': '2020-07-03T18:30:51.841000', 'signal_strength': -101, 'battery': 98, 'state': 0}
Jul 03 18:31:58 wyzesense2mqtt python3[2632]: sensor_mac: 7784FDA3
Jul 03 18:31:58 wyzesense2mqtt python3[2632]: Non-state event data: [2020-07-03 18:31:26][7784FDA3]RawEvent: type=raw_A1, data=b'0114550001012ddc46'
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: sensor_mac: 77A5ECA3
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: State event data: [2020-07-03 18:31:45][77A5ECA3]StateEvent: sensor_type=motion, state=active, battery=98, signal=104
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: {'available': True, 'mac': '77A5ECA3', 'device_class': 'motion', 'timestamp': '2020-07-03T18:31:45.201000', 'signal_strength': -104, 'battery': 98, 'state': 1}
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: sensor_mac: 77A5ECA3
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: State event data: [2020-07-03 18:31:45][77A5ECA3]StateEvent: sensor_type=motion, state=active, battery=98, signal=104
Jul 03 18:32:17 wyzesense2mqtt python3[2632]: {'available': True, 'mac': '77A5ECA3', 'device_class': 'motion', 'timestamp': '2020-07-03T18:31:45.201000', 'signal_strength': -104, 'battery': 98, 'state': 1}
dale3h commented 4 years ago

Trying to start the service again (without rebooting the pi also) fails. Here is a shortened version of the logs containing the error(s) that prevented it from starting back up:

Jul 03 23:18:55 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 03 23:19:05 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 03 23:19:05 wyzesense2mqtt python3[5048]: Logging initialized...
Jul 03 23:19:05 wyzesense2mqtt python3[5048]: Reading configuration...
Jul 03 23:19:05 wyzesense2mqtt python3[5048]: Connecting to MQTT host ************
Jul 03 23:19:05 wyzesense2mqtt python3[5048]: Connecting to dongle /dev/hidraw0
Jul 03 23:19:06 wyzesense2mqtt python3[5048]: sensor_mac: 778362A9
Jul 03 23:19:06 wyzesense2mqtt python3[5048]: State event data: [2020-07-03 23:05:43][778362A9]StateEvent: sensor_type=switch, state=close, battery=87, signal=75
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: Exception in thread Thread-1:
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: Traceback (most recent call last):
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     self.run()
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/usr/lib/python3.7/threading.py", line 865, in run
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     self._target(*self._args, **self._kwargs)
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 366, in _Worker
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     self._HandlePacket(pkt)
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 341, in _HandlePacket
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     handler(pkt)
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 270, in _OnSensorAlarm
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     self.__on_event(self, e)
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 364, in on_event
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     if (SENSORS[event.MAC].get('invert_state') == True):
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: NameError: name 'SENSORS' is not defined
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: No device found on path /dev/hidraw0
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: Reading sensors configuration...
...
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: Traceback (most recent call last):
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 413, in <module>
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     init_sensors()
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 136, in init_sensors
Jul 03 23:19:08 wyzesense2mqtt python3[5048]:     result = WYZESENSE_DONGLE.List()
Jul 03 23:19:08 wyzesense2mqtt python3[5048]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 03 23:19:08 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 03 23:19:08 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 03 23:19:18 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=10s expired, scheduling restart.
Jul 03 23:19:18 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 8.
Jul 03 23:19:18 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.

(Please note that /opt/wyzesense2mqtt is a symlink for /etc/wyzesense2mqtt/wyzesense2mqtt.)

Output to list all /dev/hidraw* devices only shows hidraw0:

pi@wyzesense2mqtt:/opt/wyzesense2mqtt $ ls -al /dev/hidraw*
crw------- 1 root root 245, 0 Jun 30 15:17 /dev/hidraw0
raetha commented 4 years ago

I think I've solved the logged issue about SENSOR being not defined. That one is a race condition on start up, and should get better with a few other changes, but I've quickly made the variable global which should at least skip any errors.

The dongle is a bigger deal though. You should never have to restart the pi unless something at the kernel level is going screwy. It's probably too late to do it now, but the next time you notice this, check the system logs for the time when things stop working, see if the kernel is giving a panic for the hidraw drivers or something else similar. Not sure there will be an easy fix here, but seeing more info might at least help. You did run that as root or using sudo right? That "no device found on path" message is the same one you get when trying to attach using a normal user account.

Another thing worth checking is the firmware version on your dongle. I know a lot of folks who 0.0.0.30, instead of 0.0.0.33. I'm not sure if Wyze fixed something that would have an impact here, but they might have. Unfortunately the only way I know to upgrade the bridge is with a Wyze Cam, and then you likely have to re-pair all of your sensors after moving it back.

dale3h commented 4 years ago

I am not sure if it's of any help now, but here is some more log output from service restarts failing: https://hastebin.com/cuxuhuvebu

I will test out the latest available code and see if I happen to stumble across the NameError: name 'SENSORS' is not defined again.

dale3h commented 4 years ago

Well, first time attempting to start after upgrading to 1.1 was the NameError: name 'SENSORS' is not defined error. Here is log output from right after upgrading a few minutes ago: https://hastebin.com/agupimarif

This log output might also be helpful for #22 also, considering the time gaps between connecting/reading and publishing/connected:

Jul 17 23:32:35 wyzesense2mqtt python3[3115]: Connecting to MQTT host XXXXXXXX
...(1s)...
Jul 17 23:32:36 wyzesense2mqtt python3[3115]: Reading sensors configuration...
...(52s)...
Jul 17 23:33:28 wyzesense2mqtt python3[3115]: Publishing discovery topics for 77800DFB
...(0s)...
Jul 17 23:33:28 wyzesense2mqtt python3[3115]: Connected to MQTT: return code 0
dale3h commented 4 years ago

@raetha I checked /var/log/syslog and nothing else seems to be happening around the same time:

Jul 19 02:43:33 wyzesense2mqtt python3[5382]: sensor_mac: 77A5E27A
Jul 19 02:43:33 wyzesense2mqtt python3[5382]: Non-state event data: [2020-07-19 02:43:01][77A5E27A]RawEvent: type=raw_AB, data=b'020205050503000200000200003600'
Jul 19 02:43:45 wyzesense2mqtt python3[5382]: sensor_mac: 77877877
Jul 19 02:43:45 wyzesense2mqtt python3[5382]: State event data: [2020-07-19 02:43:13][77877877]StateEvent: sensor_type=motion, state=inactive, battery=90, signal=70
Jul 19 02:43:45 wyzesense2mqtt python3[5382]: {'available': True, 'mac': '77877877', 'device_class': 'motion', 'last_seen': 1595144593.46, 'last_seen_iso': '2020-07-19T02:43:13.460000', 'signal_strength': -70, 'battery': 90, 'name': 'Kitchen Motion', 'state': 0}
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: sensor_mac: 77A5E27A
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: State event data: [2020-07-19 02:43:18][77A5E27A]StateEvent: sensor_type=motion, state=inactive, battery=93, signal=54
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: {'available': True, 'mac': '77A5E27A', 'device_class': 'motion', 'last_seen': 1595144598.146, 'last_seen_iso': '2020-07-19T02:43:18.146000', 'signal_strength': -54, 'battery': 93, 'name': 'Back Porch Motion', 'state': 0}
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: sensor_mac: 77A5E27A
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: State event data: [2020-07-19 02:43:18][77A5E27A]StateEvent: sensor_type=motion, state=inactive, battery=93, signal=54
Jul 19 02:43:50 wyzesense2mqtt python3[5382]: {'available': True, 'mac': '77A5E27A', 'device_class': 'motion', 'last_seen': 1595144598.146, 'last_seen_iso': '2020-07-19T02:43:18.146000', 'signal_strength': -54, 'battery': 93, 'name': 'Back Porch Motion', 'state': 0}
Jul 19 03:17:01 wyzesense2mqtt CRON[8669]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: bits received from HRNG source: 2220064
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: bits sent to kernel pool: 2162560
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: entropy added to kernel pool: 2162560
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2 successes: 111
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2 failures: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: HRNG source speed: (min=467.882; avg=932.375; max=1161.814)Kibits/s
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: FIPS tests speed: (min=2.294; avg=7.032; max=16.600)Mibits/s
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: Lowest ready-buffers level: 2
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: Entropy starvations: 0
Jul 19 03:41:39 wyzesense2mqtt rngd[343]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
raetha commented 4 years ago

So this one is frustrating me. You definitely shouldn't be getting the SENSORS undefined error now, which makes me think that when it fails to connect to the USB dongle something else is getting screwed up in the threads. We can certainly add more error handling around connecting to the USB dongle and try to fail gracefully.

Really though, I just don't get why it's having trouble connecting to the dongle when restarting. I'm going to reopen this, since we made things better, but haven't truly solved it.

Also added the help wanted. We're beyond my knowledge with troubleshooting hardware issues. Hoping maybe someone who knows more might see it and be able to give us some advice. Really hate the concept of a reboot being the fix, but that's getting to the OS and hardware level I think.

The only last quick thing I can think to check, which I might have asked before, is do you have a USB hub between the dongle and the Pi? If so, maybe try removing that and plugging the dongle in directly.

dale3h commented 4 years ago

I am not sure 100% convinced that it is failing to connect to the dongle, especially showing that it receives some sort of data before crashing.

My dongle is connected directly to the pi, and this pi is dedicated to running only wyzesense2mqtt and has no other purpose.

I still have not upgraded my bridge to firmware 0.0.0.33, so this might possibly be fixed in the later version and only present in 0.0.0.30. However, I still would like to address the issue before attempting to upgrade, that way if anyone else is running 0.0.0.30 and having the same issue, it will be fixed for them without requiring a firmware upgrade.

Random thought: are these sensors one-way devices, and if so, might it be possible to pair a single sensor to multiple bridges?

dale3h commented 4 years ago

@raetha I found something interesting this afternoon when I went to restart after an overnight failure. The error message on startup seems to go back and forth now:

Jul 24 12:28:21 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:28:21 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:28:31 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:28:32 wyzesense2mqtt python3[20880]: Logging initialized...
Jul 24 12:28:32 wyzesense2mqtt python3[20880]: Reading configuration...
Jul 24 12:28:32 wyzesense2mqtt python3[20880]: Connecting to MQTT host XXXXXXXX
Jul 24 12:28:32 wyzesense2mqtt python3[20880]: Connecting to dongle /dev/hidraw0
Jul 24 12:28:33 wyzesense2mqtt python3[20880]: sensor_mac: 77A5ECA3
Jul 24 12:28:33 wyzesense2mqtt python3[20880]: State event data: [2020-07-24 12:04:45][77A5ECA3]StateEvent: sensor_type=motion, state=inactive, battery=95, signal=77
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: Exception in thread Thread-1:
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: Traceback (most recent call last):
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     self.run()
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/usr/lib/python3.7/threading.py", line 865, in run
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     self._target(*self._args, **self._kwargs)
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 375, in _Worker
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     self._HandlePacket(pkt)
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 350, in _HandlePacket
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     handler(pkt)
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 279, in _OnSensorAlarm
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     self.__on_event(self, e)
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 397, in on_event
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     if (event.MAC not in SENSORS):
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: NameError: name 'SENSORS' is not defined
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: No device found on path /dev/hidraw0
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: Reading sensors configuration...
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: Traceback (most recent call last):
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     init_sensors()
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:28:35 wyzesense2mqtt python3[20880]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:28:35 wyzesense2mqtt python3[20880]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:28:35 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:28:35 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:28:38 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:28:38 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 2.
Jul 24 12:28:38 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:28:38 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:28:48 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Logging initialized...
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Reading configuration...
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Connecting to MQTT host XXXXXXXX
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Connecting to dongle /dev/hidraw0
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: sensor_mac: 77A5FCF6
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Non-state event data: [2020-07-24 12:05:04][77A5FCF6]RawEvent: type=raw_AB, data=b'020505050502010200000506004a00'
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: sensor_mac: 77A5FCF6
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Non-state event data: [2020-07-24 12:05:04][77A5FCF6]RawEvent: type=raw_AB, data=b'020505050502010200000506004a00'
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: sensor_mac: 77A5FCF6
Jul 24 12:28:49 wyzesense2mqtt python3[20887]: Non-state event data: [2020-07-24 12:05:04][77A5FCF6]RawEvent: type=raw_AB, data=b'020505050502010200000506004a00'
Jul 24 12:28:51 wyzesense2mqtt python3[20887]: No device found on path /dev/hidraw0
Jul 24 12:28:51 wyzesense2mqtt python3[20887]: Reading sensors configuration...
Jul 24 12:28:51 wyzesense2mqtt python3[20887]: Traceback (most recent call last):
Jul 24 12:28:51 wyzesense2mqtt python3[20887]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:28:51 wyzesense2mqtt python3[20887]:     init_sensors()
Jul 24 12:28:51 wyzesense2mqtt python3[20887]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:28:51 wyzesense2mqtt python3[20887]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:28:51 wyzesense2mqtt python3[20887]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:28:51 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:28:51 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:28:54 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:28:54 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 3.
Jul 24 12:28:54 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:28:54 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:29:04 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:29:05 wyzesense2mqtt python3[20893]: Logging initialized...
Jul 24 12:29:05 wyzesense2mqtt python3[20893]: Reading configuration...
Jul 24 12:29:05 wyzesense2mqtt python3[20893]: Connecting to MQTT host XXXXXXXX
Jul 24 12:29:05 wyzesense2mqtt python3[20893]: Connecting to dongle /dev/hidraw0
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: Exception in thread Thread-1:
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: Traceback (most recent call last):
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     self.run()
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/usr/lib/python3.7/threading.py", line 865, in run
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     self._target(*self._args, **self._kwargs)
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 358, in _Worker
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     s += self._ReadRawHID()
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 325, in _ReadRawHID
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     assert len(s) >= length + 1
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: AssertionError
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: No device found on path /dev/hidraw0
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: Reading sensors configuration...
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: Traceback (most recent call last):
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     init_sensors()
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:29:08 wyzesense2mqtt python3[20893]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:29:08 wyzesense2mqtt python3[20893]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:29:08 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:29:08 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:29:11 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:29:11 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 4.
Jul 24 12:29:11 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:29:11 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:29:21 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: Logging initialized...
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: Reading configuration...
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: Connecting to MQTT host XXXXXXXX
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: Connecting to dongle /dev/hidraw0
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: sensor_mac: 77A5ECA3
Jul 24 12:29:22 wyzesense2mqtt python3[20899]: State event data: [2020-07-24 12:05:37][77A5ECA3]StateEvent: sensor_type=motion, state=active, battery=95, signal=76
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: Exception in thread Thread-1:
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: Traceback (most recent call last):
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     self.run()
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/usr/lib/python3.7/threading.py", line 865, in run
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     self._target(*self._args, **self._kwargs)
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 375, in _Worker
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     self._HandlePacket(pkt)
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 350, in _HandlePacket
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     handler(pkt)
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 279, in _OnSensorAlarm
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     self.__on_event(self, e)
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 397, in on_event
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     if (event.MAC not in SENSORS):
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: NameError: name 'SENSORS' is not defined
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: No device found on path /dev/hidraw0
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: Reading sensors configuration...
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: Traceback (most recent call last):
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     init_sensors()
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:29:24 wyzesense2mqtt python3[20899]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:29:24 wyzesense2mqtt python3[20899]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:29:24 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:29:24 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:29:27 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:29:27 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 5.
Jul 24 12:29:27 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:29:27 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:29:37 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:29:38 wyzesense2mqtt python3[20905]: Logging initialized...
Jul 24 12:29:38 wyzesense2mqtt python3[20905]: Reading configuration...
Jul 24 12:29:38 wyzesense2mqtt python3[20905]: Connecting to MQTT host XXXXXXXX
Jul 24 12:29:38 wyzesense2mqtt python3[20905]: Connecting to dongle /dev/hidraw0
Jul 24 12:29:40 wyzesense2mqtt python3[20905]: No device found on path /dev/hidraw0
Jul 24 12:29:40 wyzesense2mqtt python3[20905]: Reading sensors configuration...
Jul 24 12:29:41 wyzesense2mqtt python3[20905]: Traceback (most recent call last):
Jul 24 12:29:41 wyzesense2mqtt python3[20905]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:29:41 wyzesense2mqtt python3[20905]:     init_sensors()
Jul 24 12:29:41 wyzesense2mqtt python3[20905]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:29:41 wyzesense2mqtt python3[20905]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:29:41 wyzesense2mqtt python3[20905]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:29:41 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:29:41 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:29:44 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:29:44 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 6.
Jul 24 12:29:44 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:29:44 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:29:54 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:29:54 wyzesense2mqtt python3[20912]: Logging initialized...
Jul 24 12:29:54 wyzesense2mqtt python3[20912]: Reading configuration...
Jul 24 12:29:54 wyzesense2mqtt python3[20912]: Connecting to MQTT host XXXXXXXX
Jul 24 12:29:54 wyzesense2mqtt python3[20912]: Connecting to dongle /dev/hidraw0
Jul 24 12:29:57 wyzesense2mqtt python3[20912]: No device found on path /dev/hidraw0
Jul 24 12:29:57 wyzesense2mqtt python3[20912]: Reading sensors configuration...
Jul 24 12:29:57 wyzesense2mqtt python3[20912]: Traceback (most recent call last):
Jul 24 12:29:57 wyzesense2mqtt python3[20912]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:29:57 wyzesense2mqtt python3[20912]:     init_sensors()
Jul 24 12:29:57 wyzesense2mqtt python3[20912]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:29:57 wyzesense2mqtt python3[20912]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:29:57 wyzesense2mqtt python3[20912]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:29:57 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:29:57 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:30:00 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:30:00 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 7.
Jul 24 12:30:00 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:30:00 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:30:10 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:30:11 wyzesense2mqtt python3[20918]: Logging initialized...
Jul 24 12:30:11 wyzesense2mqtt python3[20918]: Reading configuration...
Jul 24 12:30:11 wyzesense2mqtt python3[20918]: Connecting to MQTT host XXXXXXXX
Jul 24 12:30:11 wyzesense2mqtt python3[20918]: Connecting to dongle /dev/hidraw0
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: Exception in thread Thread-1:
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: Traceback (most recent call last):
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     self.run()
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/usr/lib/python3.7/threading.py", line 865, in run
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     self._target(*self._args, **self._kwargs)
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 358, in _Worker
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     s += self._ReadRawHID()
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/etc/wyzesense2mqtt/wyzesense2mqtt/wyzesense.py", line 325, in _ReadRawHID
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     assert len(s) >= length + 1
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: AssertionError
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: No device found on path /dev/hidraw0
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: Reading sensors configuration...
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: Traceback (most recent call last):
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 459, in <module>
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     init_sensors()
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:   File "/opt/wyzesense2mqtt/wyzesense2mqtt.py", line 154, in init_sensors
Jul 24 12:30:13 wyzesense2mqtt python3[20918]:     result = WYZESENSE_DONGLE.List()
Jul 24 12:30:13 wyzesense2mqtt python3[20918]: NameError: name 'WYZESENSE_DONGLE' is not defined
Jul 24 12:30:13 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Main process exited, code=exited, status=1/FAILURE
Jul 24 12:30:13 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Failed with result 'exit-code'.
Jul 24 12:30:16 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Service RestartSec=3s expired, scheduling restart.
Jul 24 12:30:16 wyzesense2mqtt systemd[1]: wyzesense2mqtt.service: Scheduled restart job, restart counter is at 8.
Jul 24 12:30:16 wyzesense2mqtt systemd[1]: Stopped wyzesense2mqtt.
Jul 24 12:30:16 wyzesense2mqtt systemd[1]: Starting wyzesense2mqtt...
Jul 24 12:30:26 wyzesense2mqtt systemd[1]: Started wyzesense2mqtt.
Jul 24 12:30:27 wyzesense2mqtt python3[20925]: Logging initialized...
Jul 24 12:30:27 wyzesense2mqtt python3[20925]: Reading configuration...
Jul 24 12:30:27 wyzesense2mqtt python3[20925]: Connecting to MQTT host XXXXXXXX
Jul 24 12:30:27 wyzesense2mqtt python3[20925]: Connecting to dongle /dev/hidraw0
Jul 24 12:30:28 wyzesense2mqtt python3[20925]:   MAC: 77865404,  VER: 0.0.0.30 V1.4 Dongle UD3U,  ENR: b'J\xfb\xc5\xa1\r\xcf\x86D$6\xd3\xae\x17`&\xd5'
Jul 24 12:30:28 wyzesense2mqtt python3[20925]: Reading sensors configuration...
Jul 24 12:30:28 wyzesense2mqtt python3[20925]: Linked sensors: ['77800DFB', '7784FF23', '7784FDA3', '7782784A', '777EFF2A', '7782792E', '777F01FB', '777EF86E', '778362A9', '77836170', '7782986A', '77835E02', '777EDD2F', '7782787F', '77835FAF', '77877877', '778780B7', '77825BF1', '7783716A', '77A5FCF6', '77A5FBD4', '77A5E27A', '77A5ECA3']

I have no clue what the second startup error means, but I am guessing it has something to do with reading data from the dongle.

raetha commented 4 years ago

Wow, that is a lot of good logging, but at the same time confusing as to what is really going on. What I keep catching on is the line that looks like: Jul 24 12:30:13 wyzesense2mqtt python3[20918]: No device found on path /dev/hidraw0

That should be triggering when it can't find the device file or can't access it. Theoretically the way things are written, if the USB connection fails, it will try to reconnect, but that implies when it tries to reconnect it is no longer finding the device. And I honestly haven't tested if it can survive having the bridge unplugged and plugged back in. Ideally that's how it would work, but I'm not sure how to have it retry/wait in that fashion.

It does look like the bridge is there initially, as you are seeing some events, like you mentioned. I just compared our code to Kevin Vincent's with HA-WyzeSense, and though it's written drastically differently, it basically should be doing the same thing.

I'm adding some changes to the way the retry works that should force it to keep retrying on an IOError, so if the USB bus is dumping the bridge briefly, this should keep things running and eventually reconnect, assuming it stabilizes. I've checked that in, so you can pull and test immediately. I'll be really curious to see what your logs look like after this. Theoretically the script won't die now, but if the bridge really is messed up, it might just keep trying to reconnect over and over without success.

Which leads me to my last though, and you random thought from two comments ago. It's possible you just have a bad bridge, it's helping us make things better, but it could be a hardware issue at the root that we won't be able to do much about. Your last thought was about pairing to two bridges. I'm not sure if that is possible, when you pair, we have to insert a pin to trigger pairing on the sensor, but that might just be a way for the sensor to identify itself to the bridge. It would be interesting to test if you could pair a sensor to a second bridge (if you had one) and still have it work with the original bridge if you switch back and forth. I don't have two bridges, so can't test, but it would be interesting to know for sure.

Anyway, let me know if the newest devel code keeps things up, and then what the logs look like after a day or two (or whatever time period it usually takes to flake out).

dale3h commented 4 years ago

I just left town for the weekend, but last night I went by my local Home Depot to try and find a Wyze Sense camera kit. Unfortunately, out of the 22 that their system showed in stock, we weren’t able to find evening a single one.

Once I return home early next week, I will checkout and test the latest code in the devel branch.

Have a wonderful weekend!

raetha commented 4 years ago

Found one more reference that might be the issue here: https://github.com/kevinvincent/ha-wyzesense/issues/114#issuecomment-662788476

They reported udev power saving issues on a Pi. There isn't any context about a fix, but might give another path to look at. Maybe the Pi is killing power to the bridge as a power saving measure, and that mucks everything up.

Anyway, enjoy your weekend away. I'm definitely jealous, been cooped up in my area a little too long at this point. But at least getting to go on some nice hikes and getting some kayaking in. That'll be my weekend. :)

robloh commented 4 years ago

Just set all of this up and had this exact issue within 24 hours. This was with the latest docker image. When I restart the container I also got the message no device found on that path (and the container kept restarting over and over).

RPi 3 B+ DietPi v6.25.3 Linux Wyze-Bridge-Node 5.4.51-v7+ #1327 SMP Thu Jul 23 10:58:46 BST 2020 armv7l GNU/Linux Docker version 19.03.12, build 48a6621

One thing that might be unique to my system is that I have the CPU frequency limited to 600 MHz and the CPU governor is set to powersave.

So far I've not seen anything in any log that pointed to the actual problem. After a restart I am trying the following things:

1) the infinite I/O retry patch from the devel branch with debug logging turned on

2) turn off the powersave governor if it still happens

I'll also compare the lsusb verbose output while it's working and when it stops in case anything shows up there.

I assume this is the Wyze bridge device? 1a86:e024 QinHeng Electronics

azehnwirth commented 4 years ago

@robloh

I assume this is the Wyze bridge device? 1a86:e024 QinHeng Electronics

Yes, that is the Wyze bridge.

dale3h commented 4 years ago

@raetha I ended up staying out of town much longer than anticipated, and upon my return I had to get quite a few things done. Anyhow, I just wanted to provide an update on my system stability at this point. I think I had to only restart the service a couple of times while away, but up to this point it has been running for 1 week and 4 days without any hiccups. However, I did notice that quite a few of my contact sensors have dropped off, most likely due to dead batteries. I am about to go through and see which ones need their battery replaced (and will also take a look at their most recently reported battery level).

I have a strange feeling that one of these dead sensors might be what kept causing my service to drop off.

● wyzesense2mqtt.service - wyzesense2mqtt
   Loaded: loaded (/etc/systemd/system/wyzesense2mqtt.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2020-07-28 17:18:37 CDT; 1 weeks 4 days ago
  Process: 514 ExecStartPre=/bin/sleep 10 (code=exited, status=0/SUCCESS)
 Main PID: 521 (python3)
    Tasks: 2 (limit: 2200)
   Memory: 17.2M
   CGroup: /system.slice/wyzesense2mqtt.service
           └─521 /usr/bin/python3 /opt/wyzesense2mqtt/wyzesense2mqtt.py

Not sure if it's worth mentioning, but I am currently running on my neos-smart-leak branch. As long as it's staying alive, I really don't want to make any changes to my production instance. I haven't been able to get my hands on another bridge yet, but hopefully sometime this week I can make that happen.

dale3h commented 4 years ago

I ended up having three sensors whose batteries depleted during the past month. Upon trying to install new batteries, each had different behavior:

  1. Replacing the battery immediately brought the sensor back online with a valid MAC.
  2. Replacing the battery showed the sensor to be 100% dead, no flashing LED upon installing the new battery or anything.
  3. Replacing the battery showed the sensor to be normal, but upon checking the state in HA and wyzesense2mqtt logs, it was not responding. Upon re-pairing the sensor, it got booted off for having an invalid MAC and I once again experienced the MQTT connection loop:
Aug 09 14:00:46 wyzesense2mqtt python3[521]: In on_message_scan:
Aug 09 14:01:00 wyzesense2mqtt python3[521]: Scan result: ('\x00\x00\x00\x00\x00\x00\x00\x00', 1, 16)
Aug 09 14:01:00 wyzesense2mqtt python3[521]: sensor_mac:
Aug 09 14:01:00 wyzesense2mqtt python3[521]: Unpairing bad MAC:
Aug 09 14:01:00 wyzesense2mqtt python3[521]: Clearing sensor topics
Aug 09 14:01:00 wyzesense2mqtt python3[521]: Invalid sensor found:
Aug 09 14:01:00 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:01 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:01 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:02 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:02 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:03 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:03 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:04 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:04 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:05 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:05 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:06 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:06 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:07 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:07 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:08 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:08 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:09 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:09 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:10 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:10 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:10 wyzesense2mqtt python3[521]: sensor_mac: 77A5FBD4
Aug 09 14:01:10 wyzesense2mqtt python3[521]: State event data: [2020-08-09 14:00:43][77A5FBD4]StateEvent: sensor_type=motion, state=active, battery=94, signal=77
Aug 09 14:01:10 wyzesense2mqtt python3[521]: {'available': True, 'mac': '77A5FBD4', 'device_class': 'motion', 'last_seen': 1596999643.522, 'last_seen_iso': '2020-08-09T14:00:43.522000', 'signal_strength': -77, 'battery': 94, 'name': 'Master Bedroom Motion', 'state': 1}
Aug 09 14:01:11 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:11 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:18 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:18 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:19 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:19 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:20 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:20 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:21 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:21 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:22 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:22 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:23 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:23 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:24 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:24 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:25 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:25 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:26 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:26 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:27 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:27 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:28 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:28 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:29 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:29 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:30 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:30 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1
Aug 09 14:01:31 wyzesense2mqtt python3[521]: Connected to MQTT: return code 0
Aug 09 14:01:31 wyzesense2mqtt python3[521]: Disconnected from MQTT: return code 1

But, the good news is that when I restarted the service it came online the first try! I have a feeling this is the sensor that was causing my bridge to fail randomly for some reason. I now have 5 or so dead/invalid sensors. Hopefully Wyze will be able to replace them for me.