Hi, We've started using the linelog module to record various events that happen within the radius system. All of our linelog entries start with "%t" to denote the time of the event. During one of the troubleshooting sessions we've discovered that the entries don't necessarily end up in the order we expected them to. Finally we realised that the "%t" is the time the request hits radius and not when the linelog entry is processed. In our case (we proxy all requests) that actually matters, since the home servers can take time to respond. I had a look through the dictionaries and run-time-variables but can't find 'current timestamp', is it actually available? kind regards Pshem
On Thu, Jun 23, 2016 at 01:13:03AM +0000, Pshem Kowalczyk wrote:
time to respond. I had a look through the dictionaries and run-time-variables but can't find 'current timestamp', is it actually available?
Don't believe so, no. All the timestamp xlats refer to request->timestamp. Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
On Jun 22, 2016, at 9:13 PM, Pshem Kowalczyk <pshem.k@gmail.com> wrote:
We've started using the linelog module to record various events that happen within the radius system. All of our linelog entries start with "%t" to denote the time of the event. During one of the troubleshooting sessions we've discovered that the entries don't necessarily end up in the order we expected them to.
The entries are written sequentially, so they are in time order.
Finally we realised that the "%t" is the time the request hits radius and not when the linelog entry is processed. In our case (we proxy all requests) that actually matters, since the home servers can take time to respond. I had a look through the dictionaries and run-time-variables but can't find 'current timestamp', is it actually available?
For various reasons.. no. If your proxies take more than a second to respond, there's something seriously broken with them. That should be fixed rather than poking FreeRADIUS to have more up to date timestamps. Why do you need wall-clock timestamps? Alan DeKok.
On 23 Jun 2016, at 09:36, Alan DeKok <aland@deployingradius.com> wrote:
On Jun 22, 2016, at 9:13 PM, Pshem Kowalczyk <pshem.k@gmail.com> wrote:
We've started using the linelog module to record various events that happen within the radius system. All of our linelog entries start with "%t" to denote the time of the event. During one of the troubleshooting sessions we've discovered that the entries don't necessarily end up in the order we expected them to.
The entries are written sequentially, so they are in time order.
Finally we realised that the "%t" is the time the request hits radius and not when the linelog entry is processed. In our case (we proxy all requests) that actually matters, since the home servers can take time to respond. I had a look through the dictionaries and run-time-variables but can't find 'current timestamp', is it actually available?
For various reasons.. no.
If your proxies take more than a second to respond, there's something seriously broken with them. That should be fixed rather than poking FreeRADIUS to have more up to date timestamps.
There's no cost to us though as we get packet timestamps from the kernel as part of recvmsg. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Hi, On Fri, 24 Jun 2016 at 01:38 Alan DeKok <aland@deployingradius.com> wrote:
On Jun 22, 2016, at 9:13 PM, Pshem Kowalczyk <pshem.k@gmail.com> wrote:
We've started using the linelog module to record various events that happen within the radius system. All of our linelog entries start with "%t" to denote the time of the event. During one of the troubleshooting sessions we've discovered that the entries don't necessarily end up in the order we expected them to.
The entries are written sequentially, so they are in time order.
That's correct, but we end up with something like this Fri Jun 24 05:17:11 2016 Username [ABC] BNG: 03 Accept Fri Jun 24 05:17:12 2016 Username [DEF] BNG: 02 Accept Fri Jun 24 05:17:10 2016 Username [GHI] BNG: 03 Accept So in this case packet for GHI was actually received first but responded to last.
Finally we realised that the "%t" is the time the request
hits radius and not when the linelog entry is processed. In our case (we proxy all requests) that actually matters, since the home servers can take time to respond. I had a look through the dictionaries and run-time-variables but can't find 'current timestamp', is it actually available?
For various reasons.. no.
If your proxies take more than a second to respond, there's something seriously broken with them. That should be fixed rather than poking FreeRADIUS to have more up to date timestamps.
Why do you need wall-clock timestamps?
So I can pump these logs into a system that analyses them and tells me
about performance of various aspects of the system. Since the processing in our case involves database lookups, proxying, REST calls, more database lookups I want to know where the bottlenecks are. If I could call linelog at various stages of processing and then compare timestamps I could see exactly where things are slowing down (and when). I realise that having proxies that take more than 1 sec is no ideal, but some things are outside of our control, also having those timestamps would make it easier to prove that there is actually an issue with the proxy (or REST calls or databases). kind regards Pshem
Hi,
That's correct, but we end up with something like this
Fri Jun 24 05:17:11 2016 Username [ABC] BNG: 03 Accept Fri Jun 24 05:17:12 2016 Username [DEF] BNG: 02 Accept Fri Jun 24 05:17:10 2016 Username [GHI] BNG: 03 Accept
So in this case packet for GHI was actually received first but responded to last.
you know...you can linelog elsewhere - so have a 'receive' linelog... then have a auth linelog.... if you linelog with eg syslog then syslog will timestamp the event at the current system time when it got logged - you can then look at that versus the packet receive time to see where the delay lag is - in your case you could then log the 'auth' time (syslog) versus the receive time (linelog entry you already have) but...you talk about databases....then just put the auth stuff into a DB(!) - you can have one column being insert time (NOW() or whatever your DB uses) versus receive time of the datagram by RADIUS server.... then you can do lots of basic analysis on culmns where insert_time - receive_time > X seconds if you have questions about your servers surrounding the system then run freeradius in fuller debug mode - eg radiusd -xxx and such - this gives you the time of each packet - you can then see how long each thing - LDAP, SQL, logging, perl , exec etc etc took before the packet continued. you can then profile it (theres no simple profiling tool to work with such logs that I know of....but would be very handy!! ;-) ) ilan
Hi I think I'll have another look at syslog, might be the quickest way of achieving the outcome. I don't want to push all that data into the database since the tool we use for analysis (SumoLogic) only takes text as input, so it's easier to store it that way as well. Running in debug mode is what we do now, but that produces a lot of information that we don't need for performance analysis. I can be analyse manually, but not really automated. kind regards Pshem On Fri, 24 Jun 2016 at 07:19 <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
That's correct, but we end up with something like this
Fri Jun 24 05:17:11 2016 Username [ABC] BNG: 03 Accept Fri Jun 24 05:17:12 2016 Username [DEF] BNG: 02 Accept Fri Jun 24 05:17:10 2016 Username [GHI] BNG: 03 Accept
So in this case packet for GHI was actually received first but responded to last.
you know...you can linelog elsewhere - so have a 'receive' linelog... then have a auth linelog.... if you linelog with eg syslog then syslog will timestamp the event at the current system time when it got logged - you can then look at that versus the packet receive time to see where the delay lag is - in your case you could then log the 'auth' time (syslog) versus the receive time (linelog entry you already have)
but...you talk about databases....then just put the auth stuff into a DB(!) - you can have one column being insert time (NOW() or whatever your DB uses) versus receive time of the datagram by RADIUS server.... then you can do lots of basic analysis on culmns where insert_time - receive_time > X seconds
if you have questions about your servers surrounding the system then run freeradius in fuller debug mode - eg radiusd -xxx and such - this gives you the time of each packet - you can then see how long each thing - LDAP, SQL, logging, perl , exec etc etc took before the packet continued. you can then profile it (theres no simple profiling tool to work with such logs that I know of....but would be very handy!! ;-) )
ilan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (5)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Arran Cudbard-Bell -
Matthew Newton -
Pshem Kowalczyk