On Asterisk version 12 or 13, callback calls are not billed correctly by a2billing
africallshop opened this issue · 22 comments
ample :
Log from a2billing
[16/04/2016 01:10:38]:[file:Class.RateEngine.php - line:1154 - uniqueid:1460761811.0]:[CallerID:xxxxxxxxxxx]:[CN:5670473373333]:[[CC_RATE_ENGINE_UPDATESYSTEM: usedratecard K=0 - (sessiontime=0 :: dialstatus=ANSWER :: buycost=0 :: cost= : signe_cc_call=-: signe=+)]]
Asterisk CDR :
"5670473373333","xxxxxx","xxxxxx","a2billing",""""" ","SIP/xxxxxx","SIP/xxxxxx","Dial","SIP/xxxxxx,120,L(480000)","2016-04-15 23:10:22","2016-04-15 23:10:22","2016-04-15 23:10:38",16,16,"ANSWERED","DOCUMENTATION","1460761811.0",""
As you can see, the duration time is : 16 secondes.
A2billing gets the sessiontime from $agi->get_variable("ANSWEREDTIME") variable but it seems the beheavior on Asterisk 12 and 13 has changed.
I have no problem with Asterisk 11.
Could you help me please to fix the issue ? I need to upgrade asterisk.
Regards
AfriCallShop.
More info on this:
https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Application_Dial
ANSWEREDTIME - This is the amount of time for actual call.
an issue is opened on this matter: https://issues.asterisk.org/jira/browse/ASTERISK-24620
To overcome this issue we get correct call time from CDR directly:
$agi->get_variable("CDR(answer)");
Please let me know if this works for you.
Cheers
Ok, thanks for your feedback.
On asterisk 11, $agi->get_variable("CDR(answer)") return just Array.
I suppose that $agi->get_variable("CDR(answer)"); works only with asterisk 12 or asterisk 13.
Do you confirm that ?
Rregards
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Tx >> 200 result=1
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Rx << GET VARIABLE ANSWEREDTIME
AGI debug from ASTERISK 11.
CDR(answer) seems to not an AGI variable on Asterisk 11.
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Tx >> 200 result=1 (309)
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Rx << GET VARIABLE DIALSTATUS
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Tx >> 200 result=1 (ANSWER)
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Rx << GET VARIABLE CDR(answer)
[2016-04-18 17:09:51] VERBOSE[26043][C-00000907] res_agi.c: <SIP/56e3f387cf6fe-00001370>AGI Tx >> 200 result=0
Please use this on Asterisk 13.
You may also use CDR(billsec) which is only available in latest Asterisk 13:
this is a new feature:
${CDR(clid)} Caller ID
${CDR(src)} Source
${CDR(dst)} Destination
${CDR(dcontext)} Destination context
${CDR(channel)} Channel name
${CDR(dstchannel)} Destination channel
${CDR(lastapp)} Last app executed
${CDR(lastdata)} Last app's arguments
${CDR(start)} Time the call started.
${CDR(answer)} Time the call was answered.
${CDR(end)} Time the call ended.
${CDR(duration)} Duration of the call.
${CDR(billsec)} Duration of the call once it was answered.
${CDR(disposition)} ANSWERED, NO ANSWER, BUSY
${CDR(amaflags)} DOCUMENTATION, BILL, IGNORE etc
${CDR(accountcode)} The channel's account code.
${CDR(uniqueid)} The channel's unique id.
${CDR(userfield)} The channels uses specified field.
Thanks,
I use ${CDR(billsec)} => Duration of the call once it was answered..
About billing
-> SIP : billing is correct
-> Card number : access number : billing is correct
-> Callback service : sessiontime is not equal to null :). I get a value of sessiontime but it seems incorrect.
Here is the Asterisk CDR. In my case, I shoudn't be have duration of the call = duration of the call once it was answered (2nd leg of my call).
I should be duration of the call > duration of the call once it was answered.
"5670473373333","XXXX","XXXX","a2billing",""""" ","SIP/idt-00000031","SIP/idt-00000037","Dial","SIP/XXXXX,120,L(1020000)","2016-04-18 23:42:24","2016-04-18 23:42:24","2016-04-18 23:42:34",9,9,"ANSWERED","DOCUMENTATION","1461022935.91",""
That's where Asterisk 13 rendered useless until we could figure out something for Callback service we used Asterisk 11 for Callback
We can't wait to use HES protocol introduced in Asterisk 13.
You could play around getting the Unique ID on second leg and fetch the duration from second leg's CDR.
Please let us know if you have any success
Someone was able to properly callback the callback, and could post the solution? I need urgently to migrate from asterisk11 to 13 but I need the callback working perfectly. Thank you
Dear Team, we're having this issue with an A2Billing 2.20 and Asterisk 13.
We've already changed the lines with
$answeredtime = $agi->get_variable("ANSWEREDTIME");
to
$answeredtime = $agi->get_variable("CDR(billsec)");
in Class.RateEngine.php
However it seems not to be working, it gets better than using ANSWEREDTIME but it's not the real answered time when using billsec.
Any help would be greatly appreciated.
Is the $answeredtime for callbacks incorrect because asterisk is counting from the time when the first party has answered and waiting for the second party to answer?
Actually, is not just with the Callback, it's happening with all the calls. The billsec time is not measuring the answered time accurately
Is there a pattern to the inaccurate CDR(billsec) - is it always longer or shorter by X seconds.
Does this mean that you're undercharging customers consistently by 10-13 seconds of call time.
@chris001 , no, we are overcharging customers. The time it shows in the a2billing when placing the CDR(billsec) is about 11 - 13 seconds less than the total duration of the call. (duration-billsec-show = 11 or 13 seconds)
Here are some reports of the tests performed:
start | answer | end | billsec-real | billsec-show | duration
0 | 31 | 52 | 21 | 39 | 52
0 | 42 | 73 | 31 | 60 | 73
0 | 29 | 40 | 11 | 29 | 40
0 | 30 | 61 | 31 | 50 | 61
0 | 28 | 39 | 11 | 28 | 39
we did tests with asterisk 1.8 and asterisk 13. these are the records of the call
I think the failure can be in the starttime, because if we calculate the times these are correct in both versions
@jansuar Is it possible that the reason for the overcharged seconds, because one party didn't hang up the line, so it takes about 10-15 seconds for the line, or their calling app, to realize the other party has hung up the call, and the line/app finally drops the connection?
I'm going to check if the line/app finally drops the connection. Because the party B hang up the line ok.
We kept 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:
-- 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
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<-]
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
[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification
@jansuar Great work, excellent find!
I think, in some billing scenarios, there's a need for CDR(billsec) as Asterisk 12 CDR specification calculates it = the answered time of the initial call.
It would be good to add this feature to Asterisk 12, name it something like, CDR(billsecbridged) = the answered time of the bridged call.
I think you should make this request on Asterisk JIRA to Asterisk 12/13/14 dev team, to provide CDR(billdecbridged), paste all of your researched data, and link to this issue thread here on github.
We kept 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:
-- SIP/sipetb-00000009 is ringing -- SIP/sipetb-00000009 is making progress passing it to SIP/sipetb-00000008 -- SIP/sipetb-00000009 answered SIP/sipetb-000000080x7f2c04002830 - 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
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<-]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
[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification
What is the status on this issue? I think I am having the same issue now with Asterisk 13.
All the built-in variables are useless. ANSWEREDTIME, DIALEDTIME, CDR(billsecs), CDR(duration), you name it. Completely useless. They tell me when I got my DIAL TONE on my switch, not even when the call started going through, and certainly not when my call was answered, which is what I need.
A custom wrapper I wrote gives me the time the call started going through (literally just storing the time before calling Dial()), but this is still insufficient while not as atrocious as the built-in Asterisk vars which are way off base.
I really need a way to actually get the time the most recent channel was answered, for billing purposes. I am overcharging big time now, including charging for calls that are not supposed to make a ticket at all. Partially avoided by explicitly checking for DIALSTATUS = ANSWERED but not enough to avoid charging for quick hangup calls.
This is a very serious bug in Asterisk. I am willing to upgrade from v13 if there is a fix in a newer version.
Just in case this helps someone else, I was recently tasked with bringing an old legacy pbx up-to-date, with a fresh OS, a recent asterisk, etc, and I had to deal with this issue.
On asterisk 18, for cc_card (pin-based/prepaid card) dialing a2billing would report total (leg#1) duration. That's because ANSWEREDTIME returns the total call duration, before bridging the calls (leg#1 with leg#2), whereas the value we needed is now CDR(billsec).
Changing most occurrences of agi->get_variable("ANSWEREDTIME"); to $agi->get_variable("CDR(billsec)", true); has worked well for our setup. I haven't put this under thorough testing, yet initial test show the correct (leg#2 only) call duration.
Sidenote: For our setup, we only had to apply the change on common/lib/Class.RateEngine.php on Lines 1357 and 1450, although -for completeness- I also applied the same change on common/lib/Class.A2Billing.php on Lines 1195, 1335, 1593 and 1738.