home server debugging issues
Hi, I upgraded one of our proxy servers from 2.0.4 to 2.1.7, and noticed that the proxying changed in a way that "status_check = request" logic started being critical, so this kind of stuff: Sun Nov 22 09:25:56 2009 : Error: Rejecting request 70011 due to lack of any response from home server X port 1812 ...was replaced, without a change in home server configuration, with: Tue Nov 24 06:32:01 2009 : Error: PROXY: Marking home server X port 1812 as zombie (it looks like it is dead). Tue Nov 24 06:32:03 2009 : Info: PROXY: Marking home server X port 1812 as dead. Tue Nov 24 06:32:03 2009 : Error: PROXY: Marking home server Y port 1812 as zombie (it looks like it is dead). Once this happened, I went to investigate, only to find out that our test username requests were no longer summarily rejected by those two home servers - instead they were discarded. So the marking those servers alive would never happen, and this was the obvious root of the proxying problem. It was unclear to me why didn't FreeRADIUS notice this as soon as it first happened, and when it eventually happened, why didn't it explicate the rationale. So I looked and found these in src/main/event.c: RDEBUG2("No response to status check %d from home server %s port %d", RDEBUG2("Proxying request %d to home server %s port %d", RDEBUG2("ERROR: Failed to find live home server for realm %s", RDEBUG2("Failed to find live home server for request %d", request->number); It doesn't make sense for both error and debug messages to be displayed on the same debug level. The error messages need to have priority, so that the admin actually has a chance to see them. In this particular situation, when I move from debug level 0 to 2 in order to oversee these events, I get not only these messages, but gobs of rlm_sql expansions, unlang processing logs, etc. It would be better if some of those error messages were upgraded to L_ERR, or L_PROXY, while keeping the truely informational messages as L_DBG. In fact it looks like there's only a single reference to L_PROXY in the entire file. Does this make sense, can I submit patches? -- 2. That which causes joy or happiness.
Josip Rodin wrote:
I upgraded one of our proxy servers from 2.0.4 to 2.1.7, and noticed that the proxying changed in a way that "status_check = request" logic started being critical, so this kind of stuff:
Sun Nov 22 09:25:56 2009 : Error: Rejecting request 70011 due to lack of any response from home server X port 1812
...was replaced, without a change in home server configuration, with:
It wasn't replaced, it just happens less often.
It was unclear to me why didn't FreeRADIUS notice this as soon as it first happened, and when it eventually happened, why didn't it explicate the rationale. So I looked and found these in src/main/event.c:
Odds are your config handles the "no response" packets. So the above message happens less often.
RDEBUG2("No response to status check %d from home server %s port %d", RDEBUG2("Proxying request %d to home server %s port %d", RDEBUG2("ERROR: Failed to find live home server for realm %s", RDEBUG2("Failed to find live home server for request %d", request->number);
It doesn't make sense for both error and debug messages to be displayed on the same debug level. The error messages need to have priority, so that the admin actually has a chance to see them.
Some errors shouldn't be printed to the logs. i.e. "no response to request". If you're proxying 100's of packets/s and the home server dies, you are going to get a LOT of messages in the log. This isn't desirable. Instead, various state changes (home server up / down) are logged.
In this particular situation, when I move from debug level 0 to 2 in order to oversee these events, I get not only these messages, but gobs of rlm_sql expansions, unlang processing logs, etc.
It would be better if some of those error messages were upgraded to L_ERR, or L_PROXY, while keeping the truely informational messages as L_DBG. In fact it looks like there's only a single reference to L_PROXY in the entire file.
Does this make sense, can I submit patches?
I've committed a bunch of changes to the logging in src/main/event.c. More events are logged, and there's a lot more use of L_PROXY. Alan DeKok.
On Thu, Nov 26, 2009 at 06:17:29PM +0100, Alan DeKok wrote:
RDEBUG2("No response to status check %d from home server %s port %d", RDEBUG2("Proxying request %d to home server %s port %d", RDEBUG2("ERROR: Failed to find live home server for realm %s", RDEBUG2("Failed to find live home server for request %d", request->number);
It doesn't make sense for both error and debug messages to be displayed on the same debug level. The error messages need to have priority, so that the admin actually has a chance to see them.
Some errors shouldn't be printed to the logs. i.e. "no response to request". If you're proxying 100's of packets/s and the home server dies, you are going to get a LOT of messages in the log. This isn't desirable.
Instead, various state changes (home server up / down) are logged.
In this particular situation, when I move from debug level 0 to 2 in order to oversee these events, I get not only these messages, but gobs of rlm_sql expansions, unlang processing logs, etc.
It would be better if some of those error messages were upgraded to L_ERR, or L_PROXY, while keeping the truely informational messages as L_DBG. In fact it looks like there's only a single reference to L_PROXY in the entire file.
Does this make sense, can I submit patches?
I've committed a bunch of changes to the logging in src/main/event.c. More events are logged, and there's a lot more use of L_PROXY.
Thanks, those commits are exactly what I meant. -- 2. That which causes joy or happiness.
On Thu, Nov 26, 2009 at 06:17:29PM +0100, Alan DeKok wrote:
Josip Rodin wrote:
I upgraded one of our proxy servers from 2.0.4 to 2.1.7, and noticed that the proxying changed in a way that "status_check = request" logic started being critical, so this kind of stuff:
Sun Nov 22 09:25:56 2009 : Error: Rejecting request 70011 due to lack of any response from home server X port 1812
...was replaced, without a change in home server configuration, with:
It wasn't replaced, it just happens less often.
It was unclear to me why didn't FreeRADIUS notice this as soon as it first happened, and when it eventually happened, why didn't it explicate the rationale. So I looked and found these in src/main/event.c:
Odds are your config handles the "no response" packets. So the above message happens less often.
Returning to the original problem, in my pool of two fail-over home servers I now have both of them set up with "status_check = none". My upstream proxy maintainers refuse to implement decent status checks, so I'm forced to do this for now. I can do a status check with an entry from a particular HL RADIUS that I happen to control, but that just creates a daisy-chain of SPoFs. :/ They insist that I not do anything like this, but that I set up my server so that it stubbornly tries their first server, then if that fails their second server, for each request. Now, when a request comes through that gets discarded by the first proxy (because it itself times out on a random HL RADIUS), that one gets marked as a zombie. Strangely enough, my server keeps it marked as a zombie even after several minutes (long past any of the zombie_period and revive_interval periods I've kept in the configuration). My server keeps talking only with the second server which is in the 'alive' state, and ignores the zombie. After re-reading proxy.conf comments, this actually looks logical - there is no kind of a status check that would unmark it as a zombie. revive_interval can resurrect it from the 'dead' state, but not from the zombie state. Also this part of the revive_interval comment is a bit confusing: # As a result, we recommend enabling status checks, and # we do NOT recommend using "revive_interval". # # The "revive_interval" is used ONLY if the "status_check" # entry below is not "none". Otherwise, it will not be used, # and should be deleted. So it's supposed to be a crutch only for people who *have* status checks, but not a crutch for those of us who do *not* have status checks. What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :) -- 2. That which causes joy or happiness.
On Fri, Nov 27, 2009 at 10:29:54AM +0100, Josip Rodin wrote:
What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :)
Speaking of which, this seems to have stopped working, on the 'stable' branch: % sudo radmin -e 'show home_server list' 127.0.0.1 1812 auth alive 0 10.0.0.1 1812 auth zombie 1 10.0.0.2 1812 auth alive 0 % sudo radmin -e 'set home_server state 10.0.0.1 1812 alive' ERROR: No such home server % sudo radmin -e 'set home_server state 10.0.0.2 1812 alive' ERROR: No such home server -- 2. That which causes joy or happiness.
Josip Rodin wrote:
On Fri, Nov 27, 2009 at 10:29:54AM +0100, Josip Rodin wrote:
What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :)
Speaking of which, this seems to have stopped working, on the 'stable' branch:
% sudo radmin -e 'show home_server list' 127.0.0.1 1812 auth alive 0 10.0.0.1 1812 auth zombie 1 10.0.0.2 1812 auth alive 0 % sudo radmin -e 'set home_server state 10.0.0.1 1812 alive' ERROR: No such home server % sudo radmin -e 'set home_server state 10.0.0.2 1812 alive' ERROR: No such home server
Ah, yes. That's a side-effect of the TCP integration. I've committed a fix. This makes me think we should release 2.1.8 *without* the TCP work. Followed by a 2.2.0, *with* the TCP work. Alan DeKok.
On Fri, Nov 27, 2009 at 01:49:26PM +0100, Alan DeKok wrote:
What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :)
Speaking of which, this seems to have stopped working, on the 'stable' branch:
% sudo radmin -e 'show home_server list' 127.0.0.1 1812 auth alive 0 10.0.0.1 1812 auth zombie 1 10.0.0.2 1812 auth alive 0 % sudo radmin -e 'set home_server state 10.0.0.1 1812 alive' ERROR: No such home server % sudo radmin -e 'set home_server state 10.0.0.2 1812 alive' ERROR: No such home server
Ah, yes. That's a side-effect of the TCP integration. I've committed a fix.
This makes me think we should release 2.1.8 *without* the TCP work. Followed by a 2.2.0, *with* the TCP work.
That makes sense, it's an architectural change with various possible side-effects, and there is sufficient volatility already in the 2.1 branch. :) -- 2. That which causes joy or happiness.
Josip Rodin wrote:
Returning to the original problem, in my pool of two fail-over home servers I now have both of them set up with "status_check = none".
2.1.7 has some changes in proxy fail-over. The *first* packet that discovers that a home server is dead is no longer rejected. Instead, it fails over to the second home server. This makes proxying more robust.
My upstream proxy maintainers refuse to implement decent status checks, so I'm forced to do this for now. I can do a status check with an entry from a particular HL RADIUS that I happen to control, but that just creates a daisy-chain of SPoFs. :/ They insist that I not do anything like this, but that I set up my server so that it stubbornly tries their first server, then if that fails their second server, for each request.
That's stupid. It increases latency, bandwidth used, and decreases reliability. The Status-Server draft says that using Status-Server is preferable to the alternatives. Maybe they'll follow it once it becomes an RFC.
Now, when a request comes through that gets discarded by the first proxy (because it itself times out on a random HL RADIUS), that one gets marked as a zombie. Strangely enough, my server keeps it marked as a zombie even after several minutes (long past any of the zombie_period and revive_interval periods I've kept in the configuration). My server keeps talking only with the second server which is in the 'alive' state, and ignores the zombie.
Hmm... the "zombie_period" timers depend on continued packet streams. If the NAS doesn't re-transmit packets, then it could stay zombie for a while. I'll have to take a look at that.
After re-reading proxy.conf comments, this actually looks logical - there is no kind of a status check that would unmark it as a zombie. revive_interval can resurrect it from the 'dead' state, but not from the zombie state. Also this part of the revive_interval comment is a bit confusing:
# As a result, we recommend enabling status checks, and # we do NOT recommend using "revive_interval". # # The "revive_interval" is used ONLY if the "status_check" # entry below is not "none". Otherwise, it will not be used, # and should be deleted.
So it's supposed to be a crutch only for people who *have* status checks, but not a crutch for those of us who do *not* have status checks.
Huh? That's not what it says. It says "revive_interval" is ONLY for people who have "status_check = none". i.e. no status checks.
What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :)
If you don't have status-checks, then the "revive_interval" should apply. If it's not being applied, that should be fixed. Alan DeKok.
On Fri, Nov 27, 2009 at 11:30:02AM +0100, Alan DeKok wrote:
After re-reading proxy.conf comments, this actually looks logical - there is no kind of a status check that would unmark it as a zombie. revive_interval can resurrect it from the 'dead' state, but not from the zombie state. Also this part of the revive_interval comment is a bit confusing:
# As a result, we recommend enabling status checks, and # we do NOT recommend using "revive_interval". # # The "revive_interval" is used ONLY if the "status_check" # entry below is not "none". Otherwise, it will not be used, # and should be deleted.
So it's supposed to be a crutch only for people who *have* status checks, but not a crutch for those of us who do *not* have status checks.
Huh? That's not what it says. It says "revive_interval" is ONLY for people who have "status_check = none". i.e. no status checks.
But the sentence says The "revive_interval" is used ONLY if the "status_check" entry below is not "none". ~~~ Notice the underlined "not" :) Simple thinko?
What is a crutch for this situation? A cron job that keeps doing radmin -e 'set home_server state X Y alive'? :)
If you don't have status-checks, then the "revive_interval" should apply. If it's not being applied, that should be fixed.
Nope, it's not, my primary server is still a zombie. -- 2. That which causes joy or happiness.
On Fri, Nov 27, 2009 at 11:30:02AM +0100, Alan DeKok wrote:
Now, when a request comes through that gets discarded by the first proxy (because it itself times out on a random HL RADIUS), that one gets marked as a zombie. Strangely enough, my server keeps it marked as a zombie even after several minutes (long past any of the zombie_period and revive_interval periods I've kept in the configuration). My server keeps talking only with the second server which is in the 'alive' state, and ignores the zombie.
Hmm... the "zombie_period" timers depend on continued packet streams. If the NAS doesn't re-transmit packets, then it could stay zombie for a while. I'll have to take a look at that.
After re-reading proxy.conf comments, this actually looks logical - there is no kind of a status check that would unmark it as a zombie. revive_interval can resurrect it from the 'dead' state, but not from the zombie state.
After another set of events, that first server finally got marked as dead. Then, exactly as described and when specified, revive_interval kicked in and marked it alive. So I'm guessing I just need to either have revive_interval deal with zombies as well as dead servers, or another variable that would do that. -- 2. That which causes joy or happiness.
participants (2)
-
Alan DeKok -
Josip Rodin