Child is hung for request # in component session module

[Roman]

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.