New subject: EAP-TTLS session resumption does not work.

12 May 2014

      Thanks for your reply.
...
what client?
We are using Windows 7 OS,
and Odyssey Access Client as WiFi supplicant.
...
has the fast session resumption been enabled on on it?
Yes.
When we used another RADIUS server,
session resumption worked well.
...
- FreeRadius version.
3.0.1 old (very!) and some bugs. please upgrade.
Sure.
I have upgraded FreeRadius,
but still the same issue occurs.

- This is Debug output. (radius -X)

Tue May 13 08:18:55 2014 : Info: radiusd: FreeRADIUS Version 3.0.2, for host i686-pc-linux-gnu, built on May 13 2014 at 08:05:52
Tue May 13 08:18:55 2014 : Debug: Server was built with:
Tue May 13 08:18:55 2014 : Debug:   accounting
Tue May 13 08:18:55 2014 : Debug:   authentication
Tue May 13 08:18:55 2014 : Debug:   ascend binary attributes
Tue May 13 08:18:55 2014 : Debug:   coa
Tue May 13 08:18:55 2014 : Debug:   control-socket
Tue May 13 08:18:55 2014 : Debug:   detail
Tue May 13 08:18:55 2014 : Debug:   dhcp
Tue May 13 08:18:55 2014 : Debug:   dynamic clients
Tue May 13 08:18:55 2014 : Debug:   proxy
Tue May 13 08:18:55 2014 : Debug:   regex-posix
Tue May 13 08:18:55 2014 : Debug:   session-management
Tue May 13 08:18:55 2014 : Debug:   stats
Tue May 13 08:18:55 2014 : Debug:   tcp
Tue May 13 08:18:55 2014 : Debug:   threads
Tue May 13 08:18:55 2014 : Debug:   tls
Tue May 13 08:18:55 2014 : Debug:   unlang
Tue May 13 08:18:55 2014 : Debug:   vmps
Tue May 13 08:18:55 2014 : Debug: Server core libs:
Tue May 13 08:18:55 2014 : Debug:   talloc : 2.0.*
Tue May 13 08:18:55 2014 : Debug:   ssl    : OpenSSL 1.0.1g 7 Apr 2014
Tue May 13 08:18:55 2014 : Debug: Library magic number:
Tue May 13 08:18:55 2014 : Debug:   0xf403000200000000
Tue May 13 08:18:55 2014 : Debug: Endianess:
Tue May 13 08:18:55 2014 : Debug:   little
[1mTue May 13 08:18:55 2014 : Info: Copyright (C) 1999-2014 The FreeRADIUS server project and contributors[0m
[1mTue May 13 08:18:55 2014 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A[0m
[1mTue May 13 08:18:55 2014 : Info: PARTICULAR PURPOSE[0m
[1mTue May 13 08:18:55 2014 : Info: You may redistribute copies of FreeRADIUS under the terms of the[0m
[1mTue May 13 08:18:55 2014 : Info: GNU General Public License[0m
[1mTue May 13 08:18:55 2014 : Info: For more information about these matters, see the file named COPYRIGHT[0m
[1mTue May 13 08:18:55 2014 : Info: Starting - reading configuration files ...[0m
Tue May 13 08:18:55 2014 : Debug: including dictionary file /usr/local/freeradius-3.0.2/share/freeradius/dictionary
Tue May 13 08:18:55 2014 : Debug: including dictionary file /usr/local/freeradius-3.0.2/etc/raddb/dictionary
Tue May 13 08:18:55 2014 : Debug: including configuration file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:18:55 2014 : Debug: main {
Tue May 13 08:18:55 2014 : Debug:  security {
Tue May 13 08:18:55 2014 : Debug:       allow_core_dumps = no
Tue May 13 08:18:55 2014 : Debug:  }
Tue May 13 08:18:55 2014 : Debug: }
Tue May 13 08:18:55 2014 : Debug: main {
Tue May 13 08:18:55 2014 : Debug:       name = "freeradius"
Tue May 13 08:18:55 2014 : Debug:       prefix = "/usr/local"
Tue May 13 08:18:55 2014 : Debug:       localstatedir = "/usr/local/var"
Tue May 13 08:18:55 2014 : Debug:       sbindir = "/usr/local/sbin"
Tue May 13 08:18:55 2014 : Debug:       logdir = "/usr/local/var/log"
Tue May 13 08:18:55 2014 : Debug:       run_dir = "/usr/local/var/run/freeradius"
Tue May 13 08:18:55 2014 : Debug:       libdir = "/usr/local/lib"
Tue May 13 08:18:55 2014 : Debug:       radacctdir = "/usr/local/var/log/radacct"
Tue May 13 08:18:55 2014 : Debug:       hostname_lookups = no
Tue May 13 08:18:55 2014 : Debug:       max_request_time = 30
Tue May 13 08:18:55 2014 : Debug:       cleanup_delay = 5
Tue May 13 08:18:55 2014 : Debug:       max_requests = 256
Tue May 13 08:18:55 2014 : Debug:       pidfile = "/var/run/radius/freeradius.pid"
Tue May 13 08:18:55 2014 : Debug:       checkrad = "/usr/local/sbin/checkrad"
Tue May 13 08:18:55 2014 : Debug:       debug_level = 0
Tue May 13 08:18:55 2014 : Debug:       proxy_requests = yes
Tue May 13 08:18:55 2014 : Debug:  log {
Tue May 13 08:18:55 2014 : Debug:       stripped_names = no
Tue May 13 08:18:55 2014 : Debug:       auth = no
Tue May 13 08:18:55 2014 : Debug:       auth_badpass = no
Tue May 13 08:18:55 2014 : Debug:       auth_goodpass = no
Tue May 13 08:18:55 2014 : Debug:       msg_denied = "You are already logged in - access denied"
Tue May 13 08:18:55 2014 : Debug:  }
Tue May 13 08:18:55 2014 : Debug:  security {
Tue May 13 08:18:55 2014 : Debug:       max_attributes = 0
Tue May 13 08:18:55 2014 : Debug:       reject_delay = 0
Tue May 13 08:18:55 2014 : Debug:       status_server = no
Tue May 13 08:18:55 2014 : Debug:  }
Tue May 13 08:18:55 2014 : Debug: }
Tue May 13 08:18:55 2014 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue May 13 08:18:55 2014 : Debug:  realm tinyradius {
Tue May 13 08:18:55 2014 : Debug:       authhost = 127.0.0.1:18160
Tue May 13 08:18:55 2014 : Debug:       secret = RadiusStubSecret
Tue May 13 08:18:55 2014 : Debug:  }
Tue May 13 08:18:55 2014 : Debug: radiusd: #### Loading Clients ####
Tue May 13 08:18:55 2014 : Debug:  client 10.0.0.0/8 {
Tue May 13 08:18:55 2014 : Debug:       require_message_authenticator = no
Tue May 13 08:18:55 2014 : Debug:       secret = "xxxx"
Tue May 13 08:18:55 2014 : Debug:   limit {
Tue May 13 08:18:55 2014 : Debug:       max_connections = 16
Tue May 13 08:18:55 2014 : Debug:       lifetime = 0
Tue May 13 08:18:55 2014 : Debug:       idle_timeout = 30
Tue May 13 08:18:55 2014 : Debug:   }
Tue May 13 08:18:55 2014 : Debug:  }
Tue May 13 08:18:55 2014 : No 'ipaddr' or 'ipv6addr' field found in client 10.0.0.0/8.  Please fix your configuration
Tue May 13 08:18:55 2014 : Support for old-style clients will be removed in a future release
Tue May 13 08:18:55 2014 : Debug: radiusd: #### Instantiating modules ####
Tue May 13 08:18:55 2014 : Debug: Library not found at path "/usr/local/lib/rlm_eap.so"
Tue May 13 08:18:55 2014 : Debug:     (Loaded rlm_eap, checking if it's valid)
Tue May 13 08:18:55 2014 : Debug:   # Loaded module rlm_eap
Tue May 13 08:18:55 2014 : Debug:   # Instantiating module "eap" from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:18:55 2014 : Debug:   eap {
Tue May 13 08:18:55 2014 : Debug:       default_eap_type = "ttls"
Tue May 13 08:18:55 2014 : Debug:       timer_expire = 60
Tue May 13 08:18:55 2014 : Debug:       ignore_unknown_eap_types = no
Tue May 13 08:18:55 2014 : Debug:       mod_accounting_username_bug = no
Tue May 13 08:18:55 2014 : Debug:       max_sessions = 2048
Tue May 13 08:18:55 2014 : Debug:   }
Tue May 13 08:18:55 2014 : Debug: Library not found at path "/usr/local/lib/rlm_eap_ttls.so"
Tue May 13 08:18:55 2014 : Debug:    # Linked to sub-module rlm_eap_ttls
Tue May 13 08:18:55 2014 : Debug:    ttls {
Tue May 13 08:18:55 2014 : Debug:       tls = "tls-common"
Tue May 13 08:18:55 2014 : Debug:       default_eap_type = "md5"
Tue May 13 08:18:55 2014 : Debug:       copy_request_to_tunnel = no
Tue May 13 08:18:55 2014 : Debug:       use_tunneled_reply = no
Tue May 13 08:18:55 2014 : Debug:       virtual_server = "inner-tunnel"
Tue May 13 08:18:55 2014 : Debug:       include_length = yes
Tue May 13 08:18:55 2014 : Debug:       require_client_cert = no
Tue May 13 08:18:55 2014 : Debug:    }
Tue May 13 08:18:55 2014 : Debug:    tls-config tls-common {
Tue May 13 08:18:55 2014 : Debug:       rsa_key_exchange = no
Tue May 13 08:18:55 2014 : Debug:       dh_key_exchange = yes
Tue May 13 08:18:55 2014 : Debug:       rsa_key_length = 512
Tue May 13 08:18:55 2014 : Debug:       dh_key_length = 512
Tue May 13 08:18:55 2014 : Debug:       verify_depth = 0
Tue May 13 08:18:55 2014 : Debug:       pem_file_type = yes
Tue May 13 08:18:55 2014 : Debug:       private_key_file = "/usr/local/freeradius-3.0.2/etc/raddb/certs/top-otprad51v.key"
Tue May 13 08:18:55 2014 : Debug:       certificate_file = "/usr/local/freeradius-3.0.2/etc/raddb/certs/top-otprad51v.crt"
Tue May 13 08:18:55 2014 : Debug:       dh_file = "/usr/local/freeradius-3.0.2/etc/raddb/certs/dh"
Tue May 13 08:18:55 2014 : Debug:       fragment_size = 1024
Tue May 13 08:18:55 2014 : Debug:       include_length = yes
Tue May 13 08:18:55 2014 : Debug:       check_crl = no
Tue May 13 08:18:55 2014 : Debug:       ecdh_curve = "prime256v1"
Tue May 13 08:18:55 2014 : Debug:     cache {
Tue May 13 08:18:55 2014 : Debug:       enable = no
Tue May 13 08:18:55 2014 : Debug:       lifetime = 24
Tue May 13 08:18:55 2014 : Debug:       max_entries = 255
Tue May 13 08:18:55 2014 : Debug:     }
Tue May 13 08:18:55 2014 : Debug:     verify {
Tue May 13 08:18:55 2014 : Debug:     }
Tue May 13 08:18:55 2014 : Debug:     ocsp {
Tue May 13 08:18:55 2014 : Debug:       enable = no
Tue May 13 08:18:55 2014 : Debug:       override_cert_url = no
Tue May 13 08:18:55 2014 : Debug:       use_nonce = yes
Tue May 13 08:18:55 2014 : Debug:       timeout = 0
Tue May 13 08:18:55 2014 : Debug:       softfail = yes
Tue May 13 08:18:55 2014 : Debug:     }
Tue May 13 08:18:55 2014 : Debug:    }
Tue May 13 08:18:55 2014 : Debug: radiusd: #### Loading Virtual Servers ####
Tue May 13 08:18:55 2014 : Debug: server { # from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:18:55 2014 : Debug: # Loading authenticate {...}
Tue May 13 08:18:55 2014 : Debug: # Loading authorize {...}
Tue May 13 08:18:55 2014 : Debug: # Loading post-proxy {...}
Tue May 13 08:18:55 2014 : Debug: } # server
Tue May 13 08:18:55 2014 : Debug: server inner-tunnel { # from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:18:55 2014 : Debug:  # Loading authenticate {...}
Tue May 13 08:18:55 2014 : Debug:  # Loading authorize {...}
Tue May 13 08:18:55 2014 : Debug: } # server inner-tunnel
Tue May 13 08:18:55 2014 : Debug: radiusd: #### Opening IP addresses and Ports ####
Tue May 13 08:18:55 2014 : Debug: Library not found at path "/usr/local/lib/proto_auth.so"
Tue May 13 08:18:55 2014 : Debug: listen {
Tue May 13 08:18:55 2014 : Debug:       type = "auth"
Tue May 13 08:18:55 2014 : Debug:       ipaddr = 10.33.22.38
Tue May 13 08:18:55 2014 : Debug:       port = 18120
Tue May 13 08:18:55 2014 : Debug: }
Tue May 13 08:18:55 2014 : Debug: Listening on auth address 10.33.22.38 port 18120
Tue May 13 08:18:55 2014 : Debug: Opening new proxy socket 'proxy address * port 0'
Tue May 13 08:18:55 2014 : Debug: Listening on proxy address * port 59886
Tue May 13 08:18:55 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=127, length=183
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0201000e01616e6f6e796d6f7573
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0x77b49a94be0b834482bc4f3f6b2a6318
Tue May 13 08:19:06 2014 : Debug: (0) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (0)   authorize {
Tue May 13 08:19:06 2014 : Debug: (0)   modsingle[authorize]: calling eap (rlm_eap) for request 0
Tue May 13 08:19:06 2014 : Debug: (0) eap : EAP packet type response id 1 length 14
Tue May 13 08:19:06 2014 : Debug: (0) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Tue May 13 08:19:06 2014 : Debug: (0)   modsingle[authorize]: returned from eap (rlm_eap) for request 0
Tue May 13 08:19:06 2014 : Debug: (0)   [eap] = ok
Tue May 13 08:19:06 2014 : Debug: (0)  } #  authorize = ok
Tue May 13 08:19:06 2014 : Debug: (0) Found Auth-Type = EAP
Tue May 13 08:19:06 2014 : Debug: (0) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (0)   authenticate {
Tue May 13 08:19:06 2014 : Debug: (0)   modsingle[authenticate]: calling eap (rlm_eap) for request 0
Tue May 13 08:19:06 2014 : Debug: (0) eap : Peer sent Identity (1)
Tue May 13 08:19:06 2014 : Debug: (0) eap : Calling eap_ttls to process EAP data
Tue May 13 08:19:06 2014 : Debug: (0) eap_ttls : Initiate
Tue May 13 08:19:06 2014 : Debug: (0) eap_ttls : Start returned 1
Tue May 13 08:19:06 2014 : Debug: (0) eap : New EAP session, adding 'State' attribute to reply 0x2cd644782cd4515e
Tue May 13 08:19:06 2014 : Debug: (0)   modsingle[authenticate]: returned from eap (rlm_eap) for request 0
Tue May 13 08:19:06 2014 : Debug: (0)   [eap] = handled
Tue May 13 08:19:06 2014 : Debug: (0)  } #  authenticate = handled
Sending Access-Challenge of id 127 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x010200061520
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2cd644782cd4515e847c9f571e31e758
Tue May 13 08:19:06 2014 : Debug: (0) Finished request 0.
Tue May 13 08:19:06 2014 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=128, length=287
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0202006415800000005a16030100550100005103015371594c6441cee10cb8a9591fb6ba96826659757079944c40739c8dde4eadee00002a00160013006600150012000a0005000400070009006300650060006200610064001400110003000600080100
        State = 0x2cd644782cd4515e847c9f571e31e758
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0x23e52ac2f5dae92ebc9f7a29283cc634
Tue May 13 08:19:06 2014 : Debug: (1) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (1)   authorize {
Tue May 13 08:19:06 2014 : Debug: (1)   modsingle[authorize]: calling eap (rlm_eap) for request 1
Tue May 13 08:19:06 2014 : Debug: (1) eap : EAP packet type response id 2 length 100
Tue May 13 08:19:06 2014 : Debug: (1) eap : Continuing tunnel setup.
Tue May 13 08:19:06 2014 : Debug: (1)   modsingle[authorize]: returned from eap (rlm_eap) for request 1
Tue May 13 08:19:06 2014 : Debug: (1)   [eap] = ok
Tue May 13 08:19:06 2014 : Debug: (1)  } #  authorize = ok
Tue May 13 08:19:06 2014 : Debug: (1) Found Auth-Type = EAP
Tue May 13 08:19:06 2014 : Debug: (1) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (1)   authenticate {
Tue May 13 08:19:06 2014 : Debug: (1)   modsingle[authenticate]: calling eap (rlm_eap) for request 1
Tue May 13 08:19:06 2014 : Debug: (1) eap : Expiring EAP session with state 0x2cd644782cd4515e
Tue May 13 08:19:06 2014 : Debug: (1) eap : Finished EAP session with state 0x2cd644782cd4515e
Tue May 13 08:19:06 2014 : Debug: (1) eap : Previous EAP request found for state 0x2cd644782cd4515e, released from the list
Tue May 13 08:19:06 2014 : Debug: (1) eap : Peer sent TTLS (21)
Tue May 13 08:19:06 2014 : Debug: (1) eap : EAP TTLS (21)
Tue May 13 08:19:06 2014 : Debug: (1) eap : Calling eap_ttls to process EAP data
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : Authenticate
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : processing EAP-TLS
Tue May 13 08:19:06 2014 : Debug:   TLS Length 90
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : Length Included
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : eaptls_verify returned 11
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     (other): before/accept initialization
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: before/accept initialization
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : <<< TLS 1.0 Handshake [length 0055], ClientHello
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 read client hello A
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : >>> TLS 1.0 Handshake [length 002a], ServerHello
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 write server hello A
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : >>> TLS 1.0 Handshake [length 03cc], Certificate
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 write certificate A
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 write key exchange A
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 write server done A
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: SSLv3 flush data
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls :     TLS_accept: Need to read more data: SSLv3 read client certificate A
Tue May 13 08:19:06 2014 : Debug: In SSL Handshake Phase
Tue May 13 08:19:06 2014 : Debug: In SSL Accept mode
Tue May 13 08:19:06 2014 : Debug: (1) eap_ttls : eaptls_process returned 13
Tue May 13 08:19:06 2014 : Debug: (1) eap : New EAP session, adding 'State' attribute to reply 0x2cd644782dd5515e
Tue May 13 08:19:06 2014 : Debug: (1)   modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Tue May 13 08:19:06 2014 : Debug: (1)   [eap] = handled
Tue May 13 08:19:06 2014 : Debug: (1)  } #  authenticate = handled
Sending Access-Challenge of id 128 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0103040015c00000061b160301002a020000260301aa3dfd948faf57718d7192f4e959c459bd08c6ed1334c18b9a64b2262e5652410000160016030103cc0b0003c80003c50003c2308203be308202a6020900d8e196b535b385dc300d06092a864886f70d01010505003081a0310b3009060355040613024a50310e300c06035504080c05546f6b796f310e300c06035504070c054368756f753110300e060355040a0c074e545444415441310c300a060355040b0c0349544d3128302606035504030c1f746f702d6f74707261643531762e6d6e672e6e7474646174612e636f2e6a703127302506092a864886f70d0109011618706f73746d6173746572406e7474646174612e636f2e6a70301e170d3134303431393131343534365a170d3135303431393131343534365a3081a0310b3009060355040613024a50310e300c06035504080c05546f6b796f310e300c06035504070c054368756f753110300e060355040a0c074e545444415441310c300a060355040b0c0349544d3128302606035504030c1f746f702d6f74707261643531762e6d6e672e6e7474646174612e636f2e6a703127302506092a864886f70d0109011618706f73746d6173746572406e7474646174612e636f2e6a7030820122300d06092a864886f70d01010105000382010f003082010a0282010100cbd1213f741
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2cd644782dd5515e847c9f571e31e758
Tue May 13 08:19:06 2014 : Debug: (1) Finished request 1.
Tue May 13 08:19:06 2014 : Debug: Waking up in 0.2 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=129, length=193
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020300061500
        State = 0x2cd644782dd5515e847c9f571e31e758
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xf0c302d7d3a5ad8337a272b4c6e639d1
Tue May 13 08:19:06 2014 : Debug: (2) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (2)   authorize {
Tue May 13 08:19:06 2014 : Debug: (2)   modsingle[authorize]: calling eap (rlm_eap) for request 2
Tue May 13 08:19:06 2014 : Debug: (2) eap : EAP packet type response id 3 length 6
Tue May 13 08:19:06 2014 : Debug: (2) eap : Continuing tunnel setup.
Tue May 13 08:19:06 2014 : Debug: (2)   modsingle[authorize]: returned from eap (rlm_eap) for request 2
Tue May 13 08:19:06 2014 : Debug: (2)   [eap] = ok
Tue May 13 08:19:06 2014 : Debug: (2)  } #  authorize = ok
Tue May 13 08:19:06 2014 : Debug: (2) Found Auth-Type = EAP
Tue May 13 08:19:06 2014 : Debug: (2) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:06 2014 : Debug: (2)   authenticate {
Tue May 13 08:19:06 2014 : Debug: (2)   modsingle[authenticate]: calling eap (rlm_eap) for request 2
Tue May 13 08:19:06 2014 : Debug: (2) eap : Expiring EAP session with state 0x2cd644782dd5515e
Tue May 13 08:19:06 2014 : Debug: (2) eap : Finished EAP session with state 0x2cd644782dd5515e
Tue May 13 08:19:06 2014 : Debug: (2) eap : Previous EAP request found for state 0x2cd644782dd5515e, released from the list
Tue May 13 08:19:06 2014 : Debug: (2) eap : Peer sent TTLS (21)
Tue May 13 08:19:06 2014 : Debug: (2) eap : EAP TTLS (21)
Tue May 13 08:19:06 2014 : Debug: (2) eap : Calling eap_ttls to process EAP data
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : Authenticate
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : processing EAP-TLS
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : Received TLS ACK
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : Received TLS ACK
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : ACK handshake fragment handler
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : eaptls_verify returned 1
Tue May 13 08:19:06 2014 : Debug: (2) eap_ttls : eaptls_process returned 13
Tue May 13 08:19:06 2014 : Debug: (2) eap : New EAP session, adding 'State' attribute to reply 0x2cd644782ed2515e
Tue May 13 08:19:06 2014 : Debug: (2)   modsingle[authenticate]: returned from eap (rlm_eap) for request 2
Tue May 13 08:19:06 2014 : Debug: (2)   [eap] = handled
Tue May 13 08:19:06 2014 : Debug: (2)  } #  authenticate = handled
Sending Access-Challenge of id 129 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0104022f15800000061b1656ba74fcd8aabc61ca160301020d0c0002090080f9ff408fde4339b038b6d70ffa17ddc5efd2b8a760df3f5f914e5547417d84139c0bdf7692016aba5f138e0f574a062f54f8c3c93a13a9268320eb5ea1cdb6295a102a424aa2bc0a7c058c1ec7466c81acaa48424f451b2ff0a85c87cff71735a1b337edcc5c911b4290f67be096967d7361bd217b976f2c692ef4ce1a7d26630001020080792424f5fbdb401a5956c8f425f9ae995964791cb8815a595ef9cc19ab72dfe326f814b2c9f8022f8ce13f2cdeb0909a838323ded83402f782c317acfac87dc9aa657b485820656d44a48387944c2143bab572e6719834cee607fa76f664884db3b166f1adb732c2f802bc281665352847b3f5ce2069c20c8e7bb704128bdbfc01004a596ce2100aa79acdce35e407c67eb23b03829b46ba6f250c22cec2a780e3ea9b89cfeb2420bbb1f00bcdd047761bbf0e9cf25003854dc940ffc57958ddb7790f40a0c923e5e99f8661485223fdd6e27689142d2fc0a8cf75a8593fab2bb68fa677886d250d024d480de9c8ed32aaf88625c90f6ae7df4af94226a849ead00f8baf71fbb3e111730b51ede2b09100a7875595038dc653bd869139f7d319af9bed1cc4abd2a8c1eb5c69e41c8d0580019c6a8f79eda4687cbb62b4b61446d820c081e622d92ae732c8b15938db87e38c3
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2cd644782ed2515e847c9f571e31e758
Tue May 13 08:19:06 2014 : Debug: (2) Finished request 2.
Tue May 13 08:19:06 2014 : Debug: Waking up in 0.2 seconds.
Tue May 13 08:19:07 2014 : Debug: Waking up in 4.6 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=130, length=387
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020400c81580000000be1603010086100000820080e7d6e05c9453f0d49eed693b8210d016c81ebaf411552e2900bf3c30ceb9a37a8efdd287fbe13a7813331a96aeabfdb91641bea7fdbd0376e793ce362583f32c433eb4fc7d5def3115978577290d696369433b8233d292fc7ef16224ef677faa94d97df9514fdf49412c1b738a23abda5b341990691d4e6e4b2d4fa82be885431403010001011603010028fa7268d3dafede71b23977c9bfb546992ce43458cc84be9a1f6fea0d3c4ae45479186f466f1cc4f0
        State = 0x2cd644782ed2515e847c9f571e31e758
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xb873cbd0150fda519ebe0f34381c99a1
Tue May 13 08:19:07 2014 : Debug: (3) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:07 2014 : Debug: (3)   authorize {
Tue May 13 08:19:07 2014 : Debug: (3)   modsingle[authorize]: calling eap (rlm_eap) for request 3
Tue May 13 08:19:07 2014 : Debug: (3) eap : EAP packet type response id 4 length 200
Tue May 13 08:19:07 2014 : Debug: (3) eap : Continuing tunnel setup.
Tue May 13 08:19:07 2014 : Debug: (3)   modsingle[authorize]: returned from eap (rlm_eap) for request 3
Tue May 13 08:19:07 2014 : Debug: (3)   [eap] = ok
Tue May 13 08:19:07 2014 : Debug: (3)  } #  authorize = ok
Tue May 13 08:19:07 2014 : Debug: (3) Found Auth-Type = EAP
Tue May 13 08:19:07 2014 : Debug: (3) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:07 2014 : Debug: (3)   authenticate {
Tue May 13 08:19:07 2014 : Debug: (3)   modsingle[authenticate]: calling eap (rlm_eap) for request 3
Tue May 13 08:19:07 2014 : Debug: (3) eap : Expiring EAP session with state 0x2cd644782ed2515e
Tue May 13 08:19:07 2014 : Debug: (3) eap : Finished EAP session with state 0x2cd644782ed2515e
Tue May 13 08:19:07 2014 : Debug: (3) eap : Previous EAP request found for state 0x2cd644782ed2515e, released from the list
Tue May 13 08:19:07 2014 : Debug: (3) eap : Peer sent TTLS (21)
Tue May 13 08:19:07 2014 : Debug: (3) eap : EAP TTLS (21)
Tue May 13 08:19:07 2014 : Debug: (3) eap : Calling eap_ttls to process EAP data
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : Authenticate
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : processing EAP-TLS
Tue May 13 08:19:07 2014 : Debug:   TLS Length 190
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : Length Included
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : eaptls_verify returned 11
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     TLS_accept: SSLv3 read client key exchange A
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : <<< TLS 1.0 ChangeCipherSpec [length 0001]
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : <<< TLS 1.0 Handshake [length 0010], Finished
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     TLS_accept: SSLv3 read finished A
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : >>> TLS 1.0 ChangeCipherSpec [length 0001]
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     TLS_accept: SSLv3 write change cipher spec A
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : >>> TLS 1.0 Handshake [length 0010], Finished
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     TLS_accept: SSLv3 write finished A
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     TLS_accept: SSLv3 flush data
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls :     (other): SSL negotiation finished successfully
Tue May 13 08:19:07 2014 : Debug: SSL Connection Established
Tue May 13 08:19:07 2014 : Debug: (3) eap_ttls : eaptls_process returned 13
Tue May 13 08:19:07 2014 : Debug: (3) eap : New EAP session, adding 'State' attribute to reply 0x2cd644782fd3515e
Tue May 13 08:19:07 2014 : Debug: (3)   modsingle[authenticate]: returned from eap (rlm_eap) for request 3
Tue May 13 08:19:07 2014 : Debug: (3)   [eap] = handled
Tue May 13 08:19:07 2014 : Debug: (3)  } #  authenticate = handled
Sending Access-Challenge of id 130 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0105003d158000000033140301000101160301002832bfa862496539232f5a2e1b5a90d1eeca3d670447c8b35865ea7911bb87e467101508eddad1e3a4
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2cd644782fd3515e847c9f571e31e758
Tue May 13 08:19:07 2014 : Debug: (3) Finished request 3.
Tue May 13 08:19:07 2014 : Debug: Waking up in 0.3 seconds.
Tue May 13 08:19:07 2014 : Debug: Waking up in 4.2 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=131, length=258
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0205004715800000003d1703010038dfa6411ddcb262e8133833ae94a13c2ab8de58f66d96dcb90af6e8a19a6f5f8b11edd4d6248915f7e0b6ca5abd7c1a5f9ee032442105ca3e
        State = 0x2cd644782fd3515e847c9f571e31e758
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xc8c0511d5f1bbbb0406e5fad8b40a443
Tue May 13 08:19:08 2014 : Debug: (4) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:08 2014 : Debug: (4)   authorize {
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[authorize]: calling eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4) eap : EAP packet type response id 5 length 71
Tue May 13 08:19:08 2014 : Debug: (4) eap : Continuing tunnel setup.
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[authorize]: returned from eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4)   [eap] = ok
Tue May 13 08:19:08 2014 : Debug: (4)  } #  authorize = ok
Tue May 13 08:19:08 2014 : Debug: (4) Found Auth-Type = EAP
Tue May 13 08:19:08 2014 : Debug: (4) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:08 2014 : Debug: (4)   authenticate {
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[authenticate]: calling eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4) eap : Expiring EAP session with state 0x2cd644782fd3515e
Tue May 13 08:19:08 2014 : Debug: (4) eap : Finished EAP session with state 0x2cd644782fd3515e
Tue May 13 08:19:08 2014 : Debug: (4) eap : Previous EAP request found for state 0x2cd644782fd3515e, released from the list
Tue May 13 08:19:08 2014 : Debug: (4) eap : Peer sent TTLS (21)
Tue May 13 08:19:08 2014 : Debug: (4) eap : EAP TTLS (21)
Tue May 13 08:19:08 2014 : Debug: (4) eap : Calling eap_ttls to process EAP data
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Authenticate
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : processing EAP-TLS
Tue May 13 08:19:08 2014 : Debug:   TLS Length 61
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Length Included
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : eaptls_verify returned 11
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : eaptls_process returned 7
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Session established.  Proceeding to decode tunneled attributes.
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Got tunneled request
        User-Name = '1234567'
        User-Password = '1'
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Sending tunneled request
        User-Name = '1234567'
        User-Password = '1'
server inner-tunnel {
Tue May 13 08:19:08 2014 : Debug: (4) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:08 2014 : Debug: (4)   authorize {
Tue May 13 08:19:08 2014 : Debug: (4)   update control {
Tue May 13 08:19:08 2014 : Debug: (4)   Proxy-To-Realm := 'tinyradius'
Tue May 13 08:19:08 2014 : Debug: (4) ::: FROM 1 TO 0 MAX 1
Tue May 13 08:19:08 2014 : Debug: (4) ::: Examining Proxy-To-Realm
Tue May 13 08:19:08 2014 : Debug: (4) ::: APPENDING Proxy-To-Realm FROM 0 TO 0
Tue May 13 08:19:08 2014 : Debug: (4) ::: TO in 0 out 1
Tue May 13 08:19:08 2014 : Debug: (4) ::: to[0] = Proxy-To-Realm
Tue May 13 08:19:08 2014 : Debug: (4)   } # update control = noop
Tue May 13 08:19:08 2014 : Debug: (4)  } #  authorize = noop
} # server inner-tunnel
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Got tunneled reply code 0
Tue May 13 08:19:08 2014 : Debug: (4) eap_ttls : Tunneled authentication will be proxied to tinyradius
Tue May 13 08:19:08 2014 : Debug: (4) eap :   Tunneled session will be proxied.  Not doing EAP.
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[authenticate]: returned from eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4)   [eap] = handled
Tue May 13 08:19:08 2014 : Debug: (4)  } #  authenticate = handled
Tue May 13 08:19:08 2014 : Debug: (4) Empty pre-proxy section.  Using default return values.
Tue May 13 08:19:08 2014 : Debug: (4) proxy: Trying to allocate ID (0/2)
Tue May 13 08:19:08 2014 : Debug: (4) proxy: request is now in proxy hash
Tue May 13 08:19:08 2014 : Debug: (4)  proxy: allocating destination 127.0.0.1 port 18160 - Id 112
Tue May 13 08:19:08 2014 : Debug: (4) Proxying request to home server 127.0.0.1 port 18160
Sending Access-Request of id 112 from 0.0.0.0 port 59886 to 127.0.0.1 port 18160
        User-Name = '1234567'
        User-Password = '1'
        Message-Authenticator := 0x00
        Proxy-State = 0x313331
Tue May 13 08:19:08 2014 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Accept packet from host 127.0.0.1 port 18160, id=112, length=20
Tue May 13 08:19:08 2014 : Debug: (4) proxy: request is no longer in proxy hash
Tue May 13 08:19:08 2014 : Debug: (4) # Executing section post-proxy from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:19:08 2014 : Debug: (4)   post-proxy {
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[post-proxy]: calling eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4) eap : Doing post-proxy callback
Tue May 13 08:19:08 2014 : Debug: (4) eap : Passing reply from proxy back into the tunnel.
server inner-tunnel {
Tue May 13 08:19:08 2014 : Debug: (4) Empty post-auth section.  Using default return values.
Tue May 13 08:19:08 2014 : Debug: (4) eap : post-auth returns 2
} # server inner-tunnel
Tue May 13 08:19:08 2014 : Debug: (4) eap : Final reply from tunneled session code 2
Tue May 13 08:19:08 2014 : Debug: (4) eap : Got reply 2
Tue May 13 08:19:08 2014 : Debug: (4) eap : Got tunneled Access-Accept
Tue May 13 08:19:08 2014 : Debug: (4) eap : Reply was OK
Tue May 13 08:19:08 2014 : Debug: (4) eap : Freeing handler
Tue May 13 08:19:08 2014 : Debug: (4)   modsingle[post-proxy]: returned from eap (rlm_eap) for request 4
Tue May 13 08:19:08 2014 : Debug: (4)   [eap] = ok
Tue May 13 08:19:08 2014 : Debug: (4)  } #  post-proxy = ok
Tue May 13 08:19:08 2014 : Debug: (4) Found Auth-Type = EAP
Tue May 13 08:19:08 2014 : Debug: (4) Found Auth-Type = Accept
Tue May 13 08:19:08 2014 : ERROR: (4) Warning:  Found 2 auth-types on request for user 'anonymous'
Tue May 13 08:19:08 2014 : Debug: (4) Auth-Type = Accept, accepting the user
Tue May 13 08:19:08 2014 : Debug: (4) Empty post-auth section.  Using default return values.
Sending Access-Accept of id 131 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        MS-MPPE-Recv-Key = 0xb37c7d62c03477a95524bf59a303c37d036807d8303c5769e47e9f82dac31f45
        MS-MPPE-Send-Key = 0x9c4f772273279ecde8e70c52b2b68d7800fe8cba4d876500f32e793fd82b0c60
        EAP-Message = 0x03050004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = 'anonymous'
Tue May 13 08:19:08 2014 : Debug: (4) Finished request 4.
Tue May 13 08:19:08 2014 : Debug: Waking up in 0.3 seconds.
Tue May 13 08:19:09 2014 : Debug: Waking up in 2.4 seconds.
Tue May 13 08:19:11 2014 : Debug: (0) Cleaning up request packet ID 127 with timestamp +11
Tue May 13 08:19:11 2014 : Debug: (1) Cleaning up request packet ID 128 with timestamp +11
Tue May 13 08:19:11 2014 : Debug: (2) Cleaning up request packet ID 129 with timestamp +11
Tue May 13 08:19:11 2014 : Debug: Waking up in 0.3 seconds.
Tue May 13 08:19:12 2014 : Debug: (3) Cleaning up request packet ID 130 with timestamp +12
Tue May 13 08:19:12 2014 : Debug: Waking up in 1.8 seconds.
Tue May 13 08:19:13 2014 : Debug: (4) Cleaning up request packet ID 131 with timestamp +13
Tue May 13 08:19:13 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=132, length=183
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0201000e01616e6f6e796d6f7573
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0x7bdef0f84856d05189a5b5d4b7915a01
Tue May 13 08:20:33 2014 : Debug: (5) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (5)   authorize {
Tue May 13 08:20:33 2014 : Debug: (5)   modsingle[authorize]: calling eap (rlm_eap) for request 5
Tue May 13 08:20:33 2014 : Debug: (5) eap : EAP packet type response id 1 length 14
Tue May 13 08:20:33 2014 : Debug: (5) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Tue May 13 08:20:33 2014 : Debug: (5)   modsingle[authorize]: returned from eap (rlm_eap) for request 5
Tue May 13 08:20:33 2014 : Debug: (5)   [eap] = ok
Tue May 13 08:20:33 2014 : Debug: (5)  } #  authorize = ok
Tue May 13 08:20:33 2014 : Debug: (5) Found Auth-Type = EAP
Tue May 13 08:20:33 2014 : Debug: (5) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (5)   authenticate {
Tue May 13 08:20:33 2014 : Debug: (5)   modsingle[authenticate]: calling eap (rlm_eap) for request 5
Tue May 13 08:20:33 2014 : Debug: (5) eap : Peer sent Identity (1)
Tue May 13 08:20:33 2014 : Debug: (5) eap : Calling eap_ttls to process EAP data
Tue May 13 08:20:33 2014 : Debug: (5) eap_ttls : Initiate
Tue May 13 08:20:33 2014 : Debug: (5) eap_ttls : Start returned 1
Tue May 13 08:20:33 2014 : Debug: (5) eap : New EAP session, adding 'State' attribute to reply 0xb9b6933bb9b486dc
Tue May 13 08:20:33 2014 : Debug: (5)   modsingle[authenticate]: returned from eap (rlm_eap) for request 5
Tue May 13 08:20:33 2014 : Debug: (5)   [eap] = handled
Tue May 13 08:20:33 2014 : Debug: (5)  } #  authenticate = handled
Sending Access-Challenge of id 132 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x010200061520
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb9b6933bb9b486dca08ab069110ad539
Tue May 13 08:20:33 2014 : Debug: (5) Finished request 5.
Tue May 13 08:20:33 2014 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=133, length=287
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0202006415800000005a1603010055010000510301537159a37b79cd1d08d56d250f2b0a0e096ddcf7b930439627ec8c11fb7547de00002a00160013006600150012000a0005000400070009006300650060006200610064001400110003000600080100
        State = 0xb9b6933bb9b486dca08ab069110ad539
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xd133446c5e988938a813606ae65825da
Tue May 13 08:20:33 2014 : Debug: (6) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (6)   authorize {
Tue May 13 08:20:33 2014 : Debug: (6)   modsingle[authorize]: calling eap (rlm_eap) for request 6
Tue May 13 08:20:33 2014 : Debug: (6) eap : EAP packet type response id 2 length 100
Tue May 13 08:20:33 2014 : Debug: (6) eap : Continuing tunnel setup.
Tue May 13 08:20:33 2014 : Debug: (6)   modsingle[authorize]: returned from eap (rlm_eap) for request 6
Tue May 13 08:20:33 2014 : Debug: (6)   [eap] = ok
Tue May 13 08:20:33 2014 : Debug: (6)  } #  authorize = ok
Tue May 13 08:20:33 2014 : Debug: (6) Found Auth-Type = EAP
Tue May 13 08:20:33 2014 : Debug: (6) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (6)   authenticate {
Tue May 13 08:20:33 2014 : Debug: (6)   modsingle[authenticate]: calling eap (rlm_eap) for request 6
Tue May 13 08:20:33 2014 : Debug: (6) eap : Expiring EAP session with state 0xb9b6933bb9b486dc
Tue May 13 08:20:33 2014 : Debug: (6) eap : Finished EAP session with state 0xb9b6933bb9b486dc
Tue May 13 08:20:33 2014 : Debug: (6) eap : Previous EAP request found for state 0xb9b6933bb9b486dc, released from the list
Tue May 13 08:20:33 2014 : Debug: (6) eap : Peer sent TTLS (21)
Tue May 13 08:20:33 2014 : Debug: (6) eap : EAP TTLS (21)
Tue May 13 08:20:33 2014 : Debug: (6) eap : Calling eap_ttls to process EAP data
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : Authenticate
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : processing EAP-TLS
Tue May 13 08:20:33 2014 : Debug:   TLS Length 90
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : Length Included
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : eaptls_verify returned 11
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     (other): before/accept initialization
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: before/accept initialization
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : <<< TLS 1.0 Handshake [length 0055], ClientHello
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 read client hello A
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : >>> TLS 1.0 Handshake [length 002a], ServerHello
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 write server hello A
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : >>> TLS 1.0 Handshake [length 03cc], Certificate
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 write certificate A
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 write key exchange A
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 write server done A
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: SSLv3 flush data
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls :     TLS_accept: Need to read more data: SSLv3 read client certificate A
Tue May 13 08:20:33 2014 : Debug: In SSL Handshake Phase
Tue May 13 08:20:33 2014 : Debug: In SSL Accept mode
Tue May 13 08:20:33 2014 : Debug: (6) eap_ttls : eaptls_process returned 13
Tue May 13 08:20:33 2014 : Debug: (6) eap : New EAP session, adding 'State' attribute to reply 0xb9b6933bb8b586dc
Tue May 13 08:20:33 2014 : Debug: (6)   modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Tue May 13 08:20:33 2014 : Debug: (6)   [eap] = handled
Tue May 13 08:20:33 2014 : Debug: (6)  } #  authenticate = handled
Sending Access-Challenge of id 133 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0103040015c00000061b160301002a0200002603010bdc44587d59355272d4a4b33f65770ba6e60780984dc49be79f16617fa69e9f0000160016030103cc0b0003c80003c50003c2308203be308202a6020900d8e196b535b385dc300d06092a864886f70d01010505003081a0310b3009060355040613024a50310e300c06035504080c05546f6b796f310e300c06035504070c054368756f753110300e060355040a0c074e545444415441310c300a060355040b0c0349544d3128302606035504030c1f746f702d6f74707261643531762e6d6e672e6e7474646174612e636f2e6a703127302506092a864886f70d0109011618706f73746d6173746572406e7474646174612e636f2e6a70301e170d3134303431393131343534365a170d3135303431393131343534365a3081a0310b3009060355040613024a50310e300c06035504080c05546f6b796f310e300c06035504070c054368756f753110300e060355040a0c074e545444415441310c300a060355040b0c0349544d3128302606035504030c1f746f702d6f74707261643531762e6d6e672e6e7474646174612e636f2e6a703127302506092a864886f70d0109011618706f73746d6173746572406e7474646174612e636f2e6a7030820122300d06092a864886f70d01010105000382010f003082010a0282010100cbd1213f741
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb9b6933bb8b586dca08ab069110ad539
Tue May 13 08:20:33 2014 : Debug: (6) Finished request 6.
Tue May 13 08:20:33 2014 : Debug: Waking up in 0.2 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=134, length=193
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020300061500
        State = 0xb9b6933bb8b586dca08ab069110ad539
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xadbf99b14a71060ea108bf3b218f9cf7
Tue May 13 08:20:33 2014 : Debug: (7) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (7)   authorize {
Tue May 13 08:20:33 2014 : Debug: (7)   modsingle[authorize]: calling eap (rlm_eap) for request 7
Tue May 13 08:20:33 2014 : Debug: (7) eap : EAP packet type response id 3 length 6
Tue May 13 08:20:33 2014 : Debug: (7) eap : Continuing tunnel setup.
Tue May 13 08:20:33 2014 : Debug: (7)   modsingle[authorize]: returned from eap (rlm_eap) for request 7
Tue May 13 08:20:33 2014 : Debug: (7)   [eap] = ok
Tue May 13 08:20:33 2014 : Debug: (7)  } #  authorize = ok
Tue May 13 08:20:33 2014 : Debug: (7) Found Auth-Type = EAP
Tue May 13 08:20:33 2014 : Debug: (7) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:33 2014 : Debug: (7)   authenticate {
Tue May 13 08:20:33 2014 : Debug: (7)   modsingle[authenticate]: calling eap (rlm_eap) for request 7
Tue May 13 08:20:33 2014 : Debug: (7) eap : Expiring EAP session with state 0xb9b6933bb8b586dc
Tue May 13 08:20:33 2014 : Debug: (7) eap : Finished EAP session with state 0xb9b6933bb8b586dc
Tue May 13 08:20:33 2014 : Debug: (7) eap : Previous EAP request found for state 0xb9b6933bb8b586dc, released from the list
Tue May 13 08:20:33 2014 : Debug: (7) eap : Peer sent TTLS (21)
Tue May 13 08:20:33 2014 : Debug: (7) eap : EAP TTLS (21)
Tue May 13 08:20:33 2014 : Debug: (7) eap : Calling eap_ttls to process EAP data
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : Authenticate
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : processing EAP-TLS
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : Received TLS ACK
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : Received TLS ACK
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : ACK handshake fragment handler
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : eaptls_verify returned 1
Tue May 13 08:20:33 2014 : Debug: (7) eap_ttls : eaptls_process returned 13
Tue May 13 08:20:33 2014 : Debug: (7) eap : New EAP session, adding 'State' attribute to reply 0xb9b6933bbbb286dc
Tue May 13 08:20:33 2014 : Debug: (7)   modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Tue May 13 08:20:33 2014 : Debug: (7)   [eap] = handled
Tue May 13 08:20:33 2014 : Debug: (7)  } #  authenticate = handled
Sending Access-Challenge of id 134 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0104022f15800000061b1656ba74fcd8aabc61ca160301020d0c0002090080f9ff408fde4339b038b6d70ffa17ddc5efd2b8a760df3f5f914e5547417d84139c0bdf7692016aba5f138e0f574a062f54f8c3c93a13a9268320eb5ea1cdb6295a102a424aa2bc0a7c058c1ec7466c81acaa48424f451b2ff0a85c87cff71735a1b337edcc5c911b4290f67be096967d7361bd217b976f2c692ef4ce1a7d266300010200803ce60687d012617836e173cf225a7c305c5c83675758c40b47e8815ea902dad95cf4c88fe2f0e0fc389d9c53737e9b29913a6928cfedfb9881868fd35595c9e4ed928dd22cf7d9ebd270a2f33703313d776016b6e690234c5f9df03b0edd316b31e3f36017296a306b4aef37e68425fd08a115ccbbe0d215675c51a3fb8a6d9d0100928cb08fc4d439388701473816fc1d31bcadef6a639389ada0944be0eee7d3fec1a316f0ed4e8386ce8b9859485da3e442521055a5cef97e20b70d12fd07c158ff880097d37227b513c0674a52826ef8889cd3acbece447e2fb58d576239c0e62ae2de4cf118eec3cb524bf97b1b7d56da87eea2d12d2e087aad2e5a27244128486f87177f33e805e6e4f9ccdb74f36fc81da6666f5835ee35871d0b03edf11f47537bd665bd31895bcf0558ab72ddb21ff8088283459b8cc000eea48c0ce93f686781ee970963f4d5da18731d08dc597
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb9b6933bbbb286dca08ab069110ad539
Tue May 13 08:20:33 2014 : Debug: (7) Finished request 7.
Tue May 13 08:20:33 2014 : Debug: Waking up in 0.2 seconds.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=135, length=387
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020400c81580000000be16030100861000008200801e2b01b9b526d9ca39f340b134b5528ff46141024f01881b89d5d51341d9b3de6fabb9f9d055f735032f790fb3ef1d81197aaaaf615041c74e2c71e3c1db5d66dd6f5a90db014e11c1b5633401ae2c7abcd967db24c1c13f08fca7101c3ae8d059c49bbe361d7a5122a08f9f21ad520b4d53a756bcd85aebf57917f44000520c14030100010116030100286195f1e7a73e5889ddc38dcd3fd585c61dadf8546ab0fd0890be19c9cd6913b068e536170de1280d
        State = 0xb9b6933bbbb286dca08ab069110ad539
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0xbdb20e300c2366483eca8a5b82d762bf
Tue May 13 08:20:34 2014 : Debug: (8) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:34 2014 : Debug: (8)   authorize {
Tue May 13 08:20:34 2014 : Debug: (8)   modsingle[authorize]: calling eap (rlm_eap) for request 8
Tue May 13 08:20:34 2014 : Debug: (8) eap : EAP packet type response id 4 length 200
Tue May 13 08:20:34 2014 : Debug: (8) eap : Continuing tunnel setup.
Tue May 13 08:20:34 2014 : Debug: (8)   modsingle[authorize]: returned from eap (rlm_eap) for request 8
Tue May 13 08:20:34 2014 : Debug: (8)   [eap] = ok
Tue May 13 08:20:34 2014 : Debug: (8)  } #  authorize = ok
Tue May 13 08:20:34 2014 : Debug: (8) Found Auth-Type = EAP
Tue May 13 08:20:34 2014 : Debug: (8) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:20:34 2014 : Debug: (8)   authenticate {
Tue May 13 08:20:34 2014 : Debug: (8)   modsingle[authenticate]: calling eap (rlm_eap) for request 8
Tue May 13 08:20:34 2014 : Debug: (8) eap : Expiring EAP session with state 0xb9b6933bbbb286dc
Tue May 13 08:20:34 2014 : Debug: (8) eap : Finished EAP session with state 0xb9b6933bbbb286dc
Tue May 13 08:20:34 2014 : Debug: (8) eap : Previous EAP request found for state 0xb9b6933bbbb286dc, released from the list
Tue May 13 08:20:34 2014 : Debug: (8) eap : Peer sent TTLS (21)
Tue May 13 08:20:34 2014 : Debug: (8) eap : EAP TTLS (21)
Tue May 13 08:20:34 2014 : Debug: (8) eap : Calling eap_ttls to process EAP data
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : Authenticate
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : processing EAP-TLS
Tue May 13 08:20:34 2014 : Debug:   TLS Length 190
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : Length Included
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : eaptls_verify returned 11
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     TLS_accept: SSLv3 read client key exchange A
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : <<< TLS 1.0 ChangeCipherSpec [length 0001]
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : <<< TLS 1.0 Handshake [length 0010], Finished
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     TLS_accept: SSLv3 read finished A
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : >>> TLS 1.0 ChangeCipherSpec [length 0001]
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     TLS_accept: SSLv3 write change cipher spec A
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : >>> TLS 1.0 Handshake [length 0010], Finished
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     TLS_accept: SSLv3 write finished A
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     TLS_accept: SSLv3 flush data
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls :     (other): SSL negotiation finished successfully
Tue May 13 08:20:34 2014 : Debug: SSL Connection Established
Tue May 13 08:20:34 2014 : Debug: (8) eap_ttls : eaptls_process returned 13
Tue May 13 08:20:34 2014 : Debug: (8) eap : New EAP session, adding 'State' attribute to reply 0xb9b6933bbab386dc
Tue May 13 08:20:34 2014 : Debug: (8)   modsingle[authenticate]: returned from eap (rlm_eap) for request 8
Tue May 13 08:20:34 2014 : Debug: (8)   [eap] = handled
Tue May 13 08:20:34 2014 : Debug: (8)  } #  authenticate = handled
Sending Access-Challenge of id 135 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        EAP-Message = 0x0105003d1580000000331403010001011603010028542d18a9356ec77acdeaf3a0e26750b476c989b681736159de406d994f6e8bcc05f7a4b969bdaf6a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb9b6933bbab386dca08ab069110ad539
Tue May 13 08:20:34 2014 : Debug: (8) Finished request 8.
Tue May 13 08:20:34 2014 : Debug: Waking up in 0.2 seconds.
Tue May 13 08:20:34 2014 : Debug: Waking up in 4.3 seconds.
Tue May 13 08:20:38 2014 : Debug: (5) Cleaning up request packet ID 132 with timestamp +98
Tue May 13 08:20:38 2014 : Debug: (6) Cleaning up request packet ID 133 with timestamp +98
Tue May 13 08:20:38 2014 : Debug: (7) Cleaning up request packet ID 134 with timestamp +98
Tue May 13 08:20:38 2014 : Debug: Waking up in 0.2 seconds.
Tue May 13 08:20:39 2014 : Debug: (8) Cleaning up request packet ID 135 with timestamp +99
Tue May 13 08:20:39 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.7.255.75 port 32806, id=136, length=258
        User-Name = 'anonymous'
        NAS-IP-Address = 10.78.255.11
        NAS-Port = 0
        NAS-Identifier = '10.7.255.75'
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = '002100DB0DC5'
        Called-Station-Id = '000B866E4C48'
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0205004715800000003d170301003809bab38229f251783d96fd0f0497d155d5e64498207b70403da0502b42fa87b344a31f8652d0a99abef48549113731a67e6ed3811316a502
        State = 0xb9b6933bbab386dca08ab069110ad539
        Aruba-Essid-Name = 'otptest'
        Aruba-Location-Id = '1.14.25'
        Aruba-AP-Group = 'tys-low01'
        Message-Authenticator = 0x124536dfc7dba4f0b4f9f9028c4eb7fb
Tue May 13 08:21:02 2014 : Debug: (9) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:21:02 2014 : Debug: (9)   authorize {
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[authorize]: calling eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9) eap : EAP packet type response id 5 length 71
Tue May 13 08:21:02 2014 : Debug: (9) eap : Continuing tunnel setup.
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[authorize]: returned from eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9)   [eap] = ok
Tue May 13 08:21:02 2014 : Debug: (9)  } #  authorize = ok
Tue May 13 08:21:02 2014 : Debug: (9) Found Auth-Type = EAP
Tue May 13 08:21:02 2014 : Debug: (9) # Executing group from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:21:02 2014 : Debug: (9)   authenticate {
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[authenticate]: calling eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9) eap : Expiring EAP session with state 0xb9b6933bbab386dc
Tue May 13 08:21:02 2014 : Debug: (9) eap : Finished EAP session with state 0xb9b6933bbab386dc
Tue May 13 08:21:02 2014 : Debug: (9) eap : Previous EAP request found for state 0xb9b6933bbab386dc, released from the list
Tue May 13 08:21:02 2014 : Debug: (9) eap : Peer sent TTLS (21)
Tue May 13 08:21:02 2014 : Debug: (9) eap : EAP TTLS (21)
Tue May 13 08:21:02 2014 : Debug: (9) eap : Calling eap_ttls to process EAP data
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Authenticate
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : processing EAP-TLS
Tue May 13 08:21:02 2014 : Debug:   TLS Length 61
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Length Included
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : eaptls_verify returned 11
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : eaptls_process returned 7
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Session established.  Proceeding to decode tunneled attributes.
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Got tunneled request
        User-Name = '1234567'
        User-Password = '2'
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Sending tunneled request
        User-Name = '1234567'
        User-Password = '2'
server inner-tunnel {
Tue May 13 08:21:02 2014 : Debug: (9) # Executing section authorize from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:21:02 2014 : Debug: (9)   authorize {
Tue May 13 08:21:02 2014 : Debug: (9)   update control {
Tue May 13 08:21:02 2014 : Debug: (9)   Proxy-To-Realm := 'tinyradius'
Tue May 13 08:21:02 2014 : Debug: (9) ::: FROM 1 TO 0 MAX 1
Tue May 13 08:21:02 2014 : Debug: (9) ::: Examining Proxy-To-Realm
Tue May 13 08:21:02 2014 : Debug: (9) ::: APPENDING Proxy-To-Realm FROM 0 TO 0
Tue May 13 08:21:02 2014 : Debug: (9) ::: TO in 0 out 1
Tue May 13 08:21:02 2014 : Debug: (9) ::: to[0] = Proxy-To-Realm
Tue May 13 08:21:02 2014 : Debug: (9)   } # update control = noop
Tue May 13 08:21:02 2014 : Debug: (9)  } #  authorize = noop
} # server inner-tunnel
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Got tunneled reply code 0
Tue May 13 08:21:02 2014 : Debug: (9) eap_ttls : Tunneled authentication will be proxied to tinyradius
Tue May 13 08:21:02 2014 : Debug: (9) eap :   Tunneled session will be proxied.  Not doing EAP.
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[authenticate]: returned from eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9)   [eap] = handled
Tue May 13 08:21:02 2014 : Debug: (9)  } #  authenticate = handled
Tue May 13 08:21:02 2014 : Debug: (9) Empty pre-proxy section.  Using default return values.
Tue May 13 08:21:02 2014 : Debug: (9) proxy: Trying to allocate ID (0/2)
Tue May 13 08:21:02 2014 : Debug: (9) proxy: request is now in proxy hash
Tue May 13 08:21:02 2014 : Debug: (9)  proxy: allocating destination 127.0.0.1 port 18160 - Id 18
Tue May 13 08:21:02 2014 : Debug: (9) Proxying request to home server 127.0.0.1 port 18160
Sending Access-Request of id 18 from 0.0.0.0 port 59886 to 127.0.0.1 port 18160
        User-Name = '1234567'
        User-Password = '2'
        Message-Authenticator := 0x00
        Proxy-State = 0x313336
Tue May 13 08:21:02 2014 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Accept packet from host 127.0.0.1 port 18160, id=18, length=20
Tue May 13 08:21:02 2014 : Debug: (9) proxy: request is no longer in proxy hash
Tue May 13 08:21:02 2014 : Debug: (9) # Executing section post-proxy from file /usr/local/freeradius-3.0.2/etc/raddb/radiusd.conf
Tue May 13 08:21:02 2014 : Debug: (9)   post-proxy {
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[post-proxy]: calling eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9) eap : Doing post-proxy callback
Tue May 13 08:21:02 2014 : Debug: (9) eap : Passing reply from proxy back into the tunnel.
server inner-tunnel {
Tue May 13 08:21:02 2014 : Debug: (9) Empty post-auth section.  Using default return values.
Tue May 13 08:21:02 2014 : Debug: (9) eap : post-auth returns 2
} # server inner-tunnel
Tue May 13 08:21:02 2014 : Debug: (9) eap : Final reply from tunneled session code 2
Tue May 13 08:21:02 2014 : Debug: (9) eap : Got reply 2
Tue May 13 08:21:02 2014 : Debug: (9) eap : Got tunneled Access-Accept
Tue May 13 08:21:02 2014 : Debug: (9) eap : Reply was OK
Tue May 13 08:21:02 2014 : Debug: (9) eap : Freeing handler
Tue May 13 08:21:02 2014 : Debug: (9)   modsingle[post-proxy]: returned from eap (rlm_eap) for request 9
Tue May 13 08:21:02 2014 : Debug: (9)   [eap] = ok
Tue May 13 08:21:02 2014 : Debug: (9)  } #  post-proxy = ok
Tue May 13 08:21:02 2014 : Debug: (9) Found Auth-Type = EAP
Tue May 13 08:21:02 2014 : Debug: (9) Found Auth-Type = Accept
Tue May 13 08:21:02 2014 : ERROR: (9) Warning:  Found 2 auth-types on request for user 'anonymous'
Tue May 13 08:21:02 2014 : Debug: (9) Auth-Type = Accept, accepting the user
Tue May 13 08:21:02 2014 : Debug: (9) Empty post-auth section.  Using default return values.
Sending Access-Accept of id 136 from 10.33.22.38 port 18120 to 10.7.255.75 port 32806
        MS-MPPE-Recv-Key = 0x163e7f657610b516edacfba09f5b7b632031243f9596a43c243c4df8e6ea1314
        MS-MPPE-Send-Key = 0xdbd7e58b35ccab0e27174b1fc627ecbdddd234311a0e1cd884181419845388cf
        EAP-Message = 0x03050004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = 'anonymous'
Tue May 13 08:21:02 2014 : Debug: (9) Finished request 9.
Tue May 13 08:21:02 2014 : Debug: Waking up in 0.3 seconds.
Tue May 13 08:21:03 2014 : Debug: Waking up in 4.6 seconds.
Tue May 13 08:21:07 2014 : Debug: (9) Cleaning up request packet ID 136 with timestamp +127
Tue May 13 08:21:07 2014 : Info: Ready to process requests.

Regards.

---
Kouki Hashimoto
hashimotoku at nttdata.co.jp

Re: EAP-TTLS session resumption does not work.

hashimotoku＠nttdata.co.jp

Alan DeKok

tags

participants (2)