>> 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@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
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
Check out the new Asterisk community forum at: https://community.asterisk.org/
New to Asterisk? Start here:
https://wiki.asterisk.org/wiki/display/AST/Getting+Started
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
