Fix loop on dropped connection

[bdraco]

I've been trying to catch this happening for a few months and finally
managed to catch it happening.

Pyhap loop

 31.00%  31.00%    5.80s     5.80s   recv (pyhap/hap_server.py:763)
 34.00%  34.00%    1.34s     1.36s   run (zeroconf/__init__.py:1223)
  4.00%   4.00%    1.27s     1.27s   recv (pyhap/hap_server.py:766)
  1.00%   1.00%   0.660s    0.660s   _worker (concurrent/futures/thread.py:78)
  4.00%   4.00%   0.590s    0.590s   recv (pyhap/hap_server.py:769)
  0.00%   0.00%   0.510s    0.510s   recv (pyhap/hap_server.py:768)
  0.00%   0.00%   0.470s    0.470s   recv (pyhap/hap_server.py:749)
  2.00%   2.00%   0.460s    0.460s   recv (pyhap/hap_server.py:762)
  1.00%   1.00%   0.430s    0.430s   recv (pyhap/hap_server.py:765)
  3.00%   3.00%   0.340s    0.340s   recv (pyhap/hap_server.py:767)
  1.00%   1.00%   0.280s    0.280s   recv (pyhap/hap_server.py:742)

[codecov-io]

Codecov Report

Merging #249 into dev will decrease coverage by 0.07%.
The diff coverage is 0.00%.

@@            Coverage Diff             @@
##              dev     #249      +/-   ##
==========================================
- Coverage   62.99%   62.91%   -0.08%     
==========================================
  Files          16       16              
  Lines        1732     1734       +2     
  Branches      184      185       +1     
==========================================
  Hits         1091     1091              
- Misses        589      591       +2     
  Partials       52       52              

Impacted Files	Coverage Δ
pyhap/hap_server.py	37.22% <0.00%> (-0.16%)	⬇️

[bdraco]

Switched back and forth from wifi to lte about 50 times and everything is still working. I can't reproduce the loop after this fix. I'm leaving this marked as draft so I can do some more testing in the morning.

Finally have an explanation for the random cpu spikes!

[bdraco]

Managed to repro again but this time its moved to this line

                block_length_bytes = self.socket.recv(
                    self.LENGTH_LENGTH, socket.MSG_WAITALL
                )

120.00% 120.00%   10.41s    10.41s   recv (pyhap/hap_server.py:749)

2020-05-10 04:39:38 INFO (Thread-113) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -

# grep 'Thread-113' home-assistant.log |grep 'PUT /char' |wc
  14416  172992 1629008

[bdraco]

Looks good now.

Also camera streams now start noticeably faster.

[bdraco]

2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 2948533182, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 2948533182.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 2948533182, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 2948533182.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 4086763010, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 4086763010.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 4086763010, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 4086763010.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 2757561189, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 2757561189.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Request PUT from address '('192.168.212.110', 49233)' for path '/characteristics'.
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.hap_server] Set characteristics content: {'characteristics': [{'aid': 2757561189, 'iid': 9, 'ev': True}]}
2020-05-10 05:02:35 DEBUG (Thread-75) [pyhap.accessory_driver] Subscribed client ('192.168.212.110', 49233) to topic 2757561189.9
2020-05-10 05:02:35 INFO (Thread-75) [pyhap.hap_server] 192.168.212.110 - "PUT /characteristics HTTP/1.1" 204 -

And iOS 12.4.6 seem to have a bug where ever char is subscribed to twice.

[ikalchev]

That’s some nice debugging 👌🏼good work! Let me know when I can merge

[bdraco]

@ikalchev Everything was stable overnight. Should be good to go now

[bdraco]

Thanks @ikalchev Can we get a new release. I'd like to get Home Assistant updated today or tomorrow so it goes out in beta

[ikalchev]

Does tomorrow morning work for you? (Utc +2)

[ikalchev]

That was a sloppy release I did there, but everything should be fine. The tag is on the dev branch though, sorry.

[bdraco]

That was a sloppy release I did there, but everything should be fine. The tag is on the dev branch though, sorry.

Thanks for the release. 👍 I'll update Home Assistant's dependency later today. After Home Assistant 0.110 is released I will have a few more small cleanup PRs for things I've addressed downstream.