Issue with Chap Auth - freeradius v3.0.16 on RHEL 7.4

21 Sep 2018

      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"

Issue with Chap Auth - freeradius v3.0.16 on RHEL 7.4

Andrea Mucci