Using "sql_session_start" does not insert a record into the radacct table.

9 Feb 2023

      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.