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@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@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@local
— Executing [6062@local:1] Dial(“Local/6062@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@local-0001984b;1 is ringing
— SIP/6062-000600f5 answered Local/6062@local-0001984b;2
— Local/6062@local-0001984b;1 answered
— Channel SIP/6062-000600f5 joined ‘simple_bridge’ basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
— Executing [0764444492@local:1] Macro(“Local/6062@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@local-0001984b;2 joined ‘simple_bridge’ basic-bridge <2848ea29-8d01-4b72-af35-d9992d4b3019>
— Executing [s@macro-STDOUT:1] Macro(“Local/6062@local-0001984b;1”, “WAITCHANNEL”) in new stack
— Executing [s@macro-WAITCHANNEL:1] Set(“Local/6062@local-0001984b;1”, “trycounter=0”) in new stack
— Executing [s@macro-WAITCHANNEL:2] Set(“Local/6062@local-0001984b;1”, “trycounter=1”) in new stack
— Executing [s@macro-WAITCHANNEL:3] GotoIf(“Local/6062@local-0001984b;1”, “1?testval:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,4)
— Executing [s@macro-WAITCHANNEL:4] GotoIf(“Local/6062@local-0001984b;1”, “1?2:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,2)
— Executing [s@macro-WAITCHANNEL:2] Set(“Local/6062@local-0001984b;1”, “trycounter=2”) in new stack
— Executing [s@macro-WAITCHANNEL:3] GotoIf(“Local/6062@local-0001984b;1”, “1?testval:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,4)
— Executing [s@macro-WAITCHANNEL:4] GotoIf(“Local/6062@local-0001984b;1”, “1?2:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,2)
— Executing [s@macro-WAITCHANNEL:2] Set(“Local/6062@local-0001984b;1”, “trycounter=3”) in new stack
— Executing [s@macro-WAITCHANNEL:3] GotoIf(“Local/6062@local-0001984b;1”, “1?testval:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,4)
— Executing [s@macro-WAITCHANNEL:4] GotoIf(“Local/6062@local-0001984b;1”, “1?2:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,2)
— Executing [s@macro-WAITCHANNEL:2] Set(“Local/6062@local-0001984b;1”, “trycounter=4”) in new stack
— Executing [s@macro-WAITCHANNEL:3] GotoIf(“Local/6062@local-0001984b;1”, “1?testval:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,4)
— Executing [s@macro-WAITCHANNEL:4] GotoIf(“Local/6062@local-0001984b;1”, “1?2:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,2)
— Executing [s@macro-WAITCHANNEL:2] Set(“Local/6062@local-0001984b;1”, “trycounter=5”) in new stack
— Executing [s@macro-WAITCHANNEL:3] GotoIf(“Local/6062@local-0001984b;1”, “0?testval:showval”) in new stack
— Goto (macro-WAITCHANNEL,s,5)
— Executing [s@macro-WAITCHANNEL:5] NoOp(“Local/6062@local-0001984b;1”, “CALLER ID “) in new stack
— Executing [s@macro-WAITCHANNEL:6] MacroExit(“Local/6062@local-0001984b;1”, “”) in new stack
— Executing [s@macro-STDOUT:2] Macro(“Local/6062@local-0001984b;1”, “WAITCDR”) in new stack
— Executing [s@macro-WAITCDR:1] Set(“Local/6062@local-0001984b;1”, “trycounter=0”) in new stack
— Executing [s@macro-WAITCDR:2] Set(“Local/6062@local-0001984b;1”, “trycounter=1”) in new stack
— Executing [s@macro-WAITCDR:3] GotoIf(“Local/6062@local-0001984b;1”, “1?testacc:showacc”) in new stack
— Goto (macro-WAITCDR,s,4)
— Executing [s@macro-WAITCDR:4] GotoIf(“Local/6062@local-0001984b;1”, “0?2:showacc”) in new stack
— Goto (macro-WAITCDR,s,5)
— Executing [s@macro-WAITCDR:5] NoOp(“Local/6062@local-0001984b;1”, “Account 201901110912urpnb2a”) in new stack
— Executing [s@macro-WAITCDR:6] MacroExit(“Local/6062@local-0001984b;1”, “”) in new stack
— Executing [s@macro-STDOUT:3] Macro(“Local/6062@local-0001984b;1”, “VCRECORD,localXACC201901110912urpnb2a,5554567781”) in new stack
— Executing [s@macro-VCRECORD:1] NoOp(“Local/6062@local-0001984b;1”, “Start of MixMonitor recording”) in new stack
— Executing [s@macro-VCRECORD:2] GotoIf(“Local/6062@local-0001984b;1”, “0?setcdr:setchan”) in new stack
— Goto (macro-VCRECORD,s,4)
— Executing [s@macro-VCRECORD:4] Set(“Local/6062@local-0001984b;1”, “=201901110912urpnb2a”) in new stack
— Executing [s@macro-VCRECORD:5] Set(“Local/6062@local-0001984b;1”, “recDir=1901/11”) in new stack
— Executing [s@macro-VCRECORD:6] Set(“Local/6062@local-0001984b;1”, “recFile=1901/11/190111091307DlocalXACC201901110912urpnb2aN5554567781ID201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:7] GotoIf(“Local/6062@local-0001984b;1”, “0?makedir:setacc”) in new stack
— Goto (macro-VCRECORD,s,8)
— Executing [s@macro-VCRECORD:8] Set(“Local/6062@local-0001984b;1”, “recFile=1901/11/201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:9] System(“Local/6062@local-0001984b;1”, “/bin/mkdir -p /var/spool/asterisk/monitor/1901/11”) in new stack
— Executing [s@macro-VCRECORD:10] MixMonitor(“Local/6062@local-0001984b;1”, “1901/11/201901110912urpnb2a.gsm,a”) in new stack
== Begin MixMonitor Recording Local/6062@local-0001984b;1
— Executing [s@macro-VCRECORD:11] Set(“Local/6062@local-0001984b;1”, “CDR(userfield)=/var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:12] Set(“Local/6062@local-0001984b;1”, “__chanrecording=1901/11/201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:13] NoOp(“Local/6062@local-0001984b;1”, “Recording to /var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:14] UserEvent(“Local/6062@local-0001984b;1”, “RecordingToFile,Uniqueid: 201901110912urpnb2a,Channel: Local/6062@local-0001984b;1,FileName: /var/spool/asterisk/monitor/1901/11/201901110912urpnb2a.gsm”) in new stack
— Executing [s@macro-VCRECORD:15] MacroExit(“Local/6062@local-0001984b;1”, “”) in new stack
— Executing [s@macro-STDOUT:4] Macro(“Local/6062@local-0001984b;1”, “VCCALLOUT,SIP/centra-out-rng,5554567781”) in new stack
— Executing [s@macro-VCCALLOUT:1] Set(“Local/6062@local-0001984b;1”, “accsplit=201901110912urpnb2a”) in new stack
— Executing [s@macro-VCCALLOUT:2] NoOp(“Local/6062@local-0001984b;1”, “Passed var is 360”) in new stack
— Executing [s@macro-VCCALLOUT:3] Set(“Local/6062@local-0001984b;1”, “timeLimit=360”) in new stack
— Executing [s@macro-VCCALLOUT:4] Set(“Local/6062@local-0001984b;1”, “chantouse=SIP/centra-out-rng”) in new stack
— Executing [s@macro-VCCALLOUT:5] Set(“Local/6062@local-0001984b;1”, “numtodial=5554567781”) in new stack
— Executing [s@macro-VCCALLOUT:6] Set(“Local/6062@local-0001984b;1”, “__numbertarget=5554567781”) in new stack
— Executing [s@macro-VCCALLOUT:7] NoOp(“Local/6062@local-0001984b;1”, “Passed SIP/centra-out-rng 5554567781 SIP/centra-out-rng 0764444492”) in new stack
— Executing [s@macro-VCCALLOUT:8] Goto(“Local/6062@local-0001984b;1”, “makecall”) in new stack
— Goto (macro-VCCALLOUT,s,14)
— Executing [s@macro-VCCALLOUT:14] Macro(“Local/6062@local-0001984b;1”, “SETOUTGOINGCID”) in new stack
— Executing [s@macro-SETOUTGOINGCID:1] Set(“Local/6062@local-0001984b;1”, “Origin=l/30”) in new stack
— Executing [s@macro-SETOUTGOINGCID:2] NoOp(“Local/6062@local-0001984b;1”, “Origin is l/30”) in new stack
— Executing [s@macro-SETOUTGOINGCID:3] NoOp(“Local/6062@local-0001984b;1”, “Extension is s”) in new stack
— Executing [s@macro-SETOUTGOINGCID:4] NoOp(“Local/6062@local-0001984b;1”, “Channel is Local/6062@local-0001984b;1”) in new stack
— Executing [s@macro-SETOUTGOINGCID:5] Set(“Local/6062@local-0001984b;1”, “AltOrigin=Local/6062”) in new stack
— Executing [s@macro-SETOUTGOINGCID:6] NoOp(“Local/6062@local-0001984b;1”, “Alt Origin is: Local/6062”) in new stack
— Executing [s@macro-SETOUTGOINGCID:7] NoOp(“Local/6062@local-0001984b;1”, “Internal Caller-ID Origin is: l/30”) in new stack
— Executing [s@macro-SETOUTGOINGCID:8] GotoIf(“Local/6062@local-0001984b;1”, “0?set3133:alt3133”) in new stack
— Goto (macro-SETOUTGOINGCID,s,13)
— Executing [s@macro-SETOUTGOINGCID:13] GotoIf(“Local/6062@local-0001984b;1”, “0?set3133:cont3134”) in new stack
— Goto (macro-SETOUTGOINGCID,s,14)
— Executing [s@macro-SETOUTGOINGCID:14] GotoIf(“Local/6062@local-0001984b;1”, “0?set3134:alt3134”) in new stack
— Goto (macro-SETOUTGOINGCID,s,19)
— Executing [s@macro-SETOUTGOINGCID:19] GotoIf(“Local/6062@local-0001984b;1”, “0?set3134:contend”) in new stack
— Goto (macro-SETOUTGOINGCID,s,20)
— Executing [s@macro-SETOUTGOINGCID:20] NoOp(“Local/6062@local-0001984b;1”, “Calling on normal trunk”) in new stack
— Executing [s@macro-SETOUTGOINGCID:21] NoOp(“Local/6062@local-0001984b;1”, “Caller-ID set to “6062_ctd” <>“) in new stack
— Executing [s@macro-SETOUTGOINGCID:22] MacroExit(“Local/6062@local-0001984b;1”, “”) in new stack
— Executing [s@macro-VCCALLOUT:15] GotoIf(“Local/6062@local-0001984b;1”, “0?dialNoLimit:dialLimit”) in new stack
— Goto (macro-VCCALLOUT,s,30)
— Executing [s@macro-VCCALLOUT:30] Dial(“Local/6062@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@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@local-0001984b;1
— SIP/centra-out-rng-000600fd is ringing
== Spawn extension (local, 6062, 1) exited non-zero on ‘Local/6062@local-0001984b;2’
— Executing [h@local:1] NoOp(“Local/6062@local-0001984b;2”, “Call hangup local”) in new stack
— Executing [h@local:2] UserEvent(“Local/3042@local-0001984b;2”, “RecordingToFile,Uniqueid: 201901110912urpnb2a,Channel: Local/6062@local-0001984b;2,FileName: “) in new stack
— Executing [h@local:3] NoOp(“Local/6062@local-0001984b;2”, “Recorded to “) in new stack
— Executing [h@local:4] Set(“Local/6062@local-0001984b;2”, “CDR(userfield)=”) in new stack
— Executing [h@local:5] NoOp(“Local/6062@local-0001984b;2”, “Account code is 201901110912urpnb2a”) in new stack
— Executing [h@local:6] NoOp(“Local/6062@local-0001984b;2”, “call link var is “) in new stack
— Executing [h@local:7] GotoIf(“Local/6062@local-0001984b;2”, “1?done”) in new stack
— Goto (local,h,9)
— Executing [h@local:9] NoOp(“Local/6062@local-0001984b;2”, “Call Completed”) in new stack
— Channel Local/6062@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

—