search

hass-emulated-hue / core

Hue Emulation for Home Assistant
Apache License 2.0
320 stars 55 forks source link

HTTP(s) webserver not starting #311

Open fjgalesloot opened 2 years ago

fjgalesloot commented 2 years ago

I'm runing hass-emulated-hue in a standalone docker (not as add-on). HUE Bridge cannot be found on the network. Also port 80 or 443 or not responding on the IP of the docker container.

Steps to Reproduce

Start the docker image:

docker run --name=hass-emulated-hue -hostname=hass-emulated-hue -e TZ=Europe/Amsterdam -e \
 HASS_URL=https://homeassistant.example.com -e HASS_TOKEN=*** -e VERBOSE=true --network lan-static --ip x.x.x.x \  -v hass-emulated-hue-config:/config/.emulated-hue ghcr.io/hass-emulated-hue/core:latest

Expected behavior

HUE Bridge is discoverable on the network. Also ports 80 and/or 443 should at least make a TCP connection. While browsing other issues, I noticed that the logs should contain lines like these:

emulated_hue.api -- Started HTTP webserver on port 80
emulated_hue.api -- Started HTTPS webserver on port 443

but those are not in my logs.

Logs

Output from docker container:

[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 00-set-vars.sh: executing...
[21:31:30] INFO: Starting Emulated Hue...
[cont-init.d] 00-set-vars.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
2022-06-08 21:31:30,501 DEBUG emulated_hue.utils -- Loading /root/.emulated_hue/emulated_hue.json failed: [Errno 2] No such file or directory: '/root/.emulated_hue/emulated_hue.json'
2022-06-08 21:31:30,507 INFO  emulated_hue.config -- Auto detected listen IP address is x.x.x.x
2022-06-08 21:31:30,519 DEBUG getmac -- Raw MAC found: None
2022-06-08 21:31:30,522 DEBUG getmac -- Raw MAC found: 00:50:56:ba:6b:8a

2022-06-08 21:31:30,525 DEBUG aiorun -- Entering run()
2022-06-08 21:31:30,537 DEBUG aiorun -- Creating default executor
2022-06-08 21:31:30,561 INFO  hass_client -- Connected to Home Assistant wss (version 2022.6.4)

Also I see a log entry in Home Assistant when the container starts:

[140174100621440] Client unable to keep up with pending messages. Stayed over 512 for 5 seconds

Hardware Info:

alexyao2015 commented 2 years ago

That's odd. Is this still happening? It seems like it's getting stuck when communicating to HA, but not sure exactly what the issue is.

fjgalesloot commented 2 years ago

Yes this is still happening with the docker image I pulled today:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 00-set-vars.sh: executing...
[09:58:40] INFO: Starting Emulated Hue...
[cont-init.d] 00-set-vars.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
2022-08-03 09:58:41,403 DEBUG emulated_hue.utils -- Loading /root/.emulated_hue/emulated_hue.json failed: [Errno 2] No such file or directory: '/root/.emulated_hue/emulated_hue.json'
2022-08-03 09:58:41,408 INFO  emulated_hue.config -- Auto detected listen IP address is x.x.x.x
2022-08-03 09:58:41,417 DEBUG getmac -- Raw MAC found: None
2022-08-03 09:58:41,417 DEBUG getmac -- Raw MAC found: 00:50:56:ba:02:6c

2022-08-03 09:58:41,419 DEBUG aiorun -- Entering run()
2022-08-03 09:58:41,433 DEBUG aiorun -- Creating default executor
2022-08-03 09:58:41,457 INFO  hass_client -- Connected to Home Assistant wss (version 2022.7.7)

with a similar message in de Home Assistant log:

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/http.py:130
Integration: Home Assistant WebSocket API ([documentation](https://www.home-assistant.io/integrations/websocket_api), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+websocket_api%22))
First occurred: 10:01:18 (1 occurrences)
Last logged: 10:01:18

[139803185080992] Client unable to keep up with pending messages. Stayed over 512 for 5 seconds
meden commented 1 year ago

I have the same problem: emulated_hue is not discovered by my Philips TV. The log from emulated-hue appears to be identical to the one posted above. I'm running emulated_hue as add-on in Home Assistant Supervised on Debian 11.

I just started with Home Assistant, so I may be wrong, but I noticed that the emulated_hue container does not expose any port: may it somehow relative to the inability to contact the hub?

image

alexyao2015 commented 1 year ago

@meden The image uses host networking which allows direct access to host ports. You will therefore not see any port mappings. The ports uses can be configured in the config options.

@fjgalesloot I'm not entirely sure what could be happening here. Can you list the steps that you took to reproduce this from a clean home assistant install? I am unable to reproduce this.

meden commented 1 year ago

@alexyao2015, in my case the installation was a plain install, following normal steps.

Anyway, this issue happens with the stable version of emulated-hue. The dev version is working properly (well, entertainment mode does not work as expected, but that's another story).

Possibly, having a different version number for the dev version (e.g. some snapshot/alpha/beta/dev qualifier) would have helped in properly triaging this issue.

Thanks for your work!

fjgalesloot commented 1 year ago

@alexyao2015, in my case the installation was a plain install, following normal steps.

Anyway, this issue happens with the stable version of emulated-hue. The dev version is working properly (well, entertainment mode does not work as expected, but that's another story).

Did you pull a tagged docker image from the repository that works for you? Can you share which one? I'm still having the same error with the :dev tag.

fjgalesloot commented 1 year ago

I just shelled into the docker container (image :dev). Running netstat I see:

root@ostname=hass-emulated-hue:/# netstat -n
Active Internet connections (w/o servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State
tcp   407808      0 x.x.x.95:56996          x.x.x.37:443            ESTABLISHED

Where x.x.x.37 is the IP address of Home Assistant. It seems the application is nog reading the results, as the receive queue is having data.

Maybe this helps in pinpointing the issue?

fjgalesloot commented 1 year ago

I think this has something to do with my docker host. I'm running Vmware Integrated Containers. Running the :master image on my Docker Desktop runs just fine. Running the same image on my vmware setup, I receive the error s6-overlay-suexec: fatal: can only run as pid 1.

meden commented 1 year ago

I installed it as add-on in Home Assistant Supervised. The version from stable repository is not working, while the version from the dev one is (although both show the same version number; in Maven world the latter would have an higher number with a SNAPSHOT qualifier 😁).

alexyao2015 commented 1 year ago

This message here is key s6-overlay-suexec: fatal: can only run as pid 1.. This occurs because something is overriding the default entrypoint. Oftentimes there is some setting to disable this behavior termed init which you'll need to find.

github-actions[bot] commented 1 year ago

This issue has been marked as stale due to no activity and will be closed in 7 days.

meden commented 1 year ago

The bug is still present in 0.2.13, but Dev container works.

Logs from 0.2.13 release:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 00-set-vars.sh: executing... 
[cont-init.d] 00-set-vars.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
[09:06:02] INFO: Starting Emulated Hue...
2023-01-22 09:06:04,913 INFO  emulated_hue.config -- Auto detected listen IP address is 192.168.1.12
2023-01-22 09:06:05,014 DEBUG getmac -- Raw MAC found: None
2023-01-22 09:06:05,018 DEBUG getmac -- Raw MAC found: 6e:64:72:6f:69:64
2023-01-22 09:06:05,020 DEBUG aiorun -- Entering run()
2023-01-22 09:06:05,048 DEBUG aiorun -- Creating default executor
2023-01-22 09:06:05,094 INFO  hass_client -- Connected to Home Assistant ws (version 2023.1.6)

Logs from updated Dev container:

cont-init: info: /etc/cont-init.d/00-set-vars.sh exited 0
cont-init: info: running /etc/cont-init.d/20-install.sh
[09:24:32] INFO: Installing Emulated Hue version 'master' (https://github.com/hass-emulated-hue/core/archive/master.tar.gz)...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0

100 59733    0 59733    0     0  63817      0 --:--:-- --:--:-- --:--:-- 63817
core-master/.devcontainer/
core-master/.devcontainer/Dockerfile
core-master/.devcontainer/devcontainer.json
core-master/.devcontainer/docker-compose-pycharm.yml
core-master/.devcontainer/docker-compose-vscode.yml
core-master/.devcontainer/requirements-vscode.txt
core-master/.github/
core-master/.github/ISSUE_TEMPLATE/
core-master/.github/ISSUE_TEMPLATE/bug-report.md
core-master/.github/ISSUE_TEMPLATE/config.yml
core-master/.github/ISSUE_TEMPLATE/feature_request.md
core-master/.github/dependabot.yml
core-master/.github/release-drafter.yml
core-master/.github/workflows/
core-master/.github/workflows/docker-build.yaml
core-master/.github/workflows/release-drafter.yml
core-master/.github/workflows/stale.yml
core-master/.github/workflows/test.yml
core-master/.github/workflows/update-swversion.yml
core-master/.gitignore
core-master/.launchconfigs/
core-master/.launchconfigs/EXAMPLE-hass_emulated_hue.code-workspace
core-master/.launchconfigs/Launch emulated_hue.run.xml.DELETE-ME
core-master/.pre-commit-config.yaml
core-master/.vscode/
core-master/.vscode/settings.json
core-master/LICENSE
core-master/Notes.md
core-master/README.md
core-master/docker-compose.example.yml
core-master/docker/
core-master/docker/Dockerfile
core-master/docker/publish.py
core-master/docker/rootfs-dev/
core-master/docker/rootfs-dev/etc/
core-master/docker/rootfs-dev/etc/cont-init.d/
core-master/docker/rootfs-dev/etc/cont-init.d/20-install.sh
core-master/docker/rootfs/
core-master/docker/rootfs/etc/
core-master/docker/rootfs/etc/cont-init.d/
core-master/docker/rootfs/etc/cont-init.d/00-set-vars.sh
core-master/docker/rootfs/etc/services.d/
core-master/docker/rootfs/etc/services.d/emulated-hue/
core-master/docker/rootfs/etc/services.d/emulated-hue/finish
core-master/docker/rootfs/etc/services.d/emulated-hue/run
core-master/emulated_hue/
core-master/emulated_hue/.vscode/
core-master/emulated_hue/.vscode/.ropeproject/
core-master/emulated_hue/.vscode/.ropeproject/config.py
core-master/emulated_hue/__init__.py
core-master/emulated_hue/__main__.py
core-master/emulated_hue/apiv1.py
core-master/emulated_hue/const.py
core-master/emulated_hue/controllers/
core-master/emulated_hue/controllers/__init__.py
core-master/emulated_hue/controllers/config.py
core-master/emulated_hue/controllers/devices.py
core-master/emulated_hue/controllers/entertainment.py
core-master/emulated_hue/controllers/homeassistant.py
core-master/emulated_hue/controllers/models.py
core-master/emulated_hue/controllers/scheduler.py
core-master/emulated_hue/definitions.json
core-master/emulated_hue/discovery.py
core-master/emulated_hue/ssl_cert.py
core-master/emulated_hue/utils.py
core-master/emulated_hue/web.py
core-master/emulated_hue/web_static/
core-master/emulated_hue/web_static/debug/
core-master/emulated_hue/web_static/debug/clip.css
core-master/emulated_hue/web_static/debug/clip.html
core-master/emulated_hue/web_static/debug/clip.js
core-master/emulated_hue/web_static/description.xml
core-master/emulated_hue/web_static/favicon.ico
core-master/emulated_hue/web_static/hue_logo_0.png
core-master/pylintrc
core-master/requirements.txt
core-master/setup.cfg
[09:24:33] INFO: Installed successfully!
cont-init: info: /etc/cont-init.d/20-install.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun emulated-hue (no readiness notification)
s6-rc: info: service legacy-services successfully started
[09:24:34] INFO: Starting Emulated Hue...
2023-01-22 09:24:36,021 DEBUG aiorun -- Entering run()
2023-01-22 09:24:36,041 DEBUG aiorun -- Creating default executor
2023-01-22 09:24:36,049 INFO  emulated_hue.controllers.config -- Auto detected listen IP address is 192.168.1.12
2023-01-22 09:24:36,080 DEBUG getmac -- Raw MAC found: None
2023-01-22 09:24:36,083 DEBUG getmac -- Raw MAC found: 6e:64:72:6f:69:64
2023-01-22 09:24:36,121 INFO  hass_client -- Connected to Home Assistant ws (version 2023.1.6)
2023-01-22 09:24:36,277 INFO  emulated_hue.web -- Started HTTP webserver on port 80
2023-01-22 09:24:36,373 INFO  emulated_hue.web -- Started HTTPS webserver on port 443

Maybe some issue with the build?.

v6ak commented 1 year ago

I've tried to debug that by gdb. It seems that some await waits indefinitely.

# apt update && apt install -y gdb
… (wait for installing GDB)
# gdb python -p 71
…
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".
0x0000007fa59dedac in __GI_epoll_pwait (epfd=<optimized out>, 
    events=events@entry=0x7fc490de20, maxevents=maxevents@entry=1024, 
    timeout=timeout@entry=2000, set=set@entry=0x0)
    at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42
42  ../sysdeps/unix/sysv/linux/epoll_pwait.c: No such file or directory.
…

This looks like waiting for some async I/O. I'll look at backtrace:

(gdb) bt
#0  0x0000007fa59dedac in __GI_epoll_pwait (epfd=<optimized out>, 
    events=events@entry=0x7fc490de20, maxevents=maxevents@entry=1024, 
    timeout=timeout@entry=2000, set=set@entry=0x0)
    at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42
#1  0x0000007fa59def68 in epoll_wait (epfd=<optimized out>, 
    events=events@entry=0x7fc490de20, maxevents=maxevents@entry=1024, 
    timeout=timeout@entry=2000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:32
#2  0x0000007fa32bb994 in uv__io_poll (loop=loop@entry=0x5574604590, 
    timeout=<optimized out>) at src/unix/epoll.c:236
#3  0x0000007fa32adb64 in uv_run (loop=0x5574604590, 
    mode=mode@entry=UV_RUN_DEFAULT) at src/unix/core.c:389
#4  0x0000007fa3248778 in __pyx_f_6uvloop_4loop_4Loop___run (
    __pyx_v_self=0x5574669060, __pyx_v_mode=UV_RUN_DEFAULT) at uvloop/loop.c:15044
#5  0x0000007fa3250f70 in __pyx_f_6uvloop_4loop_4Loop__run (
    __pyx_v_self=0x5574669060, __pyx_v_mode=UV_RUN_DEFAULT) at uvloop/loop.c:15423
#6  0x0000007fa3219d6c in __pyx_pf_6uvloop_4loop_4Loop_24run_forever (
    __pyx_v_self=0x5574669060) at uvloop/loop.c:28118
…

OK, looks like run_forever (probably called from asyncio.run in __main__.py), i.e., it is waiting for some coroutine.

I've also tried to run py-bt, but the python:3.10-slim container doesn't have the python3.10-dbg package. (It has only python3.9-dbg package, which is from Debian.) Anyway, I probably wouldn't see much there, as it would probably show just running threads, not coroutines being awaited.

I've also tried to build the Docker image on aarch64, but I failed with rustup. Anyway, I probably wouldn't want to build Rust on Raspberry Pi…

v6ak commented 1 year ago

I've digged a bit deeper (and found a conclusion):

File emualted_hue/controllers/__init__.py: I've added debug print around relevant await:

    print('HAC: connect')
    await ctl.controller_hass.connect()
    print('HAC: connected')

I see this:

HAC: connect
2023-02-14 21:09:37,262 INFO  hass_client -- Connected to Home Assistant wss (version 2023.2.4)

To, it seems that HomeAssistantController.connect awaits indefinitely. This method is inherited from HomeAssistantClient. At the moment of the indefinite await, we are somewhere in https://github.com/hass-emulated-hue/python-hass-client/blob/0.1.5/hass_client/client.py#L288-L293 :

So, I've started sniffing the communication between HA and HEH:

ssh user@host 'sudo dumpcap -P -w - -i lo -f "tcp port 8123"' | qvm-run-vm @dispvm 'wireshark -k -i -'

client: {"type":"subscribe_events","id":1}
server: {"id":1,"type":"result","success":false,"error":{"code":"unauthorized","message":"Unauthorized"}}

Conclusion: At this point, I can probably conclude that HEH requires admin token. When it gets user token, it doesn't report the issue properly and hangs on startup.

alexyao2015 commented 1 year ago

Thanks for that! That probably explains why I was never able to reproduce this as there haven't been any sufficient reproduction steps thus far. I can make this more obvious by adding some more logging in the future regarding this.

meden commented 1 year ago

Thanks @v6ak for the deep digging! This explains why it does not work.

But have you (or @alexyao2015) any clue on why it works fine using the Dev container?

alexyao2015 commented 1 year ago

I have no clue. The dev version and the latest release should be identical as of last week. There's not much for me to go off here besides speculation.

Dr4g0nM4st3r commented 1 year ago

I'm also affected. Release Version dosnt/never worked (Was a fresh HA OS install inside a VM) but dev Container works without problems.

Dr4g0nM4st3r commented 1 year ago

I'm also affected. Release Version dosnt/never worked (Was a fresh HA OS install inside a VM) but dev Container works without problems.

I have found another cause. My HA was running the Unifi implementation, which generated about 18,000 entities. The websocket json request was about 10 MB, so probably the Hue emulation crashed due to the big response.