I find the MariaDB periodically stopping in my current configuration. It stops
and it doesn’t restart on its own. I can start it again without difficulty
using ‘systemctl start mariadb’.
I have the impression that it is a weekly occurrence. I thought it was every
Saturday, but when I paid attention, it occurred Friday, June 5 and then again
on Thursday, June 11. I noticed that the time, 06:02, is consistent.
I did review ‘systemctl status mariadb’ while it was down. I failed to paste
it here and it is lost for now, but it only indicated that the service was
stopping without offering a reason. The entry occurred at 06:02:xx and led me
to check other logs for more information at that time. At the end of this
message is some log data surrounding the event, but all I see is confirmation
that the database became unavailable. Hopefully, there’s some place else to
look for a clue.
I’ve noticed that I should potentially be using the service name
packetfence-mariadb, not just mariadb. Currently, with the service
successfully started, ‘systemctl status mariadb’ and ‘systemctl status
packetfence-mariadb’ both successfully return the same results. And, I’ve
since realized I can start, stop and get status using either of those service
names.
Before sending this message, I’ve dug a bit further. I find that the file
/etc/systemd/system/packetfence-mariadb.service is improperly linked to
/lib/systemd/system/mariadb.service. I think it should be linked to
/lib/systemd/system/packetfence-mariadb.service. I believe I created the
improper link during some earlier testing of the PacketFence upgrade process.
It was a difficult experience to complete the upgrade for some reason and, in
the end, I removed all the packages and reinstalled them and struggled to get
it all working again. I did so, but along the way I believe I changed that
symbolic link to get the database to come up.
This suggests to me that maybe PacketFence is not managing the mariadb as it
should.
I’ve tried changing the link to /etc/systemd/system/packetfence-mariadb.service
-> /lib/systemd/system/packetfence-mariadb.service. There are errors and the
database will not start in this configuration. The error states the
/usr/local/pf/var/conf/mariadb.conf file is not found. When I have the
opportunity to check (I reboot when I make changes to the links and such) the
file is there. I’ve learned the defaults file is created during database
startup by ‘pfcmd generatemariadbconfig’ and that process is reported to be
successful.
● packetfence-mariadb.service - PacketFence MariaDB instance
Loaded: loaded (/lib/systemd/system/packetfence-mariadb.service; enabled;
vendor preset: enabled)
Active: activating (start) since Thu 2020-06-11 11:09:22 EDT; 30s ago
Process: 1011 ExecStartPre=/usr/local/pf/bin/pfcmd generatemariadbconfig
(code=exited, status=0/SUCCESS)
Main PID: 1019 (pf-mariadb)
Tasks: 7 (limit: 36864)
CGroup: /packetfence.slice/packetfence-base.slice/packetfence-mariadb.service
├─ 1019 pf-mariadb
├─14588 /bin/bash /usr/bin/mysqld_safe
--defaults-file=/usr/local/pf/var/conf/mariadb.conf
└─14590 /bin/bash /usr/bin/mysqld_safe
--defaults-file=/usr/local/pf/var/conf/mariadb.conf
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: Fatal error in defaults
handling. Program aborted
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: WARNING: Defaults file
'/usr/local/pf/var/conf/mariadb.conf' not found!
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: Could not open required
defaults file: /usr/local/pf/var/conf/mariadb.conf
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: Fatal error in defaults
handling. Program aborted
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: WARNING: Defaults file
'/usr/local/pf/var/conf/mariadb.conf' not found!
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: 200611 11:09:53 mysqld_safe
Logging to '/var/lib/mysql/nadc1-pfence-01.err'.
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: 200611 11:09:53 mysqld_safe
Starting mysqld daemon with databases from /var/lib/mysql
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: Failed starting with mode:
standalone
Jun 11 11:09:53 nadc1-pfence-01 pf-mariadb[1019]: MariaDB is not alive
Here’s the folder listing showing the mariadb.conf in existence. Created at
the same time as the service start was attempted. You might notice the
permissions of the file are 0722, not 0622 as expected. It’s something I tried
by modifying generatemariadbconfig. I only changed (increased) the
permissions. It had no effect.
root@nadc1-pfence-01:/usr/local/pf/logs# ls -al /usr/local/pf/var/conf/
total 152
drwxrwsr-x 4 pf pf 4096 Jun 11 11:12 .
drwxrwsr-x 16 pf pf 4096 Jun 11 11:09 ..
-rwxrwxr-x 1 pf pf 1485 Jun 9 16:11 captive-portal-common
-rwxrwxr-x 1 pf pf 71 Nov 26 2019 .gitignore
-rwxrwxr-x 1 pf pf 1279 Jun 9 16:15 haproxy-db.conf
-rwxrwxr-x 1 pf pf 8275 Jun 11 11:12 haproxy-portal.conf
drwxrwsr-x 2 pf pf 4096 Feb 5 10:32 httpd.conf.d
-rwxrwxr-x 1 pf pf 13399 Jun 9 09:59 iptables.conf
-rwxrwxr-x 1 pf pf 1889 Jun 9 10:03 keepalived.conf
-rwxr--r-- 1 pf pf 3888 Jun 11 11:09 mariadb.conf
drwxrwsr-x 7 pf pf 4096 Jan 13 11:56 monitoring
-rwxrwxr-x 1 pf pf 1323 Jun 9 16:11 passthrough.lua
-rwxrwxr-x 1 pf pf 395 Jun 9 10:03 pfdns.conf
-rwxrwxr-x 1 pf pf 36446 Jun 9 10:04 redis_ntlm_cache.conf
-rwxrwxr-x 1 pf pf 36354 Jun 9 10:04 redis_queue.conf
-rwxrwxr-x 1 pf pf 632 Jun 11 06:01 snmptrapd.conf
-rwxrwxr-x 1 pf pf 451 Jun 9 16:11 ssl-certificates.conf
I compared with a different instance of PacketFence and find that the symbolic
link /etc/systemd/system/packetfence-mariadb.service ->
/lib/systemd/system/packetfence-mariadb.service shouldn’t exist at all. This
symbolic link actually exists as
/etc/systemd/system/packetfence-base.target.wants/packetfence-mariadb.service->/lib/systemd/system/packetfence-mariadb.service.
That, and there’s a symbolic link as /etc/systemd/system/mariadb.service ->
/dev/null. So, I’ve created these conditions and get exactly the same result.
The database fails to start because the defaults file cannot be found or
accessed.
The main process for starting the database appears to be pf-mariadb. This
process is running as root.
There doesn’t seem to be an issue with permissions. The defaults file does
exist. Any thoughts on where I can go from here to try and resolve the issue?
To get PacketFence properly managing the MariaDB service?
Thank you.
Jeff
Log data at the time of the database shutdown:
Packetfence.log
---------------------
Jun 5 06:00:36 nadc1-pfence-01 packetfence: INFO -e(81425): generating
/usr/local/pf/var/conf/snmptrapd.conf
(pf::services::manager::snmptrapd::generateConfig)
Jun 5 06:00:36 nadc1-pfence-01 packetfence: INFO -e(81425): generating
/usr/local/pf/var/conf/snmptrapd.conf
(pf::services::manager::snmptrapd::generateConfig)
Jun 5 06:01:01 nadc1-pfence-01 pfipset[38826]: t=2020-06-05T06:01:01-0400
lvl=info msg="No Inline Network bypass ipsets reload" pid=38826
Jun 5 06:01:01 nadc1-pfence-01 pfipset[38826]: t=2020-06-05T06:01:01-0400
lvl=info msg="No Inline Network bypass ipsets reload" pid=38826
Jun 5 06:02:12 nadc1-pfence-01 packetfence: INFO -e(81578): generating
/usr/local/pf/var/conf/snmptrapd.conf
(pf::services::manager::snmptrapd::generateConfig)
Jun 5 06:02:12 nadc1-pfence-01 packetfence: INFO -e(81578): generating
/usr/local/pf/var/conf/snmptrapd.conf
(pf::services::manager::snmptrapd::generateConfig)
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) WARN: [mac:unknown]
database query failed with: MySQL server has gone away (errno: 2006), will try
again (pf::dal::db_execute)
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) WARN: [mac:unknown]
database query failed with: MySQL server has gone away (errno: 2006), will try
again (pf::dal::db_execute)
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) WARN: [mac:unknown]
database query failed with: MySQL server has gone away (errno: 2006), will try
again (pf::dal::db_execute)
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) ERROR: [mac:unknown]
Problem looking up tenant ID (1) in database (pf::dal::set_tenant)
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) FATAL: [mac:unknown]
unable to connect to database: Can't connect to local MySQL server through
socket '/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/share/perl5/CHI/Driver.pm line 546.
Jun 5 06:02:50 nadc1-pfence-01 pfqueue: pfqueue(80748) FATAL: [mac:unknown]
unable to connect to database: Can't connect to local MySQL server through
socket '/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/local/pf/lib/pf/dal.pm line 69.
mariadb_error.log
------------------------
Empty
Pfmon.log
--------------
Jun 5 06:02:39 nadc1-pfence-01 pfmon: pfmon(80800) INFO: [mac:unknown] deleted
0 entries from chi_cache for batch_delete (1591351359 1591351359)
(pf::dal::batch_remove)
Jun 5 06:02:48 nadc1-pfence-01 pfmon: pfmon(80800) INFO: [mac:unknown] deleted
0 entries from chi_cache for batch_delete (1591351368 1591351368)
(pf::dal::batch_remove)
Jun 5 06:02:48 nadc1-pfence-01 pfmon: pfmon(80800) INFO: [mac:unknown] 80800
cleanup_chi_database_cache shutting down (main::_runtask)
Jun 5 06:02:48 nadc1-pfence-01 pfmon: pfmon(80800) INFO: [mac:unknown] deleted
0 entries from chi_cache for batch_delete (1591351368 1591351368)
(pf::dal::batch_remove)
Jun 5 06:02:48 nadc1-pfence-01 pfmon: pfmon(80800) INFO: [mac:unknown] 80800
cleanup_chi_database_cache shutting down (main::_runtask)
Jun 5 06:02:56 nadc1-pfence-01 pfmon: pfmon(78149) FATAL: [mac:unknown] unable
to connect to database: Can't connect to local MySQL server through socket
'/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/share/perl5/CHI/Driver.pm line 546.
Jun 5 06:02:56 nadc1-pfence-01 pfmon: pfmon(78149) FATAL: [mac:unknown] unable
to connect to database: Can't connect to local MySQL server through socket
'/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/share/perl5/CHI/Driver.pm line 546.
Jun 5 06:02:57 nadc1-pfence-01 pfmon: pfmon(81402) FATAL: [mac:unknown] unable
to connect to database: Can't connect to local MySQL server through socket
'/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/share/perl5/CHI/Driver.pm line 546.
Jun 5 06:02:57 nadc1-pfence-01 pfmon: pfmon(81402) INFO: [mac:unknown] getting
security_events triggers for accounting cleanup
(pf::accounting::acct_maintenance)
Jun 5 06:02:57 nadc1-pfence-01 pfmon: pfmon(81402) FATAL: [mac:unknown] unable
to connect to database: Can't connect to local MySQL server through socket
'/var/run/mysqld/mysqld.sock' (2 "No such file or directory") at
/usr/share/perl5/CHI/Driver.pm line 546.
Pfstats.log
-------------
Jun 5 06:02:23 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:23-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/queues/stats"; pid=39357
Jun 5 06:02:30 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:30-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/queues/stats"; pid=39357
Jun 5 06:02:30 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:30-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/queues/stats"; pid=39357
Jun 5 06:02:40 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:40-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/queues/stats"; pid=39357
Jun 5 06:02:40 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:40-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/queues/stats"; pid=39357
Jun 5 06:02:48 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:48-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/dhcp/stats"; pid=39357
Jun 5 06:02:48 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:48-0400
lvl=info msg="Calling Unified API on uri:
https://127.0.0.1:9999/api/v1/dhcp/stats"; pid=39357
Jun 5 06:02:50 nadc1-pfence-01 pfstats[39357]: [mysql] 2020/06/05 06:02:50
packets.go:112: closing bad idle connection: unexpected read from socket
Jun 5 06:02:50 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:50-0400
lvl=eror msg="Error while performing SQL query: dial unix
/var/run/mysqld/mysqld.sock: connect: no such file or directory" pid=39357
Jun 5 06:02:50 nadc1-pfence-01 pfstats: [mysql] 2020/06/05 06:02:50
packets.go:112: closing bad idle connection: unexpected read from socket
Jun 5 06:02:50 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:50-0400
lvl=eror msg="Error while performing SQL query: dial unix
/var/run/mysqld/mysqld.sock: connect: no such file or directory" pid=39357
Jun 5 06:02:51 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:51-0400
lvl=eror msg="Error while performing SQL query: dial unix
/var/run/mysqld/mysqld.sock: connect: no such file or directory" pid=39357
Jun 5 06:02:51 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:51-0400
lvl=eror msg="Error while performing SQL query: dial unix
/var/run/mysqld/mysqld.sock: connect: no such file or directory" pid=39357
Jun 5 06:02:52 nadc1-pfence-01 pfstats[39357]: t=2020-06-05T06:02:52-0400
lvl=eror msg="Error while performing SQL query: dial unix
/var/run/mysqld/mysqld.sock: connect: no such file or directory" pid=39357
/var/log/mysql/error.log
---------------------------------
Empty
/var/log/daemon.log
----------------------------
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: Time has been changed
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 7h 34min
29.704814s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 42.370601s
random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: Time has been changed
Jun 5 06:02:49 nadc1-pfence-01 systemd: apt-daily.timer: Adding 7h 34min
29.704814s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: anacron.timer: Adding 42.370601s
random time.
Jun 5 06:02:51 nadc1-pfence-01 systemd[1]: Stopped MariaDB 10.1.41 database
server.
Jun 5 06:02:51 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:51 nadc1-pfence-01 systemd: Stopped MariaDB 10.1.41 database
server.
Jun 5 06:02:51 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 1h 9min
19.806442s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 1min
21.451889s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:52 nadc1-pfence-01 systemd: apt-daily.timer: Adding 1h 9min
19.806442s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd: anacron.timer: Adding 1min 21.451889s
random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 5h 51min
13.477790s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 3min
11.205977s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: Reloading.
/var/log/syslog
-------------------
Jun 5 06:02:48 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 2h 15min
30.360084s random time.
Jun 5 06:02:48 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 3min
32.833603s random time.
Jun 5 06:02:48 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:48 nadc1-pfence-01 systemd: apt-daily.timer: Adding 2h 15min
30.360084s random time.
Jun 5 06:02:48 nadc1-pfence-01 systemd: anacron.timer: Adding 3min 32.833603s
random time.
Jun 5 06:02:48 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 10h 7min
24.310921s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 3min
36.452655s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: Stopping MariaDB 10.1.41 database
server...
Jun 5 06:02:49 nadc1-pfence-01 systemd: apt-daily.timer: Adding 10h 7min
24.310921s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: anacron.timer: Adding 3min 36.452655s
random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: Stopping MariaDB 10.1.41 database
server...
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: Time has been changed
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 7h 34min
29.704814s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 42.370601s
random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: Time has been changed
Jun 5 06:02:49 nadc1-pfence-01 systemd: apt-daily.timer: Adding 7h 34min
29.704814s random time.
Jun 5 06:02:49 nadc1-pfence-01 systemd: anacron.timer: Adding 42.370601s
random time.
Jun 5 06:02:51 nadc1-pfence-01 systemd[1]: Stopped MariaDB 10.1.41 database
server.
Jun 5 06:02:51 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:51 nadc1-pfence-01 systemd: Stopped MariaDB 10.1.41 database
server.
Jun 5 06:02:51 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 1h 9min
19.806442s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 1min
21.451889s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:52 nadc1-pfence-01 systemd: apt-daily.timer: Adding 1h 9min
19.806442s random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd: anacron.timer: Adding 1min 21.451889s
random time.
Jun 5 06:02:52 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 5h 51min
13.477790s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 3min
11.205977s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:53 nadc1-pfence-01 systemd: apt-daily.timer: Adding 5h 51min
13.477790s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd: anacron.timer: Adding 3min 11.205977s
random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd: Reloading.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: apt-daily.timer: Adding 15min
34.916876s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd[1]: anacron.timer: Adding 1min
5.946330s random time.
Jun 5 06:02:54 nadc1-pfence-01 systemd[1]: Reloading.
Jun 5 06:02:53 nadc1-pfence-01 systemd: apt-daily.timer: Adding 15min
34.916876s random time.
Jun 5 06:02:53 nadc1-pfence-01 systemd: anacron.timer: Adding 1min 5.946330s
random time.
Jun 5 06:02:54 nadc1-pfence-01 systemd: Reloading.
PRIVACY NOTICE: The information contained in this e-mail, including any
attachments, is confidential and intended only for the named recipient(s).
Unauthorized use, disclosure, forwarding, or copying is strictly prohibited and
may be unlawful. If you are not the intended recipient, please delete the
e-mail and any attachments and notify us immediately by return e-mail.
_______________________________________________
PacketFence-users mailing list
PacketFence-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/packetfence-users
