> > Tried auth'ing from a users file, bypassing SQL, no dice. I'm
> > compiling a uni-processor kernel now to see if it's something with
> > SMP.
>
> Just to be clear, the problem is:
>
> - high CPU load
Upon startup, the process is fine. High CPU load after radiusd
processes the first request:
**radiusd is loaded with -xx (in this case). Server is up, and
responding:
Thread spawned new child 1. Total threads in pool: 1
Listening on IP address *, ports 1645/udp and 1646/udp.
Ready to process requests.
**It's waiting for it's first request:
Thread 1 waiting to be assigned a request
**It recieves and processes it's first request:
rad_recv: Access-Request packet from host 127.0.0.1:32769, id=95,
length=53
Thread 1 assigned request 0
--- Walking the entire request list ---
Thread 1 handling request 0, (1 handled so far)
User-Name = "test"
Password = "@\026LQ{\351.8um\277\277\303\016J"
NAS-IP-Address = 255.255.255.255
NAS-Port-Id = "0"
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "suffix" returns ok
users: Matched test at 44
modcall[authorize]: module "files" returns ok
modcall: group authorize returns ok
rad_check_password: Found Auth-Type Local
auth: type Local
auth: user supplied Password matches local Password
Login OK: [test/testing] (from nas local port 0)
Sending Access-Accept of id 95 to 127.0.0.1:32769
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.16.3.33
Framed-IP-Netmask = 255.255.255.0
Framed-Routing = Broadcast-Listen
Framed-Filter-Id = "std.ppp"
Framed-MTU = 1500
Framed-Compression = Van-Jacobson-TCP-IP
Finished request 0
**Request finished. Now, same thread waiting for next request:
Going to the next request
Thread 1 waiting to be assigned a request
**Check `top`, radiusd process is @99% CPU.
> - it happens in threaded mode and when running '-s'
No, in -s it's fine:
** First request:
rad_recv: Access-Request packet from host 127.0.0.1:32769, id=178,
length=53
User-Name = "test"
Password = "gx^?\364G{o-\361(5\214\337$*"
NAS-IP-Address = 255.255.255.255
NAS-Port-Id = "0"
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "suffix" returns ok
users: Matched test at 44
modcall[authorize]: module "files" returns ok
modcall: group authorize returns ok
rad_check_password: Found Auth-Type Local
auth: type Local
auth: user supplied Password matches local Password
Login OK: [test/testing] (from nas local port 0)
Sending Access-Accept of id 178 to 127.0.0.1:32769
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.16.3.33
Framed-IP-Netmask = 255.255.255.0
Framed-Routing = Broadcast-Listen
Framed-Filter-Id = "std.ppp"
Framed-MTU = 1500
Framed-Compression = Van-Jacobson-TCP-IP
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 178 with timestamp 3bd88333
Nothing to do. Sleeping until we see a request.
**Second request.
rad_recv: Access-Request packet from host 127.0.0.1:32769, id=182,
length=53
User-Name = "test"
Password = "b8\2175`Z\034\033\342\266\356Lz\n\r`"
NAS-IP-Address = 255.255.255.255
NAS-Port-Id = "0"
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "suffix" returns ok
users: Matched test at 44
modcall[authorize]: module "files" returns ok
modcall: group authorize returns ok
rad_check_password: Found Auth-Type Local
auth: type Local
auth: user supplied Password matches local Password
Login OK: [test/testing] (from nas local port 0)
Sending Access-Accept of id 182 to 127.0.0.1:32769
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.16.3.33
Framed-IP-Netmask = 255.255.255.0
Framed-Routing = Broadcast-Listen
Framed-Filter-Id = "std.ppp"
Framed-MTU = 1500
Framed-Compression = Van-Jacobson-TCP-IP
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 182 with timestamp 3bd88349
Nothing to do. Sleeping until we see a request.
**No problems. I can process requests all day, here.
> - it happens in SMP or in uni-processor mode
Correct. It happens with an SMP kernel AND a uni-processor kernel.
> Can you strip down your configuration to load and use the
> smallest number of modules possible? i.e. If you can verify
> that it happens with just rlm_files installed, that would
> help to track down where the problem is located.
Well, the output from the segments above is from a flat users file. The
sql module was commented out previously to see if it was the problem. I
will stat commenting out modules until it just doesn't work anymore :)
> But the trace you showed was weird:
>
> > > > time(NULL) = 1004022581
> > > > Password = "#testuser11"
> > > > Framed-Compression = Van-Jacobson-TCP-IP
> > > > Framed-Compression = Van-Jacobson-TCP-IP
> > > > Framed-Protocol = PPP
> > > > Framed-Compression = Van-Jacobson-TCP-IP
> > > > Framed-Protocol = PPP
> > > > Service-Type = Framed-User
> > > > Framed-Compression = Van-Jacobson-TCP-IP
> > > > Framed-Protocol = PPP
> > > > Service-Type = Framed-User
> > > > Auth-Type = Local
> > > > Framed-Compression = Van-Jacobson-TCP-IP
> > > > Framed-Protocol = PPP
> > > > Service-Type = Framed-User
> > > > Auth-Type = Local
> > > > Framed-MTU = 1500
>
> You have *multiple* identical attributes added to the
> request. That says there may even be a problem with a list
> being circularly linked.
Yes, however it didn't work in users file mode either (as can be seen
above) and in that output, there were no duplicate entries. I'm not
sure why those duplicates come about. I will post about those later
on. First things first! :)
> > > > radiusd: Starting - reading configuration files ...
>
> And this should be printed out before it handles a request,
> not after.
I think this was a typo, not sure. Either that or I sighup'd the
daemons, don't remember. Albeit, it still doesn't work :)
> > > > ***** DEAD. CPU HITS 100% *****
>
> Can you see which function is using all of the CPU time?
How do I do that? ps? top? The process is radiusd, not sure how to
check function.
> About all I can do in these situations is to add lots of :
>
> fprintf(stderr, "HERE %s:%d\n", __FILE__, __LINE__);
>
> sprinkle these throughout the code, recompile, and do:
>
> (radiusd -Xd /etc/raddb 2>&1) | tee output
>
> send it one request at a time until it hits 100% CPU, you
> should probably see lots of repeating lines. Hit CTRL-C, and
> look at the output file. You should be able to see where
> it's looping, or at least that it got to a certain file/line,
> and looped after that.
Ok, I'll try that.
> Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
