Huge AcctSessionTime returned by pfsense



  • Hi,

    I'm using pfsense (2.0.2-RELEASE) and use the captive portal together with freeradius to control the total amount of time users access the internet. I've enabled interim accounting . This works great most of the time, but from time to time I get a start and stop packet with the same timestamp and a huge AcctSessionTime. Obviously this ruins my session time accounting. Strangely enough the termination cause is "Idle Session Timeout". Is this a known problem? Is there a work-around?  Could I have misconfigured something?

    I've also looked at http://redmine.pfsense.org/issues/2164, but as far as I see it doesn't actually cover my issue.

    The relevant accounting packets are added below.

    Thanks

    Jan

    Thu Jan 10 18:47:13 2013
            NAS-IP-Address = 192.168.1.1
            NAS-Identifier = "NAS1234"
            User-Name = "USER_1"
            Acct-Status-Type = Start
            Acct-Authentic = RADIUS
            Service-Type = Login-User
            NAS-Port-Type = Ethernet
            NAS-Port = 80
            Acct-Session-Id = "066d59006583ed4d"
            Framed-IP-Address = 192.168.1.XXX
            Called-Station-Id = "192.168.1.1"
            Calling-Station-Id = "00:21:XX:XX:XX:XX"
            Acct-Unique-Session-Id = "7e804c609472d968"
            Timestamp = 1357840033
            Request-Authenticator = Verified

    Thu Jan 10 18:47:13 2013
            NAS-IP-Address = 192.168.1.1
            NAS-Identifier = "NAS1234"
            User-Name = "USER_1"
            Acct-Status-Type = Stop
            Acct-Session-Time = 4294753160
            Acct-Authentic = RADIUS
            Service-Type = Login-User
            NAS-Port-Type = Ethernet
            NAS-Port = 80
            Acct-Session-Id = "066d59006583ed4d"
            Framed-IP-Address = 192.168.1.XXX
            Called-Station-Id = "192.168.1.1"
            Calling-Station-Id = "00:21:XX:XX:XX:XX"
            Acct-Input-Packets = 0
            Acct-Input-Octets = 0
            Acct-Input-Gigawords = 0
            Acct-Output-Packets = 0
            Acct-Output-Octets = 0
            Acct-Output-Gigawords = 0
            Acct-Session-Time = 4294753160
            Acct-Terminate-Cause = Idle-Timeout
            Acct-Unique-Session-Id = "7e804c609472d968"
            Timestamp = 1357840033
            Request-Authenticator = Verified


  • Rebel Alliance Developer Netgate

    Looks suspiciously like a 32-bit integer wrapping.

    2^32 is 4,294,967,296, which although it is still not quite the same, is a little too close to be a coincidence.

    You might check the code mentioned here: http://redmine.pfsense.org/issues/2164

    Really though looking at the code, it just sets:

    $session_time = $stop_time - $start_time;
    

    […]

    $racct->session_time = $session_time;
    

    […]

    $racct->putAttribute(RADIUS_ACCT_SESSION_TIME, $session_time, "integer");
    

    So unless somehow the time calculation is going way negative, I'm not sure what it could be.

    You might try editing /usr/local/captiveportal/radius_accounting.inc and finding the "$session_time = $stop_time - $start_time;" line (~202 or so) and then adding this under it:

    log_error("Radius accounting debug: Start: {$start_time} Stop: {$stop_time} Session time: {$session_time} ");
    

    then check the system log to see what happens the next time you try a login.

    If it goes negative, I wonder if we may need to set that to 0 if it goes negative. Perhaps that attribute can't handle negatives, and it probably shouldn't since it's a timer. Could be as simple as doing this:

    
    $session_time = $stop_time - $start_time;
    $session_time = ($session_time >= 0) ? intval($session_time) : 0;
    


  • Thanks a lot for the pointers.  I'll give it a try and add some log statements. Might take some time before it occurs again.

    I also wonder what actually triggers the sending of a start and stop packet at the same time. Up to now I wasn't able to reproduce it. I just have to wait until it happens.

    Regards,

    Jan



  • Hi,

    I finally got this error situation again. But now with debug logging on:

    php: : Radius accounting debug: Start: 1361626822 Stop: 1360585337 Session time: -1041485

    Note that at logon time the user gets a timeout. After that he can't logon anymore as his quota has been exceeded.

    I'll force the session time to 0, as you suggested. This will probably solve my problem, but I'm still intrigued by the fact that the original start and stop time are completely wrong.

    Regards,

    Jan



  • Probably need to do time keeping on the installation.



  • Thanks for your reply.

    Both pfsense and the radius server itself are managed by ntp (pfsense relies on 2 external servers and the radius server on the ntp server of pfsense). The radius database server runs on a different machine. The database server's time keeping is less accurate, but I guess this is less relevant. Or is this a wrong assumption?

    Jan


Log in to reply