freeradius + mysql fails to start

[Ryan Tse]

freeradius fails to start when MySQL is a dependency to start. The usage of upstart from MySQL prevents specifying an earlier start level priority for MySQL to start first.

Wed Nov 21 01:22:19 2012 : Error: rlm_sql_mysql: Mysql error 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Wed Nov 21 01:22:19 2012 : Error: rlm_sql (sql): Failed to connect DB handle #0
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): There are no DB handles to use! skipped 5, tried to connect 0
Wed Nov 21 01:22:19 2012 : Error: Failed to load clients from SQL.
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): Closing sqlsocket 4
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): Closing sqlsocket 3
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): Closing sqlsocket 2
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): Closing sqlsocket 1
Wed Nov 21 01:22:19 2012 : Info: rlm_sql (sql): Closing sqlsocket 0
Wed Nov 21 01:22:19 2012 : Error: /etc/freeradius/sql.conf[22]: Instantiation failed for module "sql"
Wed Nov 21 01:22:19 2012 : Error: /etc/freeradius/sites-enabled/inner-tunnel[131]: Failed to load module "sql".
Wed Nov 21 01:22:19 2012 : Error: /etc/freeradius/sites-enabled/inner-tunnel[47]: Errors parsing authorize section.
Wed Nov 21 01:22:19 2012 : Error: Failed to load virtual server inner-tunnel

Description: Ubuntu 12.04.1 LTS
Release: 12.04

freeradius:
  Installed: 2.1.10+dfsg-3ubuntu0.12.04.1
  Candidate: 2.1.10+dfsg-3ubuntu0.12.04.1
  Version table:
 *** 2.1.10+dfsg-3ubuntu0.12.04.1 0
        500 http://us.archive.ubuntu.com/ubuntu/ precise-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu/ precise-security/main amd64 Packages
        100 /var/lib/dpkg/status
     2.1.10+dfsg-3build2 0
        500 http://us.archive.ubuntu.com/ubuntu/ precise/main amd64 Packages

[Yolanda Robla (yolanda.robla)]

Unfortunately, we aren't able to reproduce the issue with the same package version and platform.
Can you provide logs for all the installation process in order to verify it?
Thanks

[Launchpad Janitor (janitor)]

[Expired for freeradius (Ubuntu) because there has been no activity for 60 days.]

[Florin Andrei (florin-andrei)]

Wow, this is an old bug, still not fixed. I've stumbled upon this exact same problem last week. It's due to the fact that the freeradius service starts way too early.

Happens every time on Ubuntu 14.04.

apt-get update
apt-get dist-upgrade
apt-get install freeradius freeradius-mysql

I had the MySQL server already installed at this point, pulled as dependency for another package

Configure FreeRadius to use MySQL for authorization.

reboot

Now check syslog:

#################################
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql (sql): Attempting to connect to radius@localhost:/radius
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql_mysql: Starting connect to MySQL server for #0
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql_mysql: Couldn't connect socket to MySQL server radius@localhost:radius
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql_mysql: Mysql error 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Sep 9 12:17:55 yubi1 freeradius[970]: rlm_sql (sql): Failed to connect DB handle #0
Sep 9 12:17:55 yubi1 freeradius[970]: Loaded virtual server <default>
Sep 9 12:17:55 yubi1 freeradius[970]: Loaded virtual server inner-tunnel
Sep 9 12:17:55 yubi1 freeradius[970]: ... adding new socket proxy address * port 36585
Sep 9 12:17:55 yubi1 freeradius[970]: Ready to process requests.
Sep 9 12:17:55 yubi1 kernel: [ 4.588328] vboxsf: Successfully loaded version 4.3.14 (interface 0x00010004)
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect to radius@localhost:/radius
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql_mysql: Starting connect to MySQL server for #0
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Connected new DB handle, #0
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql_mysql: Starting connect to MySQL server for #1
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Connected new DB handle, #1
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql_mysql: Starting connect to MySQL server for #2
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Connected new DB handle, #2
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql_mysql: Starting connect to MySQL server for #3
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Connected new DB handle, #3
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
Sep 9 12:17:56 yubi1 freeradius[1256]: rlm_sql_mysql: Starting connect to MySQL server for #4
Sep 9 12:17:56 yubi1 freera...

[Florin Andrei (florin-andrei)]

As a stop-gap measure, I've added this to /etc/rc.local:

(sleep 10; service freeradius stop; service freeradius start) &

The first time freeradius is launched, it fails as usual. But then it's stopped and started again, and this time around seems to work fine.

A longer sleep time might be needed on busier systems.

It's not a proper fix, it's just something to prevent my systems from failing until the bug is truly fixed.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[sgofferj (sgofferj)]

I confirm the same problem for 14.04 LTS server as described here:
http://ubuntuforums.org/showthread.php?t=2254382

[Ragimiri (ragimiri)]

I confirm the same problem on 14.10 server. Still no solution?

[Punyal (p-punyal)]

There is a simple solution, just delay the booting of freeradius.

edit the file /etc/rc2.d/S99radiusd and add a delay of 5 seconds at the beggining.

#delay of 5 secs
sleep 5

[Christian Ehrhardt  (paelzer)]

@Mufeed - this seems like a random bug update to me.
Are you really intending to work on this old issue?
I'm not even sure it still applies in the same way.

[Andreas Hasenack (ahasenack)]

Please retry on a more recent Ubuntu release, at least xenial (16.04) and preferably bionic (18.04) or even eoan (19.10). I'll mark the bug incomplete until there is an update.

In particular, 16.04 and later are using systemd, not sysv, which is a big change in boot ordering.

[Rolf Leggewie (r0lf)]

expiring / obsolete

[Alan DeKok (aland-freeradius)]

The solution is well documented in FreeRADIUS. Just change the "pool" section of the "sql" module configuration. Set "start = 0"