packetfence-mariadb is using packetfence-config port (44444) when it restart on PacketFence upgrade (14.0 to 14.1)

[chri2]

Describe the bug
On a cluster of three nodes followed the Clustering and Upgrade documentation to upgrade the nodes.

Node A and Node C couldn't complete the postinst script of the packetfence package /var/lib/dpkg/info/packetfence.postinst .

Upgrade on Node B worked as expected.

To Reproduce
Upgrade a cluster from Packetfence 14.0 → 14.1 like described in the documentation. I don't know, yet, any circumstances that need to be met to trigger this bug.

Expected behavior
Upgrade should work on all of the nodes the same.

Additional context

Running dash -x /var/lib/dpkg/info/packetfence.postinst configure fails with:

+ systemctl start packetfence-config
Job for packetfence-config.service failed because the control process exited with error code.
See "systemctl status packetfence-config.service" and "journalctl -xeu packetfence-config.service" for details.

Here's some debugging information:

root@packetfence-demo-c3:~# journalctl -S-30m | grep 'bind: address already in use' | tail -n1
Mär 03 12:22:37 packetfence-demo-c3 pfconfig-docker-wrapper[3711507]: docker: Error response from daemon: driver failed programming external connectivity on endpoint pfconfig (06e5b4e6275468f46ae3ca70bc3e2ac392c42950a553028e984c0ff9058186ab): Error starting userland proxy: listen tcp4 100.64.0.1:44444: bind: address already in use.
root@packetfence-demo-c3:~# netstat -pna | grep 44444
tcp        0      0 100.64.0.1:44444        100.64.0.1:44444        ESTABLISHED 3677237/pf-mariadb  
root@packetfence-demo-c3:~# systemctl status packetfence-mariadb.service 
● packetfence-mariadb.service - PacketFence MariaDB instance
     Loaded: loaded (/lib/systemd/system/packetfence-mariadb.service; enabled; preset: enabled)
     Active: active (running) since Mon 2025-03-03 11:59:05 CET; 29min ago
   Main PID: 3677237 (pf-mariadb)
     Status: "Taking your SQL requests now..."
      Tasks: 11 (limit: 14298)
     Memory: 298.9M
        CPU: 3.701s
     CGroup: /packetfence.slice/packetfence-base.slice/packetfence-mariadb.service
             ├─3677237 pf-mariadb
             ├─3677434 /bin/sh /usr/bin/mysqld_safe --defaults-file=/usr/local/pf/var/conf/mariadb.conf
             ├─3677611 /usr/sbin/mariadbd --defaults-file=/usr/local/pf/var/conf/mariadb.conf --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin ->
             └─3677612 logger -t mysqld -p daemon error

Mär 03 12:13:11 packetfence-demo-c3 packetfence[3677237]: pf-mariadb(3677237) ERROR: [1741000391.32968] Failed to connect to config service for namespace resource::cluste>
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: Can't connect to pfconfig on containers-gateway.internal:44444 : Connection refused
Mär 03 12:13:11 packetfence-demo-c3 packetfence[3677237]: pf-mariadb(3677237) ERROR: [1741000391.43328] Failed to connect to config service for namespace resource::cluste>
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: [1741000391.43328] Failed to connect to config service for namespace resource::cluster_hosts(DEFAULT), retrying
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: Can't connect to pfconfig on containers-gateway.internal:44444 : Connection refused
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: [1741000391.53675] Failed to connect to config service for namespace resource::cluster_hosts(DEFAULT), retrying
Mär 03 12:13:11 packetfence-demo-c3 packetfence[3677237]: pf-mariadb(3677237) ERROR: [1741000391.53675] Failed to connect to config service for namespace resource::cluste>
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: Can't connect to pfconfig on containers-gateway.internal:44444 : Connection refused
Mär 03 12:13:11 packetfence-demo-c3 pf-mariadb[3677237]: [1741000391.63774] Failed to connect to config service for namespace resource::cluster_hosts(DEFAULT), retrying
Mär 03 12:13:11 packetfence-demo-c3 packetfence[3677237]: pf-mariadb(3677237) ERROR: [1741000391.63774] Failed to connect to config service for namespace resource::cluste>

Trying to stop mariadb via systemctl didn't work on both nodes:

root@packetfence-demo-c3:~# SYSTEMD_LOG_LEVEL=debug systemctl stop packetfence-mariadb.service 
Bus n/a: changing state UNSET → OPENING
sd-bus: starting bus by connecting to /run/systemd/private...
Bus n/a: changing state OPENING → AUTHENTICATING
Successfully forked off '(sd-askpwagent)' as PID 3712026.
Executing dbus call org.freedesktop.systemd1.Manager StopUnit(packetfence-mariadb.service, replace)
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StopUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=4 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=14 reply_cookie=2 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=15 reply_cookie=3 signature=v error-name=n/a error-message=n/a
Adding /org/freedesktop/systemd1/job/9868 to the set
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=2 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=3 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/job/9868 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
SELinux enabled state cached to: disabled
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=16 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=17 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=18 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=19 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=20 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=21 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=22 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=23 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=24 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/packetfence_2dmariadb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=25 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=26 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=27 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=28 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=29 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/_2d_2emount interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=30 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/_2d_2emount interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/shutdown_2etarget interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=32 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/systemd_2dlogind_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=33 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/systemd_2dlogind_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=34 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/user_400_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=35 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/user_400_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=36 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/user_2druntime_2ddir_400_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=37 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/user_2druntime_2ddir_400_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=38 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/user_2d0_2eslice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=39 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=40 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=41 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=42 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=43 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=44 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=45 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/session_2d98_2escope interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=46 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a

The systemctl command hangs and doesn't proceed. Looking at the mariadb log in another terminal shows:

root@packetfence-demo-c3:/usr/local/pf/logs# tail mariadb.log
2025-03-03T12:42:47.313032+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] /usr/sbin/mariadbd (initiated by: unknown): Normal shutdown
2025-03-03T12:42:47.339855+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: FTS optimize thread exiting.
2025-03-03T12:42:47.339926+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: Starting shutdown...
2025-03-03T12:42:47.339959+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2025-03-03T12:42:47.339998+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: Buffer pool(s) dump completed at 250303 12:42:47
2025-03-03T12:42:47.517889+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: Removed temporary tablespace data file: "/var/lib/mysql/ibtmp1"
2025-03-03T12:42:47.518010+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] InnoDB: Shutdown completed; log sequence number 4397636539; transaction id 20914031
2025-03-03T12:42:47.540069+01:00 packetfence-demo-c3 mysqld[3677612]: 2025-03-03 12:42:47 0 [Note] /usr/sbin/mariadbd: Shutdown complete
2025-03-03T12:42:47.540181+01:00 packetfence-demo-c3 mysqld[3677612]: 
2025-03-03T12:42:47.545489+01:00 packetfence-demo-c3 mysqld_safe[3712032]: mysqld from pid file /var/lib/mysql/packetfence-demo-c3.pid ended
root@packetfence-demo-c3:/usr/local/pf/logs# netstat -pna | grep mariadb
tcp        0      0 100.64.0.1:44444        100.64.0.1:44444        ESTABLISHED 3677237/pf-mariadb  
root@packetfence-demo-c3:/usr/local/pf/logs# ps axu | grep 3677237 | grep -v grep
root     3677237  0.0  0.6 1754572 82772 ?       Ss   11:59   0:02 pf-mariadb

The process doesn't seem to have ended and is still blocking tcp:44444 which pf-config is failing to bind to. Looking at the process I found:

root@packetfence-demo-c3:~# strace -p 3677237
strace: Process 3677237 attached
read(3, ^Cstrace: Process 3677237 detached
 <detached ...>

root@packetfence-demo-c3:~# ls -l /proc/3677237/fd/
total 0
lr-x------ 1 root root 64 Mär  3 12:28 0 -> /dev/null
lrwx------ 1 root root 64 Mär  3 12:28 1 -> 'socket:[33618954]'
lr-x------ 1 root root 64 Mär  3 12:28 12 -> '/usr/local/pf/lib_perl/lib/perl5/Net/DNS/Resolver/Base.pm (deleted)'
lrwx------ 1 root root 64 Mär  3 12:28 2 -> 'socket:[33618954]'
lrwx------ 1 root root 64 Mär  3 11:59 3 -> 'socket:[33690001]'
root@packetfence-demo-c3:~# ls -l /proc/*/fd/ | grep 33690001
lrwx------ 1 root root 64 Mär  3 11:59 3 -> socket:[33690001]

I didn't get any further trying to find out what is happening here.

To get on with the update I killed the broken mariadb process with pkill -9 pf-mariadb. In the other terminal with the stuck systemctl stop this resulted in Bus n/a: changing state RUNNING → CLOSED, the systemctl ended and the terminal ended in a prompt again.

Running apt-get install let the postinst script run again for the unconfigured packet and the configuration ended with

Installation complete
* Please fire up your Web browser and go to https://@ip_packetfence:1443 to complete your PacketFence configuration.
* Please stop your iptables service if you don't have access to configurator.

[JeGoi]

Ok that I have seen it . I have not clue the why yet AND it is very hard to reproduce AND looks completely random.

The issue is that when packetfence-mariadb restarts, it takes the same port as the port of packetfence-config 44444.
The only (far from perfect) way I found until now it to check if the port is used by mariadb or not.
If I recall correctly, I killed the pid associated with the port 44444.

I will bring it back to the team.
Thanks