- Freeradius-Users - lists.freeradius.org

RE: redis_ippool module doesnot process lease_time in ack
by Chinnapaiyan, Nagamani 07 May '19

07 May '19

Alan, > Huh? That doesn't make sense. > The lease_time configuration item is supposed to be a number. Like "86400". > If you're setting the lease time here, why use the redis_ippool module? I'm not sure that I understand. We want to use different lease time for different set of mac addresses. The sites-enabled/dhcp chooses that number based on some logic on MAC address. redis_ippool module uses that number. Arran, > Could you also provide the command that you used to create the pool and addresses in it. /usr/local/bin/rlm_redis_ippool_tool -a 10.88.64.2-10.88.67.254 devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com VSAT-UT I am using old git hash 5309825993e5c61a4b2551d9799ba41ff141478c on master branch. Regards, Nagamani Chinnapaiyan

1 0

disconnect same user both whatever
by 佛来佛网 06 May '19

06 May '19

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 !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:45:45 2019 : Debug: (134) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:45:45 2019 : Debug: (135) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:46:32 2019 : Debug: (138) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:46:32 2019 : Debug: (139) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /(a)\./) -> 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!

2 1

Freeradius does not Executing section "authorize from file /etc/freeradius/sites-enabled/default"
by myxmail1919＠yahoo.com 06 May '19

06 May '19

Hi everyone,,maybe someone can help me ? have a mysql query in /etc/freeradius/sites-enabled/default (authorize section )before authorizeing a user it checks for some attributes in mysql it works fine when i run freeradius and test it with some users !but it does not Executing section "authorize from file /etc/freeradius/sites-enabled/default" when i start freeradius under heavy load ! Start radius and test with some users : # Executing section authorize from file /etc/freeradius/sites-enabled/default +group authorize { ++[preprocess] = ok rlm_sql (sql): Released sql socket id: 29 expand: %{sql:SELECT ************************************** } ->? Evaluating ("%{sql:SELECT ************************************** }" > 1 ) -> FALSE++? if ("%{sql:SELECT ************************************** " > 1 ) -> FALSE++else else {+++[ok] = ok+++update control { +++} # update control = noop++} # else else = ok

3 4

How can i reset user quota after user consumed completely
by Abdul Riyaz 06 May '19

06 May '19

Hi, I have a user called "user" with Cleartext-Password:- 123456. I installed freeradius in UBuntu 18.04 in docker container. Now, I connected freeradius to Mikrotik Nas. Everythings works fine. user has attributes: Mikrotik-Rate-Limit :- 1000k/1000k Mikrotik-Total-Limit :- 200000000 (~2GB) Expiration: 1559678897 (June 5th 2019) The user has already consumed 2GB of data within 2 days. Data exhausted and user is unable to login. How can i reset the "user" with same quota manually. When package is changed, i want user to start using new data. I don;t wanna mess with radacct table. Can anyone advise how can i achieve this? TO say Simply, change package after data is consumed. user should login this time. My question might be so silly but please help me with this. Many Thanks Abdul Riyaz

2 1

RE: redis_ippool module doesnot process lease_time in ack
by Chinnapaiyan, Nagamani 04 May '19

04 May '19

redis_ippool module: redis_ippool { # # Note all configuration items at this level (above the redis block) # are polymorphic, meaning xlats, attribute references, literal values # and execs may be specified. # # For example pool_name could be pool_name = 'my_test_pool' if only a # single pool were being used. # # Name of the pool to allocate leases from. # pool_name = &control:Pool-Name # # How long a lease is reserved for after making an offer to the DHCP client # if no value is provided, the value from lease_time is used for initial # allocations. No value should be provided for PPP/VPNs, this is mainly for # the DORA flow in DHCP. # offer_time = 120 # # How long a lease is allocated for # lease_time = &reply:DHCP-IP-Address-Lease-Time # # The device identifier, usually the Mac-Address but could be a combination # of attributes, a user-name or a certificate serial number (if the number # of sessions were limited to one per user/serial). # device = &DHCP-Client-Hardware-Address # # The IP address being renewed or released # requested_address = "%{%{DHCP-Requested-IP-Address}:-%{DHCP-Client-IP-Address}}" # # List and attribute where the allocated address is written to. # allocated_address_attr = &reply:DHCP-Your-IP-Address # # List and attribute where the Pool-Range ID (if set) is written to. # # The idea of the Pool-Range is that it provides a key into other datastores # or caches, which store the additional options associated with the range an # IP address belongs to. # # There may be multiple ranges of IP address contained within any given pool, # which is why this is provided in addition to the pool name. # range_attr = &reply:Pool-Range # # If set - the list and attribute to write the remaining lease time to. # This can be populated on alloc, or renew, if an IP address was available # for the alloc. # expiry_attr = &reply:DHCP-IP-Address-Lease-Time # # If true - Copy the value of ip_address to the attribute specified by # reply_attr when performing an update/renew. This is needed for DHCP where # we need to send back DHCP-Your-IP-Address in ACKs. # copy_on_update = yes # # Redis connection settings - Identical to all other Redis based modules. # redis { server = devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com pool { start = 0 min = ${thread[pool].num_workers} max = ${thread[pool].num_workers} spare = 1 uses = 0 lifetime = 0 retry_delay = 30 idle_timeout = 60 } } } dhcp server: recv DHCP-Request { ... update reply { &DHCP-IP-Address-Lease-Time = 3600 &DHCP-Domain-Name-Server = 72.173.31.41 ... } Regards, Nagamani Chinnapaiyan

3 2

Fwd: Re: SQL query as fallback to auth script?
by Wladyslaw Jankowski 04 May '19

04 May '19

On 03.05.19 18:35, Alan DeKok wrote: >> On May 3, 2019, at 10:40 AM, Wladyslaw Jankowski <wladekj(a)interia.pl> >> wrote: >> >> Learn how to format your messages. When you make it difficult for us >> to help you, we're inclined to avoid helping you. Please accept my apologies for my last message's formatting. What was written in plain ASCII became somehow re-formatted to HTML, and a lot of newlines were scrambled. Using different client now. >> This is the idea: script should always reject - doing its thing >> behind the scenes - and allow for SQL fallback. >> >> That makes no sense whatsoever. If the script always rejects, then >> you always need a work-around for that reject. >> >> Why not just have the script do it's thing, and have it return an >> "ok" code? The idea is for the script to ping the auth server (proprietary solution) for given user's NT hash, and store it in a local database for a short period of time. Script should always "Reject" and there is where I was hoping for an ability for an SQL fallback. This way the script would temporarily insert NT hash into the local database, and FreeRADIUS would query the database entry moments later. This would introduce a short delay but should work - would the fallback be possible. > I can't "Accept" RADIUS auth with this script as it can't calculate > MSCHAP challanges and no cleartext password will be provided to it > (can't use PAP). > Yes, FreeRADIUS does authentication. Your script doesn't. That's the > way it should work./ From my understanding of MSCHAP RFC documents - access to the NT hash is required to calculate/validate the challenge and/or Authenticator field. The idea was for the RADIUS server not to have full access to the whole database but to fire up a script that would grab one given hash, store it in a local database, and allow FreeRADIUS to use "sql" authorization method to validate the MSCHAP challenge based on the NT hash. > Perhaps you could set a password? > > Or, set "Auth-Type := Accept" if you want the user to always be accepted. I can't blindly accept any given password without validation. The least insecure way I've figured out was to be able to grab one given hash and work with that. That's why the script was supposed to always "Reject" (or is there like a half-way-Reject allowing for fallback?). > The problem here is that you're asking how to fix the "solution" you > came up with. That's bad practice. Instead, you should be describing > your requirements. We can then offer you advice as to how to meet > those requirements. My requirements were basically that I would like to be able to authorize users with EAP-MSCHAPv2 / EAP-TTLS without having direct access to the db with NT passwords. With PAP it is possible to pass %{User-Password} to the script but no such field is present in MSCHAPv2 packets. The fallback-idea was to blindly grab the (one given) hash from the proprietary solution and allow FreeRADIUS to validate credentials based on it. Short after it was supposed to be deleted from local store. > So what are you trying to do? What *problem* are you trying to solve? > And don't answer "run the script and SQL". That isn't relevant. What > are the users trying to do? What answers do you want the RADIUS server > to return? And why? Initial problem: with fancy-artsy authorization methods - the password is not being sent in clear text like it was with PAP - so there is no way to pass username and password to the script. Desired behavior: RADIUS server should Accept or Reject the request based on given credentials. I was hoping here to do this in such way that FreeRADIUS wouldn't have to have access to the full database but I guess that I'll have to go this path if it's the only viable option(?) Thanks WJ

1 0

Instance on Files Module
by Nicolas Breuer 04 May '19

04 May '19

Hello, I tried to configure two instances for the files modules but doesn’t seems to work.. files DSL { # Search for files in a subdirectory of mods-config which # matches this instance of the files module. moddir = ${modconfdir}/${.:instance} filename = ${moddir}/authorize instance=DSL usersfile = ${moddir}/authorize1 acctusersfile = ${moddir}/accounting preproxy_usersfile = ${moddir}/pre-proxy } files { # Search for files in a subdirectory of mods-config which # matches this instance of the files module. moddir = ${modconfdir}/${.:instance} filename = ${moddir}/authorize instance=dialup usersfile = ${moddir}/authorize2 acctusersfile = ${moddir}/accounting preproxy_usersfile = ${moddir}/pre-proxy } Looked on the website & docs but didn’t find any informations about that 😊

4 8

Evaluation of Service-Type.
by Nicolas Breuer 03 May '19

03 May '19

Hello, Any ideas what is wrong here ? (0) if (&reply:Service-Type == test) { (0) ERROR: Failed retrieving values required to evaluate condition Thanks in advance,

3 9

How to check logs
by Tornóci László 03 May '19

03 May '19

Hi, I use freeradius to provide eduroam service for our university. It works fine. My setup is pretty basic, with just a few changes from the default. I am using EAP-TTLS with PAP in the inner tunnel. Yesterday I got a complaint from a foreign user, he didn't get wifi service with his usual settings. I looked for the logs under radacct/ in the folder with the IP of the NAS. I have 'auth-detail', 'pre-proxy', 'post-proxy' and 'reply-detail'. I was able to find logs of his packages in auth-detail and pre-proxy, but was unable to find out if I got any reply. I can link logs of packets between 'auth-detail' and 'pre-proxy', and also between 'post-proxy' and 'reply-detail', but I couldn't find a way to see which reply-detail packets correspond to any one in auth-detail. Is that possible? If yes, how? If not, what should I do to be able to track reports like that without running the server in debug mode? Laszlo

2 1

Compilation Issue
by Nicolas Breuer 03 May '19

03 May '19

Any ideas about this compilation issue : CC src/lib/cbuff.c In file included from /usr/include/talloc.h:28, from src/freeradius-devel/libradius.h:60, from src/lib/cbuff.c:26: /usr/include/stdlib.h:96: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__BEGIN_NAMESPACE_STDâ /usr/include/stdlib.h:140: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before âexternâ /usr/include/stdlib.h:145: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before âexternâ /usr/include/stdlib.h: In function âatoiâ: /usr/include/stdlib.h:149: error: expected declaration specifiers before â__THROWâ /usr/include/stdlib.h:152: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:153: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:168: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:190: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:191: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:382: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:383: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:474: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:475: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:488: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:489: error: expected declaration specifiers before â__END_NAMESPACE_STDâ /usr/include/stdlib.h:518: error: expected â=â, â,â, â;â, âasmâ or â__attribute__â before â__THROWâ /usr/include/stdlib.h:531: error: expected declaration specifiers before â__END_NAMESPACE_STDâ .....

3 14