getting auth reject

27 Oct 2013


      Can someone tell me what is going on here? It gives me a chap auth request
fail when everything else looks good. I am not sure why I get the "EAP
session for state 0x467250bc44764540 did not finish!" I get the same
message occasionally on other requests that seem to accept the auth anyway.
This is a new canopy ap that I am trying to make work. It originally wanted
to use the user anonymous but It was failing on that so changed the phase 1
auth to use the mac also. Is this a cert error? A configuration error?
Thanks for looking at it.


rad_recv: Access-Request packet from host 10.0.32.130 port 1238, id=0,
length=106
        User-Name = "0a-00-3e-47-df-7d"
        NAS-IP-Address = 10.0.32.130
        NAS-Port = 5
        NAS-Port-Type = Wireless-Other
        Framed-MTU = 1020
        EAP-Message = 0x020100170130612d30302d33652d34372d64662d376400
        Message-Authenticator = 0x2d0cefa2c6f99ad929553dc9aed96ff9
Sun Oct 27 14:52:04 2013 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:04 2013 : Info: +- entering group authorize {...}
Sun Oct 27 14:52:04 2013 : Info: ++[preprocess] returns ok
Sun Oct 27 14:52:04 2013 : Info: ++[chap] returns noop
Sun Oct 27 14:52:04 2013 : Info: ++[mschap] returns noop
Sun Oct 27 14:52:04 2013 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-47-df-7d", looking up realm NULL
Sun Oct 27 14:52:04 2013 : Info: [suffix] No such realm "NULL"
Sun Oct 27 14:52:04 2013 : Info: ++[suffix] returns noop
Sun Oct 27 14:52:04 2013 : Info: [eap] EAP packet type response id 1 length
23
Sun Oct 27 14:52:04 2013 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Sun Oct 27 14:52:04 2013 : Info: ++[eap] returns updated
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: %{User-Name} ->
0a-00-3e-47-df-7d
Sun Oct 27 14:52:04 2013 : Info: [sql] sql_set_user escaped user -->
'0a-00-3e-47-df-7d'
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: SELECT id, UserName,
Attribute, Value, Op   FROM radcheck   WHERE Username =
'%{SQL-User-Name}'   ORDER BY id -> SELECT id, UserName, Attribute, Value,
Op   FROM radcheck   WHERE Username = '0a-00-3e-47-df-7d'   ORDER BY id
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: query affected rows =
2 , fields = 5
Sun Oct 27 14:52:04 2013 : Info: [sql] User found in radcheck table
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: SELECT id, UserName,
Attribute, Value, Op   FROM radreply   WHERE Username =
'%{SQL-User-Name}'   ORDER BY id -> SELECT id, UserName, Attribute, Value,
Op   FROM radreply   WHERE Username = '0a-00-3e-47-df-7d'   ORDER BY id
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: query affected rows =
1 , fields = 5
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: SELECT GroupName FROM
radusergroup WHERE UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT
GroupName FROM radusergroup WHERE UserName='0a-00-3e-47-df-7d' ORDER BY
priority
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: query affected rows =
1 , fields = 1
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: SELECT id, GroupName,
Attribute, Value, op   FROM radgroupcheck   WHERE GroupName =
'%{Sql-Group}'   ORDER BY id -> SELECT id, GroupName, Attribute, Value,
op   FROM radgroupcheck   WHERE GroupName = '450-3x1'   ORDER BY id
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: query affected rows =
0 , fields = 5
Sun Oct 27 14:52:04 2013 : Info: [sql] User found in group 450-3x1
Sun Oct 27 14:52:04 2013 : Info: [sql]  expand: SELECT id, GroupName,
Attribute, Value, op   FROM radgroupreply   WHERE GroupName =
'%{Sql-Group}'   ORDER BY id -> SELECT id, GroupName, Attribute, Value,
op   FROM radgroupreply   WHERE GroupName = '450-3x1'   ORDER BY id
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql_postgresql: query affected rows =
6 , fields = 5
Sun Oct 27 14:52:04 2013 : Debug: rlm_sql (sql): Released sql socket id: 1
Sun Oct 27 14:52:04 2013 : Info: ++[sql] returns ok
Sun Oct 27 14:52:04 2013 : Info: ++[expiration] returns noop
Sun Oct 27 14:52:04 2013 : Info: ++[logintime] returns noop
Sun Oct 27 14:52:04 2013 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP
Sun Oct 27 14:52:04 2013 : Info: ++[pap] returns noop
Sun Oct 27 14:52:04 2013 : Info: Found Auth-Type = EAP
Sun Oct 27 14:52:04 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:04 2013 : Info: +- entering group authenticate {...}
Sun Oct 27 14:52:04 2013 : Info: [eap] EAP Identity
Sun Oct 27 14:52:04 2013 : Info: [eap] processing type tls
Sun Oct 27 14:52:04 2013 : Info: [tls] Initiate
Sun Oct 27 14:52:04 2013 : Info: [tls] Start returned 1
Sun Oct 27 14:52:04 2013 : Info: ++[eap] returns handled
Sending Access-Challenge of id 0 to 10.0.32.130 port 1238
        Motorola-Canopy-DLBL = 307200
        Motorola-Canopy-DLBR = 3072
        Motorola-Canopy-ULBL = 102400
        Motorola-Canopy-ULBR = 1024
        Motorola-Canopy-VLIGVID = 25
        Motorola-Canopy-VLMGVID = 24
        EAP-Message = 0x010200061520
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x063cc73b063ed219e2c4f691fc23b343
Sun Oct 27 14:52:04 2013 : Info: Finished request 360.
Sun Oct 27 14:52:04 2013 : Debug: Going to the next request
Sun Oct 27 14:52:04 2013 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.32.130 port 1238, id=0,
length=169
Sun Oct 27 14:52:04 2013 : Info: Cleaning up request 360 ID 0 with
timestamp +2903
Sun Oct 27 14:52:04 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Sun Oct 27 14:52:04 2013 : Debug: WARNING: !! EAP session for state
0x063cc73b063ed219 did not finish!
Sun Oct 27 14:52:04 2013 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Sun Oct 27 14:52:04 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "0a-00-3e-47-df-7d"
        State = 0x063cc73b063ed219e2c4f691fc23b343
        NAS-IP-Address = 10.0.32.130
        NAS-Port = 5
        NAS-Port-Type = Wireless-Other
        Framed-MTU = 1020
        EAP-Message =
0x0202004415800000003a1603010035010000310301433a5aab0f63d6f562ea45cf1d668b7ae8fe8e46c58c62c96b10d7190787d12b00000a0035002f00040005000a0100
        Message-Authenticator = 0x5b1bb664095dcdeefcec42693f0c9a2a
Sun Oct 27 14:52:04 2013 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:04 2013 : Info: +- entering group authorize {...}
Sun Oct 27 14:52:04 2013 : Info: ++[preprocess] returns ok
Sun Oct 27 14:52:04 2013 : Info: ++[chap] returns noop
Sun Oct 27 14:52:04 2013 : Info: ++[mschap] returns noop
Sun Oct 27 14:52:04 2013 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-47-df-7d", looking up realm NULL
Sun Oct 27 14:52:04 2013 : Info: [suffix] No such realm "NULL"
Sun Oct 27 14:52:04 2013 : Info: ++[suffix] returns noop
Sun Oct 27 14:52:04 2013 : Info: [eap] EAP packet type response id 2 length
68
Sun Oct 27 14:52:04 2013 : Info: [eap] Continuing tunnel setup.
Sun Oct 27 14:52:04 2013 : Info: ++[eap] returns ok
Sun Oct 27 14:52:04 2013 : Info: Found Auth-Type = EAP
Sun Oct 27 14:52:04 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:04 2013 : Info: +- entering group authenticate {...}
Sun Oct 27 14:52:04 2013 : Info: [eap] Request found, released from the list
Sun Oct 27 14:52:04 2013 : Info: [eap] EAP/ttls
Sun Oct 27 14:52:04 2013 : Info: [eap] processing type ttls
Sun Oct 27 14:52:04 2013 : Info: [ttls] Authenticate
Sun Oct 27 14:52:04 2013 : Info: [ttls] processing EAP-TLS
Sun Oct 27 14:52:04 2013 : Debug:   TLS Length 58
Sun Oct 27 14:52:04 2013 : Info: [ttls] Length Included
Sun Oct 27 14:52:04 2013 : Info: [ttls] eaptls_verify returned 11
Sun Oct 27 14:52:04 2013 : Info: [ttls]     (other): before/accept
initialization
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: before/accept
initialization
Sun Oct 27 14:52:04 2013 : Info: [ttls] <<< TLS 1.0 Handshake [length
0035], ClientHello
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: SSLv3 read client
hello A
Sun Oct 27 14:52:04 2013 : Info: [ttls] >>> TLS 1.0 Handshake [length
002a], ServerHello
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: SSLv3 write server
hello A
Sun Oct 27 14:52:04 2013 : Info: [ttls] >>> TLS 1.0 Handshake [length
0306], Certificate
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: SSLv3 write
certificate A
Sun Oct 27 14:52:04 2013 : Info: [ttls] >>> TLS 1.0 Handshake [length
0004], ServerHelloDone
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: SSLv3 write server
done A
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: SSLv3 flush data
Sun Oct 27 14:52:04 2013 : Info: [ttls]     TLS_accept: Need to read more
data: SSLv3 read client certificate A
Sun Oct 27 14:52:04 2013 : Debug: In SSL Handshake Phase
Sun Oct 27 14:52:04 2013 : Debug: In SSL Accept mode
Sun Oct 27 14:52:04 2013 : Info: [ttls] eaptls_process returned 13
Sun Oct 27 14:52:04 2013 : Info: ++[eap] returns handled
Sending Access-Challenge of id 0 to 10.0.32.130 port 1238
        EAP-Message =
0x0103034d158000000343160301002a020000260301526d6ee4f06ffa59524f6851095ab3fa4a053e52864491d5bc3a2bd2c82145d90000350016030103060b0003020002ff0002fc308202f830820261a003020102020101300d06092a864886f70d01010505003076310b30090603550406130255533111300f06035504081308496c6c696e6f697331173015060355040a130e4d6f746f726f6c612c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e64311730150603550403130e504d503332302044656d6f204341301e170d3039303730313036303130305a170d3439313233313233353935
        EAP-Message =
0x395a308194310b30090603550406130255533111300f06035504081308496c6c696e6f6973311330110603550407130a53636861756d6275726731173015060355040a130e4d6f746f726f6c612c20496e632e31223020060355040b131943616e6f707920576972656c6573732042726f616462616e643120301e06035504031317504d503332302044656d6f20436572746966696361746530819f300d06092a864886f70d010101050003818d0030818902818100d20d60d5fa96d95112c0014312be69bbb09e8e0edb620e9398d9a9307073b2645dd5e1bd04ef94e4f10d5a72f63ffbb80c1ff3f2317a9550f621fbf56cae967051621bd0d4c7b2
        EAP-Message =
0xb19ede40b2789abc45ed8d2944b0e0f0716272a6907b161e1426eacbf81fc447089a4127fd41a6f643cd95430bb7fd8005186fc1f6326677bf0203010001a377307530090603551d1304023000302806096086480186f842010d041b1619496e7365637572652044656d6f204365727469666963617465301d0603551d0e04160414741add6ffb71869c6f26c3d0a166b4c356049782301f0603551d23041830168014da4e7dcfb2244534086ba58933bd9edc7cf84876300d06092a864886f70d010105050003818100063704750634864335246876d31a85bec4e76aa63f7500a205a48e8b12d4b67d5372df8ed53efb3770e6884153ac30ddb35a7d
        EAP-Message =
0x08679632268e6f08bb6cd66fef32c7551487843db971719e3a4caac5f359480196ddab73754c37dbeef0fd650739d9643681ed68b53210ef2b4f993eea23bfb6f1df829b51c4b0c4748455b24b16030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x063cc73b073fd219e2c4f691fc23b343
Sun Oct 27 14:52:04 2013 : Info: Finished request 361.
Sun Oct 27 14:52:04 2013 : Debug: Going to the next request
Sun Oct 27 14:52:04 2013 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.32.130 port 1238, id=0,
length=309
Sun Oct 27 14:52:05 2013 : Info: Cleaning up request 361 ID 0 with
timestamp +2903
Sun Oct 27 14:52:05 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Sun Oct 27 14:52:05 2013 : Debug: WARNING: !! EAP session for state
0x063cc73b073fd219 did not finish!
Sun Oct 27 14:52:05 2013 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Sun Oct 27 14:52:05 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "0a-00-3e-47-df-7d"
        State = 0x063cc73b073fd219e2c4f691fc23b343
        NAS-IP-Address = 10.0.32.130
        NAS-Port = 5
        NAS-Port-Type = Wireless-Other
        Framed-MTU = 1020
        EAP-Message =
0x020300d01580000000c61603010086100000820080ad98aaefbe12f373184aa9a968af10d2a125bec2c1d000c4edd62e8f7bdc2206294225fcce556c11da32e93249915e92134f8a075ebe0e80df8ef271ce709e0f68bec288dc4f82b74e29300f6ddb361b3960ae62da0087b285340480a3891bb006c38474eaed04578ba5a71bde74be0a08591efec1e2422c63937fb5d89851b514030100010116030100305eec78050ed7e8eb7f2aa3deb61014d4aacb0188b2850c75e13b4813c99463853b0d9cdc05119105acb6aff51731c7f7
        Message-Authenticator = 0xdb832a94b37bc00e356a00f2347fddce
Sun Oct 27 14:52:05 2013 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:05 2013 : Info: +- entering group authorize {...}
Sun Oct 27 14:52:05 2013 : Info: ++[preprocess] returns ok
Sun Oct 27 14:52:05 2013 : Info: ++[chap] returns noop
Sun Oct 27 14:52:05 2013 : Info: ++[mschap] returns noop
Sun Oct 27 14:52:05 2013 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-47-df-7d", looking up realm NULL
Sun Oct 27 14:52:05 2013 : Info: [suffix] No such realm "NULL"
Sun Oct 27 14:52:05 2013 : Info: ++[suffix] returns noop
Sun Oct 27 14:52:05 2013 : Info: [eap] EAP packet type response id 3 length
208
Sun Oct 27 14:52:05 2013 : Info: [eap] Continuing tunnel setup.
Sun Oct 27 14:52:05 2013 : Info: ++[eap] returns ok
Sun Oct 27 14:52:05 2013 : Info: Found Auth-Type = EAP
Sun Oct 27 14:52:05 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:05 2013 : Info: +- entering group authenticate {...}
Sun Oct 27 14:52:05 2013 : Info: [eap] Request found, released from the list
Sun Oct 27 14:52:05 2013 : Info: [eap] EAP/ttls
Sun Oct 27 14:52:05 2013 : Info: [eap] processing type ttls
Sun Oct 27 14:52:05 2013 : Info: [ttls] Authenticate
Sun Oct 27 14:52:05 2013 : Info: [ttls] processing EAP-TLS
Sun Oct 27 14:52:05 2013 : Debug:   TLS Length 198
Sun Oct 27 14:52:05 2013 : Info: [ttls] Length Included
Sun Oct 27 14:52:05 2013 : Info: [ttls] eaptls_verify returned 11
Sun Oct 27 14:52:05 2013 : Info: [ttls] <<< TLS 1.0 Handshake [length
0086], ClientKeyExchange
Sun Oct 27 14:52:05 2013 : Info: [ttls]     TLS_accept: SSLv3 read client
key exchange A
Sun Oct 27 14:52:05 2013 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec
[length 0001]
Sun Oct 27 14:52:05 2013 : Info: [ttls] <<< TLS 1.0 Handshake [length
0010], Finished
Sun Oct 27 14:52:05 2013 : Info: [ttls]     TLS_accept: SSLv3 read finished
A
Sun Oct 27 14:52:05 2013 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec
[length 0001]
Sun Oct 27 14:52:05 2013 : Info: [ttls]     TLS_accept: SSLv3 write change
cipher spec A
Sun Oct 27 14:52:05 2013 : Info: [ttls] >>> TLS 1.0 Handshake [length
0010], Finished
Sun Oct 27 14:52:05 2013 : Info: [ttls]     TLS_accept: SSLv3 write
finished A
Sun Oct 27 14:52:05 2013 : Info: [ttls]     TLS_accept: SSLv3 flush data
Sun Oct 27 14:52:05 2013 : Info: [ttls]     (other): SSL negotiation
finished successfully
Sun Oct 27 14:52:05 2013 : Debug: SSL Connection Established
Sun Oct 27 14:52:05 2013 : Info: [ttls] eaptls_process returned 13
Sun Oct 27 14:52:05 2013 : Info: ++[eap] returns handled
Sending Access-Challenge of id 0 to 10.0.32.130 port 1238
        EAP-Message =
0x0104004515800000003b140301000101160301003045237ed030a4aa4f5ba0fcb2834f9cf8246779cafbf5f4ceba6bac9dd1f220b43b3056e4f66faadd194c4aab37c339a0
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x063cc73b0438d219e2c4f691fc23b343
Sun Oct 27 14:52:05 2013 : Info: Finished request 362.
Sun Oct 27 14:52:05 2013 : Debug: Going to the next request
Sun Oct 27 14:52:05 2013 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.32.130 port 1238, id=0,
length=260
Sun Oct 27 14:52:05 2013 : Info: Cleaning up request 362 ID 0 with
timestamp +2904
Sun Oct 27 14:52:05 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Sun Oct 27 14:52:05 2013 : Debug: WARNING: !! EAP session for state
0x063cc73b0438d219 did not finish!
Sun Oct 27 14:52:05 2013 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Sun Oct 27 14:52:05 2013 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        User-Name = "0a-00-3e-47-df-7d"
        State = 0x063cc73b0438d219e2c4f691fc23b343
        NAS-IP-Address = 10.0.32.130
        NAS-Port = 5
        NAS-Port-Type = Wireless-Other
        Framed-MTU = 1020
        EAP-Message =
0x0204009f1580000000951703010090e9a9dc561abde7cb65670c328b449194399b8f109db06f84abb5adc9524e2c7f195e36c9a6d205ea710ff787c7f586ccaddcc21ef836d3c48458b577d09c6b47d64ba6ad5d2ea6650bb97b11ddaf40e4ac164d170350ab04ad83195d6ba373890e169b0d172d088187359bbfe27e6ed6b8c4c04f5878f1f367e767527c4d7485be3e167b2fb2ec9758a6f3de4996e719
        Message-Authenticator = 0xb5fa8df73a564a48fbb1a3fbaa9f0961
Sun Oct 27 14:52:05 2013 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:05 2013 : Info: +- entering group authorize {...}
Sun Oct 27 14:52:05 2013 : Info: ++[preprocess] returns ok
Sun Oct 27 14:52:05 2013 : Info: ++[chap] returns noop
Sun Oct 27 14:52:05 2013 : Info: ++[mschap] returns noop
Sun Oct 27 14:52:05 2013 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-47-df-7d", looking up realm NULL
Sun Oct 27 14:52:05 2013 : Info: [suffix] No such realm "NULL"
Sun Oct 27 14:52:05 2013 : Info: ++[suffix] returns noop
Sun Oct 27 14:52:05 2013 : Info: [eap] EAP packet type response id 4 length
159
Sun Oct 27 14:52:05 2013 : Info: [eap] Continuing tunnel setup.
Sun Oct 27 14:52:05 2013 : Info: ++[eap] returns ok
Sun Oct 27 14:52:05 2013 : Info: Found Auth-Type = EAP
Sun Oct 27 14:52:05 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:05 2013 : Info: +- entering group authenticate {...}
Sun Oct 27 14:52:05 2013 : Info: [eap] Request found, released from the list
Sun Oct 27 14:52:05 2013 : Info: [eap] EAP/ttls
Sun Oct 27 14:52:05 2013 : Info: [eap] processing type ttls
Sun Oct 27 14:52:05 2013 : Info: [ttls] Authenticate
Sun Oct 27 14:52:05 2013 : Info: [ttls] processing EAP-TLS
Sun Oct 27 14:52:05 2013 : Debug:   TLS Length 149
Sun Oct 27 14:52:05 2013 : Info: [ttls] Length Included
Sun Oct 27 14:52:05 2013 : Info: [ttls] eaptls_verify returned 11
Sun Oct 27 14:52:05 2013 : Info: [ttls] eaptls_process returned 7
Sun Oct 27 14:52:05 2013 : Info: [ttls] Session established.  Proceeding to
decode tunneled attributes.
Sun Oct 27 14:52:05 2013 : Info: [ttls] Got tunneled request
        User-Name = "0a-00-3e-47-df-7d"
        MS-CHAP-Challenge = 0x4ff587d0fbf151cdb97a96a81978e059
        MS-CHAP2-Response =
0x6500dfcbfdcac94bc92950a342b1c0a3b82f0000000000000000ddb95eabbbe9df37deba2a3ba6592033b449118e83f1c717
        FreeRADIUS-Proxied-To = 127.0.0.1
Sun Oct 27 14:52:05 2013 : Info: [ttls] Sending tunneled request
        User-Name = "0a-00-3e-47-df-7d"
        MS-CHAP-Challenge = 0x4ff587d0fbf151cdb97a96a81978e059
        MS-CHAP2-Response =
0x6500dfcbfdcac94bc92950a342b1c0a3b82f0000000000000000ddb95eabbbe9df37deba2a3ba6592033b449118e83f1c717
        FreeRADIUS-Proxied-To = 127.0.0.1
        NAS-IP-Address = 10.0.32.130
        NAS-Port = 5
        NAS-Port-Type = Wireless-Other
        Framed-MTU = 1020
server inner-tunnel {
Sun Oct 27 14:52:05 2013 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
Sun Oct 27 14:52:05 2013 : Info: +- entering group authorize {...}
Sun Oct 27 14:52:05 2013 : Info: ++[chap] returns noop
Sun Oct 27 14:52:05 2013 : Info: [mschap] Found MS-CHAP attributes.
Setting 'Auth-Type  = mschap'
Sun Oct 27 14:52:05 2013 : Info: ++[mschap] returns ok
Sun Oct 27 14:52:05 2013 : Info: ++[unix] returns notfound
Sun Oct 27 14:52:05 2013 : Info: [suffix] No '@' in User-Name =
"0a-00-3e-47-df-7d", looking up realm NULL
Sun Oct 27 14:52:05 2013 : Info: [suffix] No such realm "NULL"
Sun Oct 27 14:52:05 2013 : Info: ++[suffix] returns noop
Sun Oct 27 14:52:05 2013 : Info: ++[control] returns noop
Sun Oct 27 14:52:05 2013 : Info: [eap] No EAP-Message, not doing EAP
Sun Oct 27 14:52:05 2013 : Info: ++[eap] returns noop
Sun Oct 27 14:52:05 2013 : Info: ++[files] returns noop
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: %{User-Name} ->
0a-00-3e-47-df-7d
Sun Oct 27 14:52:05 2013 : Info: [sql] sql_set_user escaped user -->
'0a-00-3e-47-df-7d'
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 0
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: SELECT id, UserName,
Attribute, Value, Op   FROM radcheck   WHERE Username =
'%{SQL-User-Name}'   ORDER BY id -> SELECT id, UserName, Attribute, Value,
Op   FROM radcheck   WHERE Username = '0a-00-3e-47-df-7d'   ORDER BY id
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
2 , fields = 5
Sun Oct 27 14:52:05 2013 : Info: [sql] User found in radcheck table
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: SELECT id, UserName,
Attribute, Value, Op   FROM radreply   WHERE Username =
'%{SQL-User-Name}'   ORDER BY id -> SELECT id, UserName, Attribute, Value,
Op   FROM radreply   WHERE Username = '0a-00-3e-47-df-7d'   ORDER BY id
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
1 , fields = 5
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: SELECT GroupName FROM
radusergroup WHERE UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT
GroupName FROM radusergroup WHERE UserName='0a-00-3e-47-df-7d' ORDER BY
priority
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
1 , fields = 1
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: SELECT id, GroupName,
Attribute, Value, op   FROM radgroupcheck   WHERE GroupName =
'%{Sql-Group}'   ORDER BY id -> SELECT id, GroupName, Attribute, Value,
op   FROM radgroupcheck   WHERE GroupName = '450-3x1'   ORDER BY id
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
0 , fields = 5
Sun Oct 27 14:52:05 2013 : Info: [sql] User found in group 450-3x1
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: SELECT id, GroupName,
Attribute, Value, op   FROM radgroupreply   WHERE GroupName =
'%{Sql-Group}'   ORDER BY id -> SELECT id, GroupName, Attribute, Value,
op   FROM radgroupreply   WHERE GroupName = '450-3x1'   ORDER BY id
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
6 , fields = 5
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql (sql): Released sql socket id: 0
Sun Oct 27 14:52:05 2013 : Info: ++[sql] returns ok
Sun Oct 27 14:52:05 2013 : Info: ++[expiration] returns noop
Sun Oct 27 14:52:05 2013 : Info: ++[logintime] returns noop
Sun Oct 27 14:52:05 2013 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP
Sun Oct 27 14:52:05 2013 : Info: ++[pap] returns noop
Sun Oct 27 14:52:05 2013 : Info: WARNING: You set Proxy-To-Realm = LOCAL,
but the realm does not exist!  Cancelling invalid proxy request.
Sun Oct 27 14:52:05 2013 : Info: Found Auth-Type = MSCHAP
Sun Oct 27 14:52:05 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
Sun Oct 27 14:52:05 2013 : Info: +- entering group MS-CHAP {...}
Sun Oct 27 14:52:05 2013 : Info: [mschap] Creating challenge hash with
username: 0a-00-3e-47-df-7d
Sun Oct 27 14:52:05 2013 : Info: [mschap] Told to do MS-CHAPv2 for
0a-00-3e-47-df-7d with NT-Password
Sun Oct 27 14:52:05 2013 : Info: [mschap] FAILED: MS-CHAP2-Response is
incorrect
Sun Oct 27 14:52:05 2013 : Info: ++[mschap] returns reject
Sun Oct 27 14:52:05 2013 : Info: Failed to authenticate the user.
} # server inner-tunnel
Sun Oct 27 14:52:05 2013 : Info: [ttls] Got tunneled reply code 3
        Cleartext-Password := "0a-00-3e-47-df-7d"
        Motorola-Canopy-DLBL = 307200
        Motorola-Canopy-DLBR = 3072
        Motorola-Canopy-ULBL = 102400
        Motorola-Canopy-ULBR = 1024
        Motorola-Canopy-VLIGVID = 25
        Motorola-Canopy-VLMGVID = 24
        MS-CHAP-Error = "eE=691 R=1"
Sun Oct 27 14:52:05 2013 : Info: [ttls] Got tunneled Access-Reject
Sun Oct 27 14:52:05 2013 : Info: [eap] Handler failed in EAP/ttls
Sun Oct 27 14:52:05 2013 : Info: [eap] Failed in EAP select
Sun Oct 27 14:52:05 2013 : Info: ++[eap] returns invalid
Sun Oct 27 14:52:05 2013 : Info: Failed to authenticate the user.
Sun Oct 27 14:52:05 2013 : Info: Using Post-Auth-Type Reject
Sun Oct 27 14:52:05 2013 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Sun Oct 27 14:52:05 2013 : Info: +- entering group REJECT {...}
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: %{User-Name} ->
0a-00-3e-47-df-7d
Sun Oct 27 14:52:05 2013 : Info: [sql] sql_set_user escaped user -->
'0a-00-3e-47-df-7d'
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: %{User-Password} ->
Sun Oct 27 14:52:05 2013 : Info: [sql]  ... expanding second conditional
Sun Oct 27 14:52:05 2013 : Info: [sql]  expand: INSERT INTO radpostauth
(username, pass, reply, authdate)   VALUES ('%{User-Name}',
'%{%{User-Password}:-Chap-Password}', '%{reply:Packet-Type}', NOW()) ->
INSERT INTO radpostauth (username, pass, reply, authdate)   VALUES
('0a-00-3e-47-df-7d', 'Chap-Password', 'Access-Reject', NOW())
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql (sql) in sql_postauth: query is
INSERT INTO radpostauth (username, pass, reply, authdate)   VALUES
('0a-00-3e-47-df-7d', 'Chap-Password', 'Access-Reject', NOW())
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: Status:
PGRES_COMMAND_OK
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql_postgresql: query affected rows =
1
Sun Oct 27 14:52:05 2013 : Debug: rlm_sql (sql): Released sql socket id: 4
Sun Oct 27 14:52:05 2013 : Info: ++[sql] returns ok
Sun Oct 27 14:52:05 2013 : Info: Delaying reject of request 363 for 3
seconds
Sun Oct 27 14:52:05 2013 : Debug: Going to the next request
Sun Oct 27 14:52:05 2013 : Debug: Waking up in 0.9 seconds.
Sun Oct 27 14:52:06 2013 : Debug: Waking up in 1.9 seconds.
rad_recv: Access-Request packet from host 10.0.32.130 port 1238, id=0,
length=260
Sun Oct 27 14:52:07 2013 : Info: Waiting to send Access-Reject to client
test pmp450 port 1238 - ID: 0
Sun Oct 27 14:52:07 2013 : Debug: Waking up in 0.9 seconds.
Sun Oct 27 14:52:08 2013 : Info: Sending delayed reject for request 363
Sending Access-Reject of id 0 to 10.0.32.130 port 1238
        EAP-Message = 0x04040004
        Message-Authenticator = 0x00000000000000000000000000000000
Sun Oct 27 14:52:08 2013 : Debug: Waking up in 4.9 seconds.


-- 
Richard Carroll
richcarroll@gmail.com

getting auth reject

rich carroll