disconnect same user both whatever
佛来佛网
314186514 at qq.com
Mon May 6 15:12:12 CEST 2019
Hi Guys,
sorry , I am not good at English.
I have configured strongswan + freeradius working well.
now I want user （ for example“test”）disconnect the same user when he connect whatever .
I write this :
###################################
authorize {
update disconnect{
&User-Name = "%{User-Name}"
}
if(User-Name){
if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
}
}
filter_username
... ...
}
######################################
some times it works and some times not works
this is works good log
#######################################
Sun May 5 09:45:45 2019 : Debug: (134) Received Access-Request Id 168 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163
Sun May 5 09:45:45 2019 : Debug: (134) User-Name = "test"
Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port-Type = Virtual
Sun May 5 09:45:45 2019 : Debug: (134) Service-Type = Framed-User
Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port = 236
Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port-Id = "IKEv2-EAP"
Sun May 5 09:45:45 2019 : Debug: (134) NAS-IP-Address = 192.168.100.11
Sun May 5 09:45:45 2019 : Debug: (134) Called-Station-Id = "192.168.100.11[4500]"
Sun May 5 09:45:45 2019 : Debug: (134) Calling-Station-Id = "153.119.175.39[56047]"
Sun May 5 09:45:45 2019 : Debug: (134) Acct-Session-Id = "1557059862-236"
Sun May 5 09:45:45 2019 : Debug: (134) EAP-Message = 0x020000090174657374
Sun May 5 09:45:45 2019 : Debug: (134) NAS-Identifier = "strongSwan"
Sun May 5 09:45:45 2019 : Debug: (134) Message-Authenticator = 0x3111389892946d1452bab86037789b9e
Sun May 5 09:45:45 2019 : Debug: (134) session-state: No State attribute
Sun May 5 09:45:45 2019 : Debug: (134) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (134) authorize {
Sun May 5 09:45:45 2019 : Debug: (134) update disconnect {
Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (134) --> test
Sun May 5 09:45:45 2019 : Debug: (134) &User-Name = test
Sun May 5 09:45:45 2019 : Debug: (134) } # update disconnect = noop
Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name){
Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name) -> TRUE
Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name) {
Sun May 5 09:45:45 2019 : Debug: (134) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May 5 09:45:45 2019 : Debug: %{User-Name}
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (134) --> test
Sun May 5 09:45:45 2019 : Debug: (134) SQL-User-Name set to 'test'
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (53)
Sun May 5 09:45:45 2019 : Debug: (134) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
Sun May 5 09:45:45 2019 : Debug: (134) SQL query returned no results
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (53)
Sun May 5 09:45:45 2019 : Info: Need 2 more connections to reach 10 spares
Sun May 5 09:45:45 2019 : Info: rlm_sql (sql): Opening additional connection (60), 1 of 24 pending slots used
Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May 5 09:45:45 2019 : Debug: (134) -->
Sun May 5 09:45:45 2019 : Debug: (134) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) } # if (User-Name) = noop
Sun May 5 09:45:45 2019 : Debug: (134) policy filter_username {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) -> TRUE
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ / /) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ / /) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@[^@]*@/ ) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.\./ ) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.\./ ) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
Sun May 5 09:45:45 2019 : Debug: (134) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.$/) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.$/) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@\./) {
Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@\./) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (134) } # if (&User-Name) = noop
Sun May 5 09:45:45 2019 : Debug: (134) } # policy filter_username = noop
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May 5 09:45:45 2019 : Debug: (134) [preprocess] = ok
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling chap (rlm_chap)
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from chap (rlm_chap)
Sun May 5 09:45:45 2019 : Debug: (134) [chap] = noop
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling mschap (rlm_mschap)
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May 5 09:45:45 2019 : Debug: (134) [mschap] = noop
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling digest (rlm_digest)
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from digest (rlm_digest)
Sun May 5 09:45:45 2019 : Debug: (134) [digest] = noop
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling suffix (rlm_realm)
Sun May 5 09:45:45 2019 : Debug: (134) suffix: Checking for suffix after "@"
Sun May 5 09:45:45 2019 : Debug: (134) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May 5 09:45:45 2019 : Debug: (134) suffix: No such realm "NULL"
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from suffix (rlm_realm)
Sun May 5 09:45:45 2019 : Debug: (134) [suffix] = noop
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (134) eap: Peer sent EAP Response (code 2) ID 0 length 9
Sun May 5 09:45:45 2019 : Debug: (134) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (134) [eap] = ok
Sun May 5 09:45:45 2019 : Debug: (134) } # authorize = ok
Sun May 5 09:45:45 2019 : Debug: (134) Found Auth-Type = eap
Sun May 5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (134) authenticate {
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authenticate]: calling eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (134) eap: Peer sent packet with method EAP Identity (1)
Sun May 5 09:45:45 2019 : Debug: (134) eap: Calling submodule eap_md5 to process data
Sun May 5 09:45:45 2019 : Debug: (134) eap_md5: Issuing MD5 Challenge
Sun May 5 09:45:45 2019 : Debug: (134) eap: Sending EAP Request (code 1) ID 1 length 22
Sun May 5 09:45:45 2019 : Debug: (134) eap: EAP session adding &reply:State = 0x3288c5703289c17c
Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authenticate]: returned from eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (134) [eap] = handled
Sun May 5 09:45:45 2019 : Debug: (134) } # authenticate = handled
Sun May 5 09:45:45 2019 : Debug: (134) Using Post-Auth-Type Challenge
Sun May 5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (134) Challenge { ... } # empty sub-section is ignored
Sun May 5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache
Sun May 5 09:45:45 2019 : Debug: (134) Empty pre-proxy section in virtual server "default". Using default return values.
Sun May 5 09:45:45 2019 : Debug: (134) proxy: Trying to allocate ID (0/2)
Sun May 5 09:45:45 2019 : Debug: (134) proxy: request is now in proxy hash
Sun May 5 09:45:45 2019 : Debug: (134) proxy: allocating destination 192.168.100.11 port 3799 - Id 62
Sun May 5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache
Sun May 5 09:45:45 2019 : Debug: (134) Sent Disconnect-Request Id 62 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May 5 09:45:45 2019 : Debug: (134) User-Name = "test"
Sun May 5 09:45:45 2019 : Debug: (134) Sent Access-Challenge Id 168 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May 5 09:45:45 2019 : Debug: (134) EAP-Message = 0x010100160410d93a974e96d012a501eb4786e0dd3e77
Sun May 5 09:45:45 2019 : Debug: (134) Message-Authenticator = 0x00000000000000000000000000000000
Sun May 5 09:45:45 2019 : Debug: (134) State = 0x3288c5703289c17c78ded5beb28006bf
Sun May 5 09:45:45 2019 : Debug: (134) Finished request
Sun May 5 09:45:45 2019 : Debug: Waking up in 2.5 seconds.
Sun May 5 09:45:45 2019 : Debug: (134) Clearing existing &reply: attributes
Sun May 5 09:45:45 2019 : Debug: (134) Received Disconnect-NAK Id 62 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May 5 09:45:45 2019 : Debug: (134) Empty post-proxy section in virtual server "default". Using default return values.
Sun May 5 09:45:45 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867
Sun May 5 09:45:45 2019 : Debug: Waking up in 4.9 seconds.
Sun May 5 09:45:45 2019 : Debug: (135) Received Access-Request Id 169 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194
Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test"
Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port-Type = Virtual
Sun May 5 09:45:45 2019 : Debug: (135) Service-Type = Framed-User
Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port = 236
Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port-Id = "IKEv2-EAP"
Sun May 5 09:45:45 2019 : Debug: (135) NAS-IP-Address = 192.168.100.11
Sun May 5 09:45:45 2019 : Debug: (135) Called-Station-Id = "192.168.100.11[4500]"
Sun May 5 09:45:45 2019 : Debug: (135) Calling-Station-Id = "153.119.175.39[56047]"
Sun May 5 09:45:45 2019 : Debug: (135) Acct-Session-Id = "1557059862-236"
Sun May 5 09:45:45 2019 : Debug: (135) EAP-Message = 0x020100160410ce217178fb4d579d68d54a027effd329
Sun May 5 09:45:45 2019 : Debug: (135) NAS-Identifier = "strongSwan"
Sun May 5 09:45:45 2019 : Debug: (135) State = 0x3288c5703289c17c78ded5beb28006bf
Sun May 5 09:45:45 2019 : Debug: (135) Message-Authenticator = 0x59fec2cedd5cf0d2f07cb53382317673
Sun May 5 09:45:45 2019 : Debug: (135) session-state: No cached attributes
Sun May 5 09:45:45 2019 : Debug: (135) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (135) authorize {
Sun May 5 09:45:45 2019 : Debug: (135) update disconnect {
Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (135) --> test
Sun May 5 09:45:45 2019 : Debug: (135) &User-Name = test
Sun May 5 09:45:45 2019 : Debug: (135) } # update disconnect = noop
Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name){
Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name) -> TRUE
Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name) {
Sun May 5 09:45:45 2019 : Debug: (135) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May 5 09:45:45 2019 : Debug: %{User-Name}
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (135) --> test
Sun May 5 09:45:45 2019 : Debug: (135) SQL-User-Name set to 'test'
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (55)
Sun May 5 09:45:45 2019 : Debug: (135) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
Sun May 5 09:45:45 2019 : Debug: (135) SQL query returned no results
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (55)
Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May 5 09:45:45 2019 : Debug: (135) -->
Sun May 5 09:45:45 2019 : Debug: (135) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) } # if (User-Name) = noop
Sun May 5 09:45:45 2019 : Debug: (135) policy filter_username {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) -> TRUE
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ / /) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ / /) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@[^@]*@/ ) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.\./ ) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.\./ ) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
Sun May 5 09:45:45 2019 : Debug: (135) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.$/) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.$/) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@\./) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@\./) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) } # if (&User-Name) = noop
Sun May 5 09:45:45 2019 : Debug: (135) } # policy filter_username = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May 5 09:45:45 2019 : Debug: (135) [preprocess] = ok
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling chap (rlm_chap)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from chap (rlm_chap)
Sun May 5 09:45:45 2019 : Debug: (135) [chap] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling mschap (rlm_mschap)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May 5 09:45:45 2019 : Debug: (135) [mschap] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling digest (rlm_digest)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from digest (rlm_digest)
Sun May 5 09:45:45 2019 : Debug: (135) [digest] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling suffix (rlm_realm)
Sun May 5 09:45:45 2019 : Debug: (135) suffix: Checking for suffix after "@"
Sun May 5 09:45:45 2019 : Debug: (135) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May 5 09:45:45 2019 : Debug: (135) suffix: No such realm "NULL"
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from suffix (rlm_realm)
Sun May 5 09:45:45 2019 : Debug: (135) [suffix] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (135) eap: Peer sent EAP Response (code 2) ID 1 length 22
Sun May 5 09:45:45 2019 : Debug: (135) eap: No EAP Start, assuming it's an on-going EAP conversation
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (135) [eap] = updated
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling files (rlm_files)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from files (rlm_files)
Sun May 5 09:45:45 2019 : Debug: (135) [files] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling sql (rlm_sql)
Sun May 5 09:45:45 2019 : Debug: %{User-Name}
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> test
Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test'
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (52)
Sun May 5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: User found in radcheck table
Sun May 5 09:45:45 2019 : Debug: (135) sql: Conditional check items matched, merging assignment check items
Sun May 5 09:45:45 2019 : Debug: (135) sql: Cleartext-Password := "991999"
Sun May 5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May 5 09:45:45 2019 : Debug: (135) sql: User found in radreply table, merging reply items
Sun May 5 09:45:45 2019 : Debug: (135) sql: Framed-IP-Address := 192.168.100.201
Sun May 5 09:45:45 2019 : Debug: (135) sql: ... falling-through to group processing
Sun May 5 09:45:45 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY priority
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May 5 09:45:45 2019 : Debug: (135) sql: User not found in any groups
Sun May 5 09:45:45 2019 : Debug: (135) sql: ... falling-through to profile processing
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (52)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from sql (rlm_sql)
Sun May 5 09:45:45 2019 : Debug: (135) [sql] = ok
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling expiration (rlm_expiration)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from expiration (rlm_expiration)
Sun May 5 09:45:45 2019 : Debug: (135) [expiration] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling logintime (rlm_logintime)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from logintime (rlm_logintime)
Sun May 5 09:45:45 2019 : Debug: (135) [logintime] = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling pap (rlm_pap)
Sun May 5 09:45:45 2019 : WARNING: (135) pap: Auth-Type already set. Not setting to PAP
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from pap (rlm_pap)
Sun May 5 09:45:45 2019 : Debug: (135) [pap] = noop
Sun May 5 09:45:45 2019 : Debug: (135) } # authorize = updated
Sun May 5 09:45:45 2019 : Debug: (135) Found Auth-Type = eap
Sun May 5 09:45:45 2019 : Debug: (135) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (135) authenticate {
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authenticate]: calling eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (135) eap: Expiring EAP session with state 0x59e200a159e304fe
Sun May 5 09:45:45 2019 : Debug: (135) eap: Finished EAP session with state 0x3288c5703289c17c
Sun May 5 09:45:45 2019 : Debug: (135) eap: Previous EAP request found for state 0x3288c5703289c17c, released from the list
Sun May 5 09:45:45 2019 : Debug: (135) eap: Peer sent packet with method EAP MD5 (4)
Sun May 5 09:45:45 2019 : Debug: (135) eap: Calling submodule eap_md5 to process data
Sun May 5 09:45:45 2019 : Debug: (135) eap: Sending EAP Success (code 3) ID 1 length 4
Sun May 5 09:45:45 2019 : Debug: (135) eap: Freeing handler
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authenticate]: returned from eap (rlm_eap)
Sun May 5 09:45:45 2019 : Debug: (135) [eap] = ok
Sun May 5 09:45:45 2019 : Debug: (135) } # authenticate = ok
Sun May 5 09:45:45 2019 : Debug: (135) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:45 2019 : Debug: (135) post-auth {
Sun May 5 09:45:45 2019 : Debug: (135) update {
Sun May 5 09:45:45 2019 : Debug: (135) No attributes updated
Sun May 5 09:45:45 2019 : Debug: (135) } # update = noop
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling sql (rlm_sql)
Sun May 5 09:45:45 2019 : Debug: .query
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: literal --> .query
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND .query
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> .query
Sun May 5 09:45:45 2019 : Debug: (135) sql: Using query template 'query'
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (56)
Sun May 5 09:45:45 2019 : Debug: %{User-Name}
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name}
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> test
Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test'
Sun May 5 09:45:45 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:45 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '
Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:45:45 2019 : Debug: literal --> ', '
Sun May 5 09:45:45 2019 : Debug: XLAT-IF {
Sun May 5 09:45:45 2019 : Debug: attribute --> User-Password
Sun May 5 09:45:45 2019 : Debug: }
Sun May 5 09:45:45 2019 : Debug: XLAT-ELSE {
Sun May 5 09:45:45 2019 : Debug: attribute --> CHAP-Password
Sun May 5 09:45:45 2019 : Debug: }
Sun May 5 09:45:45 2019 : Debug: literal --> ', '
Sun May 5 09:45:45 2019 : Debug: attribute --> Packet-Type
Sun May 5 09:45:45 2019 : Debug: literal --> ', '
Sun May 5 09:45:45 2019 : Debug: percent --> S
Sun May 5 09:45:45 2019 : Debug: literal --> ')
Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May 5 09:45:45 2019 : Debug: (135) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383')
Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383')
Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL query returned: success
Sun May 5 09:45:45 2019 : Debug: (135) sql: 1 record(s) updated
Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (56)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from sql (rlm_sql)
Sun May 5 09:45:45 2019 : Debug: (135) [sql] = ok
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling exec (rlm_exec)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from exec (rlm_exec)
Sun May 5 09:45:45 2019 : Debug: (135) [exec] = noop
Sun May 5 09:45:45 2019 : Debug: (135) policy remove_reply_message_if_eap {
Sun May 5 09:45:45 2019 : Debug: (135) if (&reply:EAP-Message && &reply:Reply-Message) {
Sun May 5 09:45:45 2019 : Debug: (135) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
Sun May 5 09:45:45 2019 : Debug: (135) else {
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling noop (rlm_always)
Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from noop (rlm_always)
Sun May 5 09:45:45 2019 : Debug: (135) [noop] = noop
Sun May 5 09:45:45 2019 : Debug: (135) } # else = noop
Sun May 5 09:45:45 2019 : Debug: (135) } # policy remove_reply_message_if_eap = noop
Sun May 5 09:45:45 2019 : Debug: (135) } # post-auth = ok
Sun May 5 09:45:45 2019 : Debug: (135) Empty pre-proxy section in virtual server "default". Using default return values.
Sun May 5 09:45:45 2019 : Debug: (135) proxy: Trying to allocate ID (0/2)
Sun May 5 09:45:45 2019 : Debug: (135) proxy: request is now in proxy hash
Sun May 5 09:45:45 2019 : Debug: (135) proxy: allocating destination 192.168.100.11 port 3799 - Id 21
Sun May 5 09:45:45 2019 : Debug: (135) session-state: Nothing to cache
Sun May 5 09:45:45 2019 : Debug: (135) Sent Disconnect-Request Id 21 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test"
Sun May 5 09:45:45 2019 : Debug: (135) Sent Access-Accept Id 169 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May 5 09:45:45 2019 : Debug: (135) Framed-IP-Address = 192.168.100.201
Sun May 5 09:45:45 2019 : Debug: (135) EAP-Message = 0x03010004
Sun May 5 09:45:45 2019 : Debug: (135) Message-Authenticator = 0x00000000000000000000000000000000
Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test"
Sun May 5 09:45:45 2019 : Debug: (135) Finished request
Sun May 5 09:45:45 2019 : Debug: Waking up in 2.2 seconds.
Sun May 5 09:45:45 2019 : Debug: (135) Clearing existing &reply: attributes
Sun May 5 09:45:45 2019 : Debug: (135) Received Disconnect-NAK Id 21 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May 5 09:45:45 2019 : Debug: (135) Empty post-proxy section in virtual server "default". Using default return values.
Sun May 5 09:45:45 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867
Sun May 5 09:45:45 2019 : Debug: Waking up in 4.8 seconds.
Sun May 5 09:45:46 2019 : Debug: (136) Received Accounting-Request Id 170 from 192.168.100.11:37595 to 192.168.100.12:1813 length 146
Sun May 5 09:45:46 2019 : Debug: (136) Acct-Status-Type = Start
Sun May 5 09:45:46 2019 : Debug: (136) Acct-Session-Id = "1557059862-236"
Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port-Type = Virtual
Sun May 5 09:45:46 2019 : Debug: (136) Service-Type = Framed-User
Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port = 236
Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port-Id = "IKEv2-EAP"
Sun May 5 09:45:46 2019 : Debug: (136) NAS-IP-Address = 192.168.100.11
Sun May 5 09:45:46 2019 : Debug: (136) Called-Station-Id = "192.168.100.11[4500]"
Sun May 5 09:45:46 2019 : Debug: (136) Calling-Station-Id = "153.119.175.39[56047]"
Sun May 5 09:45:46 2019 : Debug: (136) User-Name = "test"
Sun May 5 09:45:46 2019 : Debug: (136) Framed-IP-Address = 192.168.100.201
Sun May 5 09:45:46 2019 : Debug: (136) NAS-Identifier = "strongSwan"
Sun May 5 09:45:46 2019 : Debug: (136) # Executing section preacct from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:46 2019 : Debug: (136) preacct {
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling preprocess (rlm_preprocess)
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from preprocess (rlm_preprocess)
Sun May 5 09:45:46 2019 : Debug: (136) [preprocess] = ok
Sun May 5 09:45:46 2019 : Debug: (136) policy acct_unique {
Sun May 5 09:45:46 2019 : Debug: (136) update request {
Sun May 5 09:45:46 2019 : Debug: (136) &Tmp-String-9 := "ai:"
Sun May 5 09:45:46 2019 : Debug: (136) } # update request = noop
Sun May 5 09:45:46 2019 : Debug: (136) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
Sun May 5 09:45:46 2019 : Debug: (136) EXPAND %{hex:&Class}
Sun May 5 09:45:46 2019 : Debug: (136) -->
Sun May 5 09:45:46 2019 : Debug: (136) EXPAND ^%{hex:&Tmp-String-9}
Sun May 5 09:45:46 2019 : Debug: (136) --> ^61693a
Sun May 5 09:45:46 2019 : Debug: (136) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE
Sun May 5 09:45:46 2019 : Debug: (136) else {
Sun May 5 09:45:46 2019 : Debug: (136) update request {
Sun May 5 09:45:46 2019 : Debug: (136) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Sun May 5 09:45:46 2019 : Debug: (136) --> e233fff2cfee67c8e0763a9ba11758cb
Sun May 5 09:45:46 2019 : Debug: (136) &Acct-Unique-Session-Id := e233fff2cfee67c8e0763a9ba11758cb
Sun May 5 09:45:46 2019 : Debug: (136) } # update request = noop
Sun May 5 09:45:46 2019 : Debug: (136) } # else = noop
Sun May 5 09:45:46 2019 : Debug: (136) } # policy acct_unique = noop
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling suffix (rlm_realm)
Sun May 5 09:45:46 2019 : Debug: (136) suffix: Checking for suffix after "@"
Sun May 5 09:45:46 2019 : Debug: (136) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May 5 09:45:46 2019 : Debug: (136) suffix: No such realm "NULL"
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from suffix (rlm_realm)
Sun May 5 09:45:46 2019 : Debug: (136) [suffix] = noop
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling files (rlm_files)
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from files (rlm_files)
Sun May 5 09:45:46 2019 : Debug: (136) [files] = noop
Sun May 5 09:45:46 2019 : Debug: (136) } # preacct = ok
Sun May 5 09:45:46 2019 : Debug: (136) # Executing section accounting from file /etc/raddb/sites-enabled/default
Sun May 5 09:45:46 2019 : Debug: (136) accounting {
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling detail (rlm_detail)
Sun May 5 09:45:46 2019 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: literal --> /var/log/radius/radacct/
Sun May 5 09:45:46 2019 : Debug: XLAT-IF {
Sun May 5 09:45:46 2019 : Debug: attribute --> Packet-Src-IP-Address
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: XLAT-ELSE {
Sun May 5 09:45:46 2019 : Debug: attribute --> Packet-Src-IPv6-Address
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: literal --> /detail-
Sun May 5 09:45:46 2019 : Debug: percent --> Y
Sun May 5 09:45:46 2019 : Debug: percent --> m
Sun May 5 09:45:46 2019 : Debug: percent --> d
Sun May 5 09:45:46 2019 : Debug: (136) detail: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Sun May 5 09:45:46 2019 : Debug: (136) detail: --> /var/log/radius/radacct/192.168.100.11/detail-20190505
Sun May 5 09:45:46 2019 : Debug: (136) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/192.168.100.11/detail-20190505
Sun May 5 09:45:46 2019 : Debug: %t
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: percent --> t
Sun May 5 09:45:46 2019 : Debug: (136) detail: EXPAND %t
Sun May 5 09:45:46 2019 : Debug: (136) detail: --> Sun May 5 09:45:46 2019
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from detail (rlm_detail)
Sun May 5 09:45:46 2019 : Debug: (136) [detail] = ok
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling unix (rlm_unix)
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from unix (rlm_unix)
Sun May 5 09:45:46 2019 : Debug: (136) [unix] = ok
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling sql (rlm_sql)
Sun May 5 09:45:46 2019 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: xlat --> tolower
Sun May 5 09:45:46 2019 : Debug: {
Sun May 5 09:45:46 2019 : Debug: literal --> type.
Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Status-Type
Sun May 5 09:45:46 2019 : Debug: literal --> .query
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
Sun May 5 09:45:46 2019 : Debug: (136) sql: --> type.start.query
Sun May 5 09:45:46 2019 : Debug: (136) sql: Using query template 'query'
Sun May 5 09:45:46 2019 : Debug: rlm_sql (sql): Reserved connection (54)
Sun May 5 09:45:46 2019 : Debug: %{User-Name}
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND %{User-Name}
Sun May 5 09:45:46 2019 : Debug: (136) sql: --> test
Sun May 5 09:45:46 2019 : Debug: (136) sql: SQL-User-Name set to 'test'
Sun May 5 09:45:46 2019 : Debug: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: literal --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('
Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Session-Id
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Unique-Session-Id
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Realm
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-IP-Address
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: XLAT-IF {
Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port-Id
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: XLAT-ELSE {
Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port-Type
Sun May 5 09:45:46 2019 : Debug: literal --> ', FROM_UNIXTIME(
Sun May 5 09:45:46 2019 : Debug: xlat --> integer
Sun May 5 09:45:46 2019 : Debug: {
Sun May 5 09:45:46 2019 : Debug: literal --> Event-Timestamp
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: literal --> ), FROM_UNIXTIME(
Sun May 5 09:45:46 2019 : Debug: xlat --> integer
Sun May 5 09:45:46 2019 : Debug: {
Sun May 5 09:45:46 2019 : Debug: literal --> Event-Timestamp
Sun May 5 09:45:46 2019 : Debug: }
Sun May 5 09:45:46 2019 : Debug: literal --> ), NULL, '0', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Authentic
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Connect-Info
Sun May 5 09:45:46 2019 : Debug: literal --> ', '', '0', '0', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Called-Station-Id
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Calling-Station-Id
Sun May 5 09:45:46 2019 : Debug: literal --> ', '', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Service-Type
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Framed-Protocol
Sun May 5 09:45:46 2019 : Debug: literal --> ', '
Sun May 5 09:45:46 2019 : Debug: attribute --> Framed-IP-Address
Sun May 5 09:45:46 2019 : Debug: literal --> ')
Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
Sun May 5 09:45:46 2019 : Debug: (136) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201')
Sun May 5 09:45:46 2019 : Debug: (136) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets,calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201')
Sun May 5 09:45:46 2019 : Debug: (136) sql: SQL query returned: success
Sun May 5 09:45:46 2019 : Debug: (136) sql: 1 record(s) updated
Sun May 5 09:45:46 2019 : Debug: rlm_sql (sql): Released connection (54)
Sun May 5 09:45:46 2019 : Info: Need 1 more connections to reach 10 spares
Sun May 5 09:45:46 2019 : Info: rlm_sql (sql): Opening additional connection (61), 1 of 23 pending slots used
Sun May 5 09:45:46 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May 5 09:45:46 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from sql (rlm_sql)
Sun May 5 09:45:46 2019 : Debug: (136) [sql] = ok
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling exec (rlm_exec)
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from exec (rlm_exec)
Sun May 5 09:45:46 2019 : Debug: (136) [exec] = noop
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter)
Sun May 5 09:45:46 2019 : Debug: %{User-Name}
Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree:
Sun May 5 09:45:46 2019 : Debug: attribute --> User-Name
Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: EXPAND %{User-Name}
Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: --> test
Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: Matched entry DEFAULT at line 12
Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter)
Sun May 5 09:45:46 2019 : Debug: (136) [attr_filter.accounting_response] = updated
Sun May 5 09:45:46 2019 : Debug: (136) } # accounting = updated
Sun May 5 09:45:46 2019 : Debug: (136) Sent Accounting-Response Id 170 from 192.168.100.12:1813 to 192.168.100.11:37595 length 0
Sun May 5 09:45:46 2019 : Debug: (136) Finished request
Sun May 5 09:45:46 2019 : Debug: (136) Cleaning up request packet ID 170 with timestamp +1868
Sun May 5 09:45:46 2019 : Debug: Waking up in 4.7 seconds.
Sun May 5 09:45:50 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867
Sun May 5 09:45:50 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867
Sun May 5 09:45:50 2019 : Info: Ready to process requests
#########################################
this is not works log
#####################################################
Sun May 5 09:46:32 2019 : Debug: (138) Received Access-Request Id 172 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163
Sun May 5 09:46:32 2019 : Debug: (138) User-Name = "test"
Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port-Type = Virtual
Sun May 5 09:46:32 2019 : Debug: (138) Service-Type = Framed-User
Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port = 238
Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port-Id = "IKEv2-EAP"
Sun May 5 09:46:32 2019 : Debug: (138) NAS-IP-Address = 192.168.100.11
Sun May 5 09:46:32 2019 : Debug: (138) Called-Station-Id = "192.168.100.11[4500]"
Sun May 5 09:46:32 2019 : Debug: (138) Calling-Station-Id = "153.119.175.39[56451]"
Sun May 5 09:46:32 2019 : Debug: (138) Acct-Session-Id = "1557059862-238"
Sun May 5 09:46:32 2019 : Debug: (138) EAP-Message = 0x020000090174657374
Sun May 5 09:46:32 2019 : Debug: (138) NAS-Identifier = "strongSwan"
Sun May 5 09:46:32 2019 : Debug: (138) Message-Authenticator = 0xe29b962bf25ae5af41cb931202c00c6e
Sun May 5 09:46:32 2019 : Debug: (138) session-state: No State attribute
Sun May 5 09:46:32 2019 : Debug: (138) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (138) authorize {
Sun May 5 09:46:32 2019 : Debug: (138) update disconnect {
Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (138) --> test
Sun May 5 09:46:32 2019 : Debug: (138) &User-Name = test
Sun May 5 09:46:32 2019 : Debug: (138) } # update disconnect = noop
Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name){
Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name) -> TRUE
Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name) {
Sun May 5 09:46:32 2019 : Debug: (138) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May 5 09:46:32 2019 : Debug: %{User-Name}
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (138) --> test
Sun May 5 09:46:32 2019 : Debug: (138) SQL-User-Name set to 'test'
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (60)
Sun May 5 09:46:32 2019 : Debug: (138) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
Sun May 5 09:46:32 2019 : Debug: (138) SQL query returned no results
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (60)
Sun May 5 09:46:32 2019 : Info: Need 2 more connections to reach 10 spares
Sun May 5 09:46:32 2019 : Info: rlm_sql (sql): Opening additional connection (63), 1 of 24 pending slots used
Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10
Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May 5 09:46:32 2019 : Debug: (138) -->
Sun May 5 09:46:32 2019 : Debug: (138) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) } # if (User-Name) = noop
Sun May 5 09:46:32 2019 : Debug: (138) policy filter_username {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) -> TRUE
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ / /) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ / /) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@[^@]*@/ ) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.\./ ) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.\./ ) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
Sun May 5 09:46:32 2019 : Debug: (138) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.$/) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.$/) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@\./) {
Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@\./) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (138) } # if (&User-Name) = noop
Sun May 5 09:46:32 2019 : Debug: (138) } # policy filter_username = noop
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May 5 09:46:32 2019 : Debug: (138) [preprocess] = ok
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling chap (rlm_chap)
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from chap (rlm_chap)
Sun May 5 09:46:32 2019 : Debug: (138) [chap] = noop
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling mschap (rlm_mschap)
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May 5 09:46:32 2019 : Debug: (138) [mschap] = noop
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling digest (rlm_digest)
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from digest (rlm_digest)
Sun May 5 09:46:32 2019 : Debug: (138) [digest] = noop
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling suffix (rlm_realm)
Sun May 5 09:46:32 2019 : Debug: (138) suffix: Checking for suffix after "@"
Sun May 5 09:46:32 2019 : Debug: (138) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May 5 09:46:32 2019 : Debug: (138) suffix: No such realm "NULL"
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from suffix (rlm_realm)
Sun May 5 09:46:32 2019 : Debug: (138) [suffix] = noop
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (138) eap: Peer sent EAP Response (code 2) ID 0 length 9
Sun May 5 09:46:32 2019 : Debug: (138) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (138) [eap] = ok
Sun May 5 09:46:32 2019 : Debug: (138) } # authorize = ok
Sun May 5 09:46:32 2019 : Debug: (138) Found Auth-Type = eap
Sun May 5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (138) authenticate {
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authenticate]: calling eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (138) eap: Peer sent packet with method EAP Identity (1)
Sun May 5 09:46:32 2019 : Debug: (138) eap: Calling submodule eap_md5 to process data
Sun May 5 09:46:32 2019 : Debug: (138) eap_md5: Issuing MD5 Challenge
Sun May 5 09:46:32 2019 : Debug: (138) eap: Sending EAP Request (code 1) ID 1 length 22
Sun May 5 09:46:32 2019 : Debug: (138) eap: EAP session adding &reply:State = 0x6048d1426049d56d
Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authenticate]: returned from eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (138) [eap] = handled
Sun May 5 09:46:32 2019 : Debug: (138) } # authenticate = handled
Sun May 5 09:46:32 2019 : Debug: (138) Using Post-Auth-Type Challenge
Sun May 5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (138) Challenge { ... } # empty sub-section is ignored
Sun May 5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache
Sun May 5 09:46:32 2019 : Debug: (138) Empty pre-proxy section in virtual server "default". Using default return values.
Sun May 5 09:46:32 2019 : Debug: (138) proxy: Trying to allocate ID (0/2)
Sun May 5 09:46:32 2019 : Debug: (138) proxy: request is now in proxy hash
Sun May 5 09:46:32 2019 : Debug: (138) proxy: allocating destination 192.168.100.11 port 3799 - Id 57
Sun May 5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache
Sun May 5 09:46:32 2019 : Debug: (138) Sent Disconnect-Request Id 57 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May 5 09:46:32 2019 : Debug: (138) User-Name = "test"
Sun May 5 09:46:32 2019 : Debug: (138) Sent Access-Challenge Id 172 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May 5 09:46:32 2019 : Debug: (138) EAP-Message = 0x0101001604106d1b45d49f879829562d2c46943013e8
Sun May 5 09:46:32 2019 : Debug: (138) Message-Authenticator = 0x00000000000000000000000000000000
Sun May 5 09:46:32 2019 : Debug: (138) State = 0x6048d1426049d56d1e82e3d0d58b93c7
Sun May 5 09:46:32 2019 : Debug: (138) Finished request
Sun May 5 09:46:32 2019 : Debug: Waking up in 2.5 seconds.
Sun May 5 09:46:32 2019 : Debug: (138) Clearing existing &reply: attributes
Sun May 5 09:46:32 2019 : Debug: (138) Received Disconnect-NAK Id 57 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May 5 09:46:32 2019 : Debug: (138) Empty post-proxy section in virtual server "default". Using default return values.
Sun May 5 09:46:32 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914
Sun May 5 09:46:32 2019 : Debug: Waking up in 4.9 seconds.
Sun May 5 09:46:32 2019 : Debug: (139) Received Access-Request Id 173 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194
Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test"
Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port-Type = Virtual
Sun May 5 09:46:32 2019 : Debug: (139) Service-Type = Framed-User
Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port = 238
Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port-Id = "IKEv2-EAP"
Sun May 5 09:46:32 2019 : Debug: (139) NAS-IP-Address = 192.168.100.11
Sun May 5 09:46:32 2019 : Debug: (139) Called-Station-Id = "192.168.100.11[4500]"
Sun May 5 09:46:32 2019 : Debug: (139) Calling-Station-Id = "153.119.175.39[56451]"
Sun May 5 09:46:32 2019 : Debug: (139) Acct-Session-Id = "1557059862-238"
Sun May 5 09:46:32 2019 : Debug: (139) EAP-Message = 0x0201001604101a5615717d21560f482951e9124181b2
Sun May 5 09:46:32 2019 : Debug: (139) NAS-Identifier = "strongSwan"
Sun May 5 09:46:32 2019 : Debug: (139) State = 0x6048d1426049d56d1e82e3d0d58b93c7
Sun May 5 09:46:32 2019 : Debug: (139) Message-Authenticator = 0x1002eed55d62afee39fbe2fcd41869de
Sun May 5 09:46:32 2019 : Debug: (139) session-state: No cached attributes
Sun May 5 09:46:32 2019 : Debug: (139) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (139) authorize {
Sun May 5 09:46:32 2019 : Debug: (139) update disconnect {
Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (139) --> test
Sun May 5 09:46:32 2019 : Debug: (139) &User-Name = test
Sun May 5 09:46:32 2019 : Debug: (139) } # update disconnect = noop
Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name){
Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name) -> TRUE
Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name) {
Sun May 5 09:46:32 2019 : Debug: (139) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
Sun May 5 09:46:32 2019 : Debug: %{User-Name}
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (139) --> test
Sun May 5 09:46:32 2019 : Debug: (139) SQL-User-Name set to 'test'
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (55)
Sun May 5 09:46:32 2019 : Debug: (139) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null
Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
Sun May 5 09:46:32 2019 : Debug: (139) SQL query returned no results
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (55)
Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}
Sun May 5 09:46:32 2019 : Debug: (139) -->
Sun May 5 09:46:32 2019 : Debug: (139) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) } # if (User-Name) = noop
Sun May 5 09:46:32 2019 : Debug: (139) policy filter_username {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) -> TRUE
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ / /) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ / /) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@[^@]*@/ ) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.\./ ) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.\./ ) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
Sun May 5 09:46:32 2019 : Debug: (139) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.$/) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.$/) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@\./) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@\./) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) } # if (&User-Name) = noop
Sun May 5 09:46:32 2019 : Debug: (139) } # policy filter_username = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun May 5 09:46:32 2019 : Debug: (139) [preprocess] = ok
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling chap (rlm_chap)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from chap (rlm_chap)
Sun May 5 09:46:32 2019 : Debug: (139) [chap] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling mschap (rlm_mschap)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from mschap (rlm_mschap)
Sun May 5 09:46:32 2019 : Debug: (139) [mschap] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling digest (rlm_digest)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from digest (rlm_digest)
Sun May 5 09:46:32 2019 : Debug: (139) [digest] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling suffix (rlm_realm)
Sun May 5 09:46:32 2019 : Debug: (139) suffix: Checking for suffix after "@"
Sun May 5 09:46:32 2019 : Debug: (139) suffix: No '@' in User-Name = "test", looking up realm NULL
Sun May 5 09:46:32 2019 : Debug: (139) suffix: No such realm "NULL"
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from suffix (rlm_realm)
Sun May 5 09:46:32 2019 : Debug: (139) [suffix] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (139) eap: Peer sent EAP Response (code 2) ID 1 length 22
Sun May 5 09:46:32 2019 : Debug: (139) eap: No EAP Start, assuming it's an on-going EAP conversation
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (139) [eap] = updated
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling files (rlm_files)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from files (rlm_files)
Sun May 5 09:46:32 2019 : Debug: (139) [files] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling sql (rlm_sql)
Sun May 5 09:46:32 2019 : Debug: %{User-Name}
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> test
Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test'
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (52)
Sun May 5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: User found in radcheck table
Sun May 5 09:46:32 2019 : Debug: (139) sql: Conditional check items matched, merging assignment check items
Sun May 5 09:46:32 2019 : Debug: (139) sql: Cleartext-Password := "991999"
Sun May 5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
Sun May 5 09:46:32 2019 : Debug: (139) sql: User found in radreply table, merging reply items
Sun May 5 09:46:32 2019 : Debug: (139) sql: Framed-IP-Address := 192.168.100.201
Sun May 5 09:46:32 2019 : Debug: (139) sql: ... falling-through to group processing
Sun May 5 09:46:32 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY priority
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
Sun May 5 09:46:32 2019 : Debug: (139) sql: User not found in any groups
Sun May 5 09:46:32 2019 : Debug: (139) sql: ... falling-through to profile processing
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (52)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from sql (rlm_sql)
Sun May 5 09:46:32 2019 : Debug: (139) [sql] = ok
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling expiration (rlm_expiration)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from expiration (rlm_expiration)
Sun May 5 09:46:32 2019 : Debug: (139) [expiration] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling logintime (rlm_logintime)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from logintime (rlm_logintime)
Sun May 5 09:46:32 2019 : Debug: (139) [logintime] = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling pap (rlm_pap)
Sun May 5 09:46:32 2019 : WARNING: (139) pap: Auth-Type already set. Not setting to PAP
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from pap (rlm_pap)
Sun May 5 09:46:32 2019 : Debug: (139) [pap] = noop
Sun May 5 09:46:32 2019 : Debug: (139) } # authorize = updated
Sun May 5 09:46:32 2019 : Debug: (139) Found Auth-Type = eap
Sun May 5 09:46:32 2019 : Debug: (139) # Executing group from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (139) authenticate {
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authenticate]: calling eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x59e200a159e304fe
Sun May 5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x6048d1426049d56d
Sun May 5 09:46:32 2019 : Debug: (139) eap: Finished EAP session with state 0x6048d1426049d56d
Sun May 5 09:46:32 2019 : Debug: (139) eap: Previous EAP request found for state 0x6048d1426049d56d, released from the list
Sun May 5 09:46:32 2019 : Debug: (139) eap: Peer sent packet with method EAP MD5 (4)
Sun May 5 09:46:32 2019 : Debug: (139) eap: Calling submodule eap_md5 to process data
Sun May 5 09:46:32 2019 : Debug: (139) eap: Sending EAP Success (code 3) ID 1 length 4
Sun May 5 09:46:32 2019 : Debug: (139) eap: Freeing handler
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authenticate]: returned from eap (rlm_eap)
Sun May 5 09:46:32 2019 : Debug: (139) [eap] = ok
Sun May 5 09:46:32 2019 : Debug: (139) } # authenticate = ok
Sun May 5 09:46:32 2019 : Debug: (139) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Sun May 5 09:46:32 2019 : Debug: (139) post-auth {
Sun May 5 09:46:32 2019 : Debug: (139) update {
Sun May 5 09:46:32 2019 : Debug: (139) No attributes updated
Sun May 5 09:46:32 2019 : Debug: (139) } # update = noop
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling sql (rlm_sql)
Sun May 5 09:46:32 2019 : Debug: .query
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: literal --> .query
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND .query
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> .query
Sun May 5 09:46:32 2019 : Debug: (139) sql: Using query template 'query'
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (56)
Sun May 5 09:46:32 2019 : Debug: %{User-Name}
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name}
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> test
Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test'
Sun May 5 09:46:32 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree:
Sun May 5 09:46:32 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '
Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name
Sun May 5 09:46:32 2019 : Debug: literal --> ', '
Sun May 5 09:46:32 2019 : Debug: XLAT-IF {
Sun May 5 09:46:32 2019 : Debug: attribute --> User-Password
Sun May 5 09:46:32 2019 : Debug: }
Sun May 5 09:46:32 2019 : Debug: XLAT-ELSE {
Sun May 5 09:46:32 2019 : Debug: attribute --> CHAP-Password
Sun May 5 09:46:32 2019 : Debug: }
Sun May 5 09:46:32 2019 : Debug: literal --> ', '
Sun May 5 09:46:32 2019 : Debug: attribute --> Packet-Type
Sun May 5 09:46:32 2019 : Debug: literal --> ', '
Sun May 5 09:46:32 2019 : Debug: percent --> S
Sun May 5 09:46:32 2019 : Debug: literal --> ')
Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Sun May 5 09:46:32 2019 : Debug: (139) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711')
Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711')
Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL query returned: success
Sun May 5 09:46:32 2019 : Debug: (139) sql: 1 record(s) updated
Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (56)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from sql (rlm_sql)
Sun May 5 09:46:32 2019 : Debug: (139) [sql] = ok
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling exec (rlm_exec)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from exec (rlm_exec)
Sun May 5 09:46:32 2019 : Debug: (139) [exec] = noop
Sun May 5 09:46:32 2019 : Debug: (139) policy remove_reply_message_if_eap {
Sun May 5 09:46:32 2019 : Debug: (139) if (&reply:EAP-Message && &reply:Reply-Message) {
Sun May 5 09:46:32 2019 : Debug: (139) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
Sun May 5 09:46:32 2019 : Debug: (139) else {
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling noop (rlm_always)
Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from noop (rlm_always)
Sun May 5 09:46:32 2019 : Debug: (139) [noop] = noop
Sun May 5 09:46:32 2019 : Debug: (139) } # else = noop
Sun May 5 09:46:32 2019 : Debug: (139) } # policy remove_reply_message_if_eap = noop
Sun May 5 09:46:32 2019 : Debug: (139) } # post-auth = ok
Sun May 5 09:46:32 2019 : Debug: (139) Empty pre-proxy section in virtual server "default". Using default return values.
Sun May 5 09:46:32 2019 : Debug: (139) proxy: Trying to allocate ID (0/2)
Sun May 5 09:46:32 2019 : Debug: (139) proxy: request is now in proxy hash
Sun May 5 09:46:32 2019 : Debug: (139) proxy: allocating destination 192.168.100.11 port 3799 - Id 104
Sun May 5 09:46:32 2019 : Debug: (139) session-state: Nothing to cache
Sun May 5 09:46:32 2019 : Debug: (139) Sent Disconnect-Request Id 104 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26
Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test"
Sun May 5 09:46:32 2019 : Debug: (139) Sent Access-Accept Id 173 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0
Sun May 5 09:46:32 2019 : Debug: (139) Framed-IP-Address = 192.168.100.201
Sun May 5 09:46:32 2019 : Debug: (139) EAP-Message = 0x03010004
Sun May 5 09:46:32 2019 : Debug: (139) Message-Authenticator = 0x00000000000000000000000000000000
Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test"
Sun May 5 09:46:32 2019 : Debug: (139) Finished request
Sun May 5 09:46:32 2019 : Debug: Waking up in 2.1 seconds.
Sun May 5 09:46:32 2019 : Debug: (139) Clearing existing &reply: attributes
Sun May 5 09:46:32 2019 : Debug: (139) Received Disconnect-ACK Id 104 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20
Sun May 5 09:46:32 2019 : Debug: (139) Empty post-proxy section in virtual server "default". Using default return values.
Sun May 5 09:46:32 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914
Sun May 5 09:46:32 2019 : Debug: Waking up in 4.8 seconds.
Sun May 5 09:46:37 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914
Sun May 5 09:46:37 2019 : Debug: Waking up in 0.1 seconds.
Sun May 5 09:46:37 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914
Sun May 5 09:46:37 2019 : Info: Ready to process requests
##################################################
I think
when server does this：
##################################
update disconnect{
&User-Name = "%{User-Name}"
}
if(User-Name){
if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){
}
}
####################################
it shoud wait for the Disconnect-ACK or Disconnect-NAK
and then do the next
##################
filter_username
... ...
##################
how can I write ?
or how to write a delay time befor “filter_username”?
or is there other idea to do this (disconnect same user both strongswan and freeradius whatever ) ?
Thanks very much!
More information about the Freeradius-Users
mailing list