search

kevinvincent / ha-wyzesense

A Home Assistant Component to interface with the WYZE Sense hub and sensor system
368 stars 98 forks source link

Assertion Error After HomeKit Setup #174

Closed IIAIronWolf closed 3 months ago

IIAIronWolf commented 3 years ago

I got my HomeKit integration working today, thanks to the newest beta release of Home Assistant Core, 0.115.0b6. My sensors were working on this beta until I setup HomeKit. I am now getting the following errors in my logs and my contact sensors, which control my Custom Alarm, do not work:

2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] WYZESENSE v0.0.9
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] Attempting to open connection to hub at /dev/hidraw0
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] Start Inquiry...
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=4327, Payload=<None>
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa55430327016c'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa43042801016f'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa43042801016f'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=4328, Payload=b'01'
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] Inquiry returns 1
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=5314, Payload=b'ff'
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa55530414ff0269'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa531937a2373737393132393801000001747fd1bd7ba20103fa089455aa530e35000001747fda6ae80314ff05cb55aa531935000001747fda6aed0ea2'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa531937a2373737393132393801000001747fd1bd7ba20103fa0894'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5337, Payload=b'a2373737393132393801000001747fd1bd7ba20103fa'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5337)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555337ff0288'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa530e35000001747fda6ae80314ff05cb55aa531935000001747fda6aed0ea23737373931323938010003ff082a55aa530315016a55aa531d19000001747fda6af3a23737373931323938010d5d00010003ff4c08c1'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa530e35000001747fda6ae80314ff05cb'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5335, Payload=b'000001747fda6ae80314ff'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5335)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555335ff0286'
2020-09-11 20:07:52 INFO (Thread-5) [custom_components.wyzesense.wyzesense_custom] LOG: time=2020-09-11T20:07:34.760000, data=b'14ff'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa531935000001747fda6aed0ea23737373931323938010003ff082a55aa530315016a55aa531d19000001747fda6af3a23737373931323938010d5d00010003ff4c08c1'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa531935000001747fda6aed0ea23737373931323938010003ff082a'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5335, Payload=b'000001747fda6aed0ea23737373931323938010003ff'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5335)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555335ff0286'
2020-09-11 20:07:52 INFO (Thread-5) [custom_components.wyzesense.wyzesense_custom] LOG: time=2020-09-11T20:07:34.765000, data=b'a23737373931323938010003ff'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa530315016a55aa531d19000001747fda6af3a23737373931323938010d5d00010003ff4c08c1'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa530315016a'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5315, Payload=<None>
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5315)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555315ff0266'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa531d19000001747fda6af3a23737373931323938010d5d00010003ff4c08c1'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa531d19000001747fda6af3a23737373931323938010d5d00010003ff4c08c1'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5319, Payload=b'000001747fda6af3a23737373931323938010d5d00010003ff4c'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5319)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555319ff026a'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.binary_sensor] {'available': True, 'mac': '77791298', 'state': 0, 'device_class': 'door', 'timestamp': '2020-09-11T20:07:34.771000', 'rssi': -76, 'battery_level': 93}
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.binary_sensor] {'available': True, 'mac': '77791298', 'state': 0, 'device_class': 'door', 'timestamp': '2020-09-11T20:07:34.771000', 'rssi': -76, 'battery_level': 93}
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] 3 Sensors Loaded from storage
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] Registering Sensor Entity: 
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] {'available': False, 'mac': '\x00\x00\x00\x00\x00\x00\x00\x00', 'state': 0}
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] Registering Sensor Entity: 77791298
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] Registering Sensor Entity: 777909AD
2020-09-11 20:07:52 DEBUG (SyncWorker_8) [custom_components.wyzesense.binary_sensor] {'available': False, 'mac': '777909AD', 'state': 0}
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa530332018755aa531935000001747fda6b4c0ea2373737393132393801010400068d'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa5303320187'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5332, Payload=<None>
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5332)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555332ff0283'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=5333, Payload=b'000001747fdab161'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa55530b33000001747fdab1610470'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa531935000001747fda6b4c0ea2373737393132393801010400068d'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa531935000001747fda6b4c0ea2373737393132393801010400068d'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5335, Payload=b'000001747fda6b4c0ea2373737393132393801010400'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5335)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555335ff0286'
2020-09-11 20:07:52 INFO (Thread-5) [custom_components.wyzesense.wyzesense_custom] LOG: time=2020-09-11T20:07:34.860000, data=b'a2373737393132393801010400'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Trying to parse: b'55aa531d19000001747fda6c9fa2373737393132393801105d000101040045076e'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Received: b'55aa531d19000001747fda6c9fa2373737393132393801105d000101040045076e'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] <=== Received: Packet: Cmd=5319, Payload=b'000001747fda6c9fa2373737393132393801105d000101040045'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] ===> Sending: Packet: Cmd=53FF, Payload=ACK(5319)
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.wyzesense_custom] Sending: b'aa555319ff026a'
2020-09-11 20:07:52 DEBUG (Thread-5) [custom_components.wyzesense.binary_sensor] {'available': True, 'mac': '77791298', 'state': 1, 'device_class': 'door', 'timestamp': '2020-09-11T20:07:35.199000', 'rssi': -69, 'battery_level': 93}
2020-09-11 20:07:52 ERROR (Thread-5) [custom_components.wyzesense.wyzesense_custom] Ignoring non-OSError in worker thread. Please share the error logs with the developers.
Traceback (most recent call last):
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 373, in _Worker
    self._HandlePacket(pkt)
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 346, in _HandlePacket
    handler(pkt)
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 271, in _OnSensorAlarm
    self.__on_event(self, e)
  File "/config/custom_components/wyzesense/binary_sensor.py", line 110, in on_event
    entities[event.MAC].schedule_update_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 422, in schedule_update_ha_state
    assert self.hass is not None
AssertionError
IIAIronWolf commented 3 years ago

Configuration.yaml entry:

# Configure a default setup of Home Assistant (frontend, api, etc)
default_config:

# Uncomment this if you are using SSL/TLS, running in Docker container, etc.
http:
  ssl_certificate: /ssl/fullchain.pem
  ssl_key: /ssl/privkey.pem

# Text to speech
tts:
  - platform: google_translate

group: !include groups.yaml
automation: !include automations.yaml
script: !include scripts.yaml
scene: !include scenes.yaml

binary_sensor:
  - platform: wyzesense
    device: auto

alarm_control_panel:
  - platform: manual
    code_arm_required: false
    code: !secret alarm_code
    arming_time: 0
    armed_home:
      arming_time: 0
      trigger_time: 120
    armed_away:
      delay_time: 30 #Seconds to put in PIN when returning home
      trigger_time: 120
      arming_time: 60 

homekit:
- filter:
    include_domains:
      - alarm_control_panel
  entity_config:
    alarm_control_panel.ha_alarm:
      code: !secret alarm_code

logger:
  default: warn
  logs:
    homeassistant.components.homekit: debug
    pyhap: debug
    custom_components.wyzesense: debug
    wyzesense.gateway: debug
    custom_components.wyzeapi: debug
IIAIronWolf commented 3 years ago

More logs:

Logger: homeassistant
Source: custom_components/wyzesense/wyzesense_custom.py:388
First occurred: 9:50:12 PM (1 occurrences)
Last logged: 9:50:12 PM

Error doing job: Future exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/wyzesense/binary_sensor.py", line 116, in setup_platform
    ws = beginConn()
  File "<decorator-gen-2>", line 2, in beginConn
  File "/usr/local/lib/python3.8/site-packages/retry/api.py", line 73, in retry_decorator
    return __retry_internal(partial(f, *args, **kwargs), exceptions, tries, delay, max_delay, backoff, jitter,
  File "/usr/local/lib/python3.8/site-packages/retry/api.py", line 33, in __retry_internal
    return f()
  File "/config/custom_components/wyzesense/binary_sensor.py", line 114, in beginConn
    return Open(config[CONF_DEVICE], on_event)
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 565, in Open
    return Dongle(device, event_handler)
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 299, in __init__
    self._Start()
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 505, in _Start
    self._FinishAuth()
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 489, in _FinishAuth
    resp = self._DoSimpleCommand(Packet.FinishAuth())
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 397, in _DoSimpleCommand
    self._DoCommand(pkt, cmd_handler, timeout)
  File "/config/custom_components/wyzesense/wyzesense_custom.py", line 388, in _DoCommand
    raise TimeoutError("_DoCommand")
TimeoutError: _DoCommand
photinus commented 3 years ago

Just for transparency, I deleted the comment, I understand his frustration, but the the few comments made on this repository have not been anything but inflamatory/unhelpful.

IIAIronWolf commented 3 years ago

I imagine there will be need to be some code change, and I assume the reason this happened was because this wyzesense integration and HomeKit Bridge do not play well together; However, I fixed the issue by completely removing the wyzesense integration after settings HomeKit to not autostart. I then re-added the wyzesense integration and then went to HomeKit and told it to exclude the Wyze sensors. Then I set HomeKit back to auto start and everything appears to be working again.

I also noticed an issue with the documentation for this, so I will submit a pull request.

photinus commented 3 years ago

What kind of HA setup are you running? Docker/VM/Supervised?

I ask because it's failing at the initialization of the sensor. It's long been on my mental list of improvements to adjust the logic around the initialization to check if it's already active if it fails to initialize, but I've had limited time to work on it. My thinking behind this is I've seen cases where when HA is restarted, we don't shutdown the connection to the dongle properly, this results in the LED staying blue but the component fails to initialize on restart until the system is rebooted or the dongle is unplugged/replugged.

IIAIronWolf commented 3 years ago

So that question has always confused me a bit, and I know the clarification is probably somewhere in the HA documentation; but, I am running Home Assistant on a Raspberry Pi using host_os HassOS 4.13 and installation_type Home Assistant OS. Home Assistant version is 0.115.0b10, latest beta as of today.

I too noticed that the LED does stay blue and that very well could have been the only issue: I didn't unplug and replug. Might have saved a slight headache of reinstalling and only needed to do the above instead. But my solution thankfully did get it all back up.

What I wonder about now, though, is: Why did it fail right after I successfully got HomeKit running? Is there an issue with having the wyzesense integration be in charge of the door contacts, while also allowing HomeKit to push the wyzsense devices to the Home app?

photinus commented 3 years ago

I'm guessing in your case, HA is getting reloaded in the background and the Wyzesense component doesn't get properly unloaded. You shouldn't 'need' to unplug and re-plug the adapter. I'm not a python expert and haven't had a ton of luck reproducing issues like this, will keep trying to see if I can find a good solution.

IIAIronWolf commented 3 years ago

Well let me know if I can be of any assistance. I've done some programming for per-engineering courses, but I'm definitely still a novice. Haha

photinus commented 3 years ago

I'm thinking we can make some improvement around here: https://github.com/kevinvincent/ha-wyzesense/blob/1e193496f656fc871cd14cabb8d1c33a21fc1620/custom_components/wyzesense/wyzesense_custom.py#L492

If we can adjust the initialization (start function) to not instantly fail on a failed auth/init command and have it, for example, call the dongle get mac command to see if the dongle is alive would probably be a good secondary test before throwing an exception and failing the setup.

jamescadd commented 3 years ago

Is this in the normal startup code path as well? I've had issues with reboots of my system (ProxMox/HassIO VM) alternatively working and not working for many months. I've suspected some initialization logic may be to blame since it fixes itself randomly on reboots.

photinus commented 3 years ago

Is this in the normal startup code path as well? I've had issues with reboots of my system (ProxMox/HassIO VM) alternatively working and not working for many months. I've suspected some initialization logic may be to blame since it fixes itself randomly on reboots.

It is the normal startup path. I've noticed on my system (HassIO VM running in ESXi) that I'll have to unplug the dongle before vmware will even recognize it, been thinking about trying a wyze firmware update on it (through one of the cameras), but haven't wanted to break my setup. But that only happens after a power cycle of my vm host.

IIAIronWolf commented 3 years ago

It is the normal startup path. I've noticed on my system (HassIO VM running in ESXi) that I'll have to unplug the dongle before vmware will even recognize it, been thinking about trying a wyze firmware update on it (through one of the cameras), but haven't wanted to break my setup. But that only happens after a power cycle of my vm host.

Oh wow. I didn't even realize the hub was being updated itself from the Wyze cam's. I assumed the camera just received new control software to use with the hubs. I might try updating mine since I only have 2 door contacts at the moment. Fingers crossed I don't break it again. Haha

Now that I think about it, a recent Wyze update did mention fixing the battery level reporting, so it might be really cool to update the hub.