systemctl start-up not working correctly
Good morning! I'm seeing some strange behavior when I attempt to start FreeRADIUS (3.0.18) using the systemctl command on CentOS 7. After issuing the 'start' command, I'm left staring at a blank line for about a minute; systemctl then exits and radiusd appears to be running. However, watching the radius.log file, what I see is something like this: Tue Mar 12 08:39:15 2019 : Info: Debugger not attached Tue Mar 12 08:39:15 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:39:15 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:39:15 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:39:15 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server default Tue Mar 12 08:39:15 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:39:15 2019 : Info: Ready to process requests Tue Mar 12 08:40:45 2019 : Info: Signalled to terminate Tue Mar 12 08:40:45 2019 : Info: Exiting normally Tue Mar 12 08:40:50 2019 : Info: Debugger not attached Tue Mar 12 08:40:50 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:40:50 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:40:50 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:40:50 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server default Tue Mar 12 08:40:50 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:40:50 2019 : Info: Ready to process requests Tue Mar 12 08:41:33 2019 : Info: Signalled to terminate Tue Mar 12 08:41:33 2019 : Info: Exiting normally Tue Mar 12 08:41:36 2019 : Info: Debugger not attached Tue Mar 12 08:41:36 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:41:36 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:41:36 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:41:36 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server default Tue Mar 12 08:41:36 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:41:36 2019 : Info: Ready to process requests As you can see, about once every minute and a half or so, something is signalling radiusd to exit, and it then restarts. If I use 'radiusd -X' (I've not included that output because everything looks perfectly normal), everything starts normally, and then it just waits patiently for connections, but it never terminates and restarts. Similarly, if I start it using just the command 'radiusd', everything works as it should. It's looks as though there's something amiss with the systemctl radius.service file. For the life or me, though, I can't figure out what, and I've never seen this sort of behavior before. In case anyone wonders, here's the radiusd.service contents: [Unit] Description=FreeRADIUS multi-protocol policy server After=network-online.target Documentation=man:radiusd(8) man:radiusd.conf(5) http://wiki.freeradius.org/ http://networkradius.com/doc/ [Service] Type=notify WatchdogSec=60 NotifyAccess=all PIDFile=/var/run/radiusd/radiusd.pid EnvironmentFile=-/etc/sysconfig/radiusd # FreeRADIUS can do static evaluation of policy language rules based # on environmental variables which is very useful for doing per-host # customization. # Unfortunately systemd does not allow variable substitutions such # as %H or $(hostname) in the EnvironmentFile. # We provide HOSTNAME here for convenience. Environment=HOSTNAME=%H # Limit memory to 2G this is fine for %99.99 of deployments. FreeRADIUS # is not memory hungry, if it's using more than this, then there's probably # a leak somewhere. MemoryLimit=2G RuntimeDirectory=radiusd RuntimeDirectoryMode=0775 ExecStartPre=/usr/sbin/radiusd $FREERADIUS_OPTIONS -Cx -lstdout ExecStartPre=/usr/bin/chown radiusd:radiusd /var/run/radiusd ExecStart=/usr/sbin/radiusd $FREERADIUS_OPTIONS Restart=on-failure RestartSec=5 [Install] WantedBy=multi-user.target I've seen other notes that are *similar* to this, but many refer to the process not starting at boot. This happens at boot, as well as any other time we use systemctl to start the service. So, again, it appears to be something with the systemctl unit. Any help will be greatly appreciated. -- Jim
On Tue, 2019-03-12 at 09:00 -0400, J Kephart wrote:
Good morning! I'm seeing some strange behavior when I attempt to start FreeRADIUS (3.0.18) using the systemctl command on CentOS 7. After issuing the 'start' command, I'm left staring at a blank line for about a minute; systemctl then exits and radiusd appears to be running.
There are problems with 3.0.18 and systemctl :-( Please use v3.0.x HEAD - it's fixed there. -- Matthew
Found some additional information from the system log, that shows the following, again related to the systemctl start command: radiusd.service start operation timed out. Terminating. Mar 12 08:40:45 fr-01 systemd: Failed to start FreeRADIUS multi-protocol policy server. Mar 12 08:40:45 fr-01 systemd: Unit radiusd.service entered failed state. Mar 12 08:40:45 fr-01 systemd: radiusd.service failed. Mar 12 08:40:50 fr-01 systemd: radiusd.service holdoff time over, scheduling restart. Mar 12 08:40:50 fr-01 systemd: Stopped FreeRADIUS multi-protocol policy server. Mar 12 08:40:50 fr-01 systemd: Starting FreeRADIUS multi-protocol policy server... Despite that, however, radiusd *is* running. Very bizarre.
On Tue, 2019-03-12 at 10:08 -0400, J Kephart wrote:
Found some additional information from the system log, that shows the following, again related to the systemctl start command:
radiusd.service start operation timed out. Terminating. ...
Despite that, however, radiusd *is* running. Very bizarre.
I already said 3.0.18 is broken with systemctl... -- Matthew
Hello Jim, despite other posts, stating systmctl interface fore 3.0.18 is broken, here is my diagnosis: with the service definition below, systemd expects radiusd to trigger the watchdog every 60 sec. Radiusd obviously doesn't honor this (what exactly expects systemd to be done???) As a first measure, try and comment out at least the line --> WatchdogSec=60 or better change the service type to a less sophisticated one (no notification) *Andreas Schindler* Klappacher Str. 2-i D 64285 Darmstadt <https://www.openstreetmap.org/?mlat=49.8623&mlon=8.65461#map=17/49.8623/8.65461> E-Mail: Andreas.Schindler@schindlerman.de <mailto:andreas.schindler@schindlerman.de> Tel: +49 1575 6384244 On 12.03.19 14:00, J Kephart wrote:
Good morning! I'm seeing some strange behavior when I attempt to start FreeRADIUS (3.0.18) using the systemctl command on CentOS 7. After issuing the 'start' command, I'm left staring at a blank line for about a minute; systemctl then exits and radiusd appears to be running. However, watching the radius.log file, what I see is something like this:
Tue Mar 12 08:39:15 2019 : Info: Debugger not attached Tue Mar 12 08:39:15 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:39:15 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:39:15 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:39:15 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server default Tue Mar 12 08:39:15 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:39:15 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:39:15 2019 : Info: Ready to process requests Tue Mar 12 08:40:45 2019 : Info: Signalled to terminate Tue Mar 12 08:40:45 2019 : Info: Exiting normally Tue Mar 12 08:40:50 2019 : Info: Debugger not attached Tue Mar 12 08:40:50 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:40:50 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:40:50 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:40:50 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server default Tue Mar 12 08:40:50 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:40:50 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:40:50 2019 : Info: Ready to process requests Tue Mar 12 08:41:33 2019 : Info: Signalled to terminate Tue Mar 12 08:41:33 2019 : Info: Exiting normally Tue Mar 12 08:41:36 2019 : Info: Debugger not attached Tue Mar 12 08:41:36 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Mar 12 08:41:36 2019 : Info: rlm_sql_mysql: libmysql version: 10.1.38-MariaDB Tue Mar 12 08:41:36 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server <default> Tue Mar 12 08:41:36 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server default Tue Mar 12 08:41:36 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:339 Tue Mar 12 08:41:36 2019 : Info: Loaded virtual server inner-tunnel Tue Mar 12 08:41:36 2019 : Info: Ready to process requests
As you can see, about once every minute and a half or so, something is signalling radiusd to exit, and it then restarts. If I use 'radiusd -X' (I've not included that output because everything looks perfectly normal), everything starts normally, and then it just waits patiently for connections, but it never terminates and restarts. Similarly, if I start it using just the command 'radiusd', everything works as it should. It's looks as though there's something amiss with the systemctl radius.service file. For the life or me, though, I can't figure out what, and I've never seen this sort of behavior before. In case anyone wonders, here's the radiusd.service contents:
[Unit] Description=FreeRADIUS multi-protocol policy server After=network-online.target Documentation=man:radiusd(8) man:radiusd.conf(5) http://wiki.freeradius.org/ http://networkradius.com/doc/
[Service] Type=notify WatchdogSec=60 NotifyAccess=all PIDFile=/var/run/radiusd/radiusd.pid EnvironmentFile=-/etc/sysconfig/radiusd
# FreeRADIUS can do static evaluation of policy language rules based # on environmental variables which is very useful for doing per-host # customization. # Unfortunately systemd does not allow variable substitutions such # as %H or $(hostname) in the EnvironmentFile. # We provide HOSTNAME here for convenience. Environment=HOSTNAME=%H
# Limit memory to 2G this is fine for %99.99 of deployments. FreeRADIUS # is not memory hungry, if it's using more than this, then there's probably # a leak somewhere. MemoryLimit=2G
RuntimeDirectory=radiusd RuntimeDirectoryMode=0775 ExecStartPre=/usr/sbin/radiusd $FREERADIUS_OPTIONS -Cx -lstdout ExecStartPre=/usr/bin/chown radiusd:radiusd /var/run/radiusd ExecStart=/usr/sbin/radiusd $FREERADIUS_OPTIONS Restart=on-failure RestartSec=5
[Install] WantedBy=multi-user.target
I've seen other notes that are *similar* to this, but many refer to the process not starting at boot. This happens at boot, as well as any other time we use systemctl to start the service. So, again, it appears to be something with the systemctl unit.
Any help will be greatly appreciated.
-- Jim - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Mar 13, 2019, at 3:10 AM, Andreas Schindler <andreas.schindler@schindlerman.de> wrote:
Hello Jim,
despite other posts, stating systmctl interface fore 3.0.18 is broken, here is my diagnosis:
with the service definition below, systemd expects radiusd to trigger the watchdog every 60 sec. Radiusd obviously doesn't honor this (what exactly expects systemd to be done???) As a first measure, try and comment out at least the line --> WatchdogSec=60 or better change the service type to a less sophisticated one (no notification)
Matthew Newton is one of the core developers of FreeRADIUS. He authored a patch series which fixed the outstanding issues with systemd integration, one of which was the watchdog client not firing and informing systemd that the process was still alive. If you want to contribute something useful to the discussion then confirm that v3.0.x HEAD works correctly with systemd in your environment. -Arran
participants (4)
-
Andreas Schindler -
Arran Cudbard-Bell -
J Kephart -
Matthew Newton