ASTERISK-25596: CDR engine dispatching 2 cdrs - one for PartyA and another combined PartyA-PartyB

[Home]

Summary: ASTERISK-25596: CDR engine dispatching 2 cdrs - one for PartyA and another combined PartyA-PartyB

Reporter: Pedro Guillem (pguillem) Labels:

Date Opened: 2015-11-29 20:46:39.000-0600 Date Closed: 2020-01-14 11:14:03.000-0600

Priority: Critical Regression? No

Status: Closed/Complete Components: CDR/General

Versions: 13.6.0 Frequency of
Occurrence Constant

Related
Issues:

Environment: Linux Debian-Jessie (64bit). Compiled from source. Default cdr.conf (from make samples). Attachments:

Description: Normally Asterisk creates a single CDR per call (for both bridged legs).
For some reason, its creating two cdrs per call.

This happens when i upgrade from 1.4 to 13.6. I know there are a lot of changes in 8 years, but this one (if its indeed a change in the cdr engine) is totally meaningless. Why on earth would anyone want 2 cdr records for the same call?

The first cdr that is being dispached is the PartyA (incoming) CDR. It logs almost empty data, with no dstchannel offcourse. I assume its the state of the PartyA alone after Hagnup().

'19591652', '2015-11-29 21:03:02', '<900100>', '900100', '57XXXXXXXXX', 'default', 'SIP/162.XX-XX-XX-00000000', '', 'Hangup', 'rated', '', '0', '', '0', '0', 'ANSWERED', '0', '200121', 'Ether1-1448848954.0', '57XXXXXXX', '00', NULL, '0', NULL

Second CDR is the ONLY desired CDR, which includes relevant information regarding the combined PartyA-PartyB transaction. (Note this one includes the duration, billsec, dstchannel and the bridged call data)

'19591651', '2015-11-29 21:02:34', '<900100>', '900100', '57XXXXXXXX', 'default', 'SIP/162.XX.XX.XX-00000000', 'SIP/vox-00000001', 'Dial', 'rated', '', '0', '20200', '28', '20', 'ANSWERED', '0', '200121', 'Ether1-1448848954.0', '57XXXXXXX', '0', '0', '67', NULL

I tried setting "unanswered=no" in cdr.conf, but the outcome is the same if the call is answered. The engine logs 2 records instead of one.

Werid. Please share some light on what needs to be changed in order to produce ONE single cdr record per call.. NOT an independent CDR for PartyA and a separate one for the bridged call.

I must insist the relevant CDR is the bridged output.. not the PartyA incoming channel.

Best regards, and thanks for any hints.

Pedro

Comments: By: Asterisk Team (asteriskteam) 2015-11-29 20:46:40.829-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: Pedro Guillem (pguillem) 2015-11-29 21:01:25.144-0600

Adding the output of the CDR engine debug messages during a normal call. Kindly note the two records are created and dispatched:

0x7f51f40009a8 - Created CDR for channel SIP/900100-00000002
0x7f51f40009a8 - Transitioning CDR for SIP/900100-00000002 from state NONE to Single
0x7f51f4002bc8 - Created CDR for channel SIP/vox-00000003
0x7f51f4002bc8 - Transitioning CDR for SIP/vox-00000003 from state NONE to Single

Dial Begin message for SIP/900100-00000002, SIP/vox-00000003: 1448665204.00639317

0x7f51f40009a8 - Processing Dial Begin message for channel SIP/900100-00000002, peer SIP/vox-00000003
0x7f51f40009a8 - Updated Party A SIP/900100-00000002 snapshot
0x7f51f40009a8 - Updated Party B SIP/vox-00000003 snapshot
0x7f51f40009a8 - Transitioning CDR for SIP/900100-00000002 from state Single to Dial
0x7f51f4002bc8 - Processing Bridge Leave for SIP/vox-00000003
0x7f51f4002bc8 - Transitioning CDR for SIP/vox-00000003 from state Bridged to Finalized
0x7f51f40009a8 - Transitioning CDR for SIP/900100-00000002 from state Bridged to Finalized
0x7f51f4002bc8 - Beginning finalize/dispatch for SIP/vox-00000003
0x7f51f4002bc8 - Dispatching CDR for Party A SIP/vox-00000003, Party B <none>

Bridge Leave message for SIP/900100-00000002: 1448665215.00246400

0x7f51f4003da8 - Created CDR for channel SIP/900100-00000002
0x7f51f4003da8 - Transitioning CDR for SIP/900100-00000002 from state NONE to Single
0x7f51f4003da8 - Set answered time to 1448665215.248071
0x7f51f4003da8 - Transitioning CDR for SIP/900100-00000002 from state Single to Finalized
0x7f51f40009a8 - Beginning finalize/dispatch for SIP/900100-00000002
0x7f51f40009a8 - Dispatching CDR for Party A SIP/900100-00000002, Party B SIP/vox-00000003
By: Joshua C. Colp (jcolp) 2015-11-30 05:35:41.239-0600

You will need to provide the complete console output and dialplan which produced this to confirm if it is the correct behavior. As well yes, CDR behavior is different in 13 and above. It now conforms to a specification detailed on the wiki[1] and can result in multiple records. The behavior won't be changed unless it's not behaving according to the wiki.

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+12+CDR+Specification
By: Pedro Guillem (pguillem) 2015-12-01 02:09:47.808-0600

As always, Thanks for the prompt reply!.
I will carefully study the link, but a separate CDR for PartyA alone should not be created if the call was connected.. :/

Here is the dialplan (quite simple):
{noformat}
[general]
static=yes
writeprotect=yes

[0]
include => default

[default]
exten => _X.,1,verbose(-----------NORMAL CALL-----------)
include => processcall_normal

[processcall_normal]
exten => _X.,2,Set(PEERIP=${CHANNEL(peerip)})
exten => _X.,n,Set(RECVIP=${CHANNEL(recvip)})

exten => _X.,n,AGI(configurecall.php) ;This script creates some channel variables (routing).. depending on incoming ext and IP

exten => _X.,n,Set(LANGUAGE=ES)
exten => _X.,n,GotoIf($["${ROUTE/size}" = ""]?nobalance)
exten => _X.,n,Set(ROUTE/i=1)

exten => _X.,n,Verbose(--------------------------------------------------)
exten => _X.,n(while),GotoIf($["${ROUTE/size}" < "${ROUTE/i}"]?error) ; Loop trough configured routes
exten => _X.,n,Verbose(Route ${ROUTE/i}: ${ROUTE/${ROUTE/i}})

;Set custom billing stuff on accountcode field
exten => _X.,n(dial),Set(CHANNEL(accountcode)=${ACC_NO}|${DST/${ROUTE/i}}|LCR|${CARRIER/${ROUTE/i}}|${CALLERID(ani)}|N)
exten => _X.,n(dial),Set(CHANNEL(amaflags)=2)
exten => _X.,n(dial),Set(CHANNEL(clid)=${CALLERID(ani)})
exten => _X.,n(dial),Set(CALLERID(num)=${NEWCID})

exten => _X.,n,Progress()
exten => _X.,n,Set(TIMEOUT(absolute)=3600)
exten => _X.,n,Dial(${ROUTE/${ROUTE/i}},60,g)

;Handle all possible scenarios after dial attempt
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "CANCEL"]?tryagain)
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "BUSY"]?tryagain)
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "CHANUNAVAIL"]?tryagain)
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "CONGESTION"]?tryagain)
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "NOANSWER"]?noanswer)
exten => _X.,n,GotoIf($["${DIALSTATUS}" = "ANSWER"]?fin)
exten => _X.,n,Goto(tryagain)

;Loop to next route
exten => _X.,dial+101(tryagain),Set(ROUTE/i=$[${ROUTE/i} + 1])
exten => _X.,n,Goto(while)

exten => _X.,n(error),Congestion
exten => _X.,n(fin),HangUp
exten => _X.,n(noanswer),Busy

exten => _X.,n,HangUp
{noformat}

By: Richard Mudgett (rmudgett) 2015-12-01 11:23:43.112-0600

In the future please *attach* logs and large configuration files as *files* rather than pasting the contents in a comment.
By: Pedro Guillem (pguillem) 2015-12-01 12:51:10.684-0600

My apologies. Will do
By: Pedro Guillem (pguillem) 2015-12-02 20:25:23.612-0600

Just switched to Asterisk 11.20 and the dialplan works as expected.
I will stick to this version for now.. i presume.

I went trough the new CDR docs and fully understood how the system is shooting the CDRs nowdays, i still however couldn't think of a reason version >12 engine is dispatching an additional CDR for PartyA if the call was successfully bridged to PartyB.

What do you guys think?
By: Rusty Newton (rnewton) 2015-12-07 17:07:26.337-0600

Pedro you should attach the complete console(or logfile) output as [~jcolp] requested. Here are the instructions:

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

Attach the log output demonstrating the call itself along with a correlating CDR log.

Thanks.
By: Asterisk Team (asteriskteam) 2015-12-22 12:00:21.712-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Denis Olenev (venoel) 2017-01-19 04:48:50.810-0600

I had similar problem.

Asterisk certified/13.8-cert4

One call produced two record. One correct record, second record had the same values except 'start','end','answered' fields, which was empty.

The reason of duplicates record - cdr_odbc.so module.
{noformat}
# asterisk -rx "module show like odbc"
Module Description Use Count Status Support Level
cdr_adaptive_odbc.so Adaptive ODBC CDR backend 0 Running core
cdr_odbc.so ODBC CDR Backend 0 Running extended
cel_odbc.so ODBC CEL backend 0 Running core
func_odbc.so ODBC lookups 0 Running core
res_config_odbc.so Realtime ODBC configuration 0 Running core
res_odbc.so ODBC resource 0 Running core
res_odbc_transaction.so ODBC transaction resource 0 Running core
7 modules loaded
{noformat}

I turn him off in modules.conf
{noformat}
'noload => cdr_odbc.so'
{noformat}

Restart server and things is fine.