Core: Updating ping binary_sensor took longer than the scheduled update interval

[Misiu]

The problem

I've opened the logs and I see an error that is repeating more than 800 times! I think this shouldn't happen.

Environment

• Home Assistant Core release with the issue: 0.108.6
• Last working Home Assistant Core release (if known): not known
• Operating environment (Home Assistant/Supervised/Docker/venv): HA on PI3
• Integration causing this issue: ping
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/ping/

Problem-relevant configuration.yaml

binary_sensor:
  - platform: ping
    host: 192.166.11.1
    name: Router
    scan_interval: 30

  - platform: ping
    host: 192.166.11.2
    name: TV
    scan_interval: 30

Traceback/Error logs

Logger: homeassistant.components.binary_sensor
Source: helpers/entity_platform.py:540
Integration: Sensor binarny (documentation, issues)
First occurred: 3 May 2020, 22:14:58 (801 occurrences)
Last logged: 11:47:25

Updating ping binary_sensor took longer than the scheduled update interval 0:00:30

Additional information

[mbo18]

Same as these issues?

33281

33556

34700

[Misiu]

@mbo18 I'm not using device tracker, just a simple ping to tell if the device is offline/online (I use binary_sensor).

[probot-home-assistant[bot]]

ping documentation
ping source
_{^{(message by IssueLinks)}}

[shenxn]

@Misiu Enable debug log by adding

logger:
  default: info
  logs:
    homeassistant.components.ping: debug

to your configuration.yaml and load full home assistant log when you see the error again. This may help finding out the problem.

[Misiu]

@shenxn after adding those lines and restarting my Home Assistant (running on Raspberry PI 3) I get these entries in the log:

2020-05-06 10:45:08 DEBUG (SyncWorker_18) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.14 (192.168.18.14): 56 data bytes\n\n--- 192.168.18.14 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 3.087/17.168/48.731 ms\n', b'')
2020-05-06 10:45:09 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:30
2020-05-06 10:45:12 DEBUG (SyncWorker_11) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.15 (192.168.18.15): 56 data bytes\n\n--- 192.168.18.15 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 3.032/5.081/7.387 ms\n', b'')
2020-05-06 10:45:44 DEBUG (SyncWorker_3) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.1 (192.168.18.1): 56 data bytes\n\n--- 192.168.18.1 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 0.829/1.832/5.373 ms\n', b'')
2020-05-06 10:45:48 DEBUG (SyncWorker_4) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.2 (192.168.18.2): 56 data bytes\n\n--- 192.168.18.2 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 0.589/0.637/0.685 ms\n', b'')
2020-05-06 10:45:52 DEBUG (SyncWorker_2) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.9 (192.168.18.9): 56 data bytes\n\n--- 192.168.18.9 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.554/3.175/3.583 ms\n', b'')
2020-05-06 10:45:56 DEBUG (SyncWorker_19) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.6 (192.168.18.6): 56 data bytes\n\n--- 192.168.18.6 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.294/21.484/36.322 ms\n', b'')
2020-05-06 10:46:00 DEBUG (SyncWorker_1) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.8 (192.168.18.8): 56 data bytes\n\n--- 192.168.18.8 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.548/3.867/7.381 ms\n', b'')
2020-05-06 10:46:04 ERROR (Poll) [pyShelly] Error http GET: http://172.30.32.1/settings, [Errno 111] Connection refused, Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/pyShelly/utils.py", line 56, in shelly_http_get
    conn.request("GET", url, None, headers)
  File "/usr/local/lib/python3.7/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1298, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1247, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1026, in _send_output
    self.send(msg)
  File "/usr/local/lib/python3.7/http/client.py", line 966, in send
    self.connect()
  File "/usr/local/lib/python3.7/http/client.py", line 938, in connect
    (self.host,self.port), self.timeout, self.source_address)
  File "/usr/local/lib/python3.7/socket.py", line 728, in create_connection
    raise err
  File "/usr/local/lib/python3.7/socket.py", line 716, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/pyShelly/utils.py", line 56, in shelly_http_get
    conn.request("GET", url, None, headers)
  File "/usr/local/lib/python3.7/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1298, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1247, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.7/http/client.py", line 1026, in _send_output
    self.send(msg)
  File "/usr/local/lib/python3.7/http/client.py", line 966, in send
    self.connect()
  File "/usr/local/lib/python3.7/http/client.py", line 938, in connect
    (self.host,self.port), self.timeout, self.source_address)
  File "/usr/local/lib/python3.7/socket.py", line 728, in create_connection
    raise err
  File "/usr/local/lib/python3.7/socket.py", line 716, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused
2020-05-06 10:46:04 DEBUG (SyncWorker_5) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.7 (192.168.18.7): 56 data bytes\n\n--- 192.168.18.7 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.435/4.053/7.716 ms\n', b'')
2020-05-06 10:46:08 DEBUG (SyncWorker_12) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.14 (192.168.18.14): 56 data bytes\n\n--- 192.168.18.14 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 3.373/22.287/60.122 ms\n', b'')
2020-05-06 10:46:11 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:30
2020-05-06 10:46:12 DEBUG (SyncWorker_15) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.15 (192.168.18.15): 56 data bytes\n\n--- 192.168.18.15 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 4.436/25.014/103.053 ms\n', b'')
2020-05-06 10:46:46 DEBUG (SyncWorker_16) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.1 (192.168.18.1): 56 data bytes\n\n--- 192.168.18.1 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 0.947/1.030/1.109 ms\n', b'')
2020-05-06 10:46:50 DEBUG (SyncWorker_7) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.2 (192.168.18.2): 56 data bytes\n\n--- 192.168.18.2 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 0.531/0.594/0.651 ms\n', b'')
2020-05-06 10:46:54 DEBUG (SyncWorker_8) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.9 (192.168.18.9): 56 data bytes\n\n--- 192.168.18.9 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.272/3.103/4.945 ms\n', b'')
2020-05-06 10:46:58 DEBUG (SyncWorker_14) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.6 (192.168.18.6): 56 data bytes\n\n--- 192.168.18.6 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 6.724/19.209/27.012 ms\n', b'')
2020-05-06 10:47:02 DEBUG (SyncWorker_10) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.8 (192.168.18.8): 56 data bytes\n\n--- 192.168.18.8 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 2.297/24.820/40.966 ms\n', b'')
2020-05-06 10:47:06 DEBUG (SyncWorker_7) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.7 (192.168.18.7): 56 data bytes\n\n--- 192.168.18.7 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 24.075/25.751/29.950 ms\n', b'')
2020-05-06 10:47:10 DEBUG (SyncWorker_18) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.14 (192.168.18.14): 56 data bytes\n\n--- 192.168.18.14 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 3.155/40.591/104.894 ms\n', b'')
2020-05-06 10:47:13 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:30
2020-05-06 10:47:14 INFO (Thread-21) [pyShelly] Get status from E66927 Shelly 2.5
2020-05-06 10:47:14 DEBUG (SyncWorker_14) [homeassistant.components.ping.binary_sensor] Output is (b'PING 192.168.18.15 (192.168.18.15): 56 data bytes\n\n--- 192.168.18.15 ping statistics ---\n5 packets transmitted, 5 packets received, 0% packet loss\nround-trip min/avg/max = 3.411/30.173/79.211 ms\n', b'')
2020-05-06 10:47:15 INFO (Thread-22) [pyShelly] Get status from 6926CE Shelly 2.5
2020-05-06 10:47:15 INFO (Thread-24) [pyShelly] Get status from 6885BF Shelly 2.5
2020-05-06 10:47:18 INFO (Thread-25) [pyShelly] Get status from 688024 Shelly 2.5

There are some entries from PyShelly and Shelly components, but the rest is for homeassistant.components.ping.binary_sensor

[shenxn]

@Misiu According to your log, it seems that you've set up a lot of ping binary sensors. Since the ping component uses update instead of the async version async_update, the updates cannot be running in parallel (see here). Therefore, all those binary sensors have to update one by one and they eventually go pass the 30 seconds interval. We'll need to refactor the integration into a async one to truly solve this problem. For now, you can try to increase the update interval and / or set the count option to a smaller number.

[Misiu]

@shenxn I have only 8 devices. This isn't much, but maybe this is too much.
I'll update the update interval for not.
Not sure if it will be hard to refactor the ping integration to use async. I'll look into the code of other integrations.

[Misiu]

@shenxn thanks for looking into this :)

[shenxn]

@Misiu Refactoring shouldn't be difficult since it is a relatively small integration. If you feel you wanna try, this could be helpful, which is an async version of the subprocess module used in the integration.

[Misiu]

I've also noticed his in logs:

2020-05-06 11:16:56 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ping is taking over 10 seconds.

[Misiu]

@shenxn sadly ping has no tests so I can't test if my changes work correctly :/
Also, I'm not a Python expert.
This is my changed binary_sensor: https://github.com/Misiu/home-assistant/blob/async_ping/homeassistant/components/ping/binary_sensor.py
Could you take a look?

[shenxn]

@Misiu You are on the right track. Only a few things need to be changed. Just create a pull request so I can make a review.

[Misiu]

@shenxn I've created https://github.com/home-assistant/core/pull/35301. I'll be grateful for a review.
I can also update device_tracker but in a second run.
Any ideas on how to add tests to ping integration? They are missing and I think adding them would help to solve all the issues.

[atpage]

But, why is this suddenly requiring a rewrite after it worked fine for years?

[shenxn]

@atpage The problem is there for a long time, but it only happens when you have many ping sensors and a pretty short scan interval. Also, there is only going to be a lot of warning messages and nothing actually break.

[atpage]

Hmm, so does this not have the same cause as issue 33281? nmap_tracker has been throwing the same errors as the ping tracker, but it started suddenly in the last few months with no change to config.

[shenxn]

@atpage They can have the same cause if there was something changed in how homeassistant handles integration polling. But I don't know much about that so I'm not pretty sure.