Hi, I'm having the following problem:
I'm using Radiator (2.18.4) and have all of my data on a remote Oracle (8.1.6) server. Both machines are Sun Netra with Solaris 8. Perl version is 5.6.1. There are two instances of Radiator (one for authentication and the other for accounting). The problem is the following. If the Oracle server goes down, the queries time out (that's reasonable). The point is some times (not after every SQL timeout, but after some of them), Radiator goes down. It seems to be that this happens when the query in question is necessary as part of the authentication (e.g. during a username lookup or simultaneous use or port limit check), but not when it is nonessential (as a deletion from the radonline table for the nas/port recently received or an insertion in an AuthLog). On only one ocassion I saw the "Could not connect to any SQL database. Request is ignored. Backing off for 600 second" message, but even that time, Radiator went down. I'm using daemontool's supervise (http://cr.yp.to/daemontools.html) to keep the servers running so the server starts up again almost immediately. I see the messages when it is starting again in the log. The question is, why is Radiator silently shutting down rather than backing off? One of the main problems is that on the almost immediate restart, the first thing Radiator tries to do is to read the client list from the database. If Oracle is still down, it won't read it, it won't retry, and (since there are no hardwired <Client>'s in the config file, it won't accept anything from any NAS. Regretfully, supervise's log is autorotated and autoerased on a size basis and I don't have the output to correlate with Radiator's log. I'm attaching parts of the logs showing the SQL Timeout error immediately followed by Radiator starting up again (via supervise). The "DEBUG: Adding Clients from SQL database" is the first message issued by a NEW Radiator starting. I'm also attaching the whole set of configuration files (the main one is radius-main.cfg) in a zip file. -- Mariano Absatz El Baby ---------------------------------------------------------- Is it time for your medication or mine?
============================================================================================
Tue Nov 27 07:47:37 2001: DEBUG: Packet dump:
*** Received from 200.49.64.41 port 32975 ....
Code: Access-Request
Identifier: 24
Authentic: <129><190><181><195><164>JiuJ[|nc<142><169><250>
Attributes:
NAS-Identifier = "200.49.64.21"
User-Name = "fpopular@pbmi"
CHAP-Password = <1><149><216><0><186>*H<226><11>}<239>A~<181><197>#`
Called-Station-Id = "0390"
Calling-Station-Id = "1146445069"
NAS-Port = 2380
NAS-Port-Type = Async
Framed-Protocol = PPP
Service-Type = Framed-User
Proxy-State = <0><2><171><211>
Tue Nov 27 07:47:37 2001: DEBUG: Rewrote user name to fpopular@pbmi
Tue Nov 27 07:47:37 2001: DEBUG: Check if Handler Pert-PreRegUser-Flag = 1,
Request-Type = Access-Request should be used to hand
le this request
Tue Nov 27 07:47:37 2001: DEBUG: Check if Handler Request-Type = Access-Request should
be used to handle this request
Tue Nov 27 07:47:37 2001: DEBUG: Handling request with Handler 'Request-Type =
Access-Request'
Tue Nov 27 07:47:37 2001: DEBUG: Rewrote user name to fpopular@pbmi
Tue Nov 27 07:47:37 2001: DEBUG: SessDBUsers Deleting session for fpopular@pbmi,
200.49.64.21, 2380
Tue Nov 27 07:47:37 2001: DEBUG: do query is: DELETE FROM USUARIOS_EN_LINEA WHERE
USUA_IP_NAS='200.49.64.21' AND USUA_PORT=02380
Tue Nov 27 07:47:51 2001: DEBUG: Handling with Radius::AuthSQL
Tue Nov 27 07:47:51 2001: DEBUG: Handling with Radius::AuthSQL: UserGetPassword
Tue Nov 27 07:47:51 2001: DEBUG: Query is: SELECT U.USU_CLAVE, S.SER_CODIGO,
S.SER_MAX_SESSION_CONCURRENTES, S.TIMEFRAMEID, S.SE
R_GEN_CHECK, S.SER_GEN_REPLY, U.USU_IP_NRO_FIJA, U.USU_IP_MASC_FIJA,
U.USU_TIEMPO_RESTANTE, U.USU_BYTES_RESTANTES, U.USU_SUSPEND
IDO, U.USU_GEN_CHECK, U.USU_GEN_REPLY, VS.VISP_SER_VALID_DNIS FROM USUARIOS U, VISP V,
SERVICIOS S, VISP_SERVICIOS VS WHERE U.VI
SP_CODIGO = V.VISP_CODIGO AND U.SER_CODIGO = S.SER_CODIGO AND U.USU_CODIGO =
'fpopular' AND U.VISP_CODIGO = 'pbmi' AND V.VISP_CO
DIGO = VS.VISP_CODIGO AND S.SER_CODIGO = VS.SER_CODIGO AND '0390' LIKE
VS.VISP_SER_VALID_DNIS
Tue Nov 27 07:48:51 2001: ERR: Execute failed for 'SELECT U.USU_CLAVE, S.SER_CODIGO,
S.SER_MAX_SESSION_CONCURRENTES, S.TIMEFRAME
ID, S.SER_GEN_CHECK, S.SER_GEN_REPLY, U.USU_IP_NRO_FIJA, U.USU_IP_MASC_FIJA,
U.USU_TIEMPO_RESTANTE, U.USU_BYTES_RESTANTES, U.USU
_SUSPENDIDO, U.USU_GEN_CHECK, U.USU_GEN_REPLY, VS.VISP_SER_VALID_DNIS FROM USUARIOS U,
VISP V, SERVICIOS S, VISP_SERVICIOS VS WH
ERE U.VISP_CODIGO = V.VISP_CODIGO AND U.SER_CODIGO = S.SER_CODIGO AND U.USU_CODIGO =
'fpopular' AND U.VISP_CODIGO = 'pbmi' AND V
.VISP_CODIGO = VS.VISP_CODIGO AND S.SER_CODIGO = VS.SER_CODIGO AND '0390' LIKE
VS.VISP_SER_VALID_DNIS': SQL Timeout
Tue Nov 27 07:49:01 2001: DEBUG: Adding Clients from SQL database
Tue Nov 27 07:49:01 2001: DEBUG: Query is: SELECT NAS_IP_ADDRESS, NAS_SECRET,
NAS_IGNOREACCTSIGNATURE, NAS_DUPINTERVAL, NA
S_DEFAULTREALM, NAS_TYPE, NAS_SNMPCOMMUNITY, NAS_LIVINGSTONOFFS, NAS_LIVINGSTONHOLE,
NAS_FRAMEDGROUPBASEADDRESS, NAS_FRAMEDGROUP
MAXPORTSPERCLAS, NAS_REWRITEUSERNAME, NAS_NOIGNOREDUPLICATES, NAS_PREHANDLERHOOK FROM
NAS
Tue Nov 27 07:49:10 2001: DEBUG: Reclaiming expired leases
Tue Nov 27 07:49:10 2001: DEBUG: do query is: UPDATE POOL_IP SET OCUPADA = 0,
TIME_STAMP = 1006858150 WHERE OCUPADA != 0 AND EXP
IRA < 1006858150
Tue Nov 27 07:49:11 2001: WARNING: Unknown service name
Tue Nov 27 07:49:11 2001: INFO: Server started: Radiator 2.18.4 on radius1
============================================================================================
Tue Nov 27 09:52:05 2001: DEBUG: Packet dump:
*** Received from 200.49.64.41 port 32975 ....
Code: Access-Request
Identifier: 222
Authentic: <23>(<238><188><227><247><248><251>+!(+5<196>"|
Attributes:
NAS-Identifier = "200.49.64.21"
User-Name = "arph080@pbm"
CHAP-Password = <1><196><255>&(d<208><219><127>k<227><198><2><225>As<20>
Called-Station-Id = "0380"
Calling-Station-Id = "1149313164"
NAS-Port = 1386
NAS-Port-Type = Async
Framed-Protocol = PPP
Service-Type = Framed-User
Proxy-State = <0><2><177><164>
Tue Nov 27 09:52:05 2001: DEBUG: Rewrote user name to arph080@pbm
Tue Nov 27 09:52:05 2001: DEBUG: Check if Handler Pert-PreRegUser-Flag = 1,
Request-Type = Access-Request should be used to hand
le this request
Tue Nov 27 09:52:05 2001: DEBUG: Check if Handler Request-Type = Access-Request should
be used to handle this request
Tue Nov 27 09:52:05 2001: DEBUG: Handling request with Handler 'Request-Type =
Access-Request'
Tue Nov 27 09:52:05 2001: DEBUG: Rewrote user name to arph080@pbm
Tue Nov 27 09:52:05 2001: DEBUG: SessDBUsers Deleting session for arph080@pbm,
200.49.64.21, 1386
Tue Nov 27 09:52:05 2001: DEBUG: do query is: DELETE FROM USUARIOS_EN_LINEA WHERE
USUA_IP_NAS='200.49.64.21' AND USUA_PORT=01386
Tue Nov 27 09:53:05 2001: ERR: do failed for 'DELETE FROM USUARIOS_EN_LINEA WHERE
USUA_IP_NAS='200.49.64.21' AND USUA_PORT=01386
': SQL Timeout
Tue Nov 27 09:54:23 2001: DEBUG: Handling with Radius::AuthSQL
Tue Nov 27 09:54:23 2001: DEBUG: Handling with Radius::AuthSQL: UserGetPassword
Tue Nov 27 09:54:23 2001: DEBUG: Query is: SELECT U.USU_CLAVE, S.SER_CODIGO,
S.SER_MAX_SESSION_CONCURRENTES, S.TIMEFRAMEID, S.SE
R_GEN_CHECK, S.SER_GEN_REPLY, U.USU_IP_NRO_FIJA, U.USU_IP_MASC_FIJA,
U.USU_TIEMPO_RESTANTE, U.USU_BYTES_RESTANTES, U.USU_SUSPEND
IDO, U.USU_GEN_CHECK, U.USU_GEN_REPLY, VS.VISP_SER_VALID_DNIS FROM USUARIOS U, VISP V,
SERVICIOS S, VISP_SERVICIOS VS WHERE U.VI
SP_CODIGO = V.VISP_CODIGO AND U.SER_CODIGO = S.SER_CODIGO AND U.USU_CODIGO = 'arph080'
AND U.VISP_CODIGO = 'pbm' AND V.VISP_CODI
GO = VS.VISP_CODIGO AND S.SER_CODIGO = VS.SER_CODIGO AND '0380' LIKE
VS.VISP_SER_VALID_DNIS
Tue Nov 27 09:54:23 2001: DEBUG: Radius::AuthSQL looks for match with arph080@pbm
Tue Nov 27 09:54:23 2001: DEBUG: Query is: SELECT USUA_IP_NAS, USUA_PORT,
USUA_SESION_ID FROM USUARIOS_EN_LINEA WHERE USU_CODIGO
='arph080' AND VISP_CODIGO='pbm'
Tue Nov 27 09:54:23 2001: DEBUG: Radius::AuthSQL ACCEPT:
Tue Nov 27 09:54:23 2001: DEBUG: Handling with PORTLIMITCHECK
Tue Nov 27 09:54:23 2001: DEBUG: Query is: SELECT COUNT(*) FROM USUARIOS_EN_LINEA
WHERE VISP_CODIGO = 'pbm' AND SER_CODIGO = 'Te
letrabajo_PBM' AND '0380' LIKE VISP_SER_VALID_DNIS
Tue Nov 27 09:54:23 2001: DEBUG: PORTLIMITCHECK got a current session count of 8
Tue Nov 27 09:54:23 2001: DEBUG: Query is: SELECT VISP_SER_CANT_PORTS FROM
VISP_SERVICIOS WHERE VISP_CODIGO = 'pbm' AND SER_CODI
GO = 'Teletrabajo_PBM' AND '0380' LIKE VISP_SER_VALID_DNIS
Tue Nov 27 09:54:23 2001: DEBUG: PORTLIMITCHECK got a limit of 200
Tue Nov 27 09:54:23 2001: DEBUG: Handling with Radius::AuthDYNADDRESS
Tue Nov 27 09:54:26 2001: DEBUG: Time frame 32: 4294967295 seconds until the end of TF.
Tue Nov 27 09:54:26 2001: DEBUG: No timeout set, using 4294967295 until the end of TF.
Tue Nov 27 09:54:26 2001: DEBUG: Service code: Teletrabajo_PBM.
Tue Nov 27 09:54:26 2001: DEBUG: Valid DNIS: %0380.
Tue Nov 27 09:54:26 2001: DEBUG: Access accepted for arph080@pbm
Tue Nov 27 09:54:26 2001: DEBUG: do query is: INSERT INTO AUTH_LOG
(ACCESS_OK,TIME_STAMP,DISP_TIMESTAMP,USERNAME, USU_CODIGO,VIS
P_CODIGO,PASSWORD,SEVERITY,REASON) VALUES ('OK',1006865666,'Tue 27-Nov-2001
09:54:26','arph080@pbm', 'arph080','pbm',SUBSTR('',1
,20),00,SUBSTR('',1,120))
Tue Nov 27 09:54:26 2001: DEBUG: Packet dump:
*** Sending to 200.49.64.41 port 32975 ....
Code: Access-Accept
Identifier: 222
Authentic: <23>(<238><188><227><247><248><251>+!(+5<196>"|
Attributes:
Proxy-State = <0><2><177><164>
Framed-IP-Address = 255.255.255.254
Service-Type = Framed-User
Framed-Protocol = PPP
Session-Timeout = 4294967295
Class = "Teletrabajo_PBM:%0380"
============================================================================================
Tue Nov 27 09:57:48 2001: DEBUG: Packet dump:
*** Received from 200.49.64.41 port 32982 ....
Code: Access-Request
Identifier: 251
Authentic: T<28><10><140>c<144>a@<7>{<28><193><17>:j<24>
Attributes:
NAS-Identifier = "200.49.64.32"
User-Name = "arph144@pbm"
CHAP-Password = <1><206><137>[T<155><218><217><132>EKqa<170><223><214><31>
Called-Station-Id = "0380"
Calling-Station-Id = "1142028623"
NAS-Port = 2339
NAS-Port-Type = Async
Framed-Protocol = PPP
Service-Type = Framed-User
Proxy-State = <0><4>K<132>
Tue Nov 27 09:57:48 2001: DEBUG: Rewrote user name to arph144@pbm
Tue Nov 27 09:57:48 2001: DEBUG: Check if Handler Pert-PreRegUser-Flag = 1,
Request-Type = Access-Request should be used to hand
le this request
Tue Nov 27 09:57:48 2001: DEBUG: Check if Handler Request-Type = Access-Request should
be used to handle this request
Tue Nov 27 09:57:48 2001: DEBUG: Handling request with Handler 'Request-Type =
Access-Request'
Tue Nov 27 09:57:48 2001: DEBUG: Rewrote user name to arph144@pbm
Tue Nov 27 09:57:48 2001: DEBUG: SessDBUsers Deleting session for arph144@pbm,
200.49.64.32, 2339
Tue Nov 27 09:57:48 2001: DEBUG: do query is: DELETE FROM USUARIOS_EN_LINEA WHERE
USUA_IP_NAS='200.49.64.32' AND USUA_PORT=02339
Tue Nov 27 09:57:48 2001: DEBUG: Handling with Radius::AuthSQL
Tue Nov 27 09:57:48 2001: DEBUG: Handling with Radius::AuthSQL: UserGetPassword
Tue Nov 27 09:57:48 2001: DEBUG: Query is: SELECT U.USU_CLAVE, S.SER_CODIGO,
S.SER_MAX_SESSION_CONCURRENTES, S.TIMEFRAMEID, S.SE
R_GEN_CHECK, S.SER_GEN_REPLY, U.USU_IP_NRO_FIJA, U.USU_IP_MASC_FIJA,
U.USU_TIEMPO_RESTANTE, U.USU_BYTES_RESTANTES, U.USU_SUSPEND
IDO, U.USU_GEN_CHECK, U.USU_GEN_REPLY, VS.VISP_SER_VALID_DNIS FROM USUARIOS U, VISP V,
SERVICIOS S, VISP_SERVICIOS VS WHERE U.VI
SP_CODIGO = V.VISP_CODIGO AND U.SER_CODIGO = S.SER_CODIGO AND U.USU_CODIGO = 'arph144'
AND U.VISP_CODIGO = 'pbm' AND V.VISP_CODI
GO = VS.VISP_CODIGO AND S.SER_CODIGO = VS.SER_CODIGO AND '0380' LIKE
VS.VISP_SER_VALID_DNIS
Tue Nov 27 09:57:48 2001: DEBUG: Radius::AuthSQL looks for match with arph144@pbm
Tue Nov 27 09:57:48 2001: DEBUG: Query is: SELECT USUA_IP_NAS, USUA_PORT,
USUA_SESION_ID FROM USUARIOS_EN_LINEA WHERE USU_CODIGO
='arph144' AND VISP_CODIGO='pbm'
Tue Nov 27 09:57:48 2001: DEBUG: Radius::AuthSQL ACCEPT:
Tue Nov 27 09:57:48 2001: DEBUG: Handling with PORTLIMITCHECK
Tue Nov 27 09:57:48 2001: DEBUG: Query is: SELECT COUNT(*) FROM USUARIOS_EN_LINEA
WHERE VISP_CODIGO = 'pbm' AND SER_CODIGO = 'Te
letrabajo_PBM' AND '0380' LIKE VISP_SER_VALID_DNIS
Tue Nov 27 09:58:48 2001: ERR: Execute failed for 'SELECT COUNT(*) FROM
USUARIOS_EN_LINEA WHERE VISP_CODIGO = 'pbm' AND SER_CODI
GO = 'Teletrabajo_PBM' AND '0380' LIKE VISP_SER_VALID_DNIS': SQL Timeout
Tue Nov 27 10:03:10 2001: DEBUG: Adding Clients from SQL database
Tue Nov 27 10:03:10 2001: DEBUG: Query is: SELECT NAS_IP_ADDRESS, NAS_SECRET,
NAS_IGNOREACCTSIGNATURE, NAS_DUPINTERVAL, NA
S_DEFAULTREALM, NAS_TYPE, NAS_SNMPCOMMUNITY, NAS_LIVINGSTONOFFS, NAS_LIVINGSTONHOLE,
NAS_FRAMEDGROUPBASEADDRESS, NAS_FRAMEDGROUP
MAXPORTSPERCLAS, NAS_REWRITEUSERNAME, NAS_NOIGNOREDUPLICATES, NAS_PREHANDLERHOOK FROM
NAS
Tue Nov 27 10:03:16 2001: DEBUG: Reclaiming expired leases
Tue Nov 27 10:03:16 2001: DEBUG: do query is: UPDATE POOL_IP SET OCUPADA = 0,
TIME_STAMP = 1006866196 WHERE OCUPADA != 0 AND EXP
IRA < 1006866196
Tue Nov 27 10:03:17 2001: WARNING: Unknown service name
Tue Nov 27 10:03:17 2001: INFO: Server started: Radiator 2.18.4 on radius2
============================================================================================
etc.zip
Description: Zip archive
