request_dequeue problems (recent 3.0, when home-server stalls)
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
Brian Julin wrote:
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.
It's always worth checking.
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...
OK.
Logs are included, with a few added printfs thrown in.
Anyone have any suggestions for good commits to bisect at?
There aren't really many changes to process.c. That's the key function behind all of this.
request_dequeue found request 0x13d5220 ASSERT FAILED threads.c[468]: request->magic == REQUEST_MAGIC
Which means that the request has been deleted, but is still in the queue. That's not supposed to happen... Alan DeKok.
I had some more time to play with this; it seems to be related to retiring old threads, not actual problem on the home server. Some new observations below.
Alan DeKok wrote on Aug28, 2012:
Brian Julin wrote:
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. It's always worth checking.
OK, I've tested with a recent clean clone and it still has the problem.
request_dequeue found request 0x13d5220 ASSERT FAILED threads.c[468]: request->magic == REQUEST_MAGIC Which means that the request has been deleted, but is still in the queue. That's not supposed to happen...
After collecting some more debug logs, I noticed that this problem was happening too often on requests numbered around 260 to be a coincidence. It turns out this happens after a thread is marked for recycling due to having handled over 128 requests. I'm no longer positive that the home server is not responding, though it could have similar limits set up on the RADSEC connection so we cannot completely eliminate that as a possibility. It seems a lot more likely, though, that something is getting wedged up locally and the request to the home server never actually hits the wire. The server will ride over the thread recycling if it is handling requests that do not need to be proxied at the moment when the threads are marked; it only has trouble in the middle of conversations. Below is a debug log with some extra radlogs thrown in by hand. The "Reaping" lines happen in the loop that tests whether threads have handled so many connections that they should be retired. Is it normal for a thread to grab and handle requests after it has been marked for recycling? We start in the middle of an ongoing EAP conversation. Sending Access-Challenge of id 96 to 127.0.0.1 port 34912 [request dump omitted] (259) Finished request 259. Thread 2 waiting to be assigned a request Waking up in 0.3 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Deleting thread 3 Deleting thread 4 Reaping... Reaping thread 1 due to number of requests handled (130/128 handled) Reaping... Reaping thread 2 due to number of requests handled (131/128 handled) Waking up in 0.2 seconds. Thread 2 got semaphore Thread 2 handling request 260, (132 handled so far) [request dump omitted] Thread 1 got semaphore Thread 1 exiting... [unlang trace omitted] Sending Access-Request of id 238 to XXXXXXXXXXX port 2083 [request dump omitted] Thread 2 exiting... Waking up in 0.3 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 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 Waking up in 0.9 seconds. Waking up in 1.1 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 (256) Cleaning up request packet ID 213 with timestamp +11084 rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 (256) Cleaning up request packet ID 213 with timestamp +11084 Waking up in 0.2 seconds. (257) Cleaning up request packet ID 10 with timestamp +11085 Waking up in 0.2 seconds. (258) Cleaning up request packet ID 151 with timestamp +11085 Waking up in 0.2 seconds. (259) Cleaning up request packet ID 96 with timestamp +11085 Waking up in 2.2 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 Waking up in 1.1 seconds. Waking up in 3.7 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 Waking up in 2.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=242, length=273 Discarding duplicate request from client EDUROAM_OUT port 34912 - ID: 242 due to unfinished request 260 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. (260) <queue> : Cleaning up request packet ID 242 with timestamp +11086 Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 34912, id=104, length=272 Threads: total/active/spare threads = 2/0/2 Threads: Spawning 2 spares Thread spawned new child 5. Total threads in pool: 3 Thread spawned new child 6. Total threads in pool: 4 Waking up in 0.3 seconds. Thread 5 waiting to be assigned a request Thread 5 got semaphore ASSERT FAILED threads.c[461]: request->magic == REQUEST_MAGIC Thread 6 waiting to be assigned a request Thread 6 got semaphore
Brian Julin wrote:
After collecting some more debug logs, I noticed that this problem was happening too often on requests numbered around 260 to be a coincidence. It turns out this happens after a thread is marked for recycling due to having handled over 128 requests.
Well, set "max_requests_per_server = 0". There's really no reason to clean up old threads.
Below is a debug log with some extra radlogs thrown in by hand. The "Reaping" lines happen in the loop that tests whether threads have handled so many connections that they should be retired. Is it normal for a thread to grab and handle requests after it has been marked for recycling?
No. See src/main/threads.c. The thread loops around while self.status != cancelled That's a poorly tested edge condition. The honest recommendation is just to set "max_requests_per_server = 0". My suggestion is also to remove that configuration entirely in 3.0. Alan DeKok.
On 20/09/12 15:29, Alan DeKok wrote:
Brian Julin wrote:
After collecting some more debug logs, I noticed that this problem was happening too often on requests numbered around 260 to be a coincidence. It turns out this happens after a thread is marked for recycling due to having handled over 128 requests.
Well, set "max_requests_per_server = 0".
There's really no reason to clean up old threads.
Indeed. It's not like it will free up any OS resources - memory or file descriptor leaks are per-process.
participants (3)
-
Alan DeKok -
Brian Julin -
Phil Mayers