Acct-Delay-Time attribute in buffered-sql server mode
Hi all, I have found an interesting issue related to Acct-Delay-Time attribute when buffered-sql mode is in use. I am not sure if it is a bug or feature. IMHO it is a bug but I would like to discuss it here. I am using freeradius for accounting in buffered-sql mode with MySQL backend. The main radacct table is using memory engine so it is pretty fast nevertheless the buffered-sql mode is a must. We have more 1.000 Acct req/sec in average with additional repeated peaks. We need to store the Acct-Delay- Time for diagnostic purposes. It is not always present in the Accounting request from NAS but if it is there it indicates that NAS is experiencing some performance problems. And the issue is that even if there is no Acct-Delay-Time received from the NAS, it appears in radacct table then and from my observations it has nothing to do with the real delay of the session start and indicates just the amount of time for which the record was waiting in radacct/detail.work file. IMHO this is wrong because the SQL scripts in dialup.conf are doing a correction of session start time based using Acct-Delay-Time. My accounting-start-query: accounting_start_query = "INSERT into ${acct_table1} (AcctUpdateTime, AcctSessionId, AcctUniqueId, UserName, NASIPAddress, AcctStartTime, AcctSessionTime, AcctAuthentic, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, FramedIPAddress, AcctStartDelay, AcctStopDelay, SgsnIpAddr, Imsi, 3GPPSelectionMode, 3GPPGPRSNegotiatedQoSProfile, Acct_Status_Type, 3GPPChargingId, 3GPPNSAPI, 3GPPSGSNMNCMCC, 3GPPRATType, 3GPPUserLocationInfo, 3GPPMSTimezone, 3GPPIMEISV, TMOChargingRuleBaseName, SNVirtualAPNName, SNRulebase) values('%S', '%{Acct- Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{NAS-IP- Address}', DATE_SUB('%S', INTERVAL %{Acct-Delay-Time:-0} SECOND), '0', '%{Acct-Authentic}', '0', '0', '%{Called-Station-Id}', '%{Calling-Station- Id}', '', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0','%{3GPP-SGSN- Address}','%{3GPP-IMSI}','%{3GPP-Selection-Mode}','%{3GPP-GPRS-Negotiated-QoS- profile}','%{Acct-Status-Type}','%{3GPP-Charging-ID}','%{3GPP-NSAPI}','%{3GPP- SGSN-MCC-MNC}','%{3GPP-RAT-Type}','%{3GPP-Location-Info}','%{3GPP-MS-Time- Zone}','%{3GPP-IMEISV}','%{TMO-Charging-Rule-Base-Name}','%{SN-Virtual-APN- Name}','%{SN-Rulebase}')" I always thought buffered-sql server is just a loader of the detail file to db. But it looks like it is working as a real radius server manipulating the Acct-Delay-Time attribute which is IMHO wrong here and should be suppressed somehow. What is your opinion? I am running Debian 7.2, freeradius 2.1.12, kernel 3.2.0-4-amd64 Regards Ales
On 4 Oct 2014, at 07:51, Rygl Aleš <ales@rygl.net> wrote:
Hi all,
I have found an interesting issue related to Acct-Delay-Time attribute when buffered-sql mode is in use. I am not sure if it is a bug or feature. IMHO it is a bug but I would like to discuss it here.
I am using freeradius for accounting in buffered-sql mode with MySQL backend. The main radacct table is using memory engine so it is pretty fast nevertheless the buffered-sql mode is a must. We have more 1.000 Acct req/sec in average with additional repeated peaks. We need to store the Acct-Delay-Time for diagnostic purposes. It is not always present in the Accounting request from NAS but if it is there it indicates that NAS is experiencing some performance problems.
And the issue is that even if there is no Acct-Delay-Time received from the NAS, it appears in radacct table then and from my observations it has nothing to do with the real delay of the session start and indicates just the amount of time for which the record was waiting in radacct/detail.work file. IMHO this is wrong because the SQL scripts in dialup.conf are doing a correction of session start time based using Acct-Delay-Time.
My accounting-start-query:
accounting_start_query = "INSERT into ${acct_table1} (AcctUpdateTime, AcctSessionId, AcctUniqueId, UserName, NASIPAddress, AcctStartTime, AcctSessionTime, AcctAuthentic, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, FramedIPAddress, AcctStartDelay, AcctStopDelay, SgsnIpAddr, Imsi, 3GPPSelectionMode, 3GPPGPRSNegotiatedQoSProfile, Acct_Status_Type, 3GPPChargingId, 3GPPNSAPI, 3GPPSGSNMNCMCC, 3GPPRATType, 3GPPUserLocationInfo, 3GPPMSTimezone, 3GPPIMEISV, TMOChargingRuleBaseName, SNVirtualAPNName, SNRulebase) values('%S', '%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{NAS-IP-Address}', DATE_SUB('%S', INTERVAL %{Acct-Delay-Time:-0} SECOND), '0', '%{Acct-Authentic}', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0','%{3GPP-SGSN-Address}','%{3GPP-IMSI}','%{3GPP-Selection-Mode}','%{3GPP-GPRS-Negotiated-QoS-profile}','%{Acct-Status-Type}','%{3GPP-Charging-ID}','%{3GPP-NSAPI}','%{3GPP-SGSN-MCC-MNC}','%{3GPP-RAT-Type}','%{3GPP-Location-Info}','%{3GPP-MS-Time-Zone}','%{3GPP-IMEISV}','%{TMO-Charging-Rule-Base-Name}','%{SN-Virtual-APN-Name}','%{SN-Rulebase}')"
I always thought buffered-sql server is just a loader of the detail file to db. But it looks like it is working as a real radius server manipulating the Acct-Delay-Time attribute which is IMHO wrong here and should be suppressed somehow. What is your opinion?
No, manipulating Acct-Delay-Time here is correct. It represents the amount of time between the event occurring and the current time. Acct-Delay-Time shouldn't be used directly by the queries to calculate timestamp offsets. On receipt of an Accounting-Request if Event-Timestamp isn't present it should be synthesised from applying the received Acct-Delay-Time to the current time on the RADIUS server. If Event-Timestamp is present it should not be touched. When writing our detail file entries Event-Timestamp should be recorded. The queries in 3.0.x all use Event-Timestamp instead of using Acct-Delay-Time. You could alter you queries to do the same, and add the logic to synthesise Event-Timestamp if absent. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On Saturday 04 of October 2014 15:13:17 Arran Cudbard-Bell wrote:
I always thought buffered-sql server is just a loader of the detail file to db. But it looks like it is working as a real radius server manipulating the Acct-Delay-Time attribute which is IMHO wrong here and should be suppressed somehow. What is your opinion?
No, manipulating Acct-Delay-Time here is correct. It represents the amount of time between the event occurring and the current time.
Well, when forwarding reguests I would understand but as I have already replied to Alan, I am not sure if I understand, why it si done when loading the file to DB.
Acct-Delay-Time shouldn't be used directly by the queries to calculate
timestamp offsets.
On receipt of an Accounting-Request if Event-Timestamp isn't present it
should be synthesised from applying the received
Acct-Delay-Time to the current time on the RADIUS server.
If Event-Timestamp is present it should not be touched.
Yes, we have it always.
When writing our detail file entries Event-Timestamp should be recorded.
The queries in 3.0.x all use Event-Timestamp instead of using Acct-Delay-
Time. You could alter you queries to do the same, and add
the logic to synthesise Event-Timestamp if absent.
I have already checked them and I will start to use Event-Timestamp. Ales
Rygl Aleš wrote:
And the issue is that even if there is no Acct-Delay-Time received from the NAS, it appears in radacct table then and from my observations it has nothing to do with the real delay of the session start and indicates just the amount of time for which the record was waiting in radacct/detail.work file. IMHO this is wrong because the SQL scripts in dialup.conf are doing a correction of session start time based using Acct-Delay-Time.
I'm not sure what you're getting at. Using Acct-Delay-Time is correct, because the packet has been delayed. Otherwise, when there's no Event-Timestamp in the packet, it will assume that the session start time is the SQL *insert* time, not the packet *receive* time. Perhaps you could explain why you think it's wrong to update Acct-Delay-Time. Alan DeKok.
On Saturday 04 of October 2014 15:23:20 Alan DeKok wrote:
I'm not sure what you're getting at. Using Acct-Delay-Time is correct, because the packet has been delayed. Otherwise, when there's no Event-Timestamp in the packet, it will assume that the session start time is the SQL insert time, not the packet receive time.
Perhaps you could explain why you think it's wrong to update Acct-Delay-Time.
Using (and updating) Acct-Delay-Time is correct when the request proxied and internal processing on the Radius server takes some time or there is a retry. If I use this file buffer for doing proxy then it makes sense of course. But I do not see the point updating it when the file is just being loaded to DB. IMHO it matters to store the DB record with correct timestamps (I can use there either Event-Timestamp or %S) and keep the original Acct-Delay-Time here. Let's have following entry in the detail.work file: Sun Oct 5 12:11:31 2014 User-Name = "wap" Calling-Station-Id = "420609065063" NAS-IP-Address = 10.49.32.253 Acct-Status-Type = Start NAS-Identifier = "tmcz-gw1" SN-Software-Version = "15.0 (54515)" Service-Type = Framed-User Framed-Protocol = GPRS-PDP-Context Event-Timestamp = "Oct 5 2014 12:11:21 CEST" Acct-Delay-Time = 10 In this case the %S is "Sun Oct 5 12:11:21 2014", The delay indicates that it is not on time. When I store it using %S for session start I have to use a correction or use Event-Timestamp to get the real session start. The problem is that if there is a huge detail.work file loading it may take some time. Buffered-sql server then updates (or creates if it is not already present in the detail.work file) the Acct-Delay-Time on the time the request was waiting in the detail.work file. If the server manages to load the detail.work file every 20s the Acct-Delay-Time delay stored in DB is then not 10 but 20 or 30s (I am not sure here, it seems to me that previous value is replaced). Now I see I could use Event-Timestamp and %S and reconstruct the delay from them... I hope I manage to explain it. Or maybe I missed something? Ales
Rygl Aleš wrote:
Using (and updating) Acct-Delay-Time is correct when the request proxied and internal processing on the Radius server takes some time or there is a retry. If I use this file buffer for doing proxy then it makes sense of course. But I do not see the point updating it when the file is just being loaded to DB.
Arran and I both explained why it's useful. Perhaps you could read those explanations.
IMHO it matters to store the DB record with correct timestamps (I can use there either Event-Timestamp or %S)
No. Event-Timestamp is time when the event happened. %S is the time when the packet is being processed. It might be a long time after the event. Acct-Delay-Time is the delay between Event-Timestamp and %s. In mathematical terms: Event-Timestamp = %S - Acct-Delay-Time.
In this case the %S is "Sun Oct 5 12:11:21 2014", The delay indicates that it is not on time. When I store it using %S for session start I have to use a correction
The correction is to use Acct-Delay-Time.
The problem is that if there is a huge detail.work file loading it may take some time. Buffered-sql server then updates (or creates if it is not already present in the detail.work file) the Acct-Delay-Time on the time the request was waiting in the detail.work file. If the server manages to load the detail.work file every 20s the Acct-Delay-Time delay stored in DB is then not 10 but 20 or 30s (I am not sure here, it seems to me that previous value is replaced).
Yes. That's exactly how it's supposed to work. You shouldn't be storing Acct-Delay-Time in the database. It's not needed.
Now I see I could use Event-Timestamp and %S and reconstruct the delay from them...
That delay is Acct-Delay-time. Alan DeKok.
On Sunday 05 of October 2014 14:30:37 Alan DeKok wrote:
Rygl Aleš wrote:
Using (and updating) Acct-Delay-Time is correct when the request proxied and internal processing on the Radius server takes some time or there is a retry. If I use this file buffer for doing proxy then it makes sense of course. But I do not see the point updating it when the file is just being loaded to DB.
Arran and I both explained why it's useful. Perhaps you could read those explanations.
Yes, I did, several times :) I have already checked the latest version of sql scripts from freeradius package and I am going to start use Event-Timestamp, it is definitely a better solution.
IMHO it matters to store the DB record with correct timestamps (I can use there either Event-Timestamp or %S)
No. Event-Timestamp is time when the event happened.
%S is the time when the packet is being processed. It might be a long time after the event.
I thought %S corrected by Acct-Delay-Time of course.
Acct-Delay-Time is the delay between Event-Timestamp and %s.
In mathematical terms: Event-Timestamp = %S - Acct-Delay-Time.
Yes.
In this case the %S is "Sun Oct 5 12:11:21 2014", The delay indicates that it is not on time. When I store it using %S for session start I have to use a correction
The correction is to use Acct-Delay-Time.
Yes, It is clear.
The problem is that if there is a huge detail.work file loading it may take some time. Buffered-sql server then updates (or creates if it is not already present in the detail.work file) the Acct-Delay-Time on the time the request was waiting in the detail.work file. If the server manages to load the detail.work file every 20s the Acct-Delay-Time delay stored in DB is then not 10 but 20 or 30s (I am not sure here, it seems to me that previous value is replaced).
Yes. That's exactly how it's supposed to work.
Excuse me, but do not understand. From my point of view I do not see a reason for manipulating Acct-Delay-Time this way and replacing the original value from the request with a new one based on time needed for request processing. If you keep original value, later on, when you query DB, it would be clear when the session started (Event-Timestamp) and how much was the session start packet delayed (Acct-Delay-Time).
You shouldn't be storing Acct-Delay-Time in the database. It's not needed.
Well, we would need to store it from diagnostic reasons. It indicates possible performance problems on the NAS. For exact session start I will start to use Event-Timestamp. Is there a way how to save the original Acct-Delay-Time to DB in buffered-sql mode? Ales
Rygl Aleš wrote:
I thought %S corrected by Acct-Delay-Time of course.
No. It's not.
Excuse me, but do not understand. From my point of view I do not see a reason for manipulating Acct-Delay-Time this way and replacing the original value from the request with a new one based on time needed for request processing.
Arran and I both explained it. If you still don't understand, there's really nothing more I can say.
If you keep original value, later on, when you query DB, it would be clear when the session started (Event-Timestamp) and how much was the session start packet delayed (Acct-Delay-Time).
The session start packet was delayed by the NAS, *and* by FreeRADIUS. If you want to store Acct-Delay-Time as received from the NAS, that's *completely different*. You will need to copy it to another attribute, say "Original-Acct-Delay-Time". The attribute Acct-Delay-Time has a pre-defined meaning. The server updates the Acct-Delay-Time because it's *required* in order to keep the same meaning. When you make Acct-Delay-Time mean something else... you're wrong.
Well, we would need to store it from diagnostic reasons. It indicates possible performance problems on the NAS.
No. Acct-Delay-Time has a pre-existing meaning. Don't change it.
Is there a way how to save the original Acct-Delay-Time to DB in buffered-sql mode?
Yes, copy it to another attribute before writing it to the detail file. Alan DeKok.
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Rygl Aleš