request_dequeue problems (recent 3.0, when home-server stalls)

[Brian Julin]

I'm currently hunting a problem that causes a recent checkout of FR3.0
to abort but which does not seem to be affecting an older revision (April 8th or so)
of FR3.0 on another box.  I do have a couple small in-house patches applied
but they should probably not be relevant.

The issue seems to happen when a home-server does not respond to a request,
and then FR re-enqueues the request as a retransmit.  The request then gets
dequeued again, and at that point fails a REQUEST_MAGIC assert.  That is,
if I am reading the logs correctly...

Logs are included, with a few added printfs thrown in.

Anyone have any suggestions for good commits to bisect at?


rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=2
63
request_enqueue 0x13d5220
Thread 1 got semaphore
request_dequeue prequest before 0x13c0a00->(nil)
Thread 3 got semaphore
request_dequeue found request 0x13d5220
Thread 2 got semaphore
request_dequeue prequest after 0x13c0a00->0x13d5220
request_dequeue prequest before 0x13c0b80->(nil)
Thread 4 got semaphore
Thread 2 exiting...
Thread 1 handling request 258, (130 handled so far)
request_dequeue prequest before 0x13c0e80->(nil)
Thread 4 exiting...
   [... request dump ...]
request_dequeue prequest before 0x13c0d00->(nil)
Thread 3 exiting...
(258) <thread> : # Executing section authorize from file /etc/raddb/eduroam_sp.c
onf
   [... bunch of unlang/realm chatter ...]
Sending Access-Request of id 38 to [... request dump ...]
(258) Proxying request to home server ...
Thread 1 exiting...
Waking up in 0.2 seconds.
request_enqueue 0x13d5220
Waking up in 0.2 seconds.
Waking up in 0.4 seconds.
Waking up in 0.7 seconds.
Waking up in 1.1 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258
Waking up in 0.9 seconds.
Waking up in 1.4 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258
Waking up in 0.4 seconds.
(255) Cleaning up request packet ID 198 with timestamp +6868
Waking up in 0.2 seconds.
(256) Cleaning up request packet ID 166 with timestamp +6868
Waking up in 0.2 seconds.
(257) Cleaning up request packet ID 128 with timestamp +6868
Waking up in 2.1 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258
Waking up in 1.1 seconds.
Waking up in 3.7 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258
Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258
Waking up in 0.9 seconds.
Waking up in 5.6 seconds.
Waking up in 8.5 seconds.
Waking up in 12.8 seconds.
Waking up in 19.2 seconds.
Waking up in 28.8 seconds.
(258) <queue> : Cleaning up request packet ID 104 with timestamp +6869
Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=125, length=254
request_enqueue 0x13c2080
Deleting thread 1
Deleting thread 2
Deleting thread 3
Deleting thread 4
Waking up in 0.3 seconds.
Waking up in 0.4 seconds.
Waking up in 0.7 seconds.
Waking up in 1.1 seconds.
Waking up in 1.6 seconds.
Waking up in 2.5 seconds.
Waking up in 3.7 seconds.
Waking up in 5.6 seconds.
Waking up in 8.5 seconds.
Waking up in 12.8 seconds.
Waking up in 19.2 seconds.
Waking up in 28.8 seconds.
(259) <queue> : Cleaning up request packet ID 125 with timestamp +10992
Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=228, length=254
request_enqueue 0x13c2080
Threads: total/active/spare threads = 0/0/0
Threads: Spawning 4 spares
Thread spawned new child 5. Total threads in pool: 1
Thread spawned new child 6. Total threads in pool: 2
Thread spawned new child 7. Total threads in pool: 3
Thread 5 waiting to be assigned a request
Thread 5 got semaphore
request_dequeue prequest before 0x13c0e80->(nil)
request_dequeue found request 0x13d5220
ASSERT FAILED threads.c[468]: request->magic == REQUEST_MAGIC
Thread spawned new child 8. Total threads in pool: 4
Thread 7 waiting to be assigned a request
Thread 6 waiting to be assigned a request
Thread 6 got semaphore
Thread 7 got semaphore

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120828/0a19dae8/attachment.html>