<html dir="ltr">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1">
<style id="owaParaStyle" type="text/css">P {margin-top:0;margin-bottom:0;}</style>
</head>
<body ocsi="0" fpstyle="1">
<div style="direction: ltr;font-family: Tahoma;color: #000000;font-size: 10pt;"><br>
I'm currently hunting a problem that causes a recent checkout of FR3.0<br>
to abort but which does not seem to be affecting an older revision (April 8th or so)<br>
of FR3.0 on another box. I do have a couple small in-house patches applied<br>
but they should probably not be relevant.<br>
<br>
The issue seems to happen when a home-server does not respond to a request,<br>
and then FR re-enqueues the request as a retransmit. The request then gets<br>
dequeued again, and at that point fails a REQUEST_MAGIC assert. That is,<br>
if I am reading the logs correctly...<br>
<br>
Logs are included, with a few added printfs thrown in.<br>
<br>
Anyone have any suggestions for good commits to bisect at?<br>
<br>
<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=2<br>
63<br>
request_enqueue 0x13d5220 <br>
Thread 1 got semaphore<br>
request_dequeue prequest before 0x13c0a00->(nil) <br>
Thread 3 got semaphore<br>
request_dequeue found request 0x13d5220 <br>
Thread 2 got semaphore<br>
request_dequeue prequest after 0x13c0a00->0x13d5220 <br>
request_dequeue prequest before 0x13c0b80->(nil) <br>
Thread 4 got semaphore<br>
Thread 2 exiting...<br>
Thread 1 handling request 258, (130 handled so far)<br>
request_dequeue prequest before 0x13c0e80->(nil) <br>
Thread 4 exiting...<br>
[... request dump ...]<br>
request_dequeue prequest before 0x13c0d00->(nil) <br>
Thread 3 exiting...<br>
(258) <thread> : # Executing section authorize from file /etc/raddb/eduroam_sp.c<br>
onf<br>
[... bunch of unlang/realm chatter ...]<br>
Sending Access-Request of id 38 to [... request dump ...]<br>
(258) Proxying request to home server ...<br>
Thread 1 exiting...<br>
Waking up in 0.2 seconds.<br>
request_enqueue 0x13d5220 <br>
Waking up in 0.2 seconds.<br>
Waking up in 0.4 seconds.<br>
Waking up in 0.7 seconds.<br>
Waking up in 1.1 seconds.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263<br>
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258<br>
Waking up in 0.9 seconds.<br>
Waking up in 1.4 seconds.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263<br>
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258<br>
Waking up in 0.4 seconds.<br>
(255) Cleaning up request packet ID 198 with timestamp +6868<br>
Waking up in 0.2 seconds.<br>
(256) Cleaning up request packet ID 166 with timestamp +6868<br>
Waking up in 0.2 seconds.<br>
(257) Cleaning up request packet ID 128 with timestamp +6868<br>
Waking up in 2.1 seconds.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263<br>
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258<br>
Waking up in 1.1 seconds.<br>
Waking up in 3.7 seconds.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263<br>
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258<br>
Waking up in 2.9 seconds.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263<br>
Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258<br>
Waking up in 0.9 seconds.<br>
Waking up in 5.6 seconds.<br>
Waking up in 8.5 seconds.<br>
Waking up in 12.8 seconds.<br>
Waking up in 19.2 seconds.<br>
Waking up in 28.8 seconds.<br>
(258) <queue> : Cleaning up request packet ID 104 with timestamp +6869<br>
Ready to process requests.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=125, length=254<br>
request_enqueue 0x13c2080 <br>
Deleting thread 1<br>
Deleting thread 2<br>
Deleting thread 3<br>
Deleting thread 4<br>
Waking up in 0.3 seconds.<br>
Waking up in 0.4 seconds.<br>
Waking up in 0.7 seconds.<br>
Waking up in 1.1 seconds.<br>
Waking up in 1.6 seconds.<br>
Waking up in 2.5 seconds.<br>
Waking up in 3.7 seconds.<br>
Waking up in 5.6 seconds.<br>
Waking up in 8.5 seconds.<br>
Waking up in 12.8 seconds.<br>
Waking up in 19.2 seconds.<br>
Waking up in 28.8 seconds.<br>
(259) <queue> : Cleaning up request packet ID 125 with timestamp +10992<br>
Ready to process requests.<br>
rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=228, length=254<br>
request_enqueue 0x13c2080 <br>
Threads: total/active/spare threads = 0/0/0<br>
Threads: Spawning 4 spares<br>
Thread spawned new child 5. Total threads in pool: 1<br>
Thread spawned new child 6. Total threads in pool: 2<br>
Thread spawned new child 7. Total threads in pool: 3<br>
Thread 5 waiting to be assigned a request<br>
Thread 5 got semaphore<br>
request_dequeue prequest before 0x13c0e80->(nil) <br>
request_dequeue found request 0x13d5220 <br>
ASSERT FAILED threads.c[468]: request->magic == REQUEST_MAGIC<br>
Thread spawned new child 8. Total threads in pool: 4<br>
Thread 7 waiting to be assigned a request<br>
Thread 6 waiting to be assigned a request<br>
Thread 6 got semaphore<br>
Thread 7 got semaphore<br>
<br>
</div>
</body>
</html>