Unexpected closed sessions in database
Hi friends. I have small problem with freeradius and accounting (with database). Something is closing opened sessions and I can't see what is the reason. It seems that accounting_onoff_query was triggered by "something" and acctterminatecause field is empty so I don't see anything. accounting_onoff_query = "\ UPDATE ${acct_table1} \ SET \ acctstoptime = '%S', \ acctsessiontime = unix_timestamp('%S') - \ unix_timestamp(acctstarttime), \ acctterminatecause = '%{Acct-Terminate-Cause}', \ acctstopdelay = '%{%{Acct-Delay-Time}:-0}', \ vrijeme = '%S' \ WHERE acctstoptime = 0 \ # WHERE acctstoptime IS NULL \ AND nasipaddress = '%{NAS-IP-Address}' \ AND acctstarttime <= '%S'" Session is still alive in NAS but just like I said, account. doesn't work. I'm using old sql schema so WHERE acctstoptime IS NULL \ is commented and replaced with WHERE acctstoptime = 0 \ in sql.conf i set no for deletestalesessions because I don't need this function. # Remove stale session if checkrad does not see a double login deletestalesessions = no FreeRadius is 2.1.3 Any ideas how to trace and solve this problem ? Thanks
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Marinko Tarlac wrote:
Hi friends.
I have small problem with freeradius and accounting (with database). Something is closing opened sessions and I can't see what is the reason. It seems that accounting_onoff_query was triggered by "something" and acctterminatecause field is empty so I don't see anything.
accounting_onoff_query = "\ UPDATE ${acct_table1} \ SET \ acctstoptime = '%S', \ acctsessiontime = unix_timestamp('%S') - \ unix_timestamp(acctstarttime), \ acctterminatecause = '%{Acct-Terminate-Cause}', \ acctstopdelay = '%{%{Acct-Delay-Time}:-0}', \ vrijeme = '%S' \ WHERE acctstoptime = 0 \ # WHERE acctstoptime IS NULL \ AND nasipaddress = '%{NAS-IP-Address}' \ AND acctstarttime <= '%S'"
Session is still alive in NAS but just like I said, account. doesn't work. I'm using old sql schema so WHERE acctstoptime IS NULL \ is commented and replaced with WHERE acctstoptime = 0 \
in sql.conf i set no for deletestalesessions because I don't need this function.
# Remove stale session if checkrad does not see a double login deletestalesessions = no
FreeRadius is 2.1.3
Any ideas how to trace and solve this problem ? Could be buggy NAS ? Check detail logs for Accounting-Requests with an Acct-Status-Type of Accounting-On or Accounting-Off.
Also check that Accounting-Requests are being sent with the NAS-IP-Address attribute set correctly. Regards, Arran -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.9 (Darwin) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iEYEARECAAYFAkmWmCUACgkQcaklux5oVKLPeACfdn+6q6qE1XdWUPQBHDk8lRC8 KJYAoJGbgWHWdd2eUnUnDmDUn/JrLoT8 =ruu/ -----END PGP SIGNATURE-----
For start record I have Tue Feb 17 00:21:11 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 02:20:53 CET" Acct-Status-Type = Start NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234826471 Request-Authenticator = Verified and during the whole day, I receive regular updates Tue Feb 17 02:22:42 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 04:22:23 CET" Acct-Session-Time = 7291 Acct-Input-Octets = 4618 Acct-Input-Gigawords = 0 Acct-Input-Packets = 34 Acct-Output-Octets = 5882 Acct-Output-Gigawords = 0 Acct-Output-Packets = 41 Acct-Status-Type = Interim-Update NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234833762 Request-Authenticator = Verified At 11:23:16 (according to database) the session was closed and I cant find Stop or Accounting-Off. NAS continues to send updates at regular basis. Those lines are copied from detail file after I turned on this function. This problem I didn't have in FR1.1.7. Only in FR 2.1.3. NASes are Mikrotik version 3.17 and 2.9.x Is there any other way to trace this problem? On Sat, Feb 14, 2009 at 11:08 AM, Arran Cudbard-Bell < a.cudbard-bell@sussex.ac.uk> wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Could be buggy NAS ? Check detail logs for Accounting-Requests with an Acct-Status-Type of Accounting-On or Accounting-Off.
Also check that Accounting-Requests are being sent with the NAS-IP-Address attribute set correctly.
Regards, Arran
For start record I have
Tue Feb 17 00:21:11 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 02:20:53 CET" Acct-Status-Type = Start NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234826471 Request-Authenticator = Verified
and during the whole day, I receive regular updates
Tue Feb 17 02:22:42 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 04:22:23 CET" Acct-Session-Time = 7291 Acct-Input-Octets = 4618 Acct-Input-Gigawords = 0 Acct-Input-Packets = 34 Acct-Output-Octets = 5882 Acct-Output-Gigawords = 0 Acct-Output-Packets = 41 Acct-Status-Type = Interim-Update NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234833762 Request-Authenticator = Verified
At 11:23:16 (according to database) the session was closed and I cant find Stop or Accounting-Off. NAS continues to send updates at regular basis.
Is there an update packet at that time? Ivan Kalik Kalik Informatika ISP
I have at Tue Feb 17 11:22:44 2009 and Tue Feb 17 11:24:14 2009 which is OK because the updates are set to every 90 seconds. According to database the session was closed at 2009-02-17 11:23:16 After Tue Feb 17 11:24:14 2009, radius still receives regular updates. acctterminatecause is empty and when I kill this session in NAS list, I see that Stop was received and the same session is updated (acctterminatecause and AcctStopTime was updated which means that NAS didn't lost this session and still has its unique ID.) Huh... :) Database and server was at 0.50 load (average) and it works perfectly. Radius log is empty and I don't see anything inside... Except ... Tue Feb 17 04:00:06 2009 : Error: Received conflicting packet from client pppoe port 55074 - ID: 133 due to unfinished request 301628. Giving up o$ Tue Feb 17 04:00:06 2009 : Error: Received conflicting packet from client pppoe port 60609 - ID: 134 due to unfinished request 301629. Giving up o$ Tue Feb 17 04:00:06 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:07 2009 : Error: Received conflicting packet from client pppoe port 50529 - ID: 136 due to unfinished request 301631. Giving up o$ Tue Feb 17 04:00:07 2009 : Error: Received conflicting packet from client pppoe port 46437 - ID: 137 due to unfinished request 301632. Giving up o$ Tue Feb 17 04:00:07 2009 : Error: Received conflicting packet from client pppoe port 51690 - ID: 135 due to unfinished request 301630. Giving up o$ Tue Feb 17 04:00:07 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:08 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:08 2009 : Error: Received conflicting packet from client pppoe port 56049 - ID: 138 due to unfinished request 301633. Giving up o$ Tue Feb 17 04:00:08 2009 : Error: Received conflicting packet from client pppoe port 44656 - ID: 139 due to unfinished request 301634. Giving up o$ Tue Feb 17 04:00:09 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:09 2009 : Error: Received conflicting packet from client pppoe port 34330 - ID: 141 due to unfinished request 301636. Giving up o$ Tue Feb 17 04:00:09 2009 : Error: Received conflicting packet from client pppoe port 39034 - ID: 140 due to unfinished request 301635. Giving up o$ Tue Feb 17 04:00:09 2009 : Error: Received conflicting packet from client pppoe port 55074 - ID: 133 due to unfinished request 301637. Giving up o$ Tue Feb 17 04:00:10 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:11 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:12 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:13 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:14 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:15 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:16 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:17 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:18 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:19 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Tue Feb 17 04:00:20 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 which is coused by a sheduled backup at 4:00:00 in the morning :) Thanks for your time in any case.... :) On Wed, Feb 18, 2009 at 1:23 PM, <tnt@kalik.net> wrote:
For start record I have
Tue Feb 17 00:21:11 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 02:20:53 CET" Acct-Status-Type = Start NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234826471 Request-Authenticator = Verified
and during the whole day, I receive regular updates
Tue Feb 17 02:22:42 2009 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 416808 NAS-Port-Type = Ethernet User-Name = "branka" Calling-Station-Id = "00:4F:62:09:3C:C9" NAS-Port-Id = "konc-javne" Acct-Session-Id = "8135a552" Framed-IP-Address = 192.168.98.165 Acct-Authentic = RADIUS Event-Timestamp = "Feb 17 2009 04:22:23 CET" Acct-Session-Time = 7291 Acct-Input-Octets = 4618 Acct-Input-Gigawords = 0 Acct-Input-Packets = 34 Acct-Output-Octets = 5882 Acct-Output-Gigawords = 0 Acct-Output-Packets = 41 Acct-Status-Type = Interim-Update NAS-Identifier = "1.24 - PPPoE" NAS-IP-Address = 192.168.1.24 Acct-Delay-Time = 0 Acct-Unique-Session-Id = "1582d68f4c109a25" Timestamp = 1234833762 Request-Authenticator = Verified
At 11:23:16 (according to database) the session was closed and I cant find Stop or Accounting-Off. NAS continues to send updates at regular basis.
Is there an update packet at that time?
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
A little update... In the same time (2009-02-17 11:23:16), there was at least 20 other closed sessions and they are from different NASes so I guess that problem is on the server side... In which cases accounting_onoff_query is triggered by radius server? (Accounting Off, and Stop but is there any other ...) I partially solved this problem with cron script which reopens the closed sessions but that is not a long term solution :) Marinko Tarlac wrote:
I have at Tue Feb 17 11:22:44 2009 and Tue Feb 17 11:24:14 2009 which is OK because the updates are set to every 90 seconds.
According to database the session was closed at 2009-02-17 11:23:16
After Tue Feb 17 11:24:14 2009, radius still receives regular updates. acctterminatecause is empty and when I kill this session in NAS list, I see that Stop was received and the same session is updated (acctterminatecause and AcctStopTime was updated which means that NAS didn't lost this session and still has its unique ID.)
Marinko Tarlac wrote:
A little update... In the same time (2009-02-17 11:23:16), there was at least 20 other closed sessions and they are from different NASes so I guess that problem is on the server side...
You can turn on SQL tracing to see the SQL statements. Or, (it's easier in 2.1.4), you can turn on debugging *only* for accounting packets, with Acct-Status-Type Stop or Accounting-Off. The new "radmin" tool is very useful for tracking down these kinds of issues.
In which cases accounting_onoff_query is triggered by radius server? (Accounting Off, and Stop but is there any other ...)
Only if you're using Simultaneous-Use. Alan DeKok.
participants (4)
-
Alan DeKok -
Arran Cudbard-Bell -
Marinko Tarlac -
tnt＠kalik.net