(RADIATOR) RE: Radiator Session Handling and SNMP...
Rickard Ekeroth
rickard at spidernet.net
Mon May 16 03:45:25 CDT 2005
Hi Mike!
Well, it seems that I have mixed up the NAS types a bit.
Now that I do the tests for 'Cisco' again the behaviour is consistent. That
is the session already in the session database is deleted in both cases
(both initial snmpget and backoff period). The trace is here:
*** Received from 194.154.133.218 port 1437 ....
Packet length = 72
01 1d 00 48 64 4d 69 f8 42 18 d7 78 8f b2 70 7b
dc db f8 b2 01 0a 70 73 74 6e 74 65 73 74 02 12
c9 ad fe 97 8d fa ff cd 5b 25 65 23 e2 af 91 06
04 06 01 02 03 04 05 06 00 00 00 6c 3d 06 00 00
00 00 28 06 00 00 00 01
Code: Access-Request
Identifier: 29
Authentic: dMi<248>B<24><215>x<143><178>p{<220><219><248><178>
Attributes:
User-Name = "pstntest"
User-Password =
"<201><173><254><151><141><250><255><205>[%e#<226><175><145><6>"
NAS-IP-Address = 1.2.3.4
NAS-Port = 108
NAS-Port-Type = Async
Acct-Status-Type = Start
Mon May 16 11:23:27 2005: DEBUG: Handling request with Handler ''
Mon May 16 11:23:27 2005: DEBUG: Deleting session for pstntest, 1.2.3.4,
108
Mon May 16 11:23:27 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_DeleteSession]
@NASIPAddress='1.2.3.4', at NASPort='108', at NASPortId='', at AcctSessionId=NULL, at Cl
ass='', at Time='May 16, 2005
11:23:27', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at AcctIn
putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
Mon May 16 11:23:27 2005: DEBUG: Handling with Radius::AuthSQL
Mon May 16 11:23:27 2005: DEBUG: Handling with Radius::AuthSQL: theAuthBySQL
Mon May 16 11:23:27 2005: DEBUG: Query is: 'EXECUTE
[RADIATOR_ProcessUserAuthRequest]
@UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='108', at NASPortId='', at N
ASPortType='Async', at ServiceType='', at AcctSessionId='', at AcctMultiSessionId='',
@FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at CalledStationI
d='', at Time='May 16, 2005 11:23:27', at RadiatorCode='PRIMARY'':
Mon May 16 11:23:27 2005: DEBUG: Radius::AuthSQL looks for match with
pstntest
Mon May 16 11:23:27 2005: DEBUG: Query is: 'EXECUTE [RADIATOR_CountSessions]
@NASIPAddress='1.2.3.4', at NASPort='108', at NASPortId='', at AcctSessionId='', at Clas
s='CC7F8951-B319-4175-9908-0EC2DE847177'':
Mon May 16 11:23:27 2005: DEBUG: Checking if user is still online: Cisco,
pstntest, 1.2.3.4, 107,
Mon May 16 11:23:27 2005: WARNING: Snmpget for NAS 1.2.3.4 blocked due to
recent error for 60 seconds
Mon May 16 11:23:27 2005: DEBUG: Cisco: snmpget result:
Mon May 16 11:23:27 2005: INFO: Session for pstntest at 1.2.3.4:107 has
gone away
Mon May 16 11:23:27 2005: DEBUG: Deleting session for pstntest, 1.2.3.4,
107
Mon May 16 11:23:27 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_DeleteSession]
@NASIPAddress='1.2.3.4', at NASPort='107', at NASPortId='', at AcctSessionId=NULL, at Cl
ass='CC7F8951-B319-4175-9908-0EC2DE847177', at Time='May 16, 2005
11:23:27', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at AcctIn
putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
Mon May 16 11:23:27 2005: DEBUG: Radius::AuthSQL ACCEPT:
Mon May 16 11:23:27 2005: DEBUG: AuthBy SQL result: ACCEPT,
Mon May 16 11:23:27 2005: DEBUG: Handling with Radius::AuthRADIUS
Mon May 16 11:23:27 2005: DEBUG: AuthBy RADIUS result: ACCEPT,
Mon May 16 11:23:27 2005: DEBUG: Access accepted for pstntest
Mon May 16 11:23:27 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_ProcessUserAuthResult] @Time='May 16, 2005
11:23:27', at RadiatorCode='PRIMARY', at IsSuccess=1, at Message=NULL, at UserName='pstn
test', at NASIPAddress='1.2.3.4', at NASPort='108', at NASPortId='', at NASPortType='Asy
nc', at AcctSessionId='', at AcctMultiSessionId='', at ServiceType='', at FramedIPAddres
s='', at FramedIPNetmask='', at CallingStationId='', at CalledStationId='', at Class='CC
7F8951-B319-4175-9908-0EC2DE847177'':
However for the 'CiscoSessionMIB' NAS type the behaviour is consistently the
opposite. The user is denied access and the session is not deleted from the
database in both cases:
*** Received from 194.154.133.218 port 1468 ....
Packet length = 72
01 2f 00 48 68 2e 52 9d 05 52 b9 5e 4b a6 54 72
64 7d e7 b1 01 0a 70 73 74 6e 74 65 73 74 02 12
c1 df 54 0e 5c 57 3d 87 60 9f a9 ea 99 1e a2 76
04 06 01 02 03 04 05 06 00 00 00 67 3d 06 00 00
00 00 28 06 00 00 00 01
Code: Access-Request
Identifier: 47
Authentic: h.R<157><5>R<185>^K<166>Trd}<231><177>
Attributes:
User-Name = "pstntest"
User-Password =
"<193><223>T<14>\W=<135>`<159><169><234><153><30><162>v"
NAS-IP-Address = 1.2.3.4
NAS-Port = 103
NAS-Port-Type = Async
Acct-Status-Type = Start
Mon May 16 11:36:33 2005: DEBUG: Handling request with Handler ''
Mon May 16 11:36:33 2005: DEBUG: Deleting session for pstntest, 1.2.3.4,
103
Mon May 16 11:36:33 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_DeleteSession]
@NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at AcctSessionId=NULL, at Cl
ass='', at Time='May 16, 2005
11:36:33', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at AcctIn
putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
Mon May 16 11:36:33 2005: DEBUG: Handling with Radius::AuthSQL
Mon May 16 11:36:33 2005: DEBUG: Handling with Radius::AuthSQL: theAuthBySQL
Mon May 16 11:36:33 2005: DEBUG: Query is: 'EXECUTE
[RADIATOR_ProcessUserAuthRequest]
@UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at N
ASPortType='Async', at ServiceType='', at AcctSessionId='', at AcctMultiSessionId='',
@FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at CalledStationI
d='', at Time='May 16, 2005 11:36:33', at RadiatorCode='PRIMARY'':
Mon May 16 11:36:33 2005: DEBUG: Radius::AuthSQL looks for match with
pstntest
Mon May 16 11:36:33 2005: DEBUG: Query is: 'EXECUTE [RADIATOR_CountSessions]
@NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at AcctSessionId='', at Clas
s='A092D496-88E1-4CDF-B38B-93043916953D'':
Mon May 16 11:36:33 2005: DEBUG: Checking if user is still online:
CiscoSessionMIB, pstntest, 1.2.3.4, 102,
Mon May 16 11:36:33 2005: DEBUG: CiscoSessionMIB: Checking
->1.2.3.4:102:pstntest
Mon May 16 11:36:33 2005: DEBUG: Running command
`c:/apps/netsnmp/bin/snmpget.exe -c "skummitet" 1.2.3.4
.iso.org.dod.internet.private.enterprises.9.9.150.1.1.3.1.2.0 2>&1`
Mon May 16 11:36:39 2005: ERR: The command 'c:/apps/netsnmp/bin/snmpget.exe
-c "skummitet" 1.2.3.4
.iso.org.dod.internet.private.enterprises.9.9.150.1.1.3.1.2.0 2>&1' failed
with an error: Timeout: No Response from 1.2.3.4.
Mon May 16 11:36:39 2005: DEBUG: Radius::AuthSQL REJECT: Simultaneous-Use of
1 exceeded
Mon May 16 11:36:39 2005: DEBUG: AuthBy SQL result: REJECT, Simultaneous-Use
of 1 exceeded
Mon May 16 11:36:39 2005: INFO: Access rejected for pstntest:
Simultaneous-Use of 1 exceeded
Mon May 16 11:36:39 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_ProcessUserAuthResult] @Time='May 16, 2005
11:36:39', at RadiatorCode='PRIMARY', at IsSuccess=0, at Message='Simultaneous-Use of
1
exceeded', at UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='103', at NASPo
rtId='', at NASPortType='Async', at AcctSessionId='', at AcctMultiSessionId='', at Servi
ceType='', at FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at Call
edStationId='', at Class='A092D496-88E1-4CDF-B38B-93043916953D'':
And the backoff case for 'CiscoSessionMIB':
*** Received from 194.154.133.218 port 1468 ....
Packet length = 72
01 2f 00 48 68 2e 52 9d 05 52 b9 5e 4b a6 54 72
64 7d e7 b1 01 0a 70 73 74 6e 74 65 73 74 02 12
c1 df 54 0e 5c 57 3d 87 60 9f a9 ea 99 1e a2 76
04 06 01 02 03 04 05 06 00 00 00 67 3d 06 00 00
00 00 28 06 00 00 00 01
Code: Access-Request
Identifier: 47
Authentic: h.R<157><5>R<185>^K<166>Trd}<231><177>
Attributes:
User-Name = "pstntest"
User-Password =
"<193><223>T<14>\W=<135>`<159><169><234><153><30><162>v"
NAS-IP-Address = 1.2.3.4
NAS-Port = 103
NAS-Port-Type = Async
Acct-Status-Type = Start
Mon May 16 11:36:39 2005: DEBUG: Handling request with Handler ''
Mon May 16 11:36:39 2005: DEBUG: Deleting session for pstntest, 1.2.3.4,
103
Mon May 16 11:36:39 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_DeleteSession]
@NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at AcctSessionId=NULL, at Cl
ass='', at Time='May 16, 2005
11:36:39', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at AcctIn
putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
Mon May 16 11:36:39 2005: DEBUG: Handling with Radius::AuthSQL
Mon May 16 11:36:39 2005: DEBUG: Handling with Radius::AuthSQL: theAuthBySQL
Mon May 16 11:36:39 2005: DEBUG: Query is: 'EXECUTE
[RADIATOR_ProcessUserAuthRequest]
@UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at N
ASPortType='Async', at ServiceType='', at AcctSessionId='', at AcctMultiSessionId='',
@FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at CalledStationI
d='', at Time='May 16, 2005 11:36:39', at RadiatorCode='PRIMARY'':
Mon May 16 11:36:39 2005: DEBUG: Radius::AuthSQL looks for match with
pstntest
Mon May 16 11:36:39 2005: DEBUG: Query is: 'EXECUTE [RADIATOR_CountSessions]
@NASIPAddress='1.2.3.4', at NASPort='103', at NASPortId='', at AcctSessionId='', at Clas
s='E07E2AD3-743C-4321-93C0-567A11DDF738'':
Mon May 16 11:36:39 2005: DEBUG: Checking if user is still online:
CiscoSessionMIB, pstntest, 1.2.3.4, 102,
Mon May 16 11:36:39 2005: DEBUG: CiscoSessionMIB: Checking
->1.2.3.4:102:pstntest
Mon May 16 11:36:39 2005: WARNING: Snmpget for NAS 1.2.3.4 blocked due to
recent error for 60 seconds
Mon May 16 11:36:40 2005: DEBUG: Radius::AuthSQL REJECT: Simultaneous-Use of
1 exceeded
Mon May 16 11:36:40 2005: DEBUG: AuthBy SQL result: REJECT, Simultaneous-Use
of 1 exceeded
Mon May 16 11:36:40 2005: INFO: Access rejected for pstntest:
Simultaneous-Use of 1 exceeded
Mon May 16 11:36:40 2005: DEBUG: do query is: 'EXECUTE
[RADIATOR_ProcessUserAuthResult] @Time='May 16, 2005
11:36:40', at RadiatorCode='PRIMARY', at IsSuccess=0, at Message='Simultaneous-Use of
1
exceeded', at UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='103', at NASPo
rtId='', at NASPortType='Async', at AcctSessionId='', at AcctMultiSessionId='', at Servi
ceType='', at FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at Call
edStationId='', at Class='E07E2AD3-743C-4321-93C0-567A11DDF738'':
Personally I prefer the behaviour of the 'CiscoSessionMIB' but I am sure
that others would disagree with me. Perhaps it would be nice if it was
configurable what the behaviour should be...
-----Original Message-----
From: Mike McCauley [mailto:mikem at open.com.au]
Sent: 16 May 2005 10:59
To: rickard at spidernet.net
Cc: radiator at open.com.au
Subject: Re: Radiator Session Handling and SNMP...
Hi Rickard,
Thanks for that.
Would it be possible to get a trace of a subsequent attempt to access the
NAS during the backoff period? I gather that the issue is that the behaviour
is different for the first request that starts the backoff and a subsequent
request during the backoff period?
Cheers.
On Monday 16 May 2005 17:37, Rickard Ekeroth wrote:
> Hello Mike!
>
> Here is a trace for the initial request (before the backoff):
>
> *** Received from 194.154.133.218 port 2440 ....
>
> Packet length = 72
> 01 14 00 48 33 10 d0 cc ff db 5a 3b d0 fc 16 fb
> 59 8c a3 80 01 0a 70 73 74 6e 74 65 73 74 02 12 3f ce 04 24 a5 e8 b9
> 2a ad 96 16 6a 49 39 37 19
> 04 06 01 02 03 04 05 06 00 00 00 65 3d 06 00 00 00 00 28 06 00 00 00
> 01
> Code: Access-Request
> Identifier: 20
> Authentic:
> 3<16><208><204><255><219>Z;<208><252><22><251>Y<140><163><128>
> Attributes:
> User-Name = "pstntest"
> User-Password = "?<206><4>$<165><232><185>*<173><150><22>jI97<25>"
> NAS-IP-Address = 1.2.3.4
> NAS-Port = 101
> NAS-Port-Type = Async
> Acct-Status-Type = Start
>
> Fri May 13 17:37:01 2005: DEBUG: Handling request with Handler ''
> Fri May 13 17:37:01 2005: DEBUG: Deleting session for pstntest,
>1.2.3.4,
> 101
> Fri May 13 17:37:01 2005: DEBUG: do query is: 'EXECUTE
>[RADIATOR_DeleteSession]
>@NASIPAddress='1.2.3.4', at NASPort='101', at NASPortId='', at AcctSessionId=NUL
>L, at C
>l ass='', at Time='May 13, 2005
>
>17:37:01', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at A
>cctI n
>putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
> Fri May 13 17:37:01 2005: DEBUG: Handling with Radius::AuthSQL Fri
>May 13 17:37:01 2005: DEBUG: Handling with Radius::AuthSQL:
> theAuthBySQL Fri May 13 17:37:01 2005: DEBUG: Query is: 'EXECUTE
>[RADIATOR_ProcessUserAuthRequest]
>
>@UserName='pstntest', at NASIPAddress='1.2.3.4', at NASPort='101', at NASPortId=
>'',@
>N
>
ASPortType='Async', at ServiceType='', at AcctSessionId='', at AcctMultiSessionId=''
>,
>
>@FramedIPAddress='', at FramedIPNetmask='', at CallingStationId='', at CalledSta
>tion I d='', at Time='May 13, 2005 17:37:01', at RadiatorCode='PRIMARY'':
> Fri May 13 17:37:01 2005: DEBUG: Radius::AuthSQL looks for match with
>pstntest Fri May 13 17:37:01 2005: DEBUG: Query is: 'EXECUTE
>[RADIATOR_CountSessions]
>@NASIPAddress='1.2.3.4', at NASPort='101', at NASPortId='', at AcctSessionId='',
>@Cla s s='F6832D59-511E-42B4-813B-F23BB6A08B7F'':
>
> Fri May 13 17:37:01 2005: DEBUG: Checking if user is still online:
> Cisco, pstntest, 1.2.3.4, 100, Fri May 13 17:37:01 2005: DEBUG:
> Running command `c:/apps/netsnmp/bin/snmpget.exe -c "skummitet"
> 1.2.3.4 .iso.org.dod.internet.private.enterprises.9.2.9.2.1.18.100
> 2>&1`
>
> Fri May 13 17:37:08 2005: ERR: The command
> 'c:/apps/netsnmp/bin/snmpget.exe -c "skummitet" 1.2.3.4
> .iso.org.dod.internet.private.enterprises.9.2.9.2.1.18.100 2>&1'
> failed with an error: Timeout: No Response from 1.2.3.4.
>
> Fri May 13 17:37:08 2005: DEBUG: Cisco: snmpget result: Timeout: No
> Response from 1.2.3.4.
>
> Fri May 13 17:37:08 2005: INFO: Session for pstntest at 1.2.3.4:100
> has gone away
>
> Fri May 13 17:37:08 2005: DEBUG: Deleting session for pstntest,
> 1.2.3.4, 100
>
> Fri May 13 17:37:08 2005: DEBUG: do query is: 'EXECUTE
>[RADIATOR_DeleteSession]
>@NASIPAddress='1.2.3.4', at NASPort='100', at NASPortId='', at AcctSessionId=NUL
>L, at C l ass='F6832D59-511E-42B4-813B-F23BB6A08B7F', at Time='May 13, 2005
>17:37:08', at DelayAdjustedTime='', at Timestamp=0, at AcctStatusType='Start', at A
>cctI n
>putOctets='', at AcctOutputOctets='', at AscendDataRate='', at AscendXmitRate=''':
> Fri May 13 17:37:08 2005: DEBUG: Radius::AuthSQL ACCEPT:
> Fri May 13 17:37:08 2005: DEBUG: AuthBy SQL result: ACCEPT, Fri May
>13 17:37:08 2005: DEBUG: Handling with Radius::AuthRADIUS Fri May 13
>17:37:08 2005: DEBUG: AuthBy RADIUS result: ACCEPT, Fri May 13
>17:37:08 2005: DEBUG: Access accepted for pstntest Fri May 13 17:37:08
>2005: DEBUG: do query is: 'EXECUTE [RADIATOR_ProcessUserAuthResult]
>@Time='May 13, 2005
>17:37:08', at RadiatorCode='PRIMARY', at IsSuccess=1, at Message=NULL, at UserName=
>'pst
>n
>
>test', at NASIPAddress='1.2.3.4', at NASPort='101', at NASPortId='', at NASPortType
>='As
>y
>
>nc', at AcctSessionId='', at AcctMultiSessionId='', at ServiceType='', at FramedIPA
>ddre
>s
>
>s='', at FramedIPNetmask='', at CallingStationId='', at CalledStationId='', at Clas
>s='F
>6 832D59-511E-42B4-813B-F23BB6A08B7F'':
>
>
> As you can see the Radiator calls 'snmpget' to check for the session
> on port '100'. The snmpget returns a timeout because it can not
> contact '1.2.3.4' (because it is fake). Regardless of the fact that
> the NAS can not be contacted Radiator decides to remove the existing
session on port '100'.
>
> I am using NAS type 'Cisco'. We will probably (hopefully) go with
> 'CiscoSessionMIB' later on.
>
> This is a Radiator version 3.11 running on a Windows box.
>
>
> -----Original Message-----
> From: Mike Mccauley [mailto:mikem at open.com.au]
> Sent: 12 May 2005 21:16
> To: Hugh Irvine
> Cc: Rickard Ekeroth; RadiatorMaillist
> Subject: Re: Radiator Session Handling and SNMP...
>
> Hello Richard,
>
> I dont think I saw this description of your problem before, so thanks
> for sending it.
> I would have expected the online code to react the same way to the
> initial failure and subsequent backoff events. Can you pls send me a
> trace 4 log showing what happens? What NasType do you have configured?
>
> Cheers.
>
> On Thu, 2005-05-12 at 14:21 +1000, Hugh Irvine wrote:
> > Hi Richard -
> >
> > Mike is overseas at the moment, so he hasn't had much time to reply.
> >
> > He should be back next week and he is copied on this mail.
> >
> > regards
> >
> > Hugh
> >
> > On 11 May 2005, at 22:04, Rickard Ekeroth wrote:
> > > Hello Hugh!
> > >
> > > I wrote to you guys a while ago about the behaviour of Radiator
> > > when it queries a NAS using SNMP. I am not sure if my reply to the
> > > reply that you sent me was sent properly. Anyway here are my
> > > thoughts
> > > again:
> > >
> > > If Radiator fails to query a NAS for a specific session using SNMP
> > > it will assume that the session in question is not on the NAS.
> > > However during the following back-off period (60 seconds) the
> > > behaviour is the reverse:
> > > Radiator assumes that the session is still on the NAS and the user
> > > is denied access based on max session count.
> > >
> > > Should not the behaviour be the same in both cases? Personally I
> > > would prefer if the Radiator denied access in both cases. This is
> > > because I have a consumption debit scheme based on accounting stop
> > > packets and I would prefer not to delete sessions unless I am sure
> > > that it is not on the NAS anymore (because I can not debit a
> > > session that did not receive a stop packet since I do not know the
> > > actual session time).
> > >
> > > Regards,
> > >
> > > Rickard Ekeroth @ SpiderNet
> > > Software Developer / Analyst
> > > rickard at spidernet.net
> > > +35722844870
> >
> > NB:
> >
> > Have you read the reference manual ("doc/ref.html")?
> > Have you searched the mailing list archive
> > (www.open.com.au/archives/radiator)?
> > Have you had a quick look on Google (www.google.com)?
> > Have you included a copy of your configuration file (no secrets),
> > together with a trace 4 debug showing what is happening?
--
Mike McCauley mikem at open.com.au
Open System Consultants Pty. Ltd Unix, Perl, Motif, C++, WWW
9 Bulbul Place Currumbin Waters QLD 4223 Australia http://www.open.com.au
Phone +61 7 5598-7474 Fax +61 7 5598-7070
Radiator: the most portable, flexible and configurable RADIUS server
anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
TTLS, PEAP etc on Unix, Windows, MacOS etc.
--
Archive at http://www.open.com.au/archives/radiator/
Announcements on radiator-announce at open.com.au
To unsubscribe, email 'majordomo at open.com.au' with
'unsubscribe radiator' in the body of the message.
More information about the radiator
mailing list