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!