I’m on asterisk 16.0.0 and I’m using the opus codec. My outbound calls are recorded, but they are very slow, so the sound is pitched down. When I download them and increase the speed in VLC, they play ok. This seems to only happen with outbound calls. I know the problem is related to using the opus codec, as it didn’t record incorrectly while testing with a different codec. I posted this over in the FreePBX forums, but they directed me over here. Has anyone else experienced this issue?
Asterisk doesn’t write out opus, so a translation must be occurring. What’s the format of the recording and the translation path? What’s the output of the following for the call in question (substituting for <channel>):
*CLI> core show channel <channel>I’m not entirely sure what you mean when you ask what the translation path is. But it’s recording into wav format. Also, know it doesn’t seem to be happening to every extension, but for those that it does, it happens every time. The output from the channel to the extension is:
(I replaced some sensitive information with XXXXXXXXX)
convergentspartanburg*CLI> core show channel PJSIP/902-00003381
-- General --
Name: PJSIP/902-00003381
Type: PJSIP
UniqueID: 1552963009.15164
LinkedID: 1552963009.15164
Caller ID: XXXXXXXXX
Caller ID Name: XXXXXXXXX
Connected Line ID: XXXXXXXXX
Connected Line ID Name: CID: XXXXXXXXX
Eff. Connected Line ID: XXXXXXXXX
Eff. Connected Line ID Name: CID:XXXXXXXXX
DNID Digits: XXXXXXXXX
Language: en
State: Up (6)
NativeFormats: (opus)
WriteFormat: slin48
ReadFormat: slin48
WriteTranscode: Yes (slin@48000)->(opus@48000)
ReadTranscode: Yes (opus@48000)->(slin@48000)
Time to Hangup: 0
Elapsed Time: 0h0m59s
Bridge ID: 98007c70-43e1-4e97-8b01-9ca6369b8592
-- PBX --
Context: macro-dialout-trunk
Extension: s
Priority: 32
Call Group: 0
Pickup Group: 0
Application: Dial
Data: PJSIP/XXXXXXXXX*XXXXXXXXX@Flowroute,300,Tb(func-apply-sipheaders^s^1,(2))
Call Identifer: [C-00000bd7]
Variables:
BRIDGEPVTCALLID=2fe8d0f2-cc83-43fd-ba7d-ee582f4fa935
BRIDGEPEER=PJSIP/Flowroute-00003382
DIALEDPEERNUMBER=XXXXXXXXX*XXXXXXXXX@Flowroute
DIALEDPEERNAME=PJSIP/Flowroute-00003382
DIALSTATUS=ANSWER
DIALEDTIME=
ANSWEREDTIME=
MACRO_DEPTH=1
DB_RESULT=Matthew Bria
AGISTATUS=FAILURE
CRM_SOURCE=902
CRM_DESTINATION=XXXXXXXXX*XXXXXXXXX
CRM_DIRECTION=OUTBOUND
MACRO_PRIORITY=7
MACRO_CONTEXT=from-internal
MACRO_EXTEN=XXXXXXXXX
ARG1=2
result=0
custom=PJSIP
OUTNUM=XXXXXXXXX*XXXXXXXXX
TRUNKOUTCID=123456789
EMERGENCYCID=
USEROUTCID=
DIAL_TRUNK_OPTIONS=T
OUTBOUND_GROUP=OUT_2
DIAL_NUMBER=XXXXXXXXX
DIAL_TRUNK=2
ARG4=off
ARG3=
ARG2=XXXXXXXXX
NODEST=
TRUNKCIDOVERRIDE="XXXXXXXXX" <XXXXXXXXX>
MOHCLASS=default
GOSUB_RETVAL=
REC_STATUS=RECORDING
RECORD_ID=PJSIP/902-00003381
MIXMON_ID=0x21c3630
LOCAL_MIXMON_ID=0x21c3630
MIXMONITOR_FILENAME=/var/spool/asterisk/monitor/2019/03/18/out-XXXXXXXXX-902-20190318-223649-1552963009.15164.wav
CALLFILENAME=out-XXXXXXXXX-902-20190318-223649-1552963009.15164
REC_POLICY_MODE=FORCE
RECMODE=dontcare
REC_POLICY_MODE_SAVE=
MON_FMT=wav
FROMEXTEN=902
TIMESTR=20190318-223649
YEAR=2019
MONTH=03
DAY=18
NOW=1552963009
DIAL_OPTIONS=HhTtr
AMPUSERCID=902
AMPUSERCIDNAME=XXXXXXXXX
AMPUSER=902
REALCALLERIDNUM=902
TOUCH_MONITOR=1552963009.15164
CDR Variables:
level 1: outbound_cnam=XXXXXXXXX
level 1: outbound_cnum=XXXXXXXXX
level 1: recordingfile=out-XXXXXXXXX-902-20190318-223649-1552963009.15164.wav
level 1: cnum=902
level 1: cnam=XXXXXXXXX
level 1: dnid=XXXXXXXXX
level 1: clid="XXXXXXXXX" <XXXXXXXXX>
level 1: src=XXXXXXXXX
level 1: dst=s
level 1: dcontext=macro-dialout-trunk
level 1: channel=PJSIP/902-00003381
level 1: dstchannel=PJSIP/Flowroute-00003382
level 1: lastapp=Dial
level 1: lastdata=PJSIP/XXXXXXXXX*XXXXXXXXX@Flowroute,300,Tb(func-apply-sipheaders^s^1,(2))
level 1: start=1552963009.282383
level 1: answer=1552963020.690722
level 1: end=0.000000
level 1: duration=58
level 1: billsec=47
level 1: disposition=8
level 1: amaflags=3
level 1: uniqueid=1552963009.15164
level 1: linkedid=1552963009.15164
level 1: sequence=23064
-- Streams --
Name: audio
Type: audio
State: sendrecv
Group: -1
Formats: (opus|ulaw|alaw|g722)
Metadata:
The output from the channel to my sip provider is:
-- General --
Name: PJSIP/Flowroute-00003382
Type: PJSIP
UniqueID: 1552963009.15165
LinkedID: 1552963009.15164
Caller ID: XXXXXXXXX
Caller ID Name: CID:XXXXXXXXX
Connected Line ID: XXXXXXXXX
Connected Line ID Name: XXXXXXXXX
Eff. Connected Line ID: XXXXXXXXX
Eff. Connected Line ID Name: XXXXXXXXX
DNID Digits: (N/A)
Language: en
State: Up (6)
NativeFormats: (ulaw)
WriteFormat: slin48
ReadFormat: slin48
WriteTranscode: Yes (slin@48000)->(slin@8000)->(ulaw@8000)
ReadTranscode: Yes (ulaw@8000)->(slin@8000)->(slin@48000)
Time to Hangup: 0
Elapsed Time: 0h1m59s
Bridge ID: 98007c70-43e1-4e97-8b01-9ca6369b8592
-- PBX --
Context: from-pstn-e164-us
Extension:
Priority: 1
Call Group: 0
Pickup Group: 0
Application: AppDial
Data: (Outgoing Line)
Call Identifer: [C-00000bd7]
Variables:
BRIDGEPVTCALLID=161797_rel77NGRhNmM3N2UyMGEwMzE4YjI3ODU4YmJmMjE0MzFmZjk
BRIDGEPEER=PJSIP/902-00003381
GOSUB_RETVAL=
sipkey=
SIPHEADERKEYS=
TECH=PJSIP
DIALEDPEERNUMBER=XXXXXXXXX*XXXXXXXXX@Flowroute
CRM_SOURCE=902
CRM_DESTINATION=XXXXXXXXX*XXXXXXXXX
CRM_DIRECTION=OUTBOUND
NODEST=
REC_STATUS=RECORDING
RECORD_ID=PJSIP/902-00003381
MIXMON_ID=0x21c3630
CALLFILENAME=out-XXXXXXXXX-902-20190318-223649-1552963009.15164
REC_POLICY_MODE=FORCE
MON_FMT=wav
FROMEXTEN=902
TIMESTR=20190318-223649
YEAR=2019
MONTH=03
DAY=18
DIAL_OPTIONS=HhTtr
CDR Variables:
level 1: clid="CID:XXXXXXXXX" <XXXXXXXXX>
level 1: src=XXXXXXXXX
level 1: dcontext=from-pstn-e164-us
level 1: channel=PJSIP/Flowroute-00003382
level 1: lastapp=AppDial
level 1: lastdata=(Outgoing Line)
level 1: start=1552963009.600198
level 1: answer=1552963020.690700
level 1: end=1552963020.702019
level 1: duration=11
level 1: billsec=0
level 1: disposition=8
level 1: amaflags=3
level 1: uniqueid=1552963009.15165
level 1: linkedid=1552963009.15164
level 1: sequence=23065
-- Streams --
Name: audio
Type: audio
State: sendrecv
Group: -1
Formats: (ulaw|opus|alaw|g722)
Metadata:
Let me know if you need any more information to help troubleshoot.
Your output shows the translation paths. It’s shown in the Write/Read Transcode output. For instance:
WriteTranscode: Yes (slin@48000)->(opus@48000)
ReadTranscode: Yes (opus@48000)->(slin@48000)
A search turned up that this could be due to things recorded at higher sample rates, and then played back at a lower one. I’m guessing the above is what’s being recorded? As you can see it’s being recorded at a high sampling rate. Is it the recording itself that is “slow” (as in sounds slow when played back), or does the other end of the call experience the distortion?
The re-sampling to ulaw should handle it on the call side I’d think:
WriteTranscode: Yes (slin@48000)->(slin@8000)->(ulaw@8000)
ReadTranscode: Yes (ulaw@8000)->(slin@8000)->(slin@48000)
1 Like
I’m not sure if it is the top part that is being recorded, but it is the recording that is slow, not the other side of the call. So basically, the program that plays the file doesn’t know that it’s being recorded at a high sample rate, so plays it back slowly?
That’s my guess especially since you stated that, “When I download them and increase the speed in VLC, they play ok”.
Also, I just tested this with two pjsip endpoints. One configured for ulaw (allow=!all,ulaw), and the other opus (allow=!all,opus), and here is the dialplan I used:
exten => 931,1,Answer()
same => n,Monitor(wav,/tmp/mixmonitor,a)
same => n,Dial(${TECH}/102,20)
same => n,Hangup()
My translations paths look the same as yours, and the playback of files sound normal. My files appear to record at a 8kHz rate. If I play them back at 48kHz then they sound “sped up” (basically the opposite of yours).
How are you recording the files? What’s your dialplan look like?
I just tried a test similar to yours, and I also didn’t have a problem but for a brief moment at the beginning of one recording. However, the problem cropped up every time I dialed out from my pjsip opus extension through my flowroute trunk. I’m connecting to Flowroute with a PJSIP trunk, on the ulaw codec. When I called in through flowroute, the problem didn’t occur. So it seems to be a directional problem.
I’m not entirely sure which section of dialplan you’re looking for. I’m using FreePBX. Should I paste the logs?
[2019-03-19 18:06:22] VERBOSE[2405] pbx_variables.c: Setting global variable 'SIPDOMAIN' to XX.XX.XX.XX'
[2019-03-19 18:06:22] VERBOSE[2405] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-03-19 18:06:22] VERBOSE[2405] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2019-03-19 18:06:22] VERBOSE[2405] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:1] Macro("PJSIP/900-00003777", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/900-00003777", "TOUCH_MONITOR=1553033182.16252") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/900-00003777", "AMPUSER=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/900-00003777", "0?report") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/900-00003777", "1?Set(REALCALLERIDNUM=900)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/900-00003777", "AMPUSER=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/900-00003777", "0?limit") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/900-00003777", "AMPUSERCIDNAME=XXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/900-00003777", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/900-00003777", "0?report") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/900-00003777", "AMPUSERCID=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/900-00003777", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/900-00003777", "CALLERID(all)="XXXXXXXX" <900>") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/900-00003777", "0?limit") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/900-00003777", "1?Set(GROUP(concurrency_limit)=900)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/900-00003777", "0?Set(CHANNEL(language)=)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:16] NoOp("PJSIP/900-00003777", "Macro Depth is 1") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/900-00003777", "1?report2:macroerror") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/900-00003777", "1?continue") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/900-00003777", "CALLERID(number)=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/900-00003777", "CALLERID(name)=XXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("PJSIP/900-00003777", "0?cnum") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/900-00003777", "CDR(cnam)=XXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/900-00003777", "CDR(cnum)=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/900-00003777", "CHANNEL(language)=en") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:2] Gosub("PJSIP/900-00003777", "sub-record-check,s,1(out,XXXXXXXXXX,force)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/900-00003777", "0?initialized") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/900-00003777", "__REC_STATUS=INITIALIZED") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/900-00003777", "NOW=1553033182") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/900-00003777", "__DAY=19") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/900-00003777", "__MONTH=03") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/900-00003777", "__YEAR=2019") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/900-00003777", "__TIMESTR=20190319-180622") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/900-00003777", "__FROMEXTEN=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/900-00003777", "__MON_FMT=wav") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/900-00003777", "Recordings initialized") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/900-00003777", "0?Set(ARG3=dontcare)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/900-00003777", "REC_POLICY_MODE_SAVE=") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/900-00003777", "0?Set(REC_STATUS=NO)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/900-00003777", "3?checkaction") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/900-00003777", "1?sub-record-check,out,1") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (sub-record-check,out,1)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [out@sub-record-check:1] NoOp("PJSIP/900-00003777", "Outbound Recording Check from 900 to XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [out@sub-record-check:2] Set("PJSIP/900-00003777", "RECMODE=dontcare") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [out@sub-record-check:3] ExecIf("PJSIP/900-00003777", "1?Goto(routewins)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (sub-record-check,out,7)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [out@sub-record-check:7] Gosub("PJSIP/900-00003777", "recordcheck,1(force,out,XXXXXXXXXX)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/900-00003777", "Starting recording check against force") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/900-00003777", "force") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:5] Set("PJSIP/900-00003777", "__REC_POLICY_MODE=FORCE") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf("PJSIP/900-00003777", "1?startrec") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("PJSIP/900-00003777", "Starting recording: out, XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:17] Set("PJSIP/900-00003777", "__CALLFILENAME=out-XXXXXXXXXX-900-20190319-180622-1553033182.16252") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:18] MixMonitor("PJSIP/900-00003777", "2019/03/19/out-XXXXXXXXXX-900-20190319-180622-1553033182.16252.wav,abi(LOCAL_MIXMON_ID),") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:19] Set("PJSIP/900-00003777", "__MIXMON_ID=0x7fad04124c80") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:20] Set("PJSIP/900-00003777", "__RECORD_ID=PJSIP/900-00003777") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:21] Set("PJSIP/900-00003777", "__REC_STATUS=RECORDING") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:22] Set("PJSIP/900-00003777", "CDR(recordingfile)=out-XXXXXXXXXX-900-20190319-180622-1553033182.16252.wav") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [recordcheck@sub-record-check:23] Return("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:3] ExecIf("PJSIP/900-00003777", "0 ?Set(CDR(accountcode)=)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:4] Set("PJSIP/900-00003777", "MOHCLASS=default") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:5] ExecIf("PJSIP/900-00003777", "1?Set(TRUNKCIDOVERRIDE="XXXXXXXX" <XXXXXXXXXX>)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:6] Set("PJSIP/900-00003777", "_NODEST=") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [XXXXXXXXXX@from-internal:7] Macro("PJSIP/900-00003777", "dialout-trunk,2,1XXXXXXXXXX,,off") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/900-00003777", "DIAL_TRUNK=2") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/900-00003777", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/900-00003777", "0?sub-pincheck,s,1()") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/900-00003777", "0?Set(CALLERID(num)=900)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/900-00003777", "0?disabletrunk,1") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/900-00003777", "DIAL_NUMBER=1XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/900-00003777", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/900-00003777", "OUTBOUND_GROUP=OUT_2") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/900-00003777", "DIAL_TRUNK_OPTIONS=T") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/900-00003777", "1?nomax") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/900-00003777", "0?skipoutcid") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/900-00003777", "outbound-callerid,2") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/900-00003777", "900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/900-00003777", "off") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/900-00003777", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/900-00003777", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf("PJSIP/900-00003777", "0?Set(REALCALLERIDNUM=900)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf("PJSIP/900-00003777", "0?Set(AMPUSER=900)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf("PJSIP/900-00003777", "1?normcid") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:12] Set("PJSIP/900-00003777", "USEROUTCID=") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:13] Set("PJSIP/900-00003777", "EMERGENCYCID=") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:14] Set("PJSIP/900-00003777", "TRUNKOUTCID=123456789") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf("PJSIP/900-00003777", "1?trunkcid") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf("PJSIP/900-00003777", "1?Set(CALLERID(all)=123456789)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("PJSIP/900-00003777", "0?Set(CALLERID(all)=)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/900-00003777", "1?Set(CALLERID(all)=XXXXXXXX <XXXXXXXXXX>)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/900-00003777", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/900-00003777", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:25] Set("PJSIP/900-00003777", "CDR(outbound_cnum)=XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/900-00003777", "CDR(outbound_cnam)=XXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/900-00003777", "0?sub-flp-2,s,1()") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/900-00003777", "OUTNUM=XXXXXXXX*1XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/900-00003777", "custom=PJSIP") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/900-00003777", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/900-00003777", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/900-00003777", "dialout-trunk-predial-hook,") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] Verbose("PJSIP/900-00003777", "calling: "XXXXXXXX*1XXXXXXXXXX"") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] app_verbose.c: calling: XXXXXXXX*1XXXXXXXXXX
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:2] AGI("PJSIP/900-00003777", "blacklist.agi, XXXXXXXX*1XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/blacklist.agi
[2019-03-19 18:06:22] VERBOSE[4459][C-00000cc3] app_mixmonitor.c: Begin MixMonitor Recording PJSIP/900-00003777
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] res_agi.c: <PJSIP/900-00003777>AGI Script blacklist.agi completed, returning 0
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:3] Verbose("PJSIP/900-00003777", "result: "0"") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] app_verbose.c: result: 0
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:4] ExecIf("PJSIP/900-00003777", "0?Goto(banned,s,1") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:5] MacroExit("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/900-00003777", "0?skipcrm") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:21] Set("PJSIP/900-00003777", "__CRM_DIRECTION=OUTBOUND") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:22] Set("PJSIP/900-00003777", "__CRM_DESTINATION=XXXXXXXX*1XXXXXXXXXX") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:23] Set("PJSIP/900-00003777", "__CRM_SOURCE=900") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:24] AGI("PJSIP/900-00003777", "sangomacrm.agi") in new stack
[2019-03-19 18:06:22] VERBOSE[4457][C-00000cc3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] res_agi.c: <PJSIP/900-00003777>AGI Script sangomacrm.agi completed, returning 0
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:25] Set("PJSIP/900-00003777", "CHANNEL(hangup_handler_push)=crm-hangup,s,1") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp("PJSIP/900-00003777", "CRM Finished") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf("PJSIP/900-00003777", "0?bypass,1") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf("PJSIP/900-00003777", "1?Set(CONNECTEDLINE(num,i)=1XXXXXXXXXX)") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf("PJSIP/900-00003777", "1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:30] ExecIf("PJSIP/900-00003777", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)XXXXXXXXXX)") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:31] GotoIf("PJSIP/900-00003777", "0?customtrunk") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-dialout-trunk:32] Dial("PJSIP/900-00003777", "PJSIP/XXXXXXXX*1XXXXXXXXXX@Flowroute,300,Tb(func-apply-sipheaders^s^1,(2))") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] app_stack.c: PJSIP/Flowroute-00003778 Internal Gosub(func-apply-sipheaders,s,1(2)) start
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/Flowroute-00003778", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/Flowroute-00003778", "Applying SIP Headers to channel PJSIP/Flowroute-00003778") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/Flowroute-00003778", "TECH=PJSIP") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/Flowroute-00003778", "SIPHEADERKEYS=") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Flowroute-00003778", "0") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] app_while.c: Jumping to priority 12
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@func-apply-sipheaders:13] Return("PJSIP/Flowroute-00003778", "") in new stack
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] app_stack.c: Spawn extension (from-pstn-e164-us, XXXXXXXXXX, 1) exited non-zero on 'PJSIP/Flowroute-00003778'
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] app_stack.c: PJSIP/Flowroute-00003778 Internal Gosub(func-apply-sipheaders,s,1(2)) complete GOSUB_RETVAL=
[2019-03-19 18:06:23] VERBOSE[4457][C-00000cc3] app_dial.c: Called PJSIP/XXXXXXXX*1XXXXXXXXXX@Flowroute
[2019-03-19 18:06:24] VERBOSE[7973] res_rtp_asterisk.c: 0x7facf0174ba0 -- Strict RTP learning after remote address set to: 23.29.23.42:32684
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] app_dial.c: PJSIP/Flowroute-00003778 is making progress passing it to PJSIP/900-00003777
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] app_dial.c: PJSIP/Flowroute-00003778 is making progress passing it to PJSIP/900-00003777
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] res_rtp_asterisk.c: 0x7facf0174ba0 -- Strict RTP switching to RTP target address 23.29.23.42:32684 as source
[2019-03-19 18:06:24] VERBOSE[22760] res_rtp_asterisk.c: 0x7facf845df00 -- Strict RTP learning after remote address set to: 192.168.39.101:12520
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] res_rtp_asterisk.c: 0x7facf845df00 -- Strict RTP qualifying stream type: audio
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] app_dial.c: PJSIP/Flowroute-00003778 is making progress passing it to PJSIP/900-00003777
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] app_dial.c: PJSIP/Flowroute-00003778 is making progress passing it to PJSIP/900-00003777
[2019-03-19 18:06:24] VERBOSE[4457][C-00000cc3] res_rtp_asterisk.c: 0x7facf845df00 -- Strict RTP switching source address to 216.249.126.191:10001
[2019-03-19 18:06:28] VERBOSE[4457][C-00000cc3] app_dial.c: PJSIP/Flowroute-00003778 answered PJSIP/900-00003777
[2019-03-19 18:06:28] VERBOSE[4481][C-00000cc3] bridge_channel.c: Channel PJSIP/Flowroute-00003778 joined 'simple_bridge' basic-bridge <72a074b5-90de-42cb-8eb3-c20f57ccf37a>
[2019-03-19 18:06:28] VERBOSE[4457][C-00000cc3] bridge_channel.c: Channel PJSIP/900-00003777 joined 'simple_bridge' basic-bridge <72a074b5-90de-42cb-8eb3-c20f57ccf37a>
[2019-03-19 18:06:29] VERBOSE[4481][C-00000cc3] res_rtp_asterisk.c: 0x7facf0174ba0 -- Strict RTP learning complete - Locking on source address 23.29.23.42:32684
[2019-03-19 18:06:29] VERBOSE[4457][C-00000cc3] res_rtp_asterisk.c: 0x7facf845df00 -- Strict RTP learning complete - Locking on source address 216.249.126.191:10001
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] bridge_channel.c: Channel PJSIP/900-00003777 left 'simple_bridge' basic-bridge <72a074b5-90de-42cb-8eb3-c20f57ccf37a>
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] app_macro.c: Spawn extension (macro-dialout-trunk, s, 32) exited non-zero on 'PJSIP/900-00003777' in macro 'dialout-trunk'
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Spawn extension (from-internal, XXXXXXXXXX, 7) exited non-zero on 'PJSIP/900-00003777'
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/900-00003777", "hangupcall") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/900-00003777", "1?theend") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-03-19 18:06:36] VERBOSE[4481][C-00000cc3] bridge_channel.c: Channel PJSIP/Flowroute-00003778 left 'simple_bridge' basic-bridge <72a074b5-90de-42cb-8eb3-c20f57ccf37a>
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/900-00003777", "0?Set(CDR(recordingfile)=)") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/900-00003777", "PJSIP/Flowroute-00003778 monior file= /var/spool/asterisk/monitor/2019/03/19/out-XXXXXXXXXX-900-20190319-180622-1553033182.16252.wav") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-hangupcall:5] AGI("PJSIP/900-00003777", "attendedtransfer-rec-restart.php,PJSIP/Flowroute-00003778,/var/spool/asterisk/monitor/2019/03/19/out-XXXXXXXXXX-900-20190319-180622-1553033182.16252.wav") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2019-03-19 18:06:36] VERBOSE[3538] asterisk.c: Remote UNIX connection
[2019-03-19 18:06:36] VERBOSE[4678] asterisk.c: Remote UNIX connection disconnected
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] res_agi.c: <PJSIP/900-00003777>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2019-03-19 18:06:36] VERBOSE[3538] asterisk.c: Remote UNIX connection
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@macro-hangupcall:6] Hangup("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'PJSIP/900-00003777' in macro 'hangupcall'
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/900-00003777'
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] app_stack.c: PJSIP/900-00003777 Internal Gosub(crm-hangup,s,1) start
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/900-00003777", "Sending Hangup to CRM") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/900-00003777", "HANGUP CAUSE: 16") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/900-00003777", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/900-00003777", "MASTER CHANNEL: 1553033182.16252 = 1553033182.16252") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/900-00003777", "0?return") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/900-00003777", "__CRM_HANGUP=1") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/900-00003777", "sangomacrm.agi") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-03-19 18:06:36] VERBOSE[4688] asterisk.c: Remote UNIX connection disconnected
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] res_agi.c: <PJSIP/900-00003777>AGI Script sangomacrm.agi completed, returning 0
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/900-00003777", "") in new stack
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/900-00003777'
[2019-03-19 18:06:36] VERBOSE[4457][C-00000cc3] app_stack.c: PJSIP/900-00003777 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2019-03-19 18:06:36] VERBOSE[4459][C-00000cc3] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-03-19 18:06:36] VERBOSE[4459][C-00000cc3] app_mixmonitor.c: End MixMonitor Recording PJSIP/900-00003777
I noticed I was not using MixMonitor in my example. However, using MixMonitor I still get the same results, i.e. audio sounds normal no matter which direction I dial. What sample rate are your files being recorded in? The file’s properties might show this, or some applications should (for instance “audacity”).
Also can you post the sip traffic of the original negotiation (“pjsip set logger on”)? Do you have anything set in codecs.conf for opus?
Audacity plays the file at 8000hz. I can’t find the correct place for it to be at though. It doesn’t work at any of audacity’s presets. I think it should be somewhere around 24000hz. I’m attaching a sample file here. I had to change the extension to .txt, but if you download it and change it to .wav, then it should work. I’m realizing now that you might not feel comfortable doing that, so if there is a more secure way that you would rather I send it, let me know.
slow_call_recording.txt (343.2 KB)
Also, I honestly can’t find codecs.conf. I looked under /etc/asterisk but it isn’t there. Could this be because I’m using FreePBX?
I got way too many sip packets using pjsip set logger on, so I just used sngrep to get this.
This is the invite from the extension to the server:
2019/03/19 20:38:56.626918 XXX.XXX.XXX.XXX:10004 -> XXXXXXX:5160
INVITE sip:XXXXXXX@XXXXXXX:5160 SIP/2.0
Via: SIP/2.0/UDP 192.168.39.101:5160;branch=z9hG4bK865312358;rport
From: "900" <sip:900@XXXXXXX:5160>;tag=2007097636
To: <sip:XXXXXXX@XXXXXXX:5160>
Call-ID: 0_957094888@192.168.39.101
CSeq: 2 INVITE
Contact: <sip:900@192.168.39.101:5160>
Authorization: Digest username="900", realm="asterisk", nonce="1553042336/567d9be4ca2fe62d76bc0f0386551062", uri="sip:XXXXXXX@XXXXXXX:5160", response="62c5e043d2075f68a21da96d665aa406", algorithm=MD5, cnonce="0a4f113b", opaque="1df
42c2c02ef5f", qop=auth, nc=00000001
Content-Type: application/sdp
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T48S 66.84.0.10
Allow-Events: talk,hold,conference,refer,check-sync
Supported: replaces
Content-Length: 432
v=0
o=- 20002 20002 IN IP4 192.168.39.101
s=SDP data
c=IN IP4 192.168.39.101
t=0 0
m=audio 11896 RTP/AVP 0 107 8 18 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:107 opus/48000/2
a=fmtp:107 sprop-maxcapturerate=16000; maxaveragebitrate=20000; maxplaybackrate=48000; useinbandfec=1
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
This is the invite from the server to Flowroute
2019/03/19 20:38:56.982533 X.X.X.X:5160 -> XXXXXXX:5060
INVITE sip:XXXXXX*XXXXXXX@us-east-va.sip.flowroute.com:5060 SIP/2.0
Via: SIP/2.0/UDP XXXXXXX:5160;rport;branch=z9hG4bKPj10fe67c7-d345-4e77-a372-3a42bea9048e
From: "XXXXXXX" <sip:XXXXXXX@us-east-va.sip.flowroute.com>;tag=7aacdb6c-73c1-4199-a67c-b49c9c19445e
To: <sip:XXXXXXX*XXXXXXX@us-east-va.sip.flowroute.com>
Contact: <sip:asterisk@XXXXXXX:5160>
Call-ID: 6e7f7103-22b6-492e-938d-fc102efdfa78
CSeq: 10604 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(16.0.0)
Content-Type: application/sdp
Content-Length: 333
v=0
o=- 236955460 236955460 IN IP4 XXXXXXX
s=Asterisk
c=IN IP4 XXXXXXX
t=0 0
m=audio 12346 RTP/AVP 0 8 9 3 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
If you have an slin48 file, there will be no meta data to say what speed to use, so you will have to manually specify that. slin48 should be played back with 48,000Hz sampling.
It sounds like there is nothing wrong with the recording, but you are using the playback tools wrongly. You can use sox to add .wav (RIFF) meta data, so that playback programs know the correct sapling rate.
Yep I played it back at 24kHz and it sounded fine. I’m not really sure why it is writing out at the rate it is though.
You might try recording in a different format. I’d also be curious what happens if you chose another codec that supported a higher sampling rate.
Otherwise it could just be as David says and you could add the correct meta data.
I think I’ve realised why you are getting 24kHz, rather than 48kHz. slin48 is mono, but the program you used is probably assuming stereo, so consuming two samples for every sample time.
If you actually use Audacity, you are pretty much forced to select all the relevant parameters when you import.
Has anyone found a solution to this problem? I’m encountering a similar issue.
Below is the dashboard I constructed to illustrate the “Call Story”. It depicts how each participant in a conversation perceives the call.
As evident in the first pair of bars, one of the red bars exceeds the bars representing the total call duration. When I attempt to listen, the calls play in slow motion. This call originates from a pjsip endpoint and is directed to a sip trunk.
Conversely, the second pair of bars appear accurate and play correctly. This call is made in the opposite direction, from a sip trunk to a pjsip endpoint.
Sometimes, restarting the Asterisk resolves the problem. However, I’m uncertain of the root cause and how to permanently prevent it.
