[asterisk-bugs] [JIRA] (ASTERISK-24652) Confbridge interaction with CDR
Matt Jordan (JIRA)
noreply at issues.asterisk.org
Tue Jan 13 21:45:34 CST 2015
[ https://issues.asterisk.org/jira/browse/ASTERISK-24652?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=224441#comment-224441 ]
Matt Jordan edited comment on ASTERISK-24652 at 1/13/15 9:44 PM:
-----------------------------------------------------------------
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.
was (Author: mjordan):
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.
{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
{noformat}
When this occurs, we dispatch out the CDR that was created for the channel up to this point. This is actually somewhat of a special case, as we'll see later. The reason why we save off {{SIP/2581-00000003}} is because they are the first one into the bridge - ostensibly, we assume that they are the first party into the bridge, and we can save the CDR information that was accumulated for them while they executed dialplan.
{noformat}
[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 representing the dialplan execution. Now we have some decisions to make.
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}
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
[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
[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}
> Confbridge interaction with CDR
> -------------------------------
>
> Key: ASTERISK-24652
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-24652
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Applications/app_cdr, Applications/app_confbridge
> Affects Versions: 13.0.2
> Environment: centos6 i386
> Reporter: Jonathan White
> Assignee: Rusty Newton
> Attachments: full, full
>
>
> 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
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list