RES: RES: Freeradius 3.0.20 Fresh Install not storing radacct logs in mysql table radacct
Jonathan Davis
jonathan at prioritycolo.com
Sat Sep 3 15:07:27 UTC 2022
Again, run a tcpdump to see what's going on. Freeradius isn't seeing
accounting packets, why is that? Are they getting dropped, or are they
not being sent?
Once you know this you can continue troubleshooting, e.g. opening ports
on a firewall, checking the NAS to figure out why it is not sending
accounting backings. As Matthew said, no amount of configuring
FreeRadius will resolve this if nothing is being received by FreeRadius.
Regards,
Jonathan Davis - Priority Colo Inc.
On 2022-09-03 10:34 a.m., Pedro Daniel Costa wrote:
> Thats the problem, o freeradius -x no accounting shown on the log all i can see is on init modules and accounting being loaded.. but when device connects.. only radipool gets updated..
>
> As shown on log below once freeradius reveices request from my radius server mikrotik device
>
>
> Ready to process requests
> (0) Received Access-Request Id 185 from 1.5.5.17:47154 to 10.5.5.200:1812 length 196
> (0) Service-Type = Framed-User
> (0) Framed-Protocol = PPP
> (0) NAS-Port = 15751547
> (0) NAS-Port-Type = Ethernet
> (0) User-Name = "ispteste200"
> (0) Calling-Station-Id = "80:8F:E8:F2:73:DB"
> (0) Called-Station-Id = "PPPOE-FIBRA"
> (0) NAS-Port-Id = "VLAN1250 - FIBRA PPPOE-PONTAL"
> (0) Acct-Session-Id = "81e05971"
> (0) CHAP-Challenge = 0xc602bf8d4fbf361e9d3746f5ae6dbe1e
> (0) CHAP-Password = 0x011b258f5bb0b1aad089ab2593de5d2fab
> (0) NAS-Identifier = "ROUTER P0NT4L PPP0E 2"
> (0) NAS-IP-Address = 1.5.5.17
> (0) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default
> (0) authorize {
> (0) chap: &control:Auth-Type := CHAP
> (0) [chap] = ok
> (0) [mschap] = noop
> (0) eap: No EAP-Message, not doing EAP
> (0) [eap] = noop
> (0) sql: EXPAND %{User-Name}
> (0) sql: --> ispteste200
> (0) sql: SQL-User-Name set to 'ispteste200'
> rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 206 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 206 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 206 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 206 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 206 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 206 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare"
> rlm_sql (sql): Opening additional connection (6), 1 of 32 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.5-10.3.34-MariaDB-0ubuntu0.20.04.1, protocol version 10
> rlm_sql (sql): Reserved connection (6)
> (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
> (0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'ispteste200' ORDER BY id
> (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'ispteste200' ORDER BY id
> (0) sql: User found in radcheck table
> (0) sql: Conditional check items matched, merging assignment check items
> (0) sql: Cleartext-Password := "123123"
> (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
> (0) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'ispteste200' ORDER BY id
> (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'ispteste200' ORDER BY id
> rlm_sql (sql): 1 of 1 connections in use. You may need to increase "spare"
> rlm_sql (sql): Opening additional connection (7), 1 of 31 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.5-10.3.34-MariaDB-0ubuntu0.20.04.1, protocol version 10
> rlm_sql (sql): Reserved connection (7)
> rlm_sql (sql): Released connection (7)
> Need 1 more connections to reach min connections (3)
> rlm_sql (sql): Opening additional connection (8), 1 of 30 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.5-10.3.34-MariaDB-0ubuntu0.20.04.1, protocol version 10
> (0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
> (0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'ispteste200' ORDER BY priority
> (0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'ispteste200' ORDER BY priority
> (0) sql: User found in the group table
> (0) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
> (0) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'fibra_50' ORDER BY id
> (0) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'fibra_50' ORDER BY id
> (0) sql: Group "fibra_50": Conditional check items matched
> (0) sql: Group "fibra_50": Merging assignment check items
> (0) sql: Framed-Protocol := PPP
> (0) sql: Pool-Name := "pool_pontal"
> (0) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
> (0) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'fibra_50' ORDER BY id
> (0) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'fibra_50' ORDER BY id
> (0) sql: Group "fibra_50": Merging reply items
> (0) sql: Mikrotik-Rate-Limit := "500M/500M"
> (0) sql: Acct-Interim-Interval := 300
> (0) sql: MS-Primary-DNS-Server := 192.168.10.10
> (0) sql: MS-Secondary-DNS-Server := 192.168.10.11
> rlm_sql (sql): Released connection (6)
> (0) [sql] = ok
> (0) [expiration] = noop
> (0) [logintime] = noop
> (0) } # authorize = ok
> (0) Found Auth-Type = CHAP
> (0) # Executing group from file /etc/freeradius/3.0/sites-enabled/default
> (0) Auth-Type CHAP {
> (0) chap: Comparing with "known good" Cleartext-Password
> (0) chap: CHAP user "ispteste200" authenticated successfully
> (0) [chap] = ok
> (0) } # Auth-Type CHAP = ok
> (0) # Executing section post-auth from file /etc/freeradius/3.0/sites-enabled/default
> (0) post-auth {
> (0) update {
> (0) No attributes updated for RHS &session-state:
> (0) } # update = noop
> (0) sql: EXPAND .query
> (0) sql: --> .query
> (0) sql: Using query template 'query'
> rlm_sql (sql): Reserved connection (6)
> (0) sql: EXPAND %{User-Name}
> (0) sql: --> ispteste200
> (0) sql: SQL-User-Name set to 'ispteste200'
> (0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
> (0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'ispteste200', '0x011b258f5bb0b1aad089ab2593de5d2fab', 'Access-Accept', '2022-09-03 10:54:19')
> (0) sql: EXPAND /var/log/freeradius/post-auth.sql
> (0) sql: --> /var/log/freeradius/post-auth.sql
> (0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'ispteste200', '0x011b258f5bb0b1aad089ab2593de5d2fab', 'Access-Accept', '2022-09-03 10:54:19')
> (0) sql: SQL query returned: success
> (0) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (6)
> (0) [sql] = ok
> rlm_sql (sql): Reserved connection (7)
> (0) sqlippool: EXPAND %{User-Name}
> (0) sqlippool: --> ispteste200
> (0) sqlippool: SQL-User-Name set to 'ispteste200'
> (0) sqlippool: EXPAND START TRANSACTION
> (0) sqlippool: --> START TRANSACTION
> (0) sqlippool: Executing query: START TRANSACTION
> (0) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE pool_key = '%{Calling-Station-Id}'
> (0) sqlippool: --> UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE pool_key = '80:8F:E8:F2:73:DB'
> (0) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE pool_key = '80:8F:E8:F2:73:DB'
> rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
> (0) sqlippool: EXPAND COMMIT
> (0) sqlippool: --> COMMIT
> (0) sqlippool: Executing query: COMMIT
> (0) sqlippool: EXPAND START TRANSACTION
> (0) sqlippool: --> START TRANSACTION
> (0) sqlippool: Executing query: START TRANSACTION
> (0) sqlippool: EXPAND SELECT framedipaddress FROM radippool WHERE pool_name = '%{control:Pool-Name}' AND expiry_time IS NULL ORDER BY RAND() LIMIT 1 FOR UPDATE
> (0) sqlippool: --> SELECT framedipaddress FROM radippool WHERE pool_name = 'pool_pontal' AND expiry_time IS NULL ORDER BY RAND() LIMIT 1 FOR UPDATE
> (0) sqlippool: Executing select query: SELECT framedipaddress FROM radippool WHERE pool_name = 'pool_pontal' AND expiry_time IS NULL ORDER BY RAND() LIMIT 1 FOR UPDATE
> (0) sqlippool: Allocated IP 100.64.20.144
> (0) 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 1600 SECOND WHERE framedipaddress = '100.64.20.144'
> (0) sqlippool: --> UPDATE radippool SET nasipaddress = '1.5.5.17', pool_key = '80:8F:E8:F2:73:DB', callingstationid = '80:8F:E8:F2:73:DB', username = 'ispteste200', expiry_time = NOW() + INTERVAL 1600 SECOND WHERE framedipaddress = '100.64.20.144'
> (0) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '1.5.5.17', pool_key = '80:8F:E8:F2:73:DB', callingstationid = '80:8F:E8:F2:73:DB', username = 'ispteste200', expiry_time = NOW() + INTERVAL 1600 SECOND WHERE framedipaddress = '100.64.20.144'
> rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
> (0) sqlippool: EXPAND COMMIT
> (0) sqlippool: --> COMMIT
> (0) sqlippool: Executing query: COMMIT
> rlm_sql (sql): Released connection (7)
> (0) 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})
> (0) sqlippool: --> Allocated IP: 100.64.20.144 from pool_pontal (did PPPOE-FIBRA cli 80:8F:E8:F2:73:DB port 15751547 user ispteste200)
> (0) [sqlippool] = ok
> (0) policy remove_reply_message_if_eap {
> (0) if (&reply:EAP-Message && &reply:Reply-Message) {
> (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
> (0) else {
> (0) [noop] = noop
> (0) } # else = noop
> (0) } # policy remove_reply_message_if_eap = noop
> (0) } # post-auth = ok
> (0) Sent Access-Accept Id 185 from 10.5.5.200:1812 to 1.5.5.17:47154 length 0
> (0) Mikrotik-Rate-Limit = "500M/500M"
> (0) Acct-Interim-Interval = 300
> (0) MS-Primary-DNS-Server = 192.168.10.10
> (0) MS-Secondary-DNS-Server = 192.168.10.11
> (0) Framed-IP-Address = 100.64.20.144
> (0) Finished request
> Waking up in 4.9 seconds.
> (0) Cleaning up request packet ID 185 with timestamp +206
> Ready to process requests
>
>
> Enviado do Email<https://go.microsoft.com/fwlink/?LinkId=550986> para Windows
>
> De: Jonathan Davis<mailto:jonathan at prioritycolo.com>
> Enviado:sábado, 3 de setembro de 2022 11:26
> Para: FreeRadius users mailing list<mailto:freeradius-users at lists.freeradius.org>
> Assunto: Re: RES: Freeradius 3.0.20 Fresh Install not storing radacct logs in mysql table radacct
>
> If you do a tcpdump on the radius server, are you seeing accounting packets arriving on port 1813 from 10.5.5.17 ?
>
>> On Sep 3, 2022, at 10:15 AM, Pedro Daniel Costa <portalnet2 at outlook.com.br> wrote:
>>
>>
>>
>> As I said, you need to configure your NAS (the device with IP 10.5.5.17)
>> to send accounting packets. No amount of configuring FreeRADIUS will fix
>> this.
>>
>>
>> Ok i think i understood now what you meant with device with ip 10.5.5.17 , you meant my hardware radius server (my mikrotik test device)
>> Yes i did check this yesterday and its enabled.. on accounting port 1813
>> -
>> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
More information about the Freeradius-Users
mailing list