0.113.0 - Zeroconf errors

chemelli74 commented 4 years ago

The problem

Log error recorded

Environment

Home Assistant Core release with the issue: 0.113.0
Last working Home Assistant Core release (if known):
Operating environment (OS/Container/Supervised/Core): Core
Integration causing this issue: zeroconf
Link to integration documentation on our website:

Problem-relevant `configuration.yaml`

Traceback/Error logs


2020-07-23 17:53:13 WARNING (zeroconf-ServiceBrowser__http._tcp.local._5358) [zeroconf] Error sending through socket 25
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 2792, in send
    bytes_sent = s.sendto(packet, 0, (real_addr, port))
OSError: [Errno 22] Invalid argument

2020-07-26 08:24:40 WARNING (zeroconf-ServiceBrowser__http._tcp.local._5358) [zeroconf] Error sending through socket 25
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 2792, in send
    bytes_sent = s.sendto(packet, 0, (real_addr, port))
OSError: [Errno 19] No such device

Additional information

bdraco commented 4 years ago

Would you please post a py-spy dump (https://github.com/benfred/py-spy/releases) as well. A recording in svg format would be helpful as well

Example

# docker exec -it 81-homeassistant /bin/bash 
bash-5.0# ./py-spy 
py-spy 0.3.3
Sampling profiler for Python programs 

USAGE:
    py-spy <SUBCOMMAND>

OPTIONS:
    -h, --help       Prints help information
    -V, --version    Prints version information

SUBCOMMANDS:
    record    Records stack trace information to a flamegraph, speedscope or raw file
    top       Displays a top like view of functions consuming CPU
    dump      Dumps stack traces for a target program to stdout
    help      Prints this message or the help of the given subcommand(s)
bash-5.0# ./py-spy dump --pid 208
Process 208: python3 -m homeassistant --config /config
Python v3.8.3 (/usr/local/bin/python3.8)

Thread 208 (idle): "MainThread"
    select (selectors.py:468)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    run_until_complete (asyncio/base_events.py:603)
    run (asyncio/runners.py:43)
    run (homeassistant/runner.py:119)
    main (homeassistant/__main__.py:312)
    <module> (homeassistant/__main__.py:320)
    _run_code (runpy.py:87)
    _run_module_as_main (runpy.py:194)
Thread 230 (idle): "Thread-1"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 231 (idle): "SyncWorker_0"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 232 (idle): "SyncWorker_1"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 233 (idle): "SyncWorker_2"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 236 (idle): "SyncWorker_3"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 237 (idle): "SyncWorker_4"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 238 (idle): "SyncWorker_5"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 239 (idle): "SyncWorker_6"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 240 (idle): "SyncWorker_7"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 241 (idle): "Recorder"
    wait (threading.py:302)
    get (queue.py:170)
    run (homeassistant/components/recorder/__init__.py:340)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 248 (idle): "zeroconf-Engine-248"
    run (zeroconf/__init__.py:1309)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 249 (idle): "zeroconf-Reaper_249"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1422)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 254 (idle): "zeroconf-ServiceBrowser__googlecast._tcp.local.-_miio._udp.local.-_plugwise._tcp.local.-_esphomelib._tcp.local.-_printer._tcp.local.-_wled._tcp.local.-_ipp._tcp.local.-_hap._tcp.local.-_viziocast._tcp.local.-_dkapi._tcp.local.-_ipps._tcp.local.-_daap._tcp.local.-_api._udp.local.-_elg._tcp.local.-_axis-video._tcp.local.-_spotify-connect._tcp.local.-_nut._tcp.local._254"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2360)
    run (zeroconf/__init__.py:1660)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 255 (idle): "Thread-8"
    send_events (pyhap/accessory_driver.py:483)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 256 (idle): "Thread-9"
    select (selectors.py:415)
    serve_forever (socketserver.py:232)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 260 (idle): "Thread-13"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 262 (idle): "Thread-15"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 263 (idle): "Thread-16"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 264 (idle): "Thread-17"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 265 (idle): "Thread-18"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 266 (idle): "Thread-19"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 268 (idle): "Thread-21"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 272 (idle): "Thread-24"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 283 (idle): "Thread-35"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 284 (idle): "Thread-36"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
bash-5.0#

chemelli74 commented 4 years ago

Here the output:

Process 208: /usr/local/bin/python3 /usr/src/homeassistant/homeassistant/__main__.py --config /config
Python v3.8.3 (/usr/local/bin/python3.8)

Thread 208 (idle): "MainThread"
    select (selectors.py:468)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    run_until_complete (asyncio/base_events.py:603)
    run (asyncio/runners.py:43)
    run (homeassistant/runner.py:119)
    main (homeassistant/__main__.py:312)
    <module> (homeassistant/__main__.py:320)
Thread 26867 (idle): "Thread-1"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26868 (idle): "SyncWorker_0"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26871 (idle): "SyncWorker_1"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26872 (idle): "SyncWorker_2"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26873 (idle): "SyncWorker_3"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26874 (idle): "SyncWorker_4"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26875 (idle): "SyncWorker_5"
    readinto (socket.py:669)
    _read_status (http/client.py:264)
    begin (http/client.py:303)
    getresponse (http/client.py:1332)
    _make_request (urllib3/connectionpool.py:421)
    urlopen (urllib3/connectionpool.py:670)
    send (requests/adapters.py:439)
    send (requests/sessions.py:643)
    request (requests/sessions.py:530)
    post (requests/sessions.py:578)
    execute (fritzconnection/core/soaper.py:167)
    call_action (fritzconnection/core/fritzconnection.py:207)
    _action (fritzconnection/lib/fritzhosts.py:29)
    get_specific_host_entry (fritzconnection/lib/fritzhosts.py:51)
    get_extra_attributes (homeassistant/components/fritz/device_tracker.py:84)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26876 (idle): "Recorder"
    wait (threading.py:302)
    get (queue.py:170)
    run (homeassistant/components/recorder/__init__.py:340)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26877 (idle): "zeroconf-Engine-26877"
    run (zeroconf/__init__.py:1304)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26878 (idle): "zeroconf-Reaper_26878"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1417)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26879 (idle): "Cloud"
    _update_loop (pyShelly/cloud.py:72)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26880 (idle): "CoAP"
    _loop (pyShelly/coap.py:101)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26881 (idle): "zeroconf-Engine-26881"
    run (zeroconf/__init__.py:1304)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26882 (idle): "zeroconf-Reaper_26882"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1417)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26883 (idle): "zeroconf-ServiceBrowser__http._tcp.local._26883"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1655)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26884 (idle): "Poll"
    _update_loop (pyShelly/__init__.py:273)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26885 (idle): "zeroconf-ServiceBrowser__elg._tcp.local.-_esphomelib._tcp.local.-_spotify-connect._tcp.local.-_viziocast._tcp.local.-_plugwise._tcp.local.-_printer._tcp.local.-_hap._tcp.local.-_ipp._tcp.local.-_dkapi._tcp.local.-_googlecast._tcp.local.-_ipps._tcp.local.-_nut._tcp.local.-_wled._tcp.local.-_daap._tcp.local.-_axis-video._tcp.local.-_miio._udp.local.-_api._udp.local._26885"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1655)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

Simone

probot-home-assistant[bot] commented 4 years ago

Hey there @kane610, mind taking a look at this issue as its been labeled with an integration (zeroconf) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

kevinblo commented 4 years ago

I got a similar error:

2020-07-27 23:30:59 WARNING (Sonoff_LAN) [zeroconf] Error sending through socket 22, Traceback (most recent call last):, File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 2792, in send, bytes_sent = s.sendto(packet, 0, (real_addr, port)), PermissionError: [Errno 1] Operation not permitted

bdraco commented 4 years ago

Please try again with

default_interface: true

https://www.home-assistant.io/integrations/zeroconf/#default_interface

kevinblo commented 4 years ago

Without changes.

chemelli74 commented 4 years ago

Reproduced on 0.113.3 with debug active:

    await self.queue.execute()
  File "/usr/local/lib/python3.8/site-packages/queueman/manager.py", line 41, in execute
    raise QueueManagerExecutionStillInProgress
queueman.exceptions.QueueManagerExecutionStillInProgress
2020-08-07 11:02:06 WARNING (zeroconf-ServiceBrowser__http._tcp.local._25901) [zeroconf] Error sending through socket 30
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 2826, in send
    bytes_sent = s.sendto(packet, 0, (real_addr, port))
OSError: [Errno 19] No such device

Simone

chemelli74 commented 4 years ago

I added a debug line and discovered what follows:

2020-08-09 12:30:50 WARNING (MainThread) [asyncio] socket.send() raised exception.
2020-08-09 12:31:05 WARNING (zeroconf-ServiceBrowser__http._tcp.local._3568) [zeroconf] chemelli74: real_addr=224.0.0.251, port=5353
2020-08-09 12:31:05 WARNING (zeroconf-ServiceBrowser__http._tcp.local._3568) [zeroconf] Error sending through socket 28
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 2826, in send
    bytes_sent = s.sendto(packet, 0, (real_addr, port))
OSError: [Errno 22] Invalid argument

Doesn't make sense to me, is the same ip and port that usually works.

Simone

bdraco commented 4 years ago

@chemelli74 You have another integration that is starting Zeroconf

Thread 26881 (idle): "zeroconf-Engine-26881"
    run (zeroconf/__init__.py:1304)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26882 (idle): "zeroconf-Reaper_26882"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1417)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 26883 (idle): "zeroconf-ServiceBrowser__http._tcp.local._26883"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2326)
    run (zeroconf/__init__.py:1655)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

There are two instances running. The one Home Assistant started and the one another integration has started which has created an HTTP ServiceBrowser

Would you please provide a list of integrations you have installed, including which ones are custom. We need to find the integration that is creating another instance of Zeroconf and get it to use the main shared instance that Home Assistant starts

chemelli74 commented 4 years ago

I bet it's Samsung TV.

Anyway, let me take the time to provide a full list.

Simone

bdraco commented 4 years ago

I bet it's Samsung TV.

Anyway, let me take the time to provide a full list.

Simone

I checked that one

git clone https://github.com/bdraco/ha-samsungtv-custom
cd ha-samsungtv-custom
git grep Zeroconf

.. nothing

bdraco commented 4 years ago

This can help https://github.com/jstasiak/python-zeroconf/network/dependents?dependent_type=PACKAGE

bdraco commented 4 years ago

May be pyShelly

bdraco commented 4 years ago

pyShelly/mdns.py:from zeroconf import ( ServiceBrowser, Zeroconf )
pyShelly/mdns.py:        self._zeroconf = zeroconf = Zeroconf()

bdraco commented 4 years ago

pyShelly will need an issue opened and the custom integration as well.

Here is an example of how to get the shared zeroconf instance: https://github.com/home-assistant/core/pull/38678

Running multiple Zeroconf instances in the same process has also been known to drive up CPU

chemelli74 commented 4 years ago

I bet it's Samsung TV. Anyway, let me take the time to provide a full list. Simone

I checked that one
git clone https://github.com/bdraco/ha-samsungtv-custom
cd ha-samsungtv-custom
git grep Zeroconf
.. nothing

I was referring to https://github.com/home-assistant/core/tree/dev/homeassistant/components/samsungtv I'm testing this related PR, https://github.com/home-assistant/core/pull/35773

Simone

bdraco commented 4 years ago

35773

That PR appears to be doing things correctly and using the shared instance 👍

chemelli74 commented 4 years ago

pyShelly will need an issue opened and the custom integration as well.

Here is an example of how to get the shared zeroconf instance: #38678

Running multiple Zeroconf instances in the same process has also been known to drive up CPU

Thx a lot for the pointer. Will open a issue on both projects.

Maybe Zeroconf can add a log warning if multiple instances are instantiated.

Simone

SaturnusDJ commented 3 years ago

Can someone help at https://github.com/home-assistant/core/issues/40577? Similar problem.

home-assistant / core