| Summary: | ASTERISK-24839: CDRs: LinkedID field in Attended Transfer not reporting as expected | ||||
| Reporter: | Jonas Swiatek (jonasswiatek) | Labels: | |||
| Date Opened: | 2015-02-27 18:54:35.000-0600 | Date Closed: | 2015-03-26 09:41:30 | ||
| Priority: | Critical | Regression? | |||
| Status: | Closed/Complete | Components: | CDR/cdr_adaptive_odbc CDR/General | ||
| Versions: | 13.2.0 | Frequency of Occurrence | Constant | ||
| Related Issues: |
| ||||
| Environment: | Linux CentOS6 (Amazon Linux on AWS EC2) | Attachments: | ( 0) asterisk.conf ( 1) cdr_adaptive_odbc.conf ( 2) cdr_issue_log.txt ( 3) cdr.conf ( 4) extconfig.conf ( 5) extensions.conf ( 6) sip.conf | ||
| Description: | Initial report made here: http://forums.asterisk.org/viewtopic.php?f=1&t=92599, and malcolmd has directed me to create this issue.
Asterisk doesn't generate CDR Data it should according to the Asterisk 12 CDR Specification for the "Attended Transfer to Channel"-scenario. *\[EDIT\]*: [~mjordan]: I've copied/pasted the actual error from the forums here, as this is the important bit: {quote} What I get in my CDR records is: || seq || src || dst || dcontext || uniqueid || linkedid || | 141 | 682 | 850 | act-22575 | 1424894097.687 | 1424894097.687 | | 143 | 850 | 851 | act-22575 | 1424894105.695 | 1424894105.695 <- notice linkedid different | | 145 | 682 | 850 | act-22575 | 1424894097.687 | 1424894097.687 | What I would expect (according to the Asterisk 12 CDR Spec), is something like this: || seq || src || dst || dcontext || uniqueid || linkedid || | 141 | 682 | 850 | act-22575 | 1424894097.687 | 1424894097.687 | | 143 | 850 | 851 | act-22575 | 1424894105.695 | 1424894097.687 | | 145 | 682 | 851 | act-22575 | 1424894097.687 | 1424894097.687 | {quote} I'm using adaptive-odbc, connected to a PostgreSQL Database, with the following configuration: {noformat} [first] connection=asterisk-pgsql table=asterisk_cdr alias start => calldate {noformat} {{cdr.conf}} is the default created when running make samples, but set to log both unanswered and congested calls. This is my full configuration in extensions.conf: {noformat} [general] static = yes writeprotect = no extenpatternmatchnew = yes ; Using new pattern matcher as a test clearglobalvars = no userscontext = default ; User context is where entries from users.conf are registered. [account-shared-extensions-22575] exten => 682,1,NoOp() same => n,Set(CDR(userid)=9264) same => n,Set(AccountID=22575) same => n,Dial(SIP/swiatek,25) same => n,Hangup() exten => 850,1,NoOp() same => n,Set(CDR(userid)=9574) same => n,Set(AccountID=22575) same => n,Dial(SIP/swiatek2,25) same => n,Hangup() exten => 851,1,NoOp() same => n,Set(CDR(userid)=9598) same => n,Set(AccountID=22575) same => n,Dial(SIP/swiatek3,25) same => n,Hangup() [user-default-9264] ;swiatek include => account-shared-extensions-22575 exten => *99,1,NoOp() same => n,VoiceMailMain(swiatek@vm-22575,s) same => n,Hangup() [user-default-9574] ;swiatek2 include => account-shared-extensions-22575 exten => *99,1,NoOp() same => n,VoiceMailMain(swiatek2@vm-22575,s) same => n,Hangup() [user-default-9598] ;swiatek3 include => account-shared-extensions-22575 exten => *99,1,NoOp() same => n,VoiceMailMain(swiatek3@vm-22575,s) same => n,Hangup() {noformat} This is my users configured at the end of sip.conf (rest of the file is unchanged except for allowing some IP ranges): {noformat} [user-template](!) type = friend host = dynamic dtmfmode = auto disallow = all allow = ulaw allow = alaw ;secret = testhest context = outbound-init mohsuggest = sound_1 alwaysauthreject=yes [swiatek](user-template) context=user-default-9264 callerid="Jonas Swiatek" <682> mailbox=swiatek@vm-22575 accountcode=22575 mohsuggest=sound_1 [swiatek2](user-template) context=user-default-9574 callerid="Jonas 2" <850> mailbox=swiatek2@vm-22575 accountcode=22575 [swiatek3](user-template) context=user-default-9598 callerid="Jonas 3" <851> mailbox=swiatek3@vm-22575 accountcode=22575 {noformat} Steps taken: When testing this, I've got three phones (A(682), B(850) and C(851)) on my desk, one for each extension. I test is like this: # A, dial B # Pickup B, press Transfer, dial 851# # Pickip C, hangup B. C and A are connected. # Hangup A. See the initial post (http://forums.asterisk.org/viewtopic.php?f=1&t=92599) for a formatted layout of the table data I'm getting, and what I think it should be when reading the CDR Spec for Asterisk 12 and later. Recording log output from Asterisk during this test call: {noformat} == Using SIP RTP CoS mark 5 -- Executing [850@user-default-9264:1] NoOp("SIP/swiatek-00000032", "") in new stack -- Executing [850@user-default-9264:2] Set("SIP/swiatek-00000032", "CDR(userid)=9574") in new stack -- Executing [850@user-default-9264:3] Set("SIP/swiatek-00000032", "AccountID=22575") in new stack -- Executing [850@user-default-9264:4] Dial("SIP/swiatek-00000032", "SIP/swiatek2,25") in new stack == Using SIP RTP CoS mark 5 -- Called SIP/swiatek2 -- SIP/swiatek2-00000033 is ringing -- SIP/swiatek2-00000033 answered SIP/swiatek-00000032 -- Channel SIP/swiatek-00000032 joined 'simple_bridge' basic-bridge <7910e64c-3f55-4153-b591-e092f1f61172> -- Channel SIP/swiatek2-00000033 joined 'simple_bridge' basic-bridge <7910e64c-3f55-4153-b591-e092f1f61172> -- Channel SIP/swiatek2-00000033 left 'native_rtp' basic-bridge <7910e64c-3f55-4153-b591-e092f1f61172> -- Channel SIP/swiatek-00000032 left 'native_rtp' basic-bridge <7910e64c-3f55-4153-b591-e092f1f61172> == Spawn extension (user-default-9264, 850, 4) exited non-zero on 'SIP/swiatek-00000032' == Using SIP RTP CoS mark 5 -- Executing [850@user-default-9264:1] NoOp("SIP/swiatek-00000034", "") in new stack -- Executing [850@user-default-9264:2] Set("SIP/swiatek-00000034", "CDR(userid)=9574") in new stack -- Executing [850@user-default-9264:3] Set("SIP/swiatek-00000034", "AccountID=22575") in new stack -- Executing [850@user-default-9264:4] Dial("SIP/swiatek-00000034", "SIP/swiatek2,25") in new stack == Using SIP RTP CoS mark 5 -- Called SIP/swiatek2 -- SIP/swiatek2-00000035 is ringing -- SIP/swiatek2-00000035 answered SIP/swiatek-00000034 -- Channel SIP/swiatek-00000034 joined 'simple_bridge' basic-bridge <8d1a7359-cda4-4b00-bd99-16227d0c05f8> -- Channel SIP/swiatek2-00000035 joined 'simple_bridge' basic-bridge <8d1a7359-cda4-4b00-bd99-16227d0c05f8> -- Music class sound_1 requested but no musiconhold loaded. == Using SIP RTP CoS mark 5 -- Executing [851@user-default-9574:1] NoOp("SIP/swiatek2-00000036", "") in new stack -- Executing [851@user-default-9574:2] Set("SIP/swiatek2-00000036", "CDR(userid)=9598") in new stack -- Executing [851@user-default-9574:3] Set("SIP/swiatek2-00000036", "AccountID=22575") in new stack -- Executing [851@user-default-9574:4] Dial("SIP/swiatek2-00000036", "SIP/swiatek3,25") in new stack == Using SIP RTP CoS mark 5 -- Called SIP/swiatek3 -- SIP/swiatek3-00000037 is ringing -- SIP/swiatek3-00000037 answered SIP/swiatek2-00000036 -- Channel SIP/swiatek2-00000036 joined 'simple_bridge' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> -- Channel SIP/swiatek3-00000037 joined 'simple_bridge' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> -- Channel SIP/swiatek-00000034 left 'native_rtp' basic-bridge <8d1a7359-cda4-4b00-bd99-16227d0c05f8> -- Channel SIP/swiatek2-00000036 left 'native_rtp' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> -- Channel SIP/swiatek-00000034 swapped with SIP/swiatek2-00000036 into 'native_rtp' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> == Spawn extension (user-default-9574, 851, 4) exited non-zero on 'SIP/swiatek2-00000036' -- Channel SIP/swiatek2-00000035 left 'simple_bridge' basic-bridge <8d1a7359-cda4-4b00-bd99-16227d0c05f8> -- Channel SIP/swiatek3-00000037 left 'native_rtp' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> -- Channel SIP/swiatek-00000034 left 'native_rtp' basic-bridge <2078600c-dd52-4005-8d67-4963b8b3dcf2> == Spawn extension (user-default-9264, 850, 4) exited non-zero on 'SIP/swiatek-00000034' {noformat} | ||||
| Comments: | By: Matt Jordan (mjordan) 2015-02-27 21:35:16.284-0600 We require additional debug to continue with triage of your issue. Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information Please make sure 'cdr set debug on' is enabled as well. By: Matt Jordan (mjordan) 2015-02-27 21:36:16.024-0600 Please also attach your configuration as files to the issue, following the Asterisk Issue Guidelines: https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines Large blocks of pasted stuff in the issue description does not make it easy to read or parse what is occurring. By: Matt Jordan (mjordan) 2015-02-27 21:50:32.102-0600 Hm. I have a guess at what is happening here. By way of a test, can you add some features flags to your Dial operation to force a core bridge? That is: {{same => n,Dial(SIP/swiatek,25)}} Should become something like: {{same => n,Dial(SIP/swiatek,25,tT)}} I suspect that Native RTP bridges aren't causing the linkedids to swap over. By: Jonas Swiatek (jonasswiatek) 2015-02-28 13:05:38.264-0600 Hey Matt, Sorry about the poor formatting. I wasn't aware you could format tables and text areas in Jira. I've attached the configuration files and the debug log output with cdr debugging enabled as cdr_issue_log.txt. Adding the tT flags doesn't seem to have affected it. I get the same rows in my database: ||sequence||src||dst||dcontext||channel||dstchannel||lastapp||lastdata||duration||billsec||uniqueid||linkedid|| |11|682|850|user-default-9264|SIP/swiatek-0000000a|SIP/swiatek2-0000000b|Dial|SIP/swiatek2,25,tT|10|9|1425150064.138|1425150064.138| |13|850|851|user-default-9574|SIP/swiatek2-0000000c|SIP/swiatek3-0000000d|Dial|SIP/swiatek3,25,tT|6|1|1425150069.146|1425150069.146| |15|682|850|user-default-9264|SIP/swiatek-0000000a|SIP/swiatek3-0000000d|Dial|SIP/swiatek2,25,tT|1|1|1425150064.138|1425150064.138| By: Matt Jordan (mjordan) 2015-03-26 09:41:23.666-0500 [~jonasswiatek]: sorry for the delay in digging into the logs. As it is, in this particular case, this is actually a similar situation to ASTERISK-23493. Since this has been a point of confusion twice due to how the spec describes an attended transfer, I'll update the CDR spec to clarify the different attended transfer scenarios. As it is, this is not a bug. In your scenario, you are not performing a core attended transfer (which is what the CDR spec envisions) - rather, you are performing a SIP protocol attended transfer, which behaves differently than a core attended transfer. In a SIP attended transfer, the transferer has two different channels that make up the transfer - in your case, {{SIP/swiatek2-0000000b}} and {{SIP/swiatek2-0000000c}}. As far as Asterisk is concerned, these two channels have *no* relationship to each other. They are two independent channels that happen to have the same destination for the media (although even then, that isn't always guaranteed). When the transfer completes, these two channels never interact. As a result, there is no way to have the linkedid of {{SIP/swiatek-0000000a}} be propagated to {{SIP/swiatek2-0000000c}}. The linkedid can only propagate between records when there is either (a) a relationship established between the channels when they are created, or (b) when two channels are bridged together. In a SIP protocol transfer, this doesn't happen. In order to correlate the records, I would look to either the {{accountcode}} field or the actual device names involved in the transfer. | ||||