Child is hung for request # in component session module
Hi, Thanks for freeradius! I was googling and fight with this issue for the last 23 hours. My setup is: Mikrotik as PPPoE server and Debian Jessie 8.5 with Freeradius 2.2.5. Also tested with Debian Wheezy 7.11 and Freeradius 2.1.12. I use radutmp for Simultaneous-Use = 1 control and store users in users file. Don't plan to switch to SQL, as this setup won't grow that large. checkrad working fine on both setups (I use mikrotik_snmp method) So it asks Mikrotik by SNMP if there are virtual interfaces with usernames and reports if user allowed to login. The problem starts with stale sessions. We know, that accounting runs over udp and we could lose some logoff packets, but it should not be an issue, when checkrad does it's job. So if there is a session in radius server (radwho shows loged in user) and no session on PPPoE server, Freeradius just hangs and shows it in logs pretty honestly: ed Jul 13 01:41:02 2016 : Info: WARNING: Child is hung for request 17 in component session module . Wed Jul 13 01:41:02 2016 : Debug: Waking up in 0.1 seconds. Wed Jul 13 01:41:02 2016 : Info: WARNING: Child is hung for request 16 in component session module . Wed Jul 13 01:41:02 2016 : Debug: Waking up in 0.9 seconds. Wed Jul 13 01:41:03 2016 : Error: Discarding duplicate request from client cli-ter1-lo0 port 38676 - ID: 115 due to unfinished request 18 Wed Jul 13 01:41:03 2016 : Debug: Waking up in 0.3 seconds. Wed Jul 13 01:41:03 2016 : Info: WARNING: Child is hung for request 15 in component session module . Wed Jul 13 01:41:03 2016 : Debug: Waking up in 0.3 seconds. Nothing more interesting in logs. If I run server in debug mode, it just freezes on this step: Wed Jul 13 01:54:44 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Jul 13 01:54:44 2016 : Info: +group authorize { Wed Jul 13 01:54:44 2016 : Info: ++[preprocess] = ok Wed Jul 13 01:54:44 2016 : Info: [chap] Setting 'Auth-Type := CHAP' Wed Jul 13 01:54:44 2016 : Info: ++[chap] = ok Wed Jul 13 01:54:44 2016 : Info: ++[mschap] = noop Wed Jul 13 01:54:44 2016 : Info: [suffix] No '@' in User-Name = "tt23kswp17", looking up realm NULL Wed Jul 13 01:54:44 2016 : Info: [suffix] No such realm "NULL" Wed Jul 13 01:54:44 2016 : Info: ++[suffix] = noop Wed Jul 13 01:54:44 2016 : Info: [files] users: Matched entry tt23kswp17 at line 106 Wed Jul 13 01:54:44 2016 : Info: ++[files] = ok Wed Jul 13 01:54:44 2016 : Info: ++[expiration] = noop Wed Jul 13 01:54:44 2016 : Info: ++[logintime] = noop Wed Jul 13 01:54:44 2016 : Info: +} # group authorize = ok Wed Jul 13 01:54:44 2016 : Info: Found Auth-Type = CHAP Wed Jul 13 01:54:44 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Jul 13 01:54:44 2016 : Info: +group CHAP { Wed Jul 13 01:54:44 2016 : Info: [chap] login attempt by "tt23kswp17" with CHAP password Wed Jul 13 01:54:44 2016 : Info: [chap] Using clear text password "secret" for user tt23kswp17 authentication. Wed Jul 13 01:54:44 2016 : Info: [chap] chap user tt23kswp17 authenticated succesfully Wed Jul 13 01:54:44 2016 : Info: ++[chap] = ok Wed Jul 13 01:54:44 2016 : Info: +} # group CHAP = ok Wed Jul 13 01:54:44 2016 : Info: # Executing section session from file /etc/freeradius/sites-enabled/default Wed Jul 13 01:54:44 2016 : Info: +group session { Wed Jul 13 01:54:44 2016 : Info: [radutmp] expand: /var/log/freeradius/radutmp -> /var/log/freeradius/radutmp Wed Jul 13 01:54:44 2016 : Info: [radutmp] expand: %{User-Name} -> tt23kswp17 Wed Jul 13 01:54:44 2016 : Info: # Executing section preacct from file /etc/freeradius/sites-enabled/default Wed Jul 13 01:54:44 2016 : Info: +group preacct { Wed Jul 13 01:54:44 2016 : Info: ++[preprocess] = ok Wed Jul 13 01:54:44 2016 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent Wed Jul 13 01:54:44 2016 : Info: [acct_unique] Hashing 'NAS-Port = 15728739,,NAS-IP-Address = my.ip,Acct-Session-Id = "81300063",User-Name = "tt23kswp17"' Wed Jul 13 01:54:44 2016 : Info: [acct_unique] Acct-Unique-Session-ID = "5cddac4e2d445dcf". Wed Jul 13 01:54:44 2016 : Info: ++[acct_unique] = ok Wed Jul 13 01:54:44 2016 : Info: [suffix] No '@' in User-Name = "tt23kswp17", looking up realm NULL Wed Jul 13 01:54:44 2016 : Info: [suffix] No such realm "NULL" Wed Jul 13 01:54:44 2016 : Info: ++[suffix] = noop Wed Jul 13 01:54:44 2016 : Info: ++[files] = noop Wed Jul 13 01:54:44 2016 : Info: +} # group preacct = ok Wed Jul 13 01:54:44 2016 : Info: # Executing section accounting from file /etc/freeradius/sites-enabled/default Wed Jul 13 01:54:44 2016 : Info: +group accounting { Wed Jul 13 01:54:44 2016 : Info: [detail] expand: %{Packet-Src-IP-Address} -> my.ip Wed Jul 13 01:54:44 2016 : Info: [detail] expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /var/log/freeradius/radacct/my.ip/detail-20160713 Wed Jul 13 01:54:44 2016 : Info: [detail] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/my.ip/detail-20160713 Wed Jul 13 01:54:44 2016 : Info: [detail] expand: %t -> Wed Jul 13 01:54:44 2016 Wed Jul 13 01:54:44 2016 : Info: ++[detail] = ok and if i look at logs after some time, I get this: Wed Jul 13 01:42:29 2016 : Info: [radutmp] expand: /var/log/freeradius/radutmp -> /var/log/freeradius/radutmp Wed Jul 13 01:42:29 2016 : Info: [radutmp] expand: %{User-Name} -> tt23kswp17 Wed Jul 13 01:42:29 2016 : Info: ++[radutmp] = ok Wed Jul 13 01:42:29 2016 : Info: [sradutmp] expand: /var/log/freeradius/sradutmp -> /var/log/freeradius/sradutmp Wed Jul 13 01:42:29 2016 : Info: [sradutmp] expand: %{User-Name} -> tt23kswp17 Wed Jul 13 01:42:29 2016 : Info: ++[sradutmp] = ok Wed Jul 13 01:42:29 2016 : Info: ++[exec] = noop Wed Jul 13 01:42:29 2016 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> tt23kswp17 Wed Jul 13 01:42:29 2016 : Debug: attr_filter: Matched entry DEFAULT at line 12 Wed Jul 13 01:42:29 2016 : Info: ++[attr_filter.accounting_response] = updated Wed Jul 13 01:42:29 2016 : Info: +} # group accounting = updated Wed Jul 13 01:42:29 2016 : Info: Finished request 1. Wed Jul 13 01:42:29 2016 : Debug: Going to the next request Wed Jul 13 01:42:29 2016 : Debug: Thread 7 waiting to be assigned a request Wed Jul 13 01:42:30 2016 : Info: Cleaning up request 1 ID 137 with timestamp +2 Wed Jul 13 01:42:30 2016 : Debug: Waking up in 3.9 seconds. Wed Jul 13 01:42:34 2016 : Info: Cleaning up request 0 ID 136 with timestamp +2 Wed Jul 13 01:42:34 2016 : Info: Ready to process requests. Wed Jul 13 01:54:21 2016 : Info: Ready to process requests. Wed Jul 13 01:54:21 2016 : Info: Signalled to terminate Wed Jul 13 01:54:21 2016 : Info: Exiting normally. Wed Jul 13 01:54:21 2016 : Debug: Thread 9 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 9 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 10 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 10 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 6 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 6 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 5 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 5 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 4 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 4 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 3 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 3 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 2 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 2 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 1 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 1 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 8 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 8 exiting... Wed Jul 13 01:54:21 2016 : Debug: Thread 7 got semaphore Wed Jul 13 01:54:21 2016 : Debug: Thread 7 exiting... Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 1 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 2 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 3 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 4 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 5 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 6 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 7 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 8 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 9 Wed Jul 13 01:54:21 2016 : Debug: Deleting thread 10 And none of users are able to login, I even can't radzap session. I have to delete the radutmp file and radacc directory and start Freeradius over to get ovet this. Any ideas? I've ran out of them. -- Best regards, Roman.
Hi,
Freeradius 2.2.5. Also tested with Debian Wheezy 7.11 and Freeradius 2.1.12. I use radutmp for Simultaneous-Use = 1 control and store users in users file. Don't plan to switch to SQL, as this setup won't grow that large.
radutmp doesnt scale. after time it becomes large and unwieldy . I'm afraid that your issues are resolved by changing your plans - move to SQL.
Wed Jul 13 01:54:44 2016 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent
you need to fix that too. without uniq acct tag you'll get collisions. alan
Hi, thanks for answers! 2016-07-13 5:09 GMT+03:00 Alan DeKok <aland@deployingradius.com>:
Upgrade to 2.2.9. This issue is fixed.
I thought I won't be mammoth at all and upgraded to the latest stable 3.0.11 (built from sources). True, no such problems detected. The only thing I care about is to radzap stale sessions automatically. As Mikrotiks now send with ifDesk MIB the port numbers needed to radzap all the staled sessions, it now becomes the matter of modifying the checkrad script in the way I need it or to write a custom one. Thi logic could be radzap every single session showed in radwho output and not running on the PPPoE Server. Am I right here? Also I'd like to disconnect the session, when user makes second connection. Running this and simple command like exec(exec "/bin/echo User-Name = $ARGV[3] | radclient -r 1 IP disconnect secret"); should be enough to solve this one? 2016-07-13 10:50 GMT+03:00 <A.L.M.Buxey@lboro.ac.uk>:
radutmp doesnt scale. after time it becomes large and unwieldy . I'm afraid that your issues are resolved by changing your plans - move to SQL.
If I'll leave only the session part for radutmp to control the Simultaneous-Use would it be enough to skip moving to the SQL? I don't need the accounting thing much.
you need to fix that too. without uniq acct tag you'll get collisions.
Thanks for a note! As this was just a quick setup for testing purposes I didn't configure all the things. Now it is fixed also. -- Best regards, Roman.
On Jul 13, 2016, at 5:36 AM, Roman <romeo.r@gmail.com> wrote:
As Mikrotiks now send with ifDesk MIB the port numbers needed to radzap all the staled sessions, it now becomes the matter of modifying the checkrad script in the way I need it or to write a custom one. Thi logic could be radzap every single session showed in radwho output and not running on the PPPoE Server. Am I right here?
Sounds right.
Also I'd like to disconnect the session, when user makes second connection. Running this and simple command like exec(exec "/bin/echo User-Name = $ARGV[3] | radclient -r 1 IP disconnect secret"); should be enough to solve this one?
You can run radclient directly. No need to run "echo".
If I'll leave only the session part for radutmp to control the Simultaneous-Use would it be enough to skip moving to the SQL? I don't need the accounting thing much.
If you have ~1000 users, radutmp is OK. Past that, use SQL. Alan DeKok.
2016-07-13 15:46 GMT+03:00 Alan DeKok <aland@deployingradius.com>:
You can run radclient directly. No need to run "echo".
Oh, thanks. I will look closer at this.
If you have ~1000 users, radutmp is OK. Past that, use SQL.
Hm. This is great hint actually, thanks! Our goal is to stay maximum around 800 users total per 4 Mikrotiks and 1 FreeRadius server to keep things running smoothly. -- Best regards, Roman.
Hello All, Yesterday one of my NAS restarted and 350 users authenticated almost simultaneously. I use detail and SQL. The users normally authenticated and their connections were recorded in detail but were not updated in the MySQL database. My users are all in MySQL. My scenario: FreeRadius 2.2.9 on FreeBSD, NAS Mikrotik. No errors in the Radius LOG and MySQL LOG. I have enoughsimultaneous connections in MySQL. What could have happened? Some tunning I can do? Thank you Aurélio
On Jul 14, 2016, at 8:05 AM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
The users normally authenticated and their connections were recorded in detail but were not updated in the MySQL database.
I don't know of any situation where it magically stops using SQL. If anything goes wrong, there will be messages in the log file. Alan DeKok.
Alan, You could take a look in my defaults file? Do you suggest something better? ########### authorize { preprocess pap chap mschap digest eap { ok = return } sql expiration logintime if(!control:Auth-Type){ update control { Auth-Type := PAP } ok } } authenticate { Auth-Type PAP { pap { fail = 1 } if(fail) { update control { Pool-Name := "mkt_pool" } update reply { Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K 10/10" } ok } } Auth-Type CHAP { chap { invalid = 1 } if(invalid) { update control { Pool-Name := "mkt_pool" } update reply { Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K 10/10" } ok } } Auth-Type MS-CHAP { mschap { reject = 1 } if(reject) { update control { Pool-Name := "mkt_pool" } update reply { Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K 10/10" } ok } } digest unix eap } preacct { preprocess acct_unique } accounting { detail unix radutmp sradutmp sqlippool sql if (noop){ ok } #sql_log attr_filter.accounting_response } session { # radutmp sql } post-auth { sqlippool } ########### Aurélio Em 14/07/2016 10:05, Alan DeKok escreveu:
On Jul 14, 2016, at 8:05 AM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
The users normally authenticated and their connections were recorded in detail but were not updated in the MySQL database. I don't know of any situation where it magically stops using SQL. If anything goes wrong, there will be messages in the log file.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Jul 14, 2016, at 1:40 PM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
Alan,
You could take a look in my defaults file?
There is nothing in the server which will magically make it stop writing to SQL. a) the NAS never sent accounting packets b) your SQL server was down c) the NAS sent the wrong data, and the SQL module returned "noop" without writing to SQL. One of those situations is what happened. Alan DeKok.
Hello Everyone, I'm using FreeRadius-2.2.9 in FreeBsd with InnoDB MySQL Database, mikrotik NAS's. Everything is working fine. Today I changed my Server. I stopped FreeRadius in both, then synchronized. In my NAS with users logged in, I just change the IP from my FreeRadius Server, and few moments later I receive an "Accounting-On packet" and all my users in recconect. How can I prevent it to happens in next time I need to change my Server IP? Thanks Aurelio
On Aug 22, 2016, at 9:35 PM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
In my NAS with users logged in, I just change the IP from my FreeRadius Server, and few moments later I receive an "Accounting-On packet" and all my users in recconect.
Changing the server IP shouldn't cause all of the users to disconnect.
How can I prevent it to happens in next time I need to change my Server IP?
Buy a NAS that isn't broken. Alan DeKok.
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Aurélio de Souza Ribeiro Neto -
Roman