search

LukasGrebe / ha-addons

Addons for Home Assistant
GNU General Public License v3.0
43 stars 49 forks source link

Make script wait for MQTT to be up #104

Closed dulek closed 10 months ago

dulek commented 10 months ago

Often times when HA is restarted, the ebusd addon starts before the MQTT addon and obviously fails because MQTT is not yet up. This commit allows some tolerance here by waiting up to 60 seconds for MQTT TCP connectivity to be possible. It'll try starting ebusd even if this check fails.

tjorim commented 10 months ago

Can you provide some logs that indicate this is an issue? Preferably both add-on and supervisor (which would show the start up order). This should not be an issue because of the add-on startup config.

dulek commented 10 months ago

The add-on logs are what you can expect them to be, I've lost the copy after add-on was restarted. I don't see anything in the supervisor logs, but will update here once this happens again (unfortunately it's happening fairly often). Thanks for help!

dulek commented 10 months ago

@tjorim: Alright, got this again.

Addon:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[20:54:53] ERROR: Got unexpected response from the API: Service not enabled
> ebusd --foreground --mqtthost= --mqttport= --mqttuser= --mqttpass= --scanconfig --mqttjson --configpath=/config/ebusd-configuration/latest/en --accesslevel=* --mqttint=/etc/ebusd/mqtt-hassio.cfg --mqttvar=filter-direction=r|u|^w --mqtttopic=ebusd --device=enh:192.168.0.227:9999 --log=all:notice
ebusd: invalid mqtthost
Try `ebusd --help' or `ebusd --usage' for more information.
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

MQTT:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
cont-init: info: running /etc/cont-init.d/mosquitto.sh
[20:54:32] INFO: Certificates found: SSL is available
cont-init: info: /etc/cont-init.d/mosquitto.sh exited 0
cont-init: info: running /etc/cont-init.d/nginx.sh
cont-init: info: /etc/cont-init.d/nginx.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 mosquitto (no readiness notification)
services-up: info: copying legacy longrun nginx (no readiness notification)
s6-rc: info: service legacy-services successfully started
[20:54:44] INFO: Starting NGINX for authentication handling...
[20:54:45] INFO: Starting mosquitto MQTT broker...
2024-01-16 20:54:45: Warning: Mosquitto should not be run as root/administrator.
2024-01-16 20:54:45: mosquitto version 2.0.18 starting
2024-01-16 20:54:45: Config loaded from /etc/mosquitto/mosquitto.conf.
2024-01-16 20:54:45: Loading plugin: /usr/share/mosquitto/go-auth.so
2024-01-16 20:54:45:  ├── Username/password checking enabled.
2024-01-16 20:54:45:  ├── TLS-PSK checking enabled.
2024-01-16 20:54:45:  └── Extended authentication not enabled.
2024-01-16 20:54:45: Opening ipv4 listen socket on port 1883.
2024-01-16 20:54:45: Opening ipv6 listen socket on port 1883.
2024-01-16 20:54:45: Opening websockets listen socket on port 1884.
2024-01-16 20:54:45: Opening ipv4 listen socket on port 8883.
2024-01-16 20:54:45: Opening ipv6 listen socket on port 8883.
2024-01-16 20:54:45: Opening websockets listen socket on port 8884.
2024-01-16 20:54:45: mosquitto version 2.0.18 running
2024-01-16 20:54:47: New connection from 127.0.0.1:51554 on port 1883.
2024-01-16 20:54:47: Client <unknown> disconnected due to protocol error.
[20:54:54] INFO: Successfully send discovery information to Home Assistant.
[20:54:58] INFO: Successfully send service information to the Supervisor.
2024-01-16 20:55:49: New connection from 172.30.32.1:60293 on port 1883.
2024-01-16 20:55:49: New client connected from 172.30.32.1:60293 as 6DdcTrldABNXp1k0Rn8XGa (p2, c1, k60, u'homeassistant').
2024-01-16 20:56:11: New connection from 172.30.33.3:53652 on port 1883.
2024-01-16 20:56:11: New client connected from 172.30.33.3:53652 as mqttjs_9fcd576e (p2, c1, k60, u'addons').

Supervisor:

24-01-16 20:54:14 INFO (MainThread) [supervisor.resolution.check] System checks complete
24-01-16 20:54:14 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
24-01-16 20:54:14 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-01-16 20:54:14 INFO (MainThread) [supervisor.jobs] 'ResolutionFixup.run_autofix' blocked from execution, system is not running - setup
24-01-16 20:54:14 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
24-01-16 20:54:14 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-01-16 20:54:14 INFO (MainThread) [__main__] Running Supervisor
24-01-16 20:54:14 INFO (MainThread) [supervisor.os.manager] Rauc: B - marked slot kernel.1 as good
24-01-16 20:54:14 INFO (MainThread) [supervisor.addons.manager] Phase 'initialize' starting 0 add-ons
24-01-16 20:54:14 INFO (MainThread) [supervisor.addons.manager] Phase 'system' starting 1 add-ons
24-01-16 20:54:14 INFO (SyncWorker_7) [supervisor.docker.manager] Cleaning addon_core_mosquitto application
24-01-16 20:54:21 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-mosquitto with version 6.4.0
24-01-16 20:54:26 INFO (MainThread) [supervisor.addons.manager] Phase 'services' starting 3 add-ons
24-01-16 20:54:26 WARNING (MainThread) [supervisor.docker.addon] Advanced SSH & Web Terminal running with disabled protected mode!
24-01-16 20:54:26 INFO (SyncWorker_2) [supervisor.docker.manager] Cleaning addon_a0d7b954_ssh application
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/LukasGrebe/ha-addons/ repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/zigbee2mqtt/hassio-zigbee2mqtt repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/GollumDom/addon-repository repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/sabeechen/hassio-google-drive-backup repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/esphome/home-assistant-addon repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/hassio-addons/repository repository
24-01-16 20:54:28 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/home-assistant/addons repository
24-01-16 20:54:30 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/ssh/aarch64 with version 17.0.3
24-01-16 20:54:30 INFO (SyncWorker_1) [supervisor.docker.manager] Cleaning addon_core_duckdns application
24-01-16 20:54:37 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-duckdns with version 1.15.0
24-01-16 20:54:37 INFO (SyncWorker_6) [supervisor.docker.manager] Cleaning addon_2ad9b828_ebusd application
24-01-16 20:54:47 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on ghcr.io/lukasgrebe/ha-addon-ebusd-aarch64 with version 23.2.3
24-01-16 20:54:51 INFO (MainThread) [supervisor.store] Loading add-ons from store: 86 all - 0 new - 0 remove
24-01-16 20:54:51 INFO (MainThread) [supervisor.store] Loading add-ons from store: 86 all - 0 new - 0 remove
24-01-16 20:54:57 INFO (MainThread) [supervisor.services.modules.mqtt] Set core_mosquitto as service provider for mqtt
24-01-16 20:55:22 INFO (MainThread) [supervisor.core] Skipping start of Home Assistant
24-01-16 20:55:22 INFO (MainThread) [supervisor.addons.manager] Phase 'application' starting 3 add-ons
24-01-16 20:55:22 INFO (SyncWorker_0) [supervisor.docker.manager] Cleaning addon_core_configurator application
24-01-16 20:55:26 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-configurator with version 5.7.0
24-01-16 20:55:26 INFO (SyncWorker_4) [supervisor.docker.manager] Cleaning addon_45df7312_zigbee2mqtt application
24-01-16 20:55:30 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on zigbee2mqtt/zigbee2mqtt-aarch64 with version 1.35.1-1
24-01-16 20:55:30 INFO (SyncWorker_2) [supervisor.docker.manager] Cleaning addon_cebe7a76_hassio_google_drive_backup application
24-01-16 20:55:34 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on ghcr.io/sabeechen/hassio-google-drive-backup-aarch64 with version 0.112.1
24-01-16 20:55:42 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /core/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /mounts access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /addons access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/69c33507/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/80830ebb/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/142e7aeb/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/e3bc5eaf/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/bd430c9a/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/189464ea/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/8687f784/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/6b2c4baa/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/2472ccb0/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/f846df57/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:42 INFO (MainThread) [supervisor.api.middleware.security] /backups/c800709e/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/d9e80ead/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/98e2f904/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/7d0ca915/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/3f819d37/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/ea86c7c7/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/74a65d79/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/3de99a47/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/5581bbfc/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/d3c348e2/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/6bbb22ad/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/37971517/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/50ef149d/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/80f478da/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/f411038c/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/a5295ce5/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/fd5ffaf0/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/207f0de5/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/1dfe7be7/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/46c4f9d5/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:43 INFO (MainThread) [supervisor.api.middleware.security] /backups/396262d4/info access from cebe7a76_hassio_google_drive_backup
24-01-16 20:55:57 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
24-01-16 20:55:57 INFO (MainThread) [supervisor.core] Supervisor is up and running
24-01-16 20:55:57 INFO (MainThread) [supervisor.host.info] Updating local host information
24-01-16 20:55:57 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state running
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.checks.base] Run check for security/core
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.checks.base] Run check for pwned/addon
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.checks.base] Run check for ipv4_connection_problem/system
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.checks.base] Run check for no_current_backup/system
24-01-16 20:55:57 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_failed/dns_server
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks/system
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.checks.base] Run check for free_space/system
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.checks.base] Run check for docker_config/system
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.checks.base] Run check for trust/supervisor
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_ipv6_error/dns_server
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.check] System checks complete
24-01-16 20:55:58 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state running
24-01-16 20:56:01 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-01-16 20:56:01 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state running
24-01-16 20:56:01 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
24-01-16 20:56:01 INFO (MainThread) [supervisor.host.services] Updating service information
24-01-16 20:56:01 INFO (MainThread) [supervisor.host.network] Updating local network information
24-01-16 20:56:02 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
24-01-16 20:56:02 INFO (MainThread) [supervisor.host.manager] Host information reload completed

I can see that indeed supervisor started MQTT before ebusd, so I guess my solution is not the way forward. Any idea what the problem is?

dulek commented 10 months ago

I changed the hardware and everything looks better now. I'm suspecting this was general slowness of my RPi 3 that caused this.