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

8 Jul 2010

      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.

Cheers,
Joe

   Below include:
1. Content of post-auth section of file /etc/raddb/sites-available/inner-server:
2. content of authorize section of file /etc/raddb/sites-available/inner-server:
3. radiusd -X debug message for access-accept case
4. radiusd -X debug message for access-reject case

-------1.  Content of post-auth section of file /etc/raddb/sites-available/inner-server:---------
post-auth {
      #1st successful login and account NOT expired: update "ticket_expiration" and "1st_login_date" in table "radreply" by external script
   if ( ("%{reply:1st_login_date}" == "29991231") && ("%{reply:acct_expiration}" >= "%D") )   {
      #invoke external script by module "exec"
      1st_login_update
      noop
   }

   sql

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

----1. ends------------------------------------------------------------- 

----2.  Content of authorize {} section of file /etc/raddb/sites-available/inner-server:------
authorize {
 mschap
 update control {
          Proxy-To-Realm := LOCAL
   }

 eap {
      ok = return
   }

 auth_log
 sql
#Username NOT existed in db
  if (!(control:Cleartext-Password)) {
          update control {
            My-Err-Message := "Username %{request:User-Name} not existed in db"
            Post-Auth-Type := "REJECT"  //same result with or without this statement
          }
      reject
   }

 #account expired
   elsif ((reply:acct_expiration) &&  ("%{reply:acct_expiration}" < "%D") )  {
          update control {
                        My-Err-Message := "Your BU-Guest account has been expired since %{reply:acct_expiration}"
                        Post-Auth-Type := "REJECT"  //same result with or without this statement

          }
          reject
   }

   #account NOT expired. Already login before and ticket expired: Rejected and return message "Your BU-Guest ticket has expired"
   elsif ((reply:acct_expiration) && (reply:1st_login_date)  && (reply:ticket_expiration) && ("%{reply:1st_login_date}" != "29991231") && ("%{reply:ticket_expiration}" < "%D") )  {
          update control {
                        My-Err-Message := "Your BU-Guest ticket has been expired since %{reply:ticket_expiration}"
                        Post-Auth-Type := "REJECT"  //same result with or without this statement

          }
          reject
   }

  #for session-time quota, modify My-Err-Message if exceeded
  noreset_time_counter  {
      reject = 1
   }
   if (reject) {
      update control {
                  My-Err-Message := "Your session-time quota has been used up."
      }
      reject = return
   }

   #for session-traffic quota, modify My-Err-Message if exceeded
   noreset_traffic_counter {
      reject = 1
   }
   if (reject) {
      update control {
                  My-Err-Message := "Your session-traffic quota has been used up."
      }
      reject = return
   }

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

--------------3. radiusd -X debug message for access-accept 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 127.0.0.1 port 58342, id=0, length=118
        User-Name = "time3"
        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 = 0x0200000a0174696d6533
        Message-Authenticator = 0x86d8b188ea06f1e2db10c3c3f095378f
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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] Flushing SSL sessions (of #0)
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 0 to 127.0.0.1 port 58342
        EAP-Message = 0x010100061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c3420710d2d583cbd5e9f57d1d5e1
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 58342, id=1, length=235
        User-Name = "time3"
        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 = 0x0201006d198000000063160301005e0100005a03014c35a79c66aa56
b5c22cbfc40e708d0c8c7f35b5d8f5b657853a6a25057c2de3000032003900380035008800870084
00160013000a00330032002f00450044004100050004001500120009001400110008000600030201
00
        State = 0x710c3420710d2d583cbd5e9f57d1d5e1
        Message-Authenticator = 0xef0d3c6f293a95565fa98cb8eb7bc11e
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 58342
        EAP-Message = 0x0102040019c000000abc160301004a0200004603014c35a79c7bfdb3
61e9348ae2501e91aca3880058ed5258cf4b1ad43c4c1ee7522042bd3af4db1b4644e3a178f359c0
982943e723d7f05cd6cd24524614ee6c0313003901160301084d0b0008490008460003a8308203a4
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 = 0x710c3420700e2d583cbd5e9f57d1d5e1
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 58342, id=2, length=132
        User-Name = "time3"
        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 = 0x710c3420700e2d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x891c4b49a9002f7d191a0b0a552ce142
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 58342
        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 = 0x710c3420730f2d583cbd5e9f57d1d5e1
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 58342, id=3, length=132
        User-Name = "time3"
        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 = 0x710c3420730f2d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x79334670af1988e1500764f8893519a6
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 58342
        EAP-Message = 0x010402d6190012c062cd3163799ab42c262a3b39ee4aadeba8ca0584
510b5f850ecbe4afc188b998b5b79ebc112998a4791842e212835761d44b5202634a16bdc8886be5
a2a6ddef1becbbaa64117a58fd73726f412c140197da3a29fc44aa1b67361c18f9f72312826067f6
4edc638e6a8b5511cd2c9eff129e700e0d88cb6de9ef5c6c909025dc37b4abdc9fdc643561bb06b1
e07e30de728a7e8a4dc07dda92896b8975d7907b85b66fedf2623b70b61a7757012cb421a8c76616
0301020d0c00020900808fcc5daaf65ec4b9ed53a13aa5563c3a857d7b01a0935ce18302cbbd8117
bdcee617438d810d33e6737c2b63ad1b1e728d85e9aa9c155d
        EAP-Message = 0x84c5499240de4a0574ca81181dd71a196f1dccceee978f8380d16b7e
6019d903f2d5ed2428b8649b958dbd4a5c52b8f99989c064eb651266552a0b7eab32727454b2eee7
89c78aee3b000102008060d8a5934ce34b81cafd1c3fc8d46c5a388ed272c775dc16850bcf8d809b
5993441c997f71796739ce92d291e79f35676eb5c9bd803930ffbb7c1f1970328686307c6b6a6b33
22f3b0d6dcba4517a1af53ab3cf8a94ccc14999749239a1f1c141a3caab94646d10555148c750103
7469ed434c26f16fe521d5b9c63390591e9e010073b6d948f1730fabd195f88b32ab2073c1177e3f
8313ff0fb86c4516230d64748f4ad6e05d3a74c60a5e3771c5
        EAP-Message = 0xb48e7440d370543c830387f08a3c5f8deef8c1def77e7e7114997e5d
fcfa90d5d07d583b5e1913372411b2713f6c433f7feaf0cbb11357370479999f6ed5f02a67817c27
97f3e751f6e2636654cca929d4ea24237452d4ecc44466c0e5b8ef89e38d633335debe853d61d61a
f6e12e19984be1e4d05264eef13ffb0f4e295f30d6ccb0990906f3086641ebae82786bc7765ecc90
f7aafd63506946bc0d548f62c6fd3d3ccce0926860b91a4f44f8368a1cd6cef37b4299cb396a415a
4efb937eafe3460f003aa489ea61a63d3d645ed26883a716030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c342072082d583cbd5e9f57d1d5e1
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 58342, id=4, length=334
        User-Name = "time3"
        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 = 0x020400d01980000000c616030100861000008200801d83588e38d9da
df4ffe23f7ed3b2b90f36c0943746527fc0bb73b2c79a83dc173d0ec11b22f40f9fa76c19a6ea462
a2d9269ab0ea7f5550b600a937d2ad6732c27835d982a04e89c69ec524012ce45abadffdec3023be
60a2d2b26a3a0402508b51917d53c3c62dcae67677282e66794baa766791251219f7e9de3b739abe
7d1403010001011603010030ed2012e3aa97c24fa0a52ec354e56dfdc5b34487cc0e70fbb71eb3f8
5860f8eac1199394ced9ca49eb9563a06a35e79d
        State = 0x710c342072082d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x751c2b6c92f2074d37c88e84f2454e0d
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 42bd3af4db1b4644e3a178f359c0982943e723d7f05cd6cd24524614ee
6c0313 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 58342
        EAP-Message = 0x0105004119001403010001011603010030723f44d9944d700c443127
d161158b7db2f0787daccd60449dc6784b09a0a8d384d46ac7acac5b8084f40b7a9bc03f77
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c342075092d583cbd5e9f57d1d5e1
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 58342, id=5, length=132
        User-Name = "time3"
        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 = 0x710c342075092d583cbd5e9f57d1d5e1
        Message-Authenticator = 0xe84f03f178a81841fb46d3c61aa66e99
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 58342
        EAP-Message = 0x0106002b19001703010020745a8862fff74372e41763caf7ac58d0a9
10a05c983876e0f379e1d7752e07ef
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c3420740a2d583cbd5e9f57d1d5e1
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 58342, id=6, length=222
        User-Name = "time3"
        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 = 0x02060060190017030100204f0b0f1efbcee34d4265a97b4fc13660be
ff23b2408795c7ffc1a1c02227390e17030100300d3f41614731127eab3ca84d6cbfd7487854adc3
a6be922e4bd29675dad485590057a354a2723f2afd8b58c4e211661b
        State = 0x710c3420740a2d583cbd5e9f57d1d5e1
        Message-Authenticator = 0xbdc712363b5e27d3228a5a4d717c3bd6
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", 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 - time3
[peap] Got tunnled request
        EAP-Message = 0x0206000a0174696d6533
server (null) {
  PEAP: Got tunneled identity of time3
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to time3
Sending tunneled request
        EAP-Message = 0x0206000a0174696d6533
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "time3"
        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 = "time3", 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-20100708
[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-20100708
[auth_log]      expand: %t -> Thu Jul  8 18:25:32 2010
++[auth_log] returns ok
[sql]   expand: %{User-Name} -> time3
[sql] sql_set_user escaped user --> 'time3'
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 = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT id, username,
 attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHERE username =
 'time3' and attribute = 'Cleartext-Password') ORDER BY id
rlm_sql_mysql: query:  (SELECT id, username, attribute, value, op  FROM radcheck
  WHERE username = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT
id, username, attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHE
RE username = 'time3' 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 = 'time3'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM
radreply           WHERE username = 'time3'           ORDER BY id
[sql]   expand: SELECT groupname          FROM radusergroup           WHERE user
name = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname
   FROM radusergroup           WHERE username = 'time3'           ORDER BY prior
ity
rlm_sql_mysql: query:  SELECT groupname          FROM radusergroup           WHE
RE username = 'time3'           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 -> 20100708
?? 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 -> 20100708
?? 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='time3'
sqlcounter_expand:  '%{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserNa
me='time3'}'
[noreset_time_counter] sql_xlat
[noreset_time_counter]  expand: %{User-Name} -> time3
[noreset_time_counter] sql_set_user escaped user --> 'time3'
[noreset_time_counter]  expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE U
serName='time3' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='time
3'
[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='
time3'
[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='time3'} -> 314
rlm_sqlcounter: Check item is greater than query result
rlm_sqlcounter: Authorized user time3, check_item=4000000000, counter=314
rlm_sqlcounter: Sent Reply-Item for user time3, Type=Session-Timeout, value=3999
999686
++[noreset_time_counter] returns ok
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[noreset_traffic_counter] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x0107001f1a0107001a10fff84cf3de7f4c94dd82062ae0a7cc3a7469
6d6533
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x0a6fce370a68d41840671b0d943be774
[peap] Got tunneled reply RADIUS code 11
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x0107001f1a0107001a10fff84cf3de7f4c94dd82062ae0a7cc3a7469
6d6533
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x0a6fce370a68d41840671b0d943be774
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 6 to 127.0.0.1 port 58342
        EAP-Message = 0x0107004b19001703010040dcc0c868deed88fa3789019a7fea4c9f76
adf44ae61e81ee6667849626e5908b85dbe5a43227c582a624c356435ccad8d0249db5cbb190a77c
e4d8652b4bc46b
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c3420770b2d583cbd5e9f57d1d5e1
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 58342, id=7, length=270
        User-Name = "time3"
        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 = 0x0207009019001703010020d4d6a820410d0522989fa80aa89cec5b6e
14721ddccc2012d5e5c5c7214caeee17030100609922e3d2b5a68f441931df2eb4f29652a9111634
f2a22b98d51f5873e7034b798ac6660188bb1398c03e7cb9299417260b45ba08275c3ef3c7492f77
37672412dea92f4c9b13049b4a56421e5bcf158f9883c805399c096733f112a8b0e9873a
        State = 0x710c3420770b2d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x822422970a0a08993b17aa87398031b9
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 7 length 144
[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] EAP type mschapv2
[peap] Got tunnled request
        EAP-Message = 0x020700401a0207003b31ca83d4b3a63676473f79a8407ad5a3510000
00000000000072fec53acc650555265ec2e8be09158058c8f9d2f675a4a50074696d6533
server (null) {
  PEAP: Setting User-Name to time3
Sending tunneled request
        EAP-Message = 0x020700401a0207003b31ca83d4b3a63676473f79a8407ad5a3510000
00000000000072fec53acc650555265ec2e8be09158058c8f9d2f675a4a50074696d6533
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "time3"
        State = 0x0a6fce370a68d41840671b0d943be774
        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 = "time3", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 7 length 64
[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-20100708
[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-20100708
[auth_log]      expand: %t -> Thu Jul  8 18:25:32 2010
++[auth_log] returns ok
[sql]   expand: %{User-Name} -> time3
[sql] sql_set_user escaped user --> 'time3'
rlm_sql (sql): Reserving sql socket id: 2
[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 = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT id, username,
 attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHERE username =
 'time3' and attribute = 'Cleartext-Password') ORDER BY id
rlm_sql_mysql: query:  (SELECT id, username, attribute, value, op  FROM radcheck
  WHERE username = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT
id, username, attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHE
RE username = 'time3' 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 = 'time3'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM
radreply           WHERE username = 'time3'           ORDER BY id
[sql]   expand: SELECT groupname          FROM radusergroup           WHERE user
name = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname
   FROM radusergroup           WHERE username = 'time3'           ORDER BY prior
ity
rlm_sql_mysql: query:  SELECT groupname          FROM radusergroup           WHE
RE username = 'time3'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 2
++[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 -> 20100708
?? 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 -> 20100708
?? 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='time3'
sqlcounter_expand:  '%{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserNa
me='time3'}'
[noreset_time_counter] sql_xlat
[noreset_time_counter]  expand: %{User-Name} -> time3
[noreset_time_counter] sql_set_user escaped user --> 'time3'
[noreset_time_counter]  expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE U
serName='time3' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='time
3'
[noreset_time_counter]  expand: /var/log/radius/sqltrace.sql -> /var/log/radius/
sqltrace.sql
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_mysql: query:  SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='
time3'
[noreset_time_counter] sql_xlat finished
rlm_sql (sql): Released sql socket id: 1
[noreset_time_counter]  expand: %{sql:SELECT SUM(AcctSessionTime) FROM radacct W
HERE UserName='time3'} -> 314
rlm_sqlcounter: Check item is greater than query result
rlm_sqlcounter: Authorized user time3, check_item=4000000000, counter=314
rlm_sqlcounter: Sent Reply-Item for user time3, Type=Session-Timeout, value=3999
999686
++[noreset_time_counter] returns ok
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[noreset_traffic_counter] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] +- entering group MS-CHAP {...}
[mschap] Told to do MS-CHAPv2 for time3 with NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x010800331a0307002e533d4545334331373933383638393534324139
3230333839453445413539304631343245394331413644
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x0a6fce370b67d41840671b0d943be774
[peap] Got tunneled reply RADIUS code 11
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x010800331a0307002e533d4545334331373933383638393534324139
3230333839453445413539304631343245394331413644
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x0a6fce370b67d41840671b0d943be774
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 7 to 127.0.0.1 port 58342
        EAP-Message = 0x0108005b19001703010050e73c970ca872a0406dea9360b2831f3b4d
9960df3c69a3fbee615eeb461f2fd621df7bb4814edcbd8952534c49ff889f58899e53a1a6099006
bfe22eb8b1fdfeacfc1a435958aa40fb51e66f3f33ab3a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c342076042d583cbd5e9f57d1d5e1
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 58342, id=8, length=206
        User-Name = "time3"
        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 = 0x02080050190017030100208c1a2ad8f6faa9398231e3290f605b26d3
3f89f219417d2c4d81e7a5ce15783a17030100208f66bbcfa14f3568277f9989d3d544cfcb74e6a8
2e519f4d1212795b984a53e3
        State = 0x710c342076042d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x796dd15b9a449f6a220364198f52ca5d
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 8 length 80
[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] EAP type mschapv2
[peap] Got tunnled request
        EAP-Message = 0x020800061a03
server (null) {
  PEAP: Setting User-Name to time3
Sending tunneled request
        EAP-Message = 0x020800061a03
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "time3"
        State = 0x0a6fce370b67d41840671b0d943be774
        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 = "time3", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 8 length 6
[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-20100708
[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-20100708
[auth_log]      expand: %t -> Thu Jul  8 18:25:32 2010
++[auth_log] returns ok
[sql]   expand: %{User-Name} -> time3
[sql] sql_set_user escaped user --> 'time3'
rlm_sql (sql): Reserving sql socket id: 0
[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 = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT id, username,
 attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHERE username =
 'time3' and attribute = 'Cleartext-Password') ORDER BY id
rlm_sql_mysql: query:  (SELECT id, username, attribute, value, op  FROM radcheck
  WHERE username = 'time3' and attribute != 'Cleartext-Password') UNION (SELECT
id, username, attribute, aes_decrypt(value,'abc123456def'), op FROM radcheck WHE
RE username = 'time3' 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 = 'time3'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM
radreply           WHERE username = 'time3'           ORDER BY id
[sql]   expand: SELECT groupname          FROM radusergroup           WHERE user
name = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname
   FROM radusergroup           WHERE username = 'time3'           ORDER BY prior
ity
rlm_sql_mysql: query:  SELECT groupname          FROM radusergroup           WHE
RE username = 'time3'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 0
++[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 -> 20100708
?? 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 -> 20100708
?? 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='time3'
sqlcounter_expand:  '%{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserNa
me='time3'}'
[noreset_time_counter] sql_xlat
[noreset_time_counter]  expand: %{User-Name} -> time3
[noreset_time_counter] sql_set_user escaped user --> 'time3'
[noreset_time_counter]  expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE U
serName='time3' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='time
3'
[noreset_time_counter]  expand: /var/log/radius/sqltrace.sql -> /var/log/radius/
sqltrace.sql
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_mysql: query:  SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='
time3'
[noreset_time_counter] sql_xlat finished
rlm_sql (sql): Released sql socket id: 4
[noreset_time_counter]  expand: %{sql:SELECT SUM(AcctSessionTime) FROM radacct W
HERE UserName='time3'} -> 314
rlm_sqlcounter: Check item is greater than query result
rlm_sqlcounter: Authorized user time3, check_item=4000000000, counter=314
rlm_sqlcounter: Sent Reply-Item for user time3, Type=Session-Timeout, value=3999
999686
++[noreset_time_counter] returns ok
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[noreset_traffic_counter] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[eap] Freeing handler
++[eap] returns ok
Login OK: [time3] (from client localhost port 0 cli 02-00-00-00-00-01 via TLS tu
nnel)
+- entering group post-auth {...}
++? if (("%{reply:1st_login_date}" == "29991231") && ("%{reply:acct_expiration}"
...
= "%D") )
        expand: %{reply:1st_login_date} -> 20100601
?? Evaluating ("%{reply:1st_login_date}" == "29991231") -> FALSE
?? Skipping ("%{reply:acct_expiration}" >= "%D")
++? if (("%{reply:1st_login_date}" == "29991231") && ("%{reply:acct_expiration}"
= "%D") ) -> FALSE
[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-20100708
[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-20100708
[reply_log]     expand: %t -> Thu Jul  8 18:25:32 2010
++[reply_log] returns ok
[sql]   expand: %{User-Name} -> time3
[sql] sql_set_user escaped user --> 'time3'
[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}',
      '%{control:My-Err-Message}',
 '%S') -> INSERT INTO radpostauth                           (ID, username, passw
ord, nas_ip, auth_result, reply_message, authdate)                           VAL
UES (NULL,                            'time3',                           aes_enc
rypt('NA', 'abc123456def'),                           '127.0.0.1',
              'Access-Accept',                            '',
 '2010-07-08 18:25:32')
[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,                            'time3',
                       aes_encrypt('NA', 'abc123456def'),
    '127.0.0.1',                            'Access-Accept',
        '',                                                               '2010-
07-08 18:25:32')
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_mysql: query:  INSERT INTO radpostauth                           (ID, us
ername, password, nas_ip, auth_result, reply_message, authdate)
          VALUES (NULL,                            'time3',
      aes_encrypt('NA', 'abc123456def'),                           '127.0.0.1',
                           'Access-Accept',                            '',
 '2010-07-08 18:25:32')
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
} # server inner-tunnel
[peap] Got tunneled reply code 2
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "time3"
[peap] Got tunneled reply RADIUS code 2
        1st_login_date := "20100601"
        acct_expiration := "29991231"
        ticket_days := "90"
        ticket_expiration := "20100830"
        Session-Timeout = 3999999686
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "time3"
[peap] Tunneled authentication was successful.
[peap] SUCCESS
[peap] Saving tunneled attributes for later
++[eap] returns handled
Sending Access-Challenge of id 8 to 127.0.0.1 port 58342
        EAP-Message = 0x0109003b190017030100303e08b1a2d1b28a52af62ee2de46fc70bb5
1f2c8876b709dc033eb67dac4e7d107d42328990db41d176b866c9b5dc3462
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x710c342079052d583cbd5e9f57d1d5e1
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 58342, id=9, length=222
        User-Name = "time3"
        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 = 0x0209006019001703010020f5e34f99dabb9426b2cc077cd20d75cb1f
6d178a72b0136017f56929a9ebe876170301003069dd3e6ac821e2782dc47cab7eed4e0de694f6d0
49d02248c6e282c7d2f80b70690eac89370dbb302e008b76429ad113
        State = 0x710c342079052d583cbd5e9f57d1d5e1
        Message-Authenticator = 0x2e48e39d1253678a90df25d2cbeb7ce3
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "time3", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 9 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] Success
[peap] Using saved attributes from the original Access-Accept
[peap] Saving response in the cache
[eap] Freeing handler
++[eap] returns ok
Login OK: [time3] (from client localhost port 0 cli 02-00-00-00-00-01)
Sending Access-Accept of id 9 to 127.0.0.1 port 58342
        Session-Timeout = 3999999686
        User-Name = "time3"
        MS-MPPE-Recv-Key = 0xcfc895845e6aca093ab94dcd81afd5096eac3b2ca11ec8bd708
711bd6f520f97
        MS-MPPE-Send-Key = 0xe82169d80dd32224262bded10d64df4472ece71e5d99b29a578
3ca4f590d0a64
        EAP-Message = 0x03090004
        Message-Authenticator = 0x00000000000000000000000000000000
Finished request 9.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 0 ID 0 with timestamp +9
Cleaning up request 1 ID 1 with timestamp +9
Cleaning up request 2 ID 2 with timestamp +9
Cleaning up request 3 ID 3 with timestamp +9
Cleaning up request 4 ID 4 with timestamp +9
Cleaning up request 5 ID 5 with timestamp +9
Cleaning up request 6 ID 6 with timestamp +9
Cleaning up request 7 ID 7 with timestamp +9
Cleaning up request 8 ID 8 with timestamp +9
Cleaning up request 9 ID 9 with timestamp +9
Ready to process requests.

---3. ends------------------------------------------------------------

---------4. radiusd -X debug message for access-reject 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 127.0.0.1 port 49468, 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 = 0x24f4eb8ed73570357fa509e716f4ec3a
+- 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] Flushing SSL sessions (of #0)
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 0 to 127.0.0.1 port 49468
        EAP-Message = 0x010100061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x379da9e0379cb0870007f99580c2a718
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 49468, 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 = 0x0201006d198000000063160301005e0100005a03014c35a8163bcc47
f3eeba48e97b7cabeda316ba25231834b83b7576019349dd53000032003900380035008800870084
00160013000a00330032002f00450044004100050004001500120009001400110008000600030201
00
        State = 0x379da9e0379cb0870007f99580c2a718
        Message-Authenticator = 0x7051a1856d18e6337c951776482ca698
+- 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 49468
        EAP-Message = 0x0102040019c000000abc160301004a0200004603014c35a81667db13
e25f9bd85df914215360be8e2418dd50ed30f6b066d6aadfc42066e05cf10dd059ad56a7d8a36cb5
0353917b6f4635d6a24b23d44c25faea1c00003901160301084d0b0008490008460003a8308203a4
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 = 0x379da9e0369fb0870007f99580c2a718
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 49468, 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 = 0x379da9e0369fb0870007f99580c2a718
        Message-Authenticator = 0x1ab17d06723c9f5f8f9bf484468c6dc5
+- 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 49468
        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 = 0x379da9e0359eb0870007f99580c2a718
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 49468, 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 = 0x379da9e0359eb0870007f99580c2a718
        Message-Authenticator = 0x48ddac2a23034188ff380052d31d8a44
+- 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 49468
        EAP-Message = 0x010402d6190012c062cd3163799ab42c262a3b39ee4aadeba8ca0584
510b5f850ecbe4afc188b998b5b79ebc112998a4791842e212835761d44b5202634a16bdc8886be5
a2a6ddef1becbbaa64117a58fd73726f412c140197da3a29fc44aa1b67361c18f9f72312826067f6
4edc638e6a8b5511cd2c9eff129e700e0d88cb6de9ef5c6c909025dc37b4abdc9fdc643561bb06b1
e07e30de728a7e8a4dc07dda92896b8975d7907b85b66fedf2623b70b61a7757012cb421a8c76616
0301020d0c00020900808fcc5daaf65ec4b9ed53a13aa5563c3a857d7b01a0935ce18302cbbd8117
bdcee617438d810d33e6737c2b63ad1b1e728d85e9aa9c155d
        EAP-Message = 0x84c5499240de4a0574ca81181dd71a196f1dccceee978f8380d16b7e
6019d903f2d5ed2428b8649b958dbd4a5c52b8f99989c064eb651266552a0b7eab32727454b2eee7
89c78aee3b00010200802d40d68a213037fdef2a05b0d02557ad19514062a6c2b6b77514fd1c15a1
3933b75408fca1c9a173e2cb20808dc07fffb36fc03e041b17e407ccc97a6c2d7f1f91b3a9e0d248
f2dc467c3aec0912ca55badcf050965c6138dff792352fa2292f92a152149a5f5cf7961a5c1e9656
b7be37b32b22d9f677473e118e41b63b0a8c010017a57998cc2de71d0802f9766a65e11f23cd01db
a7580d288f40939c2c03e243e1dfbf8b14f9ac287474fe444e
        EAP-Message = 0xe026a49e96cdf3c242e82468aaf6e46fc45f16517d36d91a2a014805
0a1d39fb3b83505165efb521155a4cafb52c3ed39d5bb7950f9fd3d4cb6d38e7a790b5ad63064fae
c1792f3e5ce8e811f991a2ca0e687146ed2d3d4fce292922c8fb820058f9385703a984f6f34ce14b
9c2919f7efc83e9b3173bdb14403ea336c4ce9a36173ebf7c59142b0fdf2a57dc568453512ddf1a9
aae97bd70550d99c001c62b5265a49aa276f0fc854f8d69c145125020662caac7bcff0f71955c5e5
c0448184b0b0cfbd48409afec8bb1029595b585034991416030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x379da9e03499b0870007f99580c2a718
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 49468, 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 = 0x020400d01980000000c61603010086100000820080467a2d89b7410f
afe4361812717c3cec8717c16174a7e281b953d403a7773e8d6479fb7a0db7ecbd39f8b221bc892c
e53c59806567d87532666bf0bb115fd666e64f00c2736933ed590bf8ee24f253bdeecca351ec9a29
c467089d4b1b96afb0e8365fecb17dc727289a21786810c9a85af0bd459190512000905dc6780ca6
ef1403010001011603010030744197a78d5f100a2b1e0dde24bef68f84fe93ac677aeb3d028edcfc
1cbc4e6996be46522959cf1556c5c8386a508b77
        State = 0x379da9e03499b0870007f99580c2a718
        Message-Authenticator = 0xf65a0c170c026c7e4e0e661823bd744e
+- 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 66e05cf10dd059ad56a7d8a36cb50353917b6f4635d6a24b23d44c25fa
ea1c00 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 49468
        EAP-Message = 0x01050041190014030100010116030100304e5c1baf2a1b8d5d2a18b7
c4d1c1a3f22154ee783c7db5fd17ea3e0a7fd2ab6d247705d7edda9f423498bed6aeafbdf9
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x379da9e03398b0870007f99580c2a718
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 49468, 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 = 0x379da9e03398b0870007f99580c2a718
        Message-Authenticator = 0x12fb97053e91f203df1581c6975b8c01
+- 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 49468
        EAP-Message = 0x0106002b190017030100201171e1d1767e10f9d06c480a092e9b8ba3
c07b0e05262131dd5705132f367257
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x379da9e0329bb0870007f99580c2a718
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 49468, 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 = 0x0206006019001703010020a9d556b45919401ae1e4790740371c1be9
d6ed285273ed06042e3ec0bd020c471703010030a782020930967cc5584d7791eeeb903ef19a6ad8
5588c048606fba479e03a8ad8ee74ef22f1f16a685d6e3f142564c55
        State = 0x379da9e0329bb0870007f99580c2a718
        Message-Authenticator = 0xd9002ff440753be497004076fb58a195
+- 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-20100708
[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-20100708
[auth_log]      expand: %t -> Thu Jul  8 18:27:34 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 -> 20100708
?? 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 -> 20100708
?? 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 49468
        EAP-Message = 0x0107003b19001703010030d0af2dcdbaada51c12d0570f41e8542218
7c12e87263aa128b7647209c78495a9ebc2ae2ade479af15debdfbed77aa3f
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x379da9e0319ab0870007f99580c2a718
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 49468, 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 = 0x02070060190017030100202178f5d5c8f7282c6e2609da3fec65309e
f28ebeadf1dce71e775f3bdab51a1817030100300f13973ec6c006332d406b716cefe650fe7a9462
eed07219b551403dbec4b6d042a2025fe07f3b07314212ce9f57a4b9
        State = 0x379da9e0319ab0870007f99580c2a718
        Message-Authenticator = 0x9976397d6fffc38a9e78034df8c3a0d5
+- 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 66e05cf10dd059ad56a7d8a36cb50353917b6f4635d6a24b23d44c25
faea1c00 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 {...}
++- group REJECT returns noop
Delaying reject of request 7 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 7
Sending Access-Reject of id 7 to 127.0.0.1 port 49468
        EAP-Message = 0x04070004
        Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 3.9 seconds.
Cleaning up request 0 ID 0 with timestamp +2
Cleaning up request 1 ID 1 with timestamp +2
Cleaning up request 2 ID 2 with timestamp +2
Cleaning up request 3 ID 3 with timestamp +2
Cleaning up request 4 ID 4 with timestamp +2
Cleaning up request 5 ID 5 with timestamp +2
Cleaning up request 6 ID 6 with timestamp +2
Waking up in 0.9 seconds.
Cleaning up request 7 ID 7 with timestamp +2
Ready to process requests.

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

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

Fads Afds