disconnect same user both whatever

佛来佛网 314186514 at qq.com
Mon May 6 15:12:12 CEST 2019


Hi Guys,


sorry , I am not good at English.


I have configured strongswan + freeradius working well. 


now I want user ( for example“test”)disconnect  the same user  when he connect  whatever .




I write this :


###################################


authorize {


        update disconnect{
                &User-Name = "%{User-Name}"
        }
 
        if(User-Name){


                       if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){


          }
}




filter_username




... ...


}


######################################


some times  it works and some times not works


this is  works good  log


#######################################
Sun May  5 09:45:45 2019 : Debug: (134) Received Access-Request Id 168 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163
Sun May  5 09:45:45 2019 : Debug: (134)   User-Name = "test"
Sun May  5 09:45:45 2019 : Debug: (134)   NAS-Port-Type = Virtual
Sun May  5 09:45:45 2019 : Debug: (134)   Service-Type = Framed-User
Sun May  5 09:45:45 2019 : Debug: (134)   NAS-Port = 236
Sun May  5 09:45:45 2019 : Debug: (134)   NAS-Port-Id = "IKEv2-EAP"
Sun May  5 09:45:45 2019 : Debug: (134)   NAS-IP-Address = 192.168.100.11
Sun May  5 09:45:45 2019 : Debug: (134)   Called-Station-Id = "192.168.100.11[4500]"
Sun May  5 09:45:45 2019 : Debug: (134)   Calling-Station-Id = "153.119.175.39[56047]"
Sun May  5 09:45:45 2019 : Debug: (134)   Acct-Session-Id = "1557059862-236"
Sun May  5 09:45:45 2019 : Debug: (134)   EAP-Message = 0x020000090174657374
Sun May  5 09:45:45 2019 : Debug: (134)   NAS-Identifier = "strongSwan"
Sun May  5 09:45:45 2019 : Debug: (134)   Message-Authenticator = 0x3111389892946d1452bab86037789b9e
Sun May  5 09:45:45 2019 : Debug: (134) session-state: No State attribute
Sun May  5 09:45:45 2019 : Debug: (134) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (134)   authorize {
Sun May  5 09:45:45 2019 : Debug: (134)     update disconnect {
Sun May  5 09:45:45 2019 : Debug: (134)       EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (134)          --> test
Sun May  5 09:45:45 2019 : Debug: (134)       &User-Name = test
Sun May  5 09:45:45 2019 : Debug: (134)     } # update disconnect = noop
Sun May  5 09:45:45 2019 : Debug: (134)     if (User-Name){
Sun May  5 09:45:45 2019 : Debug: (134)     if (User-Name) -> TRUE
Sun May  5 09:45:45 2019 : Debug: (134)     if (User-Name) {
Sun May  5 09:45:45 2019 : Debug: (134)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May  5 09:45:45 2019 : Debug: %{User-Name}
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:45 2019 : Debug: (134)       EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (134)          --> test
Sun May  5 09:45:45 2019 : Debug: (134)       SQL-User-Name set to 'test'
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (53)
Sun May  5 09:45:45 2019 : Debug: (134)       Executing select query:  UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May  5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
Sun May  5 09:45:45 2019 : Debug: (134)       SQL query returned no results
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (53)
Sun May  5 09:45:45 2019 : Info: Need 2 more connections to reach 10 spares
Sun May  5 09:45:45 2019 : Info: rlm_sql (sql): Opening additional connection (60), 1 of 24 pending slots used
Sun May  5 09:45:45 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May  5 09:45:45 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May  5 09:45:45 2019 : Debug: (134)       EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May  5 09:45:45 2019 : Debug: (134)          --> 
Sun May  5 09:45:45 2019 : Debug: (134)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)     } # if (User-Name) = noop
Sun May  5 09:45:45 2019 : Debug: (134)     policy filter_username {
Sun May  5 09:45:45 2019 : Debug: (134)       if (&User-Name) {
Sun May  5 09:45:45 2019 : Debug: (134)       if (&User-Name)  -> TRUE
Sun May  5 09:45:45 2019 : Debug: (134)       if (&User-Name)  {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ / /) {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ / /)  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /@[^@]*@/ ) {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /\.\./ ) {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /\.\./ )  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Sun May  5 09:45:45 2019 : Debug: (134)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /\.$/)  {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /\.$/)   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /@\./)  {
Sun May  5 09:45:45 2019 : Debug: (134)         if (&User-Name =~ /@\./)   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (134)       } # if (&User-Name)  = noop
Sun May  5 09:45:45 2019 : Debug: (134)     } # policy filter_username = noop
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May  5 09:45:45 2019 : Debug: (134)     [preprocess] = ok
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling chap (rlm_chap)
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from chap (rlm_chap)
Sun May  5 09:45:45 2019 : Debug: (134)     [chap] = noop
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling mschap (rlm_mschap)
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May  5 09:45:45 2019 : Debug: (134)     [mschap] = noop
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling digest (rlm_digest)
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from digest (rlm_digest)
Sun May  5 09:45:45 2019 : Debug: (134)     [digest] = noop
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling suffix (rlm_realm)
Sun May  5 09:45:45 2019 : Debug: (134) suffix: Checking for suffix after "@"
Sun May  5 09:45:45 2019 : Debug: (134) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May  5 09:45:45 2019 : Debug: (134) suffix: No such realm "NULL"
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from suffix (rlm_realm)
Sun May  5 09:45:45 2019 : Debug: (134)     [suffix] = noop
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: calling eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (134) eap: Peer sent EAP Response (code 2) ID 0 length 9
Sun May  5 09:45:45 2019 : Debug: (134) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authorize]: returned from eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (134)     [eap] = ok
Sun May  5 09:45:45 2019 : Debug: (134)   } # authorize = ok
Sun May  5 09:45:45 2019 : Debug: (134) Found Auth-Type = eap
Sun May  5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (134)   authenticate {
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authenticate]: calling eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (134) eap: Peer sent packet with method EAP Identity (1)
Sun May  5 09:45:45 2019 : Debug: (134) eap: Calling submodule eap_md5 to process data
Sun May  5 09:45:45 2019 : Debug: (134) eap_md5: Issuing MD5 Challenge
Sun May  5 09:45:45 2019 : Debug: (134) eap: Sending EAP Request (code 1) ID 1 length 22
Sun May  5 09:45:45 2019 : Debug: (134) eap: EAP session adding &reply:State = 0x3288c5703289c17c
Sun May  5 09:45:45 2019 : Debug: (134)     modsingle[authenticate]: returned from eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (134)     [eap] = handled
Sun May  5 09:45:45 2019 : Debug: (134)   } # authenticate = handled
Sun May  5 09:45:45 2019 : Debug: (134) Using Post-Auth-Type Challenge
Sun May  5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (134)   Challenge { ... } # empty sub-section is ignored
Sun May  5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache
Sun May  5 09:45:45 2019 : Debug: (134) Empty pre-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:45:45 2019 : Debug: (134) proxy: Trying to allocate ID (0/2)
Sun May  5 09:45:45 2019 : Debug: (134) proxy: request is now in proxy hash
Sun May  5 09:45:45 2019 : Debug: (134) proxy: allocating destination 192.168.100.11 port 3799 - Id 62
Sun May  5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache
Sun May  5 09:45:45 2019 : Debug: (134) Sent Disconnect-Request Id 62 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May  5 09:45:45 2019 : Debug: (134)   User-Name = "test"
Sun May  5 09:45:45 2019 : Debug: (134) Sent Access-Challenge Id 168 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May  5 09:45:45 2019 : Debug: (134)   EAP-Message = 0x010100160410d93a974e96d012a501eb4786e0dd3e77
Sun May  5 09:45:45 2019 : Debug: (134)   Message-Authenticator = 0x00000000000000000000000000000000
Sun May  5 09:45:45 2019 : Debug: (134)   State = 0x3288c5703289c17c78ded5beb28006bf
Sun May  5 09:45:45 2019 : Debug: (134) Finished request
Sun May  5 09:45:45 2019 : Debug: Waking up in 2.5 seconds.
Sun May  5 09:45:45 2019 : Debug: (134) Clearing existing &reply: attributes
Sun May  5 09:45:45 2019 : Debug: (134) Received Disconnect-NAK Id 62 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May  5 09:45:45 2019 : Debug: (134) Empty post-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:45:45 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867
Sun May  5 09:45:45 2019 : Debug: Waking up in 4.9 seconds.


Sun May  5 09:45:45 2019 : Debug: (135) Received Access-Request Id 169 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194
Sun May  5 09:45:45 2019 : Debug: (135)   User-Name = "test"
Sun May  5 09:45:45 2019 : Debug: (135)   NAS-Port-Type = Virtual
Sun May  5 09:45:45 2019 : Debug: (135)   Service-Type = Framed-User
Sun May  5 09:45:45 2019 : Debug: (135)   NAS-Port = 236
Sun May  5 09:45:45 2019 : Debug: (135)   NAS-Port-Id = "IKEv2-EAP"
Sun May  5 09:45:45 2019 : Debug: (135)   NAS-IP-Address = 192.168.100.11
Sun May  5 09:45:45 2019 : Debug: (135)   Called-Station-Id = "192.168.100.11[4500]"
Sun May  5 09:45:45 2019 : Debug: (135)   Calling-Station-Id = "153.119.175.39[56047]"
Sun May  5 09:45:45 2019 : Debug: (135)   Acct-Session-Id = "1557059862-236"
Sun May  5 09:45:45 2019 : Debug: (135)   EAP-Message = 0x020100160410ce217178fb4d579d68d54a027effd329
Sun May  5 09:45:45 2019 : Debug: (135)   NAS-Identifier = "strongSwan"
Sun May  5 09:45:45 2019 : Debug: (135)   State = 0x3288c5703289c17c78ded5beb28006bf
Sun May  5 09:45:45 2019 : Debug: (135)   Message-Authenticator = 0x59fec2cedd5cf0d2f07cb53382317673
Sun May  5 09:45:45 2019 : Debug: (135) session-state: No cached attributes
Sun May  5 09:45:45 2019 : Debug: (135) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (135)   authorize {
Sun May  5 09:45:45 2019 : Debug: (135)     update disconnect {
Sun May  5 09:45:45 2019 : Debug: (135)       EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (135)          --> test
Sun May  5 09:45:45 2019 : Debug: (135)       &User-Name = test
Sun May  5 09:45:45 2019 : Debug: (135)     } # update disconnect = noop
Sun May  5 09:45:45 2019 : Debug: (135)     if (User-Name){
Sun May  5 09:45:45 2019 : Debug: (135)     if (User-Name) -> TRUE
Sun May  5 09:45:45 2019 : Debug: (135)     if (User-Name) {
Sun May  5 09:45:45 2019 : Debug: (135)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May  5 09:45:45 2019 : Debug: %{User-Name}
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:45 2019 : Debug: (135)       EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (135)          --> test
Sun May  5 09:45:45 2019 : Debug: (135)       SQL-User-Name set to 'test'
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (55)
Sun May  5 09:45:45 2019 : Debug: (135)       Executing select query:  UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May  5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
Sun May  5 09:45:45 2019 : Debug: (135)       SQL query returned no results
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (55)
Sun May  5 09:45:45 2019 : Debug: (135)       EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May  5 09:45:45 2019 : Debug: (135)          --> 
Sun May  5 09:45:45 2019 : Debug: (135)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)     } # if (User-Name) = noop
Sun May  5 09:45:45 2019 : Debug: (135)     policy filter_username {
Sun May  5 09:45:45 2019 : Debug: (135)       if (&User-Name) {
Sun May  5 09:45:45 2019 : Debug: (135)       if (&User-Name)  -> TRUE
Sun May  5 09:45:45 2019 : Debug: (135)       if (&User-Name)  {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ / /) {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ / /)  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /@[^@]*@/ ) {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /\.\./ ) {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /\.\./ )  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Sun May  5 09:45:45 2019 : Debug: (135)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /\.$/)  {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /\.$/)   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /@\./)  {
Sun May  5 09:45:45 2019 : Debug: (135)         if (&User-Name =~ /@\./)   -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)       } # if (&User-Name)  = noop
Sun May  5 09:45:45 2019 : Debug: (135)     } # policy filter_username = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May  5 09:45:45 2019 : Debug: (135)     [preprocess] = ok
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling chap (rlm_chap)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from chap (rlm_chap)
Sun May  5 09:45:45 2019 : Debug: (135)     [chap] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling mschap (rlm_mschap)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May  5 09:45:45 2019 : Debug: (135)     [mschap] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling digest (rlm_digest)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from digest (rlm_digest)
Sun May  5 09:45:45 2019 : Debug: (135)     [digest] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling suffix (rlm_realm)
Sun May  5 09:45:45 2019 : Debug: (135) suffix: Checking for suffix after "@"
Sun May  5 09:45:45 2019 : Debug: (135) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May  5 09:45:45 2019 : Debug: (135) suffix: No such realm "NULL"
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from suffix (rlm_realm)
Sun May  5 09:45:45 2019 : Debug: (135)     [suffix] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (135) eap: Peer sent EAP Response (code 2) ID 1 length 22
Sun May  5 09:45:45 2019 : Debug: (135) eap: No EAP Start, assuming it's an on-going EAP conversation
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (135)     [eap] = updated
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling files (rlm_files)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from files (rlm_files)
Sun May  5 09:45:45 2019 : Debug: (135)     [files] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling sql (rlm_sql)
Sun May  5 09:45:45 2019 : Debug: %{User-Name}
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> test
Sun May  5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test'
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (52)
Sun May  5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Sun May  5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:45:45 2019 : Debug: literal --> ' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: User found in radcheck table
Sun May  5 09:45:45 2019 : Debug: (135) sql: Conditional check items matched, merging assignment check items
Sun May  5 09:45:45 2019 : Debug: (135) sql:   Cleartext-Password := "991999"
Sun May  5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Sun May  5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:45:45 2019 : Debug: literal --> ' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May  5 09:45:45 2019 : Debug: (135) sql: User found in radreply table, merging reply items
Sun May  5 09:45:45 2019 : Debug: (135) sql:   Framed-IP-Address := 192.168.100.201
Sun May  5 09:45:45 2019 : Debug: (135) sql: ... falling-through to group processing
Sun May  5 09:45:45 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Sun May  5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:45:45 2019 : Debug: literal --> ' ORDER BY priority
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May  5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May  5 09:45:45 2019 : Debug: (135) sql: User not found in any groups
Sun May  5 09:45:45 2019 : Debug: (135) sql: ... falling-through to profile processing
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (52)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from sql (rlm_sql)
Sun May  5 09:45:45 2019 : Debug: (135)     [sql] = ok
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling expiration (rlm_expiration)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from expiration (rlm_expiration)
Sun May  5 09:45:45 2019 : Debug: (135)     [expiration] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling logintime (rlm_logintime)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from logintime (rlm_logintime)
Sun May  5 09:45:45 2019 : Debug: (135)     [logintime] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: calling pap (rlm_pap)
Sun May  5 09:45:45 2019 : WARNING: (135) pap: Auth-Type already set.  Not setting to PAP
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authorize]: returned from pap (rlm_pap)
Sun May  5 09:45:45 2019 : Debug: (135)     [pap] = noop
Sun May  5 09:45:45 2019 : Debug: (135)   } # authorize = updated
Sun May  5 09:45:45 2019 : Debug: (135) Found Auth-Type = eap
Sun May  5 09:45:45 2019 : Debug: (135) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (135)   authenticate {
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authenticate]: calling eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (135) eap: Expiring EAP session with state 0x59e200a159e304fe
Sun May  5 09:45:45 2019 : Debug: (135) eap: Finished EAP session with state 0x3288c5703289c17c
Sun May  5 09:45:45 2019 : Debug: (135) eap: Previous EAP request found for state 0x3288c5703289c17c, released from the list
Sun May  5 09:45:45 2019 : Debug: (135) eap: Peer sent packet with method EAP MD5 (4)
Sun May  5 09:45:45 2019 : Debug: (135) eap: Calling submodule eap_md5 to process data
Sun May  5 09:45:45 2019 : Debug: (135) eap: Sending EAP Success (code 3) ID 1 length 4
Sun May  5 09:45:45 2019 : Debug: (135) eap: Freeing handler
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[authenticate]: returned from eap (rlm_eap)
Sun May  5 09:45:45 2019 : Debug: (135)     [eap] = ok
Sun May  5 09:45:45 2019 : Debug: (135)   } # authenticate = ok
Sun May  5 09:45:45 2019 : Debug: (135) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:45 2019 : Debug: (135)   post-auth {
Sun May  5 09:45:45 2019 : Debug: (135)     update {
Sun May  5 09:45:45 2019 : Debug: (135)       No attributes updated
Sun May  5 09:45:45 2019 : Debug: (135)     } # update = noop
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[post-auth]: calling sql (rlm_sql)
Sun May  5 09:45:45 2019 : Debug: .query
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: literal --> .query
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND .query
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> .query
Sun May  5 09:45:45 2019 : Debug: (135) sql: Using query template 'query'
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (56)
Sun May  5 09:45:45 2019 : Debug: %{User-Name}
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name}
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> test
Sun May  5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test'
Sun May  5 09:45:45 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May  5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:45 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '
Sun May  5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:45:45 2019 : Debug: literal --> ', '
Sun May  5 09:45:45 2019 : Debug: XLAT-IF {
Sun May  5 09:45:45 2019 : Debug: 	attribute --> User-Password
Sun May  5 09:45:45 2019 : Debug: }
Sun May  5 09:45:45 2019 : Debug: XLAT-ELSE {
Sun May  5 09:45:45 2019 : Debug: 	attribute --> CHAP-Password
Sun May  5 09:45:45 2019 : Debug: }
Sun May  5 09:45:45 2019 : Debug: literal --> ', '
Sun May  5 09:45:45 2019 : Debug: attribute --> Packet-Type
Sun May  5 09:45:45 2019 : Debug: literal --> ', '
Sun May  5 09:45:45 2019 : Debug: percent --> S
Sun May  5 09:45:45 2019 : Debug: literal --> ')
Sun May  5 09:45:45 2019 : Debug: (135) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May  5 09:45:45 2019 : Debug: (135) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383')
Sun May  5 09:45:45 2019 : Debug: (135) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383')
Sun May  5 09:45:45 2019 : Debug: (135) sql: SQL query returned: success
Sun May  5 09:45:45 2019 : Debug: (135) sql: 1 record(s) updated
Sun May  5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (56)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[post-auth]: returned from sql (rlm_sql)
Sun May  5 09:45:45 2019 : Debug: (135)     [sql] = ok
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[post-auth]: calling exec (rlm_exec)
Sun May  5 09:45:45 2019 : Debug: (135)     modsingle[post-auth]: returned from exec (rlm_exec)
Sun May  5 09:45:45 2019 : Debug: (135)     [exec] = noop
Sun May  5 09:45:45 2019 : Debug: (135)     policy remove_reply_message_if_eap {
Sun May  5 09:45:45 2019 : Debug: (135)       if (&reply:EAP-Message && &reply:Reply-Message) {
Sun May  5 09:45:45 2019 : Debug: (135)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
Sun May  5 09:45:45 2019 : Debug: (135)       else {
Sun May  5 09:45:45 2019 : Debug: (135)         modsingle[post-auth]: calling noop (rlm_always)
Sun May  5 09:45:45 2019 : Debug: (135)         modsingle[post-auth]: returned from noop (rlm_always)
Sun May  5 09:45:45 2019 : Debug: (135)         [noop] = noop
Sun May  5 09:45:45 2019 : Debug: (135)       } # else = noop
Sun May  5 09:45:45 2019 : Debug: (135)     } # policy remove_reply_message_if_eap = noop
Sun May  5 09:45:45 2019 : Debug: (135)   } # post-auth = ok
Sun May  5 09:45:45 2019 : Debug: (135) Empty pre-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:45:45 2019 : Debug: (135) proxy: Trying to allocate ID (0/2)
Sun May  5 09:45:45 2019 : Debug: (135) proxy: request is now in proxy hash
Sun May  5 09:45:45 2019 : Debug: (135) proxy: allocating destination 192.168.100.11 port 3799 - Id 21
Sun May  5 09:45:45 2019 : Debug: (135) session-state: Nothing to cache
Sun May  5 09:45:45 2019 : Debug: (135) Sent Disconnect-Request Id 21 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May  5 09:45:45 2019 : Debug: (135)   User-Name = "test"
Sun May  5 09:45:45 2019 : Debug: (135) Sent Access-Accept Id 169 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May  5 09:45:45 2019 : Debug: (135)   Framed-IP-Address = 192.168.100.201
Sun May  5 09:45:45 2019 : Debug: (135)   EAP-Message = 0x03010004
Sun May  5 09:45:45 2019 : Debug: (135)   Message-Authenticator = 0x00000000000000000000000000000000
Sun May  5 09:45:45 2019 : Debug: (135)   User-Name = "test"
Sun May  5 09:45:45 2019 : Debug: (135) Finished request
Sun May  5 09:45:45 2019 : Debug: Waking up in 2.2 seconds.
Sun May  5 09:45:45 2019 : Debug: (135) Clearing existing &reply: attributes
Sun May  5 09:45:45 2019 : Debug: (135) Received Disconnect-NAK Id 21 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May  5 09:45:45 2019 : Debug: (135) Empty post-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:45:45 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867
Sun May  5 09:45:45 2019 : Debug: Waking up in 4.8 seconds.
Sun May  5 09:45:46 2019 : Debug: (136) Received Accounting-Request Id 170 from 192.168.100.11:37595 to 192.168.100.12:1813 length 146
Sun May  5 09:45:46 2019 : Debug: (136)   Acct-Status-Type = Start
Sun May  5 09:45:46 2019 : Debug: (136)   Acct-Session-Id = "1557059862-236"
Sun May  5 09:45:46 2019 : Debug: (136)   NAS-Port-Type = Virtual
Sun May  5 09:45:46 2019 : Debug: (136)   Service-Type = Framed-User
Sun May  5 09:45:46 2019 : Debug: (136)   NAS-Port = 236
Sun May  5 09:45:46 2019 : Debug: (136)   NAS-Port-Id = "IKEv2-EAP"
Sun May  5 09:45:46 2019 : Debug: (136)   NAS-IP-Address = 192.168.100.11
Sun May  5 09:45:46 2019 : Debug: (136)   Called-Station-Id = "192.168.100.11[4500]"
Sun May  5 09:45:46 2019 : Debug: (136)   Calling-Station-Id = "153.119.175.39[56047]"
Sun May  5 09:45:46 2019 : Debug: (136)   User-Name = "test"
Sun May  5 09:45:46 2019 : Debug: (136)   Framed-IP-Address = 192.168.100.201
Sun May  5 09:45:46 2019 : Debug: (136)   NAS-Identifier = "strongSwan"
Sun May  5 09:45:46 2019 : Debug: (136) # Executing section preacct from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:46 2019 : Debug: (136)   preacct {
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: calling preprocess (rlm_preprocess)
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: returned from preprocess (rlm_preprocess)
Sun May  5 09:45:46 2019 : Debug: (136)     [preprocess] = ok
Sun May  5 09:45:46 2019 : Debug: (136)     policy acct_unique {
Sun May  5 09:45:46 2019 : Debug: (136)       update request {
Sun May  5 09:45:46 2019 : Debug: (136)         &Tmp-String-9 := "ai:"
Sun May  5 09:45:46 2019 : Debug: (136)       } # update request = noop
Sun May  5 09:45:46 2019 : Debug: (136)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && 	    ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
Sun May  5 09:45:46 2019 : Debug: (136)       EXPAND %{hex:&Class}
Sun May  5 09:45:46 2019 : Debug: (136)          --> 
Sun May  5 09:45:46 2019 : Debug: (136)       EXPAND ^%{hex:&Tmp-String-9}
Sun May  5 09:45:46 2019 : Debug: (136)          --> ^61693a
Sun May  5 09:45:46 2019 : Debug: (136)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && 	    ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
Sun May  5 09:45:46 2019 : Debug: (136)       else {
Sun May  5 09:45:46 2019 : Debug: (136)         update request {
Sun May  5 09:45:46 2019 : Debug: (136)           EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Sun May  5 09:45:46 2019 : Debug: (136)              --> e233fff2cfee67c8e0763a9ba11758cb
Sun May  5 09:45:46 2019 : Debug: (136)           &Acct-Unique-Session-Id := e233fff2cfee67c8e0763a9ba11758cb
Sun May  5 09:45:46 2019 : Debug: (136)         } # update request = noop
Sun May  5 09:45:46 2019 : Debug: (136)       } # else = noop
Sun May  5 09:45:46 2019 : Debug: (136)     } # policy acct_unique = noop
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: calling suffix (rlm_realm)
Sun May  5 09:45:46 2019 : Debug: (136) suffix: Checking for suffix after "@"
Sun May  5 09:45:46 2019 : Debug: (136) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May  5 09:45:46 2019 : Debug: (136) suffix: No such realm "NULL"
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: returned from suffix (rlm_realm)
Sun May  5 09:45:46 2019 : Debug: (136)     [suffix] = noop
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: calling files (rlm_files)
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[preacct]: returned from files (rlm_files)
Sun May  5 09:45:46 2019 : Debug: (136)     [files] = noop
Sun May  5 09:45:46 2019 : Debug: (136)   } # preacct = ok
Sun May  5 09:45:46 2019 : Debug: (136) # Executing section accounting from file /etc/raddb/sites-enabled/default
Sun May  5 09:45:46 2019 : Debug: (136)   accounting {
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: calling detail (rlm_detail)
Sun May  5 09:45:46 2019 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: literal --> /var/log/radius/radacct/
Sun May  5 09:45:46 2019 : Debug: XLAT-IF {
Sun May  5 09:45:46 2019 : Debug: 	attribute --> Packet-Src-IP-Address
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: XLAT-ELSE {
Sun May  5 09:45:46 2019 : Debug: 	attribute --> Packet-Src-IPv6-Address
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: literal --> /detail-
Sun May  5 09:45:46 2019 : Debug: percent --> Y
Sun May  5 09:45:46 2019 : Debug: percent --> m
Sun May  5 09:45:46 2019 : Debug: percent --> d
Sun May  5 09:45:46 2019 : Debug: (136) detail: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Sun May  5 09:45:46 2019 : Debug: (136) detail:    --> /var/log/radius/radacct/192.168.100.11/detail-20190505
Sun May  5 09:45:46 2019 : Debug: (136) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/192.168.100.11/detail-20190505
Sun May  5 09:45:46 2019 : Debug: %t
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: percent --> t
Sun May  5 09:45:46 2019 : Debug: (136) detail: EXPAND %t
Sun May  5 09:45:46 2019 : Debug: (136) detail:    --> Sun May  5 09:45:46 2019
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: returned from detail (rlm_detail)
Sun May  5 09:45:46 2019 : Debug: (136)     [detail] = ok
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: calling unix (rlm_unix)
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: returned from unix (rlm_unix)
Sun May  5 09:45:46 2019 : Debug: (136)     [unix] = ok
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: calling sql (rlm_sql)
Sun May  5 09:45:46 2019 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: xlat --> tolower
Sun May  5 09:45:46 2019 : Debug: {
Sun May  5 09:45:46 2019 : Debug: 	literal --> type.
Sun May  5 09:45:46 2019 : Debug: 	attribute --> Acct-Status-Type
Sun May  5 09:45:46 2019 : Debug: 	literal --> .query
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: (136) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
Sun May  5 09:45:46 2019 : Debug: (136) sql:    --> type.start.query
Sun May  5 09:45:46 2019 : Debug: (136) sql: Using query template 'query'
Sun May  5 09:45:46 2019 : Debug: rlm_sql (sql): Reserved connection (54)
Sun May  5 09:45:46 2019 : Debug: %{User-Name}
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:46 2019 : Debug: (136) sql: EXPAND %{User-Name}
Sun May  5 09:45:46 2019 : Debug: (136) sql:    --> test
Sun May  5 09:45:46 2019 : Debug: (136) sql: SQL-User-Name set to 'test'
Sun May  5 09:45:46 2019 : Debug: INSERT INTO radacct (acctsessionid,		acctuniqueid,		username, realm,			nasipaddress,		nasportid, nasporttype,		acctstarttime,		acctupdatetime, acctstoptime,		acctsessiontime, 	acctauthentic, connectinfo_start,	connectinfo_stop, 	acctinputoctets, acctoutputoctets,	calledstationid, 	callingstationid, acctterminatecause,	servicetype,		framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: literal --> INSERT INTO radacct (acctsessionid,		acctuniqueid,		username, realm,			nasipaddress,		nasportid, nasporttype,		acctstarttime,		acctupdatetime, acctstoptime,		acctsessiontime, 	acctauthentic, connectinfo_start,	connectinfo_stop, 	acctinputoctets, acctoutputoctets,	calledstationid, 	callingstationid, acctterminatecause,	servicetype,		framedprotocol, framedipaddress) VALUES ('
Sun May  5 09:45:46 2019 : Debug: attribute --> Acct-Session-Id
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Acct-Unique-Session-Id
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Realm
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> NAS-IP-Address
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: XLAT-IF {
Sun May  5 09:45:46 2019 : Debug: 	attribute --> NAS-Port-Id
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: XLAT-ELSE {
Sun May  5 09:45:46 2019 : Debug: 	attribute --> NAS-Port
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> NAS-Port-Type
Sun May  5 09:45:46 2019 : Debug: literal --> ', FROM_UNIXTIME(
Sun May  5 09:45:46 2019 : Debug: xlat --> integer
Sun May  5 09:45:46 2019 : Debug: {
Sun May  5 09:45:46 2019 : Debug: 	literal --> Event-Timestamp
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: literal --> ), FROM_UNIXTIME(
Sun May  5 09:45:46 2019 : Debug: xlat --> integer
Sun May  5 09:45:46 2019 : Debug: {
Sun May  5 09:45:46 2019 : Debug: 	literal --> Event-Timestamp
Sun May  5 09:45:46 2019 : Debug: }
Sun May  5 09:45:46 2019 : Debug: literal --> ), NULL, '0', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Acct-Authentic
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Connect-Info
Sun May  5 09:45:46 2019 : Debug: literal --> ', '', '0', '0', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Called-Station-Id
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Calling-Station-Id
Sun May  5 09:45:46 2019 : Debug: literal --> ', '', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Service-Type
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Framed-Protocol
Sun May  5 09:45:46 2019 : Debug: literal --> ', '
Sun May  5 09:45:46 2019 : Debug: attribute --> Framed-IP-Address
Sun May  5 09:45:46 2019 : Debug: literal --> ')
Sun May  5 09:45:46 2019 : Debug: (136) sql: EXPAND INSERT INTO radacct (acctsessionid,		acctuniqueid,		username, realm,			nasipaddress,		nasportid, nasporttype,		acctstarttime,		acctupdatetime, acctstoptime,		acctsessiontime, 	acctauthentic, connectinfo_start,	connectinfo_stop, 	acctinputoctets, acctoutputoctets,	calledstationid, 	callingstationid, acctterminatecause,	servicetype,		framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
Sun May  5 09:45:46 2019 : Debug: (136) sql:    --> INSERT INTO radacct (acctsessionid,		acctuniqueid,		username, realm,			nasipaddress,		nasportid, nasporttype,		acctstarttime,		acctupdatetime, acctstoptime,		acctsessiontime, 	acctauthentic, connectinfo_start,	connectinfo_stop, 	acctinputoctets, acctoutputoctets,	calledstationid, 	callingstationid, acctterminatecause,	servicetype,		framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201')
Sun May  5 09:45:46 2019 : Debug: (136) sql: Executing query: INSERT INTO radacct (acctsessionid,		acctuniqueid,		username, realm,			nasipaddress,		nasportid, nasporttype,		acctstarttime,		acctupdatetime, acctstoptime,		acctsessiontime, 	acctauthentic, connectinfo_start,	connectinfo_stop, 	acctinputoctets, acctoutputoctets,calledstationid, 	callingstationid, acctterminatecause,	servicetype,		framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201')
Sun May  5 09:45:46 2019 : Debug: (136) sql: SQL query returned: success
Sun May  5 09:45:46 2019 : Debug: (136) sql: 1 record(s) updated
Sun May  5 09:45:46 2019 : Debug: rlm_sql (sql): Released connection (54)
Sun May  5 09:45:46 2019 : Info: Need 1 more connections to reach 10 spares
Sun May  5 09:45:46 2019 : Info: rlm_sql (sql): Opening additional connection (61), 1 of 23 pending slots used
Sun May  5 09:45:46 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May  5 09:45:46 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: returned from sql (rlm_sql)
Sun May  5 09:45:46 2019 : Debug: (136)     [sql] = ok
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: calling exec (rlm_exec)
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: returned from exec (rlm_exec)
Sun May  5 09:45:46 2019 : Debug: (136)     [exec] = noop
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter)
Sun May  5 09:45:46 2019 : Debug: %{User-Name}
Sun May  5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May  5 09:45:46 2019 : Debug: attribute --> User-Name
Sun May  5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: EXPAND %{User-Name}
Sun May  5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response:    --> test
Sun May  5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: Matched entry DEFAULT at line 12
Sun May  5 09:45:46 2019 : Debug: (136)     modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter)
Sun May  5 09:45:46 2019 : Debug: (136)     [attr_filter.accounting_response] = updated
Sun May  5 09:45:46 2019 : Debug: (136)   } # accounting = updated
Sun May  5 09:45:46 2019 : Debug: (136) Sent Accounting-Response Id 170 from 192.168.100.12:1813 to 192.168.100.11:37595 length 0
Sun May  5 09:45:46 2019 : Debug: (136) Finished request
Sun May  5 09:45:46 2019 : Debug: (136) Cleaning up request packet ID 170 with timestamp +1868
Sun May  5 09:45:46 2019 : Debug: Waking up in 4.7 seconds.
Sun May  5 09:45:50 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867
Sun May  5 09:45:50 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867
Sun May  5 09:45:50 2019 : Info: Ready to process requests


#########################################




this is not works log




#####################################################
Sun May  5 09:46:32 2019 : Debug: (138) Received Access-Request Id 172 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163
Sun May  5 09:46:32 2019 : Debug: (138)   User-Name = "test"
Sun May  5 09:46:32 2019 : Debug: (138)   NAS-Port-Type = Virtual
Sun May  5 09:46:32 2019 : Debug: (138)   Service-Type = Framed-User
Sun May  5 09:46:32 2019 : Debug: (138)   NAS-Port = 238
Sun May  5 09:46:32 2019 : Debug: (138)   NAS-Port-Id = "IKEv2-EAP"
Sun May  5 09:46:32 2019 : Debug: (138)   NAS-IP-Address = 192.168.100.11
Sun May  5 09:46:32 2019 : Debug: (138)   Called-Station-Id = "192.168.100.11[4500]"
Sun May  5 09:46:32 2019 : Debug: (138)   Calling-Station-Id = "153.119.175.39[56451]"
Sun May  5 09:46:32 2019 : Debug: (138)   Acct-Session-Id = "1557059862-238"
Sun May  5 09:46:32 2019 : Debug: (138)   EAP-Message = 0x020000090174657374
Sun May  5 09:46:32 2019 : Debug: (138)   NAS-Identifier = "strongSwan"
Sun May  5 09:46:32 2019 : Debug: (138)   Message-Authenticator = 0xe29b962bf25ae5af41cb931202c00c6e
Sun May  5 09:46:32 2019 : Debug: (138) session-state: No State attribute
Sun May  5 09:46:32 2019 : Debug: (138) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (138)   authorize {
Sun May  5 09:46:32 2019 : Debug: (138)     update disconnect {
Sun May  5 09:46:32 2019 : Debug: (138)       EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (138)          --> test
Sun May  5 09:46:32 2019 : Debug: (138)       &User-Name = test
Sun May  5 09:46:32 2019 : Debug: (138)     } # update disconnect = noop
Sun May  5 09:46:32 2019 : Debug: (138)     if (User-Name){
Sun May  5 09:46:32 2019 : Debug: (138)     if (User-Name) -> TRUE
Sun May  5 09:46:32 2019 : Debug: (138)     if (User-Name) {
Sun May  5 09:46:32 2019 : Debug: (138)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May  5 09:46:32 2019 : Debug: %{User-Name}
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May  5 09:46:32 2019 : Debug: (138)       EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (138)          --> test
Sun May  5 09:46:32 2019 : Debug: (138)       SQL-User-Name set to 'test'
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (60)
Sun May  5 09:46:32 2019 : Debug: (138)       Executing select query:  UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May  5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
Sun May  5 09:46:32 2019 : Debug: (138)       SQL query returned no results
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (60)
Sun May  5 09:46:32 2019 : Info: Need 2 more connections to reach 10 spares
Sun May  5 09:46:32 2019 : Info: rlm_sql (sql): Opening additional connection (63), 1 of 24 pending slots used
Sun May  5 09:46:32 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May  5 09:46:32 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May  5 09:46:32 2019 : Debug: (138)       EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May  5 09:46:32 2019 : Debug: (138)          --> 
Sun May  5 09:46:32 2019 : Debug: (138)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)     } # if (User-Name) = noop
Sun May  5 09:46:32 2019 : Debug: (138)     policy filter_username {
Sun May  5 09:46:32 2019 : Debug: (138)       if (&User-Name) {
Sun May  5 09:46:32 2019 : Debug: (138)       if (&User-Name)  -> TRUE
Sun May  5 09:46:32 2019 : Debug: (138)       if (&User-Name)  {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ / /) {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ / /)  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /@[^@]*@/ ) {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /\.\./ ) {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /\.\./ )  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Sun May  5 09:46:32 2019 : Debug: (138)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /\.$/)  {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /\.$/)   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /@\./)  {
Sun May  5 09:46:32 2019 : Debug: (138)         if (&User-Name =~ /@\./)   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (138)       } # if (&User-Name)  = noop
Sun May  5 09:46:32 2019 : Debug: (138)     } # policy filter_username = noop
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May  5 09:46:32 2019 : Debug: (138)     [preprocess] = ok
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling chap (rlm_chap)
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from chap (rlm_chap)
Sun May  5 09:46:32 2019 : Debug: (138)     [chap] = noop
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling mschap (rlm_mschap)
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May  5 09:46:32 2019 : Debug: (138)     [mschap] = noop
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling digest (rlm_digest)
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from digest (rlm_digest)
Sun May  5 09:46:32 2019 : Debug: (138)     [digest] = noop
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling suffix (rlm_realm)
Sun May  5 09:46:32 2019 : Debug: (138) suffix: Checking for suffix after "@"
Sun May  5 09:46:32 2019 : Debug: (138) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May  5 09:46:32 2019 : Debug: (138) suffix: No such realm "NULL"
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from suffix (rlm_realm)
Sun May  5 09:46:32 2019 : Debug: (138)     [suffix] = noop
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: calling eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (138) eap: Peer sent EAP Response (code 2) ID 0 length 9
Sun May  5 09:46:32 2019 : Debug: (138) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authorize]: returned from eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (138)     [eap] = ok
Sun May  5 09:46:32 2019 : Debug: (138)   } # authorize = ok
Sun May  5 09:46:32 2019 : Debug: (138) Found Auth-Type = eap
Sun May  5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (138)   authenticate {
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authenticate]: calling eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (138) eap: Peer sent packet with method EAP Identity (1)
Sun May  5 09:46:32 2019 : Debug: (138) eap: Calling submodule eap_md5 to process data
Sun May  5 09:46:32 2019 : Debug: (138) eap_md5: Issuing MD5 Challenge
Sun May  5 09:46:32 2019 : Debug: (138) eap: Sending EAP Request (code 1) ID 1 length 22
Sun May  5 09:46:32 2019 : Debug: (138) eap: EAP session adding &reply:State = 0x6048d1426049d56d
Sun May  5 09:46:32 2019 : Debug: (138)     modsingle[authenticate]: returned from eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (138)     [eap] = handled
Sun May  5 09:46:32 2019 : Debug: (138)   } # authenticate = handled
Sun May  5 09:46:32 2019 : Debug: (138) Using Post-Auth-Type Challenge
Sun May  5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (138)   Challenge { ... } # empty sub-section is ignored
Sun May  5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache
Sun May  5 09:46:32 2019 : Debug: (138) Empty pre-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:46:32 2019 : Debug: (138) proxy: Trying to allocate ID (0/2)
Sun May  5 09:46:32 2019 : Debug: (138) proxy: request is now in proxy hash
Sun May  5 09:46:32 2019 : Debug: (138) proxy: allocating destination 192.168.100.11 port 3799 - Id 57
Sun May  5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache
Sun May  5 09:46:32 2019 : Debug: (138) Sent Disconnect-Request Id 57 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May  5 09:46:32 2019 : Debug: (138)   User-Name = "test"
Sun May  5 09:46:32 2019 : Debug: (138) Sent Access-Challenge Id 172 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May  5 09:46:32 2019 : Debug: (138)   EAP-Message = 0x0101001604106d1b45d49f879829562d2c46943013e8
Sun May  5 09:46:32 2019 : Debug: (138)   Message-Authenticator = 0x00000000000000000000000000000000
Sun May  5 09:46:32 2019 : Debug: (138)   State = 0x6048d1426049d56d1e82e3d0d58b93c7
Sun May  5 09:46:32 2019 : Debug: (138) Finished request
Sun May  5 09:46:32 2019 : Debug: Waking up in 2.5 seconds.
Sun May  5 09:46:32 2019 : Debug: (138) Clearing existing &reply: attributes
Sun May  5 09:46:32 2019 : Debug: (138) Received Disconnect-NAK Id 57 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May  5 09:46:32 2019 : Debug: (138) Empty post-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:46:32 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914
Sun May  5 09:46:32 2019 : Debug: Waking up in 4.9 seconds.
Sun May  5 09:46:32 2019 : Debug: (139) Received Access-Request Id 173 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194
Sun May  5 09:46:32 2019 : Debug: (139)   User-Name = "test"
Sun May  5 09:46:32 2019 : Debug: (139)   NAS-Port-Type = Virtual
Sun May  5 09:46:32 2019 : Debug: (139)   Service-Type = Framed-User
Sun May  5 09:46:32 2019 : Debug: (139)   NAS-Port = 238
Sun May  5 09:46:32 2019 : Debug: (139)   NAS-Port-Id = "IKEv2-EAP"
Sun May  5 09:46:32 2019 : Debug: (139)   NAS-IP-Address = 192.168.100.11
Sun May  5 09:46:32 2019 : Debug: (139)   Called-Station-Id = "192.168.100.11[4500]"
Sun May  5 09:46:32 2019 : Debug: (139)   Calling-Station-Id = "153.119.175.39[56451]"
Sun May  5 09:46:32 2019 : Debug: (139)   Acct-Session-Id = "1557059862-238"
Sun May  5 09:46:32 2019 : Debug: (139)   EAP-Message = 0x0201001604101a5615717d21560f482951e9124181b2
Sun May  5 09:46:32 2019 : Debug: (139)   NAS-Identifier = "strongSwan"
Sun May  5 09:46:32 2019 : Debug: (139)   State = 0x6048d1426049d56d1e82e3d0d58b93c7
Sun May  5 09:46:32 2019 : Debug: (139)   Message-Authenticator = 0x1002eed55d62afee39fbe2fcd41869de
Sun May  5 09:46:32 2019 : Debug: (139) session-state: No cached attributes
Sun May  5 09:46:32 2019 : Debug: (139) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (139)   authorize {
Sun May  5 09:46:32 2019 : Debug: (139)     update disconnect {
Sun May  5 09:46:32 2019 : Debug: (139)       EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (139)          --> test
Sun May  5 09:46:32 2019 : Debug: (139)       &User-Name = test
Sun May  5 09:46:32 2019 : Debug: (139)     } # update disconnect = noop
Sun May  5 09:46:32 2019 : Debug: (139)     if (User-Name){
Sun May  5 09:46:32 2019 : Debug: (139)     if (User-Name) -> TRUE
Sun May  5 09:46:32 2019 : Debug: (139)     if (User-Name) {
Sun May  5 09:46:32 2019 : Debug: (139)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May  5 09:46:32 2019 : Debug: %{User-Name}
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May  5 09:46:32 2019 : Debug: (139)       EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (139)          --> test
Sun May  5 09:46:32 2019 : Debug: (139)       SQL-User-Name set to 'test'
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (55)
Sun May  5 09:46:32 2019 : Debug: (139)       Executing select query:  UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May  5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
Sun May  5 09:46:32 2019 : Debug: (139)       SQL query returned no results
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (55)
Sun May  5 09:46:32 2019 : Debug: (139)       EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May  5 09:46:32 2019 : Debug: (139)          --> 
Sun May  5 09:46:32 2019 : Debug: (139)       if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)     } # if (User-Name) = noop
Sun May  5 09:46:32 2019 : Debug: (139)     policy filter_username {
Sun May  5 09:46:32 2019 : Debug: (139)       if (&User-Name) {
Sun May  5 09:46:32 2019 : Debug: (139)       if (&User-Name)  -> TRUE
Sun May  5 09:46:32 2019 : Debug: (139)       if (&User-Name)  {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ / /) {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ / /)  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /@[^@]*@/ ) {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /\.\./ ) {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /\.\./ )  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Sun May  5 09:46:32 2019 : Debug: (139)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /\.$/)  {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /\.$/)   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /@\./)  {
Sun May  5 09:46:32 2019 : Debug: (139)         if (&User-Name =~ /@\./)   -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)       } # if (&User-Name)  = noop
Sun May  5 09:46:32 2019 : Debug: (139)     } # policy filter_username = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May  5 09:46:32 2019 : Debug: (139)     [preprocess] = ok
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling chap (rlm_chap)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from chap (rlm_chap)
Sun May  5 09:46:32 2019 : Debug: (139)     [chap] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling mschap (rlm_mschap)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May  5 09:46:32 2019 : Debug: (139)     [mschap] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling digest (rlm_digest)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from digest (rlm_digest)
Sun May  5 09:46:32 2019 : Debug: (139)     [digest] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling suffix (rlm_realm)
Sun May  5 09:46:32 2019 : Debug: (139) suffix: Checking for suffix after "@"
Sun May  5 09:46:32 2019 : Debug: (139) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May  5 09:46:32 2019 : Debug: (139) suffix: No such realm "NULL"
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from suffix (rlm_realm)
Sun May  5 09:46:32 2019 : Debug: (139)     [suffix] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (139) eap: Peer sent EAP Response (code 2) ID 1 length 22
Sun May  5 09:46:32 2019 : Debug: (139) eap: No EAP Start, assuming it's an on-going EAP conversation
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (139)     [eap] = updated
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling files (rlm_files)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from files (rlm_files)
Sun May  5 09:46:32 2019 : Debug: (139)     [files] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling sql (rlm_sql)
Sun May  5 09:46:32 2019 : Debug: %{User-Name}
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> test
Sun May  5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test'
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (52)
Sun May  5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Sun May  5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:46:32 2019 : Debug: literal --> ' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: User found in radcheck table
Sun May  5 09:46:32 2019 : Debug: (139) sql: Conditional check items matched, merging assignment check items
Sun May  5 09:46:32 2019 : Debug: (139) sql:   Cleartext-Password := "991999"
Sun May  5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Sun May  5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:46:32 2019 : Debug: literal --> ' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May  5 09:46:32 2019 : Debug: (139) sql: User found in radreply table, merging reply items
Sun May  5 09:46:32 2019 : Debug: (139) sql:   Framed-IP-Address := 192.168.100.201
Sun May  5 09:46:32 2019 : Debug: (139) sql: ... falling-through to group processing
Sun May  5 09:46:32 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Sun May  5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:46:32 2019 : Debug: literal --> ' ORDER BY priority
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May  5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May  5 09:46:32 2019 : Debug: (139) sql: User not found in any groups
Sun May  5 09:46:32 2019 : Debug: (139) sql: ... falling-through to profile processing
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (52)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from sql (rlm_sql)
Sun May  5 09:46:32 2019 : Debug: (139)     [sql] = ok
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling expiration (rlm_expiration)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from expiration (rlm_expiration)
Sun May  5 09:46:32 2019 : Debug: (139)     [expiration] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling logintime (rlm_logintime)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from logintime (rlm_logintime)
Sun May  5 09:46:32 2019 : Debug: (139)     [logintime] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: calling pap (rlm_pap)
Sun May  5 09:46:32 2019 : WARNING: (139) pap: Auth-Type already set.  Not setting to PAP
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authorize]: returned from pap (rlm_pap)
Sun May  5 09:46:32 2019 : Debug: (139)     [pap] = noop
Sun May  5 09:46:32 2019 : Debug: (139)   } # authorize = updated
Sun May  5 09:46:32 2019 : Debug: (139) Found Auth-Type = eap
Sun May  5 09:46:32 2019 : Debug: (139) # Executing group from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (139)   authenticate {
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authenticate]: calling eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x59e200a159e304fe
Sun May  5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x6048d1426049d56d
Sun May  5 09:46:32 2019 : Debug: (139) eap: Finished EAP session with state 0x6048d1426049d56d
Sun May  5 09:46:32 2019 : Debug: (139) eap: Previous EAP request found for state 0x6048d1426049d56d, released from the list
Sun May  5 09:46:32 2019 : Debug: (139) eap: Peer sent packet with method EAP MD5 (4)
Sun May  5 09:46:32 2019 : Debug: (139) eap: Calling submodule eap_md5 to process data
Sun May  5 09:46:32 2019 : Debug: (139) eap: Sending EAP Success (code 3) ID 1 length 4
Sun May  5 09:46:32 2019 : Debug: (139) eap: Freeing handler
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[authenticate]: returned from eap (rlm_eap)
Sun May  5 09:46:32 2019 : Debug: (139)     [eap] = ok
Sun May  5 09:46:32 2019 : Debug: (139)   } # authenticate = ok
Sun May  5 09:46:32 2019 : Debug: (139) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Sun May  5 09:46:32 2019 : Debug: (139)   post-auth {
Sun May  5 09:46:32 2019 : Debug: (139)     update {
Sun May  5 09:46:32 2019 : Debug: (139)       No attributes updated
Sun May  5 09:46:32 2019 : Debug: (139)     } # update = noop
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[post-auth]: calling sql (rlm_sql)
Sun May  5 09:46:32 2019 : Debug: .query
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: literal --> .query
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND .query
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> .query
Sun May  5 09:46:32 2019 : Debug: (139) sql: Using query template 'query'
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (56)
Sun May  5 09:46:32 2019 : Debug: %{User-Name}
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name}
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> test
Sun May  5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test'
Sun May  5 09:46:32 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May  5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May  5 09:46:32 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '
Sun May  5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May  5 09:46:32 2019 : Debug: literal --> ', '
Sun May  5 09:46:32 2019 : Debug: XLAT-IF {
Sun May  5 09:46:32 2019 : Debug: 	attribute --> User-Password
Sun May  5 09:46:32 2019 : Debug: }
Sun May  5 09:46:32 2019 : Debug: XLAT-ELSE {
Sun May  5 09:46:32 2019 : Debug: 	attribute --> CHAP-Password
Sun May  5 09:46:32 2019 : Debug: }
Sun May  5 09:46:32 2019 : Debug: literal --> ', '
Sun May  5 09:46:32 2019 : Debug: attribute --> Packet-Type
Sun May  5 09:46:32 2019 : Debug: literal --> ', '
Sun May  5 09:46:32 2019 : Debug: percent --> S
Sun May  5 09:46:32 2019 : Debug: literal --> ')
Sun May  5 09:46:32 2019 : Debug: (139) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May  5 09:46:32 2019 : Debug: (139) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711')
Sun May  5 09:46:32 2019 : Debug: (139) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711')
Sun May  5 09:46:32 2019 : Debug: (139) sql: SQL query returned: success
Sun May  5 09:46:32 2019 : Debug: (139) sql: 1 record(s) updated
Sun May  5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (56)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[post-auth]: returned from sql (rlm_sql)
Sun May  5 09:46:32 2019 : Debug: (139)     [sql] = ok
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[post-auth]: calling exec (rlm_exec)
Sun May  5 09:46:32 2019 : Debug: (139)     modsingle[post-auth]: returned from exec (rlm_exec)
Sun May  5 09:46:32 2019 : Debug: (139)     [exec] = noop
Sun May  5 09:46:32 2019 : Debug: (139)     policy remove_reply_message_if_eap {
Sun May  5 09:46:32 2019 : Debug: (139)       if (&reply:EAP-Message && &reply:Reply-Message) {
Sun May  5 09:46:32 2019 : Debug: (139)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
Sun May  5 09:46:32 2019 : Debug: (139)       else {
Sun May  5 09:46:32 2019 : Debug: (139)         modsingle[post-auth]: calling noop (rlm_always)
Sun May  5 09:46:32 2019 : Debug: (139)         modsingle[post-auth]: returned from noop (rlm_always)
Sun May  5 09:46:32 2019 : Debug: (139)         [noop] = noop
Sun May  5 09:46:32 2019 : Debug: (139)       } # else = noop
Sun May  5 09:46:32 2019 : Debug: (139)     } # policy remove_reply_message_if_eap = noop
Sun May  5 09:46:32 2019 : Debug: (139)   } # post-auth = ok
Sun May  5 09:46:32 2019 : Debug: (139) Empty pre-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:46:32 2019 : Debug: (139) proxy: Trying to allocate ID (0/2)
Sun May  5 09:46:32 2019 : Debug: (139) proxy: request is now in proxy hash
Sun May  5 09:46:32 2019 : Debug: (139) proxy: allocating destination 192.168.100.11 port 3799 - Id 104
Sun May  5 09:46:32 2019 : Debug: (139) session-state: Nothing to cache
Sun May  5 09:46:32 2019 : Debug: (139) Sent Disconnect-Request Id 104 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May  5 09:46:32 2019 : Debug: (139)   User-Name = "test"
Sun May  5 09:46:32 2019 : Debug: (139) Sent Access-Accept Id 173 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May  5 09:46:32 2019 : Debug: (139)   Framed-IP-Address = 192.168.100.201
Sun May  5 09:46:32 2019 : Debug: (139)   EAP-Message = 0x03010004
Sun May  5 09:46:32 2019 : Debug: (139)   Message-Authenticator = 0x00000000000000000000000000000000
Sun May  5 09:46:32 2019 : Debug: (139)   User-Name = "test"
Sun May  5 09:46:32 2019 : Debug: (139) Finished request
Sun May  5 09:46:32 2019 : Debug: Waking up in 2.1 seconds.
Sun May  5 09:46:32 2019 : Debug: (139) Clearing existing &reply: attributes
Sun May  5 09:46:32 2019 : Debug: (139) Received Disconnect-ACK Id 104 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May  5 09:46:32 2019 : Debug: (139) Empty post-proxy section in virtual server "default".  Using default return values.
Sun May  5 09:46:32 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914
Sun May  5 09:46:32 2019 : Debug: Waking up in 4.8 seconds.
Sun May  5 09:46:37 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914
Sun May  5 09:46:37 2019 : Debug: Waking up in 0.1 seconds.
Sun May  5 09:46:37 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914
Sun May  5 09:46:37 2019 : Info: Ready to process requests




##################################################






I think  


when server does this:


##################################
        update disconnect{
                &User-Name = "%{User-Name}"
        }
 
        if(User-Name){


                       if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){


          }
}


####################################


it shoud  wait for the Disconnect-ACK or  Disconnect-NAK   


and then  do the next


##################
filter_username


... ...
       
##################


how can I write  ?




or how to write a  delay time  befor   “filter_username”?




or  is there other  idea  to  do  this  (disconnect same user both strongswan and freeradius  whatever ) ?






Thanks very much!


More information about the Freeradius-Users mailing list