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@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 ---