Session-Timeout anomalies

[Bill Isaacs]

Hello all,

I'm researching this anomaly myself in all the documentation, but 
thought it would also be helpful both to me and to others to post the 
problem here.

SYMPTOM: Some "Access-Period" accounts (accounts which have X number of 
seconds to continue logging in and out starting from the very first 
login) are giving too much time -- that is, at some point they reload 
the full value of the account type and restart the count down. I 
discovered it while developing some interface code for our customer 
service dept. So far, this DOES NOT seem to be happening to all 
accounts. Moreover, the database info and radclient results are 
inconsistent on these accounts that ARE showing the anomaly.

Here is an example of one such account, a development test account which 
I created for debugging purposes. It's value is 30 days (2592000 seconds)

Radclient result:
===============
# echo User-Name="cgitest",User-Password="cgitest" | radclient -c 1 -n 3 
-r 3 -t 3 -x 127.0.0.1:1812 auth -S shared
Sending Access-Request of id 24 to 127.0.0.1 port 1812
User-Name = "cgitest"
User-Password = "cgitest"
rad_recv: Access-Accept packet from host 127.0.0.1 port 1812, id=24, 
length=26
Session-Timeout = 2366393
===============
sql query:

SELECT IFNULL(TIME_TO_SEC(TIMEDIFF(NOW(), MIN(AcctStartTime))),0) FROM 
radacct WHERE UserName='cgitest' ORDER BY AcctStartTime LIMIT 1 \g
+-------------------------------------------------------------------------------------+
| IFNULL(TIME_TO_SEC(TIMEDIFF(NOW(), MIN(AcctStartTime))),0) |
+-------------------------------------------------------------------------------------+
| 1447012 |
+-------------------------------------------------------------------------------------+
===============

Ok, the problem here should be obvious but I'll explain these results 
for those who are impatient. The "Session-Timeout" number is way too 
large. As I stated previously, this is a 30 day account. It was counting 
down with no problems until a few days ago. It then mysteriously began 
reporting in the popup window which I was working on that it had 29.9 
days left on it, after it had already counted down to something like 15 
days. It simply seems to have reloaded itself, even though the sql query 
reports the accurate number of seconds which have actually expired. 
(1447012). So if we do the math: 2592000-1447012=1144988 (or roughly 
13.25 days) should be the remaining time on this account. Not 27.38 days.

Here is the sql counter from sqlcounter.conf:

sqlcounter accessperiod {

counter-name = Max-Access-Period-Time
check-name = Access-Period
reply-name = Session-Timeout
sqlmod-inst = sql
key = User-Name
reset = never
query = “SELECT UNIX_TIMESTAMP() – UNIX_TIMESTAMP(AcctStartTime) FROM 
radacct WHERE UserName = ‘%{%k}’ ORDER BY AcctStartTime LIMIT 1″
}


(Before anyone bitches about the sql query being different, save your 
pixels -- no matter which style of query is used, the account reports 
that it began at the same time, there is truly no issue here that I can 
see).

ALSO, BEFORE YOU ASK: There is only 1 radius server and only 1 sql 
server on the system. Besides, I have tested this exhaustively using 
different things like the public IP, the fqdn, etc etc. Results are the 
same - that is to say, wrong. lol

Ok so the question then is: where the hell is radclient getting the 
notion that the account has 2366393 seconds left? Where is 
"Session-Timeout" getting this information? Why is it only doing it on 
some accounts and not others?

Any insights would be greatly appreciated. I will post the resolution 
here (unless one of you smart lads or lasses beats me to it ;) ).