search

seanblanchfield / seans-homeassistant-addons

Apache License 2.0
4 stars 1 forks source link

Sensor not being created #3

Closed davefrooney closed 3 months ago

davefrooney commented 3 months ago

I've run into an issue over the last week or so where the sensor is home assistant is not being created. The add-on had been working previously.

I am able to view the results from the webui when I type in my stop number but still no sensor available. I have tried rebuilding the add-on and doing a clean install but to no avail

Have you had any issue with this previously?

These are the logs from the add-on

106:M 26 Jun 2024 09:58:28.003 100 changes in 300 seconds. Saving... 106:M 26 Jun 2024 09:58:28.003 Background saving started by pid 30867 30867:C 26 Jun 2024 09:58:28.044 DB saved on disk 30867:C 26 Jun 2024 09:58:28.044 Fork CoW for RDB: current 0 MB, peak 0 MB, average 0 MB 106:M 26 Jun 2024 09:58:28.103 * Background saving terminated with success Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... DEBUG:root:Updating from live feed. Waiting for server to start up... DEBUG:root:Got 98 trip updates, 20098 unrecognised trips, 365 added trips, 0 cancelled trips DEBUG:root:Live feed updated. Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... Waiting for server to start up... DEBUG:root:Updating from live feed. DEBUG:root:Got 102 trip updates, 21520 unrecognised trips, 328 added trips, 0 cancelled trips DEBUG:root:Live feed updated. Waiting for server to start up..

evnvc commented 3 months ago

Getting the same here, server keeps loading for ages and does nothing. Getting warning about timezones change in the logs

seanblanchfield commented 3 months ago

I haven't had this issue. It's still running well for me. The log output you have has a lot of "Waiting for server to start up...", which means that the add-on is trying to check that the local GTFS server has started before beginning to update the sensors. So that seems to confirm the problem. For some reason the add-on script can't connect to the GTFS server the add-on starts on port 7341.

Here's some things to try:

davefrooney commented 3 months ago

I am able to access the html interface directly and that works fine. I've tried rebooting everything and still no joy. I tried removing the the stops and adding again as well as removing the entire add-on but still nothing. Let me know if you need anymore info

seanblanchfield commented 3 months ago

I just pushed some better logging into version 1.0.17. If you check for updates you should find it, and should be able to upgrade. When info level logging is enabled, it provides more detailed output. Post the logs after letting it run for a while, and hopefully we'll get a better idea of exactly where it is failing.

davefrooney commented 3 months ago

Thanks for the update. Could the memory overcommit be causing the issue?

109:M 29 Jun 2024 21:56:08.329 User requested shutdown... 109:M 29 Jun 2024 21:56:08.329 Saving the final RDB snapshot before exiting. 109:M 29 Jun 2024 21:56:08.354 DB saved on disk 109:M 29 Jun 2024 21:56:08.354 # Redis is now ready to exit, bye bye... 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 [21:57:35] INFO: Starting GTFS server... [21:57:35] INFO: Waiting 10 seconds for GTFS server to start up... python3 server.py --host 0.0.0.0 --redis redis://localhost:6379 109:C 29 Jun 2024 21:57:35.088 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect. 109:C 29 Jun 2024 21:57:35.088 oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo 109:C 29 Jun 2024 21:57:35.088 Redis version=7.2.5, bits=64, commit=00000000, modified=0, pid=109, just started 109:C 29 Jun 2024 21:57:35.088 Configuration loaded 109:M 29 Jun 2024 21:57:35.090 monotonic clock: POSIX clock_gettime 109:M 29 Jun 2024 21:57:35.091 Running mode=standalone, port=6379. 109:M 29 Jun 2024 21:57:35.091 Server initialized 109:M 29 Jun 2024 21:57:35.091 Ready to accept connections tcp INFO:root:Downloading static GTFS data from https://www.transportforireland.ie/transitData/Data/GTFS_Realtime.zip INFO:root:Finished downloading static GTFS data. INFO:root:Initializing GTFS with: live_url=https://api.nationaltransport.ie/gtfsr/v2/TripUpdates api_key=xxxxxxxx redis_url=redis://localhost:6379 rebuild_cache=True filter_stops=['2246'] profile_memory=False

INFO:root:Using redis for data storage at redis://localhost:6379 INFO:root:Loading GTFS static data from scratch. INFO:root:Loading routes. INFO:root:Loading agencies. INFO:root:Loading calendar. INFO:root:Loaded calendar with start dates ranging from 2024-06-29 to 2024-12-31 INFO:root:Loading calendar exceptions. INFO:root:Loading stops. [21:57:45] INFO: Waiting 10 seconds for GTFS server to start up... INFO:root:Loading stop times. [21:57:55] INFO: Waiting 10 seconds for GTFS server to start up... INFO:root:

Loaded 7160262 stop times in 16 seconds INFO:root:Loading trips. INFO:root:Persisting data. Loading stop times................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................109:M 29 Jun 2024 21:58:01.977 * DB saved on disk INFO:root:Updating from live feed. INFO:root:Live feed loaded. INFO:root:Initializing GTFS with: live_url=https://api.nationaltransport.ie/gtfsr/v2/TripUpdates api_key=xxxxxxx redis_url=redis://localhost:6379 rebuild_cache=False filter_stops=['2246'] profile_memory=False

INFO:root:Using redis for data storage at redis://localhost:6379 INFO:waitress:Serving on http://0.0.0.0:7341 [21:58:05] INFO: Waiting 10 seconds for GTFS server to start up... [21:58:15] INFO: Waiting 10 seconds for GTFS server to start up... [21:58:25] INFO: Waiting 10 seconds for GTFS server to start up... [21:58:35] INFO: Waiting 10 seconds for GTFS server to start up... [21:58:45] INFO: Waiting 10 seconds for GTFS server to start up... [21:58:55] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:05] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:15] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:25] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:35] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:45] INFO: Waiting 10 seconds for GTFS server to start up... [21:59:55] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:05] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:15] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:25] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:35] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:45] INFO: Waiting 10 seconds for GTFS server to start up... [22:00:55] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:05] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:15] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:25] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:35] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:45] INFO: Waiting 10 seconds for GTFS server to start up... [22:01:55] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:05] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:15] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:25] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:35] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:45] INFO: Waiting 10 seconds for GTFS server to start up... [22:02:55] INFO: Waiting 10 seconds for GTFS server to start up... 109:M 29 Jun 2024 22:03:02.028 100 changes in 300 seconds. Saving... 109:M 29 Jun 2024 22:03:02.029 Background saving started by pid 213 213:C 29 Jun 2024 22:03:02.054 DB saved on disk 213:C 29 Jun 2024 22:03:02.054 Fork CoW for RDB: current 0 MB, peak 0 MB, average 0 MB 109:M 29 Jun 2024 22:03:02.129 * Background saving terminated with success [22:03:05] INFO: Waiting 10 seconds for GTFS server to start up... [22:03:15] INFO: Waiting 10 seconds for GTFS server to start up... [22:03:25] INFO: Waiting 10 seconds for GTFS server to start up... [22:03:35] INFO: Waiting 10 seconds for GTFS server to start up... [22:03:45] INFO: Waiting 10 seconds for GTFS server to start up... [22:03:55] INFO: Waiting 10 seconds for GTFS server to start up... [22:04:05] INFO: Waiting 10 seconds for GTFS server to start up...

seanblanchfield commented 3 months ago

Thanks Dave.

It's still a mystery to me. The "memory overcommit" line is a red herring, and isn't the problem here. And isn't a problem for us in general (more background on that warning here for anyone who is interested).

I don't see anything in your logs to indicate the problem. The line

[21:57:35] INFO: Starting GTFS server...

indicates the GTFS server starts okay, but the 

[22:03:25] INFO: Waiting 10 seconds for GTFS server to start up...

lines indicate that the script can't connect to it for some reason.

If you are willing to run some tests for me over SSH, it might help find the problem. I'm providing detailed instructions below, but I understand if you don't want to go this deep.

To run these tests you will need the SSH add on here. You need to turn off protection mode in the settings. Then you will be able to connect to your HA host over SSH, and run docker commands from it (all addons are just docker containers).

image (you can re-enable protection mode later).

Then open the SSH addon's web UI, run the following commands and paste the results back in here.

1. Check the name of the addon container

Mine is "addon_a9aab0b3_tfi-gtfs". I think yours will be the same but you'll need to modify subsequent commands if yours is different.

 docker container ls  --format "{{.Names}}" | grep tfs

image

2. Get a list of what processes are running in the addon.

docker exec  addon_a9aab0b3_tfi-gtfs ps aux

image

3. Check if the GTFS server is listening on port 7341 as expected.

docker exec  addon_a9aab0b3_tfi-gtfs netstat -lt

image

4. Check what network interfaces you have.

If your system is very different from mine in some way I'm not anticipating, perhaps this will show it up. I'm running vanilla Home Assistant OS on a Home Assistant Blue. 

docker exec  addon_a9aab0b3_tfi-gtfs ifconfig

image

5. Run some tests to see if you can connect to the GTFS server from inside your container.

docker exec  addon_a9aab0b3_tfi-gtfs nc -z localhost 9999; echo $?
docker exec  addon_a9aab0b3_tfi-gtfs nc -z localhost 7341; echo $?
docker exec  addon_a9aab0b3_tfi-gtfs nc -z 127.0.0.1 7341; echo $?

image

davefrooney commented 3 months ago

Thanks for taking you're time to help out.

Here's the output from the commands. I'm running standard HASSIO on proxmox as a VM

➜ ~ docker exec addon_a9aab0b3_tfi-gtfs ps aux PID USER TIME COMMAND 1 root 0:00 /package/admin/s6/command/s6-svscan -d4 -- /run/service 15 root 0:00 {rc.init} /bin/sh -e /run/s6/basedir/scripts/rc.init top /run.sh 16 root 0:00 s6-supervise s6-linux-init-shutdownd 18 root 0:00 /package/admin/s6-linux-init/command/s6-linux-init-shutdownd -d3 -c /run/s6/basedir -g 3000 -C -B 25 root 0:00 s6-supervise s6rc-fdholder 26 root 0:00 s6-supervise s6rc-oneshot-runner 34 root 0:00 /package/admin/s6/command/s6-ipcserverd -1 -- /package/admin/s6/command/s6-ipcserver-access -v0 -E -l0 -i data/rules -- /package/admin/s6/command/s6-sudod -t 30000 -- /package/admin/s6-rc/command/s6-rc-oneshot-run -l ../.. -- 79 root 0:00 bash /usr/bin/bashio /run.sh 103 root 0:03 bash /usr/bin/bashio /run.sh 107 root 0:00 {entrypoint.sh} /bin/sh /app/entrypoint.sh 108 root 1:25 redis-server :6379 110 root 3:08 python3 server.py --host 0.0.0.0 --redis redis://localhost:6379 12401 root 0:00 sleep 10 12402 root 0:00 ps aux ➜ ~ docker exec addon_a9aab0b3_tfi-gtfs netstat -lt Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 127.0.0.11:42957 0.0.0.0: LISTEN
tcp 0 0 0.0.0.0:redis 0.0.0.0: LISTEN
tcp 0 0 0.0.0.0:7341 0.0.0.0: LISTEN
tcp 0 0 :::redis :::* LISTEN
➜ ~ docker exec addon_a9aab0b3_tfi-gtfs ifconfig eth0 Link encap:Ethernet HWaddr 02:42:AC:1E:21:06
inet addr:172.30.33.6 Bcast:172.30.33.255 Mask:255.255.254.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:56510 errors:0 dropped:0 overruns:0 frame:0 TX packets:22210 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:185519913 (176.9 MiB) TX bytes:1787823 (1.7 MiB)

lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0 inet6 addr: ::1/128 Scope:Host UP LOOPBACK RUNNING MTU:65536 Metric:1 RX packets:2942124 errors:0 dropped:0 overruns:0 frame:0 TX packets:2942124 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:293096895 (279.5 MiB) TX bytes:293096895 (279.5 MiB)

➜ ~ docker exec addon_a9aab0b3_tfi-gtfs nc -z localhost 9999; echo $? docker exec addon_a9aab0b3_tfi-gtfs nc -z localhost 7341; echo $? docker exec addon_a9aab0b3_tfi-gtfs nc -z 127.0.0.1 7341; echo $? 1 1 0

davefrooney commented 3 months ago

image The screenshot might be easier to read

seanblanchfield commented 3 months ago

Thanks Dave. That log output was helpful. In particular the last bit showed that the addon container connects okay to the GTFS server on 127.0.0.1:7341 but not to localhost:7341. I don't know what that would be the case, or why it works for me and not for you. I'm happy enough to just change to the IP number version though, which is what I've done in v 1.0.18, which I just pushed. Please update again, and see if it works now. If not, we'll dig a bit deeper.

davefrooney commented 3 months ago

That did the trick! The sensor came up straight away. Thanks so much for all your help! My dashboard is complete once again.

davefrooney commented 3 months ago

The problem started about 2 weeks ago which is when I upgraded to 2024.6. I wonder if there was a change in HA that could have affected it?

seanblanchfield commented 3 months ago

That's wonderful, I'm glad it's fixed. I don't know if it was a change in Home Assistant 2024.6 or something to do with proxmox or some combo. It would seem to be related to how Docker networking is configured, which is fairly complicated under the hood. Anyway, it's fixed now!

I just created a google group for smart home users in Dublin. I want to see if we can find enough HA users locally to maybe do a meetup. Please consider joining if that sounds interesting: https://groups.google.com/g/smart-home-dublin