[Home]

Summary:ASTERISK-27425: Calls are not billed correctly by a2billing - Asterisk 12 and 13
Reporter:Andrea Suarique (jansuar)Labels:
Date Opened:2017-11-16 08:54:59.000-0600Date Closed:2017-12-27 18:45:24.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_dial CDR/General Functions/func_cdr
Versions:13.13.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:A2Billing 2.20 and Asterisk 13.13-current Attachments:( 0) cdr_log.txt
( 1) cdr_log2.txt
Description:The CDR(billsec) and (ANSWEREDTIME) is not measuring the answered time accurately.

We debugging the issue and found what may the problem be.
According to [1] it seem that the CDR(billsec) is registering the answered time of the initial call and not the answered time of the bridged one (I mean after dialing the number on the DISA and the other party answering the call )

We CDR debug we found the right answered time data in the bridged CDR thread as shown in this log:
{noformat}
   -- SIP/sipetb-00000009 is ringing
   -- SIP/sipetb-00000009 is making progress passing it to SIP/sipetb-00000008
   -- SIP/sipetb-00000009 answered SIP/sipetb-00000008
0x7f2c04002830 - Set answered time to 1510800709.529550
Dial End message for SIP/sipetb-00000008, SIP/sipetb-00000009: 1510800709.00529783
0x7f2c04000970 - Processing Dial End message for channel SIP/sipetb-00000008, peer SIP/sipetb-00000009
0x7f2c04000970 - Transitioning CDR for SIP/sipetb-00000008 from state Dial to DialedPending
   -- Channel SIP/sipetb-00000009 joined 'simple_bridge' basic-bridge <40047399-8742-427f-8b36-e9f4eec1f8bc>
Bridge Enter message for channel SIP/sipetb-00000009: 1510800709.00529977
0x7f2c04002830 - Updating Party A SIP/sipetb-00000009 snapshot
0x7f2c04002830 - Processing bridge enter for SIP/sipetb-00000009
0x7f2c04002830 - Transitioning CDR for SIP/sipetb-00000009 from state Single to Bridged
   -- Channel SIP/sipetb-00000008 joined 'simple_bridge' basic-bridge <40047399-8742-427f-8b36-e9f4eec1f8bc>
     
Bridge Enter message for channel SIP/sipetb-00000008: 1510800709.00530039
0x7f2c04000970 - Updating Party A SIP/sipetb-00000008 snapshot
0x7f2c04000970 - Processing bridge enter for SIP/sipetb-00000008
0x7f2c04000970 - Transitioning CDR for SIP/sipetb-00000008 from state DialedPending to Dial
0x7f2c04000970 - Transitioning CDR for SIP/sipetb-00000008 from state Dial to Bridged
   -- Remote UNIX connection
   -- Remote UNIX connection disconnected
   -- Remote UNIX connection
   -- Remote UNIX connection disconnected
   -- Remote UNIX connection
   -- Remote UNIX connection disconnected
   -- Channel SIP/sipetb-00000009 left 'simple_bridge' basic-bridge <40047399-8742-427f-8b36-e9f4eec1f8bc>
   -- Channel SIP/sipetb-00000008 left 'simple_bridge' basic-bridge <40047399-8742-427f-8b36-e9f4eec1f8bc>
Bridge Leave message for SIP/sipetb-00000009: 1510800739.00509557

0x7f2c04002830 - Processing Bridge Leave for SIP/sipetb-00000009
0x7f2c04002830 - Transitioning CDR for SIP/sipetb-00000009 from state Bridged to Finalized
0x7f2c04000970 - Transitioning CDR for SIP/sipetb-00000008 from state Bridged to Finalized
0x7f2c04002830 - Beginning finalize/dispatch for SIP/sipetb-00000009
0x7f2c04002830 - Dispatching CDR for Party A SIP/sipetb-00000009, Party B <none>
Bridge Leave message for SIP/sipetb-00000008: 1510800739.00509705
a2billing_cc3.php,6: file:Class.RateEngine.php - line:1281 - uniqueid:1510800680.13 - DIAL SIP/sipetb/033168456954,60,rL(20460000:0)
a2billing_cc3.php,6: file:Class.RateEngine.php - line:1164 - uniqueid:1510800680.13 - [TRUNK STATUS UPDATE : UPDATE cc_trunk SET inuse=inuse-1 WHERE id_trunk='2']
a2billing_cc3.php,6: file:Class.RateEngine.php - line:1433 - uniqueid:1510800680.13 - -> dialstatus : ANSWER, answered time is 47
a2billing_cc3.php,6:
a2billing_cc3.php,6: file:Class.RateEngine.php - line:1437 - uniqueid:1510800680.13 - [USEDRATECARD=0]
a2billing_cc3.php,6: file:a2billing_cc3.php - line:736 - uniqueid:1510800680.13 - :[DIALEDTIME: ->59<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:740 - uniqueid:1510800680.13 - :[DIALSTATUS: ->ANSWER<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:744 - uniqueid:1510800680.13 - :[CDRSTARTTIME: ->2017-11-15 21:51:31<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:748 - uniqueid:1510800680.13 - :[CDRANSWER: ->2017-11-15 21:51:31<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:752 - uniqueid:1510800680.13 - :[CDRend: ->2017-11-15 21:52:19<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:756 - uniqueid:1510800680.13 - :[CDRduration: ->47<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:760 - uniqueid:1510800680.13 - :[CDRbillsec: ->47<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:764 - uniqueid:1510800680.13 - :[CDRdisposition: ->ANSWERED<- ]17366200
a2billing_cc3.php,6: file:a2billing_cc3.php - line:768 - uniqueid:1510800680.13 - :[ANSWERED: ->59<-]
{noformat}
What we need to do is to make the CDRANSWER variable to take the answered time registered in CDR thread 0x7f2c04002830 instead of using the one provided by the CDR thread 0x7f2c04000970
Comments:By: Asterisk Team (asteriskteam) 2017-11-16 08:55:00.256-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Richard Mudgett (rmudgett) 2017-11-16 15:24:21.731-0600

Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. Please read over the Asterisk Issue Guidelines [1] which discusses the information necessary for your issue to be resolved and the format that information needs to be in. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need:

1. The specific steps or actions you took that caused you to encounter the problem.
2. The behavior you expected and the location of documentation that led you to that expectation.
3. The behavior you actually encountered.

To demonstrate the issue in detail, please include Asterisk log files generated per the instructions on the wiki [2]. If applicable, please ensure that protocol-level trace debugging is enabled, e.g., 'sip set debug on' if the issue involves chan_sip, and configuration information such as dialplan and channel configuration.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines

[2] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Please supply information from Asterisk itself to demonstrate the problem as the problem may be in how a2billing is interpreting the CDR records output by Asterisk.

Is this a straight call where A calls B and then the call ends?

Attach any logs to the issue with a .txt file extension.
By: Andrea Suarique (jansuar) 2017-11-19 21:08:14.878-0600

Hi,
Complement the description of the problem :

1. We were using Asterisk 1.8 and upgraded to Asterisk 13.13-current.  After this  upgrade we've found that the Answered time registered by Asterisk was no longer the actual call time according to [1] so we start using CDR(billsec), however we've noticed that the right time is not being registered.   After debugging the issue according to [2] we found that the right billsec time is being registered in the bridged CDR thread according to the logs attached.

2. The behavior expected is to have the bridged call cdr time registered instead of the time being registered right now which is the time from the initial call and not the bridged one.  This is a DISA service.

3. The behavior encountered is that the CDR registered is the one from the complete call and not the bridged one.

According to this issue [3] it may be possible to do that what we want but is not clear how.

Attached log of the tests performed cdr_log2.txt

Thanks in advance for your help

[1] ASTERISK-25336
[2] https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification
[3] ASTERISK-24652

By: Andrea Suarique (jansuar) 2017-11-19 21:10:29.890-0600

Attached log of the tests performed
By: Andrea Suarique (jansuar) 2017-12-01 07:34:15.698-0600

Could you tell me about any progress on the case please?
By: Joshua C. Colp (jcolp) 2017-12-01 07:42:07.841-0600

This issue is currently in triage. It will be triaged in the future and any updates or progress mentioned here.
By: Benjamin Keith Ford (bford) 2017-12-05 17:09:35.831-0600

[~jansuar], can you provide some clarity on the issue you're having? What are the exact steps you're taking to produce the issue? Testing with one channel bridged to another returns the correct CDR(billsec), DIALEDTIME, and ANSWEREDTIME on my end, so more information is needed.
By: Andrea Suarique (jansuar) 2017-12-13 14:36:35.244-0600

Benjamin, In the attached log "cdr log2.txt" we see three responses at different times and a time in the hang of the call in CDR threads 0x7f2c04000970 and 0x7f2c04002830

A1 -> 0x7f2c04000970 - Set answered time to 1510800680.251299 02:51:20
A2 -> 0x7f2c04000970 - Set answered time to 1510800691.936315 02:51:31
A3 -> 0x7f2c04002830 - Set answered time to 1510800709.529550 02:51:49

H1 -> 0x7f2c04000970 -> Bridge Leave message for SIP/sipetb-00000009: 1510800739.00509557 02:52:19
H2 -> 0x7f2c04002830 -> Bridge Leave message for SIP/sipetb-00000008: 1510800739.00509705 02:52:19

What we need to do is to make the CDRANSWER variable to take the answered time registered in CDR thread 0x7f2c04002830 instead of using the one provided by the CDR thread 0x7f2c04000970(that is, the duration of the actual call between H2- A3 = 02: 52: 19 - 02:51:49 = 30 sec)

The variable CDR (billsec) shows the time between H1 - A2 = 02:52:19 - 02:51:31 = 48 sec
The variable DIALEDTIME shows the time between H1 - A1 = 02:52:19 - 02:51:20 = 59 sec
The variable ANSWEREDTIME shows the time between H1 - A1 = 02:52:19 - 02:51:20 = 59
By: Joshua C. Colp (jcolp) 2017-12-22 07:22:47.453-0600

I've looked over this issue and discussed it with the creator of the CDR support present as of Asterisk 12. I can certainly see how a behavior change would benefit A2Billing but this would be considered a new feature to accommodate its usage and needs. It would also need to be done in a backwards compatible fashion.

Since new feature requests are not something we commonly keep open on the issue tracker I'm placing this back into feedback to ask if this is something you would be approaching. We would certainly provide help and answers to questions as we can.
By: Andrea Suarique (jansuar) 2017-12-27 16:18:16.071-0600

Joshua, What you indicate is that there is no a feature for this query? in this case, how could I do the correct query as it was done with the previous versions of 12 asterisk? because with the version of asterisk 1.8 the variables DIALEDTIME and ANSWEREDTIME showed the duration of the actual call between correctly, and these didn't show the same time value how does this version of asterisk 13.
By: Joshua C. Colp (jcolp) 2017-12-27 16:22:42.130-0600

The CDR support was not written to work that way and has no feature to do that, no. There is no "correct query" that you can do without modifying the code to do it in some fashion or externally interpreting CEL/CDR records in some fashion to deduce it.
By: Joshua C. Colp (jcolp) 2017-12-27 18:45:24.175-0600

I'm suspending this issue since it is a new feature request. You may want to try other communication resources, such as https://community.asterisk.org/ to see how others are using CDRs and if they have any suggestions.