2.1.10 Certificate Compatibility Warning

5 Jan 2011

      I've been testing EAP-TTLS/MSCHAPv2 authentication with a network
device. FreeRADIUS keeps complaining about EAP sessions not finishing
with the link to the certificate compatibility wiki link, however the
authentication process completes successfully. Looking at the packet
exchanges more carefully it appears that the supplicant is not
incrementing the Packet Identifier. Every EAP packet sent by the
device uses an packet identifier of 0.

Digging through the RFCs I didn't find a requirement that the Packet
Identifier be incremented, only the note that it is used to correlate
requests and responses. This is obviously probably more difficult if
it never changes.

Is it a requirement that the NAS increment or change this value? It
would definitely seem to be the preferred choice. Or is the server a
bit too aggressive in detecting incomplete EAP sessions in this case?

rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=90
        User-Name = "anonymous"
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message = 0x0201000f01616e6f6e796d6f757300
        Message-Authenticator = 0x8509fb9d5f2dbeb7f8d46ab44db4053a
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 1 length 15
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] No EAP Start, assuming
it's an on-going EAP conversation
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns updated
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP Identity
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type tls
Wed Jan  5 12:20:12 2011 : Info: [tls] Flushing SSL sessions (of #0)
Wed Jan  5 12:20:12 2011 : Info: [tls] Initiate
Wed Jan  5 12:20:12 2011 : Info: [tls] Start returned 1
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns handled
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Challenge of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        EAP-Message = 0x010200061520
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x349732523495276465a22536fa36099e
Wed Jan  5 12:20:12 2011 : Info: Finished request 9.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=161
Wed Jan  5 12:20:12 2011 : Info: Cleaning up request 9 ID 0 with timestamp +54
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! EAP session for state
0x3497325234952764 did not finish!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "anonymous"
        State = 0x349732523495276465a22536fa36099e
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message =
0x0202004415800000003a16030100350100003103017484d895bc503fb0c4c912ab6232d60da4629c843adb37f0faf3e30207d0cc4f00000a0035002f00040005000a0100
        Message-Authenticator = 0x6b3d2a6441e0c787a2fd93770babab19
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 2 length 68
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Continuing tunnel setup.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Request found, released
from the list
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP/ttls
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type ttls
Wed Jan  5 12:20:12 2011 : Info: [ttls] Authenticate
Wed Jan  5 12:20:12 2011 : Info: [ttls] processing EAP-TLS
Wed Jan  5 12:20:12 2011 : Debug:   TLS Length 58
Wed Jan  5 12:20:12 2011 : Info: [ttls] Length Included
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_verify returned 11
Wed Jan  5 12:20:12 2011 : Info: [ttls]     (other): before/accept
initialization
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: before/accept
initialization
Wed Jan  5 12:20:12 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length
0035], ClientHello
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 read
client hello A
Wed Jan  5 12:20:12 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length
004a], ServerHello
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 write
server hello A
Wed Jan  5 12:20:12 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length
06ab], Certificate
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 write
certificate A
Wed Jan  5 12:20:12 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length
0004], ServerHelloDone
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 write
server done A
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 flush data
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: Need to read
more data: SSLv3 read client certificate A
Wed Jan  5 12:20:12 2011 : Debug: In SSL Handshake Phase
Wed Jan  5 12:20:12 2011 : Debug: In SSL Accept mode
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_process returned 13
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns handled
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Challenge of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        EAP-Message =
0x010303f815c000000708160301004a0200004603014d24b65c4dbdb63d3c79b319ba6a424ccf269a207ef66b8106ef2344c06569522056e4abbc8e95315b66f0618a78ce9a1ea6c20108ff0671f3835cc086cf08060500350016030106ab0b0006a70006a40003523082034e308202b7a003020102020101300d06092a864886f70d01010505003081c0310b30090603550406130255533111300f06035504081308496c6c696e6f69733121301f060355040a13184d6f746f726f6c6120536f6c7574696f6e732c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e64312230200603550403131943
        EAP-Message =
0x616e6f707920414141205365727665722044656d6f2043413133303106092a864886f70d0109011624746563686e6963616c2d737570706f72744063616e6f7079776972656c6573732e636f6d301e170d3031303130313030303030305a170d3439313233313233353935395a3081c9310b30090603550406130255533111300f06035504081308496c6c696e6f69733121301f060355040a13184d6f746f726f6c6120536f6c7574696f6e732c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e64312b30290603550403132243616e6f707920414141205365727665722044656d6f2043657274
        EAP-Message =
0x696669636174653133303106092a864886f70d0109011624746563686e6963616c2d737570706f72744063616e6f7079776972656c6573732e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100c32657829c0a23f3e456cbcb0128a00d9c180e00b857bcaecd388d159b14c017ff8e104968a1ab43622449c88cfcd301a5e78b3d54cbde59a1792118a2865b4359912727d8eff49120fdef4f16a0dd6d57298d4d8154c3cf5d7eaf0c2ff6d2464820206d9b1ce8eea199790cbffadc6da11ea78fa49717944f82a6e2f79396bd0203010001a34d304b30090603551d1304023000301d0603551d0e04160414c02f761f28
        EAP-Message =
0xade55e9451ed89078a0a74230811b8301f0603551d23041830168014eb8c22114d8cc6f0968ff7e23373b77b2eb56940300d06092a864886f70d010105050003818100bbb34e7519ee8671fafa40eddaa5a35aeaf5d3c693f9edb171649daa0d4e1344517235eec07129b379c54ef5cc7bf973104e1ff809539c92b7609dcf54017f5943a86f09a4ec427954b926789b27a2aa13202128eca10f06f5f87935112e776441859d9c65d21b225c4e68189151445c0bd5ecddb60b737747dd693cc7baba4100034c30820348308202b1a003020102020100300d06092a864886f70d01010505003081c0310b30090603550406130255533111300f06035504
        EAP-Message = 0x08130849
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x349732523594276465a22536fa36099e
Wed Jan  5 12:20:12 2011 : Info: Finished request 10.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=99
Wed Jan  5 12:20:12 2011 : Info: Cleaning up request 10 ID 0 with timestamp +54
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! EAP session for state
0x3497325235942764 did not finish!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "anonymous"
        State = 0x349732523594276465a22536fa36099e
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message = 0x020300061500
        Message-Authenticator = 0x869522bac614c2e3093e89644c53dc6a
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 3 length 6
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Continuing tunnel setup.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Request found, released
from the list
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP/ttls
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type ttls
Wed Jan  5 12:20:12 2011 : Info: [ttls] Authenticate
Wed Jan  5 12:20:12 2011 : Info: [ttls] processing EAP-TLS
Wed Jan  5 12:20:12 2011 : Info: [ttls] Received TLS ACK
Wed Jan  5 12:20:12 2011 : Info: [ttls] ACK handshake fragment handler
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_verify returned 1
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_process returned 13
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns handled
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Challenge of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        EAP-Message =
0x010403241580000007086c6c696e6f69733121301f060355040a13184d6f746f726f6c6120536f6c7574696f6e732c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e64312230200603550403131943616e6f707920414141205365727665722044656d6f2043413133303106092a864886f70d0109011624746563686e6963616c2d737570706f72744063616e6f7079776972656c6573732e636f6d301e170d3031303130313030303030305a170d3439313233313233353935395a3081c0310b30090603550406130255533111300f06035504081308496c6c696e6f69733121301f060355040a
        EAP-Message =
0x13184d6f746f726f6c6120536f6c7574696f6e732c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e64312230200603550403131943616e6f707920414141205365727665722044656d6f2043413133303106092a864886f70d0109011624746563686e6963616c2d737570706f72744063616e6f7079776972656c6573732e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100c0a0b87b37f1cab947267e48f511647106226ab3567a8c786eb048cd14d620a59af65c2efb8c7abd4438573a6984093cf44531efa8b5c776e2c8b88d1a2be829283d709a984b7e4ac9
        EAP-Message =
0x1ea9fcf413b20379285b7ead840b68e0c586b5bf2ade8e8dc0d6822b31bcfaf9f15abc23d47991b99f8c7024ac0d3618cff88ea93e3ef10203010001a350304e300c0603551d13040530030101ff301d0603551d0e04160414eb8c22114d8cc6f0968ff7e23373b77b2eb56940301f0603551d23041830168014eb8c22114d8cc6f0968ff7e23373b77b2eb56940300d06092a864886f70d0101050500038181000360b68c65dde686acea14798fe0e4029fbda711f2045a40be3f76cd787312e9bcb022578026481262cc20b501ce55680dc88696e25d99d01d78f56d9f72473387c959208584dba1f7d29b2e9b2bca043d7454bc11d29cf395d9b15e
        EAP-Message =
0x501c5d3f10d8f9089544be01959ef9c6bc226f2b4042cf2db63d06918ea3c735fa891cd316030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x349732523693276465a22536fa36099e
Wed Jan  5 12:20:12 2011 : Info: Finished request 11.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=301
Wed Jan  5 12:20:12 2011 : Info: Cleaning up request 11 ID 0 with timestamp +54
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! EAP session for state
0x3497325236932764 did not finish!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "anonymous"
        State = 0x349732523693276465a22536fa36099e
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message =
0x020400d01580000000c616030100861000008200806052251474e233df35b01e90a43892c2833489b2ac9d76b100f6c8a9c688586f7c4376c0ea704a68f593890d70beb86cca62eff2a3a00531bd58161c54db97dae680455d79d681d836da7d28dfd0c5f05ea7f16047526a173c7f336f1c4904313db71029a1a86df32ba82622bd7f4ffa9d1daa4b88cefce8adbaecb91d3639291403010001011603010030fc814716449d1366ced44cd691c760d23d77a919163b3e83226282d94e3bb860c2938036a236d260363f827a75e48337
        Message-Authenticator = 0x180e7f18caa6a2932c7df9968425f0ac
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 4 length 208
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Continuing tunnel setup.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Request found, released
from the list
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP/ttls
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type ttls
Wed Jan  5 12:20:12 2011 : Info: [ttls] Authenticate
Wed Jan  5 12:20:12 2011 : Info: [ttls] processing EAP-TLS
Wed Jan  5 12:20:12 2011 : Debug:   TLS Length 198
Wed Jan  5 12:20:12 2011 : Info: [ttls] Length Included
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_verify returned 11
Wed Jan  5 12:20:12 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length
0086], ClientKeyExchange
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 read
client key exchange A
Wed Jan  5 12:20:12 2011 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec
[length 0001]
Wed Jan  5 12:20:12 2011 : Info: [ttls] <<< TLS 1.0 Handshake [length
0010], Finished
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 read finished A
Wed Jan  5 12:20:12 2011 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec
[length 0001]
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 write
change cipher spec A
Wed Jan  5 12:20:12 2011 : Info: [ttls] >>> TLS 1.0 Handshake [length
0010], Finished
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 write finished A
Wed Jan  5 12:20:12 2011 : Info: [ttls]     TLS_accept: SSLv3 flush data
Wed Jan  5 12:20:12 2011 : Debug:   SSL: adding session
56e4abbc8e95315b66f0618a78ce9a1ea6c20108ff0671f3835cc086cf080605 to
cache
Wed Jan  5 12:20:12 2011 : Info: [ttls]     (other): SSL negotiation
finished successfully
Wed Jan  5 12:20:12 2011 : Debug: SSL Connection Established
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_process returned 13
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns handled
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Challenge of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        EAP-Message =
0x0105004515800000003b14030100010116030100301424f225e78255e13ca118b19c0741d52c6605608b43cba7e33ec19ed7b362f2ad107a1297dd55d26f400cc6ad9d612e
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x349732523792276465a22536fa36099e
Wed Jan  5 12:20:12 2011 : Info: Finished request 12.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=252
Wed Jan  5 12:20:12 2011 : Info: Cleaning up request 12 ID 0 with timestamp +54
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! EAP session for state
0x3497325237922764 did not finish!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "anonymous"
        State = 0x349732523792276465a22536fa36099e
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message =
0x0205009f158000000095170301009027f7fc953ec398362d2865c00dff24abe16326d4babc2080ebd9ffadd2ff577c401300c3b1ad3e6707880f3b156afca840797dc17605c07e2a339f0a017bac5036b081d71a4aa0f0cc397c27135a224da1be245b7456c5b1e569b24386ca2e2cfedfba5041d26a882307f7dfcc8f8cf4628d0ca11cbba6dc574523077723829df80fb27b0935ec431c77d350f981ee4c
        Message-Authenticator = 0x414201600d229c940acaa76321d47521
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 5 length 159
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Continuing tunnel setup.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Request found, released
from the list
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP/ttls
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type ttls
Wed Jan  5 12:20:12 2011 : Info: [ttls] Authenticate
Wed Jan  5 12:20:12 2011 : Info: [ttls] processing EAP-TLS
Wed Jan  5 12:20:12 2011 : Debug:   TLS Length 149
Wed Jan  5 12:20:12 2011 : Info: [ttls] Length Included
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_verify returned 11
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_process returned 7
Wed Jan  5 12:20:12 2011 : Info: [ttls] Session established.
Proceeding to decode tunneled attributes.
Wed Jan  5 12:20:12 2011 : Info: [ttls] Got tunneled request
        User-Name = "0a-00-3e-90-ff-93"
        MS-CHAP-Challenge = 0x55d8506d7436ba417bfaa01c8b21a04e
        MS-CHAP2-Response =
0xdd00c29e28c10e95bc0d708eed268ed9c633000000000000000006ce1ccccaa7956d849fd0aab90379270368a733b58f443b
        FreeRADIUS-Proxied-To = 127.0.0.1
Wed Jan  5 12:20:12 2011 : Info: [ttls] Sending tunneled request
        User-Name = "0a-00-3e-90-ff-93"
        MS-CHAP-Challenge = 0x55d8506d7436ba417bfaa01c8b21a04e
        MS-CHAP2-Response =
0xdd00c29e28c10e95bc0d708eed268ed9c633000000000000000006ce1ccccaa7956d849fd0aab90379270368a733b58f443b
        FreeRADIUS-Proxied-To = 127.0.0.1
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
server inner-tunnel {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/inner-tunnel
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info: ++[chap] returns noop
Wed Jan  5 12:20:12 2011 : Info: [mschap] Found MS-CHAP attributes.
Setting 'Auth-Type  = mschap'
Wed Jan  5 12:20:12 2011 : Info: ++[mschap] returns ok
Wed Jan  5 12:20:12 2011 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-90-ff-93", looking up realm NULL
Wed Jan  5 12:20:12 2011 : Info: [suffix] No such realm "NULL"
Wed Jan  5 12:20:12 2011 : Info: ++[suffix] returns noop
Wed Jan  5 12:20:12 2011 : Info: ++[control] returns noop
Wed Jan  5 12:20:12 2011 : Info: [eap] No EAP-Message, not doing EAP
Wed Jan  5 12:20:12 2011 : Info: ++[eap] returns noop
Wed Jan  5 12:20:12 2011 : Info: ++- entering policy redundant {...}
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand:
%{Stripped-User-Name} ->
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      ... expanding second conditional
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: %{User-Name}
-> 0a-00-3e-90-ff-93
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand:
%{%{User-Name}:-DEFAULT} -> 0a-00-3e-90-ff-93
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand:
%{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} ->
0a-00-3e-90-ff-93
Wed Jan  5 12:20:12 2011 : Info: [sqlmain] sql_set_user escaped user
--> '0a-00-3e-90-ff-93'
Wed Jan  5 12:20:12 2011 : Debug: rlm_sql (sqlmain): Reserving sql socket id: 10
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
username, attribute, value, op           FROM radcheck           WHERE
username = BINARY '%{SQL-User-Name}'           ORDER BY id -> SELECT
id, username, attribute, value, op           FROM radcheck
WHERE username = BINARY '0a-00-3e-90-ff-93'           ORDER BY id
Wed Jan  5 12:20:12 2011 : Info: [sqlmain] User found in radcheck table
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
username, attribute, value, op           FROM radreply           WHERE
username = BINARY '%{SQL-User-Name}'           ORDER BY id -> SELECT
id, username, attribute, value, op           FROM radreply
WHERE username = BINARY '0a-00-3e-90-ff-93'           ORDER BY id
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT
groupname           FROM radusergroup           WHERE username =
BINARY '%{SQL-User-Name}'           ORDER BY priority -> SELECT
groupname           FROM radusergroup           WHERE username =
BINARY '0a-00-3e-90-ff-93'           ORDER BY priority
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
groupname, attribute,           Value, op           FROM radgroupcheck
          WHERE groupname = '%{Sql-Group}'           ORDER BY id ->
SELECT id, groupname, attribute,           Value, op           FROM
radgroupcheck           WHERE groupname = 'Canopy_SM'           ORDER
BY id
Wed Jan  5 12:20:12 2011 : Info: [sqlmain] User found in group Canopy_SM
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
groupname, attribute,           value, op           FROM radgroupreply
          WHERE groupname = '%{Sql-Group}'           ORDER BY id ->
SELECT id, groupname, attribute,           value, op           FROM
radgroupreply           WHERE groupname = 'Canopy_SM'           ORDER
BY id
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
groupname, attribute,           Value, op           FROM radgroupcheck
          WHERE groupname = '%{Sql-Group}'           ORDER BY id ->
SELECT id, groupname, attribute,           Value, op           FROM
radgroupcheck           WHERE groupname = 'Canopy_Res1536'
ORDER BY id
Wed Jan  5 12:20:12 2011 : Info: [sqlmain] User found in group Canopy_Res1536
Wed Jan  5 12:20:12 2011 : Info: [sqlmain]      expand: SELECT id,
groupname, attribute,           value, op           FROM radgroupreply
          WHERE groupname = '%{Sql-Group}'           ORDER BY id ->
SELECT id, groupname, attribute,           value, op           FROM
radgroupreply           WHERE groupname = 'Canopy_Res1536'
ORDER BY id
Wed Jan  5 12:20:12 2011 : Debug: rlm_sql (sqlmain): Released sql socket id: 10
Wed Jan  5 12:20:12 2011 : Info: +++[sqlmain] returns ok
Wed Jan  5 12:20:12 2011 : Info: ++- policy redundant returns ok
Wed Jan  5 12:20:12 2011 : Info: ++[expiration] returns noop
Wed Jan  5 12:20:12 2011 : Info: ++[logintime] returns noop
Wed Jan  5 12:20:12 2011 : Info: [pap] WARNING: Auth-Type already set.
 Not setting to PAP
Wed Jan  5 12:20:12 2011 : Info: ++[pap] returns noop
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = MSCHAP
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/inner-tunnel
Wed Jan  5 12:20:12 2011 : Info: +- entering group MS-CHAP {...}
Wed Jan  5 12:20:12 2011 : Info: [mschap] Creating challenge hash with
username: 0a-00-3e-90-ff-93
Wed Jan  5 12:20:12 2011 : Info: [mschap] Told to do MS-CHAPv2 for
0a-00-3e-90-ff-93 with NT-Password
Wed Jan  5 12:20:12 2011 : Info: [mschap] adding MS-CHAPv2 MPPE keys
Wed Jan  5 12:20:12 2011 : Info: ++[mschap] returns ok
Wed Jan  5 12:20:12 2011 : Auth: Login OK: [0a-00-3e-90-ff-93] (from
client MTC WAN port 5 via TLS tunnel)
Wed Jan  5 12:20:12 2011 : Info:   WARNING: Empty post-auth section.
Using default return values.
Wed Jan  5 12:20:12 2011 : Info: # Executing section post-auth from
file /etc/raddb/sites-enabled/inner-tunnel
} # server inner-tunnel
Wed Jan  5 12:20:12 2011 : Info: [ttls] Got tunneled reply code 2
        Motorola-Canopy-VLLEARNEN = Enable
        Motorola-Canopy-VLFRAMES = All
        Motorola-Canopy-VLAGETO = 1440
        Motorola-Canopy-VLSMMGPASS = Enable
        Motorola-Canopy-BCASTMIR = 200
        Motorola-Canopy-HPENABLE = Disable
        Motorola-Canopy-ULBR = 512
        Motorola-Canopy-ULBL = 1024
        Motorola-Canopy-DLBR = 1536
        Motorola-Canopy-DLBL = 3072
        MS-CHAP2-Success =
0xdd533d35413832393633423538373533334437443036333545454243353939443343384237424435434344
        MS-MPPE-Recv-Key = 0xbeb5c2f487f5d04afdd79d7a34333156
        MS-MPPE-Send-Key = 0x654709eb0ed4833cfba23373b26ec90d
        MS-MPPE-Encryption-Policy = 0x00000001
        MS-MPPE-Encryption-Types = 0x00000006
Wed Jan  5 12:20:12 2011 : Info: [ttls] Got tunneled Access-Accept
Wed Jan  5 12:20:12 2011 : Info: [ttls] Got MS-CHAP2-Success,
tunneling it to the client in a challenge.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns handled
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Challenge of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        EAP-Message =
0x0106005f1580000000551703010050e31a54aa3f505e5dbd650217d16a5934079d8429ae74d54eaf4f71737d6738e4e87adfd2cdec2d815c71ccac52ac3b8fad73bcf6f6c17ac8e2ba97b734c77a285c4a15322756d40f6b294c001d5bf285
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x349732523091276465a22536fa36099e
Wed Jan  5 12:20:12 2011 : Info: Finished request 13.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
rad_recv: Access-Request packet from host 66.242.65.10 port 28461,
id=0, length=99
Wed Jan  5 12:20:12 2011 : Info: Cleaning up request 13 ID 0 with timestamp +54
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! EAP session for state
0x3497325230912764 did not finish!
Wed Jan  5 12:20:12 2011 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Wed Jan  5 12:20:12 2011 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "anonymous"
        State = 0x349732523091276465a22536fa36099e
        NAS-IP-Address = 192.168.4.48
        NAS-Port = 5
        NAS-Port-Type = Wireless-802.11
        Framed-MTU = 1020
        EAP-Message = 0x020600061500
        Message-Authenticator = 0xf0f5a88ff1fa628b41a033a2ece3f5d2
Wed Jan  5 12:20:12 2011 : Info: server canopy {
Wed Jan  5 12:20:12 2011 : Info: # Executing section authorize from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authorize {...}
Wed Jan  5 12:20:12 2011 : Info:        expand: %{User-Name} -> anonymous
Wed Jan  5 12:20:12 2011 : Info: ++[reply] returns notfound
Wed Jan  5 12:20:12 2011 : Info: ++[preprocess] returns ok
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP packet type response
id 6 length 6
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Continuing tunnel setup.
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Info: Found Auth-Type = eap_canopy
Wed Jan  5 12:20:12 2011 : Info: # Executing group from file
/etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: +- entering group authenticate {...}
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Request found, released
from the list
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] EAP/ttls
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] processing type ttls
Wed Jan  5 12:20:12 2011 : Info: [ttls] Authenticate
Wed Jan  5 12:20:12 2011 : Info: [ttls] processing EAP-TLS
Wed Jan  5 12:20:12 2011 : Info: [ttls] Received TLS ACK
Wed Jan  5 12:20:12 2011 : Info: [ttls] ACK handshake is finished
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_verify returned 3
Wed Jan  5 12:20:12 2011 : Info: [ttls] eaptls_process returned 3
Wed Jan  5 12:20:12 2011 : Info: [ttls] Using saved attributes from
the original Access-Accept
        Motorola-Canopy-VLLEARNEN = Enable
        Motorola-Canopy-VLFRAMES = All
        Motorola-Canopy-VLAGETO = 1440
        Motorola-Canopy-VLSMMGPASS = Enable
        Motorola-Canopy-BCASTMIR = 200
        Motorola-Canopy-HPENABLE = Disable
        Motorola-Canopy-ULBR = 512
        Motorola-Canopy-ULBL = 1024
        Motorola-Canopy-DLBR = 1536
        Motorola-Canopy-DLBL = 3072
Wed Jan  5 12:20:12 2011 : Info: [ttls] Saving response in the cache
Wed Jan  5 12:20:12 2011 : Info: [eap_canopy] Freeing handler
Wed Jan  5 12:20:12 2011 : Info: ++[eap_canopy] returns ok
Wed Jan  5 12:20:12 2011 : Auth: Login OK: [anonymous] (from client
MTC WAN port 5)
Wed Jan  5 12:20:12 2011 : Info:   WARNING: Empty post-auth section.
Using default return values.
Wed Jan  5 12:20:12 2011 : Info: # Executing section post-auth from
file /etc/raddb/sites-enabled/canopy
Wed Jan  5 12:20:12 2011 : Info: } # server canopy
Sending Access-Accept of id 0 to 66.242.65.10 port 28461
        User-Name = "anonymous"
        Motorola-Canopy-VLLEARNEN = Enable
        Motorola-Canopy-VLFRAMES = All
        Motorola-Canopy-VLAGETO = 1440
        Motorola-Canopy-VLSMMGPASS = Enable
        Motorola-Canopy-BCASTMIR = 200
        Motorola-Canopy-HPENABLE = Disable
        Motorola-Canopy-ULBR = 512
        Motorola-Canopy-ULBL = 1024
        Motorola-Canopy-DLBR = 1536
        Motorola-Canopy-DLBL = 3072
        MS-MPPE-Recv-Key =
0xdd9e15596bfac7dd8c66fd557f61357419e77e8ecccac8e9f6a3355d982ce8ab
        MS-MPPE-Send-Key =
0x8d0293fbc4e5971e8b045d16916a67d912a1f68872c049d85794c76c4e523259
        EAP-Message = 0x03060004
        Message-Authenticator = 0x00000000000000000000000000000000
Wed Jan  5 12:20:12 2011 : Info: Finished request 14.
Wed Jan  5 12:20:12 2011 : Debug: Going to the next request
Wed Jan  5 12:20:12 2011 : Debug: Waking up in 2.9 seconds.
Wed Jan  5 12:20:15 2011 : Info: Cleaning up request 14 ID 0 with timestamp +54
Wed Jan  5 12:20:15 2011 : Info: Ready to process requests.

Compared to a different string of requests generated using
wpa_supplicant the id is obviously incremented (skipping the first
five packets):
rad_recv: Access-Request packet from host 172.17.0.138 port 55717,
id=6, length=316
        User-Name = "anonymous@wisper-wireless.com"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        Connect-Info = "CONNECT 11Mbps 802.11b"
        NAS-Port-Type = Wireless-802.16
        Service-Type = Framed-User
        EAP-Message =
0x020600a0150017030100203de4af49c951500431261fcd0f815bd5a18f05d0549a0ce4af46b54f2b0d59fd17030100708c00bea3cc199c88da3b652504a95d94b52bc4ee1fda8b284bfa8d5eefc11dc66b33dd975c9faf53b1300d96b900e17558935821f276bca430f73605d2c75d3982f50eaf7e26e1b3fa81faef891962505583b278adf9f6de430f4c81e084ed55575b8c38dd655187d8319b15050b17f3
        State = 0xdf91ccf8da97d9cc64d8d4a9a5b4db83
        Message-Authenticator = 0x55b6786727aeeca2723a076f66fb9a9f

2.1.10 Certificate Compatibility Warning

Ben Wiechman