Hi All. I have an issue on Chap Authentication Request. It seems that if CHAPChallenge size is longer than 48 bytes, Freeradius sends an Access Reject. I've the samde behavoiur on different client: - an xDSL router on an Alcatel7750 - NetRadPing - freeradius radclient I'm using Freeradius 3.0.16 Follow the logs: 1) xDSL router on an Alcatel7750 (0) Received Access-Request Id 200 from 10.255.254.120:64399 to 198.18.12.36:1812 length 222 (0) User-Name = "20M-GPON-HSI@ttp.it" (0) NAS-IP-Address = 10.255.254.120 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) CHAP-Password = 0x0192f8bb1b02e31b15615c5e292de11274 (0) CHAP-Challenge = 0x5c91a970986b4bcc2201b280daf0d9d7adc449b90d45c51ff69a8bb2ae08f68a99a0fb320d477faec83230a3a3897bd0cd458bda8ad07a01ea06339a (0) NAS-Identifier = "RMTB-E31" (0) NAS-Port-Type = Ethernet (0) Acct-Session-Id = "05FF7E0001884C5BA5199A" (0) NAS-Port = 1 (0) NAS-Port-Id = "ISAM-V-DSLAM-01 atm 1/1/02/01:8.35" (0) # Executing section authorize from file /etc/raddb/sites-enabled/default (0) authorize { (0) policy debug-rule { (0) update control { (0) EXPAND %{debug:5} (0) --> 2 (0) Tmp-String-9 = 2 (0) } # update control = noop (0) } # policy debug-rule = noop (0) policy filter_username { (0) if (&User-Name) { (0) if (&User-Name) -> TRUE (0) if (&User-Name) { (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@[^@]*@/ ) { (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (0) if (&User-Name =~ /\.\./ ) { (0) if (&User-Name =~ /\.\./ ) -> FALSE (0) if (&User-Name =~ /\.$/) { (0) if (&User-Name =~ /\.$/) -> FALSE (0) if (&User-Name =~ /@\./) { (0) if (&User-Name =~ /@\./) -> FALSE (0) } # if (&User-Name) = noop (0) } # policy filter_username = noop (0) modsingle[authorize]: calling preprocess (rlm_preprocess) (0) preprocess: EXPAND ^([^@]*)@((?i)noise.it) (0) preprocess: --> ^([^@]*)@((?i)noise.it) (0) preprocess: EXPAND ^([^@]*)@((?i)ttp.it) (0) preprocess: --> ^([^@]*)@((?i)ttp.it) (0) preprocess: hints: Matched DEFAULT at 9 (0) preprocess: ::: FROM 4 TO 12 MAX 16 (0) preprocess: ::: Examining Hint (0) preprocess: ::: APPENDING Hint FROM 0 TO 12 (0) preprocess: ::: Examining Stripped-User-Name (0) preprocess: 1/3 Found: 20M-GPON-HSI (13) (0) preprocess: EXPAND %{1} (0) preprocess: --> 20M-GPON-HSI (0) preprocess: ::: APPENDING Stripped-User-Name FROM 1 TO 12 (0) preprocess: ::: Examining Realm (0) preprocess: 2/3 Found: ttp.it (7) (0) preprocess: EXPAND %{2} (0) preprocess: --> ttp.it (0) preprocess: ::: APPENDING Realm FROM 2 TO 12 (0) preprocess: ::: Examining HPE-ISPVN-Id (0) preprocess: ::: APPENDING HPE-ISPVN-Id FROM 3 TO 12 (0) preprocess: ::: TO in 12 out 12 (0) preprocess: ::: to[0] = User-Name (0) preprocess: ::: to[1] = NAS-IP-Address (0) preprocess: ::: to[2] = Service-Type (0) preprocess: ::: to[3] = Framed-Protocol (0) preprocess: ::: to[4] = CHAP-Password (0) preprocess: ::: to[5] = CHAP-Challenge (0) preprocess: ::: to[6] = NAS-Identifier (0) preprocess: ::: to[7] = NAS-Port-Type (0) preprocess: ::: to[8] = Acct-Session-Id (0) preprocess: ::: to[9] = NAS-Port (0) preprocess: ::: to[10] = NAS-Port-Id (0) preprocess: ::: to[11] = Event-Timestamp (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) (0) [preprocess] = ok (0) policy nas-info { (0) update control { (0) Cache-Status-Only = yes (0) } # update control = noop (0) modsingle[authorize]: calling cache-nas (rlm_cache) (0) cache-nas: EXPAND %{NAS-IP-Address} (0) cache-nas: --> 10.255.254.120 (0) cache-nas: Mutex acquired (0) cache-nas: No cache entry found for "10.255.254.120" (0) cache-nas: Mutex released (0) modsingle[authorize]: returned from cache-nas (rlm_cache) (0) [cache-nas] = notfound (0) if (notfound) { (0) if (notfound) -> TRUE (0) if (notfound) { (0) update control { (0) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (0) --> 20M-GPON-HSI (0) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (0) (0) EXPAND /var/log/radius/sqllog.sql (0) --> /var/log/radius/sqllog.sql (0) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (0) Need 5 more connections to reach 10 spares rlm_sql (sql_primary_default): Opening additional connection (5), 1 of 27 pending slots used (0) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (0) --> X (0) Tmp-String-0 := X (0) } # update control = noop (0) if (&control:Tmp-String-0 != "") { (0) if (&control:Tmp-String-0 != "") -> TRUE (0) if (&control:Tmp-String-0 != "") { (0) update control { (0) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (0) --> 20M-GPON-HSI (0) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (1) (0) EXPAND /var/log/radius/sqllog.sql (0) --> /var/log/radius/sqllog.sql (0) Executing select query: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '10.255.254.120' rlm_sql (sql_primary_default): Released connection (1) (0) EXPAND %{sql_primary_default:SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '%{NAS-IP-Address}'} (0) --> 6527~~ (0) Tmp-String-1 := 6527~~ (0) } # update control = noop (0) } # if (&control:Tmp-String-0 != "") = noop (0) ... skipping else: Preceding "if" was taken (0) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) { (0) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) -> TRUE (0) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) { (0) if ("%{1}" == '' || "%{3}" == '') { (0) EXPAND TMPL XLAT STRUCT (0) 1/4 Found: 6527 (5) (0) EXPAND %{1} (0) --> 6527 (0) EXPAND TMPL XLAT STRUCT (0) 3/4 Found: (1) (0) EXPAND %{3} (0) --> (0) if ("%{1}" == '' || "%{3}" == '') -> TRUE (0) if ("%{1}" == '' || "%{3}" == '') { (0) if ("%{1}" == '') { (0) EXPAND TMPL XLAT STRUCT (0) 1/4 Found: 6527 (5) (0) EXPAND %{1} (0) --> 6527 (0) if ("%{1}" == '') -> FALSE (0) else { (0) update control { (0) 1/4 Found: 6527 (5) (0) EXPAND %{1} (0) --> 6527 (0) Tmp-Integer-2 := 6527 (0) 2/4 Found: (1) (0) EXPAND %{2} (0) --> (0) Tmp-String-2 := (0) Tmp-Integer-3 := 0 (0) } # update control = noop (0) } # else = noop (0) } # if ("%{1}" == '' || "%{3}" == '') = noop (0) ... skipping else: Preceding "if" was taken (0) } # if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) = noop (0) ... skipping else: Preceding "if" was taken (0) } # if (notfound) = noop (0) modsingle[authorize]: calling cache-nas (rlm_cache) (0) cache-nas: EXPAND %{NAS-IP-Address} (0) cache-nas: --> 10.255.254.120 (0) cache-nas: Mutex acquired (0) cache-nas: No cache entry found for "10.255.254.120" (0) cache-nas: Creating new cache entry (0) cache-nas: &control:HPE-NAS-VendorId := &control:Tmp-Integer-2 -> 6527 (0) cache-nas: &control:HPE-NAS-DNS-Zone := &control:Tmp-String-2 -> '' (0) cache-nas: &control:HPE-NAS-VendorCodingId := &control:Tmp-Integer-3 -> 0 (0) cache-nas: Merging cache entry into request (0) cache-nas: &control:HPE-NAS-VendorId := 6527 (0) cache-nas: &control:HPE-NAS-DNS-Zone := "" (0) cache-nas: &control:HPE-NAS-VendorCodingId := 0 (0) cache-nas: ::: FROM 3 TO 6 MAX 9 (0) cache-nas: ::: Examining HPE-NAS-VendorId (0) cache-nas: ::: APPENDING HPE-NAS-VendorId FROM 0 TO 6 (0) cache-nas: ::: Examining HPE-NAS-DNS-Zone (0) cache-nas: ::: APPENDING HPE-NAS-DNS-Zone FROM 1 TO 6 (0) cache-nas: ::: Examining HPE-NAS-VendorCodingId (0) cache-nas: ::: APPENDING HPE-NAS-VendorCodingId FROM 2 TO 6 (0) cache-nas: ::: TO in 6 out 6 (0) cache-nas: ::: to[0] = Tmp-String-9 (0) cache-nas: ::: to[1] = Tmp-String-0 (0) cache-nas: ::: to[2] = Tmp-String-1 (0) cache-nas: ::: to[3] = Tmp-Integer-2 (0) cache-nas: ::: to[4] = Tmp-String-2 (0) cache-nas: ::: to[5] = Tmp-Integer-3 (0) cache-nas: Committed entry, TTL 60 seconds (0) cache-nas: Mutex released (0) modsingle[authorize]: returned from cache-nas (rlm_cache) (0) [cache-nas] = updated (0) } # policy nas-info = updated (0) policy auth-by-callingId { (0) if (&Calling-Station-ID){ (0) if (&Calling-Station-ID) -> FALSE (0) else { (0) update control { (0) HPE-Auth-By-CliId := No (0) } # update control = noop (0) } # else = noop (0) } # policy auth-by-callingId = noop (0) if (&control:HPE-Auth-By-CliId == "Yes") { (0) if (&control:HPE-Auth-By-CliId == "Yes") -> FALSE (0) else { (0) if (&request:Hint == "ROAM") { (0) if (&request:Hint == "ROAM") -> FALSE (0) elsif (&request:Hint == "VPDN") { (0) elsif (&request:Hint == "VPDN") -> FALSE (0) else { (0) if (&request:HPE-ISPVN-Id == 1000912) { (0) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (0) else { (0) redundant redundant_sql_default { (0) modsingle[authorize]: calling sql_primary_default (rlm_sql) (0) sql_primary_default: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (0) sql_primary_default: --> 20M-GPON-HSI (0) sql_primary_default: SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (2) (0) sql_primary_default: EXPAND SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (0) sql_primary_default: --> SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (0) sql_primary_default: Executing select query: SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (0) sql_primary_default: User found in radcheck table (0) sql_primary_default: Conditional check items matched, merging assignment check items (0) sql_primary_default: Cleartext-Password := "test" (0) sql_primary_default: ::: FROM 1 TO 10 MAX 11 (0) sql_primary_default: ::: Examining Cleartext-Password (0) sql_primary_default: ::: APPENDING Cleartext-Password FROM 0 TO 10 (0) sql_primary_default: ::: TO in 10 out 10 (0) sql_primary_default: ::: to[0] = Tmp-String-9 (0) sql_primary_default: ::: to[1] = Tmp-String-0 (0) sql_primary_default: ::: to[2] = Tmp-String-1 (0) sql_primary_default: ::: to[3] = Tmp-Integer-2 (0) sql_primary_default: ::: to[4] = Tmp-String-2 (0) sql_primary_default: ::: to[5] = Tmp-Integer-3 (0) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (0) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (0) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (0) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (0) sql_primary_default: EXPAND SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (0) sql_primary_default: --> SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,6527) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (0) sql_primary_default: Executing select query: SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,6527) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (0) sql_primary_default: ... falling-through to group processing (0) sql_primary_default: EXPAND SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY priority (0) sql_primary_default: --> SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (0) sql_primary_default: Executing select query: SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (0) sql_primary_default: User found in the group table (0) sql_primary_default: EXPAND SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (0) sql_primary_default: --> SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (0) sql_primary_default: Executing select query: SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (0) sql_primary_default: Group "RAC x 20M-GPON-HSI": Conditional check items matched (0) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging assignment check items (0) sql_primary_default: ::: FROM 0 TO 11 MAX 11 (0) sql_primary_default: ::: TO in 11 out 11 (0) sql_primary_default: ::: to[0] = Tmp-String-9 (0) sql_primary_default: ::: to[1] = Tmp-String-0 (0) sql_primary_default: ::: to[2] = Tmp-String-1 (0) sql_primary_default: ::: to[3] = Tmp-Integer-2 (0) sql_primary_default: ::: to[4] = Tmp-String-2 (0) sql_primary_default: ::: to[5] = Tmp-Integer-3 (0) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (0) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (0) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (0) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (0) sql_primary_default: ::: to[10] = Cleartext-Password (0) sql_primary_default: EXPAND SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (0) sql_primary_default: --> SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,6527) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (0) sql_primary_default: Executing select query: SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,6527) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (0) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging reply items (0) sql_primary_default: Acct-Interim-Interval = 21600 (0) sql_primary_default: Alc-Primary-Dns = 193.70.152.15 (0) sql_primary_default: Alc-Secondary-Dns = 212.52.97.15 (0) sql_primary_default: Alc-SLA-Prof-Str = "20M-GPON-HSI" (0) sql_primary_default: Alc-Subsc-Prof-Str = "sub-Gpon" (0) sql_primary_default: ::: FROM 5 TO 0 MAX 5 (0) sql_primary_default: ::: Examining Acct-Interim-Interval (0) sql_primary_default: ::: APPENDING Acct-Interim-Interval FROM 0 TO 0 (0) sql_primary_default: ::: Examining Alc-Primary-Dns (0) sql_primary_default: ::: APPENDING Alc-Primary-Dns FROM 1 TO 0 (0) sql_primary_default: ::: Examining Alc-Secondary-Dns (0) sql_primary_default: ::: APPENDING Alc-Secondary-Dns FROM 2 TO 0 (0) sql_primary_default: ::: Examining Alc-SLA-Prof-Str (0) sql_primary_default: ::: APPENDING Alc-SLA-Prof-Str FROM 3 TO 0 (0) sql_primary_default: ::: Examining Alc-Subsc-Prof-Str (0) sql_primary_default: ::: APPENDING Alc-Subsc-Prof-Str FROM 4 TO 0 (0) sql_primary_default: ::: TO in 0 out 0 (0) sql_primary_default: ... falling-through to profile processing rlm_sql (sql_primary_default): Released connection (2) (0) modsingle[authorize]: returned from sql_primary_default (rlm_sql) (0) [sql_primary_default] = ok (0) } # redundant redundant_sql_default = ok (0) policy check-block { (0) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") { (0) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") -> FALSE (0) } # policy check-block = ok (0) } # else = ok (0) } # else = ok (0) } # else = ok (0) modsingle[authorize]: calling chap (rlm_chap) (0) chap: &control:Auth-Type := CHAP (0) modsingle[authorize]: returned from chap (rlm_chap) (0) [chap] = ok (0) modsingle[authorize]: calling expiration (rlm_expiration) (0) modsingle[authorize]: returned from expiration (rlm_expiration) (0) [expiration] = noop (0) modsingle[authorize]: calling logintime (rlm_logintime) (0) modsingle[authorize]: returned from logintime (rlm_logintime) (0) [logintime] = noop (0) modsingle[authorize]: calling pap (rlm_pap) (0) pap: WARNING: Auth-Type already set. Not setting to PAP (0) modsingle[authorize]: returned from pap (rlm_pap) (0) [pap] = noop (0) } # authorize = updated (0) Found Auth-Type = CHAP (0) # Executing group from file /etc/raddb/sites-enabled/default (0) Auth-Type CHAP { (0) modsingle[authenticate]: calling chap (rlm_chap) (0) chap: Comparing with "known good" &control:Cleartext-Password value "test" (0) chap: Using challenge from &request:CHAP-Challenge (0) chap: CHAP challenge : 5c91a970986b4bcc2201b280daf0d9d7adc449b90d45c51ff69a8bb2ae08f68a99a0fb320d477faec83230a3a3897bd0cd458bda8ad07a01ea06339a (0) chap: Client sent : 92f8bb1b02e31b15615c5e292de11274 (0) chap: We calculated : 36396138626232616530386636386139 (0) chap: ERROR: Password comparison failed: password is incorrect (0) modsingle[authenticate]: returned from chap (rlm_chap) (0) [chap] = reject (0) } # Auth-Type CHAP = reject (0) Failed to authenticate the user (0) Using Post-Auth-Type Reject (0) # Executing group from file /etc/raddb/sites-enabled/default (0) Post-Auth-Type REJECT { (0) policy insert_hpe_reply_message { (0) update control { (0) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (0) --> 20M-GPON-HSI (0) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (3) (0) EXPAND /var/log/radius/sqllog.sql (0) --> /var/log/radius/sqllog.sql (0) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (3) (0) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (0) --> X (0) Tmp-String-0 := X (0) Overwriting value "X" with "X" (0) } # update control = noop (0) if (&request:Hint == "Access") { (0) if (&request:Hint == "Access") -> TRUE (0) if (&request:Hint == "Access") { (0) if (&control:Tmp-String-0 != "") { (0) if (&control:Tmp-String-0 != "") -> TRUE (0) if (&control:Tmp-String-0 != "") { (0) update reply { (0) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (0) --> 20M-GPON-HSI (0) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (4) (0) EXPAND /var/log/radius/sqllog.sql (0) --> /var/log/radius/sqllog.sql (0) Executing select query: SELECT create_message_reply('Access',1059241,'20M-GPON-HSI','','No','test','chap: Password comparison failed: password is incorrect') FROM DUAL rlm_sql (sql_primary_default): Released connection (4) (0) EXPAND %{sql_primary_default:SELECT create_message_reply('%{Hint}',%{HPE-ISPVN-Id},'%{%{Stripped-User-Name}:-%{User-Name}}','%{Calling-Station-ID}','%{&control:HPE-Auth-By-CliId}','%{%{&control:Cleartext-Password}:-''}','%{Module-Failure-Message}') FROM DUAL} (0) --> A_1059241_72924453_1058360_test_2 (0) &Reply-Message = A_1059241_72924453_1058360_test_2 (0) } # update reply = noop (0) } # if (&control:Tmp-String-0 != "") = noop (0) ... skipping else: Preceding "if" was taken (0) } # if (&request:Hint == "Access") = noop (0) ... skipping elsif: Preceding "if" was taken (0) ... skipping elsif: Preceding "if" was taken (0) } # policy insert_hpe_reply_message = noop (0) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) (0) attr_filter.access_reject: EXPAND %{User-Name} (0) attr_filter.access_reject: --> 20M-GPON-HSI@ttp.it (0) attr_filter.access_reject: Matched entry DEFAULT at line 11 (0) attr_filter.access_reject: Attribute "Acct-Interim-Interval" allowed by 0 rules, disallowed by 0 rules (0) attr_filter.access_reject: Attribute "Alc-Primary-Dns" allowed by 0 rules, disallowed by 0 rules (0) attr_filter.access_reject: Attribute "Alc-Secondary-Dns" allowed by 0 rules, disallowed by 0 rules (0) attr_filter.access_reject: Attribute "Alc-SLA-Prof-Str" allowed by 0 rules, disallowed by 0 rules (0) attr_filter.access_reject: Attribute "Alc-Subsc-Prof-Str" allowed by 0 rules, disallowed by 0 rules (0) attr_filter.access_reject: Reply-Message = "A_1059241_72924453_1058360_test_2" allowed by Reply-Message =* "" (0) attr_filter.access_reject: Attribute "Reply-Message" allowed by 1 rules, disallowed by 0 rules (0) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) (0) [attr_filter.access_reject] = updated (0) } # Post-Auth-Type REJECT = updated (0) Delaying response for 1.000000 seconds Waking up in 0.2 seconds. Waking up in 0.7 seconds. (0) Sending delayed response (0) Sent Access-Reject Id 200 from 198.18.12.36:1812 to 10.255.254.120:64399 length 55 (0) Reply-Message = "A_1059241_72924453_1058360_test_2" Waking up in 3.9 seconds. ================================================================================ 2) freeradius radclient - Without CHAP-Challenge echo "User-Name=20M-GPON-HSI@ttp.it,CHAP-Password=test " | radclient localhost:1812 auth InternalSecret Sent Access-Request Id 254 from 0.0.0.0:52073 to 127.0.0.1:1812 length 60 Received Access-Accept Id 254 from 127.0.0.1:1812 to 0.0.0.0:0 length 91 (4) Received Access-Request Id 254 from 127.0.0.1:52073 to 127.0.0.1:1812 length 60 (4) User-Name = "20M-GPON-HSI@ttp.it" (4) CHAP-Password = 0x569a8ea3bd2e4cb534e96d7b70d83cf014 (4) # Executing section authorize from file /etc/raddb/sites-enabled/default (4) authorize { (4) policy debug-rule { (4) update control { (4) EXPAND %{debug:5} (4) --> 2 (4) Tmp-String-9 = 2 (4) } # update control = noop (4) } # policy debug-rule = noop (4) policy filter_username { (4) if (&User-Name) { (4) if (&User-Name) -> TRUE (4) if (&User-Name) { (4) if (&User-Name =~ / /) { (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@[^@]*@/ ) { (4) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (4) if (&User-Name =~ /\.\./ ) { (4) if (&User-Name =~ /\.\./ ) -> FALSE (4) if (&User-Name =~ /\.$/) { (4) if (&User-Name =~ /\.$/) -> FALSE (4) if (&User-Name =~ /@\./) { (4) if (&User-Name =~ /@\./) -> FALSE (4) } # if (&User-Name) = noop (4) } # policy filter_username = noop (4) modsingle[authorize]: calling preprocess (rlm_preprocess) (4) preprocess: hints: Matched DEFAULT at 9 (4) preprocess: ::: FROM 4 TO 4 MAX 8 (4) preprocess: ::: Examining Hint (4) preprocess: ::: APPENDING Hint FROM 0 TO 4 (4) preprocess: ::: Examining Stripped-User-Name (4) preprocess: 1/3 Found: 20M-GPON-HSI (13) (4) preprocess: EXPAND %{1} (4) preprocess: --> 20M-GPON-HSI (4) preprocess: ::: APPENDING Stripped-User-Name FROM 1 TO 4 (4) preprocess: ::: Examining Realm (4) preprocess: 2/3 Found: ttp.it (7) (4) preprocess: EXPAND %{2} (4) preprocess: --> ttp.it (4) preprocess: ::: APPENDING Realm FROM 2 TO 4 (4) preprocess: ::: Examining HPE-ISPVN-Id (4) preprocess: ::: APPENDING HPE-ISPVN-Id FROM 3 TO 4 (4) preprocess: ::: TO in 4 out 4 (4) preprocess: ::: to[0] = User-Name (4) preprocess: ::: to[1] = CHAP-Password (4) preprocess: ::: to[2] = Event-Timestamp (4) preprocess: ::: to[3] = NAS-IP-Address (4) modsingle[authorize]: returned from preprocess (rlm_preprocess) (4) [preprocess] = ok (4) policy nas-info { (4) update control { (4) Cache-Status-Only = yes (4) } # update control = noop (4) modsingle[authorize]: calling cache-nas (rlm_cache) (4) cache-nas: EXPAND %{NAS-IP-Address} (4) cache-nas: --> 127.0.0.1 (4) cache-nas: Mutex acquired (4) cache-nas: No cache entry found for "127.0.0.1" (4) cache-nas: Mutex released (4) modsingle[authorize]: returned from cache-nas (rlm_cache) (4) [cache-nas] = notfound (4) if (notfound) { (4) if (notfound) -> TRUE (4) if (notfound) { (4) update control { (4) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (4) --> 20M-GPON-HSI (4) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (1) (4) EXPAND /var/log/radius/sqllog.sql (4) --> /var/log/radius/sqllog.sql (4) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (1) Need 4 more connections to reach 10 spares rlm_sql (sql_primary_default): Opening additional connection (9), 1 of 26 pending slots used (4) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (4) --> X (4) Tmp-String-0 := X (4) } # update control = noop (4) if (&control:Tmp-String-0 != "") { (4) if (&control:Tmp-String-0 != "") -> TRUE (4) if (&control:Tmp-String-0 != "") { (4) update control { (4) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (4) --> 20M-GPON-HSI (4) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (0) (4) EXPAND /var/log/radius/sqllog.sql (4) --> /var/log/radius/sqllog.sql (4) Executing select query: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '127.0.0.1' (4) SQL query returned no results rlm_sql (sql_primary_default): Released connection (0) (4) EXPAND %{sql_primary_default:SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '%{NAS-IP-Address}'} (4) --> (4) Tmp-String-1 := (4) } # update control = noop (4) } # if (&control:Tmp-String-0 != "") = noop (4) ... skipping else: Preceding "if" was taken (4) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) { (4) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) -> FALSE (4) else { (4) update control { (4) Tmp-Integer-2 := 0 (4) Tmp-String-2 := '' (4) Tmp-Integer-3 := 0 (4) } # update control = noop (4) } # else = noop (4) } # if (notfound) = noop (4) modsingle[authorize]: calling cache-nas (rlm_cache) (4) cache-nas: EXPAND %{NAS-IP-Address} (4) cache-nas: --> 127.0.0.1 (4) cache-nas: Mutex acquired (4) cache-nas: No cache entry found for "127.0.0.1" (4) cache-nas: Creating new cache entry (4) cache-nas: &control:HPE-NAS-VendorId := &control:Tmp-Integer-2 -> 0 (4) cache-nas: &control:HPE-NAS-DNS-Zone := &control:Tmp-String-2 -> '' (4) cache-nas: &control:HPE-NAS-VendorCodingId := &control:Tmp-Integer-3 -> 0 (4) cache-nas: Merging cache entry into request (4) cache-nas: &control:HPE-NAS-VendorId := 0 (4) cache-nas: &control:HPE-NAS-DNS-Zone := "" (4) cache-nas: &control:HPE-NAS-VendorCodingId := 0 (4) cache-nas: ::: FROM 3 TO 6 MAX 9 (4) cache-nas: ::: Examining HPE-NAS-VendorId (4) cache-nas: ::: APPENDING HPE-NAS-VendorId FROM 0 TO 6 (4) cache-nas: ::: Examining HPE-NAS-DNS-Zone (4) cache-nas: ::: APPENDING HPE-NAS-DNS-Zone FROM 1 TO 6 (4) cache-nas: ::: Examining HPE-NAS-VendorCodingId (4) cache-nas: ::: APPENDING HPE-NAS-VendorCodingId FROM 2 TO 6 (4) cache-nas: ::: TO in 6 out 6 (4) cache-nas: ::: to[0] = Tmp-String-9 (4) cache-nas: ::: to[1] = Tmp-String-0 (4) cache-nas: ::: to[2] = Tmp-String-1 (4) cache-nas: ::: to[3] = Tmp-Integer-2 (4) cache-nas: ::: to[4] = Tmp-String-2 (4) cache-nas: ::: to[5] = Tmp-Integer-3 (4) cache-nas: Committed entry, TTL 60 seconds (4) cache-nas: Mutex released (4) modsingle[authorize]: returned from cache-nas (rlm_cache) (4) [cache-nas] = updated (4) } # policy nas-info = updated (4) policy auth-by-callingId { (4) if (&Calling-Station-ID){ (4) if (&Calling-Station-ID) -> FALSE (4) else { (4) update control { (4) HPE-Auth-By-CliId := No (4) } # update control = noop (4) } # else = noop (4) } # policy auth-by-callingId = noop (4) if (&control:HPE-Auth-By-CliId == "Yes") { (4) if (&control:HPE-Auth-By-CliId == "Yes") -> FALSE (4) else { (4) if (&request:Hint == "ROAM") { (4) if (&request:Hint == "ROAM") -> FALSE (4) elsif (&request:Hint == "VPDN") { (4) elsif (&request:Hint == "VPDN") -> FALSE (4) else { (4) if (&request:HPE-ISPVN-Id == 1000912) { (4) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (4) else { (4) redundant redundant_sql_default { (4) modsingle[authorize]: calling sql_primary_default (rlm_sql) (4) sql_primary_default: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (4) sql_primary_default: --> 20M-GPON-HSI (4) sql_primary_default: SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (7) (4) sql_primary_default: EXPAND SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (4) sql_primary_default: --> SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (4) sql_primary_default: Executing select query: SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (4) sql_primary_default: User found in radcheck table (4) sql_primary_default: Conditional check items matched, merging assignment check items (4) sql_primary_default: Cleartext-Password := "test" (4) sql_primary_default: ::: FROM 1 TO 10 MAX 11 (4) sql_primary_default: ::: Examining Cleartext-Password (4) sql_primary_default: ::: APPENDING Cleartext-Password FROM 0 TO 10 (4) sql_primary_default: ::: TO in 10 out 10 (4) sql_primary_default: ::: to[0] = Tmp-String-9 (4) sql_primary_default: ::: to[1] = Tmp-String-0 (4) sql_primary_default: ::: to[2] = Tmp-String-1 (4) sql_primary_default: ::: to[3] = Tmp-Integer-2 (4) sql_primary_default: ::: to[4] = Tmp-String-2 (4) sql_primary_default: ::: to[5] = Tmp-Integer-3 (4) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (4) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (4) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (4) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (4) sql_primary_default: EXPAND SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (4) sql_primary_default: --> SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (4) sql_primary_default: Executing select query: SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (4) sql_primary_default: ... falling-through to group processing (4) sql_primary_default: EXPAND SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY priority (4) sql_primary_default: --> SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (4) sql_primary_default: Executing select query: SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (4) sql_primary_default: User found in the group table (4) sql_primary_default: EXPAND SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (4) sql_primary_default: --> SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (4) sql_primary_default: Executing select query: SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (4) sql_primary_default: Group "RAC x 20M-GPON-HSI": Conditional check items matched (4) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging assignment check items (4) sql_primary_default: ::: FROM 0 TO 11 MAX 11 (4) sql_primary_default: ::: TO in 11 out 11 (4) sql_primary_default: ::: to[0] = Tmp-String-9 (4) sql_primary_default: ::: to[1] = Tmp-String-0 (4) sql_primary_default: ::: to[2] = Tmp-String-1 (4) sql_primary_default: ::: to[3] = Tmp-Integer-2 (4) sql_primary_default: ::: to[4] = Tmp-String-2 (4) sql_primary_default: ::: to[5] = Tmp-Integer-3 (4) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (4) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (4) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (4) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (4) sql_primary_default: ::: to[10] = Cleartext-Password (4) sql_primary_default: EXPAND SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (4) sql_primary_default: --> SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (4) sql_primary_default: Executing select query: SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (4) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging reply items (4) sql_primary_default: Acct-Interim-Interval = 21600 (4) sql_primary_default: ::: FROM 1 TO 0 MAX 1 (4) sql_primary_default: ::: Examining Acct-Interim-Interval (4) sql_primary_default: ::: APPENDING Acct-Interim-Interval FROM 0 TO 0 (4) sql_primary_default: ::: TO in 0 out 0 (4) sql_primary_default: ... falling-through to profile processing rlm_sql (sql_primary_default): Released connection (7) (4) modsingle[authorize]: returned from sql_primary_default (rlm_sql) (4) [sql_primary_default] = ok (4) } # redundant redundant_sql_default = ok (4) policy check-block { (4) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") { (4) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") -> FALSE (4) } # policy check-block = ok (4) } # else = ok (4) } # else = ok (4) } # else = ok (4) modsingle[authorize]: calling chap (rlm_chap) (4) chap: &control:Auth-Type := CHAP (4) modsingle[authorize]: returned from chap (rlm_chap) (4) [chap] = ok (4) modsingle[authorize]: calling expiration (rlm_expiration) (4) modsingle[authorize]: returned from expiration (rlm_expiration) (4) [expiration] = noop (4) modsingle[authorize]: calling logintime (rlm_logintime) (4) modsingle[authorize]: returned from logintime (rlm_logintime) (4) [logintime] = noop (4) modsingle[authorize]: calling pap (rlm_pap) (4) pap: WARNING: Auth-Type already set. Not setting to PAP (4) modsingle[authorize]: returned from pap (rlm_pap) (4) [pap] = noop (4) } # authorize = updated (4) Found Auth-Type = CHAP (4) # Executing group from file /etc/raddb/sites-enabled/default (4) Auth-Type CHAP { (4) modsingle[authenticate]: calling chap (rlm_chap) (4) chap: Comparing with "known good" &control:Cleartext-Password value "test" (4) chap: Using challenge from &request:CHAP-Challenge (4) chap: CHAP challenge : ab92e95e73021e400f73f42fbe26221a (4) chap: Client sent : 9a8ea3bd2e4cb534e96d7b70d83cf014 (4) chap: We calculated : 9a8ea3bd2e4cb534e96d7b70d83cf014 (4) chap: CHAP user "20M-GPON-HSI" authenticated successfully (4) modsingle[authenticate]: returned from chap (rlm_chap) (4) [chap] = ok (4) } # Auth-Type CHAP = ok (4) # Executing section post-auth from file /etc/raddb/sites-enabled/default (4) post-auth { (4) policy debug-rule { (4) update control { (4) EXPAND %{debug:5} (4) --> 4 (4) Tmp-String-9 = 4 (4) Refusing to overwrite (use :=) (4) } # update control = noop (4) } # policy debug-rule = noop (4) if (&request:HPE-ISPVN-Id == 1000912) { (4) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (4) elsif (&request:HPE-ISPVN-Id == 1003334) { (4) elsif (&request:HPE-ISPVN-Id == 1003334) -> FALSE (4) policy insert_hpe_acct_class { (4) update control { (4) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (4) --> 20M-GPON-HSI (4) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (8) (4) EXPAND /var/log/radius/sqllog.sql (4) --> /var/log/radius/sqllog.sql (4) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (8) (4) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (4) --> X (4) Tmp-String-0 := X (4) Overwriting value "X" with "X" (4) } # update control = noop (4) if (&request:Hint == "Access") { (4) if (&request:Hint == "Access") -> TRUE (4) if (&request:Hint == "Access") { (4) if (&control:Tmp-String-0 != "") { (4) if (&control:Tmp-String-0 != "") -> TRUE (4) if (&control:Tmp-String-0 != "") { (4) update reply { (4) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (4) --> 20M-GPON-HSI (4) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (6) (4) EXPAND /var/log/radius/sqllog.sql (4) --> /var/log/radius/sqllog.sql (4) Executing select query: SELECT create_class_attr('Access',1059241,'20M-GPON-HSI','','No','127.0.0.1','','') FROM DUAL rlm_sql (sql_primary_default): Released connection (6) (4) EXPAND %{sql_primary_default:SELECT create_class_attr('%{Hint}',%{HPE-ISPVN-Id},'%{%{Stripped-User-Name}:-%{User-Name}}','%{Calling-Station-ID}','%{&control:HPE-Auth-By-CliId}','%{NAS-IP-Address}','%{HPE-NAS-Desc}','%{HPE-Logon-Time}') FROM DUAL}_AAA: (4) --> A__NA=UNKNOWN_1059241_72924453_1058360_5_2_Y_Y_1753043_0_0_AAA: (4) &Class = 0x415f5f4e413d554e4b4e4f574e5f313035393234315f37323932343435335f313035383336305f355f325f595f595f313735333034335f305f305f4141413a (4) } # update reply = noop (4) } # if (&control:Tmp-String-0 != "") = noop (4) ... skipping else: Preceding "if" was taken (4) } # if (&request:Hint == "Access") = noop (4) ... skipping elsif: Preceding "if" was taken (4) } # policy insert_hpe_acct_class = noop (4) } # post-auth = noop (4) Sent Access-Accept Id 254 from 127.0.0.1:1812 to 127.0.0.1:52073 length 0 (4) Acct-Interim-Interval = 21600 (4) Class = 0x415f5f4e413d554e4b4e4f574e5f313035393234315f37323932343435335f313035383336305f355f325f595f595f313735333034335f305f305f4141413a (4) Finished request ================================================================================ 3) freeradius radclient - CHAP-Challenge under 48 bytes echo "User-Name=20M-GPON-HSI@ttp.it,CHAP-Password=test,CHAP-Challenge=123456789012345678901234 " | radclient localhost:1812 auth InternalSecret Sent Access-Request Id 84 from 0.0.0.0:42359 to 127.0.0.1:1812 length 86 Received Access-Accept Id 84 from 127.0.0.1:1812 to 0.0.0.0:0 length 91 (11) Received Access-Request Id 84 from 127.0.0.1:42359 to 127.0.0.1:1812 length 86 (11) User-Name = "20M-GPON-HSI@ttp.it" (11) CHAP-Password = 0xc235ace44d9d6c7deacb03c98def21059a (11) CHAP-Challenge = 0x313233343536373839303132333435363738393031323334 (11) # Executing section authorize from file /etc/raddb/sites-enabled/default (11) authorize { (11) policy debug-rule { (11) update control { (11) EXPAND %{debug:5} (11) --> 2 (11) Tmp-String-9 = 2 (11) } # update control = noop (11) } # policy debug-rule = noop (11) policy filter_username { (11) if (&User-Name) { (11) if (&User-Name) -> TRUE (11) if (&User-Name) { (11) if (&User-Name =~ / /) { (11) if (&User-Name =~ / /) -> FALSE (11) if (&User-Name =~ /@[^@]*@/ ) { (11) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (11) if (&User-Name =~ /\.\./ ) { (11) if (&User-Name =~ /\.\./ ) -> FALSE (11) if (&User-Name =~ /\.$/) { (11) if (&User-Name =~ /\.$/) -> FALSE (11) if (&User-Name =~ /@\./) { (11) if (&User-Name =~ /@\./) -> FALSE (11) } # if (&User-Name) = noop (11) } # policy filter_username = noop (11) modsingle[authorize]: calling preprocess (rlm_preprocess) (11) preprocess: hints: Matched DEFAULT at 9 (11) preprocess: ::: FROM 4 TO 5 MAX 9 (11) preprocess: ::: Examining Hint (11) preprocess: ::: APPENDING Hint FROM 0 TO 5 (11) preprocess: ::: Examining Stripped-User-Name (11) preprocess: 1/3 Found: 20M-GPON-HSI (13) (11) preprocess: EXPAND %{1} (11) preprocess: --> 20M-GPON-HSI (11) preprocess: ::: APPENDING Stripped-User-Name FROM 1 TO 5 (11) preprocess: ::: Examining Realm (11) preprocess: 2/3 Found: ttp.it (7) (11) preprocess: EXPAND %{2} (11) preprocess: --> ttp.it (11) preprocess: ::: APPENDING Realm FROM 2 TO 5 (11) preprocess: ::: Examining HPE-ISPVN-Id (11) preprocess: ::: APPENDING HPE-ISPVN-Id FROM 3 TO 5 (11) preprocess: ::: TO in 5 out 5 (11) preprocess: ::: to[0] = User-Name (11) preprocess: ::: to[1] = CHAP-Password (11) preprocess: ::: to[2] = CHAP-Challenge (11) preprocess: ::: to[3] = Event-Timestamp (11) preprocess: ::: to[4] = NAS-IP-Address (11) modsingle[authorize]: returned from preprocess (rlm_preprocess) (11) [preprocess] = ok (11) policy nas-info { (11) update control { (11) Cache-Status-Only = yes (11) } # update control = noop (11) modsingle[authorize]: calling cache-nas (rlm_cache) (11) cache-nas: EXPAND %{NAS-IP-Address} (11) cache-nas: --> 127.0.0.1 (11) cache-nas: Mutex acquired (11) cache-nas: No cache entry found for "127.0.0.1" (11) cache-nas: Mutex released (11) modsingle[authorize]: returned from cache-nas (rlm_cache) (11) [cache-nas] = notfound (11) if (notfound) { (11) if (notfound) -> TRUE (11) if (notfound) { (11) update control { (11) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (11) --> 20M-GPON-HSI (11) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (6) (11) EXPAND /var/log/radius/sqllog.sql (11) --> /var/log/radius/sqllog.sql (11) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (6) Need 4 more connections to reach 10 spares rlm_sql (sql_primary_default): Opening additional connection (16), 1 of 26 pending slots used (11) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (11) --> X (11) Tmp-String-0 := X (11) } # update control = noop (11) if (&control:Tmp-String-0 != "") { (11) if (&control:Tmp-String-0 != "") -> TRUE (11) if (&control:Tmp-String-0 != "") { (11) update control { (11) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (11) --> 20M-GPON-HSI (11) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (12) (11) EXPAND /var/log/radius/sqllog.sql (11) --> /var/log/radius/sqllog.sql (11) Executing select query: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '127.0.0.1' (11) SQL query returned no results rlm_sql (sql_primary_default): Released connection (12) (11) EXPAND %{sql_primary_default:SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '%{NAS-IP-Address}'} (11) --> (11) Tmp-String-1 := (11) } # update control = noop (11) } # if (&control:Tmp-String-0 != "") = noop (11) ... skipping else: Preceding "if" was taken (11) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) { (11) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) -> FALSE (11) else { (11) update control { (11) Tmp-Integer-2 := 0 (11) Tmp-String-2 := '' (11) Tmp-Integer-3 := 0 (11) } # update control = noop (11) } # else = noop (11) } # if (notfound) = noop (11) modsingle[authorize]: calling cache-nas (rlm_cache) (11) cache-nas: EXPAND %{NAS-IP-Address} (11) cache-nas: --> 127.0.0.1 (11) cache-nas: Mutex acquired (11) cache-nas: No cache entry found for "127.0.0.1" (11) cache-nas: Creating new cache entry (11) cache-nas: &control:HPE-NAS-VendorId := &control:Tmp-Integer-2 -> 0 (11) cache-nas: &control:HPE-NAS-DNS-Zone := &control:Tmp-String-2 -> '' (11) cache-nas: &control:HPE-NAS-VendorCodingId := &control:Tmp-Integer-3 -> 0 (11) cache-nas: Merging cache entry into request (11) cache-nas: &control:HPE-NAS-VendorId := 0 (11) cache-nas: &control:HPE-NAS-DNS-Zone := "" (11) cache-nas: &control:HPE-NAS-VendorCodingId := 0 (11) cache-nas: ::: FROM 3 TO 6 MAX 9 (11) cache-nas: ::: Examining HPE-NAS-VendorId (11) cache-nas: ::: APPENDING HPE-NAS-VendorId FROM 0 TO 6 (11) cache-nas: ::: Examining HPE-NAS-DNS-Zone (11) cache-nas: ::: APPENDING HPE-NAS-DNS-Zone FROM 1 TO 6 (11) cache-nas: ::: Examining HPE-NAS-VendorCodingId (11) cache-nas: ::: APPENDING HPE-NAS-VendorCodingId FROM 2 TO 6 (11) cache-nas: ::: TO in 6 out 6 (11) cache-nas: ::: to[0] = Tmp-String-9 (11) cache-nas: ::: to[1] = Tmp-String-0 (11) cache-nas: ::: to[2] = Tmp-String-1 (11) cache-nas: ::: to[3] = Tmp-Integer-2 (11) cache-nas: ::: to[4] = Tmp-String-2 (11) cache-nas: ::: to[5] = Tmp-Integer-3 (11) cache-nas: Committed entry, TTL 60 seconds (11) cache-nas: Mutex released (11) modsingle[authorize]: returned from cache-nas (rlm_cache) (11) [cache-nas] = updated (11) } # policy nas-info = updated (11) policy auth-by-callingId { (11) if (&Calling-Station-ID){ (11) if (&Calling-Station-ID) -> FALSE (11) else { (11) update control { (11) HPE-Auth-By-CliId := No (11) } # update control = noop (11) } # else = noop (11) } # policy auth-by-callingId = noop (11) if (&control:HPE-Auth-By-CliId == "Yes") { (11) if (&control:HPE-Auth-By-CliId == "Yes") -> FALSE (11) else { (11) if (&request:Hint == "ROAM") { (11) if (&request:Hint == "ROAM") -> FALSE (11) elsif (&request:Hint == "VPDN") { (11) elsif (&request:Hint == "VPDN") -> FALSE (11) else { (11) if (&request:HPE-ISPVN-Id == 1000912) { (11) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (11) else { (11) redundant redundant_sql_default { (11) modsingle[authorize]: calling sql_primary_default (rlm_sql) (11) sql_primary_default: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (11) sql_primary_default: --> 20M-GPON-HSI (11) sql_primary_default: SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (14) (11) sql_primary_default: EXPAND SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (11) sql_primary_default: --> SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (11) sql_primary_default: Executing select query: SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (11) sql_primary_default: User found in radcheck table (11) sql_primary_default: Conditional check items matched, merging assignment check items (11) sql_primary_default: Cleartext-Password := "test" (11) sql_primary_default: ::: FROM 1 TO 10 MAX 11 (11) sql_primary_default: ::: Examining Cleartext-Password (11) sql_primary_default: ::: APPENDING Cleartext-Password FROM 0 TO 10 (11) sql_primary_default: ::: TO in 10 out 10 (11) sql_primary_default: ::: to[0] = Tmp-String-9 (11) sql_primary_default: ::: to[1] = Tmp-String-0 (11) sql_primary_default: ::: to[2] = Tmp-String-1 (11) sql_primary_default: ::: to[3] = Tmp-Integer-2 (11) sql_primary_default: ::: to[4] = Tmp-String-2 (11) sql_primary_default: ::: to[5] = Tmp-Integer-3 (11) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (11) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (11) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (11) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (11) sql_primary_default: EXPAND SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (11) sql_primary_default: --> SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (11) sql_primary_default: Executing select query: SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (11) sql_primary_default: ... falling-through to group processing (11) sql_primary_default: EXPAND SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY priority (11) sql_primary_default: --> SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (11) sql_primary_default: Executing select query: SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (11) sql_primary_default: User found in the group table (11) sql_primary_default: EXPAND SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (11) sql_primary_default: --> SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (11) sql_primary_default: Executing select query: SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (11) sql_primary_default: Group "RAC x 20M-GPON-HSI": Conditional check items matched (11) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging assignment check items (11) sql_primary_default: ::: FROM 0 TO 11 MAX 11 (11) sql_primary_default: ::: TO in 11 out 11 (11) sql_primary_default: ::: to[0] = Tmp-String-9 (11) sql_primary_default: ::: to[1] = Tmp-String-0 (11) sql_primary_default: ::: to[2] = Tmp-String-1 (11) sql_primary_default: ::: to[3] = Tmp-Integer-2 (11) sql_primary_default: ::: to[4] = Tmp-String-2 (11) sql_primary_default: ::: to[5] = Tmp-Integer-3 (11) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (11) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (11) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (11) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (11) sql_primary_default: ::: to[10] = Cleartext-Password (11) sql_primary_default: EXPAND SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (11) sql_primary_default: --> SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (11) sql_primary_default: Executing select query: SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (11) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging reply items (11) sql_primary_default: Acct-Interim-Interval = 21600 (11) sql_primary_default: ::: FROM 1 TO 0 MAX 1 (11) sql_primary_default: ::: Examining Acct-Interim-Interval (11) sql_primary_default: ::: APPENDING Acct-Interim-Interval FROM 0 TO 0 (11) sql_primary_default: ::: TO in 0 out 0 (11) sql_primary_default: ... falling-through to profile processing rlm_sql (sql_primary_default): Released connection (14) (11) modsingle[authorize]: returned from sql_primary_default (rlm_sql) (11) [sql_primary_default] = ok (11) } # redundant redundant_sql_default = ok (11) policy check-block { (11) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") { (11) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") -> FALSE (11) } # policy check-block = ok (11) } # else = ok (11) } # else = ok (11) } # else = ok (11) modsingle[authorize]: calling chap (rlm_chap) (11) chap: &control:Auth-Type := CHAP (11) modsingle[authorize]: returned from chap (rlm_chap) (11) [chap] = ok (11) modsingle[authorize]: calling expiration (rlm_expiration) (11) modsingle[authorize]: returned from expiration (rlm_expiration) (11) [expiration] = noop (11) modsingle[authorize]: calling logintime (rlm_logintime) (11) modsingle[authorize]: returned from logintime (rlm_logintime) (11) [logintime] = noop (11) modsingle[authorize]: calling pap (rlm_pap) (11) pap: WARNING: Auth-Type already set. Not setting to PAP (11) modsingle[authorize]: returned from pap (rlm_pap) (11) [pap] = noop (11) } # authorize = updated (11) Found Auth-Type = CHAP (11) # Executing group from file /etc/raddb/sites-enabled/default (11) Auth-Type CHAP { (11) modsingle[authenticate]: calling chap (rlm_chap) (11) chap: Comparing with "known good" &control:Cleartext-Password value "test" (11) chap: Using challenge from &request:CHAP-Challenge (11) chap: CHAP challenge : 313233343536373839303132333435363738393031323334 (11) chap: Client sent : 35ace44d9d6c7deacb03c98def21059a (11) chap: We calculated : 35ace44d9d6c7deacb03c98def21059a (11) chap: CHAP user "20M-GPON-HSI" authenticated successfully (11) modsingle[authenticate]: returned from chap (rlm_chap) (11) [chap] = ok (11) } # Auth-Type CHAP = ok (11) # Executing section post-auth from file /etc/raddb/sites-enabled/default (11) post-auth { (11) policy debug-rule { (11) update control { (11) EXPAND %{debug:5} (11) --> 4 (11) Tmp-String-9 = 4 (11) Refusing to overwrite (use :=) (11) } # update control = noop (11) } # policy debug-rule = noop (11) if (&request:HPE-ISPVN-Id == 1000912) { (11) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (11) elsif (&request:HPE-ISPVN-Id == 1003334) { (11) elsif (&request:HPE-ISPVN-Id == 1003334) -> FALSE (11) policy insert_hpe_acct_class { (11) update control { (11) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (11) --> 20M-GPON-HSI (11) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (15) (11) EXPAND /var/log/radius/sqllog.sql (11) --> /var/log/radius/sqllog.sql (11) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (15) (11) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (11) --> X (11) Tmp-String-0 := X (11) Overwriting value "X" with "X" (11) } # update control = noop (11) if (&request:Hint == "Access") { (11) if (&request:Hint == "Access") -> TRUE (11) if (&request:Hint == "Access") { (11) if (&control:Tmp-String-0 != "") { (11) if (&control:Tmp-String-0 != "") -> TRUE (11) if (&control:Tmp-String-0 != "") { (11) update reply { (11) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (11) --> 20M-GPON-HSI (11) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (13) (11) EXPAND /var/log/radius/sqllog.sql (11) --> /var/log/radius/sqllog.sql (11) Executing select query: SELECT create_class_attr('Access',1059241,'20M-GPON-HSI','','No','127.0.0.1','','') FROM DUAL rlm_sql (sql_primary_default): Released connection (13) (11) EXPAND %{sql_primary_default:SELECT create_class_attr('%{Hint}',%{HPE-ISPVN-Id},'%{%{Stripped-User-Name}:-%{User-Name}}','%{Calling-Station-ID}','%{&control:HPE-Auth-By-CliId}','%{NAS-IP-Address}','%{HPE-NAS-Desc}','%{HPE-Logon-Time}') FROM DUAL}_AAA: (11) --> A__NA=UNKNOWN_1059241_72924453_1058360_5_2_Y_Y_1753043_0_0_AAA: (11) &Class = 0x415f5f4e413d554e4b4e4f574e5f313035393234315f37323932343435335f313035383336305f355f325f595f595f313735333034335f305f305f4141413a (11) } # update reply = noop (11) } # if (&control:Tmp-String-0 != "") = noop (11) ... skipping else: Preceding "if" was taken (11) } # if (&request:Hint == "Access") = noop (11) ... skipping elsif: Preceding "if" was taken (11) } # policy insert_hpe_acct_class = noop (11) } # post-auth = noop (11) Sent Access-Accept Id 84 from 127.0.0.1:1812 to 127.0.0.1:42359 length 0 (11) Acct-Interim-Interval = 21600 (11) Class = 0x415f5f4e413d554e4b4e4f574e5f313035393234315f37323932343435335f313035383336305f355f325f595f595f313735333034335f305f305f4141413a (11) Finished request ================================================================================ 4) freeradius radclient - CHAP-Challenge over 48 bytes echo "User-Name=20M-GPON-HSI@ttp.it,CHAP-Password=test,CHAP-Challenge=1234567890123456789012345 " | radclient localhost:1812 auth InternalSecret Sent Access-Request Id 42 from 0.0.0.0:51748 to 127.0.0.1:1812 length 87 Received Access-Reject Id 42 from 127.0.0.1:1812 to 0.0.0.0:0 length 55 (0) -: Expected Access-Accept got Access-Reject (15) Received Access-Request Id 42 from 127.0.0.1:51748 to 127.0.0.1:1812 length 87 (15) User-Name = "20M-GPON-HSI@ttp.it" (15) CHAP-Password = 0x1eaa65c23ab25863470c8fed85eb60c000 (15) CHAP-Challenge = 0x31323334353637383930313233343536373839303132333435 (15) # Executing section authorize from file /etc/raddb/sites-enabled/default (15) authorize { (15) policy debug-rule { (15) update control { (15) EXPAND %{debug:5} (15) --> 2 (15) Tmp-String-9 = 2 (15) } # update control = noop (15) } # policy debug-rule = noop (15) policy filter_username { (15) if (&User-Name) { (15) if (&User-Name) -> TRUE (15) if (&User-Name) { (15) if (&User-Name =~ / /) { (15) if (&User-Name =~ / /) -> FALSE (15) if (&User-Name =~ /@[^@]*@/ ) { (15) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (15) if (&User-Name =~ /\.\./ ) { (15) if (&User-Name =~ /\.\./ ) -> FALSE (15) if (&User-Name =~ /\.$/) { (15) if (&User-Name =~ /\.$/) -> FALSE (15) if (&User-Name =~ /@\./) { (15) if (&User-Name =~ /@\./) -> FALSE (15) } # if (&User-Name) = noop (15) } # policy filter_username = noop (15) modsingle[authorize]: calling preprocess (rlm_preprocess) (15) preprocess: hints: Matched DEFAULT at 9 (15) preprocess: ::: FROM 4 TO 5 MAX 9 (15) preprocess: ::: Examining Hint (15) preprocess: ::: APPENDING Hint FROM 0 TO 5 (15) preprocess: ::: Examining Stripped-User-Name (15) preprocess: 1/3 Found: 20M-GPON-HSI (13) (15) preprocess: EXPAND %{1} (15) preprocess: --> 20M-GPON-HSI (15) preprocess: ::: APPENDING Stripped-User-Name FROM 1 TO 5 (15) preprocess: ::: Examining Realm (15) preprocess: 2/3 Found: ttp.it (7) (15) preprocess: EXPAND %{2} (15) preprocess: --> ttp.it (15) preprocess: ::: APPENDING Realm FROM 2 TO 5 (15) preprocess: ::: Examining HPE-ISPVN-Id (15) preprocess: ::: APPENDING HPE-ISPVN-Id FROM 3 TO 5 (15) preprocess: ::: TO in 5 out 5 (15) preprocess: ::: to[0] = User-Name (15) preprocess: ::: to[1] = CHAP-Password (15) preprocess: ::: to[2] = CHAP-Challenge (15) preprocess: ::: to[3] = Event-Timestamp (15) preprocess: ::: to[4] = NAS-IP-Address (15) modsingle[authorize]: returned from preprocess (rlm_preprocess) (15) [preprocess] = ok (15) policy nas-info { (15) update control { (15) Cache-Status-Only = yes (15) } # update control = noop (15) modsingle[authorize]: calling cache-nas (rlm_cache) (15) cache-nas: EXPAND %{NAS-IP-Address} (15) cache-nas: --> 127.0.0.1 (15) cache-nas: Mutex acquired (15) cache-nas: No cache entry found for "127.0.0.1" (15) cache-nas: Mutex released (15) modsingle[authorize]: returned from cache-nas (rlm_cache) (15) [cache-nas] = notfound (15) if (notfound) { (15) if (notfound) -> TRUE (15) if (notfound) { (15) update control { (15) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (15) --> 20M-GPON-HSI (15) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (12) (15) EXPAND /var/log/radius/sqllog.sql (15) --> /var/log/radius/sqllog.sql (15) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (12) (15) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (15) --> X (15) Tmp-String-0 := X (15) } # update control = noop (15) if (&control:Tmp-String-0 != "") { (15) if (&control:Tmp-String-0 != "") -> TRUE (15) if (&control:Tmp-String-0 != "") { (15) update control { (15) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (15) --> 20M-GPON-HSI (15) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (14) (15) EXPAND /var/log/radius/sqllog.sql (15) --> /var/log/radius/sqllog.sql (15) Executing select query: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '127.0.0.1' (15) SQL query returned no results rlm_sql (sql_primary_default): Released connection (14) (15) EXPAND %{sql_primary_default:SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '%{NAS-IP-Address}'} (15) --> (15) Tmp-String-1 := (15) } # update control = noop (15) } # if (&control:Tmp-String-0 != "") = noop (15) ... skipping else: Preceding "if" was taken (15) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) { (15) if (&control:Tmp-String-1 =~ /([0-9]*)~(.*)~([0-9]*)/) -> FALSE (15) else { (15) update control { (15) Tmp-Integer-2 := 0 (15) Tmp-String-2 := '' (15) Tmp-Integer-3 := 0 (15) } # update control = noop (15) } # else = noop (15) } # if (notfound) = noop (15) modsingle[authorize]: calling cache-nas (rlm_cache) (15) cache-nas: EXPAND %{NAS-IP-Address} (15) cache-nas: --> 127.0.0.1 (15) cache-nas: Mutex acquired (15) cache-nas: No cache entry found for "127.0.0.1" (15) cache-nas: Creating new cache entry (15) cache-nas: &control:HPE-NAS-VendorId := &control:Tmp-Integer-2 -> 0 (15) cache-nas: &control:HPE-NAS-DNS-Zone := &control:Tmp-String-2 -> '' (15) cache-nas: &control:HPE-NAS-VendorCodingId := &control:Tmp-Integer-3 -> 0 (15) cache-nas: Merging cache entry into request (15) cache-nas: &control:HPE-NAS-VendorId := 0 (15) cache-nas: &control:HPE-NAS-DNS-Zone := "" (15) cache-nas: &control:HPE-NAS-VendorCodingId := 0 (15) cache-nas: ::: FROM 3 TO 6 MAX 9 (15) cache-nas: ::: Examining HPE-NAS-VendorId (15) cache-nas: ::: APPENDING HPE-NAS-VendorId FROM 0 TO 6 (15) cache-nas: ::: Examining HPE-NAS-DNS-Zone (15) cache-nas: ::: APPENDING HPE-NAS-DNS-Zone FROM 1 TO 6 (15) cache-nas: ::: Examining HPE-NAS-VendorCodingId (15) cache-nas: ::: APPENDING HPE-NAS-VendorCodingId FROM 2 TO 6 (15) cache-nas: ::: TO in 6 out 6 (15) cache-nas: ::: to[0] = Tmp-String-9 (15) cache-nas: ::: to[1] = Tmp-String-0 (15) cache-nas: ::: to[2] = Tmp-String-1 (15) cache-nas: ::: to[3] = Tmp-Integer-2 (15) cache-nas: ::: to[4] = Tmp-String-2 (15) cache-nas: ::: to[5] = Tmp-Integer-3 (15) cache-nas: Committed entry, TTL 60 seconds (15) cache-nas: Mutex released (15) modsingle[authorize]: returned from cache-nas (rlm_cache) (15) [cache-nas] = updated (15) } # policy nas-info = updated (15) policy auth-by-callingId { (15) if (&Calling-Station-ID){ (15) if (&Calling-Station-ID) -> FALSE (15) else { (15) update control { (15) HPE-Auth-By-CliId := No (15) } # update control = noop (15) } # else = noop (15) } # policy auth-by-callingId = noop (15) if (&control:HPE-Auth-By-CliId == "Yes") { (15) if (&control:HPE-Auth-By-CliId == "Yes") -> FALSE (15) else { (15) if (&request:Hint == "ROAM") { (15) if (&request:Hint == "ROAM") -> FALSE (15) elsif (&request:Hint == "VPDN") { (15) elsif (&request:Hint == "VPDN") -> FALSE (15) else { (15) if (&request:HPE-ISPVN-Id == 1000912) { (15) if (&request:HPE-ISPVN-Id == 1000912) -> FALSE (15) else { (15) redundant redundant_sql_default { (15) modsingle[authorize]: calling sql_primary_default (rlm_sql) (15) sql_primary_default: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (15) sql_primary_default: --> 20M-GPON-HSI (15) sql_primary_default: SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (15) (15) sql_primary_default: EXPAND SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (15) sql_primary_default: --> SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (15) sql_primary_default: Executing select query: SELECT rc.id as id, username, ra.name as attribute, value, op FROM RADIUS_CHECK rc, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rc.css_id = s.id AND rc.radius_attr_id = ra.id AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (15) sql_primary_default: User found in radcheck table (15) sql_primary_default: Conditional check items matched, merging assignment check items (15) sql_primary_default: Cleartext-Password := "test" (15) sql_primary_default: ::: FROM 1 TO 10 MAX 11 (15) sql_primary_default: ::: Examining Cleartext-Password (15) sql_primary_default: ::: APPENDING Cleartext-Password FROM 0 TO 10 (15) sql_primary_default: ::: TO in 10 out 10 (15) sql_primary_default: ::: to[0] = Tmp-String-9 (15) sql_primary_default: ::: to[1] = Tmp-String-0 (15) sql_primary_default: ::: to[2] = Tmp-String-1 (15) sql_primary_default: ::: to[3] = Tmp-Integer-2 (15) sql_primary_default: ::: to[4] = Tmp-String-2 (15) sql_primary_default: ::: to[5] = Tmp-Integer-3 (15) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (15) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (15) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (15) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (15) sql_primary_default: EXPAND SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND lower(s.username) = '%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY id (15) sql_primary_default: --> SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (15) sql_primary_default: Executing select query: SELECT rr.id as id, username, ra.name as attribute, value, op FROM RADIUS_REPLY rr, SUBSCRIPTION s, RADIUS_ATTR ra WHERE rr.css_id = s.id AND rr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND lower(s.username) = '20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY id (15) sql_primary_default: ... falling-through to group processing (15) sql_primary_default: EXPAND SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='%{tolower:%{SQL-User-Name}}' AND s.service_id = %{HPE-ISPVN-Id} ORDER BY priority (15) sql_primary_default: --> SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (15) sql_primary_default: Executing select query: SELECT g.name groupname FROM RADIUS_SUBSCRIPTION_GROUP m, RADIUS_GROUP g, SUBSCRIPTION s WHERE m.group_id = g.id AND m.css_id = s.id AND lower(s.username)='20m-gpon-hsi' AND s.service_id = 1059241 ORDER BY priority (15) sql_primary_default: User found in the group table (15) sql_primary_default: EXPAND SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (15) sql_primary_default: --> SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (15) sql_primary_default: Executing select query: SELECT rgc.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_CHECK rgc, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgc.group_id = rg.id AND rgc.radius_attr_id = ra.id AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (15) sql_primary_default: Group "RAC x 20M-GPON-HSI": Conditional check items matched (15) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging assignment check items (15) sql_primary_default: ::: FROM 0 TO 11 MAX 11 (15) sql_primary_default: ::: TO in 11 out 11 (15) sql_primary_default: ::: to[0] = Tmp-String-9 (15) sql_primary_default: ::: to[1] = Tmp-String-0 (15) sql_primary_default: ::: to[2] = Tmp-String-1 (15) sql_primary_default: ::: to[3] = Tmp-Integer-2 (15) sql_primary_default: ::: to[4] = Tmp-String-2 (15) sql_primary_default: ::: to[5] = Tmp-Integer-3 (15) sql_primary_default: ::: to[6] = HPE-NAS-VendorId (15) sql_primary_default: ::: to[7] = HPE-NAS-DNS-Zone (15) sql_primary_default: ::: to[8] = HPE-NAS-VendorCodingId (15) sql_primary_default: ::: to[9] = HPE-Auth-By-CliId (15) sql_primary_default: ::: to[10] = Cleartext-Password (15) sql_primary_default: EXPAND SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,%{&control:HPE-Nas-VendorId}) AND rg.name = '%{sql_primary_default-SQL-Group}' ORDER BY id (15) sql_primary_default: --> SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (15) sql_primary_default: Executing select query: SELECT rgr.id as id, rg.name as groupname, ra.name as attribute, value, op FROM RADIUS_GROUP_REPLY rgr, RADIUS_GROUP rg, RADIUS_ATTR ra WHERE rgr.group_id = rg.id AND rgr.radius_attr_id = ra.id AND ra.vendor_id in (0,0) AND rg.name = 'RAC x 20M-GPON-HSI' ORDER BY id (15) sql_primary_default: Group "RAC x 20M-GPON-HSI": Merging reply items (15) sql_primary_default: Acct-Interim-Interval = 21600 (15) sql_primary_default: ::: FROM 1 TO 0 MAX 1 (15) sql_primary_default: ::: Examining Acct-Interim-Interval (15) sql_primary_default: ::: APPENDING Acct-Interim-Interval FROM 0 TO 0 (15) sql_primary_default: ::: TO in 0 out 0 (15) sql_primary_default: ... falling-through to profile processing rlm_sql (sql_primary_default): Released connection (15) (15) modsingle[authorize]: returned from sql_primary_default (rlm_sql) (15) [sql_primary_default] = ok (15) } # redundant redundant_sql_default = ok (15) policy check-block { (15) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") { (15) if (&control:HPE-Block-Subscriber && &control:HPE-Block-Subscriber == "Y") -> FALSE (15) } # policy check-block = ok (15) } # else = ok (15) } # else = ok (15) } # else = ok (15) modsingle[authorize]: calling chap (rlm_chap) (15) chap: &control:Auth-Type := CHAP (15) modsingle[authorize]: returned from chap (rlm_chap) (15) [chap] = ok (15) modsingle[authorize]: calling expiration (rlm_expiration) (15) modsingle[authorize]: returned from expiration (rlm_expiration) (15) [expiration] = noop (15) modsingle[authorize]: calling logintime (rlm_logintime) (15) modsingle[authorize]: returned from logintime (rlm_logintime) (15) [logintime] = noop (15) modsingle[authorize]: calling pap (rlm_pap) (15) pap: WARNING: Auth-Type already set. Not setting to PAP (15) modsingle[authorize]: returned from pap (rlm_pap) (15) [pap] = noop (15) } # authorize = updated (15) Found Auth-Type = CHAP (15) # Executing group from file /etc/raddb/sites-enabled/default (15) Auth-Type CHAP { (15) modsingle[authenticate]: calling chap (rlm_chap) (15) chap: Comparing with "known good" &control:Cleartext-Password value "test" (15) chap: Using challenge from &request:CHAP-Challenge (15) chap: CHAP challenge : 31323334353637383930313233343536373839303132333435 (15) chap: Client sent : aa65c23ab25863470c8fed85eb60c000 (15) chap: We calculated : 3500c23ab25863470c8fed85eb60c000 (15) chap: ERROR: Password comparison failed: password is incorrect (15) modsingle[authenticate]: returned from chap (rlm_chap) (15) [chap] = reject (15) } # Auth-Type CHAP = reject (15) Failed to authenticate the user (15) Using Post-Auth-Type Reject (15) # Executing group from file /etc/raddb/sites-enabled/default (15) Post-Auth-Type REJECT { (15) policy insert_hpe_reply_message { (15) update control { (15) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (15) --> 20M-GPON-HSI (15) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (18) (15) EXPAND /var/log/radius/sqllog.sql (15) --> /var/log/radius/sqllog.sql (15) Executing select query: SELECT * FROM DUAL rlm_sql (sql_primary_default): Released connection (18) (15) EXPAND %{sql_primary_default:SELECT * FROM DUAL} (15) --> X (15) Tmp-String-0 := X (15) Overwriting value "X" with "X" (15) } # update control = noop (15) if (&request:Hint == "Access") { (15) if (&request:Hint == "Access") -> TRUE (15) if (&request:Hint == "Access") { (15) if (&control:Tmp-String-0 != "") { (15) if (&control:Tmp-String-0 != "") -> TRUE (15) if (&control:Tmp-String-0 != "") { (15) update reply { (15) EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} (15) --> 20M-GPON-HSI (15) SQL-User-Name set to '20M-GPON-HSI' rlm_sql (sql_primary_default): Reserved connection (13) (15) EXPAND /var/log/radius/sqllog.sql (15) --> /var/log/radius/sqllog.sql (15) Executing select query: SELECT create_message_reply('Access',1059241,'20M-GPON-HSI','','No','test','chap: Password comparison failed: password is incorrect') FROM DUAL rlm_sql (sql_primary_default): Released connection (13) (15) EXPAND %{sql_primary_default:SELECT create_message_reply('%{Hint}',%{HPE-ISPVN-Id},'%{%{Stripped-User-Name}:-%{User-Name}}','%{Calling-Station-ID}','%{&control:HPE-Auth-By-CliId}','%{%{&control:Cleartext-Password}:-''}','%{Module-Failure-Message}') FROM DUAL} (15) --> A_1059241_72924453_1058360_test_2 (15) &Reply-Message = A_1059241_72924453_1058360_test_2 (15) } # update reply = noop (15) } # if (&control:Tmp-String-0 != "") = noop (15) ... skipping else: Preceding "if" was taken (15) } # if (&request:Hint == "Access") = noop (15) ... skipping elsif: Preceding "if" was taken (15) ... skipping elsif: Preceding "if" was taken (15) } # policy insert_hpe_reply_message = noop (15) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) (15) attr_filter.access_reject: EXPAND %{User-Name} (15) attr_filter.access_reject: --> 20M-GPON-HSI@ttp.it (15) attr_filter.access_reject: Matched entry DEFAULT at line 11 (15) attr_filter.access_reject: Attribute "Acct-Interim-Interval" allowed by 0 rules, disallowed by 0 rules (15) attr_filter.access_reject: Reply-Message = "A_1059241_72924453_1058360_test_2" allowed by Reply-Message =* "" (15) attr_filter.access_reject: Attribute "Reply-Message" allowed by 1 rules, disallowed by 0 rules (15) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) (15) [attr_filter.access_reject] = updated (15) } # Post-Auth-Type REJECT = updated (15) Delaying response for 1.000000 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (15) Sending delayed response (15) Sent Access-Reject Id 42 from 127.0.0.1:1812 to 127.0.0.1:51748 length 55 (15) Reply-Message = "A_1059241_72924453_1058360_test_2"