(RADIATOR) get_attr occasionally incorrectly returning NULL
Andrew Sands
andrew_sands at yahoo.com
Thu May 5 22:26:43 CDT 2005
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/65CD748FC992421A4DC536282071BB582ED040F5D715D29899B43997D804E52
D6C80F93FD715D0125268D65EDE6AFDC9A75D5AEAD71DF107A1D7505AAA6FCEB20BF29136886
2BC28F8C1505AB6448EA015EE9D21B079BF65F8D81658B769D3AA19
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,ACCTSESSIONTIM
E,ACCTSTATUSTYPE,ACCTTERMINATECAUSE,FRAMEDIPADDRESS,NASIDENTIFIER,NASPORT,NA
S_PORT_TYPE,TIME_STAMP,USERNAME) VALUES
($a_ACCTDELAYTIME,$a_ACCTINPUTOCTETS,$a_ACCTOUTPUTOCTETS,'$a_ACCTSESSIONID',
$a_ACCTSESSIONTIME,$a_ACCTSTATUSTYPE,'$a_ACCTTERMINATECAUSE','$a_FRAMEDIPADD
RESS','$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;
}
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.open.com.au/pipermail/radiator/attachments/20050506/8198199c/attachment.html>
More information about the radiator
mailing list