HAP-python
HAP-python copied to clipboard
ikalchev
No response after restart
I have written a simple accessory which publishes data from some sensors. It all works reliably if I start the code and leave it running, but if I stop the code and then restart it, the services are all marked as not responding in the Home app. This probably remains for at least eight hours, after which I got bored, deleted the accessory and added it again.
The state persistence file is being created and appears to have sensible data in it.
You can see the code at https://github.com/mjoldfield/mjo-homekit/blob/master/code/ephat.py and https://github.com/mjoldfield/mjo-homekit/blob/master/code/lib/Ephat.py
Am I making any obvious mistakes, or if not, please can you suggest how I might diagnose the problem.
Could you please paste the logs after you restart (and change them to DEBUG)?
Can you also test with the fake temperature sensor from here: https://github.com/ikalchev/HAP-python/blob/dev/accessories/TemperatureSensor.py?
Thank you for looking at this.
In the attached logs, I've filtered out DEBUG:pyhap.characteristic:set_value messages which form the bulk of the logs, but added debug messages from handle_set_characteristics() in hap_server.py:
req = self.rfile.read(data_len).decode("utf-8")
requested_chars = json.loads(req)
chars = self.accessory_handler.set_characteristics(requested_chars,
self.client_address)
data = json.dumps(chars).encode("utf-8")
logger.debug("set_char: %s -> %s", req, data)
In terms of the network, .119 is an Apple TV, .104 is a HomePod and .117 is my iPhone.
new-f.txt shows the logs when I added the accessory afresh; I then stopped the accessory and waited until the devices were shown as not responding; then restarted the accessory logging to old-f.txt
How would you like me to drive the fake temperature sensor ? Is my existing driver OK ?
Sorry for the long delay.
Interesting - either Apple changed HAP recently, or there is a long-standing bug in HAP-python. To elaborate: I see that the specs say that if PUT /characteristics completes without errors, the response code should be 204 and the body should be empty. Looking at the logs you gave, this is not the case - we return 207 with non-empty body. I have 4 accessories running 24/7 and haven't seen this issue. I will address this right away.
Can I please ask you to go into accessory_driver.py#set_characteristics and print the char:
logger.info("PUT for char: %s", char)
so hopefully I am able to better understand this why we are getting this issue now.
Will let you know when I address this. In the meantime, I suppose you should be able to mitigate the issue by changing the same function you modified to get the logging - change the response code to 204 and delete the last two lines (adding the header and writing the body).
Best, Ivan
Actually, this shouldn't be the problem: Accessories can sometimes report 207 per the spec so it should be fine as it is. Let me dig a little more. Let me know if you managed to get the char.
Can you please also share the python version and the OS?
Thanks again for looking at this. I perhaps should say that if I don't restart the accessory, it runs reliably 24x7 for weeks.
I added the log line here:
...
for cq in chars_query:
aid, iid = cq[HAP_REPR_AID], cq[HAP_REPR_IID]
char = self.accessory.get_characteristic(aid, iid)
# added to aid debug 2.viii.18
logger.info("PUT for char: %s", char)
if HAP_PERMISSION_NOTIFY in cq:
char_topic = get_topic(aid, iid)
self.subscribe_client_topic(
client_addr, char_topic, cq[HAP_PERMISSION_NOTIFY])
...
Though it doesn't appear to be called in the logs below. When should it be called ?
This is all running on a Raspberry Pi Zero, with the latest Rasbian
$ uname -a
Linux zs0 4.14.52+ #1123 Wed Jun 27 17:05:32 BST 2018 armv6l GNU/Linux
$ python3 --version
Python 3.5.3
I misspoke - what I meant was that I have this running and restarting for a long time now without a problem. But anyway:
I don't see the client subscribing for updates (this is from the previous logs):
DEBUG:pyhap.hap_server:Request PUT from address '('192.168.1.104', 49265)' for path '/characteristics'.
Are there any requests after the log you sent in you last reply? If so it seems that the clients can't get the reply of GET /accessories which happens earlier than the PUT request above.
Can you get the version of the following modules (e.g. with pip3 list | grep X):
- pycryptodome
- tlslite-ng
- curve25519-donna
- HAP-python
Was there a time that you didn't have this problem? Also, you have another unix machine on which you could test HAP-python? macOS/any linux works (I can only test on raspberry 2b and 3)
Thanks again for looking at this.
Are there any requests after the log you sent in you last reply? If so it seems that the clients can't get the reply of GET /accessories which happens earlier than the PUT request above.
There was nothing until about 4 days later when it saw this:
Aug 6 13:29:07 zs0 python3[435]: INFO:pyhap.hap_server:Got connection with ('192.168.1.109', 49165). Aug 6 13:29:07 zs0 python3[435]: DEBUG:pyhap.hap_server:Request POST from address '('192.168.1.109', 49165)' for path '/pair-verify'. Aug 6 13:29:07 zs0 python3[435]: DEBUG:pyhap.hap_server:Pair verify [1/2]. Aug 6 13:29:07 zs0 python3[435]: INFO:pyhap.hap_server:192.168.1.109 - "POST /pair-verify HTTP/1.1" 200 - Aug 6 13:29:08 zs0 python3[435]: DEBUG:pyhap.hap_server:Request POST from address '('192.168.1.109', 49165)' for path '/pair-verify'. Aug 6 13:29:08 zs0 python3[435]: DEBUG:pyhap.hap_server:Pair verify [2/2] Aug 6 13:29:08 zs0 python3[435]: DEBUG:pyhap.hap_server:Pair verify with client '('192.168.1.109', 49165)' completed. Switching to encrypted transport. Aug 6 13:29:08 zs0 python3[435]: INFO:pyhap.hap_server:192.168.1.109 - "POST /pair-verify HTTP/1.1" 200 - Aug 6 13:29:08 zs0 python3[435]: DEBUG:pyhap.hap_server:Request GET from address '('192.168.1.109', 49165)' for path '/accessories'. Aug 6 13:29:08 zs0 python3[435]: INFO:pyhap.hap_server:192.168.1.109 - "GET /accessories HTTP/1.1" 200 -
Can you get the version of the following modules (e.g. with pip3 list | grep X):
curve25519-donna (1.3) HAP-python (2.2.2) pycryptodome (3.6.4) tlslite-ng (0.7.4)
Was there a time that you didn't have this problem?
I don't think so.
Also, you have another unix machine on which you could test HAP-python? macOS/any linux works (I can only test on raspberry 2b and 3)
I can try to set this up.
I have one further observation: sometimes there seems to be an issue if e.g. I remove the accessory from the Home app and then try to add it again. The Home app can't see the device until say half an hour has passed. I vaguely wonder if some state is being cached in the my Homepod or Apple TV, which stops the Home app seeing the new accessory, but I don't know if that makes any sense.
I had an issue tonight (after updating my HAP-python) where HomeKit was not showing any of the bridged devices as being available. It turned out my code was mistakenly adding a second information service (I'd been using my own code to add this, as I wanted to change it before it was created, and I had been on a fairly old version of HAP-python).
HomeKit will just appear to ignore a bridge and/or accessory that has this problem. In my case, the problem was there from the initial start (rather than just after a restart), so when I cleared stuff out and tried to pair, the pairing failed (well, it paired correctly, but the bridge was immediately unpaired after that).
The best way I found to troubleshoot was to turn logging up, and then view the data that was being sent to the HomeKit phone: from this I could see that it was bad (and totally my fault).
Perhaps something similar is going on here?
