Homekit won't pair - Githubissues

iditude commented 6 years ago

Home Assistant release (hass --version): 0.65.0.dev0

Python release (python3 --version): Python 3.5.3

Component/platform: Homekit

Description of problem: Homekit won't pair. When initiating a pair process, iOS sees Home assistant. Logs show pairing on HASS side but IOS hangs there until it errors out (message "Impossible to add Home Assistant, Home wasn't able to connect to this accessory").

Logs report this:

2018-03-03 13:30:57 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Import type files.
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Start adding accessories.
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Add "sensor.weather_dewpoint_temperature" as "TemperatureSensor"
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Add "sensor.weather_temperature" as "TemperatureSensor"
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Add "sensor.temperature_cuisine" as "TemperatureSensor"
2018-03-03 13:31:15 DEBUG (Thread-16) [homeassistant.components.homekit] Add "sensor.owm_temperature" as "TemperatureSensor"
2018-03-03 13:31:16 INFO (Thread-16) [pyhap.accessory_driver] Storing Accessory state in `/home/pi/.homeassistant/.homekit.state`
2018-03-03 13:31:16 DEBUG (Thread-16) [homeassistant.components.homekit] Driver started
2018-03-03 13:31:16 INFO (Thread-16) [pyhap.accessory_driver] Starting accessory 'Home Assistant' on address '192.168.253.5', port '51826'.
2018-03-03 13:31:16 DEBUG (Thread-37) [homeassistant.components.homekit.sensors] sensor.weather_dewpoint_temperature: Current temperature set to 3°C
2018-03-03 13:31:16 DEBUG (Thread-39) [homeassistant.components.homekit.sensors] sensor.weather_temperature: Current temperature set to 5°C
2018-03-03 13:31:16 DEBUG (Thread-41) [homeassistant.components.homekit.sensors] sensor.temperature_cuisine: Current temperature set to 21°C
2018-03-03 13:31:16 DEBUG (Thread-42) [homeassistant.components.homekit.sensors] sensor.owm_temperature: Current temperature set to 6°C
2018-03-03 13:31:55 DEBUG (Thread-21) [homeassistant.components.homekit.sensors] sensor.temperature_cuisine: Current temperature set to 21°C
2018-03-03 13:32:00 INFO (Thread-43) [pyhap.accessory_driver] Paired with ae34e34e-aa37-4e8c-9e5e-f6e23b016293.

Expected: Successful Pairing in IOS

Problem-relevant configuration.yaml entries and steps to reproduce:

homekit:
  pincode: '123-45-678'

cdce8p commented 6 years ago

Hopefully the last version needed: zeroconf.py

Could you try the barebone config with those two files this time? Maybe also temporary disconnect the Philips Hue from the network, if possible?

ikalchev commented 6 years ago

@cdce8p It seems that the service is not unregistered at the time the new version is added. Perhaps we can instrument unregister_service to see if this is actually the case?

iditude commented 6 years ago

Hello,

As suggested, I went for barebone config and put Hass in debug. I also unplugged the Philips Hue (but pairing is still unsuccessful)

Here's the log:


2018-03-25 22:07:27 DEBUG (Thread-9) [pyhap.accessory_driver] pair: add_paired_client
2018-03-25 22:07:27 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service_data=notification_id=4663548, service_call_id=1976033168-2, domain=persistent_notification, service=dismiss>
2018-03-25 22:07:27 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=None, entity_id=persistent_notification.4663548, old_state=<state persistent_notification.4663548=notifying; message=To setup Home Assistant in the Home App, enter the following code:
### 755-79-330, title=HomeKit Setup @ 2018-03-25T22:06:56.822939+02:00>>
2018-03-25 22:07:27 DEBUG (Thread-9) [pyhap.accessory_driver] pair: persist
2018-03-25 22:07:27 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976033168-2>
2018-03-25 22:07:27 DEBUG (Thread-9) [pyhap.accessory_driver] pair: update_advertisment
2018-03-25 22:07:27 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment
2018-03-25 22:07:27 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: unregister_service
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] remove: error
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:27 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.5
2018-03-25 22:07:27 WARNING (zeroconf-Reaper) [zeroconf] remove: error
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: mdns_service_info
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: accessory <homeassistant.components.homekit.accessories.HomeBridge object at 0x724e50d0>
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: address 192.168.253.5
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: port 51827
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: sleep
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: entry 192.168.253.5
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[srv,in,Home Assistant._hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.:51827]
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: error
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.5
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: entry 192.168.253.5
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: entry record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04c#=2\x04f']...
2018-03-25 22:07:28 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: register_service
2018-03-25 22:07:28 DEBUG (Thread-9) [pyhap.accessory_driver] AccessoryMDNSServiceInfo(type='_hap._tcp.local.', name='Home Assistant._hap._tcp.local.', address=b'\xc0\xa8\xfd\x05', port=51827, weight=0, priority=0, server='raspberrypi.local.', properties={'c#': '2', 'ff': '0', 'id': '31:B1:C3:0B:A2:BA', 's#': '1', 'ci': '2', 'sf': '0', 'md': 'Home Assistant', 'sh': b'gOElSQ==', 'pv': '1.0'})
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] register_service
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] register_service: check_service
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: allow_name_change False
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: service_type_name
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: endswith
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: instance_name
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: while 0
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] name _hap._tcp.local., alias Home Assistant._hap._tcp.local.
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] entries_with_name
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] {'_hap._tcp.local.': [record[ptr,in,_hap._tcp.local.,4500/4468.693118652343,Philips hue - 6952CA-4._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.692903808594,Philips hue - 6952CA._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.692719482422,Philips hue - 6952CA-6._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.692540039063,Philips hue - 6952CA-7._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.692361083984,Philips hue - 6952CA-8._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.692178710938,Philips hue - 6952CA-5._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4468.691991455078,Philips hue - 6952CA-3._hap._tcp.local.]], 'apple-tv-9.local.': [b'\xfe\x80\x00\x00\x00\x00\x00\x00\x18\xafL\x15\x82\xc5\xfc\xd7', 192.168.253.114], 'c869cd74897e@apple tv (10)._raop._tcp.local.': [record[srv,in-unique,C869CD74897E@Apple TV (10)._raop._tcp.local.,120/98.2293857421875,Apple-TV-9.local.:7000]], 'raspberrypi.local.': [], 'home assistant._hap._tcp.local.': [record[srv,in,Home Assistant._hap._tcp.local.,3600/3569.570541503906,raspberrypi.local.:51827]]}
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.691262207031,Philips hue - 6952CA-4._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.689866699218,Philips hue - 6952CA._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.688486328125,Philips hue - 6952CA-6._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.687149414062,Philips hue - 6952CA-7._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.685843261719,Philips hue - 6952CA-8._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.684514892578,Philips hue - 6952CA-5._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4468.683202148438,Philips hue - 6952CA-3._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: wait
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: DNSOutgoing
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: while 1
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] name _hap._tcp.local., alias Home Assistant._hap._tcp.local.
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] entries_with_name
2018-03-25 22:07:28 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_hap._tcp.local.,3600/3599.9973999023437,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] {'_hap._tcp.local.': [record[ptr,in,_hap._tcp.local.,3600/3599.994673095703,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.995345703125,Philips hue - 6952CA-4._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.995162109375,Philips hue - 6952CA._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.994981445312,Philips hue - 6952CA-6._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.994797851563,Philips hue - 6952CA-7._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.994616210937,Philips hue - 6952CA-8._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.994436767578,Philips hue - 6952CA-5._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.994108886719,Philips hue - 6952CA-3._hap._tcp.local.]], 'apple-tv-9.local.': [b'\xfe\x80\x00\x00\x00\x00\x00\x00\x18\xafL\x15\x82\xc5\xfc\xd7', 192.168.253.114], 'c869cd74897e@apple tv (10)._raop._tcp.local.': [record[srv,in-unique,C869CD74897E@Apple TV (10)._raop._tcp.local.,120/98.20629248046875,Apple-TV-9.local.:7000]], 'raspberrypi.local.': [], 'home assistant._hap._tcp.local.': [record[srv,in,Home Assistant._hap._tcp.local.,3600/3569.5474501953126,raspberrypi.local.:51827]]}
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,3600/3599.9926975097655,Home Assistant._hap._tcp.local.]
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] return record
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: name conflict
2018-03-25 22:07:28 WARNING (Thread-9) [zeroconf] check_service: NonUniqueNameException
2018-03-25 22:07:35 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_spotify-connect._tcp.local.,60/59.99753588867188,5f73207c09e2559f._spotify-connect._tcp.local.]
2018-03-25 22:07:35 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in,5f73207c09e2559f._spotify-connect._tcp.local.,60/59.99554956054688,5f73207c09e2559f.local.:53903]
2018-03-25 22:07:35 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in,5f73207c09e2559f._spotify-connect._tcp.local.,60/59.993533203125,b'\tCPath=']...
2018-03-25 22:07:35 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.160
2018-03-25 22:07:52 WARNING (zeroconf-Engine) [zeroconf] add: entry record[ptr,in,_googlecast._tcp.local.,120/119.997544921875,BouygtelTV-7db3ecbeea374800e0cc497dfe24430c-1._googlecast._tcp.local.]
2018-03-25 22:07:52 WARNING (zeroconf-Engine) [zeroconf] add: entry record[txt,in-unique,BouygtelTV-7db3ecbeea374800e0cc497dfe24430c-1._googlecast._tcp.local.,4500/4499.995478515625,b'#id=7db']...
2018-03-25 22:07:52 WARNING (zeroconf-Engine) [zeroconf] add: entry record[srv,in-unique,BouygtelTV-7db3ecbeea374800e0cc497dfe24430c-1._googlecast._tcp.local.,120/119.993140625,7db3ecbe-ea37-4800-e0cc-497dfe24430c.local.:8009]
2018-03-25 22:07:52 WARNING (zeroconf-Engine) [zeroconf] add: entry 192.168.253.160```

Cheers

cdce8p commented 6 years ago

As @ikalchev suggested, I added logging to unregister_service: zeroconf.py

@ikalchev If you want to follow along, here are the git diffs: https://github.com/ikalchev/HAP-python/compare/dev...cdce8p:debug-acc_driver?expand=1

iditude commented 6 years ago

Hello,

See debug here https://pastebin.com/hjasWZ2D

It's starting to be very verbose, so potenitially difficult to read through.

Hope this helps

cdce8p commented 6 years ago

It helped. The important line seems to be this one:

2018-03-25 22:45:34 WARNING (zeroconf-Reaper) [zeroconf] remove: error list.remove(x): x not in list

Zeroconf tries to delete a DNS cache entry, but fails. That prevents pyhap from registering the DNS entry again, since it wasn't removed in the first place, so everything hangs. I can somewhat reproduce your error by arbitrary raising my own exception where yours would be.

I've cleaned up the log statements. The new file would be here: zeroconf.py. Since the error seems to be repeating itself, the earlier HA is stopped after the pairing hangs, the shorter the log will be. @iditude Could you post a new error log with the new zeroconf? Afterwards please try accessory_driver.py. This hopefully solves the issue. I don't need a log for that.

@ikalchev I believe a solution might be to set allow_name_change=True when registering a new service. I haven't noticed any issues with it being set.

ikalchev commented 6 years ago

@cdce8p setting alow_name_change=True will not remove the previous record, so potentially the Home app would see two accessories. Rather, I would suggest calling unregister_all_services in pair instead. The thinking behind this is that in unregister_service we pass the ServiceInfo object, which for some reason, we see is not found in the list.

iditude commented 6 years ago

Hello,

So I couldn't use the new zerconf file as there is a syntax error.

Traceback (most recent call last):
  File "/home/pi/homeassistant/lib/python3.5/site-packages/homeassistant/setup.py", line 142, in _async_setup_component
    result = await component.async_setup(hass, processed_config)
  File "/home/pi/homeassistant/lib/python3.5/site-packages/homeassistant/components/homekit/__init__.py", line 55, in async_setup
    homekit.setup()
  File "/home/pi/homeassistant/lib/python3.5/site-packages/homeassistant/components/homekit/__init__.py", line 157, in setup
    from .accessories import HomeBridge, HomeDriver
  File "/home/pi/homeassistant/lib/python3.5/site-packages/homeassistant/components/homekit/accessories.py", line 5, in <module>
    from pyhap.accessory_driver import AccessoryDriver
  File "/home/pi/homeassistant/lib/python3.5/site-packages/pyhap/accessory_driver.py", line 35, in <module>
    from zeroconf import ServiceInfo, Zeroconf
  File "/home/pi/homeassistant/lib/python3.5/site-packages/zeroconf.py", line 7
    <!DOCTYPE html>
    ^
SyntaxError: invalid syntax

However the new accessory file solves the issue. Pairing works! Retried also with my config and all my accessories appear. Awesome!


2018-03-26 08:39:25 DEBUG (Thread-9) [pyhap.accessory_driver] pair: add_paired_client
2018-03-26 08:39:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=dismiss, service_data=notification_id=4663548, domain=persistent_notification, service_call_id=1975869264-2>
2018-03-26 08:39:25 DEBUG (Thread-9) [pyhap.accessory_driver] pair: persist
2018-03-26 08:39:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state persistent_notification.4663548=notifying; title=HomeKit Setup, message=To setup Home Assistant in the Home App, enter the following code:
### 727-93-993 @ 2018-03-26T08:39:04.490378+02:00>, new_state=None, entity_id=persistent_notification.4663548>
2018-03-26 08:39:25 DEBUG (Thread-9) [pyhap.accessory_driver] pair: update_advertisment
2018-03-26 08:39:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1975869264-2>
2018-03-26 08:39:25 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment
2018-03-26 08:39:25 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: unregister_service
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: mdns_service_info
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: accessory <homeassistant.components.homekit.accessories.HomeBridge object at 0x725a5030>
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: address 192.168.253.5
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: port 51827
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: sleep
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: register_service
2018-03-26 08:39:26 DEBUG (Thread-9) [pyhap.accessory_driver] AccessoryMDNSServiceInfo(type='_hap._tcp.local.', name='Home Assistant._hap._tcp.local.', address=b'\xc0\xa8\xfd\x05', port=51827, weight=0, priority=0, server='raspberrypi.local.', properties={'pv': '1.0', 'id': 'EE:D5:E1:90:72:97', 'sh': b'w4738Q==', 'c#': '2', 'md': 'Home Assistant', 'sf': '0', 'ci': '2', 'ff': '0', 's#': '1'})
2018-03-26 08:39:27 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: done
2018-03-26 08:39:27 DEBUG (Thread-9) [pyhap.accessory_driver] pair: done
2018-03-26 08:39:27 INFO (Thread-9) [pyhap.hap_server] 192.168.253.156 - "POST /pair-setup HTTP/1.1" 200 -
2018-03-26 08:39:27 INFO (http_server) [pyhap.hap_server] Got connection with ('192.168.253.156', 49573).
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Request POST from address '('192.168.253.156', 49573)' for path '/pair-verify'.
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Pair verify [1/2].
2018-03-26 08:39:27 INFO (Thread-10) [pyhap.hap_server] 192.168.253.156 - "POST /pair-verify HTTP/1.1" 200 -
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Request POST from address '('192.168.253.156', 49573)' for path '/pair-verify'.
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Pair verify [2/2]
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Pair verify with client '('192.168.253.156', 49573)' completed. Switching to encrypted transport.
2018-03-26 08:39:27 INFO (Thread-10) [pyhap.hap_server] 192.168.253.156 - "POST /pair-verify HTTP/1.1" 200 -
2018-03-26 08:39:27 DEBUG (Thread-10) [pyhap.hap_server] Request GET from address '('192.168.253.156', 49573)' for path '/accessories'.
2018-03-26 08:39:27 INFO (Thread-10) [pyhap.hap_server] 192.168.253.156 - "GET /accessories HTTP/1.1" 200 -
2018-03-26 08:39:33 DEBUG (Thread-10) [pyhap.hap_server] Request PUT from address '('192.168.253.156', 49573)' for path '/characteristics'.
2018-03-26 08:39:33 INFO (Thread-10) [pyhap.hap_server] 192.168.253.156 - "PUT /characteristics HTTP/1.1" 207 -```

I see you guys are debating on best path forward, so happy to test if you need me to.

Thanks!

cdce8p commented 6 years ago

Good to here that it works now. I unfortunately linked to the wrong file, here the new link: zeroconf.py

You need to replace accessory_driver.py against the version before (that didn't work). Otherwise the issue might no get logged.

ikalchev commented 6 years ago

Glad there is a workaround and things are working for you. Can we try with unregister_all_services as well, I would prefer to not allow name changes because of the old service being left behind.

cdce8p commented 6 years ago

I change accessory_driver.py to use unregister_all_services as @ikalchev suggested.

@iditude Can you try this as well, after the above and see if pairing works (no logs)?

cdce8p commented 6 years ago

@ikalchev The old service shouldn't be an issue, more that allow_name_change=True doesn't work if you restart pyhap / Home Assistant. As far as I could test it unregister_all_services in the file linked above should do the job. If it's confirmed that it solves the issue as well, I will submit a PR to HAP-python.

ikalchev commented 6 years ago

If unreg all works I am all in for adding it to HAP-python. Not that I won’t accept the other solution, I just won’t like it that much :D

cdce8p commented 6 years ago

The other isn't an option really. Lets hope unregister_all_services solves it as well.

iditude commented 6 years ago

Hello,

Unfortunately the new version didn't solve the issue.

Here are the logs (I also updated zeroconf.py to get logging back).

Thanks

2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] pair: add_paired_client
2018-03-26 20:46:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=persistent_notification, service_data=notification_id=4663548, service_call_id=1976090480-2, service=dismiss>
2018-03-26 20:46:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: old_state=<state persistent_notification.4663548=notifying; message=To setup Home Assistant in the Home App, enter the following code:
### 087-10-911, title=HomeKit Setup @ 2018-03-26T20:46:25.693339+02:00>, new_state=None, entity_id=persistent_notification.4663548>
2018-03-26 20:46:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976090480-2>
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] pair: persist
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] pair: update_advertisment
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: unregister_service
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,3600/3596.798427490234,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4491.026280761719,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4494.219267333984,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,3600/3591.0942209472655,b'\x11md=Hom']..., record[srv,in,Home Assistant._hap._tcp.local.,3600/3594.2247189941404,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 1
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,3600/3591.091529296875,b'\x11md=Hom']...]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4490.996889892578,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4494.189867431641,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4490.891911376953,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4494.084879882813,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4490.890502685547,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4494.083473388672,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: error list.remove(x): x not in list ... entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 1
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']...]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: error record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827] is not in list ... entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827], record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']...]>
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: mdns_service_info
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 1
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: accessory <homeassistant.components.homekit.accessories.HomeBridge object at 0x725e3bf0>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: address 192.168.253.5
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: port 51827
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4490.7555581054685,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4493.948529541016,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4490.753172851562,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4493.9461452636715,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: sleep
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: error list.remove(x): x not in list ... entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] remove: error list.remove(x): x not in list ... entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x11md=Hom']...]>
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-26 20:46:50 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: register_service
2018-03-26 20:46:50 DEBUG (Thread-9) [pyhap.accessory_driver] AccessoryMDNSServiceInfo(type='_hap._tcp.local.', name='Home Assistant._hap._tcp.local.', address=b'\xc0\xa8\xfd\x05', port=51827, weight=0, priority=0, server='raspberrypi.local.', properties={'md': 'Home Assistant', 'sf': '0', 's#': '1', 'id': 'EA:F3:DC:F8:4D:22', 'sh': b'h4p8qw==', 'ci': '2', 'ff': '0', 'pv': '1.0', 'c#': '2'})
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] register_service
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: allow_name_change False
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: while (0)
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] <name: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] <cache: [record[ptr,in,_hap._tcp.local.,4500/4490.643959716797,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4493.836935791016,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4490.6428374023435,Philips hue - 6952CA-1._hap._tcp.local.]
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,4500/4493.8348374023435,Philips hue - 6952CA._hap._tcp.local.]
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: while (0) wait
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: while (0) self.send(out)
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: while (1)
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-26 20:46:50 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] <name: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] <cache: [record[ptr,in,_hap._tcp.local.,3600/3599.9935083007813,Home Assistant._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.998380371094,Philips hue - 6952CA-1._hap._tcp.local.], record[ptr,in,_hap._tcp.local.,4500/4499.9932253417965,Philips hue - 6952CA._hap._tcp.local.]]>
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,3600/3599.992058105469,Home Assistant._hap._tcp.local.]
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] return record
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: name conflict
2018-03-26 20:46:50 WARNING (Thread-9) [zeroconf] check_service: NonUniqueNameException

cdce8p commented 6 years ago

@iditude @ikalchev I don't know if we can solve this issue. My last idea is that it might be caused by zeroconf.py having a racecondition. That would explain why some have the issue and others don't. It would be highly depended on the individual config. You might be lucky or you aren't.

I opened an issue in the python-zeroconf repo to address the problem: https://github.com/jstasiak/python-zeroconf/issues/125

ikalchev commented 6 years ago

If it was a race, it should have worked from time to time I think.

@iditude I see also a Philips hue on the network, can I ask you to remove it and retry? My idea is to try a case where no other thing is mDNSing in the network.

iditude commented 6 years ago

@ikalchev here's the log without the hue on the network. Problem remains though.

Thanks

2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] pair: add_paired_client
2018-03-27 22:11:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service_call_id=1976647536-2, domain=persistent_notification, service_data=notification_id=4663548, service=dismiss>
2018-03-27 22:11:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=persistent_notification.4663548, new_state=None, old_state=<state persistent_notification.4663548=notifying; message=To setup Home Assistant in the Home App, enter the following code:
### 661-45-393, title=HomeKit Setup @ 2018-03-27T22:10:40.407371+02:00>>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] pair: persist
2018-03-27 22:11:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976647536-2>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] pair: update_advertisment
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: unregister_service
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,3600/3590.4410231933593,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,3600/3586.399747314453,b'\x04s#=1\x11m']..., record[srv,in,Home Assistant._hap._tcp.local.,3600/3591.758455566406,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 1
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,3600/3586.3957504882815,b'\x04s#=1\x11m']...]>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04s#=1\x11m']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04s#=1\x11m']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: error list.remove(x): x not in list ... entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: error record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.] is not in list ... entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: mdns_service_info
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: accessory <homeassistant.components.homekit.accessories.HomeBridge object at 0x7387e4d0>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: address 192.168.253.5
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: port 51827
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827], record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04s#=1\x11m']...]>
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: sleep
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: index: 1
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[txt,in,Home Assistant._hap._tcp.local.,0/0,b'\x04s#=1\x11m']..., record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: home assistant._hap._tcp.local., alias: None>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[srv,in,Home Assistant._hap._tcp.local.,0/0,raspberrypi.local.:51827]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: cache[key] <[record[ptr,in,_hap._tcp.local.,0/0,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: index: 0
2018-03-27 22:11:09 WARNING (zeroconf-Reaper) [zeroconf] remove: success
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] update_advertisment: register_service
2018-03-27 22:11:09 DEBUG (Thread-9) [pyhap.accessory_driver] AccessoryMDNSServiceInfo(type='_hap._tcp.local.', name='Home Assistant._hap._tcp.local.', address=b'\xc0\xa8\xfd\x05', port=51827, weight=0, priority=0, server='raspberrypi.local.', properties={'s#': '1', 'md': 'Home Assistant', 'pv': '1.0', 'ff': '0', 'sf': '0', 'ci': '2', 'c#': '2', 'id': 'C4:82:CF:FD:83:E3', 'sh': b'7lrYpA=='})
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] register_service
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: allow_name_change False
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: while (0)
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] <name: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] <cache: []>
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: while (0) wait
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: while (0) self.send(out)
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: while (1)
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] <name: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] <cache: []>
2018-03-27 22:11:09 WARNING (zeroconf-Engine) [zeroconf] add: entry <key: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:09 WARNING (Thread-9) [zeroconf] check_service: while (1) wait
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] check_service: while (1)
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] current_entry_with_name_and_alias
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] <name: _hap._tcp.local., alias: Home Assistant._hap._tcp.local.>
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] <cache: [record[ptr,in,_hap._tcp.local.,3600/3599.818712158203,Home Assistant._hap._tcp.local.]]>
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] record[ptr,in,_hap._tcp.local.,3600/3599.8177312011717,Home Assistant._hap._tcp.local.]
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] return record
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] check_service: name conflict
2018-03-27 22:11:10 WARNING (Thread-9) [zeroconf] check_service: NonUniqueNameException

ikalchev commented 6 years ago

So only solution is allow name change... too bad. I guess we can make a change in HAP-python to use this argument, or alternatively to try without it and warn and use it if it fails(problem is to avoid hanging).

Thanks for the debugging! Will keep posted on how the solution is moving :)

cdce8p commented 6 years ago

@ikalchev As I mentioned above https://github.com/home-assistant/home-assistant/issues/12868#issuecomment-376171278, allow_name_change=True doesn't work either. At least not after a restart, since if the accessory is already paired, we don't got through unregister and register again. So the address doesn't match the one which was paired.

Do we need the update_advertisement method? As far is I understand it, it just handles that the accessory/bridge isn't available for any other Home instance to pair with. If we were to delete it, it should work, since we don't need to unregister any service until to Home Assistant is stopped.

ikalchev commented 6 years ago

As I mentioned above #12868 (comment), allow_name_change=True doesn't work either.

You are right, sorry.

Do we need the update_advertisement method?

Unfortunately, we do. Imagine your accessory goes to a new version and has a different display name or more chars or whatever. iOS has no way of knowing about these changes, apart from monitoring the version field of the mDNS advert. Thus, when you do make changes to your acc, you need to bump the version field so that iOS knows it needs to fetch the whole accessory and update (see this). Ultimately, this translates to updating the advert.

So a short answer would be: yes, we need update_advertisment method in general, but we can stop calling it in the pair method. However, note that once HAP-python restarts, the mDNS will be updated, so when you unpair, you need update_advertisment again, so that others can then pair. This potentially can hang in the same way as with the pairing.

By the way (and I have missed this) do we know why the hang actually happens? I.e. why we don't see an exception instead?

cdce8p commented 6 years ago

As far as I understand zeroconf, it raises a NonUniqueNameException in check_service: https://github.com/jstasiak/python-zeroconf/blob/0622570645116b0c45ee03d38b7b308be2026bd4/zeroconf.py#L1875-L1896

Please correct me if I'm missing something, but if we don't call update_advertisement in pair, the accessory should still be available for other Home instances to pair to. So in theory we shouldn't need to call it in unpair either. That would leave config_changed. I see your point here. At least from the Home Assistant side, this method isn't called. The accessories don't change during runtime, although that might be different in the future.

cdce8p commented 6 years ago

@iditude Regarding my idea, can you try a few thing? Here are the files:

accessory_driver.py
zeroconf.py that's the original one

To start delete the .homekit.state file. See if the following things work:

Pairing
Restart Home Assistant, the Home Assistant Bridge and Accessories still work
Unpair
Pair again

You shouldn't need to delete .homekit.state during these steps. It's enough to test if these work. A log woun't be necessary.

iditude commented 6 years ago

Here it goes.

To start delete the .homekit.state file -> Done + Restart

Pairing -> Success Restart Home Assistant, the Home Assistant Bridge and Accessories still work -> Success Unpair-> Success (new Pin code shown in Hass interface) - I hope I do this right. I deleted my home from the "Home" App on the phone Pair again -> Fail I can't find "Home Assistant" in the Home App to be able to pair. If I delete .homekit.state and restart, Home assistant appears again but we're probably back to point 1.

Hope this helps

ikalchev commented 6 years ago

So in theory we shouldn't need to call it in unpair either.

@cdce8p When you unpair but do not restart HAP-python, the mDNS will indicated that the device is still paired, so it will not be possible to pair again until a restart of HAP-python.

This is exactly what we see happening for @iditude in the last comment- without a restart of Home Assistant/HAP-python, mDNS will indicate the accessory is paired so it will be ignored by iOS.

PS I am sorry I reply so slowly, but I struggle to find the time. I hope to have a better look soon.

cdce8p commented 6 years ago

I see. As a fix for now, what do you think of only removing the update_advertisement call from the pair method? If we fully convert HAP-python to async, an alternative would be aiozeroconf. That might solve the issue.

As a side node: During development sometimes I encounter the issue as well (while trying to pair), but I can't reproduce it consistently. Often a restart is enough to fix it.

ikalchev commented 6 years ago

aiozeroconf is largely based on zeroconf, so chances are this issue can be seen there as well.

ikalchev commented 6 years ago

@cdce8p what do you think of changing update_advertisement:

def update_advertisment(self):
        """Updates the mDNS service info for the accessory."""
        self.advertiser.unregister_service(self.mdns_service_info)
        self.mdns_service_info = AccessoryMDNSServiceInfo(self.accessory,
                                                          self.address,
                                                          self.port)
        time.sleep(0.1)  # Doing it right away can cause crashes.
        try:
            self.advertiser.register_service(self.mdns_service_info)
        except NonUniqueNameException:
            logger.error("Failed to update advertisement, iOS devices "
                                 "will continue the old accessory state "
                                 "until a restart of HAP-python")

This will prevent this problem from happening in config_changed and unpair as well. Thoughts?

cdce8p commented 6 years ago

@ikalchev That might work. I will update the PR

cdce8p commented 6 years ago

@iditude Can you try the four steps with accessory_driver.py again. We improved the error handling. At least there should be dedicated error messages now, if something fails.

cdce8p commented 6 years ago

Small corrections: accessory_driver.py

iditude commented 6 years ago

Hello,

Unfortunately I can't test as Homekit is behaving weirdly. I don't know if it is because I'm on the latest "dev" or the change you made in the driver, but I get this when Hass starts

2018-04-01 13:29:46 ERROR (Thread-8) [pyhap.accessory_driver] Could not register HomeKit service. Restart

I see a pin code, Hass is visible in the home App but pairing doesn't go through

Thanks

ikalchev commented 6 years ago

This is from the change in the driver from the previous comment. Unfortunately I am away from my computer, will try to debug later/tomorrow. Thanks for trying this out!

cdce8p commented 6 years ago

@ikalchev That is the error during advertiser.register_service in driver.start(). Although somewhat unexpected. I'm not sure, but this could be an outlier. I would have thought that the errors came from update_advertisement or unregister_service in driver.stop()

@iditude Can you try that again (maybe two or three more times)? Normally that error can't be raised, since it indicates that the a DNS service is already registered although there are non at that moment. If you enable debug logging, there should be a debug message beside the error one.

FYI I expect you getting this warning, after pairing worked: Failed to update advertisement, iOS devices will continue to get the old accessory state until a restart. Step 4 will probably still don't work.

iditude commented 6 years ago

Hello

I tried again with debug but wasn't able to pair (hangs). Difference from before that logs don't even show successful pairing. The pin code remains in the interface.

Here's the full log:


2018-04-01 14:55:51 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit
2018-04-01 14:55:52 INFO (MainThread) [pyhap.accessory_driver] Storing Accessory state in `/home/pi/.homeassistant/.homekit.state`
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.owm_temperature" as "TemperatureSensor"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "switch.wc_vmc" as "Switch"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_high_clouds" as HumiditySensor"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_medium_clouds" as HumiditySensor"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.owm_humidity" as HumiditySensor"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_cloudiness" as HumiditySensor"
2018-04-01 14:56:01 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.temperature_cuisine" as "TemperatureSensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "switch.chevet_charles" as "Switch"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "switch.sdb_vmc" as "Switch"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_fog" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "climate.heater" as "Thermostat"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "switch.alloff" as "Switch"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_humidity" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_dewpoint_temperature" as "TemperatureSensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_temperature" as "TemperatureSensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "switch.chevet_alexandre" as "Switch"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.iphone_guillaume_battery_level" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.processor_use" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.weather_low_clouds" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.owm_cloud_coverage" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "remote.rigaud" as "Switch"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Add "sensor.disk_use_percent_" as HumiditySensor"
2018-04-01 14:56:02 DEBUG (Thread-18) [homeassistant.components.homekit] Driver start
2018-04-01 14:56:02 INFO (Thread-18) [pyhap.accessory_driver] Starting accessory 'Home Assistant' on address '192.168.253.5', port '51827'.
2018-04-01 14:56:02 DEBUG (Thread-37) [homeassistant.components.homekit.type_switches] switch.wc_vmc: Set current state to False
2018-04-01 14:56:02 DEBUG (Thread-39) [homeassistant.components.homekit.type_switches] switch.chevet_charles: Set current state to False
2018-04-01 14:56:02 DEBUG (Thread-40) [homeassistant.components.homekit.type_sensors] sensor.weather_medium_clouds: Percent set to 99%
2018-04-01 14:56:02 DEBUG (Thread-43) [homeassistant.components.homekit.type_sensors] sensor.weather_humidity: Percent set to 69%
2018-04-01 14:56:02 DEBUG (Thread-44) [homeassistant.components.homekit.type_sensors] sensor.temperature_cuisine: Current temperature set to 21°C
2018-04-01 14:56:02 ERROR (Thread-18) [pyhap.accessory_driver] Could not register HomeKit service. Restart
2018-04-01 14:56:02 DEBUG (Thread-47) [homeassistant.components.homekit.type_switches] remote.rigaud: Set current state to True
2018-04-01 14:56:02 DEBUG (Thread-50) [homeassistant.components.homekit.type_sensors] sensor.weather_dewpoint_temperature: Current temperature set to 1°C
2018-04-01 14:56:02 DEBUG (Thread-52) [homeassistant.components.homekit.type_sensors] sensor.weather_cloudiness: Percent set to 100%
2018-04-01 14:56:02 DEBUG (Thread-18) [pyhap.accessory_driver] Exception during start of driver, register service: 
2018-04-01 14:56:02 DEBUG (Thread-53) [homeassistant.components.homekit.type_switches] switch.chevet_alexandre: Set current state to False
2018-04-01 14:56:02 DEBUG (Thread-55) [homeassistant.components.homekit.type_sensors] sensor.processor_use: Percent set to 26%
2018-04-01 14:56:02 INFO (Thread-18) [pyhap.accessory_driver] Stoping accessory 'Home Assistant' on address 192.168.253.5, port 51827.
2018-04-01 14:56:02 DEBUG (Thread-56) [homeassistant.components.homekit.type_sensors] sensor.disk_use_percent_: Percent set to 10%
2018-04-01 14:56:02 DEBUG (Thread-18) [pyhap.accessory_driver] Setting run sentinel, stopping accessory and event sending
2018-04-01 14:56:02 DEBUG (Thread-59) [homeassistant.components.homekit.type_sensors] sensor.owm_cloud_coverage: Percent set to 90%
2018-04-01 14:56:02 DEBUG (Thread-61) [homeassistant.components.homekit.type_sensors] sensor.iphone_guillaume_battery_level: Percent set to 100%
2018-04-01 14:56:02 DEBUG (Thread-62) [homeassistant.components.homekit.type_switches] switch.sdb_vmc: Set current state to False
2018-04-01 14:56:02 DEBUG (Thread-64) [homeassistant.components.homekit.type_sensors] sensor.weather_high_clouds: Percent set to 100%
2018-04-01 14:56:02 DEBUG (Thread-66) [homeassistant.components.homekit.type_sensors] sensor.owm_humidity: Percent set to 57%
2018-04-01 14:56:02 DEBUG (Thread-67) [homeassistant.components.homekit.type_sensors] sensor.owm_temperature: Current temperature set to 9°C
2018-04-01 14:56:02 DEBUG (Thread-71) [homeassistant.components.homekit.type_sensors] sensor.weather_temperature: Current temperature set to 6°C
2018-04-01 14:56:02 DEBUG (Thread-73) [homeassistant.components.homekit.type_switches] switch.alloff: Set current state to False
2018-04-01 14:56:02 DEBUG (Thread-18) [pyhap.accessory_driver] Stopping mDNS advertising
2018-04-01 14:56:05 DEBUG (Thread-17) [homeassistant.components.homekit.type_switches] switch.chevet_alexandre: Set current state to True
2018-04-01 14:56:07 DEBUG (Thread-18) [pyhap.accessory_driver] Stopping HAP server
2018-04-01 14:56:08 INFO (Thread-18) [pyhap.hap_server] Stopping HAP server
2018-04-01 14:56:08 DEBUG (Thread-18) [pyhap.accessory_driver] AccessoryDriver stopped successfully
2018-04-01 14:56:25 DEBUG (Thread-12) [homeassistant.components.homekit.type_sensors] sensor.processor_use: Percent set to 11%
2018-04-01 14:56:56 DEBUG (Thread-13) [homeassistant.components.homekit.type_sensors] sensor.processor_use: Percent set to 1%```

Cheers

iditude commented 6 years ago

Hello guys,

I've started fresh again. With all those updated files flying around, I wasn't sure of my test. I can confirm I can pair with the latest file. See below full testing:

To start delete the .homekit.state file -> Done + Restart

Pairing -> Success. I confirm I had the error message

2018-04-05` 22:49:10 DEBUG (Thread-91) [pyhap.accessory_driver] Exception during update_advertisement, register_service: 2018-04-05 22:49:10 ERROR (Thread-91) [pyhap.accessory_driver] Failed to update advertisement, iOS devices will continue to get the old accessory state until a restart.

Restart Home Assistant, the Home Assistant Bridge and Accessories still work -> Success Unpair-> Success (new Pin code shown in Hass interface) - I hope I do this right. I deleted my home from the "Home" App on the phone Pair again -> Fail I can't find "Home Assistant" in the Home App to be able to pair.

This is progress!

Cheers

cdce8p commented 6 years ago

Can you try if it works a) After a restart b) or with .homekit.state deleted and restart?

iditude commented 6 years ago

Hello,

So after unpair, it doesn't work with a simple restart.

I actually also noticed that now unpairing doesn't restore the notification in Home Assistant for the Pin Code.

After delete .homekit.state and restart it behaves sporadically (a few times I had to reboot the pi completely for Hass to appear in the iOS Home App). Lastly I simply wasn't able to pair again but a few restart helped. However I was still back to the initial problem (iOS app hangs, logs show successful pairing).

Cheers

iditude commented 6 years ago

Hello,

Do you need anything on this issue from me?

Just so you know, I tested the very latest dev and the problems are solved for me.

Pairing -> Success. Restart Home Assistant, the Home Assistant Bridge and Accessories still work -> Success Unpair-> Success Pair again -> Success

However I can't control anything anymore: items are in the HomeApp, react (turn on or off) but don't physically change anything. I assume this is because I'm using the latest dev with your revised (older) version of accessory_driver...

Thanks

cdce8p commented 6 years ago

Hi, I has been quite some time. HAP-python has changed a lot recently. I will post an updated accessory_driver file in a bit. Before, can you try using the regular one (accessory_driver.py). If the issues are still there, please also try restarting your system (not just Home Assistant). I noticed recently that this solved it for me from time to time.

cdce8p commented 6 years ago

Here is the update file accessory_driver.py. Please try the before mentioned method first.

Edit: I rebase against the wrong branch. Will update the post in a minute. The new link is online.

iditude commented 6 years ago

Hello,

Sorry for the delay, I was abroad.

I can confirm the latest version works for Pair and Control.

Thanks!

cdce8p commented 6 years ago

@iditude The regular one or the updated accessory_driver?

iditude commented 6 years ago

I used the updated file you shared.

cdce8p commented 6 years ago

@iditude Sorry to bother you again with this. The newly release HA beta 0.69.0b2 also contains a bigger HAP-python update. If possible, it would be great if you could test / clarify some things.

As setup

Upgrade to 0.69.0b2 or newer
Reboot the system / raspberry

Test Cases

The same ones as before

Pairing
Restart
Unpair
Pair again

Tests

Just the normal system
Updated accessory_driver file. For that case please take a look at the log file afterwards to see if any pyhap errors have been logged. If so the error log msg with the corresponding debug log msg (usually they start with Exception during start of driver / stop of driver / update_advertisement, ...) would be helpful.

iditude commented 6 years ago

Hello,

I've tried 0.69.1 and was successful in all cases above with the standard file as well as the revised accessory_driver.

I didn't find particular errors in the log. All seems to be working fine!

Cheers

cdce8p commented 6 years ago

@iditude Thanks for the test. Since it worked with the standard file, I would leave it at this for now and finally close this issue. If something should come up again, feel free to reopen it.

Again thanks for your patience and the help in debugging this issue!

VdkaShaker commented 6 years ago

Was finally able to test today with 0.69.0 and all tests passed successfully (standard code), and with only the info pin code in the logs.

I was particularly impressed when, after I unpaired from the Home app, the new pairing code popped up on HomeAssistant automatically.

This gives me the confidence to begin migrating off Homebridge.

Thanks for all your efforts on this.

On May 7, 2018, at 3:37 PM, cdce8p - notifications@github.com git.vs.72512ac6bb.notifications#reply@reply.github.com wrote:

@iditude Sorry to bother you again with this. The newly release HA beta 0.69.0b2 also contains a bigger HAP-python update. If possible, it would be great if you could test / clarify some things.

As setup

Upgrade to 0.69.0b2 or newer Reboot the system / raspberry Test Cases

The same ones as before

Pairing Restart Unpair Pair again Tests

Just the normal system Updated accessory_driver file. For that case please take a look at the log file afterwards to see if any pyhap errors have been logged. If so the error log msg with the corresponding debug log msg (usually they start with Exception during start of driver / stop of driver / update_advertisement, ...) would be helpful. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

iditude commented 6 years ago

Thanks Guys. Solid work here!

dvd77 commented 6 years ago

still can't get homekit to work. I am on version 0.69.1 and tried with the standard accessory_driver and the updates one. no error messages in the log and homekit couldn't connect

home-assistant / core

Homekit won't pair #12868

As setup

Test Cases

Tests