Bug in rlm_sql reconnect code??

3 Nov 2006

      Hello List,

the following I have tested with freeradius 1.1.2 and 1.1.3

I run a radius-server as test environment. The server is connected to a mysql-database. After 
long idles the mysql-server drops the radius client connections. After that the reconnect fails 
as you can see in the following output from radiusd -X.
The first packet gets a accept response, the following 2 packets get reject responses 
because the database queries fail.

rlm_sql (AuthGuest): - sql_groupcmp
radius_xlat:  '000f1fcc8e87'
rlm_sql (AuthGuest): sql_set_user escaped user --> '000f1fcc8e87'
radius_xlat:  'SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87''
rlm_sql (AuthGuest): Reserving sql socket id: 1
rlm_sql_mysql: query:  SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87'
rlm_sql (AuthGuest): - sql_groupcmp finished: User belongs in group MAC
rlm_sql (AuthGuest): Released sql socket id: 1
    users: Matched entry DEFAULT at line 162
  modcall[authorize]: module "files" returns ok for request 0
modcall: leaving group authorize (returns ok) for request 0
  rad_check_password:  Found Auth-Type Accept
  rad_check_password: Auth-Type = Accept, accepting the user
Login OK: [000f1fcc8e87] (from client noc4 port 0)
Sending Access-Accept of id 10 to 134.95.129.28 port 1025
        User-Name := ""
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 10 with timestamp 454aea03
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 134.95.129.28:1025, id=192,
length=56
        User-Name = "000f1fcc8e87"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
        Acct-Session-Id = "000021c0"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
rlm_sql (AuthGuest): - sql_groupcmp
radius_xlat:  '000f1fcc8e87'
rlm_sql (AuthGuest): sql_set_user escaped user --> '000f1fcc8e87'
radius_xlat:  'SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87''
rlm_sql (AuthGuest): Reserving sql socket id: 0
rlm_sql_mysql: query:  SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87'
rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
rlm_sql (AuthGuest): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (AuthGuest): Connected new DB handle, #0
rlm_sql (AuthGuest): failed after re-connect
rlm_sql (AuthGuest): Released sql socket id: 0
rlm_sql (AuthGuest): - sql_groupcmp finished: User does not belong in group
ADMIN
Invalid operator for item Sql-Group: reverting to '=='
rlm_sql (AuthGuest): - sql_groupcmp
radius_xlat:  '000f1fcc8e87'
rlm_sql (AuthGuest): sql_set_user escaped user --> '000f1fcc8e87'
radius_xlat:  'SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87''
rlm_sql (AuthGuest): Reserving sql socket id: 4
rlm_sql_mysql: query:  SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87'
rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
rlm_sql (AuthGuest): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (AuthGuest): Connected new DB handle, #4
rlm_sql (AuthGuest): failed after re-connect
rlm_sql (AuthGuest): Released sql socket id: 4
rlm_sql (AuthGuest): - sql_groupcmp finished: User does not belong in group
RZKR
Invalid operator for item Sql-Group: reverting to '=='
No huntgroup access: [000f1fcc8e87] (from client noc4 port 0)
  modcall[authorize]: module "preprocess" returns reject for request 1
modcall: leaving group authorize (returns reject) for request 1
Invalid user: [000f1fcc8e87/<no User-Password attribute>] (from client noc4
port 0)
Delaying request 1 for 4 seconds
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 4 seconds...
rad_recv: Access-Request packet from host 134.95.129.28:1025, id=192,
length=56
Sending Access-Reject of id 192 to 134.95.129.28 port 1025
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 192 with timestamp 454b615d
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 134.95.129.28:1025, id=87,
length=56
        User-Name = "000f1fcc8e87"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
        Acct-Session-Id = "00002657"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 2
rlm_sql (AuthGuest): - sql_groupcmp
radius_xlat:  '000f1fcc8e87'
rlm_sql (AuthGuest): sql_set_user escaped user --> '000f1fcc8e87'
radius_xlat:  'SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87''
rlm_sql (AuthGuest): Reserving sql socket id: 3
rlm_sql_mysql: query:  SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87'
rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
rlm_sql (AuthGuest): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (AuthGuest): Connected new DB handle, #3
rlm_sql (AuthGuest): failed after re-connect
rlm_sql (AuthGuest): Released sql socket id: 3
rlm_sql (AuthGuest): - sql_groupcmp finished: User does not belong in group
ADMIN
Invalid operator for item Sql-Group: reverting to '=='
rlm_sql (AuthGuest): - sql_groupcmp
radius_xlat:  '000f1fcc8e87'
rlm_sql (AuthGuest): sql_set_user escaped user --> '000f1fcc8e87'
radius_xlat:  'SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87''
rlm_sql (AuthGuest): Reserving sql socket id: 2
rlm_sql_mysql: query:  SELECT GroupName FROM usergroup WHERE
UserName='000f1fcc8e87'
rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
rlm_sql (AuthGuest): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (AuthGuest): Connected new DB handle, #2
rlm_sql (AuthGuest): failed after re-connect
rlm_sql (AuthGuest): Released sql socket id: 2
rlm_sql (AuthGuest): - sql_groupcmp finished: User does not belong in group
RZKR
Invalid operator for item Sql-Group: reverting to '=='
No huntgroup access: [000f1fcc8e87] (from client noc4 port 0)
  modcall[authorize]: module "preprocess" returns reject for request 2
modcall: leaving group authorize (returns reject) for request 2
Invalid user: [000f1fcc8e87/<no User-Password attribute>] (from client noc4
port 0)
Delaying request 2 for 4 seconds
Finished request 2
Going to the next request
--- Walking the entire request list ---
Waking up in 4 seconds...
rad_recv: Access-Request packet from host 134.95.129.28:1025, id=87,
length=56
Sending Access-Reject of id 87 to 134.95.129.28 port 1025
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 2 ID 87 with timestamp 454b6165
Nothing to do.  Sleeping until we see a request.

Grüße

Hans-Peter Fuchs

Hans-Peter Fuchs - RRZK Zimmer 20
Zentrum für angewandte Informatik - Universitätsweiter Service RRZK
Universität zu Köln - Tel: 0221-470-6972