Zoneminder fails to start following 1.34.7-1 to 1.34.16 upgrade on Centos 7

[a_zm_user]

Having been somewhat behind updates, I ran dnf upgrade on my multi-server Centos 7 depoyment and following the required zmupdate I am no longer able to start the zoneminder service:

Code: Select all

Redirecting to /bin/systemctl status zoneminder.service
● zoneminder.service - ZoneMinder CCTV recording and security system
   Loaded: loaded (/etc/systemd/system/zoneminder.service; enabled; vendor preset: disabled)
  Drop-In: /usr/lib/systemd/system/zoneminder.service.d
           └─zm-httpd.conf
   Active: failed (Result: timeout) since Tue 2020-06-23 13:03:09 GMT; 45min ago
  Process: 157869 ExecStart=/usr/bin/zmpkg.pl start (code=killed, signal=TERM)
 Main PID: 2230 (code=exited, status=0/SUCCESS)

Jun 23 13:01:21 zm-web.local zmpkg[157869]: INF [Sanity checking States table...]
Jun 23 13:01:21 zm-web.local zmpkg[157869]: INF [Command: start]
Jun 23 13:02:09 zm-web.local zmdc[157890]: FAT [Can't connect: No such file or directory]
Jun 23 13:02:09 zm-web.local zmpkg[157869]: ERR [Unable to run "/usr/bin/zmdc.pl startup", output is "Starting server", status is 255]
Jun 23 13:02:09 zm-web.local zmpkg[157869]: INF [Multi-server configuration detected. Starting up services for server 7]
Jun 23 13:02:21 zm-web.local zmdc[157910]: INF [Server starting at 20/06/23 13:02:21]
Jun 23 13:02:22 zm-web.local zmdc[157910]: INF [Socket should be open at /var/lib/zoneminder/sock/zmdc7.sock]
Jun 23 13:02:30 zm-web.local systemd[1]: zoneminder.service: Start operation timed out. Terminating.
Jun 23 13:02:49 zm-web.local zmdc[157910]: INF ['zmfilter.pl --filter_id=4 --daemon' starting at 20/06/23 13:02:49, pid = 157942]
Jun 23 13:02:49 zm-web.local zmdc[157910]: INF [Server exiting at 20/06/23 13:02:49]
Jun 23 13:02:49 zm-web.local zmdc[157942]: INF ['zmfilter.pl --filter_id=4 --daemon' started at 20/06/23 13:02:49]
Jun 23 13:03:09 zm-web.local zmdc[157910]: INF ['zmfilter.pl --filter_id=4 --daemon' sending stop to pid 157942 at 20/06/23 13:03:09]
Jun 23 13:03:09 zm-web.local zmdc[157910]: INF ['zmfilter.pl --filter_id=4 --daemon' exited, signal 14]
Jun 23 13:03:09 zm-web.local zmdc[157910]: INF [Server shutdown at 20/06/23 13:03:09]
Jun 23 13:03:09 zm-web.local systemd[1]: zoneminder.service: Failed with result 'timeout'.
Jun 23 13:03:09 zm-web.local systemd[1]: Failed to start ZoneMinder CCTV recording and security system.
-- Subject: Unit zoneminder.service has failed

This appeared to be permissions related on the sockets directory, but permissions seem ok and unchanged from prior to the upgrade:

Code: Select all

[root@zm-web zoneminder]# grep SOCKS /etc/zm/conf.d/*
/etc/zm/conf.d/01-system-paths.conf:ZM_PATH_SOCKS=/var/lib/zoneminder/sock

[root@zm-web zoneminder]# ls -l /var/lib/zoneminder/ | grep sock
drwxr-xr-x  2 apache apache 4096 Jun 23 13:03 sock

Attempting to start zmdc.pl manually gives this:

Code: Select all

[root@zm-web zoneminder]# su -c "/usr/bin/zmdc.pl startup" apache
Starting server
Can't open pid file at /var/run/zoneminder/zm.pid
23/06/20 13:36:33.750173 zmdc[158208].FAT [main:195] [Can't connect: No such file or directory]

It appears that there is no /var/run/zoneminder directory, which I would have assumed to be created if not already present..

Code: Select all

[root@zm-web zoneminder]# ls -l /var/run/zoneminder
ls: cannot access '/var/run/zoneminder': No such file or directory

So I tried creating this manually:

Code: Select all

[root@zm-web zoneminder]#  mkdir /var/run/zoneminder && chown apache:apache /var/run/zoneminder && su -c "/usr/bin/zmdc.pl startup" apache
total 0
Starting server
23/06/20 13:38:41.665041 zmdc[158249].FAT [main:195] [Can't connect: No such file or directory]

And the PID file was at least created:

Code: Select all

[root@zm-web zoneminder]# ls -l /var/run/zoneminder
total 4
-rw-r--r-- 1 apache apache 6 Jun 23 13:38 zm.pid

[root@zm-web zoneminder]# cat /var/run/zoneminder/zm.pid 
158258

So looking up the zmdc.pl.in code for the error at line 195 we can see from line 190 onwards below references the SOCK_FILE:

Code: Select all

    socket(CLIENT, PF_UNIX, SOCK_STREAM, 0) or Fatal("Can't open socket: $!");
    my $attempts = 0;
    while( !connect(CLIENT, $saddr) ) {
      $attempts++;
      Debug('Waiting for zmdc.pl server process at '.SOCK_FILE.", attempt $attempts");
      Fatal("Can't connect: $!") if $attempts > MAX_CONNECT_DELAY;
      usleep(200000);
    } # end while
  } elsif ( defined($cpid) ) {
    ZMServer::run();
  } else {
    Fatal("Can't fork: $!");
  }
} # end if ! server is up

Which also seems to be present:

Code: Select all

[root@zm-web zoneminder]# ls -l /var/lib/zoneminder/sock/
total 0
srwxr-xr-x 1 apache apache 0 Jun 23 13:38 zmdc7.sock

Any ideas on whats broken following this upgrade?

Or failing that, somewhere where I can download the 1.34.7-1 EL7 RPM's as RPMFusion seems only to make the latest version available?

[iconnor]

I doubt that downgrading would fix the problem (would be interesting to know though). There havn't been any changes to zmdc.pl since 1.34.7.

You might check in log files in /var/log/zoneminder, specifically zmdc.log

[a_zm_user]

thanks for the swift reply, the journalctl -xe output was pretty much all the useful stuff from zmdc.log

Code: Select all

23/06/20 13:02:09.465251 zmdc[157890].FAT [main:195] [Can't connect: No such file or directory]
23/06/20 13:02:21.481675 zmdc[157910].INF [ZMServer:410] [Server starting at 20/06/23 13:02:21]
23/06/20 13:02:22.560681 zmdc[157910].INF [ZMServer:410] [Socket should be open at /var/lib/zoneminder/sock/zmdc7.sock]
23/06/20 13:02:49.653752 zmdc[157910].INF [ZMServer:410] ['zmfilter.pl --filter_id=4 --daemon' starting at 20/06/23 13:02:49, pid = 157942]
23/06/20 13:02:49.653967 zmdc[157910].INF [ZMServer:410] [Server exiting at 20/06/23 13:02:49]
23/06/20 13:02:49.657793 zmdc[157942].INF [ZMServer:410] ['zmfilter.pl --filter_id=4 --daemon' started at 20/06/23 13:02:49]
23/06/20 13:03:09.678067 zmdc[157910].INF [ZMServer:410] ['zmfilter.pl --filter_id=4 --daemon' sending stop to pid 157942 at 20/06/23 13:03:09]
23/06/20 13:03:09.679589 zmdc[157910].INF [ZMServer:703] ['zmfilter.pl --filter_id=4 --daemon' exited, signal 14]
23/06/20 13:03:09.679683 zmdc[157910].INF [ZMServer:410] [Server shutdown at 20/06/23 13:03:09]
23/06/20 13:05:00.986863 zmdc[157969].FAT [main:195] [Can't connect: No such file or directory]
23/06/20 13:36:33.750173 zmdc[158208].FAT [main:195] [Can't connect: No such file or directory]
23/06/20 13:38:41.665041 zmdc[158249].FAT [main:195] [Can't connect: No such file or directory]
23/06/20 13:38:53.677430 zmdc[158258].INF [ZMServer:410] [Server starting at 20/06/23 13:38:53]
23/06/20 13:38:54.741088 zmdc[158258].INF [ZMServer:410] [Socket should be open at /var/lib/zoneminder/sock/zmdc7.sock]

The only other log file which has been modified since the upgrades are zmpkg.log:

Code: Select all

23/06/20 13:01:21.112866 zmpkg[157869].INF [main:310] [Sanity checking States table...]
23/06/20 13:01:21.128599 zmpkg[157869].INF [main:95] [Command: start]
23/06/20 13:02:09.476959 zmpkg[157869].ERR [ZoneMinder::General:150] [Unable to run "/usr/bin/zmdc.pl startup", output is "Starting server", status is 255]
23/06/20 13:02:09.478968 zmpkg[157869].INF [main:198] [Multi-server configuration detected. Starting up services for server 7]

and zmsystemctl.log

Code: Select all

23/06/20 10:57:37.572490 zmsystemctl[156463].INF [main:71] [Redirecting command through systemctl]
23/06/20 12:33:11.952184 zmsystemctl[157097].INF [main:71] [Redirecting command through systemctl]

[a_zm_user]

Interestingly after rebooting the vm's failed to make any difference I went to look in vCenter and found that the ESX host cluster had lost sync with vCenter, reconnecting was unsucessful but following a reload of vCenter I was able to manage the VM's again...

As this had taken some time I figured it was worth another attempt to start Zoneminder on one of the vm's, to my suprise it spang to life with no errors so I then started Zoneminder on the remain vm's without issue.

I forgot to log into the ESX hosts directly to see if any of them were resource constrained, or if VDRS had allowed all the ZM VM's to pile up on one host..

So I can only assume that some sort of (failed) ESX state can result in vm's being unable to make use of unix sockets as from what I could see the zmdc*.sock that line 195 of zmdc.pl tries to access did at least exist.. could there be any easy means to add some more verbose debuging here?

PS loving the update, missing a few certainly makes the differences more noticable.. with the new Emailed text in the eevent view being a particularly useful addition for me