RE: Additional EAP-TLS Logging Option

7 Sep 2010

      Alan DeKok wrote:
...
Read raddb/sites-enabled/default.  Look for "TLS-Cert".
These are attributes that you can use in *any* logging.  See the "log"
 section of radiusd.conf for custom log messages.  See the "linelog"
 module for logging miscellaneous text.
Thanks.  I've got it working now where it logs things correctly for successful authentications, but I'm not having any luck getting the logging to work when the authentication fails.  The code that generates the attributes is being executed, but when it logs them they all show up as empty.  Here is my post-auth configuration:

        post-auth {
                update reply {
                        x509_CA_Serial          += "%{TLS-Cert-Serial}"
                        x509_CA_Expiration      += "%{TLS-Cert-Expiration}"
                        x509_CA_Issuer          += "%{TLS-Cert-Issuer}"
                        x509_CA_Subject         += "%{TLS-Cert-Subject}"
                        x509_Client_Serial      += "%{TLS-Client-Cert-Serial}"
                        x509_Client_Expiration  += "%{TLS-Client-Cert-Expiration}"
                        x509_Client_Issuer      += "%{TLS-Client-Cert-Issuer}"
                        x509_Client_Subject     += "%{TLS-Client-Cert-Subject}"
                }
                post_auth_log

                Post-Auth-Type REJECT {
                        update reply {
                                Failure_Reason          += "%{Module-Failure-Message}"
                                x509_CA_Serial          += "%{TLS-Cert-Serial}"
                                x509_CA_Expiration      += "%{TLS-Cert-Expiration}"
                                x509_CA_Issuer          += "%{TLS-Cert-Issuer}"
                                x509_CA_Subject         += "%{TLS-Cert-Subject}"
                                x509_Client_Serial      += "%{TLS-Client-Cert-Serial}"
                                x509_Client_Expiration  += "%{TLS-Client-Cert-Expiration}"
                                x509_Client_Issuer      += "%{TLS-Client-Cert-Issuer}"
                                x509_Client_Subject     += "%{TLS-Client-Cert-Subject}"
                        }
                        post_auth_log
                }
        }

Here's an example log from a request where the common name check within cbtls_verify failed:

Mon Sep  6 21:32:59 2010
        Packet-Type = Access-Reject
        Failure_Reason = "TLS Alert write:fatal:certificate unknown"
        x509_CA_Serial = ""
        x509_CA_Expiration = ""
        x509_CA_Issuer = ""
        x509_CA_Subject = ""
        x509_Client_Serial = ""
        x509_Client_Expiration = ""
        x509_Client_Issuer = ""
        x509_Client_Subject = ""

Note:  This is all with the patch submitted in the separate email.

Any suggestions or ideas?

Thanks,
Mike Ross

Here is the radiusd -X output:

FreeRADIUS Version 2.1.10, for host x86_64-unknown-linux-gnu, built on Sep  6 2010 at 21:00:35
Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License v2.
Starting - reading configuration files ...
including configuration file /home/mross/Documents/FreeRadius/build/etc/raddb/radiusd.conf
including files in directory /home/mross/Documents/FreeRadius/build/etc/raddb/modules/
including configuration file /home/mross/Documents/FreeRadius/build/etc/raddb/modules/detail
including configuration file /home/mross/Documents/FreeRadius/build/etc/raddb/modules/expr
including configuration file /home/mross/Documents/FreeRadius/build/etc/raddb/eap.conf
including files in directory /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/
including configuration file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
including dictionary file /home/mross/Documents/FreeRadius/build/etc/raddb/dictionary
main {
        prefix = "/home/mross/Documents/FreeRadius/build"
        localstatedir = "/home/mross/Documents/FreeRadius/build/var"
        logdir = "/home/mross/Documents/FreeRadius/build/var/log/radius"
        libdir = "/home/mross/Documents/FreeRadius/build/lib"
        radacctdir = "/home/mross/Documents/FreeRadius/build/var/log/radius/radacct"
        hostname_lookups = no
        max_request_time = 30
        cleanup_delay = 5
        max_requests = 1024
        pidfile = "/home/mross/Documents/FreeRadius/build/var/run/radiusd/radiusd.pid"
        checkrad = "/home/mross/Documents/FreeRadius/build/sbin/checkrad"
        debug_level = 0
        proxy_requests = no
 log {
        stripped_names = no
        auth = no
        auth_badpass = no
        auth_goodpass = no
 }
 security {
        max_attributes = 200
        reject_delay = 1
        status_server = yes
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_expr
 Module: Instantiating module "expr" from file /home/mross/Documents/FreeRadius/build/etc/raddb/modules/expr
 }
radiusd: #### Loading Virtual Servers ####
server 802.1x { # from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_eap
 Module: Instantiating module "eap" from file /home/mross/Documents/FreeRadius/build/etc/raddb/eap.conf
  eap {
        default_eap_type = "tls"
        timer_expire = 60
        ignore_unknown_eap_types = no
        cisco_accounting_username_bug = no
        max_sessions = 4096
  }
 Module: Linked to sub-module rlm_eap_tls
 Module: Instantiating eap-tls
   tls {
        rsa_key_exchange = no
        dh_key_exchange = yes
        rsa_key_length = 512
        dh_key_length = 512
        verify_depth = 0
        CA_path = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/crl"
        pem_file_type = yes
        private_key_file = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/server.pem"
        certificate_file = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/server.pem"
        CA_file = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/ca.pem"
        private_key_password = "1234"
        dh_file = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/dh"
        random_file = "/home/mross/Documents/FreeRadius/build/etc/raddb/certs/random"
        fragment_size = 1024
        include_length = yes
        check_crl = no
        check_cert_cn = "valid.radius.client.boeing.com"
        cipher_list = "DEFAULT"
        check_cert_issuer = "/O=Boeing/OU=Integration Labs/CN=Test Issuing CA"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
   }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_detail
 Module: Instantiating module "auth_log" from file /home/mross/Documents/FreeRadius/build/etc/raddb/modules/detail
  detail auth_log {
        detailfile = "/home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 Module: Checking post-auth {...} for more modules to load
 Module: Instantiating module "post_auth_log" from file /home/mross/Documents/FreeRadius/build/etc/raddb/modules/detail
  detail post_auth_log {
        detailfile = "/home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Certs.log"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 } # modules
} # server
server { # from file /home/mross/Documents/FreeRadius/build/etc/raddb/radiusd.conf
 modules {
 } # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
        type = "auth"
        ipaddr = *
        port = 0
  client localhost {
        ipaddr = 127.0.0.1
        require_message_authenticator = yes
        secret = "radius"
  }
}
Listening on authentication address * port 1812 as server 802.1x

...

rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=0, length=122
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0200000c017265766f6b6564
        Message-Authenticator = 0x34b88010164dae08466e82105d6cc3b0
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 0 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Requiring client certificate
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
} # server 802.1x
Sending Access-Challenge of id 0 to 127.0.0.1 port 41736
        EAP-Message = 0x010100060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x93c976a093c87bf74064bdd70ea2ce5a
Finished request 7.
Going to the next request
Waking up in 3.6 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=1, length=221
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0201005d0d0016030100520100004e03014c85c07b6ef0254b1c5e67dcc7d434c8cf5dfbbb47e268059c980e3508a55d8b00002600390038003500160013000a00330032002f0005000400150012000900140011000800060003020100
        State = 0x93c976a093c87bf74064bdd70ea2ce5a
        Message-Authenticator = 0x642240c2ca740d3cc52481800fc0e2c4
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 1 length 93
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
[tls] eaptls_verify returned 7
[tls] Done initial handshake
[tls]     (other): before/accept initialization
[tls]     TLS_accept: before/accept initialization
[tls] <<< TLS 1.0 Handshake [length 0052], ClientHello
[tls]     TLS_accept: SSLv3 read client hello A
[tls] >>> TLS 1.0 Handshake [length 002a], ServerHello
[tls]     TLS_accept: SSLv3 write server hello A
[tls] >>> TLS 1.0 Handshake [length 0827], Certificate
[tls]     TLS_accept: SSLv3 write certificate A
[tls] >>> TLS 1.0 Handshake [length 018d], ServerKeyExchange
[tls]     TLS_accept: SSLv3 write key exchange A
[tls] >>> TLS 1.0 Handshake [length 00a1], CertificateRequest
[tls]     TLS_accept: SSLv3 write certificate request A
[tls]     TLS_accept: SSLv3 flush data
[tls]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[tls] eaptls_process returned 13
++[eap] returns handled
} # server 802.1x
Sending Access-Challenge of id 1 to 127.0.0.1 port 41736
        EAP-Message = 0x010204000dc000000a93160301002a0200002603014c85c07b5541e9efd0b1a03acfcd769fd872efe79184b008930685ea565e65fd0000390116030108270b0008230008200002f4308202f030820259a0030201020203008002300d06092a864886f70d01010505003046310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311830160603550403130f546573742049737375696e67204341301e170d3130303632383230353335365a170d3131303632383230353335365a304f310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c61
        EAP-Message = 0x62733121301f060355040313187261646975732e7365727665722e626f65696e672e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d3155c38f186b00cf87885b31ff5917dbbd3c358c9f5db8f91510ed05c87bf6725763d4b0b982e042b9466129ca1bdc6e39eb90af1e7303b84d0d3754921420c173b1e7c6335e2c7c322adf2d542329976097435456db12144be332b75c96c0944f7f8faf9e689c9158d4c51257dd5144efc70f21a676ac6d2663af4e4ff54070203010001a381e23081df301d0603551d0e04160414209b0bac45d59fb4b4a9212855ca080fc804126b300e0603551d0f0101ff0404030205a030
        EAP-Message = 0x2a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e672e636f6d2f63726c306d0603551d2304663064801496c24ba1a2a1646c74e23852a2783042c7c1bde2a147a4453043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341820300800130130603551d25040c300a06082b06010505070301300d06092a864886f70d0101050500038181000e0fc64d4594eb457bba4091d7a272ad91082d26477bbc0152d637e8264db614373f83a4399f7d32deeb87db12109acd8a3cbb8c75792832c7d37f
        EAP-Message = 0x2e0668c457c2cffc12e5bdc83f709d9cc111ce75c50ac7b7f79ba6f07447e30a25de66aaec523dc2635821e5b5e9fc3a29cc678909fa30afe136be1b089c086a19a6fe3a690002903082028c308201f5a0030201020203008001300d06092a864886f70d01010505003043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341301e170d3130303632383230353034345a170d3132303231383230353034345a3046310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c61627331
        EAP-Message = 0x1830160603550403130f5465
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x93c976a092cb7bf74064bdd70ea2ce5a
Finished request 8.
Going to the next request
Waking up in 3.6 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=2, length=134
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020200060d00
        State = 0x93c976a092cb7bf74064bdd70ea2ce5a
        Message-Authenticator = 0xb053bb841c26283ad8f5c21c1e223043
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 2 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
[tls] Received TLS ACK
[tls] ACK handshake fragment handler
[tls] eaptls_verify returned 1
[tls] eaptls_process returned 13
++[eap] returns handled
} # server 802.1x
Sending Access-Challenge of id 2 to 127.0.0.1 port 41736
        EAP-Message = 0x010304000dc000000a9373742049737375696e6720434130819f300d06092a864886f70d010101050003818d0030818902818100af2b2753c03e4a4b4a4cc484300d9c7f9b2f5c500ce3af01036eba55ba2e943ca1685a7f93413c5509a3b46658b561010bed73c11d85f8436040783ba03285917c5c5cde64e978758f53665588c0feb14d5c51f5d2ef864aff87d829660c19f6d638680c5c242c808866dc61eff9ecef058cd036d5162d84d5d2b69ca3b303870203010001a3818a308187300c0603551d13040530030101ff300b0603551d0f040403020186302a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e
        EAP-Message = 0x672e636f6d2f63726c301d0603551d0e0416041496c24ba1a2a1646c74e23852a2783042c7c1bde2301f0603551d23041830168014ca3a1f841d11917e92af5a133b829d1c19622225300d06092a864886f70d01010505000381810034907042242eb4977e8e97b9d2bbd5bb05535ea42c56f65ede6e85a48e8d1b60f89d832f1a892c56fd390c20dd3039cfeedb3590d7c3895faf89ab5b00464a33f522379707a4b44ed35b6c8c232ef8ec12878eab669e0fb25cfc0b61b8df749e311710a61ea4881b33b71d0f4ae832eec77b45b01978e578e1620dcb0179cd340002933082028f308201f8a003020102020900a04aeb4bb318e1b9300d06092a86
        EAP-Message = 0x4886f70d01010505003043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341301e170d3130303632383230343130355a170d3132303632373230343130355a3043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f7420434130819f300d06092a864886f70d010101050003818d0030818902818100d3e745a362bf42e0e655c26ec00210ea0d08cdb89b7770cdb6f614b24bc44d132ba21d513ad35cd024f32d3742
        EAP-Message = 0xc62ac413603f5084a7e88c9399375f2063d07d2fa06dd0b2bd18c99da8c1b8208f762f68ec3e42c571a80eed00e8d7a04e09edd87cc62bfc231b391823cedca81dbab493babf896ee9ba35a6695ec640e2fef70203010001a3818a308187300c0603551d13040530030101ff300b0603551d0f040403020186302a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e672e636f6d2f63726c301d0603551d0e04160414ca3a1f841d11917e92af5a133b829d1c19622225301f0603551d23041830168014ca3a1f841d11917e92af5a133b829d1c19622225300d06092a864886f70d0101050500038181005ed06447c7
        EAP-Message = 0xaa67bc0b7a9a4c1b077c4c11
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x93c976a091ca7bf74064bdd70ea2ce5a
Finished request 9.
Going to the next request
Waking up in 3.6 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=3, length=134
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020300060d00
        State = 0x93c976a091ca7bf74064bdd70ea2ce5a
        Message-Authenticator = 0x46c759e73f4679f66cff50b898b33548
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 3 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
[tls] Received TLS ACK
[tls] ACK handshake fragment handler
[tls] eaptls_verify returned 1
[tls] eaptls_process returned 13
++[eap] returns handled
} # server 802.1x
Sending Access-Challenge of id 3 to 127.0.0.1 port 41736
        EAP-Message = 0x010402b10d8000000a930cdd42b0902d3f9f6b44d919f7adc94c6f6cb988de1bf4fa8f6f63e852e176876520913ce4d258357b377b5344d335d1cf720e8e603a3bc031900650a0ae8cb08414d7ccff4d2586ef18b564f3f270036cf5fcec77fa71174ffa7a48da15708cd4f39c2f932b6364c716b150f536cf160301018d0c0001890080a8e2983a7e702cf8c9bf9ec8338205d62e2de224ae42cbfd7aaceae1732c5adc6e086a6a7cc4609bb3f3d68699c7ae503c4db864389293897bfc8cc33cba8055236a75f53c93c359bea6f6540967fee5d90e19b3e4a9e4a7d1850147556aa78a2c04061bec997b1d9fcd07af439844feb9039a9bdf4cb1f099
        EAP-Message = 0xfd4806c510941b00010200802aa2c61f6f37f94430c4b3dbb279108ebb03a230b8b429a801b61197621af5c029700708e859b0e4b0db7e649821112ca5444602a0d93bf7d0265990a1ab646c31e16fb0a78a01e3deca9f3d2ba42f855ce39a8fbc8c9b1b0c305b45fc696e1b994d7cfd3a77fa660292ccc6126b8b4c86aad5e88705b6933d272c3eb2964c290080ccfa270f4cf40ad6dae99668f61a3c44d80b3e37b8dc0e07780e0716275834ff978c0380e1bb2136ad6c24ac96df4b4e3e9bce267152e538f7cc367fa10eed98bbdf1380f9e74d7d850da981934a5f1e4977374aa5f0cced621a471c862cc80b5bf8c7509f3e9aea6920d819c0ce50
        EAP-Message = 0x9083c655c3984e607cde1f0e497c2b695d16030100a10d000099050304010240009100453043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f7420434100483046310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311830160603550403130f546573742049737375696e672043410e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x93c976a090cd7bf74064bdd70ea2ce5a
Finished request 10.
Going to the next request
Waking up in 3.6 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=4, length=1546
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020405800dc00000098d16030108370b0008330008300003043082030030820269a0030201020203008004300d06092a864886f70d01010505003046310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311830160603550403130f546573742049737375696e67204341301e170d3130303632383230353530385a170d3131303632383230353530385a3057310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c61627331293027060355040313207265766f6b65642e7261646975732e636c69656e742e626f65696e672e636f6d3081
        EAP-Message = 0x9f300d06092a864886f70d010101050003818d0030818902818100c1723fe0a67647a9005d71c9e69e39dc05a73c48bf00a907e3cb2f0a68120aa1c6d36fca1a2012f273a32b11941ec18aaa0eb3dfe5d00598f704cef07aebfb04ead5e18a938b92b5731878a5ca35a79368deec65a2609df22c9e8bd65ed49189e4ba4256affe0370611b315bd8984af00966c906fafcc9d8e8a79cbdc4e4a01f0203010001a381ea3081e730090603551d1304023000300b0603551d0f0404030203a8302a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e672e636f6d2f63726c301d0603551d0e04160414738d69ee7829458c
        EAP-Message = 0x65f7106cd2397832bf35b3d0306d0603551d2304663064801496c24ba1a2a1646c74e23852a2783042c7c1bde2a147a4453043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341820300800130130603551d25040c300a06082b06010505070302300d06092a864886f70d0101050500038181009ef238103cbbe445355f2784e348e4a61d740a7a2fbb39a176331bc745f0c3c96bb0f39a8a582d742765edfc32e1548d5d33a36a02bce52b3d0e0f4afed6418327a3b7fbf9e60455c4ad76492717b5504120e1369c20141c979b
        EAP-Message = 0x16a17b2e922d4f35fce56ae2119828f2fa53a4371cabae11f31e1864ab56c4934b580767ff9c0002903082028c308201f5a0030201020203008001300d06092a864886f70d01010505003043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341301e170d3130303632383230353034345a170d3132303231383230353034345a3046310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311830160603550403130f546573742049737375696e6720434130819f300d06
        EAP-Message = 0x092a864886f70d010101050003818d0030818902818100af2b2753c03e4a4b4a4cc484300d9c7f9b2f5c500ce3af01036eba55ba2e943ca1685a7f93413c5509a3b46658b561010bed73c11d85f8436040783ba03285917c5c5cde64e978758f53665588c0feb14d5c51f5d2ef864aff87d829660c19f6d638680c5c242c808866dc61eff9ecef058cd036d5162d84d5d2b69ca3b303870203010001a3818a308187300c0603551d13040530030101ff300b0603551d0f040403020186302a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e672e636f6d2f63726c301d0603551d0e0416041496c24ba1a2a1646c74
        EAP-Message = 0xe23852a2783042c7c1bde2301f0603551d23041830168014ca3a1f841d11917e92af5a133b829d1c19622225300d06092a864886f70d01010505000381810034907042242eb4977e8e97b9d2bbd5bb05535ea42c56f65ede6e85a48e8d1b60f89d832f1a892c56fd390c20dd3039cfeedb3590d7c3895faf89ab5b00464a33f522379707a4b44ed35b6c8c232ef8ec
        State = 0x93c976a090cd7bf74064bdd70ea2ce5a
        Message-Authenticator = 0x9fdf113724143a85a8dd88c18a71bb19
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 4 length 253
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
  TLS Length 2445
[tls] Received EAP-TLS First Fragment of the message
[tls] eaptls_verify returned 9
[tls] eaptls_process returned 13
++[eap] returns handled
} # server 802.1x
Sending Access-Challenge of id 4 to 127.0.0.1 port 41736
        EAP-Message = 0x010500060d00
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x93c976a097cc7bf74064bdd70ea2ce5a
Finished request 11.
Going to the next request
Waking up in 3.5 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 41736, id=5, length=1189
        User-Name = "revoked"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0205041d0d0012878eab669e0fb25cfc0b61b8df749e311710a61ea4881b33b71d0f4ae832eec77b45b01978e578e1620dcb0179cd340002933082028f308201f8a003020102020900a04aeb4bb318e1b9300d06092a864886f70d01010505003043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c616273311530130603550403130c5465737420526f6f74204341301e170d3130303632383230343130355a170d3132303632373230343130355a3043310f300d060355040a1306426f65696e6731193017060355040b1310496e746567726174696f6e204c61627331153013060355040313
        EAP-Message = 0x0c5465737420526f6f7420434130819f300d06092a864886f70d010101050003818d0030818902818100d3e745a362bf42e0e655c26ec00210ea0d08cdb89b7770cdb6f614b24bc44d132ba21d513ad35cd024f32d3742c62ac413603f5084a7e88c9399375f2063d07d2fa06dd0b2bd18c99da8c1b8208f762f68ec3e42c571a80eed00e8d7a04e09edd87cc62bfc231b391823cedca81dbab493babf896ee9ba35a6695ec640e2fef70203010001a3818a308187300c0603551d13040530030101ff300b0603551d0f040403020186302a0603551d1f04233021301fa01da01b8619687474703a2f2f7777772e626f65696e672e636f6d2f63726c30
        EAP-Message = 0x1d0603551d0e04160414ca3a1f841d11917e92af5a133b829d1c19622225301f0603551d23041830168014ca3a1f841d11917e92af5a133b829d1c19622225300d06092a864886f70d0101050500038181005ed06447c7aa67bc0b7a9a4c1b077c4c110cdd42b0902d3f9f6b44d919f7adc94c6f6cb988de1bf4fa8f6f63e852e176876520913ce4d258357b377b5344d335d1cf720e8e603a3bc031900650a0ae8cb08414d7ccff4d2586ef18b564f3f270036cf5fcec77fa71174ffa7a48da15708cd4f39c2f932b6364c716b150f536cf16030100861000008200807358dd170ee10d6ae05ef6268d9bcbddcaea4600807449c1fd34ccc0209581c3
        EAP-Message = 0x3c970de15d3183933176296ad5c12c08c86d006478bb7756125697ca4a657366e291867ba4c75d89ef8bc482be6fb168f2f15ead669e21e008a7d09fefef76dc5c7bb8c72e50a40b2f9e1d4cbfff97638818fcaee912881ee39914f7471a44bf16030100860f0000820080619ad4903355db107a056da0c4cc926dfb0e2c4b3d1c4493a769bd6fe106295dff843919d955edd22afb0b73015c7b7d6e8e782ba1c10fb0690659d76a84c7e8d1a9d51fdb00855d662e12b59d52d3b1353b2ce94add122dca8bd3de1e10468b7e9f97a17f6c56c8489df968a86392f496bc2028b3f6a68e7bbf1488176ee1fb1403010001011603010030b8cb62a16164bf
        EAP-Message = 0x18190bd8efa1c701add0b5bf12043b254b726c309b1819add1aac148c88372b442fee43eb26ceb668c
        State = 0x93c976a097cc7bf74064bdd70ea2ce5a
        Message-Authenticator = 0xde36629679b88d12fd0c9dc5ee83ef1c
server 802.1x {
# Executing section authorize from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authorize {...}
[eap] EAP packet type response id 5 length 253
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Packets.log
[auth_log]      expand: %t -> Mon Sep  6 21:32:59 2010
++[auth_log] returns ok
Found Auth-Type = EAP
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
[tls] eaptls_verify returned 7
[tls] Done initial handshake
[tls] <<< TLS 1.0 Handshake [length 0837], Certificate
[tls] chain-depth=2,
[tls] error=0
[tls] --> User-Name = revoked
[tls] --> BUF-Name = ?
[tls] --> subject =  ùeÊ_
[tls] --> issuer  = `W?ßÿ
[tls] --> verify return:1
[tls] chain-depth=1,
[tls] error=0
[tls] --> User-Name = revoked
[tls] --> BUF-Name = Test Issuing CA
[tls] --> subject = /O=Boeing/OU=Integration Labs/CN=Test Issuing CA
[tls] --> issuer  = /O=Boeing/OU=Integration Labs/CN=Test Root CA
[tls] --> verify return:1
[tls]   expand: valid.radius.client.boeing.com -> valid.radius.client.boeing.com
[tls] checking certificate CN (revoked.radius.client.boeing.com) with xlat'ed value (valid.radius.client.boeing.com)
rlm_eap_tls: Certificate CN (revoked.radius.client.boeing.com) does not match specified value (valid.radius.client.boeing.com)!
[tls] chain-depth=0,
[tls] error=0
[tls] --> User-Name = revoked
[tls] --> BUF-Name = revoked.radius.client.boeing.com
[tls] --> subject = /O=Boeing/OU=Integration Labs/CN=revoked.radius.client.boeing.com
[tls] --> issuer  = /O=Boeing/OU=Integration Labs/CN=Test Issuing CA
[tls] --> verify return:0
[tls] >>> TLS 1.0 Alert [length 0002], fatal certificate_unknown
TLS Alert write:fatal:certificate unknown
    TLS_accept: error in SSLv3 read client certificate B
rlm_eap: SSL error error:140890B2:SSL routines:SSL3_GET_CLIENT_CERTIFICATE:no certificate returned
SSL: SSL_read failed in a system call (-1), TLS session fails.
TLS receive handshake failed during operation
[tls] eaptls_process returned 4
[eap] Handler failed in EAP/tls
[eap] Failed in EAP select
++[eap] returns invalid
Failed to authenticate the user.
} # server 802.1x
Using Post-Auth-Type Reject
# Executing group from file /home/mross/Documents/FreeRadius/build/etc/raddb/sites-enabled/802.1x
+- entering group REJECT {...}
        expand: %{Module-Failure-Message} -> TLS Alert write:fatal:certificate unknown
        expand: %{TLS-Cert-Serial} ->
        expand: %{TLS-Cert-Expiration} ->
        expand: %{TLS-Cert-Issuer} ->
        expand: %{TLS-Cert-Subject} ->
        expand: %{TLS-Client-Cert-Serial} ->
        expand: %{TLS-Client-Cert-Expiration} ->
        expand: %{TLS-Client-Cert-Issuer} ->
        expand: %{TLS-Client-Cert-Subject} ->
++[reply] returns noop
[post_auth_log]         expand: /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Certs.log -> /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Certs.log
[post_auth_log] /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Certs.log expands to /home/mross/Documents/FreeRadius/build/var/log/radius/radacct/Certs.log
[post_auth_log]         expand: %t -> Mon Sep  6 21:32:59 2010
++[post_auth_log] returns ok
Delaying reject of request 12 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 12
Sending Access-Reject of id 5 to 127.0.0.1 port 41736
        EAP-Message = 0x04050004
        Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.5 seconds.

RE: Additional EAP-TLS Logging Option

Ross, Michael