[Home]

Summary:ASTERISK-15488: callee chanel overwrites the caller cdr
Reporter:eagvoz (eagvoz)Labels:
Date Opened:2010-01-22 09:16:52.000-0600Date Closed:2015-02-25 21:23:07.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents: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+.