Hi. I have a Freeradius server with MySQL backend, which has worked great so far. Right now we're increasing the users accounting here, and we're facing some login issues. Freeradius is used as an accounting service for Chillispot. I tried increasing num_sql_socks to 14, and raised thread_concurrency to 8 in my.cnf, but yet on the client I get radius errors. Could it be related to database performance? Server load is normally below 0.10, cpu mostly unused. In radius.log I see no errors. But on the client: radius.c: 235: No such id in radius queue: 76! radius.c: 1473: Matching request was not found in queue: 76! chilli.c: 3696: radius_ind() failed! which can mean slow response times from the server. Sadly I have no way to increase radius request timeout on the client. I believe it's not an issue with connection because I'm seeing this problem also on clients which always ran fine before the user increase. How can I check FreeRadius is not suffering too many requests? thanks -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
On Mon, Sep 19, 2011 at 7:33 PM, Lorenzo Milesi <lorenzo.milesi@yetopen.it> wrote:
Hi. I have a Freeradius server with MySQL backend, which has worked great so far. Right now we're increasing the users accounting here, and we're facing some login issues. Freeradius is used as an accounting service for Chillispot.
I tried increasing num_sql_socks to 14, and raised thread_concurrency to 8 in my.cnf, but yet on the client I get radius errors.
Could it be related to database performance? Server load is normally below 0.10, cpu mostly unused.
is the db on the same server as freeradius?
In radius.log I see no errors. But on the client: radius.c: 235: No such id in radius queue: 76! radius.c: 1473: Matching request was not found in queue: 76! chilli.c: 3696: radius_ind() failed!
which can mean slow response times from the server. Sadly I have no way to increase radius request timeout on the client. I believe it's not an issue with connection because I'm seeing this problem also on clients which always ran fine before the user increase.
How can I check FreeRadius is not suffering too many requests?
there should be something on FR log file. If not, then run the server in debug mode and see which part is slow or spitting out errors. -- Fajar
is the db on the same server as freeradius?
yes
there should be something on FR log file. If not, then run the server in debug mode and see which part is slow or spitting out errors.
will try to look for something -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
there should be something on FR log file. If not, then run the server in debug mode and see which part is slow or spitting out errors.
I ran in debug, and saw something which maybe could be wrong: User-Name = "MYUSERNAME" User-Password = "\002\234\350v[z\035Y\237\257\354\245\326\213\305." Usually I can see the passwords. Could be some encoding problem on the client side? What looks strange to me is that some pw are fine, some are screwed this way. thanks! -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
Lorenzo Milesi wrote:
there should be something on FR log file. If not, then run the server in debug mode and see which part is slow or spitting out errors.
I ran in debug, and saw something which maybe could be wrong:
User-Name = "MYUSERNAME" User-Password = "\002\234\350v[z\035Y\237\257\354\245\326\213\305."
And the REST of the debug output will say DOUBLE CHECK THE SHARED SECRET. If you're not going to read the debug output, there's no reason to run the server in debugging mode.
Usually I can see the passwords. Could be some encoding problem on the client side? What looks strange to me is that some pw are fine, some are screwed this way.
Odds are client X has the correct shared secret, and client Y does not. So... the passwords are broken for some clients, and not for others. Alan DeKok.
On Tue, Sep 20, 2011 at 8:23 PM, Lorenzo Milesi <lorenzo.milesi@yetopen.it> wrote:
there should be something on FR log file. If not, then run the server in debug mode and see which part is slow or spitting out errors.
There are several reasons why I suggest you run the server in debug mode (as also suggested many times on this list, and also on the wiki). For one, it can show you which part is slow (is it really the db, or is it something else). Another one is it can show relevant parts of the config which can help others pinpoint the problem. Pasting only PART of the debug log will only get you (at best) partial guesses.
I ran in debug, and saw something which maybe could be wrong:
User-Name = "MYUSERNAME" User-Password = "\002\234\350v[z\035Y\237\257\354\245\326\213\305."
Usually I can see the passwords. Could be some encoding problem on the client side?
Maybe. The debug log will also say something like "warning, unreadable password, check shared secret" (or something like that). Did you find it? Did you simply ignore it, or do what it suggested?
What looks strange to me is that some pw are fine, some are screwed this way.
Some things to check: - did the different case (readable vs unreadable password) comes from the same NAS? (If you don't know what NAS is, see http://en.wikipedia.org/wiki/Network_access_server) - is the shared secret correct? - does the login issue happens for ALL users or only for SOME servers? Basically if it's specific user/NAS problem, then you need to focus on those particular users. Again, debug log will usually help you find out. -- Fajar
For one, it can show you which part is slow (is it really the db, or is it something else). Another one is it can show relevant parts of the config which can help others pinpoint the problem. Pasting only PART of the debug log will only get you (at best) partial guesses.
Ok, I missed this, I thought was a suggestion to me :-) http://paste.ubuntu.com/693812/ this is the startup log, with the first authentication requests. as you can see from the same nas (.67) the first request is with the wrong pw, while the second is fine and Access-Accept is sent back. I obfuscated pw and ips, let me know if there is anything useful you can see. Another weird thing I noticed is that as you can see at line 155 in the middle of an Access-Accept report there's another rad_recv, like it's mixing up output. I don't know if this is a problem, or if it was doing it already, but still looks strange. Now I'm running -XX, I will post later something from that.
Maybe. The debug log will also say something like "warning, unreadable password, check shared secret" (or something like that). Did you find it? Did you simply ignore it, or do what it suggested?
I grepped for "warn" and "err" and found nothing in the debug log. Just a warning for a proxied request, but nothing else.
Some things to check: - did the different case (readable vs unreadable password) comes from the same NAS?
Yes. Let's say most of the problems come from a newly deployed nas.
- is the shared secret correct?
Yes. This puzzles me, some (half?) of the auth end successfully, others won't, and I cannot figure out where it is failing. Indeed I get the "check secret" message you suggested, but as said some users go through, some others don't... :/
- does the login issue happens for ALL users or only for SOME servers?
As said above most of the problems come from a single nas, which is the busiest. Occasionally other nases raise the issue, but much less often.
Basically if it's specific user/NAS problem, then you need to focus on those particular users. Again, debug log will usually help you find
I raised even more the number of SQL threads and seems I see less radius errors on the client. Now I try to compare the failed reqs with the log, will report back. Thank you very much! cheers -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
On Tue, Sep 20, 2011 at 10:22 PM, Lorenzo Milesi <lorenzo.milesi@yetopen.it> wrote:
For one, it can show you which part is slow (is it really the db, or is it something else). Another one is it can show relevant parts of the config which can help others pinpoint the problem. Pasting only PART of the debug log will only get you (at best) partial guesses.
Ok, I missed this, I thought was a suggestion to me :-) http://paste.ubuntu.com/693812/
What did you use for debug, and what FR version is this? Again, as mentioned in wiki.freeradius.org: "Always use radiusd -X when debugging!" Your output does not look llike it comes from FR2's debug log.
this is the startup log, with the first authentication requests. as you can see from the same nas (.67) the first request is with the wrong pw, while the second is fine and Access-Accept is sent back. I obfuscated pw and ips, let me know if there is anything useful you can see.
Another weird thing I noticed is that as you can see at line 155 in the middle of an Access-Accept report there's another rad_recv, like it's mixing up output. I don't know if this is a problem, or if it was doing it already, but still looks strange.
Now I'm running -XX, I will post later something from that.
Maybe. The debug log will also say something like "warning, unreadable password, check shared secret" (or something like that). Did you find it? Did you simply ignore it, or do what it suggested?
I grepped for "warn" and "err" and found nothing in the debug log. Just a warning for a proxied request, but nothing else.
Some things to check: - did the different case (readable vs unreadable password) comes from the same NAS?
Yes. Let's say most of the problems come from a newly deployed nas.
Then start from there. If the db is slow and FR is late to respond, the NAS will usually resend the request and FR will complain when receiving duplicate request. Your log shows no such event, so my guess is it's not slow or db issue. One simple test is try using the same user/password to logon from a "new", problematic NAS and from a "working" NAS. Compare debug output from both, and compare both NAS config. It should help you find out what's wrong.
I raised even more the number of SQL threads and seems I see less radius errors on the client.
If FR doesn't complain about duplicate request or "no free DB handle" (or something like that), then it shouldn't make a difference. -- Fajar
Your output does not look llike it comes from FR2's debug log.
This first debug log was a -x. And yes, it's FR 1.1.7! (yes, could have said that before)
Let's say most of the problems come from a newly deployed nas.
Then start from there.
If the db is slow and FR is late to respond, the NAS will usually resend the request and FR will complain when receiving duplicate request. Your log shows no such event, so my guess is it's not slow or db issue.
What makes this nas different from the hundreds I've deployed previously is the traffic load, which is sensibly higher. But if you say so I'm confident in believing that maybe as I wrote in the previous mail FR is not actually my main problem, instead I should start investigate this password generation problem done by the php script...
One simple test is try using the same user/password to logon from a "new", problematic NAS and from a "working" NAS. Compare debug output from both, and compare both NAS config. It should help you find out what's wrong.
We had tests like these performed already. Will try again... Thanks for the suggestions, will report back ASAP! -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
Lorenzo Milesi wrote:
Ok, I missed this, I thought was a suggestion to me :-) http://paste.ubuntu.com/693812/
Ugh. Upgrade to 2.1.x.
Another weird thing I noticed is that as you can see at line 155 in the middle of an Access-Accept report there's another rad_recv, like it's mixing up output. I don't know if this is a problem, or if it was doing it already, but still looks strange.
It's an old version. Upgrade. Alan DeKok.
On 2011/09/20 05:22 PM, Lorenzo Milesi wrote:
Ok, I missed this, I thought was a suggestion to me :-) http://paste.ubuntu.com/693812/
What is: "Can't connect to SNMP agent with SMUX: Connection refused" Is an SNMP connetion of some sorts not maybe slowing it down while authenticating? -- Johan Meiring Cape PC Services CC Tel: (021) 883-8271 Fax: (021) 886-7782 -------------------- Before acting on this email or opening any attachments you should read Cape PC Service's email disclaimer at: http://www.pcservices.co.za/disclaimer.html
Lorenzo Milesi wrote:
Hi. I have a Freeradius server with MySQL backend, which has worked great so far. Right now we're increasing the users accounting here, and we're facing some login issues. Freeradius is used as an accounting service for Chillispot.
I tried increasing num_sql_socks to 14, and raised thread_concurrency to 8 in my.cnf, but yet on the client I get radius errors.
Could it be related to database performance?
Yes. Fix the database.
Server load is normally below 0.10, cpu mostly unused. In radius.log I see no errors. But on the client: radius.c: 235: No such id in radius queue: 76! radius.c: 1473: Matching request was not found in queue: 76! chilli.c: 3696: radius_ind() failed!
which can mean slow response times from the server. Sadly I have no way to increase radius request timeout on the client.
Don't. Fix the database so that it isn't too slow.
I believe it's not an issue with connection because I'm seeing this problem also on clients which always ran fine before the user increase.
How can I check FreeRadius is not suffering too many requests?
See the logs. If the DB is slow, the logs will usually say.
Don't. Fix the database so that it isn't too slow. See the logs. If the DB is slow, the logs will usually say.
I have no slow queries on mysql-slow.log. thanks -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
Lorenzo Milesi wrote:
Don't. Fix the database so that it isn't too slow. See the logs. If the DB is slow, the logs will usually say.
I have no slow queries on mysql-slow.log.
Then it must be magic. Hire a wizard to fix the problem. Something *you did* broke the server. Either say what you did, or good luck solving it yourself. i.e. See the FAQ for useless comments like "it doesn't work", which is what your messages amount to. Alan DeKok.
Then it must be magic. Hire a wizard to fix the problem.
Thanks, your sarcasm is really helpful!
Something *you did* broke the server. Either say what you did, or good luck solving it yourself.
i.e. See the FAQ for useless comments like "it doesn't work", which is what your messages amount to.
I *DID* say what I did: increased the amount of accounted users, nothing else. I said what changes I did to the server in order to improve mysql performance. This doesn't look to me like saying "it doesn't work". And on the other hand, if I haven't been detailed enough you could have asked more specific questions, and I would have answered. Instead of wasting time trolling at me. I haven't been trolling, I didn't say "this software sucks", I just asked for help for a specific problem. So either help and it'll be appreciated, or I'd suggest you to save your time and read other mails. thanks -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
Lorenzo Milesi wrote:
Then it must be magic. Hire a wizard to fix the problem.
Thanks, your sarcasm is really helpful!
It seems to work better than honest suggestions. You've ignored those.
I *DID* say what I did: increased the amount of accounted users, nothing else.
The *default configuration* doesn't have the problem you described. So... what did you change? "adding users" is *not* the answer I'm looking for.
I said what changes I did to the server in order to improve mysql performance.
You edited radiusd.conf to improve MySQL performance? That's magic.
This doesn't look to me like saying "it doesn't work".
It looks to me like that, which is why I said it.
And on the other hand, if I haven't been detailed enough you could have asked more specific questions, and I would have answered. Instead of wasting time trolling at me. I haven't been trolling, I didn't say "this software sucks", I just asked for help for a specific problem. So either help and it'll be appreciated, or I'd suggest you to save your time and read other mails.
I asked specific questions. You evaded answering. Again, the default configuration doesn't have this problem. *You* changed the configuration. What was it? Saying "I added more users" is a ridiculous response, and deserves a ridiculous answer. If the server is taking 1s to respond, *something* is blocking it. That something is almost always an external script, or the DB. Saying "the DB log doesn't show slow queries" is a lazy answer. It means you didn't bother checking for yourself whether or not the DB was slow. The *RADIUS* server likely thinks the DB is slow. I don't care what kind of lies the DB log tells you. Go check for yourself. If you're not going to *think* in order to track down the problem, you have no hope of fixing the problem. Alan DeKok.
The *default configuration* doesn't have the problem you described. So... what did you change? "adding users" is *not* the answer I'm looking for.
This radius has been successfully running for 4y now. Problems raised since when we increased the number of users.
You edited radiusd.conf to improve MySQL performance? That's magic.
I never said that. I never mentioned the config file but the config option, so I must have edited in the RIGHT place, that is for your check in /etc/freeradius/sql.conf, which is included into radiusd.conf by $INCLUDE ${confdir}/sql.conf. Happy now?
I asked specific questions. You evaded answering.
I didn't mean to be evasive! To me slow means mysql-slow. I must be (am) wrong about this, but I didn't know what's the acknowledged value of "slow" in radius. Again I can be not enough informed, again a more polite and less evasive answer (fix the db.... can mean a thousands of actions!) would have helped.
If the server is taking 1s to respond, *something* is blocking it. That something is almost always an external script, or the DB. Saying "the DB log doesn't show slow queries" is a lazy answer. It means you didn't bother checking for yourself whether or not the DB was slow.
Again I didn't mean to be lazy, I just had the wrong parameter of "slow".
And the REST of the debug output will say
DOUBLE CHECK THE SHARED SECRET.
If you're not going to read the debug output, there's no reason to run the server in debugging mode.
I did that, and it is correct, in fact half of the login request are successfuly replied! I can't figure out why only /some/ are failing!
Odds are client X has the correct shared secret, and client Y does not. So... the passwords are broken for some clients, and not for others.
The clients use the same authentication web page, which is a php script that encodes the password against the secret. And it's the very same page for everyone on that nas. So, by the way, seems like there are two problems: the wrong passwords, and the failing radius requests. I've checked in the debug output and seems that most of the failed request are Interim-Update, so it may even be that the database is not actually my *main* problem right now. I will check request speed, thanks. ciao -- Lorenzo Milesi - lorenzo.milesi@yetopen.it YetOpen S.r.l. - http://www.yetopen.it/ Via Carlo Torri Tarelli 19 - 23900 Lecco - ITALY - Tel 0341 220 205 - Fax 178 6070 222 GPG/PGP Key-Id: 0xE704E230 - http://keyserver.linux.it -------- D.Lgs. 196/2003 -------- Si avverte che tutte le informazioni contenute in questo messaggio sono riservate ed a uso esclusivo del destinatario. Nel caso in cui questo messaggio Le fosse pervenuto per errore, La invitiamo ad eliminarlo senza copiarlo, a non inoltrarlo a terzi e ad avvertirci non appena possibile. Grazie.
Lorenzo Milesi wrote:
This radius has been successfully running for 4y now. Problems raised since when we increased the number of users.
So? Since you're using the same configuration, the performance problems must be related to your configuration.
So, by the way, seems like there are two problems: the wrong passwords, and the failing radius requests.
The "wrong" passwords are because you're using 1.1.x. Upgrade.
I've checked in the debug output and seems that most of the failed request are Interim-Update, so it may even be that the database is not actually my *main* problem right now.
So... find out why the Interim-Updates are slow. They're not slow in the default configuration. Check the DB. Are the fields indexed? Likely not... Alan DeKok.
participants (4)
-
Alan DeKok -
Fajar A. Nugraha -
Johan Meiring -
Lorenzo Milesi