Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Chromecast and Home-mini not detected after HA restart #35922

Closed
rsimiciuc opened this issue May 21, 2020 · 54 comments · Fixed by #36185
Closed

Chromecast and Home-mini not detected after HA restart #35922

rsimiciuc opened this issue May 21, 2020 · 54 comments · Fixed by #36185
Assignees

Comments

@rsimiciuc
Copy link

The problem

Recently I have noticed that my chromecast and home-mini are not detected anymore after ha restarts. If I reboot the chromecast device or the google home mini, they appear in home assistant.
I checked the mDNS messages on the ha container and I can see status updates from both devices, but it seems they are ignored by HA.
Do these devices advertise themselves at boot and not anymore after? This used to work until a few versions ago

Environment

  • Home Assistant Core release with the issue: 0.110.1
  • Last working Home Assistant Core release (if known): ?
  • Operating environment (Home Assistant/Supervised/Docker/venv): docker
  • Integration causing this issue: cast/media_player
  • Link to integration documentation on our website:

Problem-relevant configuration.yaml

Traceback/Error logs

mDNS messages coming into HA network

13:01:14.360139 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [4q] SRV (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. TXT (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. A (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. AAAA (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. (108)
13:01:14.362811 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 2/0/0 (Cache flush) TXT "id=208b1023e0dad3fe2b46ecf030a15ed3" "cd=0FBEF871F0D4A65BE824B1B54BB67AFF" "rm=" "ve=05" "md=Google Home Mini" "ic=/setup/icon.png" "fn=Living Room speaker" "ca=215044" "st=1" "bs=FA8FCA7D147C" "nf=1" "rs=Casting: Turning Away", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:8009 0 0 (358)
13:01:14.561602 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [4q] SRV (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. TXT (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. A (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. AAAA (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. (108)
13:01:14.963304 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [4q] SRV (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. TXT (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. A (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. AAAA (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. (108)
13:01:14.965596 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 2/0/0 (Cache flush) TXT "id=208b1023e0dad3fe2b46ecf030a15ed3" "cd=0FBEF871F0D4A65BE824B1B54BB67AFF" "rm=" "ve=05" "md=Google Home Mini" "ic=/setup/icon.png" "fn=Living Room speaker" "ca=215044" "st=1" "bs=FA8FCA7D147C" "nf=1" "rs=Casting: Turning Away", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:8009 0 0 (358)
13:01:15.764683 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [4q] SRV (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. TXT (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. A (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. AAAA (QM)? Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local. (108)
13:01:15.767972 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 2/0/0 (Cache flush) TXT "id=208b1023e0dad3fe2b46ecf030a15ed3" "cd=0FBEF871F0D4A65BE824B1B54BB67AFF" "rm=" "ve=05" "md=Google Home Mini" "ic=/setup/icon.png" "fn=Living Room speaker" "ca=215044" "st=1" "bs=FA8FCA7D147C" "nf=1" "rs=Casting: Turning Away", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:8009 0 0 (358)
13:01:39.546282 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 [4a] PTR (QM)? _googlecast._tcp.local. (288)
13:01:39.549647 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 4/0/0 PTR Chromecast-42a55766d50deb153177c8243c21da69-1._googlecast._tcp.local., (Cache flush) TXT "id=42a55766d50deb153177c8243c21da69" "cd=C271A9E91E06F0DC532994EEFD8146ED" "rm=" "ve=05" "md=Chromecast" "ic=/setup/icon.png" "fn=Living Room TV" "ca=200709" "st=0" "bs=FA8FCA3206EE" "nf=1" "rs=", (Cache flush) SRV 42a55766-d50d-eb15-3177-c8243c21da69-1.local.:8009 0 0, (Cache flush) A 192.168.1.13 (354)
13:01:39.558000 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 4/0/0 PTR Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3._googlecast._tcp.local., (Cache flush) TXT "id=208b1023e0dad3fe2b46ecf030a15ed3" "cd=0FBEF871F0D4A65BE824B1B54BB67AFF" "rm=" "ve=05" "md=Google Home Mini" "ic=/setup/icon.png" "fn=Living Room speaker" "ca=215044" "st=1" "bs=FA8FCA7D147C" "nf=1" "rs=Casting: Turning Away", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:8009 0 0, (Cache flush) A 192.168.1.146 (388)
13:01:40.905461 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [4a] PTR (QM)? _googlecast._tcp.local. (288)
13:02:17.125459 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 PTR (QM)? _googlerpc._tcp.local. (39)
13:02:17.128769 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 PTR (QM)? _googlezone._tcp.local. (40)
13:02:17.130528 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 4/0/0 PTR googlerpc-1._googlerpc._tcp.local., (Cache flush) TXT "cd=0FBEF871F0D4A65BE824B1B54BB67AFF", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:8012 0 0, (Cache flush) A 192.168.1.146 (180)
13:02:17.134695 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 SRV (QM)? 42a55766-d50d-eb15-3177-c8243c21da69-1._googlezone._tcp.local. (79)
13:02:17.136980 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 4/0/0 PTR 42a55766-d50d-eb15-3177-c8243c21da69-1._googlezone._tcp.local., (Cache flush) TXT "id=C271A9E91E06F0DC532994EEFD8146ED" "__common_time__=0|0", (Cache flush) SRV 42a55766-d50d-eb15-3177-c8243c21da69-1.local.:10001 210 115, (Cache flush) A 192.168.1.13 (230)
13:02:17.139940 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 3/0/0 PTR 208b1023-e0da-d3fe-2b46-ecf030a15ed3._googlezone._tcp.local., (Cache flush) TXT "id=0FBEF871F0D4A65BE824B1B54BB67AFF" "__common_time__=1|0", (Cache flush) SRV 208b1023-e0da-d3fe-2b46-ecf030a15ed3.local.:10001 610 139 (210)
13:02:17.487131 IP 172.27.0.2.5353 > 224.0.0.251.5353: 0 [2a] PTR (QM)? _googlecast._tcp.local. (164)
13:02:17.584440 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0*- [0q] 2/0/0 PTR Google-Home-Mini-208b1023e0dad3fe2b46ecf030a15ed3-1._googlecast._tcp.local., PTR Chromecast-42a55766d50deb153177c8243c21da69._googlecast._tcp.local. (158)
13:02:20.626248 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 SRV (QM)? google-home-mini-208b1023e0dad3fe2b46ecf030a15ed3-1._googlecast._tcp.local. (92)
13:02:20.631869 IP 172.27.0.1.5353 > 224.0.0.251.5353: 0 SRV (QM)? chromecast-42a55766d50deb153177c8243c21da69._googlecast._tcp.local. (84)
@hmmbob
Copy link
Contributor

hmmbob commented May 21, 2020

I am seeing similar behavior. With 0.109, I had to run an Avahi reflector on my host to get mDNS working again (I am running a docker based setup without --net=host; yes that is not according to install instructions). That worked great, but with 0.110 I am seeing weird behavior:

Upon HA reboot, all Cast devices show as unavailable - every reboot again.
Restarting the HA container or host does not make a difference. With avahi-browse on the host I am able to confirm that both the LAN and the Docker net where the containers attach to see (and resolve) all 7 Cast devices. But HA still shows them as unavailable.

The fix? Rebooting my WiFi access points, which probably triggers another advertise or so by the Chromecasts. If I do this, they show up one-by-one in HA again without me touching HA - confirming that mDNS works....

Strange....

@frenck
Copy link
Member

frenck commented May 21, 2020

Duplicate of #35735

@frenck frenck marked this as a duplicate of #35735 May 21, 2020
@frenck frenck closed this as completed May 21, 2020
@emontnemery
Copy link
Contributor

Not a duplicate, this might be a side effect of mDNS changes in 0.110

@emontnemery emontnemery reopened this May 21, 2020
@emontnemery
Copy link
Contributor

@bdraco do you think could be related to zeroconf changes in 0.110?

@bdraco
Copy link
Member

bdraco commented May 21, 2020

@bdraco do you think could be related to zeroconf changes in 0.110?

I don’t think so as I’m pretty sure the cast changes didn’t make 0.110. Will double check when I’m back to my desk

@bdraco
Copy link
Member

bdraco commented May 21, 2020

Do all the affected systems have multiple network interfaces ?

@hmmbob
Copy link
Contributor

hmmbob commented May 21, 2020

I'm running in docker on a pi. The cast devices are in the same lan as eth0 connects to. The HA docker is in a docker network called "homeassistant" (together with some other containers), Avahi is set up to reflect between eth0 and br-..... (whatever the bridge name is of the homeassistant network, don't know it by heart).

Based on the fact that the devices do appear as soon the WiFi AP is reset so they reconnect to the network I have reason to believe the actual mDNS forwarding is working.

@kmlucy
Copy link

kmlucy commented May 21, 2020

I'm seeing the same issue. Cast devices do not show up on restart of Home Assistant. Restarting Home Assistant or Avahi doesn't do anything, but restarting the access point or cast devices makes them show up immediately.

Edit: Restarting the cast device itself DOES NOT make it show up.
Edit 2: Yes it does, I just wasn't patient enough.

I have a similar setup to @hmmbob; Home Assistant is in a Docker network with Avahi reflecting the mDNS packets to it. That was working perfectly in 0.109.

@bdraco
Copy link
Member

bdraco commented May 21, 2020

@emontnemery Verified cast changes are in 0.111 only so thats not it

@emontnemery
Copy link
Contributor

emontnemery commented May 21, 2020

mDNS needs to work directions ways for discovery to work correctly:

  • Home Assistant must send mDNS queries with help of zeroconf, and those queries must make it to the Cast devices
  • Cast devices must send mDNS announcements, and those announcements must be received by Home Assistant's zeroconf client and then make it to the cast integration

Both directions rely on multicast UDP.

By restarting the AP or the cast devices, the cast devices will announce themselves once they're back on the network.
I think this points to mDNS queries sent by Home Assistant not making it to the cast devices, or no requests are sent in the first place.

@emontnemery
Copy link
Contributor

emontnemery commented May 21, 2020

Unfortunately, I can't reproduce the issue on my side.
Logs of:

  • Adding the Cast integration and discovering casts
  • HA restarting and not dsicovering casts

May help bring some light.

Log setup:

logger:
  default: info
  logs:
    homeassistant.components.cast: debug
    homeassistant.components.cast.media_player: debug
    pychromecast: debug
    pychromecast.discovery: debug
    pychromecast.socket_client: debug
    homeassistant.components.zeroconf: debug
    zeroconf: debug

@bdraco zeroconf: debug doesn't really seem to do much here, is it not the right way to enable logging of zeroconf?

@bdraco
Copy link
Member

bdraco commented May 21, 2020

@bdraco zeroconf: debug doesn't really seem to do much here, is it not the right way to enable logging of zeroconf?

if log.level == logging.NOTSET:
    log.setLevel(logging.WARN)

I've had to remove this from zeroconf's __init__.py

@hmmbob
Copy link
Contributor

hmmbob commented May 21, 2020

mDNS needs to work directions ways for discovery to work correctly:

  • Home Assistant must send mDNS queries with help of zeroconf, and those queries must make it to the Cast devices
  • Cast devices must send mDNS announcements, and those announcements must be received by Home Assistant's zeroconf client and then make it to the cast integration

Both directions rely on multicast UDP.

By restarting the AP or the cast devices, the cast devices will announce themselves once they're back on the network.
I think this points to mDNS queries sent by Home Assistant not making it to the cast devices, or no requests are sent in the first place.

Sharp thinking - seems logical and is along the lines where I was looking for the issue.

I'll try to run the container with the debug logging. Did that earlier today and can't remember to have gotten results that helped me further, but I might have missed a sign.

@hmmbob
Copy link
Contributor

hmmbob commented May 21, 2020

Log file dump of reboot with failed recovery to be found here (copy-paste would make it a long post). I cut out everything that wasn't related.

Upon reboot all Cast devices showed as unavailable. Around 20:10 I rebooted (through the google home app) one of the devices ("Studeerkamer"), and as a miracle roughly half of the devices suddenly appeared available. At this moment, still not all of them are available though (1 Google Home mini, 2x Chromecast).

Funny enough, esphome (which also relies on mDNS based on Avahi-browse) is setting up just fine.

--
Edit:
Removed cast from my configuration.yaml, rebooted, removed cast integration, another reboot, and added cast again through integrations. Log of that run is found here - cast was set up without error but did not show any device. At 20:37 I initiaded a reboot of one of the devices, which was picked up by HA when it came back online. All others were not visible in HA up until now (20:46).

@emontnemery
Copy link
Contributor

@hmmbob I don't think these lines look normal:
[pychromecast.discovery] add_service failed to add _googlecast._tcp.local., Chromecast-32e39183bc97abac51d77fce98a766a4-6._googlecast._tcp.local.

Can you check if you get the same prints in Home Assistant 0.109?
If you don't can you try changing zeroconf version in Home Assistant 0.110 to 0.25.1?

@hmmbob
Copy link
Contributor

hmmbob commented May 21, 2020

Ok, restarting with 0.109.6, let's what that brings.

You'll have to tell me how to do the 2nd test :)

edit: first observation with 0.109 is that I already see a lot of cast and zeroconf debug messages while HA isn't still fully started yet, opposite to 0.110. Will post log shortly.
edit2: log of 109.6 run here. Contains nothing like failed, ánd all media players are available (well, 'off') from the moment I can check them in the HA frontend.

@emontnemery
Copy link
Contributor

emontnemery commented May 21, 2020

@hmmbob I think you can do:

pip3 install --upgrade --force-reinstall zeroconf==0.25.1
hass --skip-pip

@probot-home-assistant
Copy link

cast documentation
cast source
(message by IssueLinks)

@hmmbob
Copy link
Contributor

hmmbob commented May 22, 2020

@hmmbob I think you can do:

pip3 install --upgrade --force-reinstall zeroconf==0.25.1
hass --skip-pip

I can't reliably do this - in the docker I can't kill the running HA and when running hass --skip-pip it will run a 2nd instance. Installing zeroconf 0.25.1 is not a problem - getting HA in the docker to use it is.

@emontnemery
Copy link
Contributor

@hmmbob can you try to instead change zeroconf version in homeassistant/package_constraints.txt?

@hmmbob
Copy link
Contributor

hmmbob commented May 22, 2020

That worked. 0.110.0 with zeroconf 0.25.1 does not have this problem. Logs here: 110.0.zeroconf_0.25.1.log

Even though the log says Attempting install of zeroconf==0.26.1, i verified that 0.25.1 is installed with pip list | grep zeroconf

@rickh18
Copy link

rickh18 commented May 22, 2020

@emontnemery, I have the same setup and the same issue as described above. I set zeroconf to 0.25.1 in the docker container, installing it manually and changing the package constraint, otherwise HA will install 0.26.1 on startup. Now running with 0.25.1 I see the same pattern in the logging
[pychromecast.discovery] add_service failed to add _googlecast._tcp.local.,
However, I also see some success messages:
[homeassistant.components.cast.discovery] Discovered chromecast ChromecastInfo(host='192.168.2.212', port=8009, service='Google-Nest-Hub-XXX-1._googlecast._tcp.local.', uuid='XXX', model_name='Google Nest Hub', friendly_name='Bedroom display'))

Installed yesterday, one device status stayed connected, others lost connection after a while:
image

So it is better with 0.25.1, but not perfect. Also tried the dev build. Same issue.

@emontnemery
Copy link
Contributor

@hmmbob Nice! Can you try also with zeroconf 0.26.0?

@rickh18
Copy link

rickh18 commented May 22, 2020

@rickh18 In your case, does everything work with HA 0.109?

Tried 0.109.6, Seems to be the same behaviour as with 0.110.1 and zeroconf 0.25.1. Still seeing:
add_service failed to add _googlecast._tcp.local.,

So it looks to me these two setups show the same behaviour.

I just changed the mDNS setup with avahi-daemon on the host machine just before updating from 0.109.6 to 0.110.1 and therefore have no reference to a stable working setup.

edit: 0.109.6 with zeroconf 0.26.1 Breaks as well

@hmmbob
Copy link
Contributor

hmmbob commented May 22, 2020

@hmmbob Nice! Can you try also with zeroconf 0.26.0?

0.26.0 has the issue too - none of the devices show up. Logs here: 110.0.zeroconf_0.26.0.log

@emontnemery
Copy link
Contributor

emontnemery commented May 22, 2020

Could be related to #35832

There are no exceptions in the log though, can that bug be triggered silently?

Edit: #35832 causes UDP broadcasts to not be sent as you explain in the fix, donor would certainly explain this issue..

This call is failing in logs from @hmmbob https://github.com/home-assistant-libs/pychromecast/blob/c95db5b49ab0a9824f50a4ca59d583134772c206/pychromecast/discovery.py#L52

0.26.0 includes python-zeroconf/python-zeroconf#239, could it break or change the behaviour of get_service?

@hmmbob
Copy link
Contributor

hmmbob commented May 22, 2020

zeroconf 0.26.2 did not fix this issue for me (we probably weren't aiming for a fix here - I just wanted to test). Logs look similar - won't be uploading them unless really needed.

@emontnemery
Copy link
Contributor

emontnemery commented May 22, 2020

@hmmbob Would you mind testing again with zeroconf 0.25.1 and 0.26.0, and in both cases remove these lines from zeroconf/__init__py:

if log.level == logging.NOTSET:
    log.setLevel(logging.WARN)

This will dump all data sent and received by zeroconf, hopefully it can shed some light on what's going on.

Note: There's confusingly a stale zeroconf.py installed directly under site_packages which is not the right one.

@emontnemery
Copy link
Contributor

@hmmbob, @rickh18 if you could try testing with additional logs as suggested here: #35922 (comment) that would be highly appreciated
@rickh18 maybe I misunderstood you, is zeroconf 0.25.1 not resolving the problem for you?

@hmmbob
Copy link
Contributor

hmmbob commented May 24, 2020

Will definitely do so, but haven't found time yet ;)
I'm expecting to have some time avail later today.

@shanep2300
Copy link

shanep2300 commented May 24, 2020

Running HassOS on VirtualBox (not using Docker) and they become unavailable on a shutdown as I have my PC go to sleep from 2-7am every night. The only way to get them to be found is by removing the integration and the devices, restart HA, then reinstall the integration.

What do I need to do for my setup to help you guys out in getting more logs? This same issue is also happening with myq (garage) integration.

@hmmbob
Copy link
Contributor

hmmbob commented May 24, 2020

@emontnemery tests done. Logs:

110-25.1-zeroconf_debug.log
110-26.1-zeroconf_debug.log

Might be helpful in debugging: in the 0.26.1 run 1 device got connected - it's called "studeerkamer". All other cast devices did not get connected (even though i see their messages passing by in the logs)

@emontnemery
Copy link
Contributor

@hmmbob Awesome!
However, the first line in https://www.hmmbob.nl/110-25.1-zeroconf_debug.log is:
2020-05-24 16:36:35 INFO (SyncWorker_8) [homeassistant.util.package] Attempting install of zeroconf==0.26.1

Can you double check that the logs are the right ones?

@hmmbob
Copy link
Contributor

hmmbob commented May 24, 2020

Yeah, it always prints that but I verified each run with pip list | grep zeroconf. It is 0.25.1 in this run.

I used the package_constraints.txt trick from above.

@emontnemery I just digged through both logs as well, and in the 25.1 one I see "connected" printed for all my devices: 192.168.88.11, .17, .13, .12, .16, .14 - in that order.
Fun side fact: even though it is normal for .15 to be missing - (my Android TV never shows when turned off), I do see it in the zeroconf ligs (TPM191E).

The 26.1 log just prints "connected" for one device (192.168.88.12), even though all IPs are being discovered once in the logs - it seems no-one ever bothers connecting to it.

@emontnemery
Copy link
Contributor

emontnemery commented May 24, 2020

@hmmbob thanks for confirming.
As you say, all chromecasts are discovered in both logs.
The difference is that the call to zconf.get_service_info(typ, name) fails
In the 0.26.1 log, zeroconf repeatedly sends queries until pychromecast gives up.
In the 0.25.1 log, it succeeds immediately.

From the log it seems like there are replies to the queries, but the incoming messages are not printed in a very helpful way.
python-zeroconf/python-zeroconf#254 attempts to improve the readability.
If you have time, can you collect logs again with python-zeroconf/python-zeroconf#254 + the previous change to enable logs, again with both 0.25.1 and 0.26.1?

zeroconf 26.0 added python-zeroconf/python-zeroconf#239, this is highly likely to be a side effect of that.

@hmmbob
Copy link
Contributor

hmmbob commented May 24, 2020

I'll give it a run tomorrow!

@jstasiak
Copy link

@hmmbob Would you mind testing again with zeroconf 0.25.1 and 0.26.0, and in both cases remove these lines from zeroconf/__init__py:

if log.level == logging.NOTSET:
    log.setLevel(logging.WARN)

FWIW this conditional setLevel call is there specifically so that you can configure zeroconf's logging level from the outside, in the central place where you configure all other logging-related things, without having to patch zeroconf.

@emontnemery
Copy link
Contributor

@jstasiak Yes, but it's not compatible with how homeassistant filters logs.
There's a change here which does it without patching zeroconf: #36002

@jstasiak
Copy link

Ah, that's fair, I didn't know about this.

@bdraco
Copy link
Member

bdraco commented May 25, 2020

@emontnemery Is it possible that new ones are coming in via update_service instead of add_service because they are in the cache already before the listener sees them?

@emontnemery
Copy link
Contributor

@bdraco Yeah that's one theory to be tested: python-zeroconf/python-zeroconf#255 (comment)

By the way, with the singleton zeroconf changes in 0.111, are service browsers also shared or only the main zeroconf instance?

@bdraco
Copy link
Member

bdraco commented May 25, 2020

By the way, with the singleton zeroconf changes in 0.111, are service browsers also shared or only the main zeroconf instance?

Browsers are not shared. Only the main instance.

@rickh18
Copy link

rickh18 commented May 25, 2020

@hmmbob Would you mind testing again with zeroconf 0.25.1 and 0.26.0, and in both cases remove these lines from zeroconf/__init__py:

if log.level == logging.NOTSET:
    log.setLevel(logging.WARN)

This will dump all data sent and received by zeroconf, hopefully it can shed some light on what's going on.

Note: There's confusingly a stale zeroconf.py installed directly under site_packages which is not the right one.

I removed both lines. I ran 0.26.1 first, then 0.25.1. However, with logging enabled, 0.26.1 was suddenly working correctly (all chromecasts showed up. I ran 0.26.1 without logging and restarted it twice, both time it was not working. I then enabled logging again after which it was all working as expected. Only after restarting again, it was broken again.

HA 0.110.1 zeroconf 0.26.1 Working (Why?):
https://gist.github.com/rickh18/482dc94996d26fa69e5720ad388744d9

HA 0.110.1 zeroconf 0.25.1:
https://gist.github.com/rickh18/69ec23adacd11b9878bb29b19215bdaf

HA 0.110.1 zeroconf 0.26.1 Broken
https://gist.github.com/rickh18/c420c57fddd18b6ecb015f06600d3252

Seems to me like some kind of timing issue?

@bdraco
Copy link
Member

bdraco commented May 25, 2020

Seems like there is a race condition going on here. I'm thinking it has something to do with it being in the cache before the listener sees it.

@peternijssen
Copy link
Contributor

peternijssen commented May 25, 2020

Just wanted to add that I am experiencing the same issue since the update to HA 0.110.0. My 2 chromecasts and google home mini are no longer in HA. As opposed to others, I use the PyPi/venv way of installing HA rather than Docker. Unless I experience a different problem, the problem itself is not Docker related.

Update: Pulling the plug from the chromecast and google home mini and plugging them back in don't make them appear either in HA.

Update 2: I've tried

pip3 install --upgrade --force-reinstall zeroconf==0.25.1
hass --skip-pip

On my local development version of HA. The devices still do not appear, so I guess my problem is different then the problem described here :(

Update 3: Restarted a single router. Problem solved. -> add curse words here <-
Sorry for hijacking this issue :(

@emontnemery
Copy link
Contributor

emontnemery commented May 25, 2020

Two corrections which together should fix this:

@hmmbob has been very patient with debugging and testing, it would be really appreciated if someone else could test after applying these changes

@jstasiak
Copy link

On the update_service front – we probably should've started throwing some warnings in case of missing update_service methods at some point and then start calling them unconditionally in a later release. I guess it's finally time for those warnings.

PS. I can testify to the dedication and patience of everyone involved.

@emontnemery
Copy link
Contributor

emontnemery commented May 25, 2020

@jstasiak I don't understand how you want to change update_service can you explain a bit more about the warnings?
Edit: I found the PR, agreed this is a good idea and it would have meant update_service was implemented in pychromecast :)

@jstasiak
Copy link

Yeah, sorry, should've said explicitly by "we" I meant "zeroconf". Warn in case of missing listener methods as you already found out. :) (python-zeroconf/python-zeroconf#259 for others reading this thread)

@dvbavel
Copy link

dvbavel commented May 26, 2020

This all sounds to familiar, seeing the exact same in my logs since 0.110 and casting is close to impossible. My challenge is just I'm using Supervised Hass, how could I get zeroconf 0.25.1 in too that one? Is there some hidden trick I didnt find yet? I prefer to not ending up with building my own containers again. Thanks in advance!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.