"[sql] stop packet with zero session length" problem

[Selahattin Cilek]

On 04.04.2017 12:03, Brian Candler wrote:
On 04/04/2017 06:25, Selahattin Cilek wrote:
Sometimes, and for some reason that is unknown to me, when a user connects to a UAP NAS, he is immediately kicked out. We can see that in the accounting details log of the NAS:

Tue Apr  4 08:02:36 2017
     Acct-Session-Id = "58D911BB-00001F5D"
     Acct-Status-Type = Start
     Acct-Authentic = RADIUS
     User-Name = "99481225842"
     NAS-Identifier = "44d9e77a2de5"
     NAS-Port = 0
     Called-Station-Id = "46-D9-E7-7B-2D-E5:YEMEKHANE"
     Calling-Station-Id = "28-ED-6A-30-55-5A"
     NAS-Port-Type = Wireless-802.11
     Connect-Info = "CONNECT 0Mbps 802.11b"
     Class = 0x3939343831323235383432
     NAS-IP-Address = 192.168.0.31
     FreeRADIUS-Acct-Session-Start-Time = "Apr  4 2017 08:02:36 MSK"
     Timestamp = 1491282156

Tue Apr  4 08:02:36 2017
     Acct-Session-Id = "58D911BB-00001F5D"
     Acct-Status-Type = Stop
     Acct-Authentic = RADIUS
     User-Name = "99481225842"
     NAS-Identifier = "44d9e77a2de5"
     NAS-Port = 0
     Called-Station-Id = "46-D9-E7-7B-2D-E5:YEMEKHANE"
     Calling-Station-Id = "28-ED-6A-30-55-5A"
     NAS-Port-Type = Wireless-802.11
     Connect-Info = "CONNECT 0Mbps 802.11b"
     Class = 0x3939343831323235383432
     Acct-Session-Time = 0
     Acct-Input-Packets = 11
     Acct-Output-Packets = 12
     Acct-Input-Octets = 1289
     Acct-Output-Octets = 3415
     Event-Timestamp = "Apr  4 2017 08:02:35 MSK"
     Acct-Terminate-Cause = User-Request
     NAS-IP-Address = 192.168.0.31
     FreeRADIUS-Acct-Session-Start-Time = "Apr  4 2017 08:02:36 MSK"
     Timestamp = 1491282156


I believe this is ridiculous. How on earth could someone be connected to a WLAN for 0 seconds, right?

It's perfectly possible and reasonable. For example, say it were an authentication exchange which did not complete - it could be aborted either by the RADIUS server or the client. 11 or 12 packets sounds reasonable for that, and could certainly take less than 1 second.

But these two are accounting packets. We start to see these after the authentication and authorization phases are completed, right? So I assume at this stage, the user has already been authenticated. Do I assume wrong?

And why do we see exchange of data but no session time? I think this is another bug in the firmware.


The important thing is, *was* the user actually still on-line after this exchange? If they were not, then the RADIUS accounting Stop packet correctly reflects truth (that they were disconnected).  I would then expect to see the user try to re-auth, i.e. you'd see a new authentication exchange and new accounting Start packet a short time later.

Yes, the user *was* online after the exchange. The first packet *is* entered into radacct table, but the second packet is not.


But because it refuses to accept the second packet, I end up with a suspended session.

What refuses the second packet? Your stored procedure, or FreeRADIUS?

If it's your stored procedure, then fix it.  If you think it's FreeRADIUS, then show the freeradius -X output where this occurs.

I believe it is FreeRADIUS that refuses to accept the second packet because my stored procedure
a) does not care about what session length it receives as an argument,
b) can not create entries is the system log.

And I am afraid I can't send you the debug log, since I retrieve all my data from a live network. I constantly check the system log, the database and accounting details and when I see something strange, I check it. FYI, I have not run into the same problem in my test lab; but of course, I only have a Windows 7 laptop and iPhone SE to test.


Regards,

Brian.

P.S. There definitely used to be some bugs in Unifi AP RADIUS accounting a few years ago - it got one pair of send/receive counters the wrong way round, and there was also a situation where the value was not initialized properly so it gave garbage.  But those problems came from a very old version of Hostapd, and I think they have picked up the fixes by now.


"Used to be"? I could provide you with evidence of 5 RADIUS accounting bugs right now. For one thing, the UAP *sometimes* miscounts data. It does not implement the Session-Timeout attribute properly. (Still, the second session is never terminated.) It does not respect the Idle-Timeout attribute at all. (It could try to resume a session hours later!) RADIUS accounting functionality is riddled with bugs. Now, I look like an idiot thanks to them.

Best regards.

Selahattin CILEK






[https://ipmcdn.avast.com/images/icons/icon-envelope-tick-round-orange-animated-no-repeat-v1.gif]<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=emailclient>      Virus-free. www.avast.com<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=emailclient>