Redundant SQL servers accounting problem, FreeRadius 1.1.4

[Alexander V. Klepikov]

Hello!

I set up redundant SQL PostgeSQL servers configuration:

modules{
...
    sql sql2 {
        server = "gw-core.up.ua"
        num_sql_socks = 3
...
    }
    sql sql1 {
        server = "sql.up.ua"
        num_sql_socks = 3
...
    }
}

authorize {
...
    redundant {
        sql2
        sql1
    }
}
...
accounting {
...
    redundant {
        sql2
        sql1
    }
}

If sql2 is up when I run FreeRadius, everything works fine. If sql2 is down 
when I start FreeRadius, everything works fine too and when sql2 comes up, 
Freeradius starts to use it. But when sql2 was up and then comes down (and 
FreeRadius is running), FreeRadius exits when it processes accounting query 
with message in syslog

kernel: pid 4516 (radiusd), uid 1002: exited on signal 6

I started it in debug mode:

#/usr/local/sbin/radiusd -X

...

  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0

...

modcall: entering group redundant  for request 0
radius_xlat:  'klepikov_av'
rlm_sql (sql2): sql_set_user escaped user --> 'klepikov_av'
radius_xlat:  'SELECT id, UserName, Attribute, Value, Op ??FROM radcheck 
??WHERE
 Username = 'klepikov_av' ??ORDER BY id'
rlm_sql (sql2): Reserving sql socket id: 2
rlm_sql_postgresql: Status: PGRES_FATAL_ERROR
rlm_sql_postgresql: affected rows =
rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning 
SQL_DOW
N
rlm_sql (sql2): Attempting to connect rlm_sql_postgresql #2
rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server 
radius at gw-core.
up.ua:radius_db
rlm_sql_postgresql: Postgresql error 'could not connect to server: 
Connection re
fused ?Is the server running on host gw-core.up.ua and accepting ?TCP/IP 
connect
ions on port 5432? '
rlm_sql (sql2): Failed to connect DB handle #2
rlm_sql (sql2): reconnect failed, database down?
rlm_sql_getvpdata: database query error
rlm_sql (sql2): SQL query error; rejecting user
rlm_sql (sql2): Released sql socket id: 2
  modcall[authorize]: module "sql2" returns fail for request 0
rlm_sql (sql1): sql_set_user escaped user --> 'klepikov_av'
radius_xlat:  'SELECT id, UserName, Attribute, Value, Op ??FROM radcheck 
??WHERE
 Username = 'klepikov_av' ??ORDER BY id'
rlm_sql (sql1): Reserving sql socket id: 1
rlm_sql_postgresql: Status: PGRES_TUPLES_OK

...

rlm_sql (sql1): Released sql socket id: 1
  modcall[authorize]: module "sql1" returns ok for request 0
modcall: leaving group redundant  (returns ok) for request 0
modcall: leaving group authorize (returns ok) for request 0

...

  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 1

...

modcall: entering group redundant  for request 1
radius_xlat:  'klepikov_av'
rlm_sql (sql2): sql_set_user escaped user --> 'klepikov_av'
radius_xlat:  'INSERT into radacct ??(AcctSessionId, AcctUniqueId, UserName, 
Rea
lm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctAuthentic, 
??Connec
tInfo_start, CalledStationId, CallingStationId, ServiceType, FramedProtocol, 
Fra
medIPAddress, AcctStartDelay) ??values('45FA990A460300', 'e55d351c2f2bdb96', 
'kl
epikov_av', 'up.ua', '10.0.0.1', ??'1', 'Async', ('2007-03-16 
15:18:02'::timesta
mp - '0'::interval), 'RADIUS', '', ??'', '10.1.1.3', 'Framed-User', 'PPP', 
??NUL
LIF('10.0.1.15', '')::inet, '0')'
rlm_sql (sql2): Reserving sql socket id: 0
rlm_sql_postgresql: Status: PGRES_FATAL_ERROR
rlm_sql_postgresql: affected rows =
rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning 
SQL_DOW
N
rlm_sql (sql2): Attempting to connect rlm_sql_postgresql #0
rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server 
radius at gw-core.
up.ua:radius_db
rlm_sql_postgresql: Postgresql error 'could not connect to server: 
Connection re
fused ?Is the server running on host gw-core.up.ua and accepting ?TCP/IP 
connect
ions on port 5432? '
rlm_sql (sql2): Failed to connect DB handle #0
rlm_sql (sql2): reconnect failed, database down?
rlm_sql (sql2): Couldn't insert SQL accounting START record - (null)
radius_xlat:  'UPDATE radacct ??SET AcctStartTime = ('2007-03-16 
15:18:02'::time
stamp - '0'::interval), AcctStartDelay = '0', ??ConnectInfo_start = '' WHERE 
Acc
tSessionId = '45FA990A460300' AND UserName = 'klepikov_av' ??AND 
NASIPAddress =
'10.0.0.1' AND AcctStopTime IS NULL'
rlm_sql_postgresql: PostgreSQL Query failed Error: no connection to the 
server
radiusd in free(): error: chunk is already free
Abort

It looks like accounting module cannot properly make a connection to SQL 
server, but authorize module can. I found that with num_sql_socks <= 2 
FreeRadius works perfect, I made several tests stopping and starting my SQL 
servers, everything works as it is described in manuals. It seemes to me 
that problem is somewhere in rlm_sql module, but I am not a programmer, so I 
can't just find it and write a patch.

I use FreeBSD 6.2, FreeRadius 1.1.4, PostgreSQL 7.3.15 (to be exact, 
PGCluster 1.0.11), the same problem was with PostgreSQL 8.2.3 (to be exact, 
PGCluster 1.7.0rc5)

To reproduce this problem, set up FreeRadius as mentioned above, start 
databases, start FreeRadius and then stop first database listed in redundant 
group.

With best regards, Alexander V. Klepikov.  E-mail: klepikov_a at up.ua

PS Sorry for my bad english