Linelog - timestamps

[Pshem Kowalczyk]

Hi,


On Fri, 24 Jun 2016 at 01:38 Alan DeKok <aland at deployingradius.com> wrote:

> On Jun 22, 2016, at 9:13 PM, Pshem Kowalczyk <pshem.k at 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