(RADIATOR) get_attr occasionally incorrectly returning NULL
Andrew Sands
andrew_sands at yahoo.com
Fri May 6 07:33:16 CDT 2005
Hi Hugh,
Actually there was more code not shown that wrote the SQL statement to a
file as well before executing it:
INSERT INTO RADUSAGE_200504
(ACCTDELAYTIME,ACCTINPUTOCTETS,ACCTOUTPUTOCTETS,ACCTSESSIONID,ACCTSESSIONTIM
E,ACCTSTATUSTYPE,ACCTTERMINATECAUSE,FRAMEDIPADDRESS,NASIDENTIFIER,NASPORT,NA
S_PORT_TYPE,TIME_STAMP,USERNAME) VALUES
(10,302699,1626030,'NULL',578,2,'NULL','xx.xx.162.191','NULL',6374,NULL,1112
585928,'xxxx at xxxx.com.au');
Thus I can see that the value of the $a_ACCTSESSIONID perl variable was NULL
(or was translated to the string 'NULL').
Given that for April data (132248 records) it worked correctly 99.98% of the
time (ie failed 24 times), I suspect that there is a race condition
somewhere that is occasionally being hit, presumably during periods of high
load.
Can you please advise what symptoms one would expect to see when Radiator is
overloaded with traffic? Are some requests dealt with correctly whilst
others are dropped or does overall reliability decrease? Also how could I
tell if my system was overloaded?
Thanks for your help.
Andrew.
-----Original Message-----
From: owner-radiator at open.com.au [mailto:owner-radiator at open.com.au] On
Behalf Of Hugh Irvine
Sent: Friday, 6 May 2005 8:52 PM
To: Andrew Sands
Cc: radiator at open.com.au
Subject: Re: (RADIATOR) get_attr occasionally incorrectly returning NULL
Hello Andrew -
I can't see anything wrong either.
Suggest you add some debugging code to your hook to log the
Acct-Session-Id value that the hook code is using.
regards
Hugh
On 6 May 2005, at 13:26, Andrew Sands wrote:
> Hi,
>
> I have a situation where I use get_attr in a postauthhook and in over
> 100000 requests last month it worked but on 24 occasions it returned
> NULL when I know it should never do that. I wonder if anyone else has
> ever experienced this, can see a mistake in what I am doing, or can
> suggest a fix?
>
> First of all I know that the Acct-Session-Id is not NULL for this STOP
> accounting record because I can see it in the trace as follows:
>
> Mon Apr 4 13:38:58 2005: DEBUG: Packet dump:
> *** Received from xx.xx.xx.xx port 1813 ....
> Code: Accounting-Request
> Identifier: 230
> Authentic: ".<137><143><166>#<11><249>f<<221>`<208><255><198>5
> Attributes:
> Acct-Session-Id = "000C0BB2"
> Framed-Protocol = PPP
> Acct-Authentic = RADIUS
> Ascend-Disconnect-Cause = 816
> Ascend-Connect-Progress = prLanSessionUp
> Ascend-PreSession-Time = 29
> Ascend-Xmit-Rate = 50667
> Ascend-Data-Rate = 28800
> Acct-Session-Time = 578
> Acct-Input-Octets = 302699
> Acct-Output-Octets = 1626030
> Ascend-Pre-Input-Octets = 336
> Ascend-Pre-Output-Octets = 113
> Acct-Input-Packets = 2508
> Acct-Output-Packets = 1479
> Ascend-Pre-Input-Packets = 8
> Ascend-Pre-Output-Packets = 4
> Acct-Status-Type = Stop
> Acct-Multi-Session-Id = "00078981"
> Ascend-Multilink-ID = 493953
> Acct-Link-Count = 1
> Ascend-Num-In-Multilink = 1
> Framed-IP-Address = xx.xx.162.191
> Called-Station-Id = "142330755113178"
> NAS-Port-Type = Async
> NAS-Port = 6374
> Service-Type = Framed-User
> NAS-IP-Address = xx.xx.238.101
> Ascend-Session-Svr-Key = "7FF3E294"
> NAS-Identifier = "xxx-JOHN-STP.xxxxx.com.au"
> Acct-Delay-Time = 10
> User-Name = "xxx_wl/xxxx at xxxx.com.au"
> Proxy-State =
> BSP2MyMaster/
> 65CD748FC992421A4DC536282071BB582ED040F5D715D29899B43997D804E52D6C80F93
> FD715D0125268D65EDE6AFDC9A75D5AEAD71DF107A1D7505AAA6FCEB20BF291368862BC
> 28F8C1505AB6448EA015EE9D21B079BF65F8D81658B769D3AA19
>
> I can also see from the TRACE debug that there were no errors
> experienced during the processing:
>
> Mon Apr 4 13:38:58 2005: DEBUG: Handling request with Handler
> 'User-Name = /^our_partner\//i'
> Mon Apr 4 13:38:58 2005: DEBUG: Rewrote user name to xxxx at xxxx.com.au
> Mon Apr 4 13:38:58 2005: DEBUG: SDB1 Deleting session for
> xxx_wl/xxxx at xxxx.com.au, xx.xx.238.101, 6374
> Mon Apr 4 13:38:58 2005: DEBUG: do query is: 'delete from RADONLINE
> where NASIDENTIFIER='xx.xx.238.101' and NASPORT='6374'':
> Mon Apr 4 13:38:58 2005: DEBUG: PostAuthHook network-access
> ++++++++++++++++++++++++++++
> Mon Apr 4 13:38:58 2005: DEBUG: execute SQL okay
> Mon Apr 4 13:38:58 2005: DEBUG: PostAuthHook network-access
> ----------------------------
> Mon Apr 4 13:38:58 2005: DEBUG: Accounting accepted
>
>
> When I look in the database at the saved STOP record I can see:
>
> mysql> select * from RADUSAGE_200504 where ACCTSESSIONID = 'NULL' and
> ACCTSTATUSTYPE = 2 and USERNAME like 'xxxx%'\G;
> *************************** 1. row ***************************
> ACCTDELAYTIME: 10
> ACCTINPUTOCTETS: 302699
> ACCTOUTPUTOCTETS: 1626030
> ACCTSESSIONID: NULL
> ACCTSESSIONTIME: 578
> ACCTSTATUSTYPE: 2
> ACCTTERMINATECAUSE: NULL
> FRAMEDIPADDRESS: xx.xx.162.191
> NASIDENTIFIER: NULL
> NASPORT: 6374
> NAS_PORT_TYPE: NULL
> TIME_STAMP: 1112585928
> USERNAME: xxxx at xxxx.com.au
> 1 row in set (0.01 sec)
>
>
> The missing ACCTSESSIONID was not used anywhere else:
>
> mysql> select count(*) from RADUSAGE_200504 where ACCTSESSIONID =
> '000C0BB2';
> +----------+
> | count(*) |
> +----------+
> | 0 |
> +----------+
> 1 row in set (1.28 sec)
>
>
> This has happened only 24 times during the month:
>
> mysql> select count(*) from RADUSAGE_200504 where ACCTSESSIONID =
> 'NULL';
> +----------+
> | count(*) |
> +----------+
> | 24 |
> +----------+
> 1 row in set (1.01 sec)
>
>
>
> The ACCTSESSIONID is being set to the string ‘NULL’ rather than being
> set to a NULL:
> (a minor problem I’m ignoring at the moment).
>
> mysql> select count(*) from RADUSAGE_200504 where ACCTSESSIONID is
> NULL and ACCTSTATUSTYPE = 2;
> +----------+
> | count(*) |
> +----------+
> | 0 |
> +----------+
> 1 row in set (0.99 sec)
>
>
> mysql> select count(*) from RADUSAGE_200504;
> +----------+
> | count(*) |
> +----------+
> | 132248 |
> +----------+
> 1 row in set (0.00 sec)
>
> mysql>
>
>
>
>
> The relevant Radius Config is:
>
>
> <Handler User-Name = /^our_partner\//i >
> RewriteUsername s/^our_partner\/(.*)/$1/
> AuthByPolicy ContinueAlways
> AuthBy CheckRadmin
> AuthLog ALDB1
> SessionDatabase SDB1
> PostAuthHook file:"%D/network_access.pl"
> </Handler>
>
>
> And the relevant bits of the postauthhook are:
>
> sub
> {
> my $p = ${$_[0]};
> my $rp = ${$_[1]};
> my $result = ${$_[2]};
>
> &main::log($main::LOG_DEBUG,"PostAuthHook network-access
> ++++++++++++++++++++++++++++");
>
> my $u_name = $p->get_attr('User-Name');
>
> my $a_TIME_STAMP ;
> my $a_ACCTSTATUSTYPE ;
> my $a_ACCTDELAYTIME ;
> my $a_ACCTINPUTOCTETS ;
> my $a_ACCTOUTPUTOCTETS ;
> my $a_ACCTSESSIONID ;
> my $a_ACCTSESSIONTIME ;
> my $a_ACCTTERMINATECAUSE ;
> my $a_NASIDENTIFIER ;
> my $a_NASPORT ;
> my $a_NAS_PORT_TYPE ;
> my $a_FRAMEDIPADDRESS ;
>
> my $req_type = "?";
>
> $req_type = $p->code;
>
> if ($req_type eq 'Access-Request') {
> # Other stuff
> } else {
> $a_TIME_STAMP = $p-> get_attr('Timestamp');
> $a_ACCTSTATUSTYPE = $p->
> get_attr('Acct-Status-Type');
> $a_ACCTSTATUSTYPE =
> $rp->{Dict}->valNameToNum('Acct-Status-Type', $a_ACCTSTATUSTYPE);
> $a_ACCTDELAYTIME = $p->
> get_attr('Acct-Delay-Time');
>
> if ($a_ACCTDELAYTIME eq "") {
> $a_ACCTDELAYTIME = "NULL";
> }
>
> $a_ACCTINPUTOCTETS = $p->
> get_attr('Acct-Input-Octets');
> if ($a_ACCTINPUTOCTETS eq "") {
> $a_ACCTINPUTOCTETS = "NULL";
> }
>
> $a_ACCTOUTPUTOCTETS = $p->
> get_attr('Acct-Output-Octets');
> if ($a_ACCTOUTPUTOCTETS eq "") {
> $a_ACCTOUTPUTOCTETS = "NULL";
> }
>
> $a_ACCTSESSIONID = $p->
> get_attr('Acct-Session-Id');
>
>
> # Other attributes gathered, and connect to database
>
> my $insert_sql;
> my $insert_text;
>
> $insert_text = "INSERT INTO RADUSAGE_200504
> (ACCTDELAYTIME,ACCTINPUTOCTETS,ACCTOUTPUTOCTETS,ACCTSESSIONID,ACCTSESSI
> ONTIME,ACCTSTATUSTYPE,ACCTTERMINATECAUSE,FRAMEDIPADDRESS,NASIDENTIFIER,
> NASPORT,NAS_PORT_TYPE,TIME_STAMP,USERNAME) VALUES
> ($a_ACCTDELAYTIME,$a_ACCTINPUTOCTETS,$a_ACCTOUTPUTOCTETS,'$a_ACCTSESSIO
> NID',$a_ACCTSESSIONTIME,$a_ACCTSTATUSTYPE,'$a_ACCTTERMINATECAUSE','$a_F
> RAMEDIPADDRESS','$a_NASIDENTIFIER',$a_NASPORT,$a_NAS_PORT_TYPE,$a_TIME_
> STAMP,'$u_name');";
> }
>
> ($insert_sql) = $dbh->prepare (qq{$insert_text});
> if ($insert_sql->execute()) {
> &main::log($main::LOG_DEBUG,"execute SQL
> okay");
> } else {
> # Other error handling code
> }
> }
>
> &main::log($main::LOG_DEBUG,"PostAuthHook network-access
> ----------------------------");
> return;
> }
>
>
>
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?
--
Radiator: the most portable, flexible and configurable RADIUS server
anywhere. Available on *NIX, *BSD, Windows, MacOS X.
-
Nets: internetwork inventory and management - graphical, extensible,
flexible with hardware, software, platform and database independence.
-
CATool: Private Certificate Authority for Unix and Unix-like systems.
--
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.
--
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