Hello,
Happy New Year to everyone.
I'm trying to write in radius.log some logs from SQLIPPOOL.
I wrote this code in linelog:
linelog log_sqlippool {
destination = file
format = "%S, %{control:Module-Success-Message}"
filename = ${logdir}/radius.log
permissions = 0600
reference =
"sqlippool.%{%{control:Module-Success-Message}:-default}"
sqlippool {
exists = "Existing IP: %{reply:Framed-IP-Address} (did
%{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user
%{User-Name})"
success = "Allocated IP: %{reply:Framed-IP-Address}
from %{control:Pool-Name} (did %{Called-Station-Id} cli
%{Calling-Station-Id} port %{NAS-Port} user %{User-Name})"
clear = "Released IP %{Framed-IP-Address} (did
%{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name})"
failed = "IP Allocation FAILED from
%{control:Pool-Name} (did %{Called-Station-Id} cli
%{Calling-Station-Id} port %{NAS-Port} user %{User-Name})"
nopool = "No Pool-Name defined (did
%{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user
%{User-Name})"
}
}
And in defaults file at post-auth section insert log_sqlippool, and
here is my radiusd -X output. Look Bold Lines:
(78) Received Access-Request Id 185 from 172.17.200.30:48361 to
0.0.0.0:1812 length 201
(78) Service-Type = Framed-User
(78) Framed-Protocol = PPP
(78) NAS-Port = 15728702
(78) NAS-Port-Type = Ethernet
(78) User-Name = "testepppoe"
(78) Calling-Station-Id = "18:D6:C7:37:8B:BB"
(78) Called-Station-Id = "CE - TESTE PPPoE - 2"
(78) NAS-Port-Id = "ether2"
(78) MS-CHAP-Challenge = 0x7892fdf06d29958f
(78) MS-CHAP-Response =
0x010100000000000000000000000000000000000000000000000023768ee729e8e4849
e399d60c83535ec2e60bf87a20ddfa7
(78) NAS-Identifier = "CE-TESTE-ENCOL"
(78) NAS-IP-Address = 172.17.200.30
(78) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(78) authorize {
(78) [preprocess] = ok
(78) [chap] = noop
(78) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
(78) [mschap] = ok
(78) sql: EXPAND %{User-Name}
(78) sql: --> testepppoe
(78) sql: SQL-User-Name set to 'testepppoe'
rlm_sql (sql): Reserved connection (3)
(78) 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'
(78) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND N.nasname =
'172.17.200.30' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'testepppoe' AND
plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.200.30'
) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND M.grupocliente
= 'ALL-POPS'
(78) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND N.nasname =
'172.17.200.30' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'testepppoe' AND
plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT gw_id FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.200.30'
) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND M.grupocliente
= 'ALL-POPS'
(78) sql: User found in radcheck table
(78) sql: Conditional check items matched, merging assignment check
items
(78) sql: Simultaneous-Use := 4
(78) sql: Pool-Name := "main_pool"
(78) sql: Cleartext-Password := "testeppp1234"
(78) 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'
(78) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND N.nasname =
'172.17.200.30' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'testepppoe' AND
plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT
gw_id
FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.200.30'
) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND M.grupocliente
= 'ALL-POPS'
(78) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND N.nasname =
'172.17.200.30' AND N.gw_id = (SELECT
gateway_id FROM
mpc_lw.maclist
WHERE usuario_login = BINARY
'testepppoe' AND
plano_id NOT IN
(6,8,9,793) AND
gateway_id = ( SELECT
gw_id
FROM
mpc_freeradius.nas
WHERE nasname =
'172.17.200.30'
) 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
'testepppoe' AND M.usuario_login =
BINARY 'testepppoe' AND M.grupocliente
= 'ALL-POPS'
(78) sql: User found in radreply table, merging reply items
(78) sql: Simultaneous-Use := 4
(78) sql: Pool-Name := "main_pool"
(78) sql: Cleartext-Password := "testeppp1234"
(78) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority
(78) sql: --> SELECT groupname FROM radusergroup WHERE username =
'testepppoe' ORDER BY priority
(78) sql: Executing select query: SELECT groupname FROM radusergroup
WHERE username = 'testepppoe' ORDER BY priority
(78) sql: User found in the group table
(78) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
(78) sql: --> SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '749' ORDER BY id
(78) sql: Executing select query: SELECT id, groupname, attribute,
Value, op FROM radgroupcheck WHERE groupname = '749' ORDER BY id
(78) sql: Group "749": Conditional check items matched
(78) sql: Group "749": Merging assignment check items
(78) sql: EXPAND SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
(78) sql: --> SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '749' ORDER BY id
(78) sql: Executing select query: SELECT id, groupname, attribute,
value, op FROM radgroupreply WHERE groupname = '749' ORDER BY id
(78) sql: Group "749": Merging reply items
(78) sql: Framed-Compression := Van-Jacobson-TCP-IP
(78) sql: Framed-Protocol := PPP
(78) sql: Framed-Routing := Broadcast-Listen
(78) sql: Framed-MTU := 1500
(78) sql: Service-Type := Framed-User
(78) sql: Mikrotik-Rate-Limit := "100M/100M 100M/100M 100M/100M
10/10"
rlm_sql (sql): Released connection (3)
Need 5 more connections to reach 35 spares
rlm_sql (sql): Opening additional connection (30), 1 of 34 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.24-0ubuntu0.16.04.1-log, protocol version 10
(78) [sql] = ok
(78) [expiration] = noop
(78) [logintime] = noop
(78) pap: WARNING: Auth-Type already set. Not setting to PAP
(78) [pap] = noop
(78) } # authorize = ok
(78) Found Auth-Type = MS-CHAP
(78) # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
(78) Auth-Type MS-CHAP {
(78) mschap: Found Cleartext-Password, hashing to create NT-Password
(78) mschap: Found Cleartext-Password, hashing to create LM-Password
(78) mschap: Client is using MS-CHAPv1 with NT-Password
(78) mschap: ERROR: MS-CHAP2-Response is incorrect
(78) [mschap] = reject
(78) if (reject) {
(78) if (reject) -> TRUE
(78) if (reject) {
(78) update control {
(78) Pool-Name := "mkt_pool"
(78) } # update control = noop
(78) update reply {
(78) Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K
10/10"
(78) } # update reply = noop
(78) [ok] = ok
(78) } # if (reject) = ok
(78) } # Auth-Type MS-CHAP = ok
(78) # Executing section session from file
/usr/local/etc/raddb/sites-enabled/default
(78) session {
(78) sql: EXPAND %{User-Name}
(78) sql: --> testepppoe
(78) sql: SQL-User-Name set to 'testepppoe'
(78) sql: EXPAND SELECT COUNT(*) FROM
radacct WHERE username =
'%{SQL-User-Name}' AND
ISNULL(acctstoptime) AND framedipaddress
NOT REGEXP '^10\.'
(78) sql: --> SELECT COUNT(*) FROM
radacct WHERE username =
'testepppoe' AND
ISNULL(acctstoptime) AND framedipaddress
NOT REGEXP '^10\.'
rlm_sql (sql): Reserved connection (21)
(78) sql: Executing select query: SELECT
COUNT(*) FROM
radacct WHERE username =
'testepppoe' AND
ISNULL(acctstoptime) AND framedipaddress
NOT REGEXP '^10\.'
rlm_sql (sql): Released connection (21)
(78) [sql] = ok
(78) } # session = ok
(78) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(78) post-auth {
(78) update {
(78) No attributes updated
(78) } # update = noop
rlm_sql (sql): Reserved connection (25)
(78) sqlippool: EXPAND %{User-Name}
(78) sqlippool: --> testepppoe
(78) sqlippool: SQL-User-Name set to 'testepppoe'
(78) sqlippool: EXPAND START TRANSACTION
(78) sqlippool: --> START TRANSACTION
(78) sqlippool: Executing query: START TRANSACTION
(78) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', pool_key
= 0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND pool_key =
'%{Calling-Station-Id}'
(78) sqlippool: --> UPDATE radippool SET nasipaddress = '', pool_key
= 0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND pool_key =
'18:D6:C7:37:8B:BB'
(78) sqlippool: Executing query: UPDATE radippool SET nasipaddress =
'', pool_key = 0, callingstationid = '', username = '', expiry_time =
NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND pool_key =
'18:D6:C7:37:8B:BB'
rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
(78) sqlippool: EXPAND COMMIT
(78) sqlippool: --> COMMIT
(78) sqlippool: Executing query: COMMIT
(78) sqlippool: EXPAND START TRANSACTION
(78) sqlippool: --> START TRANSACTION
(78) sqlippool: Executing query: START TRANSACTION
(78) sqlippool: EXPAND SELECT framedipaddress FROM radippool WHERE
pool_name = '%{control:Pool-Name}' AND expiry_time IS NULL ORDER BY
(username <> '%{User-Name}'), (callingstationid <>
'%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE
(78) sqlippool: --> SELECT framedipaddress FROM radippool WHERE
pool_name = 'mkt_pool' AND expiry_time IS NULL ORDER BY (username <>
'testepppoe'), (callingstationid <> '18:D6:C7:37:8B:BB'), expiry_time
LIMIT 1 FOR UPDATE
(78) sqlippool: Executing select query: SELECT framedipaddress FROM
radippool WHERE pool_name = 'mkt_pool' AND expiry_time IS NULL ORDER
BY (username <> 'testepppoe'), (callingstationid <>
'18:D6:C7:37:8B:BB'), expiry_time LIMIT 1 FOR UPDATE
(78) sqlippool: Allocated IP 10.10.10.6
(78) 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
(78) sqlippool: --> UPDATE radippool SET nasipaddress =
'172.17.200.30', pool_key = '18:D6:C7:37:8B:BB', callingstationid =
'18:D6:C7:37:8B:BB', username = 'testepppoe', expiry_time = NOW() +
INTERVAL 3600 SECOND WHERE framedipaddress = '10.10.10.6' AND
expiry_time IS NULL
(78) sqlippool: Executing query: UPDATE radippool SET nasipaddress =
'172.17.200.30', pool_key = '18:D6:C7:37:8B:BB', callingstationid =
'18:D6:C7:37:8B:BB', username = 'testepppoe', 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
(78) sqlippool: EXPAND COMMIT
(78) sqlippool: --> COMMIT
(78) sqlippool: Executing query: COMMIT
rlm_sql (sql): Released connection (25)
(78) 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})
(78) sqlippool: --> Allocated IP: 10.10.10.6 from mkt_pool (did CE -
TESTE PPPoE - 2 cli 18:D6:C7:37:8B:BB port 15728702 user testepppoe)
(78) [sqlippool] = ok
(78) log_sqlippool: EXPAND
sqlippool.%{%{control:Module-Success-Message}:-default}
(78) log_sqlippool: --> sqlippool.Allocated IP: 10.10.10.6 from
mkt_pool (did CE - TESTE PPPoE - 2 cli 18:D6:C7:37:8B:BB port 15728702
user testepppoe)
(78) log_sqlippool: No such entry ".sqlippool.Allocated IP: 10.10.10.6
from mkt_pool (did CE - TESTE PPPoE - 2 cli 18:D6:C7:37:8B:BB port
15728702 user testepppoe)"
(78) [log_sqlippool] = noop
(78) sql: EXPAND .query
(78) sql: --> .query
(78) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (18)
(78) sql: EXPAND %{User-Name}
(78) sql: --> testepppoe
(78) sql: SQL-User-Name set to 'testepppoe'
(78) sql: EXPAND INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( '%{SQL-User-Name}',
'%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(78) sql: --> INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'testepppoe', '', 'Access-Accept', '2019-01-03
17:34:56')
(78) sql: Executing query: INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( 'testepppoe', '', 'Access-Accept',
'2019-01-03 17:34:56')
(78) sql: SQL query returned: success
(78) sql: 1 record(s) updated
rlm_sql (sql): Released connection (18)
(78) [sql] = ok
(78) [exec] = noop
(78) } # post-auth = ok
(78) Login OK: [testepppoe] (from client ce-teste-rb port 15728702 cli
18:D6:C7:37:8B:BB)
(78) Sent Access-Accept Id 185 from 0.0.0.0:1812 to 172.17.200.30:48361
length 0
(78) Framed-Compression = Van-Jacobson-TCP-IP
(78) Framed-Protocol = PPP
(78) Framed-Routing = Broadcast-Listen
(78) Framed-MTU = 1500
(78) Service-Type = Framed-User
(78) Mikrotik-Rate-Limit := "300K/2M 600K/2200K 450K/1500K 10/10"
(78) MS-CHAP-Error = "\001E=691 R=1 C=75f40ae245a21f29 V=2"
(78) Framed-IP-Address = 10.10.10.6
(78) Finished request
How can I solve this problem?
(78) log_sqlippool: No such entry ".sqlippool.Allocated IP:
10.10.10.6 from mkt_pool (did CE - TESTE PPPoE - 2 cli
18:D6:C7:37:8B:BB port 15728702 user testepppoe)"
Thanks
Aurélio
