Comment 3 for bug 1081509

Revision history for this message
Florin Andrei (florin-andrei) wrote :

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 freeradius[1256]: rlm_sql (sql): Connected new DB handle, #4
Sep 9 12:17:56 yubi1 freeradius[1256]: Loaded virtual server <default>
Sep 9 12:17:56 yubi1 freeradius[1256]: Loaded virtual server inner-tunnel
Sep 9 12:17:56 yubi1 freeradius[1263]: Failed binding to authentication address * port 1812: Address already in use
Sep 9 12:17:56 yubi1 freeradius[1263]: /etc/freeradius/radiusd.conf[240]: Error binding to port for 0.0.0.0 port 1812
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1313]: Upgrading MySQL tables if necessary.
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1316]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1316]: Looking for 'mysql' as: /usr/bin/mysql
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1316]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1316]: This installation of MySQL is already upgraded to 5.5.38, use --force if you still need to run mysql_upgrade
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1327]: Checking for insecure root accounts.
Sep 9 12:17:57 yubi1 /etc/mysql/debian-start[1332]: Triggering myisam-recover for all MyISAM tables
#################################

As it's clear from the logs, the problem is that the FreeRadius service starts before MySQL, but FreeRadius depends on MySQL.

It should start after MySQL, just like many other services do.

This is the relevant software:

# dpkg -l | grep -e freeradius -e mysql
ii freeradius 2.1.12+dfsg-1.2ubuntu8 amd64 high-performance and highly configurable RADIUS server
ii freeradius-common 2.1.12+dfsg-1.2ubuntu8 all FreeRADIUS common files
ii freeradius-mysql 2.1.12+dfsg-1.2ubuntu8 amd64 MySQL module for FreeRADIUS server
ii freeradius-utils 2.1.12+dfsg-1.2ubuntu8 amd64 FreeRADIUS client utilities
ii libdbd-mysql-perl 4.025-1 amd64 Perl5 database interface to the MySQL database
ii libfreeradius2 2.1.12+dfsg-1.2ubuntu8 amd64 FreeRADIUS shared library
ii libmysqlclient18:amd64 5.5.38-0ubuntu0.14.04.1 amd64 MySQL database client library
ii mysql-client-5.5 5.5.38-0ubuntu0.14.04.1 amd64 MySQL database client binaries
ii mysql-client-core-5.5 5.5.38-0ubuntu0.14.04.1 amd64 MySQL database core client binaries
ii mysql-common 5.5.38-0ubuntu0.14.04.1 all MySQL database common files, e.g. /etc/mysql/my.cnf
ii mysql-server 5.5.38-0ubuntu0.14.04.1 all MySQL database server (metapackage depending on the latest version)
ii mysql-server-5.5 5.5.38-0ubuntu0.14.04.1 amd64 MySQL database server binaries and system database setup
ii mysql-server-core-5.5 5.5.38-0ubuntu0.14.04.1 amd64 MySQL database server binaries
ii php5-mysql 5.5.9+dfsg-1ubuntu4.3 amd64 MySQL module for php5