Core: Google cast broken in 0.109 in docker

Created on 29 Apr 2020  路  30Comments  路  Source: home-assistant/core

The problem

On updating from 0.107.7 to 0.109.0, all my Chromecasts (v1, v2, Ultra, Audio) show as unavailable with the restored: true attribute.

My Chromecasts are all on a different subnet to Home Assistant, but have worked perfectly with static IPs up until now. mDNS repeater is setup on my router and I am able to cast and work with my Chromecasts from a different subnet.

Environment

  • Home Assistant Core release with the issue: 0.109.0
  • Last working Home Assistant Core release (if known): 0.107.7 (0.108 may or may not work. I couldn't use that version due to an unrelated bug)
  • Operating environment (Home Assistant/Supervised/Docker/venv): Docker
  • Integration causing this issue: Google Cast
  • Link to integration documentation on our website: https://www.home-assistant.io/integrations/cast/

Problem-relevant configuration.yaml

# Chromecast
cast:
  media_player:
    - host: 192.168.5.3
    - host: 192.168.5.9
    - host: 192.168.5.27
    - host: 192.168.5.36
    - host: 192.168.5.45
    - host: 192.168.5.54
    - host: 192.168.5.63
    - host: 192.168.5.72
    - host: 192.168.5.81
    - host: 192.168.5.99

Traceback/Error logs


I enabled debug logging:

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

And these are the only relevant logs:

2020-04-29 13:25:00 INFO (SyncWorker_61) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
2020-04-29 13:25:01 INFO (SyncWorker_81) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2020-04-29 13:25:01 INFO (MainThread) [homeassistant.setup] Setting up media_player
2020-04-29 13:25:01 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds.
2020-04-29 13:24:58 INFO (SyncWorker_0) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2020-04-29 13:25:48 INFO (MainThread) [homeassistant.setup] Setting up cast
2020-04-29 13:25:48 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2020-04-29 13:25:49 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2020-04-29 13:25:49 DEBUG (SyncWorker_100) [homeassistant.components.cast.discovery] Starting internal pychromecast discovery.

Additional information

I looked through the changelogs and the change that looks like it could be causing this is #33922.

cast

Most helpful comment

So to conclude:

  • The documentation on setting up HA in Docker mentions --net=host / network_mode: host, and if this is followed mDNS discovery works.
  • An alternative is to setup avahi-daemon reflector on the host.

A PR mentioning docker as well as a summary of setting up avahi on the host for here https://www.home-assistant.io/integrations/discovery/#troubleshooting or here https://www.home-assistant.io/integrations/cast/#cast-devices-and-home-assistant-on-different-subnets would be very welcome.

All 30 comments

@emontnemery This is a continuation from #34631.

cast documentation
cast source
(message by IssueLinks)

All my cast devices suddenly show "unavailable" too. They are setup with IPs in configuration.yaml, but removing this config and trying to add through "integrations" does raise "no cast devices found on network".

I'm running Docker on a Pi3B. The Pi is in the same subnet as the cast devices though. No errors showing in the logs, neither at debug nor warning settings. I have to say that zeroconf never worked for me while on Docker, but at least the manual IP specification did the trick.

Key | value
-- | --
arch | armv7l
dev | false
docker | true
hassio | false
os_name | Linux
os_version | 4.19.97-v7+
python_version | 3.7.7
timezone | Europe/Amsterdam
version | 0.109.0
virtualenv | false

#configuration.yaml:
cast:
  media_player:
    - host: 192.168.xx.xxx
    - host: 192.168.xx.xxx
    - host: 192.168.xx.xxx
...

Hey there @emontnemery, mind taking a look at this issue as its been labeled with a integration (cast) you are listed as a codeowner for? Thanks!
(message by CodeOwnersMention)

@hmmbob Do you have any custom components enabled? Problems have been reported due to both plex_assistant and spotcast pinning an old version of pychromecast.

@kmlucy You're probably right that this is due to #33922, HA now depends on mDNS discovery even if the IPs of the casts are specified.

The reason for this breaking change was to fix bugs related to casts being unreachable when HA was starting and to simplify the code.

Note that Chromecast and client on different subnets is not a usecase which is supported by Google (mDNS does not support it, and chromecast blocks requests originating from different subnets than its own)

You need to setup mDNS forwarding, please see the docs here: https://www.home-assistant.io/integrations/cast/#cast-devices-and-home-assistant-on-different-subnets
In avahi the option is called "enable-reflector", there's also a specialized tool called "bonjour-reflector".

@emontnemery I'm using neither of them, nor any other custom component that should have to do anything with cast (assuming that Hacs isn't doing anything with cast)

@emontnemery I have mDNS forwarding setup in my router. I added that to the topic when I copied that over, but it probably got missed since most is the same.

@hmmbob OK, can you please open a separate issue, let's keep this about google cast on different subnets.

FYI the only custom components I have are HACS and Browser Mod, neither of which pin any version of pychromecast.

Oh, I missed that you have mDNS forwarding enabled, sorry about that.

You didn't attach a full log, so can you confirm this is present:
Setup of domain zeroconf took 0.1 seconds.

Please add also debug logging of homeassistant.components.zeroconf

This is something that regressed also a long time ago (3 years ago), and it seems I have made a fix for it back then. Not sure if that fix is still in the code.

https://github.com/home-assistant/core/pull/4470

I already had zeroconf debug logging enabled (see the first post for my debug settings). I do not have any further messages about zeroconf. The logs are picked are based on grep -i 'cast\|media\|zero\|debug'.

@michaelarnauts Thanks for the pointer. The code is since rewritten to depend on working mDNS as mentioned here https://github.com/home-assistant/core/issues/34874#issuecomment-621394931

@kmlucy You mention logging of zeroconf but not homeassistant.components.zeroconf in the issue description.

Anyhow, from the log it seems homeassistant.components.zeroconf is not being set up.

Have you done something to disable zeroconf, maybe removed default_config: from configuration.yaml as mentioned here: https://www.home-assistant.io/integrations/zeroconf/#configuration ?

@hmmbob Since this issue no longer seems directly related to mDNS across subnets, I think it's OK to handle your issue here as well :)

Would you mind enabling logging and sharing a log?

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

I copied the logger section from another cast issue thread; I'll add homeassistant.components.zeroconf debug logs.

I do not have default_config in my configuration, nor did I re-add zeroconf.

Here are updated logs with zeroconf enabled and updating logging:

2020-04-29 15:20:49 INFO (SyncWorker_12) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2020-04-29 15:20:50 INFO (SyncWorker_37) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
2020-04-29 15:20:52 INFO (SyncWorker_85) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2020-04-29 15:20:52 INFO (MainThread) [homeassistant.setup] Setting up zeroconf
2020-04-29 15:20:52 INFO (MainThread) [homeassistant.setup] Setting up media_player
2020-04-29 15:20:52 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds.
2020-04-29 15:20:52 INFO (MainThread) [homeassistant.setup] Setup of domain zeroconf took 0.1 seconds.
2020-04-29 15:21:37 INFO (MainThread) [homeassistant.setup] Setting up cast
2020-04-29 15:21:37 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2020-04-29 15:21:38 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2020-04-29 15:21:38 DEBUG (SyncWorker_112) [homeassistant.components.cast.discovery] Starting internal pychromecast discovery.
2020-04-29 15:21:38 INFO (SyncWorker_8) [homeassistant.components.zeroconf] Starting Zeroconf broadcast

There has been no change to the behavior of the Chromecasts with this change.

@kmlucy thanks for the patience.
We can conclude so far that mDNS is not working.

I'm not familiar with Docker, but it seems you need to add the option --net=host or network_mode: host for mDNS to work from within a container, do you have that option enabled?

You could also try to run this script with option --show-debug both in the host and from within the container. The script needs pychromecast + pythonzeroconf.

@hmmbob Since this issue no longer seems directly related to mDNS across subnets, I think it's OK to handle your issue here as well :)

Would you mind enabling logging and sharing a log?

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

Here you go:

2020-04-29 21:31:11 INFO (SyncWorker_19) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2020-04-29 21:31:19 INFO (MainThread) [homeassistant.setup] Setting up ssdp
2020-04-29 21:31:19 INFO (MainThread) [homeassistant.setup] Setup of domain ssdp took 0.0 seconds.
2020-04-29 21:31:22 INFO (MainThread) [homeassistant.components.emulated_hue] Listen IP address not specified, auto-detected address is 172.18.0.7
2020-04-29 21:31:22 INFO (MainThread) [homeassistant.setup] Setting up config
2020-04-29 21:31:24 INFO (MainThread) [homeassistant.setup] Setting up cast
2020-04-29 21:31:24 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2020-04-29 21:31:24 INFO (MainThread) [homeassistant.setup] Setup of domain config took 1.8 seconds.
2020-04-29 21:31:25 INFO (MainThread) [homeassistant.setup] Setting up zeroconf
2020-04-29 21:31:25 INFO (MainThread) [homeassistant.setup] Setup of domain zeroconf took 0.4 seconds.
2020-04-29 21:31:26 INFO (MainThread) [homeassistant.setup] Setting up media_player
2020-04-29 21:31:26 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds.
2020-04-29 21:31:26 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2020-04-29 21:31:26 DEBUG (SyncWorker_15) [homeassistant.components.cast.discovery] Starting internal pychromecast discovery.
2020-04-29 21:31:30 INFO (MainThread) [homeassistant.setup] Setting up default_config
2020-04-29 21:31:30 INFO (SyncWorker_0) [homeassistant.loader] Loaded stream from homeassistant.components.stream
2020-04-29 21:31:30 INFO (MainThread) [homeassistant.setup] Setting up stream
2020-04-29 21:31:30 INFO (MainThread) [homeassistant.setup] Setup of domain stream took 0.1 seconds.
2020-04-29 21:31:30 INFO (MainThread) [homeassistant.setup] Setup of domain default_config took 0.5 seconds.
2020-04-29 21:31:37 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 28.75s
2020-04-29 21:31:37 INFO (MainThread) [homeassistant.core] Starting Home Assistant
2020-04-29 21:31:37 INFO (SyncWorker_1) [homeassistant.components.zeroconf] Starting Zeroconf broadcast

As said, I am also running on docker. This is the relevant docker-compose:

  homeassistant:
    image: homeassistant/home-assistant:0.109.0
    container_name: homeassistant
    restart: unless-stopped
    depends_on:
      - traefik
      - mqtt
      - zigbee2mqtt
    labels:
      - traefik.backend=[[redacted]]
      - traefik.frontend.rule=Host:[[redacted]]
      - traefik.frontend.entrypoint=https
      - traefik.docker.network=traefik
      - traefik.enable=true
      - traefik.port=8123
    networks:
      - traefik
    ports:
      - 8300:8300
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - /home/pi/docker/homeassistant:/config
    privileged: true

I see your notice about net: host, but with priviliged: true that is implied, I was told.

@hmmbob I'm not familiar with docker, but it's mentioned here that ports: is not compatible with network_mode: host : https://docs.docker.com/compose/compose-file/#ports

Can you try to configure the container more similar to the official documentation https://www.home-assistant.io/docs/installation/docker/, as well as the pychromecast script both on the host and from within the container?

@hmmbob I'm not familiar with docker, but it's mentioned here that ports: is not compatible with network_mode: host : https://docs.docker.com/compose/compose-file/#ports

Can you try to configure the container more similar to the official documentation https://www.home-assistant.io/docs/installation/docker/, as well as the pychromecast script both on the host and from within the container?

I changed the network_mode and I already see successful cast messages in the logs. It is still starting up though. Will come back soon - seems solved.

edit: works with network_mode: host, but it breaks my traefik setup. Let me work that.

I wasn't happy about having to use host networking with the container, both for security reasons, and because I use separate Docker networks for postgres and other services to keep them segmented from my main network.

I found this post which works perfectly. With the avahi-daemon reflector running on the host, Home Assistant immediately picked up the Chromecasts.

So to conclude:

  • The documentation on setting up HA in Docker mentions --net=host / network_mode: host, and if this is followed mDNS discovery works.
  • An alternative is to setup avahi-daemon reflector on the host.

A PR mentioning docker as well as a summary of setting up avahi on the host for here https://www.home-assistant.io/integrations/discovery/#troubleshooting or here https://www.home-assistant.io/integrations/cast/#cast-devices-and-home-assistant-on-different-subnets would be very welcome.

I'll try the avahi reflector later today and if it works, I'll create a PR with documentation.

@emontnemery I'm still trying to understand what has caused this issue (even though we identified the solution being docker host-networking) as it did work correctly until 0.108.9. Would you say it is related to this change?

https://github.com/home-assistant/core/pull/34082

I wasn't happy about having to use host networking with the container, both for security reasons, and because I use separate Docker networks for postgres and other services to keep them segmented from my main network.

I found this post which works perfectly. With the avahi-daemon reflector running on the host, Home Assistant immediately picked up the Chromecasts.

Same result here - thanks for the pointer. I'll create a PR to update the docs.

I managed to do it without --net=host. You just need to install avahi-daemon on the docker host with enable-reflector=yes

@hmmbob Thanks for putting the PR for the docs together.

@hmmbob
Not relying on mDNS had the following issues:

  • Broken behavior if a cast device added by its IP was not available when HA started
  • Multiple code paths for adding cast devices
  • Google has made changes to the local API recently which meant mDNS is needed to get device information such as model name

The two first issues were more about code complexity and maintainability, the third one was the last straw.

PR for the documentation change was rejected, as this is describing a way of running HA that is not supported by the HA team.

I got this as well running in a vm on unraid. For me (as mentioned above) removing plex_assistant solved the problem

Was this page helpful?
0 / 5 - 0 ratings