Re: sql returns fail for some stop requests

2012-08-08 Thread Amir Tal 
After moving MYSQL to a clustered environment, and moving all backup and not 
related tasks to slave hosts,
It seems the issue is resolved, radius has been running for several days 
without any errors and/or sessions not being stopped.

Thanks for all your help and suggestions,

Amir.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-24 Thread Arran Cudbard-Bell 

On 23 Jul 2012, at 14:06, Amir Tal wrote:

 Dialup.conf :
  
 [root@RADIUS4 radius]# cat /etc/raddb/sql/mysql/dialup.conf


Looks ok… Could you build with the 2.1x head and post the debug output?

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

RE: sql returns fail for some stop requests

2012-07-24 Thread Amir Tal 
After additional debugging the fault seems to be with a rouge backup process 
running on DB host, causing it to be slow to un-responsive for 10-20 minutes.
(all unclosed sessions are within this time frame)

This is easy to fix, but I'm looking for a way to make a fail-safe solution.
There can always be occasions where DB connection is momentarily slow due to 
some other issue like network or storage,
Since SQL is used here only for accounting data, is there a way to set the 
radius to accept all users (or reject all) in case DB is not-available, 
possibly keeping a buffer of accounting data to be written when DB access is 
restored?

I am currently considering two possible solitions:
Create a fail over for sql to allow login if sql is n/a, Similar to:
redundant {
 sql
 ok
   }

and/or use buffered-sql to catch these queries and update them in sql at later 
time.
Is it possible to use buffered-sql and still perform simultaneous use checks 
based on same DB?

Thanks for all replies,

Amir.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-24 Thread Alan DeKok 
Amir Tal wrote:
 After additional debugging the fault seems to be with a rouge backup
 process running on DB host, causing it to be slow to un-responsive for
 10-20 minutes.

  Stop that.  The database used by the RADIUS server should ONLY be used
by the RADIUS server.

 This is easy to fix, but I'm looking for a way to make a fail-safe
 solution.

  Don't shut down the database while the RADIUS server is using it.

 There can always be occasions where DB connection is momentarily slow
 due to some other issue like network or storage,

  Then the DB isn't that important, is it?

  I've never understood why people do that with critical systems.
They're critical, but NON-critical traffic takes them down.  The
solution for them is to BUTCHER the critical system, rather than
separating it from the non-critical systems.

 Since SQL is used here only for accounting data, is there a way to set
 the radius to accept all users (or reject all) in case DB is
 not-available,

  You do know that accounting is not authentication?  Saying accept all
users for accounting makes no sense.

 possibly keeping a buffer of accounting data to be
 written when DB access is restored?

  Stop that.  FIX THE SYSTEM SO IT WORKS.

 I am currently considering two possible solitions:

  No.  BOTH solutions are wrong.

  Fix your SQL database so that it doesn't go down.  Fix the network so
that it doesn't starve the RADIUS-SQL connection.

  ADDING complexity to the system means it is LESS stable than before.

  Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-24 Thread Arran Cudbard-Bell 

On 24 Jul 2012, at 14:24, Alan DeKok wrote:

 Amir Tal wrote:
 After additional debugging the fault seems to be with a rouge backup
 process running on DB host, causing it to be slow to un-responsive for
 10-20 minutes.
 
  Stop that.  The database used by the RADIUS server should ONLY be used
 by the RADIUS server.

Use SQL replication to transfer the records to another system and backup from 
that. Do not perform intensive queries on a live system. It also sounds like 
you might be using MyISAM for radacct, if you are convert it to InnoDB ASAP.

Yes you can use buffered SQL to protection against temporary DB outages. But 
only for Accounting. Don't try this on 2.1x branch, use 3.0 if you want 
something that actually works reliably...

Yes you can use redundant to fail open or closed, but its simpler to just:

sql {
fail = 1
}
if (fail) {
update control {
Auth-Type := 'Accept'
}
}

or

if (fail) {
reject
}

-Arran
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-24 Thread Arran Cudbard-Bell 

On 24 Jul 2012, at 18:18, Arran Cudbard-Bell wrote:

 
 On 24 Jul 2012, at 14:24, Alan DeKok wrote:
 
 Amir Tal wrote:
 After additional debugging the fault seems to be with a rouge backup
 process running on DB host, causing it to be slow to un-responsive for
 10-20 minutes.
 
 Stop that.  The database used by the RADIUS server should ONLY be used
 by the RADIUS server.
 
 Use SQL replication to transfer the records to another system and backup from 
 that. Do not perform intensive queries on a live system. It also sounds like 
 you might be using MyISAM for radacct, if you are convert it to InnoDB ASAP.
 
 Yes you can use buffered SQL to protection against temporary DB outages. But 
 only for Accounting. Don't try this on 2.1x branch, use 3.0 if you want 
 something that actually works reliably...
 
 Yes you can use redundant to fail open or closed, but its simpler to just:

Um and

redundant {
sql
ok
}

Wouldn't work...
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

RE: sql returns fail for some stop requests

2012-07-22 Thread Amir Tal 
Adding unique key to the database results in the following being returned from 
rlm_sql,
What happen to accounting data when a duplicate entry is encountered?
In addition, currently there is no scheduled clearing of the data in radacct 
table, wont this increase in occurrence?

--
[sql]   expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} - shimoni
[sql] sql_set_user escaped user -- 'shimoni'
[sql]   expand: %{Acct-Input-Gigawords} - 0
[sql]   expand: %{Acct-Input-Octets} - 0
[sql]   expand: %{Acct-Output-Gigawords} - 0
[sql]   expand: %{Acct-Output-Octets} - 0
[sql]   expand: %{Acct-Delay-Time} - 12
[sql]   expand:  UPDATE radacct SET  acctstoptime   = '%S',  
acctsessiontime= '%{Acct-Session-Time}',  acctinputoctets= 
'%{%{Acct-Input-Gigawords}:-0}'  32 | '%{%{Acct-Input-Octets}:-0}',  
acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}'  32 | 
'%{%{Acct-Output-Octets}:-0}',  acctterminatecause = '%{Acct-Terminate-Cause}', 
 acctstopdelay  = '%{%{Acct-Delay-Time}:-0}',  connectinfo_stop   = 
'%{Connect-Info}' WHERE acctsessionid   = '%{Acct-Session-Id}' AND username 
 = '%{SQL-User-Name}' AND nasipaddress  = '%{NAS-IP-Address}' -  
UPDATE radacct SET  acctstoptime   = '2012-07-22 02:03:28',  
acctsessiontime= '0',  acctinputoctets= '0'  32 | '0',  
acctoutputoctets   = '0'  32 | '0',  acctterminatecause = 'User-Error',  
acctstopdelay  = '12',  connectinfo_stop   = '' WHERE acctsessionid   = 
'erx ip:109.226.0.9:172.29.81.67:3280:96f8:1aa8:87fb:4d2:0062712021' AND 
username  = 'shimoni' AND nasipaddress  = '109.226.1.12'
[sql]   expand: /var/log/radius/sqltrace.sql - /var/log/radius/sqltrace.sql
rlm_sql_mysql: MYSQL check_error: 1062 received
[sql] Couldn't insert SQL accounting STOP record - Duplicate entry 
'c6d3d253355b3dcf' for key 2
rlm_sql_mysql: MYSQL check_error: 1062 received
rlm_sql_mysql: Cannot store result
rlm_sql_mysql: MySQL error 'Duplicate entry 'c6d3d253355b3dcf' for key 2'
rlm_sql (sql): Released sql socket id: 11
++[sql] returns fail
--
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to 
/var/log/radius/radacct/moreshet.relay
[sql]   expand: %{Acct-Delay-Time} - 0
[detail.moreshet]   expand: %t - Sun Jul 22 02:03:34 2012
[sql]   expand:  UPDATE radacct SET  acctstoptime   = '%S',  
acctsessiontime= '%{Acct-Session-Time}',  acctinputoctets= 
'%{%{Acct-Input-Gigawords}:-0}'  32 | '%{%{Acct-Input-Octets}:-0}',  
acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}'  32 | 
'%{%{Acct-Output-Octets}:-0}',  acctterminatecause = '%{Acct-Terminate-Cause}', 
 acctstopdelay  = '%{%{Acct-Delay-Time}:-0}',  connectinfo_stop   = 
'%{Connect-Info}' WHERE acctsessionid   = '%{Acct-Session-Id}' AND username 
 = '%{SQL-User-Name}' AND nasipaddress  = '%{NAS-IP-Address}' -  
UPDATE radacct SET  acctstoptime   = '2012-07-22 02:03:34',  
acctsessiontime= '0',  acctinputoctets= '0'  32 | '0',  
acctoutputoctets   = '0'  32 | '0',  acctterminatecause = 'User-Error',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx 
ip:109.226.0.9:172.24.245.233:2653:c9e:101:e0ba:4d2:0062712040' AND username
  = 'mosh19703' AND nasipaddress  = '109.226.1.12'
[sql]   expand: /var/log/radius/sqltrace.sql - /var/log/radius/sqltrace.sql
[detail.moreshet]   expand: /var/log/radius/radacct/moreshet.relay - 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet]   expand: %t - Sun Jul 22 02:03:34 2012
++[detail.moreshet] returns ok
rlm_sql_mysql: MYSQL check_error: 1062 received
[sql] Couldn't insert SQL accounting ALIVE record - Duplicate entry 
'923952cbd6569744' for key 2
rlm_sql_mysql: MYSQL check_error: 1062 received
rlm_sql_mysql: Cannot store result
rlm_sql_mysql: MySQL error 'Duplicate entry '923952cbd6569744' for key 2'
rlm_sql (sql): Released sql socket id: 27
++[sql] returns fail
--


Just wanted to state that I had started with the default provided configuration 
files,
Alredy changed the rlm_sql source code, default SQL queries, default DB 
structure.

There are still unclosed accounting packets existing.
Log shows a lot of warning messages:

rlm_sql (sql): Reserving sql socket id: 31
rlm_sql_mysql: query:   UPDATE radacct SET  acctstoptime   = '2012-07-22 
02:04:57',  acctsessiontime= '0',  acctinputoctets= '0'  32 | '0',  
acctoutputoctets   = '0'  32 | '0',  acctterminatecause = 'User-Request',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx 
ip:109.226.0.17:172.23.184.73:dd94:1847:fcca:a66:4d2:0051412783' AND username   
   = 'yali4780' AND nasipaddress  = '109.226.1.20'
[sql]   expand: %{Acct-Input-Gigawords} - 0
[sql]   expand: %{Acct-Input-Octets} - 0
[sql]   expand: %{Acct-Output-Gigawords} - 0
[sql]   expand: %{Acct-Output-Octets} - 0
[sql]   expand: %{Acct-Delay-Time} -

Re: sql returns fail for some stop requests

2012-07-22 Thread Alan DeKok 
Amir Tal wrote:
 Adding unique key to the database results in the following being
 returned from rlm_sql,
 
 What happen to accounting data when a duplicate entry is encountered?

  It SHOULD run the normal query, followed by the alt query.

 In addition, currently there is no scheduled clearing of the data in
 radacct table, wont this increase in occurrence?

  Yes.  Accounting is about storing data.  If you want to delete data,
it's one line of SQL.

 [sql] Couldn't insert SQL accounting STOP record - Duplicate entry
 'c6d3d253355b3dcf' for key 2
 rlm_sql_mysql: MYSQL check_error: 1062 received 
 rlm_sql_mysql: Cannot store result
 rlm_sql_mysql: MySQL error 'Duplicate entry 'c6d3d253355b3dcf' for key 2'

  OK... it SHOULD run the alt query here, to UPDATE the record.

 WARNING: Child is hung for request 5763411 in component core module
 queue. 
 WARNING: Child is hung for request 5763412 in component core module
 queue.

  And that's a problem.  Your SQL database is slow.  Fix it.

  Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-22 Thread Arran Cudbard-Bell 

On 22 Jul 2012, at 11:56, Amir Tal wrote:

 Adding unique key to the database results in the following being returned 
 from rlm_sql,
 What happen to accounting data when a duplicate entry is encountered?
 In addition, currently there is no scheduled clearing of the data in radacct 
 table, wont this increase in occurrence?
  
 --
 [sql]   expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} - shimoni
 [sql] sql_set_user escaped user -- 'shimoni'
 [sql]   expand: %{Acct-Input-Gigawords} - 0
 [sql]   expand: %{Acct-Input-Octets} - 0
 [sql]   expand: %{Acct-Output-Gigawords} - 0
 [sql]   expand: %{Acct-Output-Octets} - 0
 [sql]   expand: %{Acct-Delay-Time} - 12
 [sql]   expand:  UPDATE radacct SET  acctstoptime   = '%S',  
 acctsessiontime= '%{Acct-Session-Time}',  acctinputoctets= 
 '%{%{Acct-Input-Gigawords}:-0}'  32 | '%{%{Acct-Input-Octets}:-0}',  
 acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}'  32 | 
 '%{%{Acct-Output-Octets}:-0}',  acctterminatecause = 
 '%{Acct-Terminate-Cause}',  acctstopdelay  = '%{%{Acct-Delay-Time}:-0}',  
 connectinfo_stop   = '%{Connect-Info}' WHERE acctsessionid   = 
 '%{Acct-Session-Id}' AND username  = '%{SQL-User-Name}' AND 
 nasipaddress  = '%{NAS-IP-Address}' -  UPDATE radacct SET  acctstoptime  
  = '2012-07-22 02:03:28',  acctsessiontime= '0',  acctinputoctets
 = '0'  32 | '0',  acctoutputoctets   = '0'  32 | '0',  acctterminatecause 
 = 'User-Error',  acctstopdelay  = '12',  connectinfo_stop   = '' WHERE 
 acctsessionid   = 'erx 
 ip:109.226.0.9:172.29.81.67:3280:96f8:1aa8:87fb:4d2:0062712021' AND username  
 = 'shimoni' AND nasipaddress  = '109.226.1.12'
 [sql]   expand: /var/log/radius/sqltrace.sql - /var/log/radius/sqltrace.sql
 rlm_sql_mysql: MYSQL check_error: 1062 received
 [sql] Couldn't insert SQL accounting STOP record - Duplicate entry 
 'c6d3d253355b3dcf' for key 2
 rlm_sql_mysql: MYSQL check_error: 1062 received
 rlm_sql_mysql: Cannot store result
 rlm_sql_mysql: MySQL error 'Duplicate entry 'c6d3d253355b3dcf' for key 2'
 rlm_sql (sql): Released sql socket id: 11
 ++[sql] returns fail
 --

Can you please build against the current v2.1.x HEAD; the debug output doesn't 
make sense when checking through the rlm_sql.c code. Could you also post your 
dialup.conf file.

-Arran-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

RE: sql returns fail for some stop requests

2012-07-19 Thread Amir Tal 
I have increased the value of MAX_QUERY_LEN in 
freeradius-server-2.1.12/src/modules/rlm_sql/conf.h
(#define MAX_QUERY_LEN   8192)

There are still duplicated connections/sessions , example sqltrace:
INSERT INTO radacct (acctsessionid,acctuniqueid, username,  realm,  
  nasipaddress, nasportid,  nasporttype,  acctstarttime,
acctstoptime,  acctsessiontime,  acctauthentic,connectinfo_start,  
connectinfo_stop, acctinputoctets,  acctoutputoctets,  calledstationid,  
callingstationid, acctterminatecause,  servicetype,  framedprotocol,   
framedipaddress,  acctstartdelay,   acctstopdelay,xascendsessionsvrkey) 
VALUES  ('erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:606b:498b:4fdbe98:0050515007', 
'e2faac6ede73a716',  '37444332',  'ccc', '109.226.1.20', '23437230',  
'Virtual', '2012-07-19 01:54:07', NULL,  '0', 'RADIUS', '',  '', '0', '0',  '', 
'47 5/1 vlan-id 1421:32', '',  'Framed-User', 'PPP', '109.226.50.244',  '0', 
'0', '');
 UPDATE radacct SET  acctstoptime   = '2012-07-19 01:54:55',  
acctsessiontime= '48',  acctinputoctets= '0'  32 | '60',  
acctoutputoctets   = '0'  32 | '60',  acctterminatecause = 'NAS-Request',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:606b:498b:4fdbe98:0050515007' AND 
username  = '37444332' AND nasipaddress  = '109.226.1.20';
 INSERT INTO radacct (acctsessionid,acctuniqueid, username,  realm, 
   nasipaddress, nasportid,  nasporttype,  acctstarttime,
acctstoptime,  acctsessiontime,  acctauthentic,connectinfo_start,  
connectinfo_stop, acctinputoctets,  acctoutputoctets,  calledstationid,  
callingstationid, acctterminatecause,  servicetype,  framedprotocol,   
framedipaddress,  acctstartdelay,   acctstopdelay,xascendsessionsvrkey) 
VALUES  ('erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:35a4:4aaa:4fdc13c:0050515459', 
'ec2da39d0766abef',  '37444332',  'ccc', '109.226.1.20', '23438030',  
'Virtual', '2012-07-19 01:56:02', NULL,  '0', 'RADIUS', '',  '', '0', '0',  '', 
'47 5/1 vlan-id 1421:32', '',  'Framed-User', 'PPP', '109.226.50.185',  '0', 
'0', '');
 UPDATE radacct SET  acctstoptime   = '2012-07-19 01:56:52',  
acctsessiontime= '50',  acctinputoctets= '0'  32 | '60',  
acctoutputoctets   = '0'  32 | '510',  acctterminatecause = 'NAS-Request',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:35a4:4aaa:4fdc13c:0050515459' AND 
username  = '37444332' AND nasipaddress  = '109.226.1.20';
 INSERT INTO radacct (acctsessionid,acctuniqueid, username,  realm, 
   nasipaddress, nasportid,  nasporttype,  acctstarttime,
acctstoptime,  acctsessiontime,  acctauthentic,connectinfo_start,  
connectinfo_stop, acctinputoctets,  acctoutputoctets,  calledstationid,  
callingstationid, acctterminatecause,  servicetype,  framedprotocol,   
framedipaddress,  acctstartdelay,   acctstopdelay,xascendsessionsvrkey) 
VALUES  ('erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:cfbc:4aff:4fdc2b2:0050515722', 
'bfede13c66b4f238',  '37444332',  'ccc', '109.226.1.20', '23438472',  
'Virtual', '2012-07-19 01:57:05', NULL,  '0', 'RADIUS', '',  '', '0', '0',  '', 
'47 5/1 vlan-id 1421:32', '',  'Framed-User', 'PPP', '37.19.123.248',  '0', 
'0', '');
 UPDATE radacct SET  acctstoptime   = '2012-07-19 01:57:54',  
acctsessiontime= '49',  acctinputoctets= '0'  32 | '60',  
acctoutputoctets   = '0'  32 | '8366',  acctterminatecause = 'NAS-Request',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:cfbc:4aff:4fdc2b2:0050515722' AND 
username  = '37444332' AND nasipaddress  = '109.226.1.20';
 INSERT INTO radacct (acctsessionid,acctuniqueid, username,  realm, 
   nasipaddress, nasportid,  nasporttype,  acctstarttime,
acctstoptime,  acctsessiontime,  acctauthentic,connectinfo_start,  
connectinfo_stop, acctinputoctets,  acctoutputoctets,  calledstationid,  
callingstationid, acctterminatecause,  servicetype,  framedprotocol,   
framedipaddress,  acctstartdelay,   acctstopdelay,xascendsessionsvrkey) 
VALUES  ('erx 
ip:109.226.0.17:147.235.134.47:ef47:632c:3374:4b57:4fdc420:0050515966', 
'457b5c3e9fc92416',  '37444332',  'ccc', '109.226.1.20', '23438894',  
'Virtual', '2012-07-19 01:58:07', NULL,  '0', 'RADIUS', '',  '', '0', '0',  '', 
'47 5/1 vlan-id 1421:32', '',  'Framed-User', 'PPP', '109.226.50.123',  '0', 
'0', '');
 UPDATE radacct SET  acctstoptime   = '2012-07-19 01:58:55',  
acctsessiontime= '48',  acctinputoctets= '0'  32 | '60',  
acctoutputoctets   = '0'  32 | '60',  acctterminatecause = 'NAS-Request',  
acctstopdelay  = '0',  connectinfo_stop   = '' WHERE acctsessionid   = 'erx

Re: sql returns fail for some stop requests

2012-07-19 Thread Arran Cudbard-Bell 

 This seems to be the case for duplicated connections, there are several 
 accounting start requests sent within a few seconds from each other, all of 
 them create a new accounting record, and no stop request is sent for these 
 sessions.

I don't know about your original issue, but there's a bug in the default schema 
for released versions of 2.1.x.

The acctuniqueid column should have a UNIQUE KEY constraint on it, but in the 
default schema it doesn't.

mysql -e 'DROP INDEX acctuniqueid ON radacct; CREATE UNIQUE INDEX acctuniqueid 
ON radacct (acctuniqueid);' radius

Will fix your duplicates issue.

All users of rlm_sql_mysql with a schema based on 3.0 versions prior to 
87a8919aa23678f35778beae4ca6f5decfe3bab6, and 1/2.x before 
3651b564b98a7511e4a0793e86fbc91dcb650d07 should add the unique key constraint 
to avoid the possibility of duplicate sessions from multiple accounting starts. 
Its been this way for at least five years, but it's definitely incorrect.

The alternate query should be executed when the server errors out after hitting 
a unique value constraint on the accuniqueid, at which point it'll try and 
update the existing record with new data. If no such constraint exists it will 
just insert a new row, and you'll get the duplicate sessions.

-Arran
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

RE: sql returns fail for some stop requests

2012-07-15 Thread Amir Tal 
(sorry if this is duplicate)

i have modified the sql queries and removed unnecessary whitespace,
but am still getting some queries cut-off in the log.
the main issue is with accounting stop requests.
(i am using the default queries provided with freeradius 2.1.12 - dialup.conf)

is there a way to increase the space/memory available for sql queries?
the main issue is with accounting stop requests.

in addition i have found the following in the logs:
rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0
++[sql] returns fail

number of DB connections has already been raised from the default 5 to 25,
this is a rare error, but it still exists, might be related.

Amir.


From: Amir Tal
Sent: Wednesday, July 11, 2012 4:48 PM
To: 'freeradius-users@lists.freeradius.org'
Subject: sql returns fail for some stop requests

Freeradius ver 2.1.12, configured to use ldap for auth, sql for acct.

Sometimes users' sessions get stuck and have to be closed manualy (simultaneous 
use is turned on for all users).
After extensive debugging I have found the following in the logs (radius -X)


[thread] # Executing section preacct from file 
/etc/raddb/sites-enabled/default
[thread] +- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 14117776,Client-IP-Address = 
xx.xx.xx.xx,NAS-IP-Address = xx.xx.xx.xx,Acct-Session-Id = erx 
ip:109.226.0.9:147.235.234.115:1e47:6248:14c2:8b6a:5dac845:0060992452,Use
r-Name = x@ccc'
[acct_unique] Acct-Unique-Session-ID = d49ba42fa077f5f0.
++[acct_unique] returns ok
[suffix] Looking up realm ccc for User-Name = x@ccc
[suffix] Found realm ccc
[suffix] Adding Stripped-User-Name = x
[suffix] Adding Realm = ccc
[suffix] Accounting realm is LOCAL.
++[suffix] returns ok
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]expand: %{Packet-Src-IP-Address} - xx.xx.xx.xx
[detail]expand: 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
 - /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail] 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
 expands to /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail]expand: %t - Wed Jul 11 02:03:45 2012
Cleaning up request 12612249 ID 93 with timestamp +729235
++[detail] returns ok
[detail.moreshet]   expand: /var/log/radius/radacct/moreshet.relay - 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet]   expand: %t - Wed Jul 11 02:03:45 2012
++[detail.moreshet] returns ok
++[unix] returns ok
[sql]   expand: %{Stripped-User-Name} - x
[sql]   expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} - x
[sql] sql_set_user escaped user -- 'x'
[sql]   expand: %{Acct-Input-Gigawords} - 0
[sql]   expand: %{Acct-Input-Octets} - 4001
[sql]   expand: %{Acct-Output-Gigawords} - 0
[sql]   expand: %{Acct-Output-Octets} - 8134
[sql]   expand: %{Acct-Delay-Time} - 0
[sql]   expand:UPDATE radacct SET  acctstoptime   = 
'%S',  acctsessiontime= '%{Acct-Session-Time}',  
acctinputoctets= '%{%{Acct-Input-Gigawords}:-0}'  32 |
   '%{%{Acct-Input-Octets}:-0}',  acctoutputoctets   = 
'%{%{Acct-Output-Gigawords}:-0}'  32 |   
'%{%{Acct-Output-Octets}:-0}',  acctterminatecause = 
'%{Acct-Terminate-Cause}',  acctstopdelay  = 
'%{%{Acct-Delay-Time}:-0}',  connectinfo_stop   = '%{Connect-Info}' 
  WHERE acctsessionid   = '%{Acct-Session-Id}'   AND username   
   = '%{SQL-User-Name}'   AND nasipaddress  = 
'%{NAS-IP-Address}' -UPDATE radacct SET  acctstoptime  
 = '2012-07-11 02:03:45',  acctsessiontime= '517',  
acctinputoctets= '0'  32 |   '4001',  
acctoutputoctets   = '0'  32 |

[sql]   expand: /var/log/radius/sqltrace.sql - /var/log/radius/sqltrace.sql
Cleaning up request 12612250 ID 95 with timestamp +729235
++[sql] returns fail
Thread 20 got semaphore
Thread 19 got semaphore

It seems the last SQL query line is cut off for some reason, this only happens 
on some connections, while others are stopped correctly.
Not specific to users or time of day.

Versions information:

cat /etc/issue :
CentOS release 5.6 (Final)
Kernel \r on an \m

rpm -qa | grep radius :
freeradius2-python-2.1.12-7
freeradius2-ldap-2.1.12-7
freeradius2-2.1.12-7
freeradius2-krb5-2.1.12-7
freeradius2-mysql-2.1.12-7
freeradius2-utils-2.1.12-7
freeradius2-postgresql-2.1.12-7
freeradius2-perl-2.1.12-7
freeradius2-unixODBC-2.1.12-7

additional logs and/or information can be provided

Re: sql returns fail for some stop requests

2012-07-15 Thread Alan DeKok 
Amir Tal wrote:
 i have modified the sql queries and removed unnecessary whitespace, 
 but am still getting some queries cut-off in the log.
...
 is there a way to increase the space/memory available for sql queries?

  Edit the source code.  See src/modules/rlm_sql/

 in addition i have found the following in the logs:
 
 rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 
 ++[sql] returns fail
...
 this is a rare error, but it still exists, might be related.

  It's not related.

  Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

sql returns fail for some stop requests

2012-07-11 Thread Amir Tal 
Freeradius ver 2.1.12, configured to use ldap for auth, sql for acct.

Sometimes users' sessions get stuck and have to be closed manualy (simultaneous 
use is turned on for all users).
After extensive debugging I have found the following in the logs (radius -X)


[thread] # Executing section preacct from file 
/etc/raddb/sites-enabled/default
[thread] +- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 14117776,Client-IP-Address = 
xx.xx.xx.xx,NAS-IP-Address = xx.xx.xx.xx,Acct-Session-Id = erx 
ip:109.226.0.9:147.235.234.115:1e47:6248:14c2:8b6a:5dac845:0060992452,Use
r-Name = x@ccc'
[acct_unique] Acct-Unique-Session-ID = d49ba42fa077f5f0.
++[acct_unique] returns ok
[suffix] Looking up realm ccc for User-Name = x@ccc
[suffix] Found realm ccc
[suffix] Adding Stripped-User-Name = x
[suffix] Adding Realm = ccc
[suffix] Accounting realm is LOCAL.
++[suffix] returns ok
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]expand: %{Packet-Src-IP-Address} - xx.xx.xx.xx
[detail]expand: 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
 - /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail] 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
 expands to /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail]expand: %t - Wed Jul 11 02:03:45 2012
Cleaning up request 12612249 ID 93 with timestamp +729235
++[detail] returns ok
[detail.moreshet]   expand: /var/log/radius/radacct/moreshet.relay - 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to 
/var/log/radius/radacct/moreshet.relay
[detail.moreshet]   expand: %t - Wed Jul 11 02:03:45 2012
++[detail.moreshet] returns ok
++[unix] returns ok
[sql]   expand: %{Stripped-User-Name} - x
[sql]   expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} - x
[sql] sql_set_user escaped user -- 'x'
[sql]   expand: %{Acct-Input-Gigawords} - 0
[sql]   expand: %{Acct-Input-Octets} - 4001
[sql]   expand: %{Acct-Output-Gigawords} - 0
[sql]   expand: %{Acct-Output-Octets} - 8134
[sql]   expand: %{Acct-Delay-Time} - 0
[sql]   expand:UPDATE radacct SET  acctstoptime   = 
'%S',  acctsessiontime= '%{Acct-Session-Time}',  
acctinputoctets= '%{%{Acct-Input-Gigawords}:-0}'  32 |
   '%{%{Acct-Input-Octets}:-0}',  acctoutputoctets   = 
'%{%{Acct-Output-Gigawords}:-0}'  32 |   
'%{%{Acct-Output-Octets}:-0}',  acctterminatecause = 
'%{Acct-Terminate-Cause}',  acctstopdelay  = 
'%{%{Acct-Delay-Time}:-0}',  connectinfo_stop   = '%{Connect-Info}' 
  WHERE acctsessionid   = '%{Acct-Session-Id}'   AND username   
   = '%{SQL-User-Name}'   AND nasipaddress  = 
'%{NAS-IP-Address}' -UPDATE radacct SET  acctstoptime  
 = '2012-07-11 02:03:45',  acctsessiontime= '517',  
acctinputoctets= '0'  32 |   '4001',  
acctoutputoctets   = '0'  32 |
[sql]   expand: /var/log/radius/sqltrace.sql - /var/log/radius/sqltrace.sql
Cleaning up request 12612250 ID 95 with timestamp +729235
++[sql] returns fail
Thread 20 got semaphore
Thread 19 got semaphore

It seems the last SQL query line is cut off for some reason, this only happens 
on some connections, while others are stopped correctly.
Not specific to users or time of day.

Versions information:

cat /etc/issue :
CentOS release 5.6 (Final)
Kernel \r on an \m

rpm -qa | grep radius :
freeradius2-python-2.1.12-7
freeradius2-ldap-2.1.12-7
freeradius2-2.1.12-7
freeradius2-krb5-2.1.12-7
freeradius2-mysql-2.1.12-7
freeradius2-utils-2.1.12-7
freeradius2-postgresql-2.1.12-7
freeradius2-perl-2.1.12-7
freeradius2-unixODBC-2.1.12-7

additional logs and/or information can be provided if required.
Help would be appreciated.

The Cloud has no limit !

[cid:image001.jpg@01CD5F84.25487600]http://www.ccc.co.il/

Amir Tal

Systems Automation Expert

Cloud Services

Direct: 972-(0)3-9201471

Fax: 972-(0)-3-9201442

www.ccc.co.ilhttp://www.ccc.co.il/   [cid:image002.png@01CD5F84.25487600] 
http://www.facebook.com/triplec.il




inline: image001.jpginline: image002.png-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: sql returns fail for some stop requests

2012-07-11 Thread Alan DeKok 
Amir Tal wrote:
 It seems the last SQL query line is cut off for some reason, this only
 happens on some connections, while others are stopped correctly.

  The server has limited space for SQL qeuries.  Make them shorter.
Remove multiple spaces, etc.

  Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html