ASTERISK-24652: Confbridge interaction with CDR

[Home]

Summary: ASTERISK-24652: Confbridge interaction with CDR

Reporter: Jonathan White (londonnet) Labels:

Date Opened: 2014-12-30 07:58:56.000-0600 Date Closed: 2015-01-13 21:44:27.000-0600

Priority: Major Regression?

Status: Closed/Complete Components: Applications/app_cdr Applications/app_confbridge

Versions: 13.0.2 Frequency of
Occurrence Constant

Related
Issues:

Environment: centos6 i386 Attachments: ( 0) full
( 1) full

Description: I have noticed CDR is not reporting the correct duration for some calls.

In my case I have calls being answered and a dialplan request for a pin before placing the caller into a confbridge.

In some instances the duration of the call is reported to be the number of seconds before the call is placed into confbridge but none of the confbridge seconds are reported.

If I put a second call into the same bridge the first call will report the correct call duration but the second call will report the duration of the call up to the point it is placed into the confbridge.

My cdr config is simple. I am using CDR adaptive
{noformat}
[asterisk]
connection=asterisk-odbc
table=ast_cdr
alias start => calldate
{noformat}
In addition I get a double entry for the CDR(userfield) I assume the combination of the two channels in the confbridge but this is only for the first call which enters the bridge not the second.

Below is an example of the CDR output. The first line is the first call which shows the correct duration and billsec of 43 seconds. It also shows a double entry for CDR(userfield) Bridge-1005;Bridge-1005
{noformat}
"2014-12-28 02:31:00";"""2581"" <2581>";"2581";"1001";"apps";"SIP/2581-00000010";"SIP/2581-00000011";"ConfBridge";"1005,,user_admin,menu_admin";"43";"43";"ANSWERED";"3";;"1419733860.55";"Bridge-1005;Bridge-1005"
{noformat}
The second call only reports 18 seconds for billsec which is the amount of time the call lasts before being placed into the confbridge. This CDR record reports corectly the CDR(userfield) as Bridge-1005
{noformat}
"2014-12-28 02:31:22";"""2581"" <2581>";"2581";"1001";"apps";"SIP/2581-00000011";;"ConfBridge";"1005,,user_participant,menu_participant";"19";"18";"ANSWERED";"3";;"1419733882.59";"Bridge-1005"
{noformat}
My suspicion is there is an issue with how confbridge interacts with CDR

Comments: By: Rusty Newton (rnewton) 2015-01-02 14:34:31.760-0600

To help us further investigate - we need some additional debug:

Please provide an Asterisk log with the "DEBUG" logger channel enabled, showing during the time of the CDR processing.

[You can find instructions linked here|https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information]

Please include the correlating CDR output for the Asterisk logs.

In addition please provide examples of cases that don't have an issue and cases that do. Thanks!
By: Jonathan White (londonnet) 2015-01-02 15:07:49.912-0600

A debug of an example call replicating the error
By: Jonathan White (londonnet) 2015-01-02 15:10:45.035-0600

Please find attached a debug of the following call placed from extension 2581 and produced the following cdr records

"2015-01-02 21:20:25","""2581"" <2581>","2581","1001","apps","SIP/2581-00000003","SIP/2581-00000004","ConfBridge","1005,,user_admin,menu_admin","60","60","ANSWERED","3",,"1420233625.30","Bridge-1005;Bridge-1005"
"2015-01-02 21:20:53","""2581"" <2581>","2581","1001","apps","SIP/2581-00000004",,"ConfBridge","1005,,user_participant,menu_participant","21","21","ANSWERED","3",,"1420233653.37","Bridge-1005"
By: Matt Jordan (mjordan) 2015-01-07 10:51:22.079-0600

# The entries in the userfield are what I would expect if you had set the userfield data on both parties involved in the CDR. From https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification:
{quote}
A user defined field set on the channels. If set on both the Party A and Party B channel, the userfields of both are concatenated and separated by a ;
{quote}
# While your log file is helpful, it doesn't show why the CDR engine made the decisions it made. Please provide a log file with 'cdr set debug on' enabled.
By: Jonathan White (londonnet) 2015-01-12 16:57:49.832-0600

A new debug with cdr debug enabled
By: Jonathan White (londonnet) 2015-01-12 16:58:14.200-0600

additional debug attached. Thanks
By: Jonathan White (londonnet) 2015-01-12 17:09:25.251-0600

I have re run the same call and enabled cdr debugging. debug attached

If it is normal operation for the userfield field to be concatenated with bridged calls why does it only concatenate the first calls cdr record and not the second?

If I created an additional cdr field and set that variable would that also concatenate?

Thanks
By: Matt Jordan (mjordan) 2015-01-13 21:21:29.940-0600

So here is what is actually occurring in the CDR engine in this scenario:

We first create a CDR for {{SIP/2581-00000003}}. When a channel is first created, it gets a CDR for its execution in the dialplan (this is represented by it being placed in the *Single* state - that is, it is a single party):
{noformat}
[2015-01-12 22:48:46] VERBOSE[2863] cdr.c: 0xb7303464 - Created CDR for channel SIP/2581-00000003
[2015-01-12 22:48:46] VERBOSE[2863] cdr.c: 0xb7303464 - Transitioning CDR for SIP/2581-00000003 from state NONE to Single
[2015-01-12 22:48:46] VERBOSE[2863] cdr.c: 0xb7303464 - Set answered time to 1421102926.958939
{noformat}

When {{SIP/2581-00000003}} enter {{ConfBridge}}, it is placed into a bridge. In Asterisk 12+, a bridge, is a bridge, is a bridge. Bridges that are part of a conference are no different than bridges that are created as a result of Queue, or Dial, or ARI. As a result, we can expect that this channel is going to get paired with another channel - or, in the case of a ConfBridge, multiple channels. As such, we transition it to the *Bridged* state. The 'finalization' that occurs temporarily saves the timestamps that we have for the channel's CDR, including its Answered time.
{noformat}
[2015-01-12 22:49:06] VERBOSE[2863] cdr.c: Bridge Enter message for channel SIP/2581-00000003: 1421102946.00324322
[2015-01-12 22:49:06] VERBOSE[2863] cdr.c: 0xb7303464 - Updating Party A SIP/2581-00000003 snapshot
[2015-01-12 22:49:06] VERBOSE[2863] cdr.c: 0xb7303464 - Processing bridge enter for SIP/2581-00000003
[2015-01-12 22:49:06] VERBOSE[2863] cdr.c: 0xb7303464 - Transitioning CDR for SIP/2581-00000003 from state Single to Bridged
[2015-01-12 22:49:06] DEBUG[2863] cdr.c: Finalized CDR for SIP/2581-00000003 - start 1421102926.812025 answer 1421102926.958939 end 1421102946.324842 dispo ANSWERED
{noformat}

Now we have another channel, {{SIP/2581-00000004}}. Once again, we make a CDR for it and set it to the *Single* state.
{noformat}
[2015-01-12 22:49:07] VERBOSE[2863] cdr.c: 0xb7319cec - Created CDR for channel SIP/2581-00000004
[2015-01-12 22:49:07] VERBOSE[2863] cdr.c: 0xb7319cec - Transitioning CDR for SIP/2581-00000004 from state NONE to Single
[2015-01-12 22:49:07] VERBOSE[2863] cdr.c: 0xb7319cec - Set answered time to 1421102947.961423
{noformat}

Eventually, {{SIP/2581-00000004}} also goes into the ConfBridge. This causes it to be placed into the same bridge, and we transition its existing CDR to *Bridged*. In the same fashion as {{SIP/2581-000000003}}, we finalize the CDR to save its Answered time.

When two channels are bridged, we should only have a single CDR for the communication path between those channels. As such, we pick a Party A (which is {{SIP/2581-00000003}}) and set this channel as the Party B.

{noformat}
[2015-01-12 22:49:30] VERBOSE[2863] cdr.c: Bridge Enter message for channel SIP/2581-00000004: 1421102970.00933303
[2015-01-12 22:49:30] VERBOSE[2863] cdr.c: 0xb7319cec - Updating Party A SIP/2581-00000004 snapshot
[2015-01-12 22:49:30] VERBOSE[2863] cdr.c: 0xb7319cec - Processing bridge enter for SIP/2581-00000004
[2015-01-12 22:49:30] VERBOSE[2863] cdr.c: 0xb7319cec - Transitioning CDR for SIP/2581-00000004 from state Single to Bridged
[2015-01-12 22:49:30] DEBUG[2863] cdr.c: Finalized CDR for SIP/2581-00000004 - start 1421102947.701149 answer 1421102947.961423 end 1421102970.936450 dispo ANSWERED
[2015-01-12 22:49:30] VERBOSE[2863] cdr.c: 0xb7303464 - Party A SIP/2581-00000003 has new Party B SIP/2581-00000004
{noformat}

This would create the behaviour you don't like. In Asterisk 12+, a bridge, is a bridge, is a bridge. Once two parties have been put into a bridge, we collapse down the CDRs that are present to represent the paths of communication between the respective parties. Because {{SIP/2581-00000003}} had no party B, and was determined to be the Party A in the path of communication between itself and the other party in the bridge, it gains {{SIP/2581-00000004}} as the Party B in its existing CDR.

Finally, we get some people leaving the ConfBridge. First, {{SIP/2581-00000004}} leaves, which finalizes their path of communication with {{SIP/2581-00000003}}. This dispatches the CDR for the two parties on {{SIP/2581-00000003}}.
{noformat}
[2015-01-12 22:49:31] VERBOSE[2863] cdr.c: Bridge Leave message for SIP/2581-00000004: 1421102971.00628965
[2015-01-12 22:49:31] VERBOSE[2863] cdr.c: 0xb7319cec - Processing Bridge Leave for SIP/2581-00000004
[2015-01-12 22:49:31] VERBOSE[2863] cdr.c: 0xb7319cec - Transitioning CDR for SIP/2581-00000004 from state Bridged to Finalized
[2015-01-12 22:49:31] DEBUG[2863] cdr.c: Finalized CDR for SIP/2581-00000003 - start 1421102926.812025 answer 1421102926.958939 end 1421102971.631111 dispo ANSWERED
{noformat}

One second later, {{SIP/2581-00000003}} leaves the ConfBridge. That causes us to finalize their CDR.
{noformat}
[2015-01-12 22:49:32] VERBOSE[2863] cdr.c: Bridge Leave message for SIP/2581-00000003: 1421102972.00521984
[2015-01-12 22:49:32] VERBOSE[2863] cdr.c: 0xb7303464 - Processing Bridge Leave for SIP/2581-00000003
[2015-01-12 22:49:32] VERBOSE[2863] cdr.c: 0xb7303464 - Transitioning CDR for SIP/2581-00000003 from state Bridged to Finalized
{noformat}

Lastly, when the two channels hang up, we dispatch their CDRs.
{noformat}
[2015-01-12 22:49:38] VERBOSE[2863] cdr.c: 0xb7319cec - Beginning finalize/dispatch for SIP/2581-00000004
[2015-01-12 22:49:38] VERBOSE[2863] cdr.c: 0xb7319cec - Dispatching CDR for Party A SIP/2581-00000004, Party B <none>
[2015-01-12 22:49:41] VERBOSE[2863] cdr.c: 0xb7303464 - Beginning finalize/dispatch for SIP/2581-00000003
[2015-01-12 22:49:41] VERBOSE[2863] cdr.c: 0xb7303464 - Dispatching CDR for Party A SIP/2581-00000003, Party B SIP/2581-00000004
{noformat}

We can see this in the resulting CDRs that are sent to the backend:
{noformat}
11680:[2015-01-12 22:49:38] DEBUG[2863] cdr_adaptive_odbc.c: Executing [INSERT INTO ast_cdr (calldate,clid,src,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,userfield) VALUES ({ ts '2015-01-12 22:49:07' },'"2581" <2581>','2581','1001','apps','SIP/2581-00000004','ConfBridge','1005,,user_participant,menu_participant',23,22,'ANSWERED',3,'1421102947.13','Bridge-1005')]
11845:[2015-01-12 22:49:41] DEBUG[2863] cdr_adaptive_odbc.c: Executing [INSERT INTO ast_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,userfield) VALUES ({ ts '2015-01-12 22:48:46' },'"2581" <2581>','2581','1001','apps','SIP/2581-00000003','SIP/2581-00000004','ConfBridge','1005,,user_admin,menu_admin',44,44,'ANSWERED',3,'1421102926.9','Bridge-1005;Bridge-1005')]
{noformat}

That is, the first CDR - the one for {{SIP/2581-00000004}} - represents the time that channel was in the system by itself. However, since it became a Party B for {{SIP/2581-00000003}}, its remaining time is part of that CDR. The second CDR represents the total time {{SIP/2581-00000003}} was in the system, plus the time it communicated with {{SIP/2581-00000004}}.

This is in line with what the CDR specification says will happen:

https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification#Asterisk12CDRSpecification-ConferenceCall

Note that if you want to control the CDRs in a more fine-grained fashion, you can use the ForkCDR or CDR_PROP functions. If you want CDRs for the time that channels were in the system prior to going into the ConfBridge, Fork the CDRs prior to going into the ConfBridge. If you want only the time the channels were in the ConfBridge, disable the CDR, Fork it, then enable the new CDR.
By: Jonathan White (londonnet) 2015-01-14 19:32:42.059-0600

Thank you for the very detailed explanation, it is greatly appreciated.

We were simply expecting Asterisk to log individual calls from the time Asterisk answers to the time Asterisk hangs up on a per call basis.

Although we see the benefit of being able to track how calls interact with each other the fundamental use of CDR is log call start and call hang-up which in this instance (quite a common call scenario) Asterisk fails to provide, it's not even that clear what will be logged and when in different call scenarios.

At present we feel Asterisk is producing inaccurate and incomplete CDR records.

We can't see there is an option to capture the entire call duration in a single record. Is there an answer to this issue?

Thanks again for you kind support.
By: Matt Jordan (mjordan) 2015-01-14 20:26:04.493-0600

The CDR specification is pretty clear about this:

[https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification]

{quote}
CDR Overview

A CDR is a record of communication between one or two parties. As such, a single CDR always addresses the communication between two parties: a Party A and a Party B. The CDR reflects the view of the call from the perspective of Party A, while Party B is the party that Party A is communicating with. Each CDR includes the following times:

* Start time - the time at which the CDR was created for Party A
* Answer time - the time at which Party A and Party B could begin communicating
* End time - the time at which Party A and Party B could no longer communicate

From these times, two durations are computed:

* Duration - the End time minus the Start time.
* Billsec - the End time minus the Answer time. (Whether or not you actually bill for this period of time is up to you)

A single CDR only tracks information about a single path of communication between two endpoints. In many scenarios, there will be multiple paths of communication between multiple parties, even in a single "call". Each path of communication results in a new CDR, each representing the communication between two endpoints. All of the CDRs involved are associated by virtue of a special linked identifier field, linkedid. The CDRs themselves, however, typically do not aggregate the time between records. It is up to billing systems to determine which CDRs should be used for their billing records, and add up the times/durations themselves.
{quote}

As the CDR specification states, a CDR represents a path of communication between two parties. A single CDR is not going to be able to account for:
* Multiple aggregate time periods, which is what occurs in your scenario.
* Any time multiple parties are involved, which is what occurs often in ConfBridge.

As I stated previously, Asterisk provides you the tools to have finer grained control over the CDRs:
{quote}
Note that if you want to control the CDRs in a more fine-grained fashion, you can use the ForkCDR or CDR_PROP functions. If you want CDRs for the time that channels were in the system prior to going into the ConfBridge, Fork the CDRs prior to going into the ConfBridge. If you want only the time the channels were in the ConfBridge, disable the CDR, Fork it, then enable the new CDR.
{quote}

Barring that, Asterisk provides CEL, so that you can build your own billing system on top of the channel events.
By: Jonathan White (londonnet) 2015-01-15 08:32:52.360-0600

Thanks again for your support.

I performed a much simpler test which is just to have a single call be answered by Asterisk and then drop into a confbridge. At the point of the single call joining the bridge CDR stops. A single CDR is generated which reading the spec above should either create a single CDR for the duration of the entire call or multiple CDR's as Party A creates a new communication path. This does not happen

I perhaps take the point that when there are multiple calls which join you could say the leg of the second caller is joined with the first caller and therefore the second call terminates. (not what I would expect but if that's how it works I'll have to work round that) but this is inconsistent when a single call which joins a confbridge stops logging at the point of entering where as when there are two calls the second call stops but the first calls CDR continues to log time

In this instance the CDR does not record time spent in the confbridge by itself nor does it create a separate CDR which the documentation suggests.

I have enabled CEL to compare the output and this does log all the events but no duration of each record. If you are supposed to calculate the time between events or first event and last I could see this being possible using the unique id but I feel this is the job of CDR which is behaving inconsistently.

Do you agree that a single call should either produce a CDR for full duration of the call or at least multiple CDR's?

It shouldn't stop just because Party A enters a bridge.
By: Jonathan White (londonnet) 2015-01-21 16:53:22.740-0600

Can we discuss this issue further, possibly reopen this ticket? I don't think CDR is behaving consistently when it interacts with confbridge.

CDR stops tracking time when a call is placed into conference and only starts tracking time again when a second call joins the bridge. Why is the first call treated differently from the second and third?

I'm struggling to see how the spec for CDR involving bridges is fit for purpose.

Thanks