PEAP/MSCHAPv2, Post-Auth-Type REJECT {} of inner-tunnel is neverentered for access reject

Fads Afds down101load at yahoo.com.hk
Fri Jul 9 08:16:54 CEST 2010


Dear Alan,

   Thanks for your prompt reply and helpful information. 

    I tried to get the error-message of inner-tunnel by running sql query in "Post-Auth-Type Reject {} of default. The message field in radpostauth table is empty. The query seems cannot access %{inner.control:My-Err-Message} attribute. 
    My question is: Can sql in default (outer session) access innner-server control attribute when the login is rejected? If the answer is no, would you hint me how I can get & log the error message of inner-session? 
 
    Thanks again.

  After your reply, I include:
1. The warning message:
2. sql query for radpostauth
3. content of authorize section of file /etc/raddb/sites-available/default 
4. radiusd -X debug message for access-reject case

------------Alan's reply ---------------------------------------
 Fads Afds wrote:
> Hi Fellows,
>  
>    I have configured FreeRadius 2.1.8 running on SLES 11 for PEAP/MSCHAPv2. MySQL is used for user database. I have tested using "eapol_test" and win/XP SP3 supplicant.
>      Accounting data can be received & stored to radacct table.
>    Inner-server can successfully accept user with accumulated session time quota not exceeded and reject user with accumulated session time quota exceeded.
>    My problem:
>    I expect to store accept or reject log with rejecting message to radpostauth table. 
>    For access-accept case, sql inside post-auth {} of inner-tunnl is invoked and logging message is written to radpostauth table as expected. 
>    For access-reject cases (username not existed in db, wrong username, accumulated session time quota exceeded, etc), Post-Auth-Type REJECT {} of inner-tunnel is never entered. What is wrong? Any help?  Thanks in advance.

  The server does not currently run the "Post-Auth-Type Reject" when in
the inner tunnel.  Instead, it is run in the default virtual server,
outside of the tunnel.

  Alan DeKok.
-
-----------Alan's reply ends ------------------------------

    
-------------1. The warning message -------
[sql] WARNING: Unknown module "inner.control" in string expansion "%{inner.control:My-Err-Message}',
-------------1. ends --------------------------

------2. sql query for radpostauth ------------------
postauth_query = "INSERT INTO ${postauth_table} \
                          (ID, username, password, nas_ip, auth_result, reply_message, authdate) \
                          VALUES (NULL,  \
                          '%{User-Name}', \
                          aes_encrypt('NA', 'abc123456def'), \
                          '%{NAS-IP-ADDRESS}',  \
                          '%{reply:Packet-Type}',  \
                          '%{inner.control:My-Err-Message}', \
                          '%S')"

-----------------2. ends -----------------------------



-----3. content of Post-Auth-Type Reject{} section of file /etc/raddb/sites-available/default ---------------

Post-Auth-Type REJECT {
      sql
      reply_log
      attr_filter.access_reject
   }
----3. ends ------------------------------------------



----4. radiusd -X message for rejected case------------------------------
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Listening on proxy address * port 1814
Ready to process requests.
rad_recv: Access-Request packet from host 158.182.118.234 port 43514, id=159, length=168
        User-Name = "visit04"
        NAS-IP-Address = 158.182.118.234
        NAS-Port = 1
        NAS-Identifier = "158.182.118.234"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "34159EE8BD35"
        Called-Station-Id = "000B8609D780"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0201000c0176697369743034
        Aruba-Essid-Name = "BU-Guest"
        Aruba-Location-Id = "SRH-S906"
        Message-Authenticator = 0x5fbf723681bafb64473bda5fb613e4b4
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "visit04", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 1 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Flushing SSL sessions (of #0)
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 159 to 158.182.118.234 port 43514
        EAP-Message = 0x010200061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2451839f24539a76dd46fbeb200155bb
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 158.182.118.234 port 43514, id=160, length=310
        User-Name = "visit04"
        NAS-IP-Address = 158.182.118.234
        NAS-Port = 1
        NAS-Identifier = "158.182.118.234"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "34159EE8BD35"
        Called-Station-Id = "000B8609D780"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0202008819800000007e16030100790100007503014c36b96bd9a767fea76af8ea1ad3b3fe170ef44198d94e94e1d7f4d45eb7d95300003ac00ac009c007c008c013c014c011c012c004c005c002c003c00ec00fc00cc00d002f000500040035000a0009000300080033003900160015001401000012000a00080006001700180019000b00020100
        State = 0x2451839f24539a76dd46fbeb200155bb
        Aruba-Essid-Name = "BU-Guest"
        Aruba-Location-Id = "SRH-S906"
        Message-Authenticator = 0x807c6e2d452be6f72076f30aae603e1e
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "visit04", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 2 length 136
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 126
[peap] Length Included
[peap] eaptls_verify returned 11
[peap]     (other): before/accept initialization
[peap]     TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 0079], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 004a], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 084d], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap]     TLS_accept: SSLv3 write server done A
[peap]     TLS_accept: SSLv3 flush data
[peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 160 to 158.182.118.234 port 43514
        EAP-Message = 0x0103040019c0000008aa160301004a0200004603014c36b97de42d2baf0dfe1eaffecf9e25722e8e8bc582f3a8297b4a4096de4ea420747bba71baba01650b81ddf7414a3fb3d5ac2e003f9d20859ffc9ec61dd8fe59002f00160301084d0b0008490008460003a8308203a43082028ca003020102020101300d06092a864886f70d010104050030818c310b300906035504061302434e310b300906035504081302484b310c300a06035504071303656475310d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564752e686b312a302806035504031321484b425520477565
        EAP-Message = 0x737420434120636572742028363462697420736572766572293020170d3130303632343033353835305a180f32303530303631343033353835305a308182310b300906035504061302434e310b300906035504081302484b310d300b060355040a1304484b4255312e302c06035504031325484b42552047756573742073657276657220636572746966696361746520283634626974293127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564752e686b30820122300d06092a864886f70d01010105000382010f003082010a0282010100c7649ee337738ce465aec9a12a375bd4d76fc3c2f50ac701065d1433
        EAP-Message = 0x22c38dd78776d5ad0cb747a32f6b512dce6d26cccffefd49cf1517670305c6cb6eee0b70c86cb259383ca439bf011e8d8689cd17c41e99498256f13e6f14282b8eeef46f95e742d40254b69d7270d1d349e8cd41cff1dc98ea38fb494ea6007aed1575391d69e9f1c230fea9125f09a28d544282e9520e4c5987f54ff43f94567991d6172f98bfd3a200aeb07e60345e40caff2f1f34c52e77707e3321a774bc7601827ccbd723e044ee635de38dc174e37aea2640f5dbacb3454bd89bd2e03b81031365232fe8f014c069983950f75aa8fdcce7a9ee52d57dc7fec1512a57fabb3b993b0203010001a317301530130603551d25040c300a06082b0601
        EAP-Message = 0x0505070301300d06092a864886f70d01010405000382010100192613ffaf84004131ad7ce0d3da7b42d8a594371b96058ea7dc28554921dfd279076ad03cbf83ab81d7d3ac909202e97a3c22fdad6eee38f2961ef4e9cc9398c5e4bd8a0f41c9174d4fa44a1e77e95c887c065197300ea90c8ffc1d32c898c4e137b6a74834c769d7be8008fea4b3ca9c5a33505b588fd93fa440584d00f8c0c11d62bd886037289e5f27cec1039a4c311a04a7cf75b9ed578b840c66993dea65d31adf591ffc290d98d6565e70a1d3d45ae3f0c877c5104d1def8c23a79f38c92731165bfb2a84759f2c6c07e15ff75e4fe6f99e67dac4fc5ca7bf6cbdf849c44b77f6
        EAP-Message = 0x614977256b1dcde1b92a76f3
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2451839f25529a76dd46fbeb200155bb
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 158.182.118.234 port 43514, id=161, length=180
        User-Name = "visit04"
        NAS-IP-Address = 158.182.118.234
        NAS-Port = 1
        NAS-Identifier = "158.182.118.234"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "34159EE8BD35"
        Called-Station-Id = "000B8609D780"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020300061900
        State = 0x2451839f25529a76dd46fbeb200155bb
        Aruba-Essid-Name = "BU-Guest"
        Aruba-Location-Id = "SRH-S906"
        Message-Authenticator = 0xc129a38994a204510116e4a413e3fd4f
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "visit04", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 3 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 161 to 158.182.118.234 port 43514
        EAP-Message = 0x010403fc1940d8d084a884e20a2a165c46af33618c22000498308204943082037ca003020102020900a00b0c8b6ee723bb300d06092a864886f70d010105050030818c310b300906035504061302434e310b300906035504081302484b310c300a06035504071303656475310d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564752e686b312a302806035504031321484b425520477565737420434120636572742028363462697420736572766572293020170d3130303632343033353833335a180f32303530303631343033353833335a30818c310b30090603550406
        EAP-Message = 0x1302434e310b300906035504081302484b310c300a06035504071303656475310d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564752e686b312a302806035504031321484b4255204775657374204341206365727420283634626974207365727665722930820122300d06092a864886f70d01010105000382010f003082010a0282010100c001917da3c962085a616702fa98c2bd794c7edfa3a1f038258e018a126e736e3a61ae5120b956ab0566a9258b889d66e616e2d702b1a0f5ec79b1b484a9a9ec5ff3ba49d31895a6073ac132c9aa28f3e9906d0a6e3c24e852
        EAP-Message = 0x621586b8db41ce111ebf2befc143a5cc9d562d020594fe407135ec1c068dd0303eca75e5c5dd9cab898af3e870072ea3eca78602644eea0bac0c5619925b56aba1b1c1fc4c48fded87cdcf44d1b99a2c1f534e8b88e4a35f9d1ffa8a50cdb402743516a0cbce2a4796459501875ec225357d4a362202e15ee12a0154f018e5b84a5e5884c268d3154ed41f7b78ea2f6df852e07bdd50a55c26467bcaf75c41d393bc78b27fb5170203010001a381f43081f1301d0603551d0e04160414c134ca58d9d8f09b9207417630a08266b192ef523081c10603551d230481b93081b68014c134ca58d9d8f09b9207417630a08266b192ef52a18192a4818f3081
        EAP-Message = 0x8c310b300906035504061302434e310b300906035504081302484b310c300a06035504071303656475310d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564752e686b312a302806035504031321484b42552047756573742043412063657274202836346269742073657276657229820900a00b0c8b6ee723bb300c0603551d13040530030101ff300d06092a864886f70d010105050003820101000d81bb75569e9ce10ee1cc274ce224d6d175d681f14079bdb2953b179dc9e15eedecd08f8d61f1759f3bb4c97458573e0b9b6b6be66954fc48d713a54ad949e99d806a
        EAP-Message = 0x400957b5cd394c74
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2451839f26559a76dd46fbeb200155bb
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 158.182.118.234 port 43514, id=162, length=180
        User-Name = "visit04"
        NAS-IP-Address = 158.182.118.234
        NAS-Port = 1
        NAS-Identifier = "158.182.118.234"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "34159EE8BD35"
        Called-Station-Id = "000B8609D780"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x020400061900
        State = 0x2451839f26559a76dd46fbeb200155bb
        Aruba-Essid-Name = "BU-Guest"
        Aruba-Location-Id = "SRH-S906"
        Message-Authenticator = 0x840c9d88dbf3256afd4525a35ea49bd4
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "visit04", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 4 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 162 to 158.182.118.234 port 43514
        EAP-Message = 0x010500c4190012c062cd3163799ab42c262a3b39ee4aadeba8ca0584
be4afc188b998b5b79ebc112998a4791842e212835761d44b5202634a16bdc8886be5a2a6ddef1be
58fd73726f412c140197da3a29fc44aa1b67361c18f9f72312826067f64edc638e6a8b5511cd2c9e
d88cb6de9ef5c6c909025dc37b4abdc9fdc643561bb06b1e07e30de728a7e8a4dc07dda92896b897
6fedf2623b70b61a7757012cb421a8c76616030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2451839f27549a76dd46fbeb200155bb
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 158.182.118.234 port 43514, id=163, le
ngth=512
        User-Name = "visit04"
        NAS-IP-Address = 158.182.118.234
        NAS-Port = 1
        NAS-Identifier = "158.182.118.234"
        NAS-Port-Type = Wireless-802.11
        Calling-Station-Id = "34159EE8BD35"
        Called-Station-Id = "000B8609D780"
        Service-Type = Login-User
        Framed-MTU = 1100
        EAP-Message = 0x0205015019800000014616030101061000010201003bf0a1c7ffabbf
d264a9ed58e54032fa600764768552751ec7f53062cd5a9ebaa52c46c6d6473f0ca33765d222a337
0309fd496e403f48ffa250620d87d7e2b53adff292a0fe7aa59ce6c6a894c9a9f251310c58d2798e
462eaef1dd00f79a31fb4074edfeb033e90924c3f8d236a5155f28b1a3f99c6ec692afccca487db4
4f9a9044c7d837eebf3da89c3f8f4f441b1e7f89b8eb9ae31e4ace331184697e1becff07f91fae76
6b7db43ab8665fbf2fee0a1e60dc06b4da5372041ed4c3f0e8644c5833201b9fa612988d54f2909f
6a0c4378a46a93fb1c589f62dfe98b51d639aa10afc5cdfe22
        EAP-Message = 0x4c6390331da2262fadc0868cc2a68da17c72dc060fbeb7d814030100
0101160301003054624df5fcb87f023583a20ff07bded2d37e6bade2f35680bb627a67a08c3715fb
e34c1eab20dd678bebe49473239609
        State = 0x2451839f27549a76dd46fbeb200155bb
        Aruba-Essid-Name = "BU-Guest"
        Aruba-Location-Id = "SRH-S906"
        Message-Authenticator = 0x305bb4b0e144e78dc6a57741b74fcc54
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "visit04", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 5 length 253
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 326
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
[peap]     TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap]     TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 write finished A
[peap]     TLS_accept: SSLv3 flush data
  SSL: adding session 747bba71baba01650b81ddf7414a3fb3d5ac2e003f9d20859ffc9ec61d
d8fe59 to cache
[peap]     (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 163 to 158.182.118.234 port 43514
        EAP-Message = 0x0106004119001403010001011603010030eb029049a915c4eed9864c
22405237450831a8c271e7d0df2892e87916cd8c988d2f45f0d8295ee9b3a28fecb0b9cb26
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2451839f20579a76dd46fbeb200155bb
Finished request 4.
Going to the next request
Waking up in 4.8 seconds.
Cleaning up request 0 ID 159 with timestamp +1
Cleaning up request 1 ID 160 with timestamp +1
Cleaning up request 2 ID 161 with timestamp +1
Cleaning up request 3 ID 162 with timestamp +1
Cleaning up request 4 ID 163 with timestamp +1
Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=0, length=118
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0200000a0174696d6531
        Message-Authenticator = 0x92f180fdc088db77ec99a79a3853e8df
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 0 length 10
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[pap] WARNING! No "known good" password found for the user.  Authentication may
fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 0 to 127.0.0.1 port 44979
        EAP-Message = 0x010100061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee87916af76dd5fdb5b529c56e9d
Finished request 5.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=1, length=235
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0201006d198000000063160301005e0100005a03014c36b9940675bc
6559c07769a84fd3181a44bc79b9976f0ae1362e9afe4bb177000032003900380035008800870084
00160013000a00330032002f00450044004100050004001500120009001400110008000600030201
00
        State = 0x916bee87916af76dd5fdb5b529c56e9d
        Message-Authenticator = 0x8be06fd650f109fc2ad4ec626bcf639c
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 1 length 109
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 99
[peap] Length Included
[peap] eaptls_verify returned 11
[peap]     (other): before/accept initialization
[peap]     TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 005e], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 004a], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 084d], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange
[peap]     TLS_accept: SSLv3 write key exchange A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap]     TLS_accept: SSLv3 write server done A
[peap]     TLS_accept: SSLv3 flush data
[peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 1 to 127.0.0.1 port 44979
        EAP-Message = 0x0102040019c000000abc160301004a0200004603014c36b9948fd417
c358d194f7f033ae8cc5ff244d77ca8166fc6881b774d94ef32044540d0f50e26d1444cb5ce1d6f3
d574fbc20b1cddb9a708567434fa1bebc167003901160301084d0b0008490008460003a8308203a4
3082028ca003020102020101300d06092a864886f70d010104050030818c310b3009060355040613
02434e310b300906035504081302484b310c300a06035504071303656475310d300b060355040a13
04484b42553127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e
6564752e686b312a302806035504031321484b425520477565
        EAP-Message = 0x73742043412063657274202836346269742073657276657229302017
0d3130303632343033353835305a180f32303530303631343033353835305a308182310b30090603
5504061302434e310b300906035504081302484b310d300b060355040a1304484b4255312e302c06
035504031325484b4255204775657374207365727665722063657274696669636174652028363462
6974293127302506092a864886f70d0109011618726f6f7440667267756573742e686b62752e6564
752e686b30820122300d06092a864886f70d01010105000382010f003082010a0282010100c7649e
e337738ce465aec9a12a375bd4d76fc3c2f50ac701065d1433
        EAP-Message = 0x22c38dd78776d5ad0cb747a32f6b512dce6d26cccffefd49cf151767
0305c6cb6eee0b70c86cb259383ca439bf011e8d8689cd17c41e99498256f13e6f14282b8eeef46f
95e742d40254b69d7270d1d349e8cd41cff1dc98ea38fb494ea6007aed1575391d69e9f1c230fea9
125f09a28d544282e9520e4c5987f54ff43f94567991d6172f98bfd3a200aeb07e60345e40caff2f
1f34c52e77707e3321a774bc7601827ccbd723e044ee635de38dc174e37aea2640f5dbacb3454bd8
9bd2e03b81031365232fe8f014c069983950f75aa8fdcce7a9ee52d57dc7fec1512a57fabb3b993b
0203010001a317301530130603551d25040c300a06082b0601
        EAP-Message = 0x0505070301300d06092a864886f70d01010405000382010100192613
ffaf84004131ad7ce0d3da7b42d8a594371b96058ea7dc28554921dfd279076ad03cbf83ab81d7d3
ac909202e97a3c22fdad6eee38f2961ef4e9cc9398c5e4bd8a0f41c9174d4fa44a1e77e95c887c06
5197300ea90c8ffc1d32c898c4e137b6a74834c769d7be8008fea4b3ca9c5a33505b588fd93fa440
584d00f8c0c11d62bd886037289e5f27cec1039a4c311a04a7cf75b9ed578b840c66993dea65d31a
df591ffc290d98d6565e70a1d3d45ae3f0c877c5104d1def8c23a79f38c92731165bfb2a84759f2c
6c07e15ff75e4fe6f99e67dac4fc5ca7bf6cbdf849c44b77f6
        EAP-Message = 0x614977256b1dcde1b92a76f3
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee879069f76dd5fdb5b529c56e9d
Finished request 6.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=2, length=132
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020200061900
        State = 0x916bee879069f76dd5fdb5b529c56e9d
        Message-Authenticator = 0xd8afe5a5dd1ff493ea23d2bdcdf9ccde
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 2 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 2 to 127.0.0.1 port 44979
        EAP-Message = 0x010303fc1940d8d084a884e20a2a165c46af33618c22000498308204
943082037ca003020102020900a00b0c8b6ee723bb300d06092a864886f70d010105050030818c31
0b300906035504061302434e310b300906035504081302484b310c300a0603550407130365647531
0d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f744066726775
6573742e686b62752e6564752e686b312a302806035504031321484b425520477565737420434120
636572742028363462697420736572766572293020170d3130303632343033353833335a180f3230
3530303631343033353833335a30818c310b30090603550406
        EAP-Message = 0x1302434e310b300906035504081302484b310c300a06035504071303
656475310d300b060355040a1304484b42553127302506092a864886f70d0109011618726f6f7440
667267756573742e686b62752e6564752e686b312a302806035504031321484b4255204775657374
204341206365727420283634626974207365727665722930820122300d06092a864886f70d010101
05000382010f003082010a0282010100c001917da3c962085a616702fa98c2bd794c7edfa3a1f038
258e018a126e736e3a61ae5120b956ab0566a9258b889d66e616e2d702b1a0f5ec79b1b484a9a9ec
5ff3ba49d31895a6073ac132c9aa28f3e9906d0a6e3c24e852
        EAP-Message = 0x621586b8db41ce111ebf2befc143a5cc9d562d020594fe407135ec1c
068dd0303eca75e5c5dd9cab898af3e870072ea3eca78602644eea0bac0c5619925b56aba1b1c1fc
4c48fded87cdcf44d1b99a2c1f534e8b88e4a35f9d1ffa8a50cdb402743516a0cbce2a4796459501
875ec225357d4a362202e15ee12a0154f018e5b84a5e5884c268d3154ed41f7b78ea2f6df852e07b
dd50a55c26467bcaf75c41d393bc78b27fb5170203010001a381f43081f1301d0603551d0e041604
14c134ca58d9d8f09b9207417630a08266b192ef523081c10603551d230481b93081b68014c134ca
58d9d8f09b9207417630a08266b192ef52a18192a4818f3081
        EAP-Message = 0x8c310b300906035504061302434e310b300906035504081302484b31
0c300a06035504071303656475310d300b060355040a1304484b42553127302506092a864886f70d
0109011618726f6f7440667267756573742e686b62752e6564752e686b312a302806035504031321
484b42552047756573742043412063657274202836346269742073657276657229820900a00b0c8b
6ee723bb300c0603551d13040530030101ff300d06092a864886f70d010105050003820101000d81
bb75569e9ce10ee1cc274ce224d6d175d681f14079bdb2953b179dc9e15eedecd08f8d61f1759f3b
b4c97458573e0b9b6b6be66954fc48d713a54ad949e99d806a
        EAP-Message = 0x400957b5cd394c74
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee879368f76dd5fdb5b529c56e9d
Finished request 7.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=3, length=132
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020300061900
        State = 0x916bee879368f76dd5fdb5b529c56e9d
        Message-Authenticator = 0xea8dbecd0bbfd3fd3a2ecfa044306feb
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 3 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 3 to 127.0.0.1 port 44979
        EAP-Message = 0x010402d6190012c062cd3163799ab42c262a3b39ee4aadeba8ca0584
510b5f850ecbe4afc188b998b5b79ebc112998a4791842e212835761d44b5202634a16bdc8886be5
a2a6ddef1becbbaa64117a58fd73726f412c140197da3a29fc44aa1b67361c18f9f72312826067f6
4edc638e6a8b5511cd2c9eff129e700e0d88cb6de9ef5c6c909025dc37b4abdc9fdc643561bb06b1
e07e30de728a7e8a4dc07dda92896b8975d7907b85b66fedf2623b70b61a7757012cb421a8c76616
0301020d0c00020900808fcc5daaf65ec4b9ed53a13aa5563c3a857d7b01a0935ce18302cbbd8117
bdcee617438d810d33e6737c2b63ad1b1e728d85e9aa9c155d
        EAP-Message = 0x84c5499240de4a0574ca81181dd71a196f1dccceee978f8380d16b7e
6019d903f2d5ed2428b8649b958dbd4a5c52b8f99989c064eb651266552a0b7eab32727454b2eee7
89c78aee3b000102008006712a5b381bc117e45cbd7fab4a3f79b5de212697b11ea7050ea92387e2
bd8f55f1fcaed363ad2e59ac6ba4e20a502f5d9e320a4e67aa8a59c032fa7b1fa7c88ebf4f45a365
e247503763959d230aeba6d365560776fb3f1a37c7768df257ec6b8e874bbcc8725cc5cc3aabbf5a
a607b1ddb9aadc912084a35431ffd12d72280100567b7a139ef0b540f469f3152ea29b1279ce2c0b
e37d8b0589af62c0feabc70a4b75e169fbe19eaed05d94fd35
        EAP-Message = 0x0487fa6a7fb0deb69a9441ff459df22b562e61aea5b6d6a925ebddd2
734c0f91be9589c39f74308377167856c63654257d3b82c3e1cd1dc2078af6428cd457be9f4f16f7
8a57f6726e9008ae8a91446703c2409b24f8c1dc43824cec7d78baeb1c4bdedd15e6e7d646c11261
1e5f2fca452578637f56d7f8bc7fb70a5046bc5855a58c1a478b3a0d815d5a7a679dcda704ee07e0
f998917389ac127708a67b52b700b8d6fcd2e2b07b12255a72e7daa1641063f71fd4071d842283ac
dcf4f8cbafeb53d34c08874d672b4d0ed135e0948d32e316030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee87926ff76dd5fdb5b529c56e9d
Finished request 8.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=4, length=334
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020400d01980000000c6160301008610000082008033eddf5661f7ab
ee16b84267fd8caedf21933f4765a74e0225225c1a0f0fa34073f798a1c6fb78d1d8cce2a7233f96
c0e46dee307cbcc4fafbfeefed0cee3d4ace2cda38f588d621182cf7784b5cfadf4ae002cb1229fe
3c25cf8a84d651b9f1a48d5c653f24078908b3f76eabcbaf0336110ea6b5ce43bce7e9806b21f497
e11403010001011603010030c0fad5b2a8620a03c368f400561a18aa1ef9c47c812975c1200ee4d9
1b6f7ab876a8328439a8d6c46b92a9d9675d5ab6
        State = 0x916bee87926ff76dd5fdb5b529c56e9d
        Message-Authenticator = 0xcb67ce8cdef834a019f0bc172be79567
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 4 length 208
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 198
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
[peap]     TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap]     TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 write finished A
[peap]     TLS_accept: SSLv3 flush data
  SSL: adding session 44540d0f50e26d1444cb5ce1d6f3d574fbc20b1cddb9a708567434fa1b
ebc167 to cache
[peap]     (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 4 to 127.0.0.1 port 44979
        EAP-Message = 0x010500411900140301000101160301003023d4aff3b00678962d4461
db9937f233d330e52eb786e7f491bf95a2ff34e61403a6af4475b47928a9a9dc5ed504a7db
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee87956ef76dd5fdb5b529c56e9d
Finished request 9.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=5, length=132
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020500061900
        State = 0x916bee87956ef76dd5fdb5b529c56e9d
        Message-Authenticator = 0x6368b75534fe339b5807873da362c3ad
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 5 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake is finished
[peap] eaptls_verify returned 3
[peap] eaptls_process returned 3
[peap] EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 5 to 127.0.0.1 port 44979
        EAP-Message = 0x0106002b19001703010020875473c93e0b7cb56d652eb5fe471f11d9
35542130e98f57a3704a1b29200490
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee87946df76dd5fdb5b529c56e9d
Finished request 10.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=6, length=222
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020600601900170301002031960254e6cb92dd55e739f57bf9821c52
1ba47d45a525945bf075364b02362c1703010030430376a22471040f6ae116593bc609d44298483d
275e06234fb07925c512cc8e21911dc9580157366992019cd0648de2
        State = 0x916bee87946df76dd5fdb5b529c56e9d
        Message-Authenticator = 0xba24b8aee8858b6bfe01e4a0996df0d7
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 6 length 96
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Identity - time1
[peap] Got tunnled request
        EAP-Message = 0x0206000a0174696d6531
server (null) {
  PEAP: Got tunneled identity of time1
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to time1
Sending tunneled request
        EAP-Message = 0x0206000a0174696d6531
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
server inner-tunnel {
+- entering group authorize {...}
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 6 length 10
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[auth_log]      expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail
-%Y%m%d -> /var/log/radius/radacct/127.0.0.1/auth-detail-20100709
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expan
ds to /var/log/radius/radacct/127.0.0.1/auth-detail-20100709
[auth_log]      expand: %t -> Fri Jul  9 13:54:28 2010
++[auth_log] returns ok
[sql]   expand: %{User-Name} -> time1
[sql] sql_set_user escaped user --> 'time1'
rlm_sql (sql): Reserving sql socket id: 4
[sql]   expand: (SELECT id, username, attribute, value, op  FROM radcheck  WHERE
 username = '%{SQL-User-Name}' and attribute != 'Cleartext-Password') UNION (SEL
ECT id, username, attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck
 WHERE username = '%{SQL-User-Name}' and attribute = 'Cleartext-Password') ORDER
 BY id -> (SELECT id, username, attribute, value, op  FROM radcheck  WHERE usern
ame = 'time1' and attribute != 'Cleartext-Password') UNION (SELECT id, username,
 attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHERE username =
 'time1' and attribute = 'Cleartext-Password') ORDER BY id
rlm_sql_mysql: query:  (SELECT id, username, attribute, value, op  FROM radcheck
  WHERE username = 'time1' and attribute != 'Cleartext-Password') UNION (SELECT
id, username, attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHE
RE username = 'time1' and attribute = 'Cleartext-Password') ORDER BY id
[sql] User found in radcheck table
[sql]   expand: SELECT id, username, attribute, value, op           FROM radrepl
y           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT
id, username, attribute, value, op           FROM radreply           WHERE usern
ame = 'time1'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM
radreply           WHERE username = 'time1'           ORDER BY id
[sql]   expand: SELECT groupname          FROM radusergroup           WHERE user
name = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname
   FROM radusergroup           WHERE username = 'time1'           ORDER BY prior
ity
rlm_sql_mysql: query:  SELECT groupname          FROM radusergroup           WHE
RE username = 'time1'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
++? if (!(control:Cleartext-Password))
?? Evaluating (control:Cleartext-Password) -> TRUE
? Converting !TRUE -> FALSE
++? if (!(control:Cleartext-Password)) -> FALSE
++? elsif ((reply:acct_expiration) &&  ("%{reply:acct_expiration}" < "%D") )
?? Evaluating (reply:acct_expiration) -> TRUE
        expand: %{reply:acct_expiration} -> 29991231
        expand: %D -> 20100709
?? Evaluating ("%{reply:acct_expiration}" < "%D") -> FALSE
++? elsif ((reply:acct_expiration) &&  ("%{reply:acct_expiration}" < "%D") ) ->
FALSE
++? elsif ((reply:acct_expiration) && (reply:1st_login_date)  && (reply:ticket_e
xpiration) && ("%{reply:1st_login_date}" != "29991231") && ("%{reply:ticket_expi
ration}" < "%D") )
?? Evaluating (reply:acct_expiration) -> TRUE
?? Evaluating (reply:1st_login_date) -> TRUE
?? Evaluating (reply:ticket_expiration) -> TRUE
        expand: %{reply:1st_login_date} -> 20100601
?? Evaluating ("%{reply:1st_login_date}" != "29991231") -> TRUE
        expand: %{reply:ticket_expiration} -> 20100830
        expand: %D -> 20100709
?? Evaluating ("%{reply:ticket_expiration}" < "%D") -> FALSE
++? elsif ((reply:acct_expiration) && (reply:1st_login_date)  && (reply:ticket_e
xpiration) && ("%{reply:1st_login_date}" != "29991231") && ("%{reply:ticket_expi
ration}" < "%D") ) -> FALSE
rlm_sqlcounter: Entering module authorize code
sqlcounter_expand:  'SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%{
User-Name}''
[noreset_time_counter]  expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE U
serName='%{User-Name}' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserNam
e='time1'
sqlcounter_expand:  '%{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserNa
me='time1'}'
[noreset_time_counter] sql_xlat
[noreset_time_counter]  expand: %{User-Name} -> time1
[noreset_time_counter] sql_set_user escaped user --> 'time1'
[noreset_time_counter]  expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE U
serName='time1' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='time
1'
[noreset_time_counter]  expand: /var/log/radius/sqltrace.sql -> /var/log/radius/
sqltrace.sql
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_mysql: query:  SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='
time1'
[noreset_time_counter] sql_xlat finished
rlm_sql (sql): Released sql socket id: 3
[noreset_time_counter]  expand: %{sql:SELECT SUM(AcctSessionTime) FROM radacct W
HERE UserName='time1'} -> 205
rlm_sqlcounter: (Check item - counter) is less than zero
rlm_sqlcounter: Rejected user time1, check_item=20, counter=205
++[noreset_time_counter] returns reject
++? if (reject)
? Evaluating (reject) -> TRUE
++? if (reject) -> TRUE
++- entering if (reject) {...}
+++[control] returns reject
++- if (reject) returns reject
Invalid user (rlm_sqlcounter: Maximum never usage time reached): [time1/<via Aut
h-Type = EAP>] (from client localhost port 0 cli 02-00-00-00-00-01 via TLS tunne
l)
} # server inner-tunnel
[peap] Got tunneled reply code 3
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Reply-Message = "Your maximum never usage time has been reached"
[peap] Got tunneled reply RADIUS code 3
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Reply-Message = "Your maximum never usage time has been reached"
[peap] Tunneled authentication was rejected.
[peap] FAILURE
++[eap] returns handled
Sending Access-Challenge of id 6 to 127.0.0.1 port 44979
        EAP-Message = 0x0107003b190017030100300a7bc9169f55617f8b9404f23c70a22ec0
351e07fa46e1f17ec51bf9edddc23df774d9da16c92de9e5a5eb8ae95eaace
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x916bee87976cf76dd5fdb5b529c56e9d
Finished request 11.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 44979, id=7, length=222
        User-Name = "time1"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "02-00-00-00-00-01"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x0207006019001703010020e87fc62cb04cb5a8db18300f4f10d851de
97490da264270001365b5b2474578517030100309b29d0ffe622d696ca430fd4b2c7a86c0040aaa1
70818dc976eeb7338151522559da71fff0361565af9fb778cccf58b8
        State = 0x916bee87976cf76dd5fdb5b529c56e9d
        Message-Authenticator = 0x0132e061daaf8f9d3ae6d187066d3f04
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 7 length 96
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Received EAP-TLV response.
[peap]  Had sent TLV failure.  User was rejected earlier in this session.
  SSL: Removing session 44540d0f50e26d1444cb5ce1d6f3d574fbc20b1cddb9a708567434fa
1bebc167 from the cache
[eap] Handler failed in EAP/peap
[eap] Failed in EAP select
++[eap] returns invalid
Failed to authenticate the user.
Login incorrect: [time1/<via Auth-Type = EAP>] (from client localhost port 0 cli
 02-00-00-00-00-01)
Using Post-Auth-Type Reject
+- entering group REJECT {...}
[sql]   expand: %{User-Name} -> time1
[sql] sql_set_user escaped user --> 'time1'
[sql] WARNING: Unknown module "inner.control" in string expansion "%{inner.contr
ol:My-Err-Message}',
 '%S')"
[sql]   expand: INSERT INTO radpostauth                           (ID, username,
 password, nas_ip, auth_result, reply_message, authdate)
   VALUES (NULL,                            '%{User-Name}',
      aes_encrypt('NA', 'abc123456def'),                           '%{NAS-IP-ADD
RESS}',                            '%{reply:Packet-Type}',
      '%{inner.control:My-Err-Message}',
 '%S') -> INSERT INTO radpostauth                           (ID, username, passw
ord, nas_ip, auth_result, reply_message, authdate)                           VAL
UES (NULL,                            'time1',                           aes_enc
rypt('NA', 'abc123456def'),                           '127.0.0.1',
              'Access-Reject',                            '',
 '2010-07-09 13:54:28')
[sql]   expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
          (ID, username, password, nas_ip, auth_result, reply_message, authdate)
                           VALUES (NULL,                            'time1',
                       aes_encrypt('NA', 'abc123456def'),
    '127.0.0.1',                            'Access-Reject',
        '',                                                               '2010-
07-09 13:54:28')
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql_mysql: query:  INSERT INTO radpostauth                           (ID, us
ername, password, nas_ip, auth_result, reply_message, authdate)
          VALUES (NULL,                            'time1',
      aes_encrypt('NA', 'abc123456def'),                           '127.0.0.1',
                           'Access-Reject',                            '',
 '2010-07-09 13:54:28')
rlm_sql (sql): Released sql socket id: 2
++[sql] returns ok
[reply_log]     expand: /var/log/radius/radacct/%{Client-IP-Address}/reply-detai
l-%Y%m%d -> /var/log/radius/radacct/127.0.0.1/reply-detail-20100709
[reply_log] /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d exp
ands to /var/log/radius/radacct/127.0.0.1/reply-detail-20100709
[reply_log]     expand: %t -> Fri Jul  9 13:54:28 2010
++[reply_log] returns ok
[attr_filter.access_reject]     expand: %{User-Name} -> time1
 attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] returns updated
Delaying reject of request 12 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 12
Sending Access-Reject of id 7 to 127.0.0.1 port 44979
        EAP-Message = 0x04070004
        Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 3.9 seconds.
Cleaning up request 5 ID 0 with timestamp +24
Cleaning up request 6 ID 1 with timestamp +24
Cleaning up request 7 ID 2 with timestamp +24
Cleaning up request 8 ID 3 with timestamp +24
Cleaning up request 9 ID 4 with timestamp +24
Cleaning up request 10 ID 5 with timestamp +24
Cleaning up request 11 ID 6 with timestamp +24

----4. ends -------------------------


      





More information about the Freeradius-Users mailing list