Freeradius and smsotp
Milovan Kotlica
milovan.kotlica at hb.co.me
Mon Jul 27 08:48:26 CEST 2020
Hi,
I have installed Freeradius 2.1.12 on Centos 6 and I use Thomas
Glanzmann SMSOTP. Now I want to migrate that on Centos 8. I installed
Freeradius 3.0.17 and same SMSOTP. When I login on vpn I first type
username/password and after that smsotp pin.
On new instalation I have issue with smsotp. My first login is OK and
smsotp module creates and send smsotp pin. But after I type smsotp pin
on vpn radius reject.
smsotpd.pl scripts return wornings:
Subroutine _call redefined at (eval 155) line 30.
Subroutine SendSMSExtService::want_som redefined at (eval 155) line 73.
Subroutine AUTOLOAD redefined at (eval 155) line 90.
Subroutine SendSMSExtService::SendSMSExt redefined at (eval 155) line 88.
Server session encountered read error 104: Connection reset by peer
Server session encountered read error 104: Connection reset by peer
p.s. In attach is last part of Freeradius debug.
Thanks
-------------- next part --------------
Sun Jul 26 18:20:01 2020 : Debug: (1) ntlm_auth_vpn_hb: Program returned code (0) and output 'NT_STATUS_OK: The operation completed successfully. (0x0)'
Sun Jul 26 18:20:01 2020 : Debug: (1) ntlm_auth_vpn_hb: Program executed successfully
Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: returned from ntlm_auth_vpn_hb (rlm_exec)
Sun Jul 26 18:20:01 2020 : Debug: (1) [ntlm_auth_vpn_hb] = ok
Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: calling smsotp (rlm_smsotp)
Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp (smsotp): Reserved connection (0)
Sun Jul 26 18:20:01 2020 : Debug: (1) smsotp: Generating OTP
Sun Jul 26 18:20:01 2020 : Debug: (1) smsotp: Unique ID is 8475108159
Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp: Sending Access-Challenge
Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp (smsotp): Released connection (0)
Sun Jul 26 18:20:01 2020 : Info: rlm_smsotp (smsotp): Closing connection (1), from 4 unused connections
Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: returned from smsotp (rlm_smsotp)
Sun Jul 26 18:20:01 2020 : Debug: (1) [smsotp] = handled
Sun Jul 26 18:20:01 2020 : Debug: (1) } # Auth-Type smsotp = handled
Sun Jul 26 18:20:01 2020 : Debug: (1) Using Post-Auth-Type Challenge
Sun Jul 26 18:20:01 2020 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default
Sun Jul 26 18:20:01 2020 : Debug: (1) Challenge { ... } # empty sub-section is ignored
Sun Jul 26 18:20:01 2020 : Debug: (1) session-state: Nothing to cache
Sun Jul 26 18:20:01 2020 : Debug: (1) Sent Access-Challenge Id 200 from 10.100.x.60:1812 to 10.100.x.3:17138 length 0
Sun Jul 26 18:20:01 2020 : Debug: (1) Framed-IP-Address = 10.100.x.112
Sun Jul 26 18:20:01 2020 : Debug: (1) Reply-Message = "Enter Mobile PIN:"
Sun Jul 26 18:20:01 2020 : Debug: (1) State = 0x38343735313038313539
Sun Jul 26 18:20:01 2020 : Debug: (1) Finished request
Sun Jul 26 18:20:01 2020 : Debug: Waking up in 4.9 seconds.
Sun Jul 26 18:20:06 2020 : Debug: (1) Cleaning up request packet ID 200 with timestamp +83
Sun Jul 26 18:20:06 2020 : Info: Ready to process requests
Sun Jul 26 18:20:16 2020 : Debug: (2) Received Access-Request Id 201 from 10.100.x.3:17138 to 10.100.x.60:1812 length 627
Sun Jul 26 18:20:16 2020 : Debug: (2) User-Name = "milovan.kotlica"
Sun Jul 26 18:20:16 2020 : Debug: (2) User-Password = "02987"
Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-Port = 37847040
Sun Jul 26 18:20:16 2020 : Debug: (2) Called-Station-Id = "x.x.x.x"
Sun Jul 26 18:20:16 2020 : Debug: (2) Calling-Station-Id = "109.228.125.82"
Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-Port-Type = Virtual
Sun Jul 26 18:20:16 2020 : Debug: (2) Tunnel-Client-Endpoint:0 = "109.228.125.82"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-phone-id=unknown"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-platform=android"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-platform-version=10"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-mac=aa-02-36-c3-b3-aa"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-type=samsung SM-A715F"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=ac-user-agent=AnyConnect Android 4.8.03651"
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-uid=8137C81B06B9A4D33B3B673C1BFA077AF83273B03ADA995C4276C4F534E349EF"
Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-IP-Address = 10.100.x.3
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "audit-session-id=0a64c803024180005f1db0f4"
Sun Jul 26 18:20:16 2020 : Debug: (2) State = 0x38343735313038313539
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "ip:source-ip=109.228.125.82"
Sun Jul 26 18:20:16 2020 : Debug: (2) ASA-TunnelGroupName = "XXXXXXX"
Sun Jul 26 18:20:16 2020 : Debug: (2) ASA-ClientType = AnyConnect-Client-SSL-VPN
Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "coa-push=true"
Sun Jul 26 18:20:16 2020 : Debug: (2) session-state: No cached attributes
Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default
Sun Jul 26 18:20:16 2020 : Debug: (2) authorize {
Sun Jul 26 18:20:16 2020 : Debug: (2) policy filter_username {
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) {
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) -> TRUE
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) {
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ / /) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ / /) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.\./ ) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.\./ ) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.$/) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.$/) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@\./) {
Sun Jul 26 18:20:16 2020 : Debug: No matches
Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@\./) -> FALSE
Sun Jul 26 18:20:16 2020 : Debug: (2) } # if (&User-Name) = notfound
Sun Jul 26 18:20:16 2020 : Debug: (2) } # policy filter_username = notfound
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Sun Jul 26 18:20:16 2020 : Debug: (2) [preprocess] = ok
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling auth_log (rlm_detail)
Sun Jul 26 18:20:16 2020 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> /var/log/radius/radacct/
Sun Jul 26 18:20:16 2020 : Debug: XLAT-IF {
Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Src-IP-Address
Sun Jul 26 18:20:16 2020 : Debug: }
Sun Jul 26 18:20:16 2020 : Debug: XLAT-ELSE {
Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Src-IPv6-Address
Sun Jul 26 18:20:16 2020 : Debug: }
Sun Jul 26 18:20:16 2020 : Debug: literal --> /auth-detail-
Sun Jul 26 18:20:16 2020 : Debug: percent --> Y
Sun Jul 26 18:20:16 2020 : Debug: percent --> m
Sun Jul 26 18:20:16 2020 : Debug: percent --> d
Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: --> /var/log/radius/radacct/10.100.x.3/auth-detail-20200726
Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.100.x.3/auth-detail-20200726
Sun Jul 26 18:20:16 2020 : Debug: %t
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: percent --> t
Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: EXPAND %t
Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: --> Sun Jul 26 18:20:16 2020
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from auth_log (rlm_detail)
Sun Jul 26 18:20:16 2020 : Debug: (2) [auth_log] = ok
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling chap (rlm_chap)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from chap (rlm_chap)
Sun Jul 26 18:20:16 2020 : Debug: (2) [chap] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap)
Sun Jul 26 18:20:16 2020 : Debug: (2) [mschap] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling digest (rlm_digest)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from digest (rlm_digest)
Sun Jul 26 18:20:16 2020 : Debug: (2) [digest] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm)
Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: Checking for suffix after "@"
Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: No '@' in User-Name = "milovan.kotlica", looking up realm NULL
Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: No such realm "NULL"
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm)
Sun Jul 26 18:20:16 2020 : Debug: (2) [suffix] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap)
Sun Jul 26 18:20:16 2020 : Debug: (2) eap: No EAP-Message, not doing EAP
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap)
Sun Jul 26 18:20:16 2020 : Debug: (2) [eap] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling files (rlm_files)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from files (rlm_files)
Sun Jul 26 18:20:16 2020 : Debug: (2) [files] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling sql (rlm_sql)
Sun Jul 26 18:20:16 2020 : Debug: %{User-Name}
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: attribute --> User-Name
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND %{User-Name}
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> milovan.kotlica
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: SQL-User-Name set to 'milovan.kotlica'
Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 75 seconds
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Socket destructor called, closing socket
Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 75 seconds
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): You probably need to lower "min"
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Socket destructor called, closing socket
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Reserved connection (1)
Sun Jul 26 18:20:16 2020 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name
Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'milovan.kotlica' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'milovan.kotlica' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User found in radcheck table
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Conditional check items matched, merging assignment check items
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Auth-Type := smsotp
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: Examining Auth-Type
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: APPENDING Auth-Type FROM 0 TO 0
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: TO in 0 out 0
Sun Jul 26 18:20:16 2020 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name
Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'milovan.kotlica' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'milovan.kotlica' ORDER BY id
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User found in radreply table, merging reply items
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Framed-IP-Address = 10.100.x.112
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: Examining Framed-IP-Address
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: APPENDING Framed-IP-Address FROM 0 TO 0
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: TO in 0 out 0
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ... falling-through to group processing
Sun Jul 26 18:20:16 2020 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name
Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY priority
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT groupname FROM radusergroup WHERE username = 'milovan.kotlica' ORDER BY priority
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'milovan.kotlica' ORDER BY priority
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User not found in any groups
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ... falling-through to profile processing
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Released connection (1)
Sun Jul 26 18:20:16 2020 : Info: Need 1 more connections to reach min connections (3)
Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Opening additional connection (8), 1 of 30 pending slots used
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.3.17-MariaDB, protocol version 10
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from sql (rlm_sql)
Sun Jul 26 18:20:16 2020 : Debug: (2) [sql] = ok
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling smsotp (rlm_smsotp)
Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp: Found reply to access challenge (AUTZ), Adding Auth-Type 'smsotp-reply'
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from smsotp (rlm_smsotp)
Sun Jul 26 18:20:16 2020 : Debug: (2) [smsotp] = ok
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling expiration (rlm_expiration)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from expiration (rlm_expiration)
Sun Jul 26 18:20:16 2020 : Debug: (2) [expiration] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling logintime (rlm_logintime)
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from logintime (rlm_logintime)
Sun Jul 26 18:20:16 2020 : Debug: (2) [logintime] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling pap (rlm_pap)
Sun Jul 26 18:20:16 2020 : WARNING: (2) pap: No "known good" password found for the user. Not setting Auth-Type
Sun Jul 26 18:20:16 2020 : WARNING: (2) pap: Authentication will fail unless a "known good" password is available
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from pap (rlm_pap)
Sun Jul 26 18:20:16 2020 : Debug: (2) [pap] = noop
Sun Jul 26 18:20:16 2020 : Debug: (2) } # authorize = ok
Sun Jul 26 18:20:16 2020 : Debug: (2) Found Auth-Type = smsotp-reply
Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default
Sun Jul 26 18:20:16 2020 : Debug: (2) Auth-Type smsotp-reply {
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authenticate]: calling smsotp (rlm_smsotp)
Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp (smsotp): Reserved connection (2)
Sun Jul 26 18:20:16 2020 : Debug: (2) smsotp: Found reply to access challenge
Sun Jul 26 18:20:16 2020 : Debug: (2) smsotp: answer is FAILED
Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp (smsotp): Released connection (2)
Sun Jul 26 18:20:16 2020 : Info: rlm_smsotp (smsotp): Closing connection (3), from 3 unused connections
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authenticate]: returned from smsotp (rlm_smsotp)
Sun Jul 26 18:20:16 2020 : Debug: (2) [smsotp] = fail
Sun Jul 26 18:20:16 2020 : Debug: (2) } # Auth-Type smsotp-reply = fail
Sun Jul 26 18:20:16 2020 : Debug: (2) Failed to authenticate the user
Sun Jul 26 18:20:16 2020 : Debug: (2) Using Post-Auth-Type Reject
Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default
Sun Jul 26 18:20:16 2020 : Debug: (2) Post-Auth-Type REJECT {
Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[post-auth]: calling sql (rlm_sql)
Sun Jul 26 18:20:16 2020 : Debug: .query
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> .query
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND .query
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> .query
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Using query template 'query'
Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Reserved connection (7)
Sun Jul 26 18:20:16 2020 : Debug: %{User-Name}
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: attribute --> User-Name
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND %{User-Name}
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> milovan.kotlica
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: SQL-User-Name set to 'milovan.kotlica'
Sun Jul 26 18:20:16 2020 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', 'xxxxxxx', '%{reply:Packet-Type}', '%S')
Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:16 2020 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '
Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name
Sun Jul 26 18:20:16 2020 : Debug: literal --> ', 'xxxxxxx', '
Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Type
Sun Jul 26 18:20:16 2020 : Debug: literal --> ', '
Sun Jul 26 18:20:16 2020 : Debug: percent --> S
Sun Jul 26 18:20:16 2020 : Debug: literal --> ')
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', 'xxxxxxx', '%{reply:Packet-Type}', '%S')
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'milovan.kotlica', 'xxxxxxx', 'Access-Reject', '2020-07-26 18:20:16')
Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'milovan.kotlica', 'xxxxxxx', 'Access-Reject', '2020-07-26 18:20:16')
Sun Jul 26 18:20:17 2020 : Debug: (2) sql: SQL query returned: success
Sun Jul 26 18:20:17 2020 : Debug: (2) sql: 1 record(s) updated
Sun Jul 26 18:20:17 2020 : Debug: rlm_sql (sql): Released connection (7)
Sun Jul 26 18:20:17 2020 : Info: Need 7 more connections to reach 10 spares
Sun Jul 26 18:20:17 2020 : Info: rlm_sql (sql): Opening additional connection (9), 1 of 29 pending slots used
Sun Jul 26 18:20:17 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Sun Jul 26 18:20:17 2020 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.3.17-MariaDB, protocol version 10
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from sql (rlm_sql)
Sun Jul 26 18:20:17 2020 : Debug: (2) [sql] = ok
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter)
Sun Jul 26 18:20:17 2020 : Debug: %{User-Name}
Sun Jul 26 18:20:17 2020 : Debug: Parsed xlat tree:
Sun Jul 26 18:20:17 2020 : Debug: attribute --> User-Name
Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: EXPAND %{User-Name}
Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: --> milovan.kotlica
Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: Matched entry DEFAULT at line 11
Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: Attribute "Framed-IP-Address" allowed by 0 rules, disallowed by 0 rules
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter)
Sun Jul 26 18:20:17 2020 : Debug: (2) [attr_filter.access_reject] = updated
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling eap (rlm_eap)
Sun Jul 26 18:20:17 2020 : Debug: (2) eap: Request didn't contain an EAP-Message, not inserting EAP-Failure
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from eap (rlm_eap)
Sun Jul 26 18:20:17 2020 : Debug: (2) [eap] = noop
Sun Jul 26 18:20:17 2020 : Debug: (2) policy remove_reply_message_if_eap {
Sun Jul 26 18:20:17 2020 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) {
Sun Jul 26 18:20:17 2020 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
Sun Jul 26 18:20:17 2020 : Debug: (2) else {
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling noop (rlm_always)
Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from noop (rlm_always)
Sun Jul 26 18:20:17 2020 : Debug: (2) [noop] = noop
Sun Jul 26 18:20:17 2020 : Debug: (2) } # else = noop
Sun Jul 26 18:20:17 2020 : Debug: (2) } # policy remove_reply_message_if_eap = noop
Sun Jul 26 18:20:17 2020 : Debug: (2) } # Post-Auth-Type REJECT = updated
Sun Jul 26 18:20:17 2020 : Debug: (2) Delaying response for 1.000000 seconds
Sun Jul 26 18:20:17 2020 : Debug: Waking up in 0.3 seconds.
Sun Jul 26 18:20:17 2020 : Debug: Waking up in 0.6 seconds.
Sun Jul 26 18:20:18 2020 : Debug: (2) Sending delayed response
Sun Jul 26 18:20:18 2020 : Debug: (2) Sent Access-Reject Id 201 from 10.100.x.60:1812 to 10.100.x.3:17138 length 20
Sun Jul 26 18:20:18 2020 : Debug: Waking up in 3.9 seconds.
Sun Jul 26 18:20:22 2020 : Debug: (2) Cleaning up request packet ID 201 with timestamp +98
Sun Jul 26 18:20:22 2020 : Info: Ready to process requests
More information about the Freeradius-Users
mailing list