[Home]

Summary:ASTERISK-19552: CDR logs on call transfers prints only last leg
Reporter:Sarada Athavale (sarada)Labels:
Date Opened:2012-03-16 01:15:28Date Closed:2012-03-16 08:48:30
Priority:MajorRegression?
Status:Closed/CompleteComponents:CDR/cdr_custom
Versions:10.2.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:CentOS 5.5Attachments:
Description:Scenario : USER1 is in queue waiting for an available agent. Agent1 answers the call and transfers it to extension 202. At the end of the call, only last leg is printed in the logs.

User1->Agent1->202

Call Logs as follows :
cdr-custom/Master.csv :
"""user1"" <user1>","user1","202","INTERNAL","SIP/user1-00000063","SIP/202-00000066","Dial","SIP/202","2012-03-16 05:32:07","2012-03-16 05:33:11","2012-03-16 05:33:25","78","14","ANSWERED","DOCUMENTATION","","1331856127.99","",114

Verbose printed on CLI :
         Please check my notes below pointed by -------->

-- Executing [1111@INCOMING:1] Answer("SIP/user1-0000005f", "") in new stack
   -- Executing [1111@INCOMING:2] Set("SIP/user1-0000005f", "TIMEOUT(absolute)=1000") in new stack
Channel will hangup at 2012-03-16 05:40:12.153 IST.
   -- Executing [1111@INCOMING:3] Set("SIP/user1-0000005f", "TIMEOUT(digit)=3") in new stack
   -- Digit timeout set to 3.000
   -- Executing [1111@INCOMING:4] Set("SIP/user1-0000005f", "LANGUAGE=en") in new stack
   -- Executing [1111@INCOMING:5] BackGround("SIP/user1-0000005f", "available-options") in new stack
   -- <SIP/user1-0000005f> Playing 'available-options.gsm' (language 'en')
   -- Executing [1111@INCOMING:6] SayNumber("SIP/user1-0000005f", "1") in new stack
   -- <SIP/user1-0000005f> Playing 'digits/1.ulaw' (language 'en')
   -- Executing [1111@INCOMING:7] SayNumber("SIP/user1-0000005f", "2") in new stack
   -- <SIP/user1-0000005f> Playing 'digits/2.ulaw' (language 'en')
   -- Executing [1111@INCOMING:8] SayNumber("SIP/user1-0000005f", "3") in new stack
   -- <SIP/user1-0000005f> Playing 'digits/3.ulaw' (language 'en')
   -- Executing [1111@INCOMING:9] BackGround("SIP/user1-0000005f", "silence/10") in new stack
   -- <SIP/user1-0000005f> Playing 'silence/10.ulaw' (language 'en')
 == CDR updated on SIP/user1-0000005f
   -- Executing [1@INCOMING:1] Set("SIP/user1-0000005f", "_USERQUEUE=sales") in new stack
   -- Executing [1@INCOMING:2] BackGround("SIP/user1-0000005f", "US_reminder_message") in new stack
   -- <SIP/user1-0000005f> Playing 'US_reminder_message.gsm' (language 'en')
 == CDR updated on SIP/user1-0000005f
   -- Executing [0@INCOMING:1] ExecIf("SIP/user1-0000005f", "0?goto(INCOMING,i,1)") in new stack
   -- Executing [0@INCOMING:2] Queue("SIP/user1-0000005f", "sales") in new stack
   -- Started music on hold, class 'default', on SIP/user1-0000005f
 == Using SIP RTP CoS mark 5
   -- SIP/agent2-00000060 is ringing
   -- Nobody picked up in 15000 ms
 == Using SIP RTP CoS mark 5
   -- SIP/agent1-00000061 is ringing
   -- SIP/agent1-00000061 answered SIP/user1-0000005f  
   -- Stopped music on hold on SIP/user1-0000005f
   -- Locally bridging SIP/user1-0000005f and SIP/agent1-00000061
   -- Started music on hold, class 'default', on SIP/user1-0000005f
   -- Stopped music on hold on SIP/user1-0000005f
 == Spawn extension (INTERNAL, 202, 1) exited non-zero on 'SIP/user1-0000005f'
   -- Executing [202@INTERNAL:1] Answer("SIP/user1-0000005f", "") in new stack
   -- Executing [202@INTERNAL:2] Dial("SIP/user1-0000005f", "SIP/202") in new stack  
 == Using SIP RTP CoS mark 5
   -- Called SIP/202
   -- SIP/202-00000062 is ringing
   -- SIP/202-00000062 answered SIP/user1-0000005f
   -- Locally bridging SIP/user1-0000005f and SIP/202-00000062
 == Spawn extension (INTERNAL, 202, 2) exited non-zero on 'SIP/user1-0000005f'
 == Using SIP RTP CoS mark 5
   -- Executing [1111@INCOMING:1] Answer("SIP/user1-00000063", "") in new stack
   -- Executing [1111@INCOMING:2] Set("SIP/user1-00000063", "TIMEOUT(absolute)=1000") in new stack
Channel will hangup at 2012-03-16 05:48:47.387 IST.
   -- Executing [1111@INCOMING:3] Set("SIP/user1-00000063", "TIMEOUT(digit)=3") in new stack
   -- Digit timeout set to 3.000
   -- Executing [1111@INCOMING:4] Set("SIP/user1-00000063", "LANGUAGE=en") in new stack
   -- Executing [1111@INCOMING:5] BackGround("SIP/user1-00000063", "available-options") in new stack
   -- <SIP/user1-00000063> Playing 'available-options.gsm' (language 'en')
   -- Executing [1111@INCOMING:6] SayNumber("SIP/user1-00000063", "1") in new stack
   -- <SIP/user1-00000063> Playing 'digits/1.ulaw' (language 'en')
   -- Executing [1111@INCOMING:7] SayNumber("SIP/user1-00000063", "2") in new stack
   -- <SIP/user1-00000063> Playing 'digits/2.ulaw' (language 'en')
   -- Executing [1111@INCOMING:8] SayNumber("SIP/user1-00000063", "3") in new stack
   -- <SIP/user1-00000063> Playing 'digits/3.ulaw' (language 'en')
   -- Executing [1111@INCOMING:9] BackGround("SIP/user1-00000063", "silence/10") in new stack
   -- <SIP/user1-00000063> Playing 'silence/10.ulaw' (language 'en')
 == CDR updated on SIP/user1-00000063
   -- Executing [1@INCOMING:1] Set("SIP/user1-00000063", "_USERQUEUE=sales") in new stack
   -- Executing [1@INCOMING:2] BackGround("SIP/user1-00000063", "US_reminder_message") in new stack
   -- <SIP/user1-00000063> Playing 'US_reminder_message.gsm' (language 'en')
 == CDR updated on SIP/user1-00000063
   -- Executing [0@INCOMING:1] ExecIf("SIP/user1-00000063", "0?goto(INCOMING,i,1)") in new stack
   -- Executing [0@INCOMING:2] Queue("SIP/user1-00000063", "sales") in new stack
   -- Started music on hold, class 'default', on SIP/user1-00000063
 == Using SIP RTP CoS mark 5
   -- SIP/agent2-00000064 is ringing
   -- Nobody picked up in 15000 ms
 == Using SIP RTP CoS mark 5
   -- SIP/agent1-00000065 is ringing
   -- SIP/agent1-00000065 answered SIP/user1-00000063      ----------------------> Call answered by agent1
   -- Stopped music on hold on SIP/user1-00000063
   -- Locally bridging SIP/user1-00000063 and SIP/agent1-00000065  --------------------> Call bridged
   -- Started music on hold, class 'default', on SIP/user1-00000063 --------------------> Music on hold on transfer
   -- Stopped music on hold on SIP/user1-00000063
[Mar 16 05:33:08] NOTICE[28543]: chan_sip.c:20973 handle_response_notify: Got OK on REFER Notify message
 == Spawn extension (INTERNAL, 202, 1) exited non-zero on 'SIP/user1-00000063'
   -- Executing [202@INTERNAL:1] Answer("SIP/user1-00000063", "") in new stack
   -- Executing [202@INTERNAL:2] Dial("SIP/user1-00000063", "SIP/202") in new stack
 == Using SIP RTP CoS mark 5
   -- Called SIP/202
   -- SIP/202-00000066 is ringing
   -- SIP/202-00000066 answered SIP/user1-00000063                ----------------------> 202 answered
   -- Locally bridging SIP/user1-00000063 and SIP/202-00000066
 == Spawn extension (INTERNAL, 202, 2) exited non-zero on 'SIP/user1-00000063'



Comments:By: David Woolley (davidw) 2012-03-16 05:28:04.222-0500

My initial impression is that this is not a bug report, but a support question.  Subject to timestamps on the log entries indicating something to the contrary, it looks to me like this is working correctly.  Unless you do something explicit to force out additional CDRs, you will get, at most, one CDR per call and it will reflect the final application, context, extension and destination channel.

In any case, CDRs are known not to provide enough information for complex cases, for which you should use call event logging.
By: Matt Jordan (mjordan) 2012-03-16 08:48:30.472-0500

David is correct.  The behavior of CDRs in complex scenarios - particularly involving transfers - is undefined.

If you need information regarding all stages of a call, when that call goes through multiple states, you should look into Call Event Logging (CEL).