Correlating Access-Requests and Replys
Hi all, we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.). We'd basically like to figure out the elapsed time between first Access-Request and the final Access-Accept (or Access-Reject for that matter). A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server. I searched a little and found a post by Alan DeKok from 2012 on a very similar matter. The problem is that there's nothing much you can use to correlate an Access-Request reliably to the answers by the RADIUS server. Alan suggested adding a reply item to the reply: update reply { FreeRADIUS-Correlation-Id = "%{Packet-Src-IP-Address}-%{Packet-Src-Port}... } I like the idea (you can probably even update the original request with that FreeRADIUS-Correlation-Id before logging it), however, I need some help with the "..." part of the above config snippet. Src IP and src port unfortunately aren't unique enough (the same NAS sends all requests from the same source port). I looked through dictionary.freeradius.internal to find some suitable attribute that isn't part of the original request and that would add some uniqueness but I don't see anything useful. Do you guys happen to know a suitable way of creating such a FreeRADIUS-Correlationa-Id that's unique for an Access-Request-...-Access-Accept exchange? I'm not sure whether the NAS will also include the attribute in all its later request packets. Do you happen to know if this is the case? The approach with a correlation ID has one more disadvantage: according to RFC 2865, Access-Reject messages mustn't include such attributes. So this leaves us with the problem how to correlate rejects. This leads me to this question: FreeRADIUS obviously keeps track internally which reply correlates to which request. Is there any way to include some hint to this correlation via a FreeRADIUS-internal attribute which in turn could be logged in auth-detail or reply-detail files? Any help would be highly appreciated. Kind regards, Christian Strauf -- Dipl.-Math. Christian Strauf Clausthal University of Techn. E-Mail: strauf@rz.tu-clausthal.de Rechenzentrum Web: www.rz.tu-clausthal.de Erzstraße 51 Tel.: +49-5323-72-2086 Fax: -992086 D-38678 Clausthal-Zellerfeld
On Thu, Apr 21, 2016 at 01:02:06PM +0000, Christian Strauf wrote:
we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.).
Nice. I assume you've seen https://github.com/FreeRADIUS/freeradius-server/tree/v3.1.x/doc/schemas/logs... which might be useful.
A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server.
The State attribute should tie any challenges with the subsequent request, which might be helpful.
Do you guys happen to know a suitable way of creating such a FreeRADIUS-Correlationa-Id that's unique for an Access-Request-...-Access-Accept exchange? I'm not sure whether the NAS will also include the attribute in all its later request packets. Do you happen to know if this is the case?
Include the Calling-Station-Id and User-Name as well? Then perhaps hash them to get a (most likely unique) hex string. (See e.g. acct_unique policy.) I would have thought you could generate a new Correlation attribute on first request, log it with the request, and then cache it with rlm_cache. Then pull it out each time you are about to log a request or reply and put it on the log. Then you should have a stable ID across all entries in your elasticsearch db.
The approach with a correlation ID has one more disadvantage: according to RFC 2865, Access-Reject messages mustn't include such attributes. So this leaves us with the problem how to correlate rejects.
You might be better to keep track of the request time in FreeRADIUS and then just log it with each log entry. rlm_cache probably needed as well - but examples of arithmetic are in sites-enabled/default preacct (FreeRADIUS-Acct-Session-Start-Time). Doing both timing in FR as well as a Correlation attribute is probably the best option. Matthew -- Matthew Newton, Ph.D. <mcn4@le.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>
I assume you've seen https://github.com/FreeRADIUS/freeradius-server/tree/v3.1.x/doc/schemas/logs... which might be useful. Very interesting! If you'd like to, please drop me an email, I'd be happy exchange experiences / thoughts.
The State attribute should tie any challenges with the subsequent request, which might be helpful. Good point. The problem is that I don't see the State attribute in Access-Accepts anymore.
Include the Calling-Station-Id and User-Name as well? Then perhaps hash them to get a (most likely unique) hex string. (See e.g. acct_unique policy.) Sounds like this calls for some unlang wizardry but definitely feasible.
I would have thought you could generate a new Correlation attribute on first request, log it with the request, and then cache it with rlm_cache. Then pull it out each time you are about to log a request or reply and put it on the log. Then you should have a stable ID across all entries in your elasticsearch db. rlm_cache is a very good advice. Copying the attributes to tunneled requests with the session-state methods should be easy enough as well so that we get a consistent correlation.
You might be better to keep track of the request time in FreeRADIUS and then just log it with each log entry. rlm_cache probably needed as well - but examples of arithmetic are in sites-enabled/default preacct (FreeRADIUS-Acct-Session-Start-Time).
Doing both timing in FR as well as a Correlation attribute is probably the best option. Sounds sensible. I'll say what I can manage to do. Sounds like I've got some work ahead of me to get this to work.
Thanks for the hints, that's good advice. Cheers, Christian -- Dipl.-Math. Christian Strauf Clausthal University of Techn. E-Mail: strauf@rz.tu-clausthal.de Rechenzentrum Web: www.rz.tu-clausthal.de Erzstraße 51 Tel.: +49-5323-72-2086 Fax: -992086 D-38678 Clausthal-Zellerfeld
On Apr 21, 2016, at 10:38 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
I assume you've seen https://github.com/FreeRADIUS/freeradius-server/tree/v3.1.x/doc/schemas/logs... which might be useful. Very interesting! If you'd like to, please drop me an email, I'd be happy exchange experiences / thoughts.
The State attribute should tie any challenges with the subsequent request, which might be helpful. Good point. The problem is that I don't see the State attribute in Access-Accepts anymore.
Internally we track the progression of requests/responses. Working on something now to expose the ID of the state struct we use to do that. It'll only be in the v3.1.x branch though. -Arran
Internally we track the progression of requests/responses.
Working on something now to expose the ID of the state struct we use to do that.
It'll only be in the v3.1.x branch though. That's brilliant. This makes things a lot easier. Thank you very much for looking into this, it's highly appreciated.
Christian
On Apr 22, 2016, at 1:41 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
Internally we track the progression of requests/responses.
Working on something now to expose the ID of the state struct we use to do that.
It'll only be in the v3.1.x branch though. That's brilliant. This makes things a lot easier. Thank you very much for looking into this, it's highly appreciated.
3, 2, 1 bikeshed... Relevant lines are 746-751 src/main/log.c The second number is the request that started the current authentication attempt. Makes it easier to find the initial request. I really like the v3.1.x debug output, I think it's the cleanest we've ever gotten it. -Arran (1) Received Access-Request Id 0 from 127.0.0.1:52963 to 127.0.0.1:1812 via lo0 length 126 (1) User-Name = "anonymous" (1) NAS-IP-Address = 127.0.0.1 (1) Calling-Station-Id = "02-00-00-00-00-01" (1) Framed-MTU = 1400 (1) NAS-Port-Type = Wireless-802.11 (1) Connect-Info = "CONNECT 11Mbps 802.11b" (1) EAP-Message = 0x0200000e01616e6f6e796d6f7573 (1) Message-Authenticator = 0x08e16ae9e6233a386ae4de4296f6b118 (1) Running section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) authorize { (1) eap - Peer sent EAP Response (code 2) ID 0 length 14 (1) eap - Peer sent EAP-Identity. Returning 'ok' so we can short-circuit the rest of authorize (1) eap (ok) (1) } # authorize (ok) (1) Using 'Auth-Type = eap' for authenticate {...} (1) Running Auth-Type eap from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) authenticate { (1) eap - Peer sent packet with EAP method Identity (1) (1) eap - Calling submodule eap_peap to process data (1) eap_peap - Initiating new TLS session (1) eap - Sending EAP Request (code 1) ID 1 length 6 (1) eap (handled) (1) } # authenticate (handled) (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) Running Post-Auth-Type Challenge from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) Sent Access-Challenge Id 0 from 127.0.0.1:1812 to 127.0.0.1:52963 via lo0 length 0 (1) EAP-Message = 0x010100061920 (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0x0101c700126c6ab4c489c65ec7b88ebe (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 1 from 127.0.0.1:52963 to 127.0.0.1:1812 via lo0 length 445 (2) User-Name = "anonymous" (2) NAS-IP-Address = 127.0.0.1 (2) Calling-Station-Id = "02-00-00-00-00-01" (2) Framed-MTU = 1400 (2) NAS-Port-Type = Wireless-802.11 (2) Connect-Info = "CONNECT 11Mbps 802.11b" (2) EAP-Message = 0x0201013919800000012f160301012a010001260303c887b579a289f020b83a7d919316267d5c0d426fd99bf0c7fcde066d259344760000acc030c02cc028c024c014c00a00a500a300a1009f006b006a0069006800390038003700360088008700860085c032c02ec02ac026c00fc005009d003d00350084c02fc02bc027c023c013c00900a400a200a0009e00670040003f003e0033003200310030009a0099009800970045004400430042c031c02dc029c025c00ec004009c003c002f009600410007c011c007c00cc00200050004c012c008001600130010000dc00dc003000a00ff01000051000b000403000102000a001c001a00170019001c001b0018001a0016000e000d000b000c0009000a000d0020001e060106020603050105020503040104020403030103020303020102020203000f000101 (2) State = 0x0101c700126c6ab4c489c65ec7b88ebe (2) Message-Authenticator = 0x3520f3dcf56a5e163e2f257b1534376d (2,1) Running section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (2,1) authorize { (2,1) eap - Peer sent EAP Response (code 2) ID 1 length 313 (2,1) eap - Continuing tunnel setup (2,1) eap (ok) (2,1) } # authorize (ok) (2,1) Using 'Auth-Type = eap' for authenticate {...} (2,1) Running Auth-Type eap from file /usr/local/freeradius/etc/raddb/sites-enabled/default (2,1) authenticate { (2,1) eap - Peer sent packet with EAP method PEAP (25) (2,1) eap - Calling submodule eap_peap to process data (2,1) eap_peap - Continuing EAP-TLS (2,1) eap_peap - Peer indicated complete TLS record size will be 303 bytes (2,1) eap_peap - Got complete TLS record, with length field (303 bytes) (2,1) eap_peap - [eap-tls verify] = complete (2,1) eap_peap - Handshake state - before/accept initialization (2,1) eap_peap - Handshake state - Server before/accept initialization (2,1) eap_peap - <<< recv handshake [length 298], client_hello (2,1) eap_peap - Handshake state - Server SSLv3 read client hello A (2,1) eap_peap - >>> send handshake [length 94], server_hello (2,1) eap_peap - Handshake state - Server SSLv3 write server hello A (2,1) eap_peap - >>> send handshake [length 2259], certificate (2,1) eap_peap - Handshake state - Server SSLv3 write certificate A (2,1) eap_peap - >>> send handshake [length 333], server_key_exchange (2,1) eap_peap - Handshake state - Server SSLv3 write key exchange A (2,1) eap_peap - >>> send handshake [length 4], server_hello_done (2,1) eap_peap - Handshake state - Server SSLv3 write server done A (2,1) eap_peap - Handshake state - Server SSLv3 flush data (2,1) eap_peap - Handshake state - Server SSLv3 read client certificate A (2,1) eap_peap - Need more data from client (2,1) eap_peap - Need more data from client (2,1) eap_peap - Complete TLS record (2710 bytes) larger than MTU (990 bytes), will fragment (2,1) eap_peap - Sending first TLS record fragment (990 bytes), 1720 bytes remaining (2,1) eap_peap - [eap-tls process] = handled (2,1) eap - Sending EAP Request (code 1) ID 2 length 1000 (2,1) eap (handled) (2,1) } # authenticate (handled) (2,1) Using Post-Auth-Type Challenge (2,1) Post-Auth-Type sub-section not found. Ignoring. (2,1) Running Post-Auth-Type Challenge from file /usr/local/freeradius/etc/raddb/sites-enabled/default (2,1) Sent Access-Challenge Id 1 from 127.0.0.1:1812 to 127.0.0.1:52963 via lo0 length 0 (2,1) EAP-Message = 0x010203e819c000000a96160303005e0200005a0303f999c5c1765fdd98d1a90ae98ca5a44cc425b9398a8cc88146a55814235bdf3e20eb1ede90c8c7e900c176e8e74bd18822c015f76b09cfa73cd7a4094ded01aedfc030000012ff01000100000b000403000102000f00010116030308d30b0008cf0008cc0003de308203da308202c2a003020102020101300d06092a864886f70d01010b0500308193310b3009060355040613024652310f300d06035504080c065261646975733112301006035504070c09536f6d65776865726531153013060355040a0c0c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e6f72673126302406035504030c1d4578616d706c6520436572746966696361746520417574686f72697479301e170d3136303430393030343431355a170d3136303630383030343431355a307c310b3009060355040613024652310f300d06035504080c0652616469757331153013060355040a0c0c4578616d706c6520496e632e3123302106035504030c1a4578616d706c65205365727665722043657274696669636174653120301e06092a864886f70d010901161161646d696e406578616d706c652e6f726730820122300d06092a864886f70d01010105000382010f003082010a0282010100d7da0664390c5f5919cf10809f2bebb59145fd75d486878d1d45f2c86d5ba3477b29b75bba55023fe8dffdbf8ce477b4e3ba51c04792c58d010d15b06393082bb5ec57b203cbd6bd7bc6b486e1cff66e0228b1787f5ed3e9b4d0580ea47229e8010f515e9a3786ce5b7f3b1033e04a0c5b0371722fe327d35e968590fac06ec253a646a6adb98eb151551d213057bfa25250d9f4c70c938a9074a6e369bc10929bd57c7a510b558619072ce40bd436015ebe53d7fb0a1759becec6dbe203ff7869769863154db74cf34fb9669578a56fd97260ab7d4d9fd73d23ed0b528c69334d8c164b449635b5dbe15987df3e25ff1e0377d28d3bd57bfe5aef663719b77d0203010001a34f304d30130603551d25040c300a06082b0601050507030130360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000382010100884dc686e71063e754aea8a5fe44098ce2353e3c4f034868630d9d77395c867b4e26b8af91557da0152a19e6797379494b11497c7bd5505c8929ea2224166a64c6998683f500483ccd4937aa4ef8ffbc868e328424ab835895a85861c143e6a45af71d79ccbe4d5f84470133ba0ae587b2ced91c53adeb69a3e26d5991fd2f06fa86259ba3aba4c4330190a9e497 (2,1) Message-Authenticator = 0x00000000000000000000000000000000 (2,1) State = 0x0203c7008a97c29ac489c65ec7b88ebe (2,1) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 2 from 127.0.0.1:52963 to 127.0.0.1:1812 via lo0 length 136 (3) User-Name = "anonymous" (3) NAS-IP-Address = 127.0.0.1 (3) Calling-Station-Id = "02-00-00-00-00-01" (3) Framed-MTU = 1400 (3) NAS-Port-Type = Wireless-802.11 (3) Connect-Info = "CONNECT 11Mbps 802.11b" (3) EAP-Message = 0x020200061900 (3) State = 0x0203c7008a97c29ac489c65ec7b88ebe (3) Message-Authenticator = 0xac16834a3bedcda9294764381e488fcb (3,1) Running section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (3,1) authorize { (3,1) eap - Peer sent EAP Response (code 2) ID 2 length 6 (3,1) eap - Continuing tunnel setup (3,1) eap (ok) (3,1) } # authorize (ok) (3,1) Using 'Auth-Type = eap' for authenticate {...} (3,1) Running Auth-Type eap from file /usr/local/freeradius/etc/raddb/sites-enabled/default (3,1) authenticate { (3,1) eap - Peer sent packet with EAP method PEAP (25) (3,1) eap - Calling submodule eap_peap to process data (3,1) eap_peap - Continuing EAP-TLS (3,1) eap_peap - Peer ACKed our handshake fragment (3,1) eap_peap - [eap-tls verify] = request (3,1) eap_peap - Sending additional TLS record fragment (994 bytes), 726 bytes remaining (3,1) eap_peap - [eap-tls process] = handled (3,1) eap - Sending EAP Request (code 1) ID 3 length 1000 (3,1) eap (handled)
On 21/04/16 14:35, Matthew Newton wrote:
The State attribute should tie any challenges with the subsequent request, which might be helpful.
"State" is not added until the eap.authenticate method has run, which is sub-optimal for certain types of logging. It also mutates on every round-trip, so it's actually a PITA for correlating all requests in a multi-request exchange. I've played with all this extensively; will try to write a short email documenting what we did.
On Apr 21, 2016, at 9:02 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.). We'd basically like to figure out the elapsed time between first Access-Request and the final Access-Accept (or Access-Reject for that matter).
The server doesn't really track that in 3.0, or tracks it only at second resolution. In 3.1, it tracks all requests / responses in millisecond or better resolution.
A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server. I searched a little and found a post by Alan DeKok from 2012 on a very similar matter. The problem is that there's nothing much you can use to correlate an Access-Request reliably to the answers by the RADIUS server. Alan suggested adding a reply item to the reply:
I'm not sure why you need to correlate them. They're already correlated in the server. All you need to do is print out the time difference between request and response.
I like the idea (you can probably even update the original request with that FreeRADIUS-Correlation-Id before logging it), however, I need some help with the "..." part of the above config snippet. Src IP and src port unfortunately aren't unique enough (the same NAS sends all requests from the same source port). I looked through dictionary.freeradius.internal to find some suitable attribute that isn't part of the original request and that would add some uniqueness but I don't see anything useful. Do you guys happen to know a suitable way of creating such a FreeRADIUS-Correlationa-Id that's unique for an Access-Request-...-Access-Accept exchange? I'm not sure whether the NAS will also include the attribute in all its later request packets. Do you happen to know if this is the case?
The NAS won't include any VSA in later request packets.
The approach with a correlation ID has one more disadvantage: according to RFC 2865, Access-Reject messages mustn't include such attributes. So this leaves us with the problem how to correlate rejects.
VSAs are allowed in Access-Reject.
This leads me to this question: FreeRADIUS obviously keeps track internally which reply correlates to which request. Is there any way to include some hint to this correlation via a FreeRADIUS-internal attribute which in turn could be logged in auth-detail or reply-detail files? Any help would be highly appreciated.
The simplest thing is to look at the request authenticator. It's essentially unique for all Access-Request packets. And you can track it in Access-Accepts. Add a dictionary entry for it (in a VSA space), as an attribute of type "octets", and then do: update reply { My-Correlation-String := "0x%{request:Packet-Authentication-Vector}" } You can then correlate requests and responses by looking at that field. Alan DeKok.
On Apr 21, 2016, at 11:11 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Apr 21, 2016, at 9:02 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.). We'd basically like to figure out the elapsed time between first Access-Request and the final Access-Accept (or Access-Reject for that matter).
The server doesn't really track that in 3.0, or tracks it only at second resolution.
In 3.1, it tracks all requests / responses in millisecond or better resolution.
A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server. I searched a little and found a post by Alan DeKok from 2012 on a very similar matter. The problem is that there's nothing much you can use to correlate an Access-Request reliably to the answers by the RADIUS server. Alan suggested adding a reply item to the reply:
I'm not sure why you need to correlate them. They're already correlated in the server. All you need to do is print out the time difference between request and response.
He's after completion time. I.e. from the first Access-Request to the Access-Accept/Access-Reject. It's not something we currently track (as far as i'm aware?), it's not something radsniff can do either. Easy to do in v3.1.x as we have request->state->id, which gets populated after the first call to rlm_eap and is stable throughout the progression of the authentication attempt. I was already thinking of adding this, it's useful for debugging issues with EAP. -Arran
Sounds like I have a really good reason to look forward to 3.1.x, since our wireless guys have been asking about response-time stats. Since I'll be upgrading from 2.2.x, are there huge gotchas I should be looking for? I've noticed mentions of the newer alternative to ntlm_auth, which I'll look into. Other than that, will a 2.2.x config work out of the gate, or am I looking at a fresh rebuild? Thanks, Steve Lovaas Colorado State University ________________________________________ From: Freeradius-Users <freeradius-users-bounces+steven.lovaas=colostate.edu@lists.freeradius.org> on behalf of Arran Cudbard-Bell <a.cudbardb@freeradius.org> Sent: Thursday, April 21, 2016 9:21 AM To: FreeRadius users mailing list Subject: Re: Correlating Access-Requests and Replys
On Apr 21, 2016, at 11:11 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Apr 21, 2016, at 9:02 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.). We'd basically like to figure out the elapsed time between first Access-Request and the final Access-Accept (or Access-Reject for that matter).
The server doesn't really track that in 3.0, or tracks it only at second resolution.
In 3.1, it tracks all requests / responses in millisecond or better resolution.
A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server. I searched a little and found a post by Alan DeKok from 2012 on a very similar matter. The problem is that there's nothing much you can use to correlate an Access-Request reliably to the answers by the RADIUS server. Alan suggested adding a reply item to the reply:
I'm not sure why you need to correlate them. They're already correlated in the server. All you need to do is print out the time difference between request and response.
He's after completion time. I.e. from the first Access-Request to the Access-Accept/Access-Reject. It's not something we currently track (as far as i'm aware?), it's not something radsniff can do either. Easy to do in v3.1.x as we have request->state->id, which gets populated after the first call to rlm_eap and is stable throughout the progression of the authentication attempt. I was already thinking of adding this, it's useful for debugging issues with EAP. -Arran
On Apr 21, 2016, at 11:35 AM, Lovaas,Steven <Steven.Lovaas@ColoState.EDU> wrote:
Sounds like I have a really good reason to look forward to 3.1.x, since our wireless guys have been asking about response-time stats.
Since I'll be upgrading from 2.2.x, are there huge gotchas I should be looking for? I've noticed mentions of the newer alternative to ntlm_auth, which I'll look into. Other than that, will a 2.2.x config work out of the gate, or am I looking at a fresh rebuild?
Rebuild. The move from v3.0.x to v3.1.x is less painful. May want to use it as an intermediary step. -Arran
On Apr 21, 2016, at 11:35 AM, Lovaas,Steven <Steven.Lovaas@ColoState.EDU> wrote:
Sounds like I have a really good reason to look forward to 3.1.x, since our wireless guys have been asking about response-time stats.
Since I'll be upgrading from 2.2.x, are there huge gotchas I should be looking for? I've noticed mentions of the newer alternative to ntlm_auth, which I'll look into. Other than that, will a 2.2.x config work out of the gate, or am I looking at a fresh rebuild?
See raddb/README.rst It contains instructions for upgrading. Alan DeKok.
On Apr 21, 2016, at 11:21 AM, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On Apr 21, 2016, at 11:11 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Apr 21, 2016, at 9:02 AM, Christian Strauf <strauf@rz.tu-clausthal.de> wrote:
we're trying to use an ELK stack (Elasticsearch, Logstash & Kibana) to monitor the performance of our FreeRADIUS 3.0.11 servers which rely on a number of external servers (database, directory etc.). We'd basically like to figure out the elapsed time between first Access-Request and the final Access-Accept (or Access-Reject for that matter).
The server doesn't really track that in 3.0, or tracks it only at second resolution.
In 3.1, it tracks all requests / responses in millisecond or better resolution.
A prerequisite for this is that we can actually correlate Access-Requests and replies by the RADIUS server. I searched a little and found a post by Alan DeKok from 2012 on a very similar matter. The problem is that there's nothing much you can use to correlate an Access-Request reliably to the answers by the RADIUS server. Alan suggested adding a reply item to the reply:
I'm not sure why you need to correlate them. They're already correlated in the server. All you need to do is print out the time difference between request and response.
He's after completion time. I.e. from the first Access-Request to the Access-Accept/Access-Reject.
It's not something we currently track (as far as i'm aware?), it's not something radsniff can do either.
Easy to do in v3.1.x as we have request->state->id, which gets populated after the first call to rlm_eap and is stable throughout the progression of the authentication attempt.
Lies, all lies... I'll add something that behaves like that. -Arran
On 21/04/16 16:39, Arran Cudbard-Bell wrote:
I'll add something that behaves like that.
It would be super-useful if the thing you add is present before "authorize" is called; State only appears after eap.authenticate, which can be too late for some kinds of logging. I never understood why State mutates on each roundtrip ;o)
On Apr 21, 2016, at 12:16 PM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 21/04/16 16:39, Arran Cudbard-Bell wrote:
I'll add something that behaves like that.
It would be super-useful if the thing you add is present before "authorize" is called; State only appears after eap.authenticate, which can be too late for some kinds of logging.
Yeah, the state I was referring to wasn't the state attribute, it was the a fr_state_entry_t. But the ID of that struct mutates every round too, because a new instance of that struct is allocated each time. We can change fr_state_to_request to populate a field in the REQUEST * with a session number if it fails to find a matching state entry or state attribute. If it does fine a state entry, we copy over the session number from that state entry. fr_state_to_request runs before authorize, so that'd meet your requirement :)
I never understood why State mutates on each roundtrip ;o)
Hmm, I think the idea might have been to add support for diverse proxy paths eventually, in which case you can't rely on just the request ID. -Arran
On 21 Apr 2016, at 13:11, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On Apr 21, 2016, at 12:16 PM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 21/04/16 16:39, Arran Cudbard-Bell wrote:
I'll add something that behaves like that.
It would be super-useful if the thing you add is present before "authorize" is called; State only appears after eap.authenticate, which can be too late for some kinds of logging.
Yeah, the state I was referring to wasn't the state attribute, it was the a fr_state_entry_t. But the ID of that struct mutates every round too, because a new instance of that struct is allocated each time.
We can change fr_state_to_request to populate a field in the REQUEST * with a session number if it fails to find a matching state entry or state attribute.
If it does fine a state entry, we copy over the session number from that state entry.
fr_state_to_request runs before authorize, so that'd meet your requirement :)
I never understood why State mutates on each roundtrip ;o)
Hmm, I think the idea might have been to add support for diverse proxy paths eventually, in which case you can't rely on just the request ID.
OK, request counter switched to a proper C11 atomic uin64_t. Added seq_start to request and fr_state_entry_t. Exposed with %s (request number is %n, so going for consistency with the one letter expansions). %s gets you the request number that initiated this sequence of requests. Avoids another atomic counter, which whilst they aren't the most expensive things, still aren't free. ... and oh joy, the compiler in travis is so old it doesn't ship with stdatomic.h, I guess i'll have to go fix that. I had a pass at trying to group requests in the same conversation together, it's not very good though, so will likely need to change. We do need some way of marking requests in the same conversation together. Alan and I discussed just printing the start number once, but for me a major advantage in displaying something that joins the requests together, is that you can grep for a sequence of log messages in debug output, so you need the number somewhere in each line. If you need something unique then: %{md5:%t%s} Should do that. Building session IDs is something separate for what I wrote this code for. I need a way of extracting complete EAP conversations out of debug logs, any other uses you find for it are happy side effects :) -- Though if you do want to create unique session IDs... Might also be an idea to record the time when the server started processing requests (when the event loop started) with high resolution. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On Apr 21, 2016, at 12:16 PM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
I never understood why State mutates on each roundtrip ;o)
Magic. :) It doesn't have to mutate. Many RADIUS servers just use the same one. We put a counter into it, so we can look at the State attribute, and see how many round trips have been taken. Alan DeKok.
It would be super-useful if the thing you add is present before "authorize" is called; State only appears after eap.authenticate, which can be too late for some kinds of logging. I agree with you, Phil. Having this Correlation attribute / variable from the very first to the very last packet would be incredibly useful.
Christian
On 21/04/16 14:02, Christian Strauf wrote:
but I don't see anything useful. Do you guys happen to know a suitable way of creating such a FreeRADIUS-Correlationa-Id that's unique for an Access-Request-...-Access-Accept exchange? I'm not sure whether the NAS will also include the attribute in all its later
As others have pointed out, this is tricky in current versions of the server. We have a rather complex set of policy that tries to "emulate" a "session" value, and a bunch of log searching scripts that are semi-smart in matching these request together. Some NAS vendors help you out here, by including attributes that let you correlate. For example, Cisco have: Cisco-AVPair = "audit-session-id=xxx" ...which is a very helpful attribute. Our (large) unlang policy for request/reply logging looks something like this: https://gist.github.com/philmayers/ae14614c1f13eb2f3fb7d0c253ac7fb7 This is basically a load of unlang that tries to emulate a "session" value into the (locally-defined) "Req-Session" variable. It then calls the linelog instances "reqlog" and "replog" to log a load of data from the request & reply, such as source/nas IP, Req-Session, the Req-Auth-Info (which includes the first bytes of the first EAP-Message AVP, from which you can extract EAP type and frame length), Module-Failure-Message, Reply-Message, and similar. It also ties the inner and outer together. The post-processing script is too big to post here and too integated with our systems, but it's basically a two-pass search a-la exigrep or similar - first search for matches of the search string, extracting the Req-Session, then do a 2nd pass, extracting all lines for that Req-Session. The script then post-processes the lines, extracting EAP IDs, frame times, making some intelligent guesses (you can spot the MSCHAP auth in a PEAP session from length) and generally prettying it up. It does some detection of half-complete EAP exchanges by the absence of the inner. It's helpful, but the server could make this so, so much easier by allocating a "session" to every packet received, either a new one or the previous one (keyed by State). Even for PAP requests. Cheers, Phil
On Apr 21, 2016, at 12:14 PM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
It's helpful, but the server could make this so, so much easier by allocating a "session" to every packet received, either a new one or the previous one (keyed by State). Even for PAP requests.
That's useful. And probably not hard to do. Just define a "FreeRADIUS-Session-Id" attribute as an octet string. If it doesn't exist, create it from 32 random bytes. If it does exist, ensure it's saved in the session_state list. And probably echoed back to the NAS in the Class attribute. And probably add rules to create a "possibly started" accounting session, with that session ID. If there's no accounting "start" within 10min, the "possibly started" record can be deleted. Otherwise, you have the pre-existing FreeRADIUS-Session-Id in SQL that can be used to track all packets for a session. Alan DeKok.
Our (large) unlang policy for request/reply logging looks something like this: Thank you very much for sharing this. It looks quite elegant. Please correct me if I'm wrong, but the only thing you need to modify to use your policy is to put Req-Session into the local dictionary and include the policy subroutines in the appropriate sections of the virtual server, right?
Cheers, Christian
On 22/04/16 06:47, Christian Strauf wrote:
Our (large) unlang policy for request/reply logging looks something like this: Thank you very much for sharing this. It looks quite elegant. Please correct me if I'm wrong, but the only thing you need to modify to use your policy is to put Req-Session into the local dictionary and include the policy subroutines in the appropriate sections of the virtual server, right?
You'd need to define the reqlog and replog modules - we use linelog instances, but you could use appropriate detail, redis, sql or other policy {} blocks. But yes, aside from defining the attributes (Req-Session and others) in the dictionary, that's it.
participants (6)
-
Alan DeKok -
Arran Cudbard-Bell -
Christian Strauf -
Lovaas,Steven -
Matthew Newton -
Phil Mayers