SQLIPPOOL + LINELOG

3 Jan 2019


      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

SQLIPPOOL + LINELOG

Aurélio de Souza Ribeiro Neto