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)