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.2ubuntu8amd64
high-performance and highly configurable RADIUS server
ii freeradius-common 2.1.12+dfsg-1.2ubuntu8all
FreeRADIUS common files
ii freeradius-mysql
