FreeRADIUS and Postgres annoyance
Joe Warren-Meeks
joe.warren-meeks at aggregator.tv
Tue Aug 8 11:40:05 CEST 2006
radiusd: FreeRADIUS Version 1.1.2, for host , built on Jul 27 2006 at
16:42:40
Linux auth2 2.6.15-23-server #1 SMP Tue May 23 15:10:35 UTC 2006 i686
GNU/Linux
Hey there,
I had radiusd working nicely with MySQL, but apparently we have to
use Postgres, which is fine.. Recompiled it with postgres support and
I have it talking to the db, in that it successfully opens up 4
connections to the database.
I've also setup postgresql.conf too, looks ok..
However, when I try to authenticate, the DB isn't returning any
results. I can take the query string and run it from psql and get the
right result, but radiusd doesn't seem to get the answer.
radius=> SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = 'joetest' ORDER BY id;
id | username | attribute | value | op
----+----------+-----------+---------+----
3 | joetest | Password | letmein | ==
(1 row)
radius=>
(a log is appended to the end, showing the output of radiusd -Xx)
On a side note, I also can't see where to configure radiusd to use
the nas table to get its list of clients from, pointers?)
Thanks for any help I can get
-- joe.
Tue Aug 8 10:33:12 2006 : Info: Starting - reading configuration
files ...
Tue Aug 8 10:33:12 2006 : Debug: reread_config: reading radiusd.conf
Tue Aug 8 10:33:12 2006 : Debug: Config: including file: /usr/
local/freeradius/etc/raddb/clients.conf
Tue Aug 8 10:33:12 2006 : Debug: Config: including file: /usr/
local/freeradius/etc/raddb/snmp.conf
Tue Aug 8 10:33:12 2006 : Debug: Config: including file: /usr/
local/freeradius/etc/raddb/eap.conf
Tue Aug 8 10:33:12 2006 : Debug: Config: including file: /usr/
local/freeradius/etc/raddb/postgresql.conf
Tue Aug 8 10:33:12 2006 : Debug: main: prefix = "/usr/local/
freeradius"
Tue Aug 8 10:33:12 2006 : Debug: main: localstatedir = "/usr/local/
freeradius/var"
Tue Aug 8 10:33:12 2006 : Debug: main: logdir = "/usr/local/
freeradius/var/log/radius"
Tue Aug 8 10:33:12 2006 : Debug: main: libdir = "/usr/local/
freeradius/lib"
Tue Aug 8 10:33:12 2006 : Debug: main: radacctdir = "/usr/local/
freeradius/var/log/radius/radacct"
Tue Aug 8 10:33:12 2006 : Debug: main: hostname_lookups = no
Tue Aug 8 10:33:12 2006 : Debug: main: max_request_time = 30
Tue Aug 8 10:33:12 2006 : Debug: main: cleanup_delay = 5
Tue Aug 8 10:33:12 2006 : Debug: main: max_requests = 1024
Tue Aug 8 10:33:12 2006 : Debug: main: delete_blocked_requests = 0
Tue Aug 8 10:33:12 2006 : Debug: main: port = 0
Tue Aug 8 10:33:12 2006 : Debug: main: allow_core_dumps = no
Tue Aug 8 10:33:12 2006 : Debug: main: log_stripped_names = no
Tue Aug 8 10:33:12 2006 : Debug: main: log_file = "/usr/local/
freeradius/var/log/radius/radius.log"
Tue Aug 8 10:33:12 2006 : Debug: main: log_auth = no
Tue Aug 8 10:33:12 2006 : Debug: main: log_auth_badpass = no
Tue Aug 8 10:33:12 2006 : Debug: main: log_auth_goodpass = no
Tue Aug 8 10:33:12 2006 : Debug: main: pidfile = "/usr/local/
freeradius/var/run/radiusd/radiusd.pid"
Tue Aug 8 10:33:12 2006 : Debug: main: user = "nobody"
Tue Aug 8 10:33:12 2006 : Debug: main: group = "nogroup"
Tue Aug 8 10:33:12 2006 : Debug: main: usercollide = no
Tue Aug 8 10:33:12 2006 : Debug: main: lower_user = "no"
Tue Aug 8 10:33:12 2006 : Debug: main: lower_pass = "no"
Tue Aug 8 10:33:12 2006 : Debug: main: nospace_user = "no"
Tue Aug 8 10:33:12 2006 : Debug: main: nospace_pass = "no"
Tue Aug 8 10:33:12 2006 : Debug: main: checkrad = "/usr/local/
freeradius/sbin/checkrad"
Tue Aug 8 10:33:12 2006 : Debug: main: proxy_requests = no
Tue Aug 8 10:33:12 2006 : Debug: security: max_attributes = 200
Tue Aug 8 10:33:12 2006 : Debug: security: reject_delay = 1
Tue Aug 8 10:33:12 2006 : Debug: security: status_server = no
Tue Aug 8 10:33:12 2006 : Debug: main: debug_level = 0
Tue Aug 8 10:33:12 2006 : Debug: read_config_files: reading dictionary
Tue Aug 8 10:33:12 2006 : Debug: read_config_files: reading naslist
Tue Aug 8 10:33:12 2006 : Info: Using deprecated naslist file.
Support for this will go away soon.
Tue Aug 8 10:33:12 2006 : Debug: read_config_files: reading clients
Tue Aug 8 10:33:12 2006 : Debug: read_config_files: reading realms
Tue Aug 8 10:33:12 2006 : Debug: radiusd: entering modules setup
Tue Aug 8 10:33:12 2006 : Debug: Module: Library search path is /usr/
local/freeradius/lib
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded exec
Tue Aug 8 10:33:12 2006 : Debug: exec: wait = yes
Tue Aug 8 10:33:12 2006 : Debug: exec: program = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: exec: input_pairs = "request"
Tue Aug 8 10:33:12 2006 : Debug: exec: output_pairs = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: exec: packet_type = "(null)"
Tue Aug 8 10:33:12 2006 : Info: rlm_exec: Wait=yes but no output
defined. Did you mean output=none?
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated exec (exec)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded expr
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated expr (expr)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded PAP
Tue Aug 8 10:33:12 2006 : Debug: pap: encryption_scheme = "crypt"
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated pap (pap)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded CHAP
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated chap (chap)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded MS-CHAP
Tue Aug 8 10:33:12 2006 : Debug: mschap: use_mppe = yes
Tue Aug 8 10:33:12 2006 : Debug: mschap: require_encryption = no
Tue Aug 8 10:33:12 2006 : Debug: mschap: require_strong = no
Tue Aug 8 10:33:12 2006 : Debug: mschap: with_ntdomain_hack = no
Tue Aug 8 10:33:12 2006 : Debug: mschap: passwd = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: mschap: ntlm_auth = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated mschap (mschap)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded System
Tue Aug 8 10:33:12 2006 : Debug: unix: cache = no
Tue Aug 8 10:33:12 2006 : Debug: unix: passwd = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: unix: shadow = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: unix: group = "(null)"
Tue Aug 8 10:33:12 2006 : Debug: unix: radwtmp = "/usr/local/
freeradius/var/log/radius/radwtmp"
Tue Aug 8 10:33:12 2006 : Debug: unix: usegroup = no
Tue Aug 8 10:33:12 2006 : Debug: unix: cache_reload = 600
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated unix (unix)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded eap
Tue Aug 8 10:33:12 2006 : Debug: eap: default_eap_type = "md5"
Tue Aug 8 10:33:12 2006 : Debug: eap: timer_expire = 60
Tue Aug 8 10:33:12 2006 : Debug: eap: ignore_unknown_eap_types = no
Tue Aug 8 10:33:12 2006 : Debug: eap: cisco_accounting_username_bug
= no
Tue Aug 8 10:33:12 2006 : Debug: rlm_eap: Loaded and initialized
type md5
Tue Aug 8 10:33:12 2006 : Debug: rlm_eap: Loaded and initialized
type leap
Tue Aug 8 10:33:12 2006 : Debug: gtc: challenge = "Password: "
Tue Aug 8 10:33:12 2006 : Debug: gtc: auth_type = "PAP"
Tue Aug 8 10:33:12 2006 : Debug: rlm_eap: Loaded and initialized
type gtc
Tue Aug 8 10:33:12 2006 : Debug: mschapv2: with_ntdomain_hack = no
Tue Aug 8 10:33:12 2006 : Debug: rlm_eap: Loaded and initialized
type mschapv2
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated eap (eap)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded preprocess
Tue Aug 8 10:33:12 2006 : Debug: preprocess: huntgroups = "/usr/
local/freeradius/etc/raddb/huntgroups"
Tue Aug 8 10:33:12 2006 : Debug: preprocess: hints = "/usr/local/
freeradius/etc/raddb/hints"
Tue Aug 8 10:33:12 2006 : Debug: preprocess: with_ascend_hack = no
Tue Aug 8 10:33:12 2006 : Debug: preprocess:
ascend_channels_per_line = 23
Tue Aug 8 10:33:12 2006 : Debug: preprocess: with_ntdomain_hack = no
Tue Aug 8 10:33:12 2006 : Debug: preprocess:
with_specialix_jetstream_hack = no
Tue Aug 8 10:33:12 2006 : Debug: preprocess: with_cisco_vsa_hack = no
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated preprocess
(preprocess)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded realm
Tue Aug 8 10:33:12 2006 : Debug: realm: format = "suffix"
Tue Aug 8 10:33:12 2006 : Debug: realm: delimiter = "@"
Tue Aug 8 10:33:12 2006 : Debug: realm: ignore_default = no
Tue Aug 8 10:33:12 2006 : Debug: realm: ignore_null = no
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated realm (suffix)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded files
Tue Aug 8 10:33:12 2006 : Debug: files: usersfile = "/usr/local/
freeradius/etc/raddb/users"
Tue Aug 8 10:33:12 2006 : Debug: files: acctusersfile = "/usr/local/
freeradius/etc/raddb/acct_users"
Tue Aug 8 10:33:12 2006 : Debug: files: preproxy_usersfile = "/usr/
local/freeradius/etc/raddb/preproxy_users"
Tue Aug 8 10:33:12 2006 : Debug: files: compat = "no"
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated files (files)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded SQL
Tue Aug 8 10:33:12 2006 : Debug: sql: driver = "rlm_sql_postgresql"
Tue Aug 8 10:33:12 2006 : Debug: sql: server = "192.168.3.17"
Tue Aug 8 10:33:12 2006 : Debug: sql: port = ""
Tue Aug 8 10:33:12 2006 : Debug: sql: login = "radius"
Tue Aug 8 10:33:12 2006 : Debug: sql: password =
"thatllbemypasswordthen"
Tue Aug 8 10:33:12 2006 : Debug: sql: radius_db = "radius"
Tue Aug 8 10:33:12 2006 : Debug: sql: nas_table = "nas"
Tue Aug 8 10:33:12 2006 : Debug: sql: sqltrace = yes
Tue Aug 8 10:33:12 2006 : Debug: sql: sqltracefile = "/usr/local/
freeradius/var/log/radius/sqltrace.sql"
Tue Aug 8 10:33:12 2006 : Debug: sql: readclients = no
Tue Aug 8 10:33:12 2006 : Debug: sql: deletestalesessions = yes
Tue Aug 8 10:33:12 2006 : Debug: sql: num_sql_socks = 5
Tue Aug 8 10:33:12 2006 : Debug: sql: sql_user_name = "%{User-Name}"
Tue Aug 8 10:33:12 2006 : Debug: sql: default_user_profile = ""
Tue Aug 8 10:33:12 2006 : Debug: sql: query_on_not_found = no
Tue Aug 8 10:33:12 2006 : Debug: sql: authorize_check_query =
"SELECT id, UserName, Attribute, Value, Op FROM radcheck WHERE
Username = '%{SQL-User-Name}' ORDER BY id"
Tue Aug 8 10:33:12 2006 : Debug: sql: authorize_reply_query =
"SELECT id, UserName, Attribute, Value, Op FROM radreply WHERE
Username = '%{SQL-User-Name}' ORDER BY id"
Tue Aug 8 10:33:12 2006 : Debug: sql: authorize_group_check_query =
"SELECT radgroupcheck.id, radgroupcheck.GroupName,
radgroupcheck.Attribute, radgroupcheck.Value,radgroupche
ck.Op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-
User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName ORDER
BY radgroupcheck.id"
Tue Aug 8 10:33:12 2006 : Debug: sql: authorize_group_reply_query =
"SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, radgroupreply.Value, radgroupre
ply.Op FROM radgroupreply,usergroup WHERE usergroup.Username = '%{SQL-
User-Name}' AND usergroup.GroupName = radgroupreply.GroupName ORDER
BY radgroupreply.id"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_onoff_query =
"UPDATE radacct SET AcctStopTime = ('%S'::timestamp - '%{Acct-Delay-
Time:-0}'::interval), AcctSessionTime = (EXT
RACT(EPOCH FROM('%S'::timestamp with time zone -
AcctStartTime::timestamp with time zone - '%{Acct-Delay-
Time:-0}'::interval)))::BIGINT, AcctTerminateCause='%{Acct-Terminate-Cau
se}', AcctStopDelay = '%{Acct-Delay-Time:-0}' WHERE AcctSessionTime
IS NULL AND AcctStopTime IS NULL AND NASIPAddress= '%{NAS-IP-
Address}' AND AcctStartTime <= '%S'::timestamp"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_update_query =
"UPDATE radacct SET FramedIPAddress = NULLIF('%{Framed-IP-Address}',
'')::inet, AcctSessionTime = (EXTRACT(EPOC
H FROM('%S'::timestamp with time zone - AcctStartTime::timestamp with
time zone - '%{Acct-Delay-Time:-0}'::interval)))::BIGINT,
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 AcctSessionId
= '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND
NASIPAddress= '%{NAS-IP-Address}' AND AcctStopTime IS NULL"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_update_query_alt =
"INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm,
NASIPAddress, NASPortId, NASPortType, A
cctStartTime, AcctSessionTime, AcctAuthentic, AcctInputOctets,
AcctOutputOctets, CalledStationId, CallingStationId, ServiceType,
FramedProtocol, FramedIPAddress) values('%{Acct-
Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%
{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', ('%
S'::timestamp - '%{Acct-Delay-Time:-0}'::i
nterval - '%{Acct-Session-Time:-0}'::interval), '%{Acct-Session-
Time}', '%{Acct-Authentic}', (('%{Acct-Input-Gigawords:-0}'::bigint
<< 32) + '%{Acct-Input-Octets:-0}'::bigint),
(('%{Acct-Output-Gigawords:-0}'::bigint << 32) + '%{Acct-Output-
Octets:-0}'::bigint), '%{Called-Station-Id}', '%{Calling-Station-
Id}', '%{Service-Type}', '%{Framed-Protocol}', N
ULLIF('%{Framed-IP-Address}', '')::inet)"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_start_query =
"INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm,
NASIPAddress, NASPortId, NASPortType, AcctSt
artTime, AcctAuthentic, ConnectInfo_start, CalledStationId,
CallingStationId, ServiceType, FramedProtocol, FramedIPAddress,
AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-
Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-
Address}', '%{NAS-Port}', '%{NAS-Port-Type}', ('%S'::timestamp - '%
{Acct-Delay-Time:-0}'::interval), '%{Acct-Authe
ntic}', '%{Connect-Info}', '%{Called-Station-Id}', '%{Calling-Station-
Id}', '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-
Address}', '')::inet, '%{Acct-Delay-Time
:-0}')"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_start_query_alt =
"UPDATE radacct SET AcctStartTime = ('%S'::timestamp - '%{Acct-Delay-
Time:-0}'::interval), AcctStartDelay =
'%{Acct-Delay-Time:-0}', ConnectInfo_start = '%{Connect-Info}' WHERE
AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-
Name}' AND NASIPAddress = '%{NAS-IP-Address}
' AND AcctStopTime IS NULL"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_stop_query =
"UPDATE radacct SET AcctStopTime = ('%S'::timestamp - '%{Acct-Delay-
Time:-0}'::interval), AcctSessionTime = NULLI
F('%{Acct-Session-Time}', '')::bigint, 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}', AcctStopDelay = '%
{Acct-Delay-Time:-0}', FramedIPAddress = N
ULLIF('%{Framed-IP-Address}', '')::inet, ConnectInfo_stop = '%
{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND
UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{
NAS-IP-Address}' AND AcctStopTime IS NULL"
Tue Aug 8 10:33:12 2006 : Debug: sql: accounting_stop_query_alt =
"INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm,
NASIPAddress, NASPortId, NASPortType, Acc
tStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic,
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId,
CallingStationId, AcctTerminateCause, ServiceType
, FramedProtocol, FramedIPAddress, AcctStopDelay) values('%{Acct-
Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%
{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '
%{NAS-Port-Type}', ('%S'::timestamp - '%{Acct-Delay-
Time:-0}'::interval - '%{Acct-Session-Time:-0}'::interval), ('%
S'::timestamp - '%{Acct-Delay-Time:-0}'::interval), NULLIF('%
{Acct-Session-Time}', '')::bigint, '%{Acct-Authentic}', '%{Connect-
Info}', (('%{Acct-Input-Gigawords:-0}'::bigint << 32) + '%{Acct-Input-
Octets:-0}'::bigint), (('%{Acct-Output-G
igawords:-0}'::bigint << 32) + '%{Acct-Output-Octets:-0}'::bigint), '%
{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-
Cause}', '%{Service-Type}', '%{Framed-Prot
ocol}', NULLIF('%{Framed-IP-Address}', '')::inet, '%{Acct-Delay-
Time:-0}')"
Tue Aug 8 10:33:12 2006 : Debug: sql: group_membership_query =
"SELECT GroupName FROM usergroup WHERE UserName='%{SQL-User-Name}'"
Tue Aug 8 10:33:12 2006 : Debug: sql: connect_failure_retry_delay = 60
Tue Aug 8 10:33:12 2006 : Debug: sql: simul_count_query = ""
Tue Aug 8 10:33:12 2006 : Debug: sql: simul_verify_query = ""
Tue Aug 8 10:33:12 2006 : Debug: sql: postauth_query = "INSERT INTO
radpostauth (username, pass, reply, authdate) VALUES ('%{User-Name}',
'%{User-Password:-Chap-Password}', '%
{reply:Packet-Type}', NOW())"
Tue Aug 8 10:33:12 2006 : Debug: sql: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Tue Aug 8 10:33:12 2006 : Info: rlm_sql (sql): Driver
rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked
Tue Aug 8 10:33:12 2006 : Info: rlm_sql (sql): Attempting to connect
to radius at 192.168.3.17:/radius
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): starting 0
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Attempting to
connect rlm_sql_postgresql #0
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Connected new DB
handle, #0
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): starting 1
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Attempting to
connect rlm_sql_postgresql #1
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Connected new DB
handle, #1
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): starting 2
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Attempting to
connect rlm_sql_postgresql #2
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Connected new DB
handle, #2
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): starting 3
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Attempting to
connect rlm_sql_postgresql #3
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Connected new DB
handle, #3
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): starting 4
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Attempting to
connect rlm_sql_postgresql #4
Tue Aug 8 10:33:12 2006 : Debug: rlm_sql (sql): Connected new DB
handle, #4
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated sql (sql)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded Acct-Unique-Session-Id
Tue Aug 8 10:33:12 2006 : Debug: acct_unique: key = "User-Name,
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated acct_unique
(acct_unique)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded detail
Tue Aug 8 10:33:12 2006 : Debug: detail: detailfile = "/usr/local/
freeradius/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Tue Aug 8 10:33:12 2006 : Debug: detail: detailperm = 384
Tue Aug 8 10:33:12 2006 : Debug: detail: dirperm = 493
Tue Aug 8 10:33:12 2006 : Debug: detail: locking = no
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated detail (detail)
Tue Aug 8 10:33:12 2006 : Debug: Module: Loaded radutmp
Tue Aug 8 10:33:12 2006 : Debug: radutmp: filename = "/usr/local/
freeradius/var/log/radius/radutmp"
Tue Aug 8 10:33:12 2006 : Debug: radutmp: username = "%{User-Name}"
Tue Aug 8 10:33:12 2006 : Debug: radutmp: case_sensitive = yes
Tue Aug 8 10:33:12 2006 : Debug: radutmp: check_with_nas = yes
Tue Aug 8 10:33:12 2006 : Debug: radutmp: perm = 384
Tue Aug 8 10:33:12 2006 : Debug: radutmp: callerid = yes
Tue Aug 8 10:33:12 2006 : Debug: Module: Instantiated radutmp (radutmp)
Tue Aug 8 10:33:12 2006 : Debug: Listening on authentication *:1812
Tue Aug 8 10:33:12 2006 : Debug: Listening on accounting *:1813
Tue Aug 8 10:33:12 2006 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.3.20:32770, id=65,
length=47
User-Name = "joetest"
User-Password = "letmein"
Tue Aug 8 10:33:15 2006 : Debug: Processing the authorize section
of radiusd.conf
Tue Aug 8 10:33:15 2006 : Debug: modcall: entering group authorize
for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from preprocess (rlm_preprocess) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module
"preprocess" returns ok for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling
chap (rlm_chap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from chap (rlm_chap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module "chap"
returns noop for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling
mschap (rlm_mschap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from mschap (rlm_mschap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module
"mschap" returns noop for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling
suffix (rlm_realm) for request 0
Tue Aug 8 10:33:15 2006 : Debug: rlm_realm: No '@' in User-Name
= "joetest", looking up realm NULL
Tue Aug 8 10:33:15 2006 : Debug: rlm_realm: No such realm "NULL"
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from suffix (rlm_realm) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module
"suffix" returns noop for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling eap
(rlm_eap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: rlm_eap: No EAP-Message, not
doing EAP
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from eap (rlm_eap) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module "eap"
returns noop for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling
files (rlm_files) for request 0
Tue Aug 8 10:33:15 2006 : Debug: users: Matched entry DEFAULT at
line 152
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from files (rlm_files) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module
"files" returns ok for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: calling sql
(rlm_sql) for request 0
Tue Aug 8 10:33:15 2006 : Debug: radius_xlat: 'joetest'
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql (sql): sql_set_user escaped
user --> 'joetest'
Tue Aug 8 10:33:15 2006 : Debug: radius_xlat: 'SELECT id, UserName,
Attribute, Value, Op FROM radcheck WHERE Username = 'joetest' ORDER
BY id'
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql (sql): Reserving sql socket
id: 4
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: query: SELECT
id, UserName, Attribute, Value, Op FROM radcheck WHERE Username =
'joetest' ORDER BY id
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: affected rows =
Tue Aug 8 10:33:15 2006 : Debug: radius_xlat: 'SELECT
radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op FROM radgroupche
ck, usergroup WHERE usergroup.Username = 'joetest' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: query: SELECT
radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op FROM
radgroupcheck, usergroup WHERE usergroup.Username = 'joetest' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: affected rows =
Tue Aug 8 10:33:15 2006 : Debug: radius_xlat: 'SELECT id, UserName,
Attribute, Value, Op FROM radreply WHERE Username = 'joetest' ORDER
BY id'
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: query: SELECT
id, UserName, Attribute, Value, Op FROM radreply WHERE Username =
'joetest' ORDER BY id
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: affected rows =
Tue Aug 8 10:33:15 2006 : Debug: radius_xlat: 'SELECT
radgroupreply.id, radgroupreply.GroupName, radgroupreply.Attribute,
radgroupreply.Value, radgroupreply.Op FROM radgroupre
ply,usergroup WHERE usergroup.Username = 'joetest' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: query: SELECT
radgroupreply.id, radgroupreply.GroupName, radgroupreply.Attribute,
radgroupreply.Value, radgroupreply.Op FRO
M radgroupreply,usergroup WHERE usergroup.Username = 'joetest' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: Status:
PGRES_TUPLES_OK
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql_postgresql: affected rows =
Tue Aug 8 10:33:15 2006 : Debug: rlm_sql (sql): Released sql socket
id: 4
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authorize]: returned
from sql (rlm_sql) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authorize]: module "sql"
returns ok for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall: leaving group authorize
(returns ok) for request 0
Tue Aug 8 10:33:15 2006 : Debug: rad_check_password: Found Auth-
Type System
Tue Aug 8 10:33:15 2006 : Debug: auth: type "System"
Tue Aug 8 10:33:15 2006 : Debug: Processing the authenticate
section of radiusd.conf
Tue Aug 8 10:33:15 2006 : Debug: modcall: entering group
authenticate for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authenticate]: calling
unix (rlm_unix) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modsingle[authenticate]: returned
from unix (rlm_unix) for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall[authenticate]: module
"unix" returns notfound for request 0
Tue Aug 8 10:33:15 2006 : Debug: modcall: leaving group authenticate
(returns notfound) for request 0
Tue Aug 8 10:33:15 2006 : Debug: auth: Failed to validate the user.
Tue Aug 8 10:33:15 2006 : Debug: Delaying request 0 for 1 seconds
Tue Aug 8 10:33:15 2006 : Debug: Finished request 0
Tue Aug 8 10:33:15 2006 : Debug: Going to the next request
Tue Aug 8 10:33:15 2006 : Debug: --- Walking the entire request list
---
Tue Aug 8 10:33:15 2006 : Debug: Waking up in 1 seconds...
Tue Aug 8 10:33:16 2006 : Debug: --- Walking the entire request list
---
More information about the Freeradius-Users
mailing list