Re: 3.0.9 rlm_sql startup error

26 Jun 2015

      On 26 Jun 2015, at 18:25, Arran Cudbard-Bell wrote:
...
...
On Jun 26, 2015, at 1:20 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Jun 26, 2015, at 12:54 PM, Adam Hammond <adam.hammond@wicoms.com> wrote:
...
...
...
Up till now (well - up till 3.0.4) 'Sql-Group' has always just worked for me in the configuration included in each instance.
I'll make sure I set it properly from now on.
The issue is that SQL-Group does group checking against the “sql” module.  NOT against a “wicoms_sql” module.  So they could have been checking different tables, or even different databases.
Fixing it may cause problems with existing configurations, but those configurations didn’t really work right in the first place.
Actually, thinking about it, this should be trivial to fix. I'll push something…
Not sure if this is relevant, but I've renamed the variable in my queries.conf:

authorize_group_check_query = "\
        SELECT id, GroupName, Attribute, Value, op \
        FROM ${groupcheck_table} \
        WHERE GroupName = '%{wicoms_sql-Sql-Group}' \
        ORDER BY id"

authorize_group_reply_query = "\
        SELECT id, GroupName, Attribute, Value, op \
        FROM ${groupreply_table} \
        WHERE GroupName = '%{wicoms_sql-Sql-Group}' \
        ORDER BY id"

… and the server starts with no error as expected. When I send an authentication request though I get an error:

wicoms_sql: ERROR: Error creating Sql-Group attribute

Full debug:

Copyright (C) 1999-2015 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/local/share/freeradius/dictionary
including dictionary file /usr/local/share/freeradius/dictionary.dhcp
including dictionary file /usr/local/share/freeradius/dictionary.vqp
including dictionary file /etc/raddb/dictionary
including configuration file /etc/raddb/radiusd.conf
including configuration file /etc/raddb/proxy.conf
including configuration file /etc/raddb/clients.conf
including files in directory /etc/raddb/mods-enabled/
including configuration file /etc/raddb/mods-enabled/expr
including configuration file /etc/raddb/mods-enabled/sql
including configuration file /etc/raddb/mods-config/sql/main/postgresql/queries.conf
including configuration file /etc/raddb/mods-enabled/pap
including configuration file /etc/raddb/mods-enabled/attr_filter
including configuration file /etc/raddb/mods-enabled/realm
including configuration file /etc/raddb/mods-enabled/expiration
including configuration file /etc/raddb/mods-enabled/always
including files in directory /etc/raddb/policy.d/
including configuration file /etc/raddb/policy.d/dhcp
including configuration file /etc/raddb/policy.d/debug
including configuration file /etc/raddb/policy.d/operator-name
including configuration file /etc/raddb/policy.d/cui
including configuration file /etc/raddb/policy.d/abfab-tr
including configuration file /etc/raddb/policy.d/control
including configuration file /etc/raddb/policy.d/eap
including configuration file /etc/raddb/policy.d/accounting
including configuration file /etc/raddb/policy.d/canonicalization
including configuration file /etc/raddb/policy.d/filter
including files in directory /etc/raddb/sites-enabled/
including configuration file /etc/raddb/sites-enabled/test
main {
 security {
 	user = "radiusd"
 	group = "radiusd"
 	allow_core_dumps = no
 }
	name = "radiusd"
	prefix = "/usr"
	localstatedir = "/var"
	logdir = "/var/log/radius"
	run_dir = "/var/run/radiusd"
}
main {
	name = "radiusd"
	prefix = "/usr"
	localstatedir = "/var"
	sbindir = "/usr/sbin"
	logdir = "/var/log/radius"
	run_dir = "/var/run/radiusd"
	libdir = "/usr/lib64/freeradius"
	radacctdir = "/var/log/radius/radacct"
	hostname_lookups = no
	max_request_time = 30
	cleanup_delay = 5
	max_requests = 2048
	pidfile = "/var/run/radiusd/radiusd.pid"
	checkrad = "/usr/sbin/checkrad"
	debug_level = 0
	proxy_requests = yes
 log {
 	stripped_names = no
 	auth = no
 	auth_badpass = no
 	auth_goodpass = no
 	colourise = yes
 	msg_denied = "You are already logged in - access denied"
 }
 resources {
 }
 security {
 	max_attributes = 200
 	reject_delay = 0.000000
 	status_server = yes
 }
}
radiusd: #### Loading Realms and Home Servers ####
 proxy server {
 	retry_delay = 5
 	retry_count = 3
 	default_fallback = no
 	dead_time = 120
 	wake_all_if_all_dead = no
 }
 realm WICOMS {
	virtual_server = testrad
 }
 realm NULL {
	virtual_server = testrad
Please use pools instead of authhost and accthost
Please use pools instead of authhost and accthost
 }
radiusd: #### Loading Clients ####
 client 0.0.0.0/0 {
 	ipaddr = 0.0.0.0/0
 	require_message_authenticator = no
 	secret = <<< secret >>>
 	proto = "*"
  limit {
  	max_connections = 16
  	lifetime = 0
  	idle_timeout = 30
  }
 }
Debugger not attached
radiusd: #### Instantiating modules ####
  # Loaded module rlm_expr
  # Loading module "expr" from file /etc/raddb/mods-enabled/expr
  expr {
  	safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
  }
  # Loaded module rlm_sql
  # Loading module "wicoms_sql" from file /etc/raddb/mods-enabled/sql
  sql wicoms_sql {
  	driver = "rlm_sql_postgresql"
  	server = "10.0.10.31"
  	port = 5432
  	login = "wicoms_radius"
  	password = <<< secret >>>
  	radius_db = "fortitude"
  	read_groups = yes
  	read_profiles = yes
  	read_clients = no
  	delete_stale_sessions = yes
  	sql_user_name = "%{User-Name}"
  	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 = '%{wicoms_sql-Sql-Group}' ORDER BY id"
  	authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{wicoms_sql-Sql-Group}' ORDER BY id"
  	group_membership_query = "SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' ORDER BY priority"
  	safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
   accounting {
   	reference = "%{tolower:type.%{%{Acct-Status-Type}:-none}.query}"
    type {
     accounting-on {
     	query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM(AcctStartTime))), AcctTerminateCause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE AcctStopTime IS NULL AND NASIPAddress= '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND AcctStartTime <= '%S'::timestamp"
     }
     accounting-off {
     	query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM(AcctStartTime))), AcctTerminateCause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE AcctStopTime IS NULL AND NASIPAddress= '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND AcctStartTime <= '%S'::timestamp"
     }
     start {
     	query = "INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULL, 0, '%{Acct-Authentic}', '%{Connect-Info}', NULL, 0, 0, '%{Called-Station-Id}', '%{Calling-Station-Id}', NULL, '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet)"
     }
     interim-update {
     	query = "UPDATE radacct SET FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, AcctSessionTime = %{%{Acct-Session-Time}:-NULL}, AcctInterval = (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM (COALESCE(AcctUpdateTime, AcctStartTime)))), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), 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}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = COALESCE(%{%{Acct-Session-Time}:-NULL}, (%{integer:Event-Timestamp} - 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, 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, authdate) VALUES('%{User-Name}', '%{%{User-Password}:-Chap-Password}', '%{reply:Packet-Type}', NOW())"
   }
  }
rlm_sql (wicoms_sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked
Creating attribute wicoms_sql-SQL-Group
  # Loaded module rlm_pap
  # Loading module "pap" from file /etc/raddb/mods-enabled/pap
  pap {
  	normalise = yes
  }
  # Loaded module rlm_attr_filter
  # Loading module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
  attr_filter attr_filter.post-proxy {
  	filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
  	key = "%{Realm}"
  	relaxed = no
  }
  # Loading module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
  attr_filter attr_filter.pre-proxy {
  	filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
  	key = "%{Realm}"
  	relaxed = no
  }
  # Loading module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
  attr_filter attr_filter.access_reject {
  	filename = "/etc/raddb/mods-config/attr_filter/access_reject"
  	key = "%{User-Name}"
  	relaxed = no
  }
  # Loading module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
  attr_filter attr_filter.access_challenge {
  	filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
  	key = "%{User-Name}"
  	relaxed = no
  }
  # Loading module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
  attr_filter attr_filter.accounting_response {
  	filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
  	key = "%{User-Name}"
  	relaxed = no
  }
  # Loaded module rlm_realm
  # Loading module "slash" from file /etc/raddb/mods-enabled/realm
  realm slash {
  	format = "prefix"
  	delimiter = "/"
  	ignore_default = no
  	ignore_null = no
  }
  # Loading module "suffix" from file /etc/raddb/mods-enabled/realm
  realm suffix {
  	format = "suffix"
  	delimiter = "@"
  	ignore_default = no
  	ignore_null = no
  }
  # Loading module "realmpercent" from file /etc/raddb/mods-enabled/realm
  realm realmpercent {
  	format = "suffix"
  	delimiter = "%"
  	ignore_default = no
  	ignore_null = no
  }
  # Loading module "ntdomain" from file /etc/raddb/mods-enabled/realm
  realm ntdomain {
  	format = "prefix"
  	delimiter = "\"
  	ignore_default = no
  	ignore_null = no
  }
  # Loaded module rlm_expiration
  # Loading module "expiration" from file /etc/raddb/mods-enabled/expiration
  # Loaded module rlm_always
  # Loading module "reject" from file /etc/raddb/mods-enabled/always
  always reject {
  	rcode = "reject"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "fail" from file /etc/raddb/mods-enabled/always
  always fail {
  	rcode = "fail"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "ok" from file /etc/raddb/mods-enabled/always
  always ok {
  	rcode = "ok"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "handled" from file /etc/raddb/mods-enabled/always
  always handled {
  	rcode = "handled"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "invalid" from file /etc/raddb/mods-enabled/always
  always invalid {
  	rcode = "invalid"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "userlock" from file /etc/raddb/mods-enabled/always
  always userlock {
  	rcode = "userlock"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "notfound" from file /etc/raddb/mods-enabled/always
  always notfound {
  	rcode = "notfound"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "noop" from file /etc/raddb/mods-enabled/always
  always noop {
  	rcode = "noop"
  	simulcount = 0
  	mpp = no
  }
  # Loading module "updated" from file /etc/raddb/mods-enabled/always
  always updated {
  	rcode = "updated"
  	simulcount = 0
  	mpp = no
  }
 instantiate {
 }
 modules {
  # Instantiating module "wicoms_sql" from file /etc/raddb/mods-enabled/sql
   postgresql {
   	send_application_name = yes
   }
rlm_sql (wicoms_sql): Attempting to connect to database "fortitude"
rlm_sql (wicoms_sql): Initialising connection pool
   pool {
   	start = 5
   	min = 4
   	max = 32
   	spare = 3
   	uses = 0
   	lifetime = 0
   	cleanup_interval = 30
   	idle_timeout = 60
   	retry_delay = 1
   	spread = no
   }
rlm_sql (wicoms_sql): Opening additional connection (0), 1 of 32 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23442
rlm_sql (wicoms_sql): Opening additional connection (1), 1 of 31 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23443
rlm_sql (wicoms_sql): Opening additional connection (2), 1 of 30 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23444
rlm_sql (wicoms_sql): Opening additional connection (3), 1 of 29 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23445
rlm_sql (wicoms_sql): Opening additional connection (4), 1 of 28 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23446
  # Instantiating module "pap" from file /etc/raddb/mods-enabled/pap
  # Instantiating module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
  # Instantiating module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
  # Instantiating module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
  # Instantiating module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
  # Instantiating module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
  # Instantiating module "slash" from file /etc/raddb/mods-enabled/realm
  # Instantiating module "suffix" from file /etc/raddb/mods-enabled/realm
  # Instantiating module "realmpercent" from file /etc/raddb/mods-enabled/realm
  # Instantiating module "ntdomain" from file /etc/raddb/mods-enabled/realm
  # Instantiating module "expiration" from file /etc/raddb/mods-enabled/expiration
  # Instantiating module "reject" from file /etc/raddb/mods-enabled/always
  # Instantiating module "fail" from file /etc/raddb/mods-enabled/always
  # Instantiating module "ok" from file /etc/raddb/mods-enabled/always
  # Instantiating module "handled" from file /etc/raddb/mods-enabled/always
  # Instantiating module "invalid" from file /etc/raddb/mods-enabled/always
  # Instantiating module "userlock" from file /etc/raddb/mods-enabled/always
  # Instantiating module "notfound" from file /etc/raddb/mods-enabled/always
  # Instantiating module "noop" from file /etc/raddb/mods-enabled/always
  # Instantiating module "updated" from file /etc/raddb/mods-enabled/always
 } # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /etc/raddb/radiusd.conf
} # server
server realm-switch { # from file /etc/raddb/sites-enabled/test
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
} # server realm-switch
server testrad { # from file /etc/raddb/sites-enabled/test
 # Loading authenticate {...}
 # Loading authorize {...}
 # Loading accounting {...}
} # server testrad
radiusd: #### Opening IP addresses and Ports ####
listen {
  	type = "auth"
  	ipaddr = *
  	port = 31812
}
listen {
  	type = "acct"
  	ipaddr = *
  	port = 31813
}
listen {
  	type = "auth"
  	ipv6addr = ::
  	port = 31812
}
listen {
  	type = "acct"
  	ipv6addr = ::
  	port = 31813
}
Listening on auth address * port 31812 bound to server realm-switch
Listening on acct address * port 31813 bound to server realm-switch
Listening on auth address :: port 31812 bound to server realm-switch
Listening on acct address :: port 31813 bound to server realm-switch
Ready to process requests
(0) Received Access-Request Id 32 from 10.0.10.30:33643 to 10.0.10.31:31812 length 107
(0)   User-Name = "callingtest"
(0)   User-Password = "testing"
(0)   Acct-Session-Id = "5371b4ba00000007"
(0)   Calling-Station-Id = "07-08-09-04-05-06"
(0)   Called-Station-Id = "00-01-C0-12-36-88"
(0) # Executing section authorize from file /etc/raddb/sites-enabled/test
(0)   authorize {
(0) slash: Checking for prefix before "/"
(0) slash: No '/' in User-Name = "callingtest", looking up realm NULL
(0) slash: Found realm "NULL"
(0) slash: Adding Stripped-User-Name = "callingtest"
(0) slash: Adding Realm = "NULL"
(0) slash: Proxying request from user callingtest to realm NULL
(0) slash: Preparing to proxy authentication request to realm "NULL"
(0)     [slash] = updated
(0)   } # authorize = updated
Proxying to virtual server testrad
(0) # Executing section authorize from file /etc/raddb/sites-enabled/test
(0)   authorize {
(0) wicoms_sql: EXPAND %{User-Name}
(0) wicoms_sql:    --> callingtest
(0) wicoms_sql: SQL-User-Name set to 'callingtest'
rlm_sql (wicoms_sql): Closing connection (0): Hit idle_timeout, was idle for 150 seconds
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (wicoms_sql): Closing connection (1): Hit idle_timeout, was idle for 150 seconds
rlm_sql (wicoms_sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (wicoms_sql): Closing connection (2): Hit idle_timeout, was idle for 150 seconds
rlm_sql (wicoms_sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (wicoms_sql): Closing connection (3): Hit idle_timeout, was idle for 150 seconds
rlm_sql (wicoms_sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (wicoms_sql): Closing connection (4): Hit idle_timeout, was idle for 150 seconds
rlm_sql (wicoms_sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (wicoms_sql): 0 of 0 connections in use.  You  may need to increase "spare"
rlm_sql (wicoms_sql): Opening additional connection (5), 1 of 32 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23456
rlm_sql (wicoms_sql): Reserved connection (5)
(0) wicoms_sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id
(0) wicoms_sql:    --> SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = 'callingtest' ORDER BY id
(0) wicoms_sql: Executing select query: SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE Username = 'callingtest' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 4 , fields = 5
(0) wicoms_sql: User found in radcheck table
(0) wicoms_sql: Conditional check items matched, merging assignment check items
(0) wicoms_sql:   MD5-Password := 0x6165326231666361353135393439653564353466623232623865643935353735
(0) wicoms_sql:   Calling-Station-Id += "07-08-09-04-05-06"
(0) wicoms_sql:   Calling-Station-Id += "01-02-03-04-05-06"
(0) wicoms_sql:   Calling-Station-Id += "11-11-11-22-22-22"
(0) wicoms_sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id
(0) wicoms_sql:    --> SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = 'callingtest' ORDER BY id
(0) wicoms_sql: Executing select query: SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE Username = 'callingtest' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(0) wicoms_sql: EXPAND SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' ORDER BY priority
(0) wicoms_sql:    --> SELECT GroupName FROM radusergroup WHERE UserName='callingtest' ORDER BY priority
(0) wicoms_sql: Executing select query: SELECT GroupName FROM radusergroup WHERE UserName='callingtest' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 1
(0) wicoms_sql: User found in the group table
(0) wicoms_sql: ERROR: Error creating Sql-Group attribute
rlm_sql (wicoms_sql): Released connection (5)
rlm_sql (wicoms_sql): 0 of 1 connections in use.  Need more spares
rlm_sql (wicoms_sql): Opening additional connection (6), 1 of 31 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='fortitude' host='10.0.10.31' port=5432 user='wicoms_radius' password='blah' application_name='FreeRADIUS 3.0.9 - radiusd (wicoms_sql)'
Connected to database 'fortitude' on '10.0.10.31' server version 90309, protocol version 3, backend PID 23457
(0)     [wicoms_sql] = fail
(0)   } # authorize = fail
(0) Using Post-Auth-Type Reject
(0) Post-Auth-Type sub-section not found.  Ignoring.
(0) Finished internally proxied request.
(0) Clearing existing &reply: attributes
(0) Using Post-Auth-Type Reject
(0) Post-Auth-Type sub-section not found.  Ignoring.
(0) Sent Access-Reject Id 32 from 10.0.10.31:31812 to 10.0.10.30:33643 length 0
(0) Finished request