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