Observing a common error in Freeradius with Postgres but not justification why it happens
Ibrahim Al Mahfooz
ibrahim.nezar at sevennet.net
Sat Sep 2 10:53:02 UTC 2023
Thanks for your responses and patience and apology for the lack of details,
let me add more,
Depends what your queries are and your table sizes and so on - you say you
> have modified them but have not provided the changes or the logs or any
> postgres table metrics so no way to tell.
>
Postgres Dashboard constantly showing these metrics, from pgadmin:
- Transaction Per Second: ~ 1500 every ~ 5 seconds)
- Tuples In: ~ 100 Inserts, ~ 1400 Updates every 5 seconds, 0 deletes
- Tuples Out: Fetched ~ 1500, Returned ~ 25k every 5 seconds
- Block I/O: ~ 15-20 Reads, ~ 40k Hits
- Database Sessions: Total 20-30 sessions, Idle 20-30 sessions, Active 1-2
sessions
- Note that we have no reads from the DB, since this is not the main use
case, we just store and read rarely.
Here is the accounting part of the queries.conf file
column_list = "\
AcctSessionId, \
AcctUniqueId, \
AcctStartTime, \
AcctUpdateTime, \
AcctStopTime, \
CallingStationId, \
FramedIpAddress, \
imei, \
location"
start {
query = "\
INSERT INTO ${....acct_table1} \
(${...column_list}) \
VALUES(\
'%{Acct-Session-Id}', \
'%{Acct-Unique-Session-Id}', \
${....event_timestamp}, \
${....event_timestamp}, \
NULL, \
'%{Calling-Station-Id}', \
NULLIF('%{Framed-IP-Address}',
'')::inet, \
NULLIF('%{3GPP-IMEISV}',''), \
NULLIF('%{3GPP-User-Location-Info}',''))\
ON CONFLICT (AcctUniqueId) \
DO UPDATE \
SET \
AcctStartTime =
${....event_timestamp}, \
AcctUpdateTime =
${....event_timestamp} \
WHERE ${....acct_table1}.AcctUniqueId =
'%{Acct-Unique-Session-Id}' \
AND ${....acct_table1}.AcctStopTime IS NULL"
....
interim-update {
query = "\
UPDATE ${....acct_table1} \
SET \
FramedIPAddress =
NULLIF('%{Framed-IP-Address}', '')::inet, \
AcctUpdateTime =
${....event_timestamp}, \
location =
NULLIF('%{3GPP-User-Location-Info}','') \
WHERE AcctUniqueId =
'%{Acct-Unique-Session-Id}' \
AND AcctStopTime IS NULL"
query = "\
INSERT INTO ${....acct_table1} \
(${...column_list}) \
VALUES(\
'%{Acct-Session-Id}', \
'%{Acct-Unique-Session-Id}', \
TO_TIMESTAMP(${....event_timestamp_epoch} - %{%{Acct-Session-Time}:-0}), \
${....event_timestamp}, \
NULL, \
'%{Calling-Station-Id}', \
NULLIF('%{Framed-IP-Address}',
'')::inet, \
NULLIF('%{3GPP-IMEISV}', ''), \
NULLIF('%{3GPP-User-Location-Info}','')) \
ON CONFLICT (AcctUniqueId) \
DO NOTHING"
....
stop {
query = "\
UPDATE ${....acct_table2} \
SET \
AcctStopTime =
${....event_timestamp}, \
AcctUpdateTime =
${....event_timestamp}, \
FramedIPAddress =
NULLIF('%{Framed-IP-Address}', '')::inet, \
location =
NULLIF('%{3GPP-User-Location-Info}','') \
WHERE AcctUniqueId =
'%{Acct-Unique-Session-Id}' \
AND AcctStopTime IS NULL"
query = "\
INSERT INTO ${....acct_table1} \
(${...column_list}) \
VALUES(\
'%{Acct-Session-Id}', \
'%{Acct-Unique-Session-Id}', \
TO_TIMESTAMP(${....event_timestamp_epoch} - %{%{Acct-Session-Time}:-0}), \
${....event_timestamp}, \
${....event_timestamp}, \
'%{Calling-Station-Id}', \
NULLIF('%{Framed-IP-Address}',
'')::inet, \
NULLIF('%{3GPP-IMEISV}', ''), \
NULLIF('%{3GPP-User-Location-Info}','')) \
ON CONFLICT (AcctUniqueId) \
DO NOTHING"
....
Here is a raddebug from sample user performing start session:
(1745106) Sat Sep 2 13:44:04 2023: Debug: Received Accounting-Request Id
222 from 10.26.3.10:45939 to 172.16.17.14:1813 length 399
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Status-Type = Start
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Link-Count = 1
(1745106) Sat Sep 2 13:44:04 2023: Debug: Event-Timestamp = "Sep 2 2023
13:44:04 +03"
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Authentic = RADIUS
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Delay-Time = 0
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Multi-Session-Id =
"9755fbbc"
(1745106) Sat Sep 2 13:44:04 2023: Debug: Calling-Station-Id =
"1112223334445"
(1745106) Sat Sep 2 13:44:04 2023: Debug: Framed-IP-Address =
10.25.241.108
(1745106) Sat Sep 2 13:44:04 2023: Debug: Acct-Session-Id =
"0a1a03169755fbbc"
(1745106) Sat Sep 2 13:44:04 2023: Debug: Framed-Protocol =
GPRS-PDP-Context
(1745106) Sat Sep 2 13:44:04 2023: Debug: Called-Station-Id = "gnet"
(1745106) Sat Sep 2 13:44:04 2023: Debug: User-Name = "gnet"
(1745106) Sat Sep 2 13:44:04 2023: Debug: Service-Type = Framed-User
(1745106) Sat Sep 2 13:44:04 2023: Debug: NAS-Port-Type = Virtual
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-IMSI = "55557011234567"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-Charging-ID = 2538994620
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-PDP-Type = 0
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-Charging-Gateway-Address
= 10.26.3.106
(1745106) Sat Sep 2 13:44:04 2023: Debug:
3GPP-GPRS-Negotiated-QoS-profile = "08-4406001e84800004baf0"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-SGSN-Address = 10.26.3.22
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-GGSN-Address = 10.26.3.22
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-IMSI-MCC-MNC = "41877"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-GGSN-MCC-MNC = "41877"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-NSAPI = "6"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-Selection-Mode = "0"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-Charging-Characteristics
= "0800"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-SGSN-MCC-MNC = "41877"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-IMEISV =
"1234568712345688"
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-RAT-Type = EUTRAN
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-User-Location-Info =
0x8214f8772af814f877029bff0c
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-MS-Time-Zone = 0x2100
(1745106) Sat Sep 2 13:44:04 2023: Debug: 3GPP-Negotiated-DSCP = 18
(1745106) Sat Sep 2 13:44:04 2023: Debug: NAS-IP-Address = 10.26.3.10
(1745106) Sat Sep 2 13:44:04 2023: Debug: # Executing section preacct from
file /etc/raddb/sites-enabled/default
(1745106) Sat Sep 2 13:44:04 2023: Debug: preacct {
(1745106) Sat Sep 2 13:44:04 2023: Debug: [preprocess] = ok
(1745106) Sat Sep 2 13:44:04 2023: Debug: policy acct_unique {
(1745106) Sat Sep 2 13:44:04 2023: Debug: update request {
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # update request = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: if (("%{hex:&Class}" =~
/^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~
/^ai:([0-9a-f]{32})/i)) {
(1745106) Sat Sep 2 13:44:04 2023: Debug: EXPAND %{hex:&Class}
(1745106) Sat Sep 2 13:44:04 2023: Debug: -->
(1745106) Sat Sep 2 13:44:04 2023: Debug: EXPAND
^%{hex:&Tmp-String-9}
(1745106) Sat Sep 2 13:44:04 2023: Debug: --> ^61693a
(1745106) Sat Sep 2 13:44:04 2023: Debug: if (("%{hex:&Class}" =~
/^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~
/^ai:([0-9a-f]{32})/i)) -> FALSE
(1745106) Sat Sep 2 13:44:04 2023: Debug: else {
(1745106) Sat Sep 2 13:44:04 2023: Debug: update request {
(1745106) Sat Sep 2 13:44:04 2023: Debug: EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(1745106) Sat Sep 2 13:44:04 2023: Debug: -->
aaf13b83bdd8b7cb59846e96d174d76c
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # update request = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # else = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: update request {
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # update request = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # policy acct_unique = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: suffix: Checking for suffix
after "@"
(1745106) Sat Sep 2 13:44:04 2023: Debug: suffix: No '@' in User-Name =
"gnet", looking up realm NULL
(1745106) Sat Sep 2 13:44:04 2023: Debug: suffix: No such realm "NULL"
(1745106) Sat Sep 2 13:44:04 2023: Debug: [suffix] = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: [files] = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # preacct = ok
(1745106) Sat Sep 2 13:44:04 2023: Debug: # Executing section accounting
from file /etc/raddb/sites-enabled/default
(1745106) Sat Sep 2 13:44:04 2023: Debug: accounting {
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: EXPAND
%{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: --> type.start.query
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: Using query template 'query'
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: EXPAND %{User-Name}
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: --> gnet
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: SQL-User-Name set to 'gnet'
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: EXPAND INSERT INTO radacct
(AcctSessionId, AcctUniqueId, AcctStartTime, AcctUpdateTime, AcctStopTime,
CallingStationId, FramedIpAddress, imei, location)
VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}),
TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), NULL,
'%{Calling-Station-Id}', NULLIF('%{Framed-IP-Address}', '')::inet,
NULLIF('%{3GPP-IMEISV}',''), NULLIF('%{3GPP-User-Location-Info}',''))ON
CONFLICT (AcctUniqueId) DO UPDATE SET AcctStartTime =
TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime =
TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE radacct.AcctUniqueId
= '%{Acct-Unique-Session-Id}' AND radacct.AcctStopTime IS NULL
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: --> INSERT INTO radacct
(AcctSessionId, AcctUniqueId, AcctStartTime, AcctUpdateTime, AcctStopTime,
CallingStationId, FramedIpAddress, imei, location)
VALUES('0a1a03169755fbbc', 'aaf13b83bdd8b7cb59846e96d174d76c',
TO_TIMESTAMP(1693651444), TO_TIMESTAMP(1693651444), NULL, '1112223334445',
NULLIF('10.25.241.108', '')::inet, NULLIF('1234568712345688',''),
NULLIF('0x8214f8772af814f877029bff0c',''))ON CONFLICT (AcctUniqueId) DO
UPDATE SET AcctStartTime = TO_TIMESTAMP(1693651444), AcctUpdateTime =
TO_TIMESTAMP(1693651444) WHERE radacct.AcctUniqueId =
'aaf13b83bdd8b7cb59846e96d174d76c' AND radacct.AcctStopTime IS NULL
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: Executing query: INSERT
INTO radacct (AcctSessionId, AcctUniqueId, AcctStartTime, AcctUpdateTime,
AcctStopTime, CallingStationId, FramedIpAddress, imei, location)
VALUES('0a1a03169755fbbc', 'aaf13b83bdd8b7cb59846e96d174d76c',
TO_TIMESTAMP(1693651444), TO_TIMESTAMP(1693651444), NULL, '1112223334445',
NULLIF('10.25.241.108', '')::inet, NULLIF('1234568712345688',''),
NULLIF('0x8214f8772af814f877029bff0c',''))ON CONFLICT (AcctUniqueId) DO
UPDATE SET AcctStartTime = TO_TIMESTAMP(1693651444), AcctUpdateTime =
TO_TIMESTAMP(1693651444) WHERE radacct.AcctUniqueId =
'aaf13b83bdd8b7cb59846e96d174d76c' AND radacct.AcctStopTime IS NULL
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: SQL query returned: success
(1745106) Sat Sep 2 13:44:04 2023: Debug: sql: 1 record(s) updated
(1745106) Sat Sep 2 13:44:04 2023: Debug: [sql] = ok
(1745106) Sat Sep 2 13:44:04 2023: Debug: [exec] = noop
(1745106) Sat Sep 2 13:44:04 2023: Debug: attr_filter.accounting_response:
EXPAND %{User-Name}
(1745106) Sat Sep 2 13:44:04 2023: Debug: attr_filter.accounting_response:
--> gnet
(1745106) Sat Sep 2 13:44:04 2023: Debug: attr_filter.accounting_response:
Matched entry DEFAULT at line 12
(1745106) Sat Sep 2 13:44:04 2023: Debug:
[attr_filter.accounting_response] = updated
(1745106) Sat Sep 2 13:44:04 2023: Debug: } # accounting = updated
(1745106) Sat Sep 2 13:44:04 2023: Debug: Sent Accounting-Response Id 222
from 172.16.17.14:1813 to 10.26.3.10:45939 length 20
(1745106) Sat Sep 2 13:44:04 2023: Debug: Finished request
(1745106) Sat Sep 2 13:44:05 2023: Debug: Cleaning up request packet ID
222 with timestamp +6115 due to timer
It will also depend heavily on the storage - postgres by default does not
>
complete a commit until the data is written to disk. If you have SSD vs.
>
spinning rust it will be very different.
>
Hard drives are HDD SAS 15K EPM, and logical partition set as RAID 50 (6
disks each 300GB)
The documentation describes what this parameter is where you configure it,
> and says: "This should be 256 multiplied by the number of clients. e.g.
> With 4 clients, this number should be 1024."
>
>
> https://github.com/FreeRADIUS/freeradius-server/blob/db3d1924d9a2e8d37c43872932621f69cfdbb099/raddb/radiusd.conf.in#L224
>
Thanks for the reference, however this didn't answer the question, what
does client here means does it mean NAS client or SQL connections based on
max requests?
In our case, we set it to max_requests = 32000
How big are your tables (rows and GB) and how big are your indexes (GB)?
>
Radius DB size: 8748 MB
Current radacct table size is 3525 MB
Table Index Size: 5213 MB
I don’t think your pgbench data is very useful, it is using a different
> number of clients, and it is doing completely different queries to
> FreeRADIUS on completely different schema.
>
I was thinking of making a custom pgbench queries that mimec the accounting
inserts/update and run it against the db, do you think this will help to
give an idea about the TPS and delay time of the real case?
Are you deleting old data from the tables and vacuuming them regularly? You
> probably should be doing that, unless you know to how scale postgres
> properly.
>
Not yet, but definitely we will. In fact, we started storing accounting
data 2 weeks ago. We assumed we shouldn't face performance issues at the
early stages at least for the first couple of weeks.
Is there a rule of thumb for the DB delay response time? Perhaps it will
help me to tune the db accordingly?
More information about the Freeradius-Users
mailing list