(RADIATOR) Radiator going down after Oracle SQL Timeout
Mariano Absatz
radiator at lists.com.ar
Wed Dec 12 15:14:07 CST 2001
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?
-------------- next part --------------
============================================================================================
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 at 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 at 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 at pbmi
Tue Nov 27 07:47:37 2001: DEBUG: SessDBUsers Deleting session for fpopular at 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 at 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 at 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 at pbm
Tue Nov 27 09:52:05 2001: DEBUG: SessDBUsers Deleting session for arph080 at 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 at 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 at 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 at 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 at 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 at 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 at pbm
Tue Nov 27 09:57:48 2001: DEBUG: SessDBUsers Deleting session for arph144 at 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 at 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
============================================================================================
-------------- next part --------------
A non-text attachment was scrubbed...
Name: etc.zip
Type: application/zip
Size: 6359 bytes
Desc: not available
URL: <http://www.open.com.au/pipermail/radiator/attachments/20011212/f081b3d0/attachment.zip>
More information about the radiator
mailing list