We use rlm_python and AWS DynamoDB as a backend, and over the weekend there were some problems with DynamoDB: http://venturebeat.com/2015/09/20/amazons-aws-outage-takes-down-netflix-redd.... During this time we saw lots of dynamo errors, but we also started to see a lot of freeradius problems: Sun Sep 20 09:22:18 2015 : WARNING: (27733) WARNING: Module rlm_python became unblocked for request 27733 Sun Sep 20 09:22:37 2015 : Error: Unresponsive child for request 27751, in component accounting module python During this timeframe I see a few things in my statistics: * Our python code taking as long as 4,500 seconds to respond to requests (freeradius is configured to 30 seconds max per request) [image: Inline image 1] * Accounting requests went from 100/5minutes to 17,000/5minutes (as devices were resending accounting packets because they didn't get a response) [image: Inline image 4] These errors kept accumulating and eventually our server wasn't sending any incoming requests to python (and it didn't recover when dynamo recovered), which I know because the python code should have created external logs that don't exist during this time period. This morning I turned on debugging on a node and this is what I see: Mon Sep 21 18:14:46 2015 : Debug: (870048) accounting { Mon Sep 21 18:14:46 2015 : Debug: (870048) modsingle[accounting]: calling python (rlm_python) for request 870048 Mon Sep 21 18:14:46 2015 : Debug: (870048) python: Using thread state 0x7f1058000cc0 Mon Sep 21 18:14:46 2015 : Debug: (870048) modsingle[accounting]: returned from python (rlm_python) for request 870048 Mon Sep 21 18:14:46 2015 : Debug: (870048) [python] = fail Mon Sep 21 18:14:46 2015 : Debug: (870048) } # accounting = fail Mon Sep 21 18:14:46 2015 : Debug: (870048) Not sending reply to client. The first line in our python accounting module is to radlog() so I know if the request hit our code, and that wasn't even happening so it seems as though FreeRADIUS+rlm_python had failed in some way. Restarting freeradius resolved the problem. I'm fairly certain the long request time problem is because the default timeout for the dynamo SDK is none (wait forever). I'm working on setting a boto timeout to prevent the long response time from happening again, but at the moment I'm concerned about how freeradius was failing to even call python after a while. Aside from the boto timeout issue how would we go about debugging the freeradius+python problem to make sure it doesn't happen in the future? Thanks! Andrew
The first line in our python accounting module is to radlog() so I know if the request hit our code, and that wasn't even happening
Hmm, so Python SDK has no timeout, and your complaint is that requests were never timing out? Yes python is smart enough to release the GIL on blocking I/O, no there is not a mechanism to return control to the caller of the Python interpreter on blocking I/O. At least none that i've found wandering through the shitty Python embedding documentation.
so it seems as though FreeRADIUS+rlm_python had failed in some way. Restarting freeradius resolved the problem.
No, your SDK failed, FreeRADIUS+rlm_python functioned as intended.
I'm fairly certain the long request time problem is because the default timeout for the dynamo SDK is none (wait forever). I'm working on setting a boto timeout to prevent the long response time from happening again, but at the moment I'm concerned about how freeradius was failing to even call python after a while.
No, all worker threads were blocked in the python module so there were no threads to call python after a while, they were all already calling python.
Aside from the boto timeout issue how would we go about debugging the freeradius+python problem to make sure it doesn't happen in the future?
Fix the SDK timeout. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Like I said in my original email we are aware of the problems caused by the lack of a timeout and are actively working to fix that, so you don't need to be condescending and rude about the lack of a timeout. My question was that even after dynamo recovered FreeRADIUS continued to fail to call python, and I wanted to make sure that even after we fix the timeout issue that there isn't another problem that could be triggered. Are you suggesting the only possible explanation for what we saw was that all of the worker threads were still waiting for a response from dynamo 2 days later, and that there is no point in debugging why FreeRADIUS was unable to execute rlm_python? I suppose that's possible but it seems unlikely that that many sockets were hung open for that long. Is there any way to see what the worker threads were doing? On Mon, Sep 21, 2015 at 2:37 PM, Arran Cudbard-Bell < a.cudbardb@freeradius.org> wrote:
The first line in our python accounting module is to radlog() so I know
if
the request hit our code, and that wasn't even happening
Hmm, so Python SDK has no timeout, and your complaint is that requests were never timing out?
Yes python is smart enough to release the GIL on blocking I/O, no there is not a mechanism to return control to the caller of the Python interpreter on blocking I/O. At least none that i've found wandering through the shitty Python embedding documentation.
so it seems as though FreeRADIUS+rlm_python had failed in some way. Restarting freeradius resolved the problem.
No, your SDK failed, FreeRADIUS+rlm_python functioned as intended.
I'm fairly certain the long request time problem is because the default timeout for the dynamo SDK is none (wait forever). I'm working on setting a boto timeout to prevent the long response time from happening again, but at the moment I'm concerned about how freeradius was failing to even call python after a while.
No, all worker threads were blocked in the python module so there were no threads to call python after a while, they were all already calling python.
Aside from the boto timeout issue how would we go about debugging the freeradius+python problem to make sure it doesn't happen in the future?
Fix the SDK timeout.
-Arran
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Sep 21, 2015, at 7:06 PM, Andrew Parisio <parisioa@gmail.com> wrote:
Like I said in my original email we are aware of the problems caused by the lack of a timeout and are actively working to fix that, so you don't need to be condescending and rude about the lack of a timeout.
His message was neither condescending nor rude. It simply points out that you're blaming FreeRADIUS, when the real blame lies elsewhere. I suggest learning how to take feedback without getting offended. After all, *you* are the one who asked for help. You should have entertained the idea that perhaps the problem wasn't FreeRADIUS. I *hate* it when people ask questions and get offended at the answers. It's anti-social, and has no place in polite society. suggest dropping the idea that you've been offended, and keeping the conversation technical. The alternative is for you to keep complaining, which will result in you getting unsubscribed and permanently banned from the list.
My question was that even after dynamo recovered FreeRADIUS continued to fail to call python, and I wanted to make sure that even after we fix the timeout issue that there isn't another problem that could be triggered. Are you suggesting the only possible explanation for what we saw was that all of the worker threads were still waiting for a response from dynamo 2 days later, and that there is no point in debugging why FreeRADIUS was unable to execute rlm_python?
That is what Arran said. FreeRADIUS calls Python, which calls your software. If your software doesn't return execution to FreeRADIUS for 2 days, it's the fault of *your software*. Go fix it.
I suppose that's possible but it seems unlikely that that many sockets were hung open for that long. Is there any way to see what the worker threads were doing?
Do python / C debuggers exist? If so, use them. Use "strace". These are all tools which are available to you as an administrator. There is nothing FreeRADIUS-specific about debugging a program. I'll bet dollars to donuts that if you run your Python programs from the shell (not using FreeRADIUS), they'll block for 2 days, too. Which would indicate that the problem isn't FreeRADIUS. Alan DeKok.
On 22 Sep 2015, at 01:46, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 21, 2015, at 7:06 PM, Andrew Parisio <parisioa@gmail.com> wrote:
Like I said in my original email we are aware of the problems caused by the lack of a timeout and are actively working to fix that, so you don't need to be condescending and rude about the lack of a timeout.
His message was neither condescending nor rude. It simply points out that you're blaming FreeRADIUS, when the real blame lies elsewhere. I suggest learning how to take feedback without getting offended.
Right, I was pointing out the issue with the mental model OP constructed to explain what was occurring. I then explained the technical limitation that prevents FreeRADIUS from intervening, control is never returned to rlm_python during blocking calls. For that you'd need a python/C coroutine implementation, which probably doesn't exist, or a python interpreter on the end of a socket, which would allow you to implement an asynchronous interface. Even there, there'd still be issues with blocking, but at least it'd allow FreeRADIUS to control the timeout.
My question was that even after dynamo recovered FreeRADIUS continued to fail to call python, and I wanted to make sure that even after we fix the timeout issue that there isn't another problem that could be triggered. Are you suggesting the only possible explanation for what we saw was that all of the worker threads were still waiting for a response from dynamo 2 days later, and that there is no point in debugging why FreeRADIUS was unable to execute rlm_python?
That is what Arran said.
FreeRADIUS calls Python, which calls your software. If your software doesn't return execution to FreeRADIUS for 2 days, it's the fault of *your software*. Go fix it.
They're blocked with an infinite timeout. What could cause them to unblock? Probably nothing. Fix the blindingly obvious issue first, before going hunting for other issues you're not sure exist.
I suppose that's possible but it seems unlikely that that many sockets were hung open for that long. Is there any way to see what the worker threads were doing?
Do python / C debuggers exist? If so, use them. Use "strace". These are all tools which are available to you as an administrator. There is nothing FreeRADIUS-specific about debugging a program.
I think in this case it'd be more python debugger. Given the weird way Python deals with I/O strace probably won't show a blocking system call, but it may allow examination of the sequence of calls. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Thank you, this response is very helpful. The goal was to see if anybody knew of any other obvious problems or a way to test similar situations with the freeradius+python combo that might have been triggered by the lack of a (python) timeout that we could prevent with some work today rather than finding it in production down the road. With the timeout fixed we'll do some stress testing with long sleeps in python to make sure radius recovers when python finally responds. Thanks! On Tue, Sep 22, 2015 at 11:26 AM, Arran Cudbard-Bell < a.cudbardb@freeradius.org> wrote:
On 22 Sep 2015, at 01:46, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 21, 2015, at 7:06 PM, Andrew Parisio <parisioa@gmail.com> wrote:
Like I said in my original email we are aware of the problems caused by the lack of a timeout and are actively working to fix that, so you don't need to be condescending and rude about the lack of a timeout.
His message was neither condescending nor rude. It simply points out that you're blaming FreeRADIUS, when the real blame lies elsewhere. I suggest learning how to take feedback without getting offended.
Right, I was pointing out the issue with the mental model OP constructed to explain what was occurring.
I then explained the technical limitation that prevents FreeRADIUS from intervening, control is never returned to rlm_python during blocking calls.
For that you'd need a python/C coroutine implementation, which probably doesn't exist, or a python interpreter on the end of a socket, which would allow you to implement an asynchronous interface. Even there, there'd still be issues with blocking, but at least it'd allow FreeRADIUS to control the timeout.
My question was that even after dynamo recovered FreeRADIUS continued to fail to call python, and I wanted to make sure that even after we fix the timeout issue that there isn't another problem that could be triggered. Are you suggesting the only possible explanation for what we saw was that all of the worker threads were still waiting for a response from dynamo 2 days later, and that there is no point in debugging why FreeRADIUS was unable to execute rlm_python?
That is what Arran said.
FreeRADIUS calls Python, which calls your software. If your software doesn't return execution to FreeRADIUS for 2 days, it's the fault of *your software*. Go fix it.
They're blocked with an infinite timeout. What could cause them to unblock? Probably nothing. Fix the blindingly obvious issue first, before going hunting for other issues you're not sure exist.
I suppose that's possible but it seems unlikely that that many sockets were hung open for that long. Is there any way to see what the worker threads were doing?
Do python / C debuggers exist? If so, use them. Use "strace". These are all tools which are available to you as an administrator. There is nothing FreeRADIUS-specific about debugging a program.
I think in this case it'd be more python debugger. Given the weird way Python deals with I/O strace probably won't show a blocking system call, but it may allow examination of the sequence of calls.
-Arran
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Andrew Parisio wrote:
Like I said in my original email we are aware of the problems caused by the lack of a timeout and are actively working to fix that, [..] My question was that even after dynamo recovered FreeRADIUS continued to fail to call python, and I wanted to make sure that even after we fix the timeout issue that there isn't another problem that could be triggered.
Disclaimer: I don't know the FreeRADIUS internals and never used rlm_python. But first I'd solve the timeout issue and then re-test. Before that your analysis will always be unassured.
Are you suggesting the only possible explanation for what we saw was that all of the worker threads were still waiting for a response from dynamo 2 days later, and that there is no point in debugging why FreeRADIUS was unable to execute rlm_python? I suppose that's possible but it seems unlikely that that many sockets were hung open for that long. Is there any way to see what the worker threads were doing?
Also I'm not sure whether directly embedding Python/Perl/whatever interpreters in a server process is a good approach. For various reasons I usually prefer to implement a separate server process (e.g. in Python) listening on a Unix domain socket. This gives you more control and you can better isolate blocking problems in your own external listener. Not sure whether current FreeRADIUS has such an interface though. Ciao, Michael.
participants (4)
-
Alan DeKok -
Andrew Parisio -
Arran Cudbard-Bell -
Michael Ströder