alexbelgium / hassio-addons

My homeassistant addons
MIT License
1.58k stars 225 forks source link

🐛 [zoneminder] cannot start (mysql startup timer expired) #884

Closed charchess closed 1 year ago

charchess commented 1 year ago

Description

When I deploy homeassistant addon, it's starting and then stopping

Reproduction steps

1. install zoneminder addon
2. Click on start

Addon Logs

Starting...
/etc/cont-init.d/00-banner.sh: executing
-----------------------------------------------------------
 Add-on: Zoneminder
 A full-featured, open source, state-of-the-art video surveillance software system
-----------------------------------------------------------
 Add-on version: 1.36.33
 You are running the latest version of this add-on.
 System: Home Assistant OS 10.3  (amd64 / generic-x86-64)
 Home Assistant Core: 2023.6.3
 Home Assistant Supervisor: 2023.06.2
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums
 https://github.com/alexbelgium/hassio-addons
-----------------------------------------------------------
/etc/cont-init.d/00-folders.sh: executing
/./etc/cont-init.d/00-folders.sh: line 9: bashio::config.has_value: command not found
... making sure /config/addons_config/zoneminder exists
... checking permissions
... making symlinks
/etc/cont-init.d/01-custom_script.sh: executing
[19:43:16] INFO: Execute /config/addons_autoscripts/zoneminder.sh if existing
[19:43:16] INFO: ... no script found
/etc/cont-init.d/99-run.sh: executing
[19:43:16] INFO: Defining database
[19:43:16] INFO: Using internal database
[19:43:16] INFO: Please wait while the app is loading !
 * First run of MYSQL, initializing DB.
 * Starting MySQL database server service   ...done.
 * Warning: Mysql startup timer expired!
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)
 * First run of mysql in the container, creating ZoneMinder dB.
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)
 * Starting Apache http web server service   ...done.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
Unable to connect to DB. ZM Cannot continue.
BEGIN failed--compilation aborted at /usr/share/perl5/ZoneMinder/Config.pm line 150.
Compilation failed in require at /usr/bin/zmupdate.pl line 74.
BEGIN failed--compilation aborted at /usr/bin/zmupdate.pl line 74.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
DBI connect('database=zm;host=localhost','zmuser',...) failed: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) at /usr/share/perl5/ZoneMinder/Database.pm line 110.
Unable to connect to DB. ZM Cannot continue.
BEGIN failed--compilation aborted at /usr/share/perl5/ZoneMinder/Config.pm line 150.
Compilation failed in require at /usr/bin/zmupdate.pl line 74.
BEGIN failed--compilation aborted at /usr/bin/zmupdate.pl line 74.
 * Starting ZoneMinder video surveillance recorder   ...failed!
/etc/cont-init.d/99-run.sh: exiting 1

Architecture

amd64

OS

HAos

alexbelgium commented 1 year ago

Hi, I can't replicate. Here is my log. Is this systematic ? have you tried rebooting your host ?

Starting...
/etc/cont-init.d/00-banner.sh: executing
-----------------------------------------------------------
 Add-on: Zoneminder
 A full-featured, open source, state-of-the-art video surveillance software system
-----------------------------------------------------------
 Add-on version: 1.36.33
 You are running the latest version of this add-on.
 System: Home Assistant OS 10.3  (aarch64 / raspberrypi4-64)
 Home Assistant Core: 2023.6.3
 Home Assistant Supervisor: 2023.06.2
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums
 https://github.com/alexbelgium/hassio-addons
-----------------------------------------------------------
/etc/cont-init.d/00-folders.sh: executing
/./etc/cont-init.d/00-folders.sh: line 9: bashio::config.has_value: command not found
... making sure /config/addons_config/zoneminder exists
... checking permissions
... making symlinks
/etc/cont-init.d/01-custom_script.sh: executing
[08:57:48] INFO: Execute /config/addons_autoscripts/zoneminder.sh if existing
[08:57:48] INFO: ... no script found
/etc/cont-init.d/99-run.sh: executing
[08:57:48] INFO: Defining database
[08:57:48] INFO: Using internal database
[08:57:48] INFO: Please wait while the app is loading !
 * First run of MYSQL, initializing DB.
 * Starting MySQL database server service   ...done.
 * First run of mysql in the container, creating ZoneMinder dB.
 * Starting Apache http web server service   ...done.
 * Starting ZoneMinder video surveillance recorder
Database already at version 1.36.12, update skipped.
Freshening configuration in database
Migratings passwords, if any...
Loading config from DB 221 entries
Saving config to DB 221 entries
   ...done.
tail: cannot open '/var/log/zoneminder/zm*.log' for reading: No such file or directory
==> /var/log/zm/zmdc.log <==
06/29/23 08:58:17.390992 zmdc[640].INF [ZMServer:411] ['zmfilter.pl --filter_id=1 --daemon' starting at 23/06/29 08:58:17, pid = 671]
06/29/23 08:58:17.391012 zmdc[671].INF [ZMServer:411] ['zmfilter.pl --filter_id=1 --daemon' started at 23/06/29 08:58:17]
06/29/23 08:58:17.822435 zmdc[640].INF [ZMServer:411] ['zmfilter.pl --filter_id=2 --daemon' starting at 23/06/29 08:58:17, pid = 679]
06/29/23 08:58:17.822455 zmdc[679].INF [ZMServer:411] ['zmfilter.pl --filter_id=2 --daemon' started at 23/06/29 08:58:17]
06/29/23 08:58:18.300956 zmdc[640].INF [ZMServer:411] ['zmwatch.pl' starting at 23/06/29 08:58:18, pid = 688]
06/29/23 08:58:18.307880 zmdc[688].INF [ZMServer:411] ['zmwatch.pl' started at 23/06/29 08:58:18]
06/29/23 08:58:18.782660 zmdc[640].INF [ZMServer:411] ['zmupdate.pl -c' starting at 23/06/29 08:58:18, pid = 696]
06/29/23 08:58:18.782680 zmdc[696].INF [ZMServer:411] ['zmupdate.pl -c' started at 23/06/29 08:58:18]
06/29/23 08:58:19.227854 zmdc[640].INF [ZMServer:411] ['zmstats.pl' starting at 23/06/29 08:58:19, pid = 703]
06/29/23 08:58:19.227874 zmdc[703].INF [ZMServer:411] ['zmstats.pl' started at 23/06/29 08:58:19]
==> /var/log/zm/zmfilter_1.log <==
06/29/23 08:58:18.193433 zmfilter_1[671].INF [main:182] [Scanning for events using filter id '1']
==> /var/log/zm/zmfilter_2.log <==
06/29/23 08:58:18.618499 zmfilter_2[679].INF [main:182] [Scanning for events using filter id '2']
==> /var/log/zm/zmpkg.log <==
06/29/23 08:58:14.665894 zmpkg[621].INF [main:318] [Sanity checking States table...]
06/29/23 08:58:14.675821 zmpkg[621].INF [main:95] [Command: start]
06/29/23 08:58:16.986881 zmpkg[621].INF [main:211] [Single server configuration detected. Starting up services.]
==> /var/log/zm/zmupdate.log <==
==> /var/log/zm/zmwatch.log <==
06/29/23 08:58:18.701066 zmwatch[688].INF [main:79] [Watchdog starting, pausing for 30 seconds]
tail: cannot watch parent directory of '/var/log/zoneminder/zm*.log': No such file or directory
tail: inotify cannot be used, reverting to polling
==> /var/log/zm/zmdc.log <==
Update agent starting at 23/06/29 08:58:19
==> /var/log/zm/zmupdate.log <==
06/29/23 08:58:19.281154 zmupdate[696].INF [main:166] [Checking for updates]
06/29/23 08:58:19.895696 zmupdate[696].INF [main:182] [Got version: 1.36.33]
charchess commented 1 year ago

I did several restart, uninstall/reinstall (of zoneminder) with no success

As I did post my issue, you posted some shebang fix and I went like woohoo that should be it !

I was able to login the container to check and it seems the /etc/cont-init.d/00-folders.sh is still the old one (#!/bin/bash)

It just doesn't seem like my HA is willing to update it besides all the forcing I'm doing. If you have any clue on how to kick it somewhere so he update the image, I'd appreciate it,

thanks for your help and thanks for the repository and the work

charchess commented 1 year ago

I tinkered a bit in the container to find the issue and I could change the shebang, it fixes the message about the bashio command not found but not my issue ...

after some more tinkering around, I tried to run "mysqld --initialize-insecure --user=mysql --datadir=/var/lib/mysql/" which is supposed to initiate the DB in the entrypoint.sh and got the following : root@db21ed7f-zoneminder:/# mysqld --initialize-insecure --user=mysql --datadir=/var/lib/mysql/ mysqld: Out of memory (Needed 4294967200 bytes) (I had to remove the content of /var/lib/mysql beforehand)

Am wondering if I have enough memory and how I could check on that ?

mysqld: Out of memory (Needed 4294967200 bytes) 2023-06-29T10:36:27.887943Z 0 [Warning] Changed limits: max_open_files: 64 (requested 5000) 2023-06-29T10:36:27.888154Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2023-06-29T10:36:27.889214Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting. 2023-06-29T10:36:27.889228Z 0 [ERROR] Aborting

charchess commented 1 year ago

database finally did accept to run with "mysqld --user=mysql --datadir=/var/lib/mysql/" and I was able to connect on webui but that's not a solution (tinkering inside of a container is never a solution)

alexbelgium commented 1 year ago

quite interesting...

Would it help if we add to Dockerfile some kind of sed -i "s>mysqld --initialize-insecure --user=mysql --datadir>/var/lib/mysql/=mysqld --initialize-insecure --user=mysql --datadir=/var/lib/mysql/ || { bashio::log.warning "Warning, please note the password if first initialization"; mysqld --user=mysql --datadir=/var/lib/mysql/; } >g" /usr/local/bin/entrypoint.sh ?

So that it doesn't change for users for which it works, but then executes your code otherwise

charchess commented 1 year ago

will try that later in a freshly deployed container to see if it helps, will let you know this evening (I guess)

charchess commented 1 year ago

Hi, I may miss something but docker pull ghcr.io/alexbelgium/zoneminder-amd64 image seems to still be the one from 4 months ago, aren't you supposed to build new one after modifying Dockerfile or am I missing something ?

And I try messing with my container with not much success .. and will not be able to work on it as much as I'd like for the next days

alexbelgium commented 1 year ago

Hi, the build failed, I'll change the sed and try again. You'll need to refresh the repo for HA to see the new version

alexbelgium commented 1 year ago

Build done !

charchess commented 1 year ago

Hi and thanks for your reactivity but ... not solving my issue so far :/

I think I pinpoint something though !

"{MYSQLD} --initialize-insecure --user=mysql --datadir=/config/addons_config/zoneminder/mysql/" is filing with the errors : mysqld: Can't change dir to '/config/addons_config/zoneminder/mysql/' (Errcode: 13 - Permission denied) 2023-07-01T03:11:59.887503Z 0 [Warning] Changed limits: max_open_files: 64 (requested 5000) 2023-07-01T03:11:59.887946Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2023-07-01T03:11:59.891381Z 0 [ERROR] failed to set datadir to /config/addons_config/zoneminder/mysql/ 2023-07-01T03:11:59.891412Z 0 [ERROR] Aborting

I tried with several other datadir (/var/lib/mysql2, /tmp/mysql) and it seems they are working fine, but as soon as I try to initialize outside of the container (I tried /config/addons_config/zoneminder/mysql2 and even /config/test), it fails ...

alexbelgium commented 1 year ago

Mmh probably permissions issues on one of the parent directory of /config/addons_config/zoneminder... It's a root user, right? You could try to set /config/addons_config or /config/addons_config/zoneminder to chmod 777 to check the hypothesis...

charchess commented 1 year ago

I think we are onto something, I changed into user mysql (the one supposed to start the mysqld processs) and was unable to access to the directory where things should be happening :

root@db21ed7f-zoneminder:/# su -l mysql -s /bin/bash No directory, logging in with HOME=/ mysql@db21ed7f-zoneminder:/$ ls /config/addons_config/zoneminder/mysql ls: cannot access '/config/addons_config/zoneminder/mysql': Permission denied mysql@db21ed7f-zoneminder:/$ ls /config/addons_config/zoneminder ls: cannot access '/config/addons_config/zoneminder': Permission denied mysql@db21ed7f-zoneminder:/$ ls /config/ ls: cannot open directory '/config/': Permission denied

mysql@db21ed7f-zoneminder:/$ ls / -hail 262164 drwx------ 21 root root 4.0K Jul 1 11:03 config

I don't know if those permissions are by default on HAOS but that's definitely an issue :/

github-actions[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

charchess commented 1 year ago

Hi, the issue is not yet solved but I did lack time to work on it ...

could you let me know what permission I should expect on /config directory ? (I'm using haos)

My other option would be to run another haos in some VM to compare those

alexbelgium commented 1 year ago

In theory it would be 755 ; but putting 777 might be a non-secure way to solve that permission issue :-)

Another better way would be to chown the sql user as owner of its database folder perhaps it would work

It's all based on symlinks that sometimes don't play nice with permissions...

charchess commented 1 year ago

I'm encountering one of the thing I love the most in IT .... things are now working and I have no clue what solved it ...

for the record, I started the container, it worked ... I stopped it, uninstalled, remove /config/addons_config/zoneminder and reinstalled ...and things are working fine now

thanks for your help, next time I'll try some voodoo and sacrifice a chicken -_-

alexbelgium commented 1 year ago

Well then what I usually do in this situation is quickly do a backup in case anything happens!! I had exactly the same this weekend where I spent 2 days troubleshooting a libreelec installation that in the end came back to life without explanation...