Hello Alan,
I'm using Freeradius 3.0.19 in Ubuntu 16.
I was having trouble when I tried to update control in authenticate
session in default file, for Auth-Type mschap, when authentication is
rejected.
The condition wasn't reached.
In debug mode, I see this line (complete dump below): (7) mschap:
Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
So I changed "Auth-Type MS-CHAP { " to "Auth-Type mschap" in
default file and all works fine!!
It's a bug or just my fault?
:: "ERROR DUMP"
Ready to process requests
(7) Received Access-Request Id 114 from 172.17.6.2:33846 to
XXX.XXX.XXX.XXX:1812 length 193
(7) Service-Type = Framed-User
(7) Framed-Protocol = PPP
(7) NAS-Port = 15729015
(7) NAS-Port-Type = Ethernet
(7) User-Name = "XXXXXXXXXXX"
(7) Calling-Station-Id = "XX:XX:XX:XX:XX:XX"
(7) Called-Station-Id = "CE - POP ITPM5"
(7) NAS-Port-Id = "ether5"
(7) MS-CHAP-Challenge = 0xdb9cf50eb227ee11
(7) MS-CHAP-Response =
0x01010000000000000000000000000000000000000000000000006bc5f0726031baa47
5638dca8a9348c12d6d0d8d21ffe29e
(7) NAS-Identifier = "CE-ITPM"
(7) NAS-IP-Address = 172.17.6.2
(7) # Executing section authorize from file
/etc/freeradius/sites-enabled/default
(7) authorize {
(7) [preprocess] = ok
(7) [chap] = noop
(7) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
(7) [mschap] = ok
(7) sql: EXPAND %{User-Name}
(7) sql: --> XXXXXXXXXXXXX
(7) sql: SQL-User-Name set to 'XXXXXXXXXXXXXXX'
rlm_sql (sql): Reserved connection (9)
(7) sql: EXPAND SELECT DISTINCT (R.id), R.username, R.attribute,
R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'%{SQL-User-Name}' AND M.usuario_login
= BINARY '%{SQL-User-Name}' AND
N.nasname = '%{Nas-IP-Address}' AND
N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'%{SQL-User-Name}'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'%{Nas-IP-Address}'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'%{SQL-User-Name}' AND M.usuario_login
= BINARY '%{SQL-User-Name}' AND
M.grupocliente = 'ALL-POPS'
(7) sql: --> SELECT DISTINCT (R.id), R.username, R.attribute,
R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND N.nasname
= '172.17.6.2' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'XXXXXXXXXXXXX'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.6.2'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND
M.grupocliente = 'ALL-POPS'
(7) sql: Executing select query: SELECT DISTINCT (R.id), R.username,
R.attribute, R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND N.nasname
= '172.17.6.2' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'XXXXXXXXXXXXX'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.6.2'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND
M.grupocliente = 'ALL-POPS'
rlm_sql (sql): Closing expired connection (7): Hit lifetime limit
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Reserved connection (10)
rlm_sql (sql): Released connection (10)
Need 8 more connections to reach 10 spares
rlm_sql (sql): Opening additional connection (11), 1 of 29 pending
slots used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'mpc_freeradius' on
mysql.mpc.com.br via TCP/IP, server version
5.7.26-0ubuntu0.16.04.1-log, protocol version 10
(7) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority
(7) sql: --> SELECT groupname FROM radusergroup WHERE username =
'XXXXXXXXXXXXX' ORDER BY priority
(7) sql: Executing select query: SELECT groupname FROM radusergroup
WHERE username = 'XXXXXXXXXXXXX' ORDER BY priority
(7) sql: User not found in any groups
rlm_sql (sql): Released connection (9)
(7) [sql] = notfound
(7) [expiration] = noop
(7) [logintime] = noop
Not doing PAP as Auth-Type is already set.
(7) [pap] = noop
(7) } # authorize = ok
(7) Found Auth-Type = mschap
(7) # Executing group from file /etc/freeradius/sites-enabled/default
(7) authenticate {
(7) mschap: WARNING: No Cleartext-Password configured. Cannot create
NT-Password
(7) mschap: WARNING: No Cleartext-Password configured. Cannot create
LM-Password
(7) mschap: Client is using MS-CHAPv1 with NT-Password
(7) mschap: ERROR: FAILED: No NT/LM-Password. Cannot perform
authentication
(7) mschap: ERROR: MS-CHAP2-Response is incorrect
(7) [mschap] = reject
(7) } # authenticate = reject
(7) Failed to authenticate the user
(7) Using Post-Auth-Type Reject
(7) # Executing group from file /etc/freeradius/sites-enabled/default
(7) Post-Auth-Type REJECT {
(7) attr_filter.access_reject: EXPAND %{User-Name}
(7) attr_filter.access_reject: --> XXXXXXXXXXXXX
(7) attr_filter.access_reject: Matched entry DEFAULT at line 11
(7) [attr_filter.access_reject] = updated
(7) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default}
(7) linelog: --> messages.Access-Reject
(7) linelog: No such entry ".messages.Access-Reject"
(7) [linelog] = noop
(7) } # Post-Auth-Type REJECT = updated
(7) Login incorrect (mschap: FAILED: No NT/LM-Password. Cannot perform
authentication): [XXXXXXXXXXXXX/<via Auth-Type = mschap>] (from client
ce-popitpm-rb port 15729015 cli XX:XX:XX:XX:XX:XX)
(7) Delaying response for 1.000000 seconds
Waking up in 0.6 seconds.
Waking up in 0.3 seconds.
(7) Sending delayed response
(7) Sent Access-Reject Id 114 from 187.120.197.140:1812 to
172.17.6.2:33846 length 61
(7) MS-CHAP-Error = "\001E=691 R=1 C=aa56c73c463c7a63 V=2"
Waking up in 8.9 seconds.
:: "ALL OK DUMP"
(1) Received Access-Request Id 209 from 172.17.6.2:59186 to
XXX.XXX.XXX.XXX:1812 length 193
(1) Service-Type = Framed-User
(1) Framed-Protocol = PPP
(1) NAS-Port = 15729042
(1) NAS-Port-Type = Ethernet
(1) User-Name = "XXXXXXXXXXXXX"
(1) Calling-Station-Id = "XX:XX:XX:XX:XX:XX"
(1) Called-Station-Id = "CE - POP ITPM5"
(1) NAS-Port-Id = "ether5"
(1) MS-CHAP-Challenge = 0xdf11a990dc9e9fb7
(1) MS-CHAP-Response =
0x010100000000000000000000000000000000000000000000000075ad989b83ff7ae24
102c6e3a0f272e11ff159260152f933
(1) NAS-Identifier = "CE-ITPM"
(1) NAS-IP-Address = 172.17.6.2
(1) # Executing section authorize from file
/etc/freeradius/sites-enabled/default
(1) authorize {
(1) [preprocess] = ok
(1) [chap] = noop
(1) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
(1) [mschap] = ok
(1) sql: EXPAND %{User-Name}
(1) sql: --> XXXXXXXXXXXXX
(1) sql: SQL-User-Name set to 'XXXXXXXXXXXXX'
rlm_sql (sql): Reserved connection (3)
(1) sql: EXPAND SELECT DISTINCT (R.id), R.username, R.attribute,
R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'%{SQL-User-Name}' AND M.usuario_login
= BINARY '%{SQL-User-Name}' AND
N.nasname = '%{Nas-IP-Address}' AND
N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'%{SQL-User-Name}'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'%{Nas-IP-Address}'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'%{SQL-User-Name}' AND M.usuario_login
= BINARY '%{SQL-User-Name}' AND
M.grupocliente = 'ALL-POPS'
(1) sql: --> SELECT DISTINCT (R.id), R.username, R.attribute,
R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND N.nasname
= '172.17.6.2' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'XXXXXXXXXXXXX'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.6.2'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND
M.grupocliente = 'ALL-POPS'
(1) sql: Executing select query: SELECT DISTINCT (R.id), R.username,
R.attribute, R.value, R.op FROM
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND N.nasname
= '172.17.6.2' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'XXXXXXXXXXXXX'
AND plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.6.2'
) ORDER BY
ID) UNION
ALL SELECT DISTINCT (R.id),
R.username, R.attribute, R.value, R.op
FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist
M WHERE R.username = BINARY
'XXXXXXXXXXXXX' AND M.usuario_login =
BINARY 'XXXXXXXXXXXXX' AND
M.grupocliente = 'ALL-POPS'
rlm_sql (sql): Reserved connection (4)
rlm_sql (sql): Released connection (4)
Need 4 more connections to reach 10 spares
rlm_sql (sql): Opening additional connection (7), 1 of 25 pending slots
used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'mpc_freeradius' on
mysql.mpc.com.br via TCP/IP, server version
5.7.26-0ubuntu0.16.04.1-log, protocol version 10
(1) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority
(1) sql: --> SELECT groupname FROM radusergroup WHERE username =
'XXXXXXXXXXXXX' ORDER BY priority
(1) sql: Executing select query: SELECT groupname FROM radusergroup
WHERE username = 'XXXXXXXXXXXXX' ORDER BY priority
(1) sql: User not found in any groups
rlm_sql (sql): Released connection (3)
(1) [sql] = notfound
(1) [expiration] = noop
(1) [logintime] = noop
Not doing PAP as Auth-Type is already set.
(1) [pap] = noop
(1) } # authorize = ok
(1) Found Auth-Type = mschap
(1) # Executing group from file /etc/freeradius/sites-enabled/default
(1) Auth-Type mschap {
(1) mschap: WARNING: No Cleartext-Password configured. Cannot create
NT-Password
(1) mschap: WARNING: No Cleartext-Password configured. Cannot create
LM-Password
(1) mschap: Client is using MS-CHAPv1 with NT-Password
(1) mschap: ERROR: FAILED: No NT/LM-Password. Cannot perform
authentication
(1) mschap: ERROR: MS-CHAP2-Response is incorrect
(1) [mschap] = reject
(1) if (reject) {
(1) if (reject) -> TRUE
(1) if (reject) {
(1) update control {
(1) Pool-Name := "mkt_pool"
(1) } # update control = noop
(1) update reply {
(1) Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K
10/10"
(1) } # update reply = noop
(1) [ok] = ok
(1) } # if (reject) = ok
(1) } # Auth-Type mschap = ok
(1) # Executing section post-auth from file
/etc/freeradius/sites-enabled/default
(1) post-auth {
(1) if (session-state:User-Name && reply:User-Name &&
request:User-Name && (reply:User-Name == request:User-Name)) {
(1) if (session-state:User-Name && reply:User-Name &&
request:User-Name && (reply:User-Name == request:User-Name)) -> FALSE
(1) update {
(1) No attributes updated for RHS &session-state:
(1) } # update = noop
(1) sql: EXPAND .query
(1) sql: --> .query
(1) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (0)
(1) sql: EXPAND %{User-Name}
(1) sql: --> XXXXXXXXXXXXX
(1) sql: SQL-User-Name set to 'XXXXXXXXXXXXX'
(1) sql: EXPAND INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( '%{SQL-User-Name}',
'%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(1) sql: --> INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'XXXXXXXXXXXXX', '', 'Access-Accept', '2019-06-26
11:44:54')
(1) sql: Executing query: INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( 'XXXXXXXXXXXXX', '', 'Access-Accept',
'2019-06-26 11:44:54')
(1) sql: SQL query returned: success
(1) sql: 1 record(s) updated
rlm_sql (sql): Released connection (0)
(1) [sql] = ok
rlm_sql (sql): Reserved connection (5)
(1) sqlippool: EXPAND %{User-Name}
(1) sqlippool: --> XXXXXXXXXXXXX
(1) sqlippool: SQL-User-Name set to 'XXXXXXXXXXXXX'
(1) sqlippool: EXPAND START TRANSACTION
(1) sqlippool: --> START TRANSACTION
(1) sqlippool: Executing query: START TRANSACTION
(1) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', pool_key
= 0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress =
'%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'
(1) sqlippool: --> UPDATE radippool SET nasipaddress = '', pool_key
= 0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress =
'172.17.6.2'
(1) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '',
pool_key = 0, callingstationid = '', username = '', expiry_time = NULL
WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress =
'172.17.6.2'
rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
(1) sqlippool: EXPAND COMMIT
(1) sqlippool: --> COMMIT
(1) sqlippool: Executing query: COMMIT
(1) sqlippool: EXPAND START TRANSACTION
(1) sqlippool: --> START TRANSACTION
(1) sqlippool: Executing query: START TRANSACTION
(1) sqlippool: EXPAND SELECT framedipaddress FROM radippool WHERE
pool_name = '%{control:Pool-Name}' AND (expiry_time < NOW() OR
expiry_time IS NULL) ORDER BY (username <> '%{User-Name}'),
(callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR
UPDATE
(1) sqlippool: --> SELECT framedipaddress FROM radippool WHERE
pool_name = 'mkt_pool' AND (expiry_time < NOW() OR expiry_time IS NULL)
ORDER BY (username <> 'XXXXXXXXXXXXX'), (callingstationid <>
'XX:XX:XX:XX:XX:XX'), expiry_time LIMIT 1 FOR UPDATE
(1) sqlippool: Executing select query: SELECT framedipaddress FROM
radippool WHERE pool_name = 'mkt_pool' AND (expiry_time < NOW() OR
expiry_time IS NULL) ORDER BY (username <> 'XXXXXXXXXXXXX'),
(callingstationid <> 'XX:XX:XX:XX:XX:XX'), expiry_time LIMIT 1 FOR
UPDATE
(1) sqlippool: Allocated IP 10.10.10.6
(1) sqlippool: EXPAND UPDATE radippool SET nasipaddress =
'%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}',
callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}',
expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress =
'10.10.10.6' AND expiry_time IS NULL
(1) sqlippool: --> UPDATE radippool SET nasipaddress = '172.17.6.2',
pool_key = 'XX:XX:XX:XX:XX:XX', callingstationid = 'XX:XX:XX:XX:XX:XX',
username = 'XXXXXXXXXXXXX', expiry_time = NOW() + INTERVAL 3600 SECOND
WHERE framedipaddress = '10.10.10.6' AND expiry_time IS NULL
(1) sqlippool: Executing query: UPDATE radippool SET nasipaddress =
'172.17.6.2', pool_key = 'XX:XX:XX:XX:XX:XX', callingstationid =
'XX:XX:XX:XX:XX:XX', username = 'XXXXXXXXXXXXX', expiry_time = NOW() +
INTERVAL 3600 SECOND WHERE framedipaddress = '10.10.10.6' AND
expiry_time IS NULL
rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
(1) sqlippool: EXPAND COMMIT
(1) sqlippool: --> COMMIT
(1) sqlippool: Executing query: COMMIT
rlm_sql (sql): Released connection (5)
(1) sqlippool: EXPAND Allocated IP: %{reply:Framed-IP-Address} from
%{control:Pool-Name} (did %{Called-Station-Id} cli
%{Calling-Station-Id} port %{NAS-Port} user %{User-Name})
(1) sqlippool: --> Allocated IP: 10.10.10.6 from mkt_pool (did CE -
POP ITPM5 cli XX:XX:XX:XX:XX:XX port 15729042 user XXXXXXXXXXXXX)
(1) [sqlippool] = ok
(1) log_post_auth: EXPAND %{reply:Packet-Type}
(1) log_post_auth: --> Access-Accept
(1) log_post_auth: EXPAND %t : Info: Allocated IP:
%{reply:Framed-IP-Address} from %{control:Pool-Name} (did
%{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user
%{User-Name})
(1) log_post_auth: --> Wed Jun 26 11:44:54 2019 : Info: Allocated
IP: 10.10.10.6 from mkt_pool (did CE - POP ITPM5 cli XX:XX:XX:XX:XX:XX
port 15729042 user XXXXXXXXXXXXX)
(1) log_post_auth: EXPAND /var/log/freeradius/radius.log
(1) log_post_auth: --> /var/log/freeradius/radius.log
(1) [log_post_auth] = ok
(1) [exec] = noop
(1) } # post-auth = ok
(1) Login OK: [XXXXXXXXXXXXX] (from client ce-popitpm-rb port 15729042
cli XX:XX:XX:XX:XX:XX)
(1) Sent Access-Accept Id 209 from 187.120.197.140:1812 to
172.17.6.2:59186 length 0
(1) MS-CHAP-Error = "\001E=691 R=1 C=6514e8f833e51125 V=2"
(1) Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K 10/10"
(1) Framed-IP-Address = 10.10.10.6
(1) Finished request
