Issue with Chap Auth - freeradius v3.0.16 on RHEL 7.4
Andrea Mucci
andrea.mucci at outlook.com
Fri Sep 21 18:42:04 CEST 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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"
More information about the Freeradius-Users
mailing list