Anyone seen this?
I'm getting some strange errors from postgres, it's almost as if my
queries aren't filled in the whole way.
What am I missing? Is my switch just not returning all of the proper
accounting info?
-Bob
--- Walking the entire request list ---
Cleaning up request 2 ID 87 with timestamp 43e8bcea
Waking up in 2 seconds...
rad_recv: Access-Request packet from host 192.168.2.160:1045, id=90,
length=70
User-Name = "root"
User-Password = "something"
NAS-IP-Address = 192.168.2.160
NAS-Identifier = "HP5304"
NAS-Port-Type = Virtual
Service-Type = NAS-Prompt-User
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 5
modcall[authorize]: module "preprocess" returns ok for request 5
modcall[authorize]: module "chap" returns noop for request 5
modcall[authorize]: module "mschap" returns noop for request 5
rlm_realm: No '@' in User-Name = "root", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 5
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 5
users: Matched entry DEFAULT at line 157
modcall[authorize]: module "files" returns ok for request 5
modcall: group authorize returns ok for request 5
rad_check_password: Found Auth-Type System
auth: type "System"
Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 5
rlm_unix: [root]: invalid password
modcall[authenticate]: module "unix" returns reject for request 5
modcall: group authenticate returns reject for request 5
auth: Failed to validate the user.
Delaying request 5 for 1 seconds
Finished request 5
Going to the next request
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 3 ID 88 with timestamp 43e8bcec
Waking up in 1 seconds...
--- Walking the entire request list ---
Sending Access-Reject of id 90 to 192.168.2.160:1045
Waking up in 2 seconds...
rad_recv: Accounting-Request packet from host 192.168.2.160:1050, id=91,
length=99
Acct-Session-Id = "000700000009"
Acct-Status-Type = Stop
Service-Type = NAS-Prompt-User
Acct-Authentic = Local
Acct-Delay-Time = 15
NAS-IP-Address = 192.168.2.160
NAS-Identifier = "HP5304"
Calling-Station-Id = "192.168.2.152"
Acct-Terminate-Cause = User-Request
Acct-Session-Time = 29
Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 6
modcall[preacct]: module "preprocess" returns noop for request 6
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request,
unique ID MAY be inconsistent
rlm_acct_unique: WARNING: Attribute User-Name was not found in request,
unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address =
192.168.2.160,NAS-IP-Address = 192.168.2.160,Acct-Session-Id =
"000700000009",'
rlm_acct_unique: Acct-Unique-Session-ID = "e8b7a55267489b1f".
modcall[preacct]: module "acct_unique" returns ok for request 6
rlm_realm: Proxy reply, or no User-Name. Ignoring.
modcall[preacct]: module "suffix" returns noop for request 6
modcall[preacct]: module "files" returns noop for request 6
modcall: group preacct returns ok for request 6
Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 6
radius_xlat: '/var/log/radius/radacct/192.168.2.160/detail-20060207'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /var/log/radius/radacct/192.168.2.160/detail-20060207
modcall[accounting]: module "detail" returns ok for request 6
modcall[accounting]: module "unix" returns noop for request 6
radius_xlat: '/var/log/radius/radutmp'
radius_xlat: ''
rlm_radutmp: No NAS-Port seen. Cannot do anything.
rlm_radumtp: WARNING: checkrad will probably not work!
modcall[accounting]: module "radutmp" returns noop for request 6
radius_xlat: ''
radius_xlat: 'UPDATE radacct ??SET AcctStopTime = (now() -
'15'::interval), ??AcctSessionTime = NULLIF('29', '')::bigint,
??AcctInputOctets = (('0'::bigint << 32) + '0'::bigint),
??AcctOutputOctets = (('0'::bigint << 32) + '0'::bigint),
??AcctTerminateCause = 'User-Request', AcctStopDelay = '15',
??FramedIPAddress = NULLIF('', '')::inet, ConnectInfo_stop = '' ??WHERE
AcctSessionId = '000700000009' AND UserName = '' ??AND NASIPAddress =
'192.168.2.160' AND AcctStopTime IS NULL'
radius_xlat: '/var/log/radius/sqltrace.sql'
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql_postgresql: query: UPDATE radacct ??SET AcctStopTime = (now() -
'15'::interval), ??AcctSessionTime = NULLIF('29', '')::bigint,
??AcctInputOctets = (('0'::bigint << 32) + '0'::bigint),
??AcctOutputOctets = (('0'::bigint << 32) + '0'::bigint),
??AcctTerminateCause = 'User-Request', AcctStopDelay = '15',
??FramedIPAddress = NULLIF('', '')::inet, ConnectInfo_stop = '' ??WHERE
AcctSessionId = '000700000009' AND UserName = '' ??AND NASIPAddress =
'192.168.2.160' AND AcctStopTime IS NULL
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: affected rows = 0
radius_xlat: 'INSERT into radacct ??(AcctSessionId, AcctUniqueId,
UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime,
AcctStopTime, ??AcctSessionTime, AcctAuthentic, ConnectInfo_stop,
AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId,
??AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress,
AcctStopDelay) ??values('000700000009', 'e8b7a55267489b1f', '', '',
'192.168.2.160', ??'', '', (now() - '15'::interval - '29'::interval),
??(now() - '15'::interval), NULLIF('29', '')::bigint, ??'Local', '',
??(('0'::bigint << 32) + '0'::bigint), ??(('0'::bigint << 32) +
'0'::bigint), '', ??'192.168.2.152', 'User-Request', 'NAS-Prompt-User',
'', ??NULLIF('', '')::inet, '15')'
radius_xlat: '/var/log/radius/sqltrace.sql'
rlm_sql_postgresql: query: INSERT into radacct ??(AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, ??AcctSessionTime, AcctAuthentic,
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId,
CallingStationId, ??AcctTerminateCause, ServiceType, FramedProtocol,
FramedIPAddress, AcctStopDelay) ??values('000700000009',
'e8b7a55267489b1f', '', '', '192.168.2.160', ??'', '', (now() -
'15'::interval - '29'::interval), ??(now() - '15'::interval),
NULLIF('29', '')::bigint, ??'Local', '', ??(('0'::bigint << 32) +
'0'::bigint), ??(('0'::bigint << 32) + '0'::bigint), '',
??'192.168.2.152', 'User-Request', 'NAS-Prompt-User', '', ??NULLIF('',
'')::inet, '15')
rlm_sql_postgresql: Status: PGRES_FATAL_ERROR
rlm_sql_postgresql: affected rows =
rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning
SQL_DOWN
rlm_sql (sql): Attempting to connect rlm_sql_postgresql #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql_postgresql: query: INSERT into radacct ??(AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, ??AcctSessionTime, AcctAuthentic,
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId,
CallingStationId, ??AcctTerminateCause, ServiceType, FramedProtocol,
FramedIPAddress, AcctStopDelay) ??values('000700000009',
'e8b7a55267489b1f', '', '', '192.168.2.160', ??'', '', (now() -
'15'::interval - '29'::interval), ??(now() - '15'::interval),
NULLIF('29', '')::bigint, ??'Local', '', ??(('0'::bigint << 32) +
'0'::bigint), ??(('0'::bigint << 32) + '0'::bigint), '',
??'192.168.2.152', 'User-Request', 'NAS-Prompt-User', '', ??NULLIF('',
'')::inet, '15')
rlm_sql_postgresql: Status: PGRES_FATAL_ERROR
rlm_sql_postgresql: affected rows =
rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning
SQL_DOWN
rlm_sql (sql): failed after re-connect
rlm_sql (sql): Couldn't insert SQL accounting STOP record - ERROR:
invalid input syntax for integer: ""
rlm_sql (sql): Released sql socket id: 0
modcall[accounting]: module "sql" returns fail for request 6
modcall: group accounting returns fail for request 6
Finished request 6
Going to the next request
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 4 ID 89 with timestamp 43e8bcef
Waking up in 2 seconds...
rad_recv: Access-Request packet from host 192.168.2.160:1045, id=92,
length=70
User-Name = "root"
User-Password = "classicnw"
NAS-IP-Address = 192.168.2.160
NAS-Identifier = "HP5304"
NAS-Port-Type = Virtual
Service-Type = NAS-Prompt-User
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 7
modcall[authorize]: module "preprocess" returns ok for request 7
modcall[authorize]: module "chap" returns noop for request 7
modcall[authorize]: module "mschap" returns noop for request 7
rlm_realm: No '@' in User-Name = "root", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 7
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 7
users: Matched entry DEFAULT at line 157
modcall[authorize]: module "files" returns ok for request 7
modcall: group authorize returns ok for request 7
rad_check_password: Found Auth-Type System
auth: type "System"
Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 7
rlm_unix: [root]: invalid password
modcall[authenticate]: module "unix" returns reject for request 7
modcall: group authenticate returns reject for request 7
auth: Failed to validate the user.
Delaying request 7 for 1 seconds
Finished request 7
Going to the next request
--- Walking the entire request list ---
Cleaning up request 5 ID 90 with timestamp 43e8bcf1
Waking up in 1 seconds...
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Sending Access-Reject of id 92 to 192.168.2.160:1045
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 6 ID 91 with timestamp 43e8bcf4
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 7 ID 92 with timestamp 43e8bcf7
Nothing to do. Sleeping until we see a request.
