disconnect same user both whatever
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!
On May 6, 2019, at 9:12 AM, 佛来佛网 <314186514@qq.com> wrote:
when server does this：
################################## update disconnect{ &User-Name = "%{User-Name}"
it shoud wait for the Disconnect-ACK or Disconnect-NAK
and then do the next
That's not how the server works. The disconnect is sent AFTER the current packet is finished. That's what the documentation says, and that's how the server works. If you want it to wait for the Disconnect-ACK, you will have to run "radclient" via a shell script. See the "exec" module for documentation. But there are issues with doing that. If the NAS doesn't reply for 2-3 seconds, the server can get blocked very quickly. Alan DeKok.
participants (2)
-
Alan DeKok -
佛来佛网