"[sql] stop packet with zero session length" problem
I have been trying to get the Unifi AP line of products to work with FreeRADIUS (v 2.2.9) seamlessly for quite some time now; but with little success, I am afraid to say. It turned out that the portion of the firmware that deals with RADIUS accounting is a complete mess. I have sent them many e-mails with detailed information for the many bugs I have discovered. They say they will fix them all and I am still waiting. Since I cannot tell the site owners to dump all their Ubiquiti hardware and buy new equipment, my only option is to make the most of FreeRADIUS configuration and MySQL programming to compensate for the firmware bugs in the UAP. However, there is one bug for which I have not been able to find a workaround. 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? We can observe this bug in FreeRADIUS log messages too: Apr 4 08:02:36 radiusd 96187 [sql] stop packet with zero session length. [user '99481225842', nas '192.168.0.31'] So what is the problem? Well, the problem is that when FreeRADIUS receives the first packet, it runs a custom MySQL stored procedure I have written myself, which enters a record into the radacct table. But because it refuses to accept the second packet, I end up with a suspended session. And because users allowed to connect one device only to the network (Simultaneous-Use := 1), they will have to wait for 10 minutes for the suspended session to drop, thanks to a custom bash script. My question is: How can I make the sql module to accept accounting packets with zero session length? PS: Upgrading to FreeRADIUS 3.x is not an option. Thanks in advance. 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>
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. 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.
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. 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.
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>
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.
I have seen NASes which send a Stop accounting record (with zero session time) for authentication failures. But you're right that the Start record *does* imply authentication was OK. So it might mean the client disconnected immediately after authenticating. Any session with duration less than one full second I would expect to see as zero.
Yes, the user*was* online after the exchange. The first packet*is* entered into radacct table, but the second packet is not.
What I asked was whether you had any evidence that the user was in fact online after the Stop record was sent. The accounting records say the user was *not* online, and in the absence of evidence to the contrary, I am inclined to believe them. If you go through your radacct table and find a subsequent Start record for the same user a few seconds later, then that would be evidence that the user did in fact disconnect and then started a new session, i.e. the AP is telling the truth. If the user is still online and sending/receiving packets after the Stop record was sent, but no further Start packet has been seen, then you have evidence that the Stop packet was incorrect.
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.
What you seem to be saying is: "I think freeradius 2.2.9 is broken, but I can't provide any direct evidence to back up the assertion nor information to help the developers fix it, and by the way I'm not prepared to update to a current and supported version either" I think you need to get into a position where you can collect more information. For example: a live network obviously should have more than one RADIUS server for redundancy. Can you perhaps run one in debug mode and the rest in normal mode? Even if the debug instance can't keep up with a full load, the others should take up the slack. Or stop the server, run in debug mode for 5 seconds and replicate the problem, then start the server in normal mode again. The debug output will probably identify the issue for you. If it's a config issue on your side, a database problem, or a NAS problem then you can proceed to fix. But if it *did* happen to be a FreeRADIUS problem, remember that nobody is going to release a version 2.2.10 for you. And even if they did, and you got 2.2.9 from an OS package, the OS vendor would need persuading to package 2.2.10. So in that case, you'd have to make your own patch and build/deploy it yourself (this is open source, so help yourself). IBut it would probably be easier for you to deploy 3.0.13, which is what many people on this list are running and developing against. Regards, Brian.
On 04.04.2017 13:35, Brian Candler wrote:
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.
I have seen NASes which send a Stop accounting record (with zero session time) for authentication failures. But you're right that the Start record *does* imply authentication was OK. So it might mean the client disconnected immediately after authenticating. Any session with duration less than one full second I would expect to see as zero.
Yes, the user *was* online after the exchange. The first packet *is* entered into radacct table, but the second packet is not.
What I asked was whether you had any evidence that the user was in fact online after the Stop record was sent. The accounting records say the user was *not* online, and in the absence of evidence to the contrary, I am inclined to believe them. If you go through your radacct table and find a subsequent Start record for the same user a few seconds later, then that would be evidence that the user did in fact disconnect and then started a new session, i.e. the AP is telling the truth. If the user is still online and sending/receiving packets after the Stop record was sent, but no further Start packet has been seen, then you have evidence that the Stop packet was incorrect.
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.
What you seem to be saying is: "I think freeradius 2.2.9 is broken, but I can't provide any direct evidence to back up the assertion nor information to help the developers fix it, and by the way I'm not prepared to update to a current and supported version either" I did not imply anything of the sort. I only wanted to know if there is some sort of configuration parameter that I could manipulate to make the sql module accept accounting packets with zero session length so that I could compensate for the issue in MySQL code. FreeRADIUS (2.2.9) is quite solid, the problem is the NAS. I think you need to get into a position where you can collect more information. For example: a live network obviously should have more than one RADIUS server for redundancy. Can you perhaps run one in debug mode and the rest in normal mode? Even if the debug instance can't keep up with a full load, the others should take up the slack. Or stop the server, run in debug mode for 5 seconds and replicate the problem, then start the server in normal mode again. The debug output will probably identify the issue for you. If it's a config issue on your side, a database problem, or a NAS problem then you can proceed to fix. But if it *did* happen to be a FreeRADIUS problem, remember that nobody is going to release a version 2.2.10 for you. And even if they did, and you got 2.2.9 from an OS package, the OS vendor would need persuading to package 2.2.10. I understand. You're welcome. So in that case, you'd have to make your own patch and build/deploy it yourself (this is open source, so help yourself). IBut it would probably be easier for you to deploy 3.0.13, which is what many people on this list are running and developing against. Regards, Brian. 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>
On Apr 4, 2017, at 5:03 AM, Brian Candler <b.candler@pobox.com> wrote: 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.
I disagree. The NAS should *only* send accounting packets after an authentication session has been established. Alan DeKok.
On 4 Apr 2017, at 06:25, Selahattin Cilek <selahattin_cilek@hotmail.com> wrote:
My question is: How can I make the sql module to accept accounting packets with zero session length?
You could change the code to override the check, but that seems unnecessary. I would just override the session length to 1. Regards, Adam Bishop Senior Infrastructure and Systems Architect gpg: E75B 1F92 6407 DFDF 9F1C BF10 C993 2504 6609 D460 t: +44 (0)1235 822 245 xmpp: adamb@jabber.dev.ja.net jisc.ac.uk Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc’s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800. Jisc Services Limited is a wholly owned Jisc subsidiary and a company limited by guarantee which is registered in England under company number 2881024, VAT number GB 197 0632 86. The registered office is: One Castle Park, Tower Hill, Bristol BS2 0JA. T 0203 697 5800.
On Apr 4, 2017, at 1:25 AM, Selahattin Cilek <selahattin_cilek@hotmail.com> wrote:
Since I cannot tell the site owners to dump all their Ubiquiti hardware and buy new equipment, my only option is to make the most of FreeRADIUS configuration and MySQL programming to compensate for the firmware bugs in the UAP. However, there is one bug for which I have not been able to find a workaround.
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: ... I believe this is ridiculous. How on earth could someone be connected to a WLAN for 0 seconds, right? We can observe this bug in FreeRADIUS log messages too:
Apr 4 08:02:36 radiusd 96187 [sql] stop packet with zero session length. [user '99481225842', nas '192.168.0.31']
So what is the problem? Well, the problem is that when FreeRADIUS receives the first packet, it runs a custom MySQL stored procedure I have written myself, which enters a record into the radacct table. But because it refuses to accept the second packet, I end up with a suspended session. And because users allowed to connect one device only to the network (Simultaneous-Use := 1), they will have to wait for 10 minutes for the suspended session to drop, thanks to a custom bash script.
My question is: How can I make the sql module to accept accounting packets with zero session length?
Follow Adam's suggestion. In code: accounting { ... if (Acct-Session-Time == 0) { update request { Acct-Session-Time := 1 } } sql ... }
PS: Upgrading to FreeRADIUS 3.x is not an option.
I've never understood that approach. Yes, you *can* upgrade. You simply choose not to. Alan DeKok.
On 04.04.2017 15:33, Alan DeKok wrote: On Apr 4, 2017, at 1:25 AM, Selahattin Cilek <selahattin_cilek@hotmail.com><mailto:selahattin_cilek@hotmail.com> wrote: Since I cannot tell the site owners to dump all their Ubiquiti hardware and buy new equipment, my only option is to make the most of FreeRADIUS configuration and MySQL programming to compensate for the firmware bugs in the UAP. However, there is one bug for which I have not been able to find a workaround. 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: ... I believe this is ridiculous. How on earth could someone be connected to a WLAN for 0 seconds, right? We can observe this bug in FreeRADIUS log messages too: Apr 4 08:02:36 radiusd 96187 [sql] stop packet with zero session length. [user '99481225842', nas '192.168.0.31'] So what is the problem? Well, the problem is that when FreeRADIUS receives the first packet, it runs a custom MySQL stored procedure I have written myself, which enters a record into the radacct table. But because it refuses to accept the second packet, I end up with a suspended session. And because users allowed to connect one device only to the network (Simultaneous-Use := 1), they will have to wait for 10 minutes for the suspended session to drop, thanks to a custom bash script. My question is: How can I make the sql module to accept accounting packets with zero session length? Follow Adam's suggestion. In code: accounting { ... if (Acct-Session-Time == 0) { update request { Acct-Session-Time := 1 } } sql ... } Thanks for the advice, I'll give it a try. The solution was obvious, was it not? PS: Upgrading to FreeRADIUS 3.x is not an option. I've never understood that approach. Yes, you *can* upgrade. You simply choose not to. Well, it is not a matter of choice. The reason is just embarrassing, I can't tell you why. Please do not ask. Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html [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>
Ahh,
PS: Upgrading to FreeRADIUS 3.x is not an option. I've never understood that approach. Yes, you *can* upgrade. You simply choose not to. Well, it is not a matter of choice. The reason is just embarrassing, I can't tell you why. Please do not ask.
Alan, I suspect this is a classic case of 'decision made above my pay grade despite me being the technical authority'. It happens. Often. Stefan Paetow Moonshot Industry & Research Liaison Coordinator t: +44 (0)1235 822 125 gpg: 0x3FCE5142 xmpp: stefanp@jabber.dev.ja.net skype: stefan.paetow.janet jisc.ac.uk Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc¹s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800.
On Apr 6, 2017, at 9:11 AM, Stefan Paetow <Stefan.Paetow@jisc.ac.uk> wrote:
Alan, I suspect this is a classic case of 'decision made above my pay grade despite me being the technical authority'.
It happens. Often.
This is known as getting a subject-matter expert, and then not listening to them. As people here may have figured out, I'm rather opposed to that attitude. It's one reason I've left jobs in the past. Alan DeKok.
participants (5)
-
Adam Bishop -
Alan DeKok -
Brian Candler -
Selahattin Cilek -
Stefan Paetow