Using "sql_session_start" does not insert a record into the radacct table.
Hi everyone I am having a weird issue that can hopefully be easily resolved by someone on the group. I suspect that I may have missed a setting. No record is being inserted into the radacct table after a successful authentication with the sql_session_start queries enabled and the sites-enabled/default files has the line uncommented. debug info here below with all personalised info filtered. -- Conrad Classen FreeRADIUS Version 3.2.1 Copyright (C) 1999-2022 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /usr/share/freeradius/dictionary including dictionary file /usr/share/freeradius/dictionary.dhcp including dictionary file /usr/share/freeradius/dictionary.vqp including dictionary file /etc/freeradius/dictionary including configuration file /etc/freeradius/radiusd.conf including configuration file /etc/freeradius/mods-enabled/sql including configuration file /etc/freeradius/mods-config/sql/main/postgresql/queries.conf including files in directory /etc/freeradius/mods-enabled/ including configuration file /etc/freeradius/mods-enabled/linelog including configuration file /etc/freeradius/mods-enabled/expr including configuration file /etc/freeradius/mods-enabled/chap including configuration file /etc/freeradius/mods-enabled/expiration including configuration file /etc/freeradius/mods-enabled/date including configuration file /etc/freeradius/mods-enabled/utf8 including configuration file /etc/freeradius/mods-enabled/realm including configuration file /etc/freeradius/mods-enabled/always including configuration file /etc/freeradius/mods-enabled/attr_filter including configuration file /etc/freeradius/mods-enabled/pap including configuration file /etc/freeradius/mods-enabled/replicate including configuration file /etc/freeradius/mods-enabled/echo including configuration file /etc/freeradius/mods-enabled/mschap including configuration file /etc/freeradius/mods-enabled/unpack including configuration file /etc/freeradius/mods-enabled/ntlm_auth including configuration file /etc/freeradius/mods-enabled/detail including configuration file /etc/freeradius/mods-enabled/exec including configuration file /etc/freeradius/mods-enabled/logintime including configuration file /etc/freeradius/mods-enabled/files including configuration file /etc/freeradius/mods-enabled/preprocess including configuration file /etc/freeradius/mods-enabled/detail.log including configuration file /etc/freeradius/mods-enabled/totp including configuration file /etc/freeradius/mods-enabled/soh including configuration file /etc/freeradius/mods-enabled/sradutmp including files in directory /etc/freeradius/policy.d/ including configuration file /etc/freeradius/policy.d/moonshot-targeted-ids including configuration file /etc/freeradius/policy.d/accounting including configuration file /etc/freeradius/policy.d/abfab-tr including configuration file /etc/freeradius/policy.d/eap including configuration file /etc/freeradius/policy.d/cui including configuration file /etc/freeradius/policy.d/debug including configuration file /etc/freeradius/policy.d/rfc7542 including configuration file /etc/freeradius/policy.d/control including configuration file /etc/freeradius/policy.d/filter including configuration file /etc/freeradius/policy.d/dhcp including configuration file /etc/freeradius/policy.d/operator-name including configuration file /etc/freeradius/policy.d/canonicalization including files in directory /etc/freeradius/sites-enabled/ including configuration file /etc/freeradius/sites-enabled/default main { security { user = "freerad" group = "freerad" allow_core_dumps = no } name = "freeradius" prefix = "/usr" localstatedir = "/var" logdir = "/var/log/freeradius" run_dir = "/var/run/freeradius" } main { name = "freeradius" prefix = "/usr" localstatedir = "/var" sbindir = "/usr/sbin" logdir = "/var/log/freeradius" run_dir = "/var/run/freeradius" libdir = "/usr/lib/freeradius" radacctdir = "/var/log/freeradius/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 15 max_requests = 186000 postauth_client_lost = no pidfile = "/var/run/freeradius/freeradius.pid" checkrad = "/usr/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = yes auth_badpass = yes auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 1.000000 status_server = yes } } radiusd: #### Loading Realms and Home Servers #### radiusd: #### Loading Clients #### Debugger not attached systemd watchdog is disabled # Creating Auth-Type = mschap # Creating Auth-Type = PAP # Creating Auth-Type = CHAP # Creating Auth-Type = MS-CHAP radiusd: #### Instantiating modules #### modules { # Loaded module rlm_sql # Loading module "sql" from file /etc/freeradius/mods-enabled/sql sql { driver = "rlm_sql_postgresql" server = "10.255.0.58" port = 5432 login = "radius" password = <<< secret >>> radius_db = "dbname=radius host=10.255.0.58 port=5432 user=radius password=r4d1u5u53r" read_groups = yes read_profiles = yes read_clients = yes delete_stale_sessions = yes sql_user_name = "%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}" default_user_profile = "" client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" authorize_check_query = "SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_reply_query = "SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_group_check_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = '%{SQL-Group}' ORDER BY id" authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{SQL-Group}' ORDER BY id" group_membership_query = "SELECT GroupName FROM radusergroup_connectnet_v WHERE UserName='%{SQL-User-Name}' ORDER BY priority" simul_count_query = "SELECT COUNT(RadAcctId) FROM radacct a LEFT OUTER JOIN nasreload n USING (NASIPAddress) WHERE UserName='%{SQL-User-Name}' AND AcctStopTime IS NULL AND (a.AcctStartTime > n.ReloadTime OR n.ReloadTime IS NULL)" simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct a LEFT OUTER JOIN nasreload n USING (nasipaddress) WHERE UserName='%{SQL-User-Name}' AND AcctStopTime IS NULL AND (a.AcctStartTime > n.reloadtime OR n.reloadtime IS NULL)" safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" auto_escape = no query_timeout = 5 accounting { reference = "%{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}" type { accounting-on { query = "INSERT INTO nasreload (NASIPAddress, ReloadTime) VALUES ('%{NAS-IP-Address}', TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l})) ON CONFLICT ON (NASIPAddress) DO UPDATE SET ReloadTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l})" } accounting-off { query = "INSERT INTO nasreload (NASIPAddress, ReloadTime) VALUES ('%{NAS-IP-Address}', TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l})) ON CONFLICT ON (NASIPAddress) DO UPDATE SET ReloadTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l})" } start { query = "UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL" } interim-update { query = "UPDATE radacct SET FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctSessionTime = %{%{Acct-Session-Time}:-NULL}, AcctInterval = (%{%{integer:Event-Timestamp}:-%l} - EXTRACT(EPOCH FROM (COALESCE(AcctUpdateTime, AcctStartTime)))), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctInputOctets = (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), AcctOutputOctets = (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL" } stop { query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctSessionTime = COALESCE(%{%{Acct-Session-Time}:-NULL}, (%{%{integer:Event-Timestamp}:-%l} - EXTRACT(EPOCH FROM(AcctStartTime)))), AcctInputOctets = (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), AcctOutputOctets = (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint), AcctTerminateCause = '%{Acct-Terminate-Cause}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, ConnectInfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL" } } } post-auth { reference = ".query" query = "INSERT INTO radpostauth (username, pass, reply, calledstationid, callingstationid, authdate ) VALUES('%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%S.%M' )" } } rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked Creating attribute SQL-Group # Loaded module rlm_linelog # Loading module "linelog" from file /etc/freeradius/mods-enabled/linelog linelog { filename = "/var/log/freeradius/linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{reply:Packet-Type}:-default}" } # Loading module "log_accounting" from file /etc/freeradius/mods-enabled/linelog linelog log_accounting { filename = "/var/log/freeradius/linelog-accounting" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loaded module rlm_expr # Loading module "expr" from file /etc/freeradius/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" } # Loaded module rlm_chap # Loading module "chap" from file /etc/freeradius/mods-enabled/chap # Loaded module rlm_expiration # Loading module "expiration" from file /etc/freeradius/mods-enabled/expiration # Loaded module rlm_date # Loading module "date" from file /etc/freeradius/mods-enabled/date date { format = "%b %e %Y %H:%M:%S %Z" utc = no } # Loading module "wispr2date" from file /etc/freeradius/mods-enabled/date date wispr2date { format = "%Y-%m-%dT%H:%M:%S" utc = no } # Loaded module rlm_utf8 # Loading module "utf8" from file /etc/freeradius/mods-enabled/utf8 # Loaded module rlm_realm # Loading module "IPASS" from file /etc/freeradius/mods-enabled/realm realm IPASS { format = "prefix" delimiter = "/" ignore_default = no ignore_null = no } # Loading module "suffix" from file /etc/freeradius/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Loading module "bangpath" from file /etc/freeradius/mods-enabled/realm realm bangpath { format = "prefix" delimiter = "!" ignore_default = no ignore_null = no } # Loading module "realmpercent" from file /etc/freeradius/mods-enabled/realm realm realmpercent { format = "suffix" delimiter = "%" ignore_default = no ignore_null = no } # Loading module "ntdomain" from file /etc/freeradius/mods-enabled/realm realm ntdomain { format = "prefix" delimiter = "\\" ignore_default = no ignore_null = no } # Loaded module rlm_always # Loading module "reject" from file /etc/freeradius/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /etc/freeradius/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /etc/freeradius/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /etc/freeradius/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /etc/freeradius/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /etc/freeradius/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /etc/freeradius/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /etc/freeradius/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /etc/freeradius/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_attr_filter # Loading module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/etc/freeradius/mods-config/attr_filter/post-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/etc/freeradius/mods-config/attr_filter/pre-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/etc/freeradius/mods-config/attr_filter/access_reject" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/etc/freeradius/mods-config/attr_filter/access_challenge" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/etc/freeradius/mods-config/attr_filter/accounting_response" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.coa" from file /etc/freeradius/mods-enabled/attr_filter attr_filter attr_filter.coa { filename = "/etc/freeradius/mods-config/attr_filter/coa" key = "%{User-Name}" relaxed = no } # Loaded module rlm_pap # Loading module "pap" from file /etc/freeradius/mods-enabled/pap pap { normalise = yes } # Loaded module rlm_replicate # Loading module "replicate" from file /etc/freeradius/mods-enabled/replicate # Loaded module rlm_exec # Loading module "echo" from file /etc/freeradius/mods-enabled/echo exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = "request" output_pairs = "reply" shell_escape = yes } # Loaded module rlm_mschap # Loading module "mschap" from file /etc/freeradius/mods-enabled/mschap mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes winbind_retry_with_normalised_username = no } # Loaded module rlm_unpack # Loading module "unpack" from file /etc/freeradius/mods-enabled/unpack # Loading module "ntlm_auth" from file /etc/freeradius/mods-enabled/ntlm_auth exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } # Loaded module rlm_detail # Loading module "detail" from file /etc/freeradius/mods-enabled/detail detail { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "exec" from file /etc/freeradius/mods-enabled/exec exec { wait = no input_pairs = "request" shell_escape = yes timeout = 10 } # Loaded module rlm_logintime # Loading module "logintime" from file /etc/freeradius/mods-enabled/logintime logintime { minimum_timeout = 60 } # Loaded module rlm_files # Loading module "files" from file /etc/freeradius/mods-enabled/files files { } # Loaded module rlm_preprocess # Loading module "preprocess" from file /etc/freeradius/mods-enabled/preprocess preprocess { with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } # Loading module "auth_log" from file /etc/freeradius/mods-enabled/detail.log detail auth_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "reply_log" from file /etc/freeradius/mods-enabled/detail.log detail reply_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log detail pre_proxy_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log detail post_proxy_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loaded module rlm_totp # Loading module "totp" from file /etc/freeradius/mods-enabled/totp # Loaded module rlm_soh # Loading module "soh" from file /etc/freeradius/mods-enabled/soh soh { dhcp = yes } # Loaded module rlm_radutmp # Loading module "sradutmp" from file /etc/freeradius/mods-enabled/sradutmp radutmp sradutmp { filename = "/var/log/freeradius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } instantiate { } # Instantiating module "sql" from file /etc/freeradius/mods-enabled/sql postgresql { send_application_name = yes } rlm_sql (sql): Attempting to connect to database "dbname=radius" rlm_sql (sql): Initialising connection pool pool { start = 5 min = 3 max = 32 spare = 10 uses = 0 lifetime = 0 cleanup_interval = 30 idle_timeout = 60 retry_delay = 30 spread = no } rlm_sql (sql): Opening additional connection (0), 1 of 32 pending slots used rlm_sql_postgresql: Connecting using parameters: dbname=radius port=5432 user=XXXXX connect_timeout=5 application_name='FreeRADIUS 3.2.1 - radiusd (sql)' Connected to database 'radius' on 'aaa.bbb.ccc.ddd' server version 150001, protocol version 3, backend PID 4157105 rlm_sql (sql): Processing generate_sql_clients rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas rlm_sql (sql): Reserved connection (0) rlm_sql (sql): Executing select query: SELECT id, nasname, shortname, type, secret, server FROM nas rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 7 , fields = 6 rlm_sql (sql): Adding client 41.208.51.188/32 (cngmpvt-mtn-sec-red) to global clients list rlm_sql (jjj.kkk.lll.mmm): Client "jjj-kkk-lll-mmm" (sql) added rlm_sql (sql): Adding client 127.0.0.1/32 (localhost) to global clients list rlm_sql (127.0.0.1): Client "localhost" (sql) added rlm_sql (sql): Released connection (0) Need more connections to reach 10 spares rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used rlm_sql_postgresql: Connecting using parameters: dbname=radius port=5432 user=XXXXX connect_timeout=5 application_name='FreeRADIUS 3.2.1 - radiusd (sql)' Connected to database 'radius' on 'aaa.bbb.ccc.ddd' server version 150001, protocol version 3, backend PID 4157107 # Instantiating module "linelog" from file /etc/freeradius/mods-enabled/linelog # Instantiating module "log_accounting" from file /etc/freeradius/mods-enabled/linelog # Instantiating module "expiration" from file /etc/freeradius/mods-enabled/expiration # Instantiating module "IPASS" from file /etc/freeradius/mods-enabled/realm # Instantiating module "suffix" from file /etc/freeradius/mods-enabled/realm # Instantiating module "bangpath" from file /etc/freeradius/mods-enabled/realm # Instantiating module "realmpercent" from file /etc/freeradius/mods-enabled/realm # Instantiating module "ntdomain" from file /etc/freeradius/mods-enabled/realm # Instantiating module "reject" from file /etc/freeradius/mods-enabled/always # Instantiating module "fail" from file /etc/freeradius/mods-enabled/always # Instantiating module "ok" from file /etc/freeradius/mods-enabled/always # Instantiating module "handled" from file /etc/freeradius/mods-enabled/always # Instantiating module "invalid" from file /etc/freeradius/mods-enabled/always # Instantiating module "userlock" from file /etc/freeradius/mods-enabled/always # Instantiating module "notfound" from file /etc/freeradius/mods-enabled/always # Instantiating module "noop" from file /etc/freeradius/mods-enabled/always # Instantiating module "updated" from file /etc/freeradius/mods-enabled/always # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/access_reject # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/accounting_response # Instantiating module "attr_filter.coa" from file /etc/freeradius/mods-enabled/attr_filter reading pairlist file /etc/freeradius/mods-config/attr_filter/coa # Instantiating module "pap" from file /etc/freeradius/mods-enabled/pap # Instantiating module "mschap" from file /etc/freeradius/mods-enabled/mschap rlm_mschap (mschap): using internal authentication # Instantiating module "detail" from file /etc/freeradius/mods-enabled/detail # Instantiating module "logintime" from file /etc/freeradius/mods-enabled/logintime # Instantiating module "files" from file /etc/freeradius/mods-enabled/files # Instantiating module "preprocess" from file /etc/freeradius/mods-enabled/preprocess # Instantiating module "auth_log" from file /etc/freeradius/mods-enabled/detail.log rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output # Instantiating module "reply_log" from file /etc/freeradius/mods-enabled/detail.log # Instantiating module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log # Instantiating module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log } # modules radiusd: #### Loading Virtual Servers #### server { # from file /etc/freeradius/radiusd.conf } # server server default { # from file /etc/freeradius/sites-enabled/default # Loading authenticate {...} Compiling Auth-Type PAP for attr Auth-Type Compiling Auth-Type CHAP for attr Auth-Type Compiling Auth-Type MS-CHAP for attr Auth-Type # Loading authorize {...} # Loading preacct {...} # Loading accounting {...} # Loading session {...} # Loading post-auth {...} Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Compiling Post-Auth-Type Challenge for attr Post-Auth-Type Compiling Post-Auth-Type Client-Lost for attr Post-Auth-Type } # server default radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = * port = 0 recv_buff = 65536 limit { max_pps = 1000 max_connections = 32 lifetime = 0 idle_timeout = 10 } } listen { type = "acct" ipaddr = * port = 0 limit { max_pps = 1000 max_connections = 32 lifetime = 0 idle_timeout = 10 } } Listening on auth address * port 1812 bound to server default Listening on acct address * port 1813 bound to server default Ready to process requests (9) Received Access-Request Id 55 from jjj.kkk.lll.mmm:13856 to 192.168.0.10:1812 length 360 (9) Calling-Station-Id = "27xxxxxxxxx" (9) User-Name = "27xxxxxxxxx" (9) NAS-IP-Address = jjj.kkk.lll.mmm (9) NAS-Identifier = "nas-id-name" (9) Called-Station-Id = "nas-csid" (9) Service-Type = Framed-User (9) Framed-Protocol = GPRS-PDP-Context (9) NAS-Port-Type = Wireless-Other (9) 3GPP-IMSI = "<hidden>" (9) 3GPP-IMSI-MCC-MNC = "<hidden>" (9) 3GPP-NSAPI = "6" (9) 3GPP-Charging-ID = 0000000000 (9) 3GPP-Charging-Characteristics = "0800" (9) 3GPP-SGSN-Address = nnn.ooo.ppp.qqq (9) 3GPP-GGSN-Address = rrr.sss.ttt.uuu.vvv (9) 3GPP-RAT-Type = EUTRAN (9) 3GPP-User-Location-Info = 0x<hidden> (9) 3GPP-SGSN-MCC-MNC = "<hidden>" (9) 3GPP-GGSN-MCC-MNC = "<hidden>" (9) 3GPP-Selection-Mode = "0" (9) 3GPP-MS-Time-Zone = 0x0000 (9) 3GPP-GPRS-Negotiated-QoS-profile = "08-04060041893700129DA0" (9) 3GPP-PDP-Type = 0 (9) 3GPP-Negotiated-DSCP = 0 (9) Framed-IP-Address = 192.168.10.111 (9) NAS-Port = 1002109 (9) User-Password = "<hidden>" (9) # Executing section authorize from file /etc/freeradius/sites-enabled/default (9) authorize { (9) policy check_user_type { (9) if (&Calling-Station-Id) { (9) if (&Calling-Station-Id) -> TRUE (9) if (&Calling-Station-Id) { (9) if (&Calling-Station-Id =~ /27[[:digit:]]+/) { (9) if (&Calling-Station-Id =~ /27[[:digit:]]+/) -> TRUE (9) if (&Calling-Station-Id =~ /27[[:digit:]]+/) { (9) update request { (9) EXPAND %{Calling-Station-Id} (9) --> 27000000000 (9) &User-Name := 27000000000 (9) &User-Password := "<hidden>" (9) &CHAP-Challenge !* ANY (9) &CHAP-Password !* ANY (9) &MS-CHAP-Challenge !* ANY (9) &MS-CHAP2-Response !* ANY (9) } # update request = noop (9) update reply { (9) EXPAND %{Calling-Station-Id} (9) --> 27000000000 (9) &Calling-Station-Id := 27000000000 (9) } # update reply = noop (9) update control { (9) &Cleartext-Password := 'void' (9) } # update control = noop (9) } # if (&Calling-Station-Id =~ /27[[:digit:]]+/) = noop (9) ... skipping else: Preceding "if" was taken (9) } # if (&Calling-Station-Id) = noop (9) } # policy check_user_type = noop (9) policy filter_username { (9) if (&User-Name) { (9) if (&User-Name) -> TRUE (9) if (&User-Name) { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@[^@]*@/ ) { (9) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (9) if (&User-Name =~ /\.\./ ) { (9) if (&User-Name =~ /\.\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\.$/) { (9) if (&User-Name =~ /\.$/) -> FALSE (9) if (&User-Name =~ /@\./) { (9) if (&User-Name =~ /@\./) -> FALSE (9) } # if (&User-Name) = noop (9) } # policy filter_username = noop (9) policy filter_password { (9) if (&User-Password && (&User-Password != "%{string:User-Password}")) { (9) EXPAND %{string:User-Password} (9) --> void (9) if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (9) } # policy filter_password = noop (9) [preprocess] = ok (9) [chap] = noop (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "27000000000", looking up realm NULL (9) suffix: No such realm "NULL" (9) [suffix] = noop (9) [files] = noop (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' rlm_sql (sql): Reserved connection (4) (9) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id (9) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = '27000000000' ORDER BY id (9) sql: Executing select query: SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = '27000000000' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 5 (9) sql: User found in radcheck table (9) sql: Conditional check items matched, merging assignment check items (9) sql: Calling-Station-Id := "27000000000" (9) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id (9) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = '27000000000' ORDER BY id (9) sql: Executing select query: SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = '27000000000' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 0 , fields = 5 (9) sql: EXPAND SELECT GroupName FROM radusergroup_connectnet_v WHERE UserName='%{SQL-User-Name}' ORDER BY priority (9) sql: --> SELECT GroupName FROM radusergroup_connectnet_v WHERE UserName='27000000000' ORDER BY priority (9) sql: Executing select query: SELECT GroupName FROM radusergroup_connectnet_v WHERE UserName='27000000000' ORDER BY priority rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 1 (9) sql: User found in the group table (9) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = '%{SQL-Group}' ORDER BY id (9) sql: --> SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'GROUP_NAME' ORDER BY id (9) sql: Executing select query: SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'GROUP_NAME' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 4 , fields = 5 (9) sql: Group "APN-NAME": Conditional check items matched (9) sql: Group "APN-NAME": Merging assignment check items (9) sql: Cleartext-Password := "<hidden>" (9) sql: Simultaneous-Use := 1 (9) sql: Framed-Protocol := GPRS-PDP-Context (9) sql: Called-Station-Id := "nas-csid" (9) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{SQL-Group}' ORDER BY id (9) sql: --> SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'GROUP_NAME' ORDER BY id (9) sql: Executing select query: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'GROUP_NAME' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 9 , fields = 5 (9) sql: Group "GROUP_NAME": Merging reply items (9) sql: Session-Timeout := 86400 (9) sql: Idle-Timeout := 0 (9) sql: Service-Type := Framed-User (9) sql: Framed-IP-Netmask := 255.255.255.255 (9) sql: MS-Primary-DNS-Server := 8.8.8.8 (9) sql: MS-Secondary-DNS-Server := 8.8.4.4 (9) sql: Framed-IP-Netmask := 255.255.255.255 (9) sql: Framed-MTU := 1500 (9) sql: Fall-Through := No rlm_sql (sql): Released connection (4) Need more connections to reach 10 spares rlm_sql (sql): Opening additional connection (6), 1 of 26 pending slots used rlm_sql_postgresql: Connecting using parameters: dbname=radius port=5432 user=XXXXX connect_timeout=5 application_name='FreeRADIUS 3.2.1 - radiusd (sql)' Connected to database 'radius' on server version 150001, protocol version 3, backend PID 4157108 (9) [sql] = ok (9) [expiration] = noop (9) [logintime] = noop (9) [pap] = updated (9) } # authorize = updated (9) Found Auth-Type = PAP (9) # Executing group from file /etc/freeradius/sites-enabled/default (9) Auth-Type PAP { (9) pap: Login attempt with password (9) pap: Comparing with "known good" Cleartext-Password (9) pap: User authenticated successfully (9) [pap] = ok (9) } # Auth-Type PAP = ok (9) # Executing section session from file /etc/freeradius/sites-enabled/default (9) session { (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' rlm_sql (sql): Reserved connection (0) (9) sql: EXPAND SELECT COUNT(RadAcctId) FROM radacct a LEFT OUTER JOIN nasreload n USING (NASIPAddress) WHERE UserName='%{SQL-User-Name}' AND AcctStopTime IS NULL AND (a.AcctStartTime > n.ReloadTime OR n.ReloadTime IS NULL) (9) sql: --> SELECT COUNT(RadAcctId) FROM radacct a LEFT OUTER JOIN nasreload n USING (NASIPAddress) WHERE UserName='27000000000' AND AcctStopTime IS NULL AND (a.AcctStartTime > n.ReloadTime OR n.ReloadTime IS NULL) (9) sql: Executing select query: SELECT COUNT(RadAcctId) FROM radacct a LEFT OUTER JOIN nasreload n USING (NASIPAddress) WHERE UserName='27000000000' AND AcctStopTime IS NULL AND (a.AcctStartTime > n.ReloadTime OR n.ReloadTime IS NULL) rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 1 rlm_sql (sql): Released connection (0) (9) [sql] = ok (9) } # session = ok (9) # Executing section post-auth from file /etc/freeradius/sites-enabled/default (9) post-auth { (9) if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) { (9) if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) -> FALSE (9) update { (9) No attributes updated for RHS &session-state: (9) } # update = noop (9) policy sql_session_start.post-auth { (9) policy acct_unique { (9) update request { (9) &Tmp-String-9 := "cnnet:" (9) } # update request = noop (9) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) { (9) EXPAND %{hex:&Class} (9) --> (9) EXPAND ^%{hex:&Tmp-String-9} (9) --> ^636e6e65743a (9) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) -> FALSE (9) else { (9) update request { (9) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (9) --> 7fc6a73a5dc5f8844e53d1534e63691a (9) &Acct-Unique-Session-Id := 7fc6a73a5dc5f8844e53d1534e63691a (9) } # update request = noop (9) } # else = noop (9) update request { (9) &Tmp-String-9 !* ANY (9) } # update request = noop (9) } # policy acct_unique = noop (9) update request { (9) &Acct-Status-Type := Start (9) } # update request = noop (9) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query} (9) sql: --> type.start.query (9) sql: Using query template 'query' rlm_sql (sql): Reserved connection (5) (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' (9) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL (9) sql: --> UPDATE radacct SET AcctSessionId = '', AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a', AcctAuthentic = '', ConnectInfo_start = '', ServiceType = 'Framed-User', FramedProtocol = 'GPRS-PDP-Context', FramedIPAddress = NULLIF('10.226.166.197', '')::inet, FramedIPv6Address = NULLIF('', '')::inet, FramedIPv6Prefix = NULLIF('', '')::inet, FramedInterfaceId = NULLIF('', ''), DelegatedIPv6Prefix = NULLIF('', '')::inet, AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789) WHERE AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a' AND AcctStopTime IS NULL (9) sql: Executing query: UPDATE radacct SET AcctSessionId = '', AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a', AcctAuthentic = '', ConnectInfo_start = '', ServiceType = 'Framed-User', FramedProtocol = 'GPRS-PDP-Context', FramedIPAddress = NULLIF('10.226.166.197', '')::inet, FramedIPv6Address = NULLIF('', '')::inet, FramedIPv6Prefix = NULLIF('', '')::inet, FramedInterfaceId = NULLIF('', ''), DelegatedIPv6Prefix = NULLIF('', '')::inet, AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789) WHERE AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a' AND AcctStopTime IS NULL rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 (9) sql: SQL query returned: success (9) sql: 0 record(s) updated (9) sql: Trying next query... (9) sql: EXPAND UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), ConnectInfo_start = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' (9) sql: --> UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789), ConnectInfo_start = '' WHERE AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a' (9) sql: Executing query: UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789), ConnectInfo_start = '' WHERE AcctUniqueId = '7fc6a73a5dc5f8844e53d1534e63691a' rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 (9) sql: SQL query returned: success (9) sql: 0 record(s) updated (9) sql: No additional queries configured rlm_sql (sql): Released connection (5) (9) [sql.accounting] = noop (9) } # policy sql_session_start.post-auth = noop (9) sql: EXPAND .query (9) sql: --> .query (9) sql: Using query template 'query' rlm_sql (sql): Reserved connection (1) (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' (9) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, calledstationid, callingstationid, authdate ) VALUES('%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%S.%M' ) (9) sql: --> INSERT INTO radpostauth (username, pass, reply, calledstationid, callingstationid, authdate ) VALUES('27000000000', 'void', 'Access-Accept', 'connectnet.net', '27000000000', '2023-02-09 12:33:09.046870' ) (9) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, calledstationid, callingstationid, authdate ) VALUES('27000000000', 'void', 'Access-Accept', 'connectnet.net', '27000000000', '2023-02-09 12:33:09.046870' ) rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 1 (9) sql: SQL query returned: success (9) sql: 1 record(s) updated rlm_sql (sql): Released connection (1) (9) [sql] = ok (9) [exec] = noop (9) policy insert_acct_class { (9) update reply { (9) EXPAND ai:%{md5:%t,%{Packet-Src-Port},%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}},%{NAS-IP-Address},%{Calling-Station-ID},%{User-Name},%{session-state:User-Name} } (9) --> ai:38988ce3f4859a0670b0522ecb21a9e0 (9) &Class = 0x636e6e65743a3338393838636533663438353961303637306230353232656362323161396530 (9) } # update reply = noop (9) } # policy insert_acct_class = noop (9) } # post-auth = ok (9) Login OK: [27000000000] (from client VCM-CN-NET-APN-NAS1 port 1002109 cli 27000000000) (9) Sent Access-Accept Id 55 from 192.168.0.10:1812 to aaa.bbb.ccc.ddd:13856 length 137 (9) Calling-Station-Id = "27000000000" (9) Session-Timeout = 86400 (9) Idle-Timeout = 0 (9) Service-Type = Framed-User (9) Framed-IP-Netmask = 255.255.255.255 (9) MS-Primary-DNS-Server = 8.8.8.8 (9) MS-Secondary-DNS-Server = 8.8.4.4 (9) Framed-IP-Netmask = 255.255.255.255 (9) Framed-MTU = 1500 (9) Class = 0x636e6e65743a3338393838636533663438353961303637306230353232656362323161396530 (9) Finished request Waking up in 14.9 seconds. (16) Received Accounting-Request Id 138 from aaa.bbb.ccc.ddd:13216 to 192.168.0.10:1813 length 468 (16) User-Name = "27000000000" (16) Calling-Station-Id = "27000000000" (16) NAS-IP-Address = aaa.bbb.ccc.ddd (16) Acct-Status-Type = Start (16) NAS-Identifier = "nas-id-name" (16) Service-Type = Framed-User (16) Framed-Protocol = GPRS-PDP-Context (16) NAS-Port-Type = Wireless-Other (16) 3GPP-IMSI = "<hidden>" (16) 3GPP-IMSI-MCC-MNC = "<hidden>" (16) 3GPP-NSAPI = "5" (16) 3GPP-Selection-Mode = "0" (16) 3GPP-Charging-ID = 0000000000 (16) 3GPP-GPRS-Negotiated-QoS-profile = "99-136212739673737405FFFF" (16) 3GPP-Charging-Characteristics = "0800" (16) Called-Station-Id = "nas-csid" (16) 3GPP-GGSN-MCC-MNC = "<hidden>" (16) 3GPP-Negotiated-DSCP = 0 (16) 3GPP-RAT-Type = GERAN (16) 3GPP-IMEISV = "<hidden>" (16) 3GPP-PDP-Type = 0 (16) Acct-Session-Id = "C42EA1E54341140D" (16) 3GPP-SGSN-Address = jjj.kkk.lll.mmm (16) 3GPP-GGSN-Address = nnn.ooo.ppp.qqq (16) Acct-Authentic = RADIUS (16) Class = 0x636e6e65743a3235336466303333623266316663646662313132396562396434343563643634 (16) Acct-Multi-Session-Id = "C42EA1E54341140D" (16) Framed-MTU = 1500 (16) 3GPP-User-Location-Info = 0x<hidden> (16) 3GPP-SGSN-MCC-MNC = "<hidden>" (16) Event-Timestamp = "Feb 9 2023 12:33:09 SAST" (16) Framed-IP-Address = 192.168.10.111 (16) NAS-Port = 829926 (16) # Executing section preacct from file /etc/freeradius/sites-enabled/default (16) preacct { (16) policy check_user_type { (16) if (&Calling-Station-Id) { (16) if (&Calling-Station-Id) -> TRUE (16) if (&Calling-Station-Id) { (16) if (&Calling-Station-Id =~ /27[[:digit:]]+/) { (16) if (&Calling-Station-Id =~ /27[[:digit:]]+/) -> TRUE (16) if (&Calling-Station-Id =~ /27[[:digit:]]+/) { (16) update request { (16) EXPAND %{Calling-Station-Id} (16) --> 27000000000 (16) &User-Name := 27000000000 (16) &User-Password := "void" (16) &CHAP-Challenge !* ANY (16) &CHAP-Password !* ANY (16) &MS-CHAP-Challenge !* ANY (16) &MS-CHAP2-Response !* ANY (16) } # update request = noop (16) update reply { (16) EXPAND %{Calling-Station-Id} (16) --> 27000000000 (16) &Calling-Station-Id := 27000000000 (16) } # update reply = noop (16) update control { (16) &Cleartext-Password := 'void' (16) } # update control = noop (16) } # if (&Calling-Station-Id =~ /27[[:digit:]]+/) = noop (16) ... skipping else: Preceding "if" was taken (16) } # if (&Calling-Station-Id) = noop (16) } # policy check_user_type = noop (16) [preprocess] = ok (16) update request { (16) EXPAND %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}} (16) --> 1675938789 (16) &FreeRADIUS-Acct-Session-Start-Time = Feb 9 2023 12:33:09 SAST (16) } # update request = noop (16) policy acct_unique { (16) update request { (16) &Tmp-String-9 := "cnnet:" (16) } # update request = noop (16) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) { (16) EXPAND %{hex:&Class} (16) --> 636e6e65743a3235336466303333623266316663646662313132396562396434343563643634 (16) EXPAND ^%{hex:&Tmp-String-9} (16) --> ^636e6e65743a (16) EXPAND %{string:&Class} (16) --> cnnet:253df033b2f1fcdfb1129eb9d445cd64 (16) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) -> TRUE (16) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) { (16) update request { (16) EXPAND %{md5:%{1},%{Acct-Session-ID}} (16) --> 45447ac6583ad4d69a965e7ba426567c (16) &Acct-Unique-Session-Id := 45447ac6583ad4d69a965e7ba426567c (16) } # update request = noop (16) } # if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^cnnet:([0-9a-f]{32})/i)) = noop (16) ... skipping else: Preceding "if" was taken (16) update request { (16) &Tmp-String-9 !* ANY (16) } # update request = noop (16) } # policy acct_unique = noop (16) suffix: Checking for suffix after "@" (16) suffix: No '@' in User-Name = "27000000000", looking up realm NULL (16) suffix: No such realm "NULL" (16) [suffix] = noop (16) } # preacct = ok (16) # Executing section accounting from file /etc/freeradius/sites-enabled/default (16) accounting { (16) sradutmp: EXPAND /var/log/freeradius/sradutmp (16) sradutmp: --> /var/log/freeradius/sradutmp (16) sradutmp: EXPAND %{User-Name} (16) sradutmp: --> 27000000000 (16) [sradutmp] = ok (16) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query} (16) sql: --> type.start.query (16) sql: Using query template 'query' rlm_sql (sql): Reserved connection (5) (16) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (16) sql: --> 27000000000 (16) sql: SQL-User-Name set to '27000000000' (16) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL (16) sql: --> UPDATE radacct SET AcctSessionId = 'C42EA1E54341140D', AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c', AcctAuthentic = 'RADIUS', ConnectInfo_start = '', ServiceType = 'Framed-User', FramedProtocol = 'GPRS-PDP-Context', FramedIPAddress = NULLIF('172.20.182.148', '')::inet, FramedIPv6Address = NULLIF('', '')::inet, FramedIPv6Prefix = NULLIF('', '')::inet, FramedInterfaceId = NULLIF('', ''), DelegatedIPv6Prefix = NULLIF('', '')::inet, AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789) WHERE AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c' AND AcctStopTime IS NULL (16) sql: Executing query: UPDATE radacct SET AcctSessionId = 'C42EA1E54341140D', AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c', AcctAuthentic = 'RADIUS', ConnectInfo_start = '', ServiceType = 'Framed-User', FramedProtocol = 'GPRS-PDP-Context', FramedIPAddress = NULLIF('172.20.182.148', '')::inet, FramedIPv6Address = NULLIF('', '')::inet, FramedIPv6Prefix = NULLIF('', '')::inet, FramedInterfaceId = NULLIF('', ''), DelegatedIPv6Prefix = NULLIF('', '')::inet, AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789) WHERE AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c' AND AcctStopTime IS NULL rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 (16) sql: SQL query returned: success (16) sql: 0 record(s) updated (16) sql: Trying next query... (16) sql: EXPAND UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), ConnectInfo_start = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' (16) sql: --> UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789), ConnectInfo_start = '' WHERE AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c' (16) sql: Executing query: UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(1675938789), AcctUpdateTime = TO_TIMESTAMP(1675938789), ConnectInfo_start = '' WHERE AcctUniqueId = '45447ac6583ad4d69a965e7ba426567c' rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 (16) sql: SQL query returned: success (16) sql: 0 record(s) updated (16) sql: No additional queries configured rlm_sql (sql): Released connection (5) (16) [sql] = noop (16) [exec] = noop (16) attr_filter.accounting_response: EXPAND %{User-Name} (16) attr_filter.accounting_response: --> 27000000000 (16) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (16) [attr_filter.accounting_response] = updated (16) } # accounting = updated (16) Sent Accounting-Response Id 138 from 192.168.0.10:1813 to aaa.bbb.ccc.ddd:13216 length 20 (16) Finished request (16) Cleaning up request packet ID 138 with timestamp +1 due to done Waking up in 14.6 seconds.
On Feb 9, 2023, at 7:26 AM, Conrad Classen <conrad.classen@gmail.com> wrote:
No record is being inserted into the radacct table after a successful authentication with the sql_session_start queries enabled and the sites-enabled/default files has the line uncommented. ... (9) Received Access-Request Id 55 from jjj.kkk.lll.mmm:13856 to 192.168.0.10:1812 length 360
(9) Calling-Station-Id = "27xxxxxxxxx"
OK.... having the debug output double-spaced doesn't help. But whatever.
(9) # Executing section post-auth from file /etc/freeradius/sites-enabled/default ... (9) policy sql_session_start.post-auth {
It's running the sql_session_start policy, which is good.
(9) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query} (9) sql: --> type.start.query
And it's using the "start" query.
(9) sql: Using query template 'query' rlm_sql (sql): Reserved connection (5) (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' (9) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL
Why is doing an "update" instead of an "insert" ? The only reason is that you've edited the queries.conf file, and broken it. The default configuration has an "insert" as the first query. It works. Why did you change that?
rlm_sql_postgresql: query affected rows = 0
Since there's no existing row, the UPDATE doesn't update anything. This makes sense.
(9) sql: SQL query returned: success (9) sql: 0 record(s) updated (9) sql: Trying next query...
Which is what it's supposed to do. And why the first query in the default configuration is an INSERT.
(16) Received Accounting-Request Id 138 from aaa.bbb.ccc.ddd:13216 to 192.168.0.10:1813 length 468
And then when it receives an accounting request, the same thing happens. Why did you edit the default queries and break them? If you're editing the queries, you should first understand what they do. And if you edit them, you shouldn't be surprised at how they work. You should understand them before making random changes to the configuration. Use the default queries in mods-config/sql/main/postgresql/queries.conf. They work. The configuration you created doesn't work. Alan DeKok.
Hi Alan Thanks In terms of disabling a query, I was following the instructions to implement the change to move the - character from the lower query variable to the one above it, i.e. from the 2nd block to the first block in sections of the accounting queries. # # When using "sql_session_start", you should comment out # the previous query, and enable this one. # # Just change the previous query to "-query", # and this one to "query". The previous one # will be ignored, and this one will be # enabled. Thanks, and much appreciated. Conrad I will restore the original one and try again to implement the "sql_session_start" On 2023/02/09 16:41, Alan DeKok wrote:
On Feb 9, 2023, at 7:26 AM, Conrad Classen<conrad.classen@gmail.com> wrote:
No record is being inserted into the radacct table after a successful authentication with the sql_session_start queries enabled and the sites-enabled/default files has the line uncommented. ... (9) Received Access-Request Id 55 from jjj.kkk.lll.mmm:13856 to 192.168.0.10:1812 length 360
(9) Calling-Station-Id = "27xxxxxxxxx" OK.... having the debug output double-spaced doesn't help. But whatever. (9) # Executing section post-auth from file /etc/freeradius/sites-enabled/default ... (9) policy sql_session_start.post-auth { It's running the sql_session_start policy, which is good.
(9) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query} (9) sql: --> type.start.query And it's using the "start" query.
(9) sql: Using query template 'query' rlm_sql (sql): Reserved connection (5) (9) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-none}} (9) sql: --> 27000000000 (9) sql: SQL-User-Name set to '27000000000' (9) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, FramedIPv6Address = NULLIF('%{Framed-IPv6-Address}', '')::inet, FramedIPv6Prefix = NULLIF('%{Framed-IPv6-Prefix}', '')::inet, FramedInterfaceId = NULLIF('%{Framed-Interface-Id}', ''), DelegatedIPv6Prefix = NULLIF('%{Delegated-IPv6-Prefix}', '')::inet, AcctStartTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}), AcctUpdateTime = TO_TIMESTAMP(%{%{integer:Event-Timestamp}:-%l}) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL Why is doing an "update" instead of an "insert" ?
The only reason is that you've edited the queries.conf file, and broken it. The default configuration has an "insert" as the first query. It works.
Why did you change that?
rlm_sql_postgresql: query affected rows = 0 Since there's no existing row, the UPDATE doesn't update anything. This makes sense.
(9) sql: SQL query returned: success (9) sql: 0 record(s) updated (9) sql: Trying next query... Which is what it's supposed to do. And why the first query in the default configuration is an INSERT.
(16) Received Accounting-Request Id 138 from aaa.bbb.ccc.ddd:13216 to 192.168.0.10:1813 length 468 And then when it receives an accounting request, the same thing happens.
Why did you edit the default queries and break them?
If you're editing the queries, you should first understand what they do. And if you edit them, you shouldn't be surprised at how they work. You should understand them before making random changes to the configuration.
Use the default queries in mods-config/sql/main/postgresql/queries.conf. They work. The configuration you created doesn't work.
Alan DeKok.
- List info/subscribe/unsubscribe? Seehttp://www.freeradius.org/list/users.html
On Feb 9, 2023, at 10:15 AM, Conrad Classen <conrad.classen@gmail.com> wrote:
In terms of disabling a query, I was following the instructions to implement the change to move the - character from the lower query variable to the one above it, i.e. from the 2nd block to the first block in sections of the accounting queries.
Hmm.. I'll go double-check that. Alan DeKok.
Hi Alan Any update on your checking? Am I misunderstanding the instructions in the queries.conf file. I need to have the accounting record created at the end of the Access-Request block by the post-accounting due to very fast requests being made by SIM devices to the NAS. Thanks Conrad On 2023/02/09 17:16, Alan DeKok wrote:
On Feb 9, 2023, at 10:15 AM, Conrad Classen<conrad.classen@gmail.com> wrote:
In terms of disabling a query, I was following the instructions to implement the change to move the - character from the lower query variable to the one above it, i.e. from the 2nd block to the first block in sections of the accounting queries. Hmm.. I'll go double-check that.
Alan DeKok.
- List info/subscribe/unsubscribe? Seehttp://www.freeradius.org/list/users.html
On Feb 10, 2023, at 6:16 AM, Conrad Classen <conrad.classen@gmail.com> wrote:
Any update on your checking? Am I misunderstanding the instructions in the queries.conf file.
We don't always put complex fixes into the server immediately. Sometimes it takes time. Especially when this is free software...
I need to have the accounting record created at the end of the Access-Request block by the post-accounting due to very fast requests being made by SIM devices to the NAS.
The configuration files are editable text for a reason: they can be edited for your local configuration. You're free to investigate the problem yourself, and to propose fixes. Or, to edit the configuration files and come up with a different fix which works in your environment. Alan DeKok.
participants (2)
-
Alan DeKok -
Conrad Classen