Summary: | ASTERISK-15488: callee chanel overwrites the caller cdr | ||
Reporter: | eagvoz (eagvoz) | Labels: | |
Date Opened: | 2010-01-22 09:16:52.000-0600 | Date Closed: | 2015-02-25 21:23:07.000-0600 |
Priority: | Minor | Regression? | No |
Status: | Closed/Complete | Components: | Channels/chan_local |
Versions: | Frequency of Occurrence | ||
Related Issues: | |||
Environment: | Attachments: | ( 0) cdr_diff.pdf | |
Description: | When
# contextA answers the call # contextA dials contextB (with local /n of course) # contextB answers the call we expect (as like asterisk 1.2 and asterisk 1.4): - That CDR of contextA has its own billsec (cdrA) and contextB its own billsec (cdrB). But in asterisk 1.6 we see: - when contextB answers the call it sets the billsec of cdrA equals to the billsec of cdrB. *STEPS TO REPRODUCE* With the following context we will expect - The duration of "A" CDR will be the length of "thanks-for-calling-today" sound + the time of calling context B - The billsec of "A" CDR will be equals duration because there are no waittings. - The duration of "B" CDR will be 3 + the length of "goodbye" sound - The billsec of "B" CDR will be the length of "goodbye" sound {noformat} [contextA] exten => s,1,NoOp(I'm contextA) exten => s,n,Set(CDR(accountcode)=A) exten => s,n,Answer() exten => s,n,PlayBack(thanks-for-calling-today) exten => s,n,Dial(Local/s@contextB/n) [contextB] exten => s,1,NoOp(I'm contextB) exten => s,n,Set(CDR(accountcode)=B) exten => s,n,Wait(3) exten => s,n,Answer() exten => s,n,PlayBack(goodbye) exten => s,n,Hangup {noformat} | ||
Comments: | By: Leif Madsen (lmadsen) 2010-01-28 14:54:31.000-0600 Please provide some additional information, such as the console output when this is happening, along with debugging information, a SIP trace (if using SIP), and examples of correct, and incorrect CDRs. By: eagvoz (eagvoz) 2010-01-29 05:45:59.000-0600 --- Reproducibility --- Always --- RESULTING CDRs ON ASTERISK 1.6.2.1 (BAD CDRs) --- uniqueid userfield accountcode src dst dcontext clid channel dstchannel lastapp lastdata calldate duration billsec disposition amaflags 1264760350.12 B_SHORTCDR 100 s contextB \User Name\" <100>" Local/s@contextB-fdc9;2 Hangup 2010-01-29 11:19:10 4 1 ANSWERED 3 1264760348.10 A_LARGECDR 100 s contextA \User Name\" <100>" IAX2/remoteHost-6426 Local/s@contextB-fdc9;1 Dial Local/s@contextB/n 2010-01-29 11:19:08 5 1 ANSWERED 3 For the "A_LARGECDR" CDR asterisk stores: The duration is OK because: ~1s (sound contextA) + 3s (wait on context B) + ~1s (sound on context B) = 5 seconds but the billsec on "A_LARGECDR" is NOT ok because: ~1s (sound contextA) + 3s (wait on context B) + ~1s (sound on context B) != 1 seconds !!! --- EXPECTED CDRs . RESULTS TAKEN FROM ASTERISK 1.4.21.1 (GOOD CDRs) --- (Same contexts, clid, etc.) uniqueid userfield accountcode src dst dcontext clid channel dstchannel lastapp lastdata calldate duration billsec disposition amaflags 1264762373.726 B_SHORTCDR 100 s contextB \User Name\" <100>" Local/s@contextB-0407,2 Hangup 2010-01-29 11:52:53 4 1 ANSWERED 3 1264762373.724 A_LARGECDR 100 s contextA \User Name\" <100>" IAX2/remoteHost-2547 Local/s@contextB-0407,1 Dial Local/s@contextB/n 2010-01-29 11:52:53 5 5 ANSWERED 3 For the "A_LARGECDR" CDR asterisk stores: The duration is correct because: ~1s (sound contextA) + 3s (wait on context B) + ~1s (sound on context B) = 5 seconds the billsec on "A_LARGECDR" OK because: ~1s (sound contextA) + 3s (wait on context B) + ~1s (sound on context B) = 5 seconds As you can see on asterisk 1.6 the billsec of first channel is equals to billsec of last channel. That is not true, because first CDR may be answered before last CDR. If you have more local channels between the first and last channel, all of those billsecs will be changed by the last created channel. --- Contexts used ---- [contextA] exten => s,1,NoOp(I'm contextA) exten => s,n,Set(CDR(accountcode)=A_LARGECDR) exten => s,n,Answer() exten => s,n,PlayBack(thanks-for-calling-today) exten => s,n,Dial(Local/s@contextB/n) exten => h,1,NoOp(Putting some global vars into userfield) [contextB] exten => s,1,NoOp(I'm contextB) exten => s,n,Set(CDR(accountcode)=B_SHORTCDR) exten => s,n,Wait(3) exten => s,n,NoOp(Setting some global vars) exten => s,n,Answer() exten => s,n,PlayBack(goodbye) exten => s,n,Hangup exten => h,1,NoOp(Cleaning B) --- Asterisk console (debug=999,verbose=999,iax.debug=on) ---- As expected we see: Connected to Asterisk 1.6.2.1 currently running on myhost (pid = 4243) Verbosity is at least 999 Core debug is at least 999 myhost*CLI>iax2 set debug on IAX2 Debugging Enabled Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00014ms SCall: 00005 DCall: 00000 [remoteIP:4569] VERSION : 2 CALLED NUMBER : s CODEC_PREFS : (gsm) CALLING NUMBER : 102 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : User Name LANGUAGE : es CALLED CONTEXT : contextA USERNAME : user001 FORMAT : 2 CAPABILITY : 57346 ADSICPE : 2 DATE TIME : 2010-01-29 11:18:50 Tx-Frame Retry[-01] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00014ms SCall: 06426 DCall: 00005 [remoteIP:4569] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00002ms SCall: 06426 DCall: 00005 [remoteIP:4569] AUTHMETHODS : 2 CHALLENGE : \x31\x39\x32\x36\x38\x34\x30\x38\x39 USERNAME : user001 Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00076ms SCall: 00005 DCall: 06426 [remoteIP:4569] MD5 RESULT : xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00076ms SCall: 06426 DCall: 00005 [remoteIP:4569] -- Accepting AUTHENTICATED call from remoteIP: > requested format = gsm, > requested prefs = (gsm), > actual format = gsm, > host prefs = (gsm), > priority = mine Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00061ms SCall: 06426 DCall: 00005 [remoteIP:4569] FORMAT : 2 -- Executing [s@contextA:1] NoOp("IAX2/user001-6426", "I'm contextA") in new stack -- Executing [s@contextA:2] Set("IAX2/user001-6426", "CDR(accountcode)=A_LARGECDR") in new stack -- Executing [s@contextA:3] Answer("IAX2/user001-6426", "") in new stack Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER Timestamp: 00064ms SCall: 06426 DCall: 00005 [remoteIP:4569] Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?) Timestamp: 00067ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00061ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00064ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT Timestamp: 00079ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00079ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00067ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT Timestamp: 00082ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00082ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT Timestamp: 00085ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 00085ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: VOICE Subclass: 2 Timestamp: 00140ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX Subclass: ACK Timestamp: 00140ms SCall: 06426 DCall: 00005 [remoteIP:4569] -- Executing [s@contextA:4] Playback("IAX2/user001-6426", "thanks-for-calling-today") in new stack -- <IAX2/user001-6426> Playing 'thanks-for-calling-today.gsm' (language 'es') Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 006 Type: VOICE Subclass: 2 Timestamp: 00160ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 00160ms SCall: 00005 DCall: 06426 [remoteIP:4569] -- Executing [s@contextA:5] Dial("IAX2/user001-6426", "Local/s@contextB/n") in new stack -- Called s@contextB/n -- Executing [s@contextB:1] NoOp("Local/s@contextB-fdc9;2", "I'm contextB") in new stack -- Executing [s@contextB:2] Set("Local/s@contextB-fdc9;2", "CDR(accountcode)=B_SHORTCDR") in new stack -- Executing [s@contextB:3] Wait("Local/s@contextB-fdc9;2", "3") in new stack Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00009ms SCall: 00021 DCall: 00000 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00009ms SCall: 00021 DCall: 00001 [remoteIP:4569] -- Executing [s@contextB:4] NoOp("Local/s@contextB-fdc9;2", "Setting some global vars") in new stack -- Executing [s@contextB:5] Answer("Local/s@contextB-fdc9;2", "") in new stack -- Local/s@contextB-fdc9;1 answered IAX2/user001-6426 Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 006 Type: CONTROL Subclass: SRCUPDT Timestamp: 04749ms SCall: 06426 DCall: 00005 [remoteIP:4569] Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 006 Type: CONTROL Subclass: SRCUPDT Timestamp: 04752ms SCall: 06426 DCall: 00005 [remoteIP:4569] Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 006 Type: CONTROL Subclass: (255?) Timestamp: 04755ms SCall: 06426 DCall: 00005 [remoteIP:4569] Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 006 Type: CONTROL Subclass: SRCUPDT Timestamp: 04758ms SCall: 06426 DCall: 00005 [remoteIP:4569] -- Executing [s@contextB:6] Playback("Local/s@contextB-fdc9;2", "goodbye") in new stack -- <Local/s@contextB-fdc9;2> Playing 'goodbye.gsm' (language 'en') Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 006 Type: IAX Subclass: ACK Timestamp: 04749ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 007 Type: IAX Subclass: ACK Timestamp: 04752ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 008 Type: IAX Subclass: ACK Timestamp: 04755ms SCall: 00005 DCall: 06426 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT Timestamp: 04803ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 007 Type: IAX Subclass: ACK Timestamp: 04803ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT Timestamp: 04806ms SCall: 00005 DCall: 06426 [remoteIP:4569] Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 008 Type: IAX Subclass: ACK Timestamp: 04806ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 009 Type: IAX Subclass: ACK Timestamp: 04758ms SCall: 00005 DCall: 06426 [remoteIP:4569] -- Executing [s@contextB:7] Hangup("Local/s@contextB-fdc9;2", "") in new stack == Spawn extension (contextB, s, 7) exited non-zero on 'Local/s@contextB-fdc9;2' -- Executing [h@contextB:1] NoOp("Local/s@contextB-fdc9;2", "Cleaning B") in new stack -- Executing [h@contextA:1] NoOp("IAX2/user001-6426", "Putting some global vars into userfield") in new stack Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT Timestamp: 05663ms SCall: 06426 DCall: 00005 [remoteIP:4569] Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 010 Type: IAX Subclass: ACK Timestamp: 05663ms SCall: 00005 DCall: 06426 [remoteIP:4569] == Spawn extension (contextA, s, 5) exited non-zero on 'IAX2/user001-6426' -- Hungup 'IAX2/user001-6426' Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 008 Type: IAX Subclass: HANGUP Timestamp: 05796ms SCall: 06426 DCall: 00005 [remoteIP:4569] CAUSE CODE : 16 Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 011 Type: IAX Subclass: ACK Timestamp: 05796ms SCall: 00005 DCall: 06426 [remoteIP:4569] myhost*CLI> By: Matt Jordan (mjordan) 2015-02-25 21:22:50.259-0600 I can confirm this is still an issue in Asterisk 11. Using the following dialplan: {noformat} [contextA] exten => s,1,NoOp(I'm contextA) exten => s,n,Set(CDR(accountcode)=A) exten => s,n,Answer() exten => s,n,PlayBack(silence/5) exten => s,n,Dial(Local/s@contextB/n) [contextB] exten => s,1,NoOp(I'm contextB) exten => s,n,Set(CDR(accountcode)=B) exten => s,n,Wait(3) exten => s,n,Answer() exten => s,n,PlayBack(silence/3) exten => s,n,Hangup {noformat} And originating a Local channel to {{Local/s@contextA}} (with the other end in Echo) I get the following CDRs: {noformat} "A","","s","contextA","","Local/s@contextA-00000000;2","Local/s@contextB-00000001;1","Dial","Local/s@contextB/n","2015-02-26 03:11:58","2015-02-26 03:12:06","2015-02-26 03:12:07",9,1,"ANSWERED","DOCUMENTATION","1424920318.1","" "B","","s","contextB","","Local/s@contextB-00000001;2","","Hangup","","2015-02-26 03:12:03","2015-02-26 03:12:06","2015-02-26 03:12:10",7,4,"ANSWERED","DOCUMENTATION","1424920323.3","" {noformat} Much like the issue suggests, {{Local/s@contextA-00000000;2}} has 5 seconds of being Answered that is unaccounted for. That being said, CDRs are generally intractable and prone to major issues when fixed in a release branch. As it is, I do not think we would attempt to alter their behaviour in that branch. Testing with Asterisk 13 yields the following CDRs: {noformat} "B","","s","contextB",""""" <>","Local/s@contextB-00000001;2","","Hangup","","2015-02-26 03:18:48","2015-02-26 03:18:51","2015-02-26 03:18:54",6,3,"ANSWERED","DOCUMENTATION","1424920728.3","" "A","","s","contextA",""""" <>","Local/s@contextA-00000000;2","Local/s@contextB-00000001;1","Dial","Local/s@contextB/n","2015-02-26 03:18:42","2015-02-26 03:18:42","2015-02-26 03:18:54",12,12,"ANSWERED","DOCUMENTATION","1424920722.1","" "","","s","contextA",""""" <>","Local/s@contextA-00000000;1","","Echo","","2015-02-26 03:18:42","2015-02-26 03:18:42","2015-02-26 03:18:54",12,12,"ANSWERED","DOCUMENTATION","1424920722.0","" {noformat} Disregarding the Echo half of the Local channel (which shows up because it was Answered, and we don't hide these things any longer) we can see that {{Local/s@contextA-00000000;2}} has the full billing seconds - which is equal to the duration in this case since we are Answered immediately - and {{Local/s@contextB-00000001;2}} has 3 second of non-billing time, which matches our Wait time. Since this is fixed in the great CDR overhaul that occurred in Asterisk 12, and since we are extremely unlikely to risk causing further risk in Asterisk 11 by modifying CDR behaviour, I'm going to close this out as "Fixed" in Asterisk 12+. |