[asterisk-users] Switched from Asterisk 1.8 to 13 - CDR

Stefan Viljoen viljoens at verishare.co.za
Fri Jan 11 01:34:27 CST 2019 

>> Is it possible that the setup part of the call (between initiation and answer)
>> is recorded in a separate CDR?

>An excellent question. Unlike in the past versions calls can actually generate multiple CDRs because CDRs now represent the flow of communication between things.

>Providing the actual CDR records that were generated as well as console output would allow better understanding of what is going on.

>--
>Joshua C. Colp
>Digium - A Sangoma Company | Senior Software Developer

Hi Joshua

That is exactly what is happening. 

I get a separate CDR for the originate of the call to the agent's extension, and then a separate CDR for the call that then goes out to the client.

The separate CDR for an originate event DOES appear to be correct, there is usually a second or two seconds worth of ringtime indicated, e. g. start and answer will vary (as outgoing calls did on 1.8) under 13:

Start                              | Answer                         | End
2019-01-11 08:01:20 | 2019-01-11 08:01:22 | 2019-01-11 08:01:25

E. g. the agent originated by calling the AMI via our app at 2019-01-11 08:01:20, he picked up the phone at 2019-01-11 08:01:22 (e. g. he let it ring for 2 seconds) etc.

So the "originate call" to the agent's local channel has correct difference between start and and start, but the actual call going out to the client from the agent has the "13 sickness" e. g. start and answer times are exactly the same.

Here are sample actual CDR records (apologies for the format):

id	clid	src	dst	dcontext	channel	dstchannel	lastapp	lastdata	start	answer	end	duration	billsec	disposition	amaflags	accountcode	uniqueid	userfield	linkedid	sequence	customdata
8132380b-1569-11e9-9184-18d6c702b3d7	6140_ctd	6140	6140	local	Local/6140 at local-0006232d;2	SIP/6140-004e99bd	Dial	SIP/6140,120,tT	2019-01-11 08:22:07	2019-01-11 08:22:12	2019-01-11 08:24:09	122	116	ANSWERED	3	201901110822sobtpb8	201901110822sobtpb8B	/var/spool/asterisk/monitor/1901/11/201901110822sobtpb8.gsm	201901110822sobtpb8	9217937	

813671dc-1569-11e9-9184-18d6c702b3d7	6140	6140	5554567781 	local	Local/6140 at local-0006232d;1	SIP/centra-out-rng-004e99c5	Dial	SIP/centra-out-rng/5554567781,120,TL(3900000:60000:30000)	2019-01-11 08:22:12	2019-01-11 08:22:12	2019-01-11 08:24:09	116	116	ANSWERED	3	201901110822sobtpb8	201901110822sobtpb8	/var/spool/asterisk/monitor/1901/11/201901110822sobtpb8.gsm	201901110822sobtpb8	9217936	

E. g. the first line is the originate to extension 6140. As you can see on the times, the agent waited 5 seconds after the phone started ringing internally, to pick up the originated call:

Start: 2019-01-11 08:22:07
Answer: 2019-01-11 08:22:12
End: 2019-01-11 08:24:09

As you can see the "origination call" CDR's end time exactly spans the "actual call" duration.

The second line is the actual call to the customer at 5554567781. As you can see on the times, apparently the client picked up instantly (which they did not, if I listend to the recording in /var/spool/asterisk/monitor/1901/11/201901110822sobtpb8.gsm):

Start: 2019-01-11 08:22:12
Answer: 2019-01-11 08:22:12
End: 2019-01-11 08:24:09

As you can see the "actual call" CDR's start and end times are exactly the same, even though the client picked up only after several seconds (8, in this case, if you listen to the recording with a stopwatch and time start of audio and actual pickup.)

E. g. it is impossible to now tell how long the agent waited for the client to pick up using the above model of originating calls, whereas it was working with 1.8, 13 always emits the same times to the second for both start and answer in the outgoing leg of the call in the above scenario.

The "origination leg" of the call's total time spans the outgoing leg, but the start / answer times in the "origination leg" is the internal pickup of the agent of his phone after he click "Originate call" in our app which calls the AMI.

Again, on 1.8, both CDRs as above were created with the same dialplan code as communicated yesterday, but on 1.8 each of the two CDRs start and answer times differ, the one CDR emitted indicating how long the agent took to pickup the phone after it started ringing for his click of the Originate button, and the other CDR emitted indicating (in varying start and answer times) how long the client took to pickup the phone.

-----

Console output for a typical originated call:

core set verbose 3
Console verbose was OFF and is now 3.
    -- Called 6062 at local
    -- Executing [6062 at local:1] Dial("Local/6062 at local-0001984b;2", "SIP/6062,120,t") in new stack
== Using SIP RTP CoS mark 5
    -- Called SIP/6062
    -- SIP/6062-000600f5 is ringing
    -- Local/6062 at local-0001984b;1 is ringing
    -- SIP/6062-000600f5 answered Local/6062 at local-0001984b;2
    -- Local/6062 at local-0001984b;1 answered
    -- Channel SIP/6062-000600f5 joined 'simple_bridge' basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
    -- Executing [0764444492 at local:1] Macro("Local/6062 at local-0001984b;1", "STDOUT,SIP/centra-out-rng,5554567781,SIP/centra-out-rng,0764444492") in new stack
    -- Channel SIP/6062-000600f5 joined 'simple_bridge' basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
    -- Channel Local/6062 at local-0001984b;2 joined 'simple_bridge' basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
    -- Executing [s at macro-STDOUT:1] Macro("Local/6062 at local-0001984b;1", "WAITCHANNEL") in new stack
    -- Executing [s at macro-WAITCHANNEL:1] Set("Local/6062 at local-0001984b;1", "trycounter=0") in new stack
    -- Executing [s at macro-WAITCHANNEL:2] Set("Local/6062 at local-0001984b;1", "trycounter=1") in new stack
    -- Executing [s at macro-WAITCHANNEL:3] GotoIf("Local/6062 at local-0001984b;1", "1?testval:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,4)
    -- Executing [s at macro-WAITCHANNEL:4] GotoIf("Local/6062 at local-0001984b;1", "1?2:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,2)
    -- Executing [s at macro-WAITCHANNEL:2] Set("Local/6062 at local-0001984b;1", "trycounter=2") in new stack
    -- Executing [s at macro-WAITCHANNEL:3] GotoIf("Local/6062 at local-0001984b;1", "1?testval:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,4)
    -- Executing [s at macro-WAITCHANNEL:4] GotoIf("Local/6062 at local-0001984b;1", "1?2:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,2)
    -- Executing [s at macro-WAITCHANNEL:2] Set("Local/6062 at local-0001984b;1", "trycounter=3") in new stack
    -- Executing [s at macro-WAITCHANNEL:3] GotoIf("Local/6062 at local-0001984b;1", "1?testval:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,4)
    -- Executing [s at macro-WAITCHANNEL:4] GotoIf("Local/6062 at local-0001984b;1", "1?2:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,2)
    -- Executing [s at macro-WAITCHANNEL:2] Set("Local/6062 at local-0001984b;1", "trycounter=4") in new stack
    -- Executing [s at macro-WAITCHANNEL:3] GotoIf("Local/6062 at local-0001984b;1", "1?testval:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,4)
    -- Executing [s at macro-WAITCHANNEL:4] GotoIf("Local/6062 at local-0001984b;1", "1?2:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,2)
    -- Executing [s at macro-WAITCHANNEL:2] Set("Local/6062 at local-0001984b;1", "trycounter=5") in new stack
    -- Executing [s at macro-WAITCHANNEL:3] GotoIf("Local/6062 at local-0001984b;1", "0?testval:showval") in new stack
    -- Goto (macro-WAITCHANNEL,s,5)
    -- Executing [s at macro-WAITCHANNEL:5] NoOp("Local/6062 at local-0001984b;1", "CALLER ID ") in new stack
    -- Executing [s at macro-WAITCHANNEL:6] MacroExit("Local/6062 at local-0001984b;1", "") in new stack
    -- Executing [s at macro-STDOUT:2] Macro("Local/6062 at local-0001984b;1", "WAITCDR") in new stack
    -- Executing [s at macro-WAITCDR:1] Set("Local/6062 at local-0001984b;1", "trycounter=0") in new stack
    -- Executing [s at macro-WAITCDR:2] Set("Local/6062 at local-0001984b;1", "trycounter=1") in new stack
    -- Executing [s at macro-WAITCDR:3] GotoIf("Local/6062 at local-0001984b;1", "1?testacc:showacc") in new stack
    -- Goto (macro-WAITCDR,s,4)
    -- Executing [s at macro-WAITCDR:4] GotoIf("Local/6062 at local-0001984b;1", "0?2:showacc") in new stack
    -- Goto (macro-WAITCDR,s,5)
    -- Executing [s at macro-WAITCDR:5] NoOp("Local/6062 at local-0001984b;1", "Account 201901110912urpnb2a") in new stack
    -- Executing [s at macro-WAITCDR:6] MacroExit("Local/6062 at local-0001984b;1", "") in new stack
    -- Executing [s at macro-STDOUT:3] Macro("Local/6062 at local-0001984b;1", "VCRECORD,localXACC201901110912urpnb2a,5554567781") in new stack
    -- Executing [s at macro-VCRECORD:1] NoOp("Local/6062 at local-0001984b;1", "Start of MixMonitor recording") in new stack
    -- Executing [s at macro-VCRECORD:2] GotoIf("Local/6062 at local-0001984b;1", "0?setcdr:setchan") in new stack
    -- Goto (macro-VCRECORD,s,4)
    -- Executing [s at macro-VCRECORD:4] Set("Local/6062 at local-0001984b;1", "=201901110912urpnb2a") in new stack
    -- Executing [s at macro-VCRECORD:5] Set("Local/6062 at local-0001984b;1", "recDir=1901/11") in new stack
    -- Executing [s at macro-VCRECORD:6] Set("Local/6062 at local-0001984b;1", "recFile=1901/11/190111091307DlocalXACC201901110912urpnb2aN5554567781ID201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:7] GotoIf("Local/6062 at local-0001984b;1", "0?makedir:setacc") in new stack
    -- Goto (macro-VCRECORD,s,8)
    -- Executing [s at macro-VCRECORD:8] Set("Local/6062 at local-0001984b;1", "recFile=1901/11/201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:9] System("Local/6062 at local-0001984b;1", "/bin/mkdir -p /var/spool/asterisk/monitor/1901/11") in new stack
    -- Executing [s at macro-VCRECORD:10] MixMonitor("Local/6062 at local-0001984b;1", "1901/11/201901110912urpnb2a.gsm,a") in new stack
  == Begin MixMonitor Recording Local/6062 at local-0001984b;1
    -- Executing [s at macro-VCRECORD:11] Set("Local/6062 at local-0001984b;1", "CDR(userfield)=/var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:12] Set("Local/6062 at local-0001984b;1", "__chanrecording=1901/11/201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:13] NoOp("Local/6062 at local-0001984b;1", "Recording to /var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:14] UserEvent("Local/6062 at local-0001984b;1", "RecordingToFile,Uniqueid: 201901110912urpnb2a,Channel: Local/6062 at local-0001984b;1,FileName: /var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm") in new stack
    -- Executing [s at macro-VCRECORD:15] MacroExit("Local/6062 at local-0001984b;1", "") in new stack
    -- Executing [s at macro-STDOUT:4] Macro("Local/6062 at local-0001984b;1", "VCCALLOUT,SIP/centra-out-rng,5554567781") in new stack
    -- Executing [s at macro-VCCALLOUT:1] Set("Local/6062 at local-0001984b;1", "accsplit=201901110912urpnb2a") in new stack
    -- Executing [s at macro-VCCALLOUT:2] NoOp("Local/6062 at local-0001984b;1", "Passed var is 360") in new stack
    -- Executing [s at macro-VCCALLOUT:3] Set("Local/6062 at local-0001984b;1", "timeLimit=360") in new stack
    -- Executing [s at macro-VCCALLOUT:4] Set("Local/6062 at local-0001984b;1", "chantouse=SIP/centra-out-rng") in new stack
    -- Executing [s at macro-VCCALLOUT:5] Set("Local/6062 at local-0001984b;1", "numtodial=5554567781") in new stack
    -- Executing [s at macro-VCCALLOUT:6] Set("Local/6062 at local-0001984b;1", "__numbertarget=5554567781") in new stack
    -- Executing [s at macro-VCCALLOUT:7] NoOp("Local/6062 at local-0001984b;1", "Passed SIP/centra-out-rng 5554567781 SIP/centra-out-rng 0764444492") in new stack
    -- Executing [s at macro-VCCALLOUT:8] Goto("Local/6062 at local-0001984b;1", "makecall") in new stack
    -- Goto (macro-VCCALLOUT,s,14)
    -- Executing [s at macro-VCCALLOUT:14] Macro("Local/6062 at local-0001984b;1", "SETOUTGOINGCID") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:1] Set("Local/6062 at local-0001984b;1", "Origin=l/30") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:2] NoOp("Local/6062 at local-0001984b;1", "Origin is l/30") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:3] NoOp("Local/6062 at local-0001984b;1", "Extension is s") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:4] NoOp("Local/6062 at local-0001984b;1", "Channel is Local/6062 at local-0001984b;1") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:5] Set("Local/6062 at local-0001984b;1", "AltOrigin=Local/6062") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:6] NoOp("Local/6062 at local-0001984b;1", "Alt Origin is: Local/6062") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:7] NoOp("Local/6062 at local-0001984b;1", "Internal Caller-ID Origin is: l/30") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:8] GotoIf("Local/6062 at local-0001984b;1", "0?set3133:alt3133") in new stack
    -- Goto (macro-SETOUTGOINGCID,s,13)
    -- Executing [s at macro-SETOUTGOINGCID:13] GotoIf("Local/6062 at local-0001984b;1", "0?set3133:cont3134") in new stack
    -- Goto (macro-SETOUTGOINGCID,s,14)
    -- Executing [s at macro-SETOUTGOINGCID:14] GotoIf("Local/6062 at local-0001984b;1", "0?set3134:alt3134") in new stack
    -- Goto (macro-SETOUTGOINGCID,s,19)
    -- Executing [s at macro-SETOUTGOINGCID:19] GotoIf("Local/6062 at local-0001984b;1", "0?set3134:contend") in new stack
    -- Goto (macro-SETOUTGOINGCID,s,20)
    -- Executing [s at macro-SETOUTGOINGCID:20] NoOp("Local/6062 at local-0001984b;1", "Calling on normal trunk") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:21] NoOp("Local/6062 at local-0001984b;1", "Caller-ID set to "6062_ctd" <>") in new stack
    -- Executing [s at macro-SETOUTGOINGCID:22] MacroExit("Local/6062 at local-0001984b;1", "") in new stack
    -- Executing [s at macro-VCCALLOUT:15] GotoIf("Local/6062 at local-0001984b;1", "0?dialNoLimit:dialLimit") in new stack
    -- Goto (macro-VCCALLOUT,s,30)
    -- Executing [s at macro-VCCALLOUT:30] Dial("Local/6062 at local-0001984b;1", "SIP/centra-out-rng/5554567781,120,TL(3900000:60000:30000)") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/centra-out-rng/5554567781
    -- Local/6062 at local-0001984b;1 requested media update control 26, passing it to SIP/centra-out-rng-000600fd    
    -- SIP/centra-out-rng-000600fd is making progress passing it to Local/6062 at local-0001984b;1
    -- SIP/centra-out-rng-000600fd is ringing	
== Spawn extension (local, 6062, 1) exited non-zero on 'Local/6062 at local-0001984b;2'
    -- Executing [h at local:1] NoOp("Local/6062 at local-0001984b;2", "Call hangup local") in new stack
    -- Executing [h at local:2] UserEvent("Local/3042 at local-0001984b;2", "RecordingToFile,Uniqueid: 201901110912urpnb2a,Channel: Local/6062 at local-0001984b;2,FileName: ") in new stack
    -- Executing [h at local:3] NoOp("Local/6062 at local-0001984b;2", "Recorded to ") in new stack
    -- Executing [h at local:4] Set("Local/6062 at local-0001984b;2", "CDR(userfield)=") in new stack
    -- Executing [h at local:5] NoOp("Local/6062 at local-0001984b;2", "Account code is 201901110912urpnb2a") in new stack
    -- Executing [h at local:6] NoOp("Local/6062 at local-0001984b;2", "call link var is ") in new stack
    -- Executing [h at local:7] GotoIf("Local/6062 at local-0001984b;2", "1?done") in new stack
    -- Goto (local,h,9)
    -- Executing [h at local:9] NoOp("Local/6062 at local-0001984b;2", "Call Completed") in new stack
    -- Channel Local/6062 at local-0001984b;1 left 'simple_bridge' basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
    -- Channel SIP/centra-out-rng-000600fd left 'simple_bridge' basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>	
	
  Thanks again

Stefan

More information about the asterisk-users mailing list