Weird call behavior, dropped calls, no audio, no ringback tone

FreePBX Endpoints
1

Hello All,

I recently was locked out of my pbx via cli. I followed these instructions ( https://www.redhat.com/sysadmin/recover-root-passwd ) to recover the password, that was successful. After that I tested calls and got no audio. I am testing using a soft phone, to a mobile phone and vise versa. I get no call audio on outbound or inbound calls. There is also no ringback tone when I am making calls. I hear the ringback maybe once sometimes, and then it just goes blank until the call is answered or not. Here is a log of one of the calls. Any help would be greatly appreciated.

Executing [+16022395896@from-pstn-e164-us:1] Set(“SIP/L3_In-0000005d”, “CALLERID(number)=8585255052”) in new stack
– Executing [+16022395896@from-pstn-e164-us:2] Goto(“SIP/L3_In-0000005d”, “from-pstn,6022395896,1”) in new stack
– Goto (from-pstn,6022395896,1)
– Executing [6022395896@from-pstn:1] Set(“SIP/L3_In-0000005d”, “__DIRECTION=INBOUND”) in new stack
– Executing [6022395896@from-pstn:2] Gosub(“SIP/L3_In-0000005d”, “sub-record-check,s,1(in,6022395896,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/L3_In-0000005d”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“SIP/L3_In-0000005d”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“SIP/L3_In-0000005d”, “NOW=1606322676”) in new stack
– Executing [s@sub-record-check:4] Set(“SIP/L3_In-0000005d”, “__DAY=25”) in new stack
– Executing [s@sub-record-check:5] Set(“SIP/L3_In-0000005d”, “__MONTH=11”) in new stack
– Executing [s@sub-record-check:6] Set(“SIP/L3_In-0000005d”, “__YEAR=2020”) in new stack
– Executing [s@sub-record-check:7] Set(“SIP/L3_In-0000005d”, “__TIMESTR=20201125-164436”) in new stack
– Executing [s@sub-record-check:8] Set(“SIP/L3_In-0000005d”, “__FROMEXTEN=unknown”) in new stack
– Executing [s@sub-record-check:9] Set(“SIP/L3_In-0000005d”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“SIP/L3_In-0000005d”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/L3_In-0000005d”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/L3_In-0000005d”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/L3_In-0000005d”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/L3_In-0000005d”, “2?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/L3_In-0000005d”, “1?sub-record-check,in,1”) in new stack
– Goto (sub-record-check,in,1)
– Executing [in@sub-record-check:1] NoOp(“SIP/L3_In-0000005d”, “Inbound Recording Check to 6022395896”) in new stack
– Executing [in@sub-record-check:2] Set(“SIP/L3_In-0000005d”, “FROMEXTEN=unknown”) in new stack
– Executing [in@sub-record-check:3] ExecIf(“SIP/L3_In-0000005d”, “10?Set(FROMEXTEN=8585255052)”) in new stack
– Executing [in@sub-record-check:4] Gosub(“SIP/L3_In-0000005d”, “recordcheck,1(dontcare,in,6022395896)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/L3_In-0000005d”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/L3_In-0000005d”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [in@sub-record-check:5] Return(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [6022395896@from-pstn:3] Set(“SIP/L3_In-0000005d”, “CHANNEL(tonezone)=us”) in new stack
– Executing [6022395896@from-pstn:4] Set(“SIP/L3_In-0000005d”, “__FROM_DID=6022395896”) in new stack
– Executing [6022395896@from-pstn:5] Set(“SIP/L3_In-0000005d”, “returnhere=1”) in new stack
– Executing [6022395896@from-pstn:6] Gosub(“SIP/L3_In-0000005d”, “app-blacklist-check,s,1()”) in new stack
– Executing [s@app-blacklist-check:1] GotoIf(“SIP/L3_In-0000005d”, “0?blacklisted”) in new stack
– Executing [s@app-blacklist-check:2] Set(“SIP/L3_In-0000005d”, “CALLED_BLACKLIST=1”) in new stack
– Executing [s@app-blacklist-check:3] Return(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [6022395896@from-pstn:7] Set(“SIP/L3_In-0000005d”, “CDR(did)=6022395896”) in new stack
– Executing [6022395896@from-pstn:8] GotoIf(“SIP/L3_In-0000005d”, “0?”) in new stack
– Executing [6022395896@from-pstn:9] ExecIf(“SIP/L3_In-0000005d”, “0 ?Set(CALLERID(name)=8585255052)”) in new stack
– Executing [6022395896@from-pstn:10] Set(“SIP/L3_In-0000005d”, “__MOHCLASS=”) in new stack
– Executing [6022395896@from-pstn:11] Set(“SIP/L3_In-0000005d”, “__REVERSAL_REJECT=FALSE”) in new stack
– Executing [6022395896@from-pstn:12] GotoIf(“SIP/L3_In-0000005d”, “1?post-reverse-charge”) in new stack
– Goto (from-pstn,6022395896,14)
– Executing [6022395896@from-pstn:14] NoOp(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [6022395896@from-pstn:15] Set(“SIP/L3_In-0000005d”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
– Executing [6022395896@from-pstn:16] Set(“SIP/L3_In-0000005d”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
– Executing [6022395896@from-pstn:17] Set(“SIP/L3_In-0000005d”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
– Executing [6022395896@from-pstn:18] Set(“SIP/L3_In-0000005d”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
– Executing [6022395896@from-pstn:19] NoOp(“SIP/L3_In-0000005d”, “CallerID Entry Point”) in new stack
– Executing [6022395896@from-pstn:20] Set(“SIP/L3_In-0000005d”, “__CRM_DIRECTION=INBOUND”) in new stack
– Executing [6022395896@from-pstn:21] Set(“SIP/L3_In-0000005d”, “__CRM_SOURCE=8585255052”) in new stack
– Executing [6022395896@from-pstn:22] Set(“SIP/L3_In-0000005d”, “__CRM_LINKEDID=1606322676.107”) in new stack
– Executing [6022395896@from-pstn:23] AGI(“SIP/L3_In-0000005d”, “agi://127.0.0.1/sangomacrm.agi,true”) in new stack
– <SIP/L3_In-0000005d>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
– Executing [6022395896@from-pstn:24] ExecIf(“SIP/L3_In-0000005d”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
– Executing [6022395896@from-pstn:25] Goto(“SIP/L3_In-0000005d”, “ext-local,vmu5896,1”) in new stack
– Goto (ext-local,vmu5896,1)
– Executing [vmu5896@ext-local:1] Macro(“SIP/L3_In-0000005d”, “vm,5896,NOANSWER,”) in new stack
– Executing [s@macro-vm:1] Macro(“SIP/L3_In-0000005d”, “user-callerid,SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/L3_In-0000005d”, “TOUCH_MONITOR=1606322676.107”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/L3_In-0000005d”, “AMPUSER=8585255052”) in new stack
– Executing [s@macro-user-callerid:3] Set(“SIP/L3_In-0000005d”, “HOTDESCKCHAN=L3_In-0000005d”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/L3_In-0000005d”, “HOTDESKEXTEN=L3_In”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/L3_In-0000005d”, “HOTDESKCALL=0”) in new stack
– Executing [s@macro-user-callerid:6] ExecIf(“SIP/L3_In-0000005d”, “0?Set(HOTDESKCALL=1)”) in new stack
– Executing [s@macro-user-callerid:7] ExecIf(“SIP/L3_In-0000005d”, “0?Set(CALLERID(name)=)”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“SIP/L3_In-0000005d”, “0?report”) in new stack
– Executing [s@macro-user-callerid:9] ExecIf(“SIP/L3_In-0000005d”, “1?Set(REALCALLERIDNUM=8585255052)”) in new stack
– Executing [s@macro-user-callerid:10] Set(“SIP/L3_In-0000005d”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:11] GotoIf(“SIP/L3_In-0000005d”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:12] Set(“SIP/L3_In-0000005d”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:13] ExecIf(“SIP/L3_In-0000005d”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“SIP/L3_In-0000005d”, “1?report”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“SIP/L3_In-0000005d”, “Macro Depth is 2”) in new stack
– Executing [s@macro-user-callerid:24] GotoIf(“SIP/L3_In-0000005d”, “1?report2:macroerror”) in new stack
– Goto (macro-user-callerid,s,25)
– Executing [s@macro-user-callerid:25] GotoIf(“SIP/L3_In-0000005d”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,44)
– Executing [s@macro-user-callerid:44] Set(“SIP/L3_In-0000005d”, “CALLERID(number)=8585255052”) in new stack
– Executing [s@macro-user-callerid:45] Set(“SIP/L3_In-0000005d”, “CALLERID(name)=WIRELESS CALLER”) in new stack
– Executing [s@macro-user-callerid:46] GotoIf(“SIP/L3_In-0000005d”, “0?cnum”) in new stack
– Executing [s@macro-user-callerid:47] Set(“SIP/L3_In-0000005d”, “CDR(cnam)=WIRELESS CALLER”) in new stack
– Executing [s@macro-user-callerid:48] Set(“SIP/L3_In-0000005d”, “CDR(cnum)=8585255052”) in new stack
– Executing [s@macro-user-callerid:49] Set(“SIP/L3_In-0000005d”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-vm:2] Set(“SIP/L3_In-0000005d”, “VMGAIN=”) in new stack
– Executing [s@macro-vm:3] Macro(“SIP/L3_In-0000005d”, “blkvm-check,”) in new stack
– Executing [s@macro-blkvm-check:1] Set(“SIP/L3_In-0000005d”, “GOSUB_RETVAL=”) in new stack
– Executing [s@macro-blkvm-check:2] ExecIf(“SIP/L3_In-0000005d”, “0?Set(GOSUB_RETVAL=TRUE)”) in new stack
– Executing [s@macro-blkvm-check:3] MacroExit(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [s@macro-vm:4] GotoIf(“SIP/L3_In-0000005d”, “1?vmx,1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] Set(“SIP/L3_In-0000005d”, “__EXTTOCALL=5896”) in new stack
– Executing [vmx@macro-vm:2] Set(“SIP/L3_In-0000005d”, “__CRM_VOICEMAIL=5896”) in new stack
– Executing [vmx@macro-vm:3] Set(“SIP/L3_In-0000005d”, “MEXTEN=5896”) in new stack
– Executing [vmx@macro-vm:4] Set(“SIP/L3_In-0000005d”, “MMODE=NOANSWER”) in new stack
– Executing [vmx@macro-vm:5] Set(“SIP/L3_In-0000005d”, “RETVM=”) in new stack
– Executing [vmx@macro-vm:6] Set(“SIP/L3_In-0000005d”, “MODE=unavail”) in new stack
– Executing [vmx@macro-vm:7] Macro(“SIP/L3_In-0000005d”, “get-vmcontext,5896”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“SIP/L3_In-0000005d”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/L3_In-0000005d”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [vmx@macro-vm:8] Set(“SIP/L3_In-0000005d”, “MODE=unavail”) in new stack
– Executing [vmx@macro-vm:9] NoOp(“SIP/L3_In-0000005d”, “MODE IS: unavail”) in new stack
– Executing [vmx@macro-vm:10] GotoIf(“SIP/L3_In-0000005d”, “1?chknomsg”) in new stack
– Goto (macro-vm,vmx,12)
– Executing [vmx@macro-vm:12] GotoIf(“SIP/L3_In-0000005d”, “0?s-NOANSWER,1”) in new stack
– Executing [vmx@macro-vm:13] GotoIf(“SIP/L3_In-0000005d”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,15)
– Executing [vmx@macro-vm:15] NoOp(“SIP/L3_In-0000005d”, "Checking if ext 5896 is enabled: ") in new stack
– Executing [vmx@macro-vm:16] GotoIf(“SIP/L3_In-0000005d”, “1?s-NOANSWER,1”) in new stack
– Goto (macro-vm,s-NOANSWER,1)
– Executing [s-NOANSWER@macro-vm:1] Macro(“SIP/L3_In-0000005d”, “get-vmcontext,5896”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“SIP/L3_In-0000005d”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/L3_In-0000005d”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“SIP/L3_In-0000005d”, “”) in new stack
– Executing [s-NOANSWER@macro-vm:2] VoiceMail(“SIP/L3_In-0000005d”, “5896@default,u”) in new stack
Audio is at 11460
Adding codec ulaw to SDP
Adding codec alaw to SDP

== Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘SIP/L3_In-0000005d’ in macro ‘vm’
== Spawn extension (ext-local, vmu5896, 1) exited non-zero on ‘SIP/L3_In-0000005d’
– Executing [h@ext-local:1] Macro(“SIP/L3_In-0000005d”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/L3_In-0000005d”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [s@macro-hangupcall:3] ExecIf(“SIP/L3_In-0000005d”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:4] NoOp(“SIP/L3_In-0000005d”, " montior file= ") in new stack
– Executing [s@macro-hangupcall:5] GotoIf(“SIP/L3_In-0000005d”, “1?skipagi”) in new stack
– Goto (macro-hangupcall,s,7)
– Executing [s@macro-hangupcall:7] Hangup(“SIP/L3_In-0000005d”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘SIP/L3_In-0000005d’ in macro ‘hangupcall’
== Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/L3_In-0000005d’
– SIP/L3_In-0000005d Internal Gosub(crm-hangup,s,1) start
– Executing [s@crm-hangup:1] NoOp(“SIP/L3_In-0000005d”, “Sending Hangup to CRM”) in new stack
– Executing [s@crm-hangup:2] NoOp(“SIP/L3_In-0000005d”, “HANGUP CAUSE: 16”) in new stack
– Executing [s@crm-hangup:3] ExecIf(“SIP/L3_In-0000005d”, “1?Set(__CRM_VOICEMAIL=FAILED)”) in new stack
– Executing [s@crm-hangup:4] NoOp(“SIP/L3_In-0000005d”, “MASTER CHANNEL: 1606322676.107 = 1606322676.107”) in new stack
– Executing [s@crm-hangup:5] GotoIf(“SIP/L3_In-0000005d”, “0?return”) in new stack
– Executing [s@crm-hangup:6] Set(“SIP/L3_In-0000005d”, “__CRM_HANGUP=1”) in new stack
– Executing [s@crm-hangup:7] AGI(“SIP/L3_In-0000005d”, “agi://127.0.0.1/sangomacrm.agi”) in new stack
– <SIP/L3_In-0000005d>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
– Executing [s@crm-hangup:8] Return(“SIP/L3_In-0000005d”, “”) in new stack
== Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/L3_In-0000005d’
– SIP/L3_In-0000005d Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

2

Also, when I enter the asterisk cli with -rvvv, the terminal is getting a ton of messages like this.

<— SIP read from UDP:10.129.254.8:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.129.254.3:5060;branch=z9hG4bK0b2cd622
From: “Unknown” sip:[email protected];tag=as079c79c4
To: sip:[email protected];tag=1c1103179655
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
Contact: sip:10.129.254.8:5060;expires=0
Supported: 100rel
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: MP-124E FXS/v.6.60A.301.005
X-Resources: telchs=24/0;mediachs=0/0
Accept: application/sdp, application/simple-message-summary, message/sipfrag
Content-Type: application/sdp
Content-Length: 233

I also see a lot of this.

Really destroying SIP dialog ‘[email protected]’ Method: REGISTER
Really destroying SIP dialog ‘[email protected]’ Method: REGISTER
Really destroying SIP dialog ‘[email protected]’ Method: REGISTER
Really destroying SIP dialog ‘[email protected]’ Method: REGISTER
Really destroying SIP dialog ‘[email protected]’ Method: REGISTER
Really destroying SIP dialog ‘[email protected]’ Method: REGISTER

3

Both inbound and outbound calls drop after 30 seconds. There is no audio going either way.

4

Here is a sip show settings output

freepbx*CLI> sip show settings

Global Settings:

UDP Bindaddress: 0.0.0.0:5060
TCP SIP Bindaddress: Disabled
TLS SIP Bindaddress: Disabled
RTP Bindaddress: Disabled
Videosupport: No
Textsupport: No
Ignore SDP sess. ver.: No
AutoCreate Peer: Off
Match Auth Username: No
Allow unknown access: Yes
Allow subscriptions: Yes
Allow overlap dialing: Yes
Allow promisc. redir: No
Enable call counters: No
SIP domain support: No
Path support : No
Realm. auth: No
Our auth realm asterisk
Use domains as realms: No
Call to non-local dom.: Yes
URI user is phone no: No
Always auth rejects: Yes
Direct RTP setup: No
User Agent: FPBX-15.0.16.75(16.11.1)
SDP Session Name: Asterisk PBX 16.11.1
SDP Owner Name: root
Reg. context: (not set)
Regexten on Qualify: No
Trust RPID: No
Send RPID: No
Legacy userfield parse: No
Send Diversion: Yes
Caller ID: Unknown
From: Domain:
Record SIP history: Off
Auth. Failure Events: Off
T.38 support: Yes
T.38 EC mode: Redundancy
T.38 MaxDtgrm: 400
SIP realtime: Disabled
Qualify Freq : 60000 ms
Q.850 Reason header: No
Store SIP_CAUSE: No

Network QoS Settings:

IP ToS SIP: CS3
IP ToS RTP audio: EF
IP ToS RTP video: AF41
IP ToS RTP text: CS0
802.1p CoS SIP: 4
802.1p CoS RTP audio: 5
802.1p CoS RTP video: 6
802.1p CoS RTP text: 5
Jitterbuffer enabled: No

Network Settings:

SIP address remapping: Enabled using externaddr
Externhost:
Externaddr: 96.8.44.26:0
Externrefresh: 10
Localnet: 10.129.254.0/255.255.255.0
96.8.44.24/255.255.255.248
10.129.255.0/255.255.255.0
10.255.1.0/255.255.255.0
10.255.129.0/255.255.255.0
10.255.255.0/255.255.255.128
172.27.4.0/255.255.255.128

Global Signalling Settings:

Codecs: (ulaw|alaw|gsm)
Relax DTMF: No
RFC2833 Compensation: No
Symmetric RTP: No
Compact SIP headers: No
RTP Keepalive: 0 (Disabled)
RTP Timeout: 30
RTP Hold Timeout: 300
MWI NOTIFY mime type: application/simple-message-summary
DNS SRV lookup: No
Pedantic SIP support: Yes
Reg. min duration 60 secs
Reg. max duration: 3600 secs
Reg. default duration: 120 secs
Sub. min duration 60 secs
Sub. max duration: 3600 secs
Outbound reg. timeout: 20 secs
Outbound reg. attempts: 0
Outbound reg. retry 403:No
Notify ringing state: Yes
Include CID: No
Notify hold state: Yes
SIP Transfer mode: open
Max Call Bitrate: 384 kbps
Auto-Framing: No
Outb. proxy:
Session Timers: Accept
Session Refresher: uas
Session Expires: 1800 secs
Session Min-SE: 90 secs
Timer T1: 500
Timer T1 minimum: 100
Timer B: 32000
No premature media: Yes
Max forwards: 70

Default Settings:

Allowed transports: UDP
Outbound transport: UDP
Context: from-sip-external
Record on feature: automon
Record off feature: automon
Force rport: No
DTMF: rfc2833
Qualify: 0
Keepalive: 0
Use ClientCode: No
Progress inband: No
Language: en
Tone zone:
MOH Interpret: default
MOH Suggest:
Voice Mail Extension: *97
RTCP Multiplexing: No

Please let me know what else would be desired to help with troubleshooting.

5

PBX is behind a cisco asa. Routing is on the asa, and a cisco core switch. PBX has a public address that has a route to the provider address. Please let me know any info that would help in troubleshooting this.

6

RTP timeout is set to 30 seconds. Calls are being dropped at 30 seconds, so RTP is not being passed. How can I get RTP transmissions to go through?

7

When you dial *43 (echo test) from your softphone, does that work correctly (you hear the announcement then your voice is echoed back)? If not, we’ll use that for testing.

If *43 is ok, can you call 18004377950 and hear your number read back? If not, we’ll use that for testing.

At the Asterisk command prompt, type
sip set debug on
if your extension is pjsip, also type
pjsip set logger on
make a test call, paste the Asterisk log for the call (from /var/log/asterisk/full , not the console output) at pastebin.freepbx.org and post the link here.

8

Stewart1, Thank you for replying.

When I dial via softphone *43, I hear the audio and I can hear my echo.

The 1800 number via softphone did not work, and timed out at 30 seconds.

The extensions are chansip, there is no pjsip on this freepbx. So I did chansip set logger on

Please give me a few minutes to find the call log from the log directory, there is a lot of spam in there and I am trying to find the actual logs from the call.

9

Search /var/log/asterisk/full for the first occurrence of 8004377950 and paste from there to the end of the log. A few hundred lines of spam won’t hurt anything.

10

Stewart,

Here is a link to the pastebin output. https://pastebin.freepbx.org/view/708479c2

Please let me know if that is what you are looking for

11

We have switched from chansip to pjsip, and have got calls from extension to extension working, but outbound calls are no good. It looks like we are having troubles on the trunk now

12

Is Zoiper at 10.255.255.93 on the same LAN as the PBX at 10.129.7.201 ? If not, please describe the networking gear between them (routers, VPN, etc.)

The end of the log shows a retransmit of the 200 OK to Zoiper. In the ~30 seconds after the end of what you pasted, are there more retransmits? This is weird, because *43 worked ok and I see nothing wrong with the 200 sent.

In Zoiper, Settings -> Preferences -> Advanced -> Diagnostics, check Enable debug log, make another test call, paste both the FreePBX log and the Zoiper log (separate pastes) and post the link.

13

Zoiper is not on the same LAN. I am hitting this via vpn. I am at home, connected to my work vpn which is hosted on a cisco asa. There is a tunnel between the asa at my job and another asa at the remote site where pbx is hosted. PBX phone lan and management lan are hosted on the asa, the public interface of pbx is hosted on the core cisco switch.

I believe there were some more retransmits after my last log. Here is that output. https://pastebin.freepbx.org/view/8f6981d4

I will post the other two outputs in a couple minutes.

14

Here is the log from pbx https://pastebin.freepbx.org/view/d04b0b97

Here is the zoiper log https://pastebin.freepbx.org/view/1204e236

15

The continuation log correctly shows the 200s being properly ACKed. There was just one retransmit, presumably caused by the VPN delay.

Do I understand correctly that the PBX has two NICs, one at 10.129.7.201 with ASA gateway and one with 203.54.133.114 on the switch? If not, please provide details. Also, please post the output of
ip route
(given at a root shell prompt).

16

I see a routing problem, but can’t quite understand how it could result in your specific symptoms (though I’m not familiar with Level3 trunk behavior).

The outbound INVITE correctly has Asterisk’s public IP in Via, Contact and the SDP. The 200 from L3 has a media server at 4.55.16.66, which (based on your PM) doesn’t match any of your explicit routes. The default route is via eth2, so L3 sees your RTP coming from a different public address. Depending on firewall settings, possible SIP ALG, etc., L3 might not receive the RTP and/or the RTP they send might not get to Asterisk.

As a test, change the route
4.55.16.97 via x.x.x.x dev eth0
to
4.0.0.0/9 via x.x.x.x dev eth0
and see whether this fixes the problem or at least improves things.

If it works, we need to determine what the right route should be. Possibly, some destinations may use media servers of another carrier, outside of 4.0.0.0/9. The conservative approach would be to have the default via eth0, but then we have to look carefully at the other routes (and it may run afoul of a security policy).

If it doesn’t help at all, the next step is to capture traffic with tcpdump and see where RTP is going to and coming from.

17

Stewart,
Once again, thank you for your help this far. I took the day off yesterday on this, I apologize I was not able to get back sooner. I have decided to start completely from scratch with a fresh vm and go from there. I am running into one issue now. Calls from extension to extension are working fine, as well as calls outbound to my cellphones. Incoming calls come up with the ‘this number is not in service’ message.

This is the call log from the dropped incoming call.

[2020-11-28 02:36:20] VERBOSE[16394] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘96.8.44.26’
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-sip-external:1] NoOp(“PJSIP/anonymous-00000001”, “Received incoming SIP connection from unknown peer to +16022521770”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-sip-external:2] Set(“PJSIP/anonymous-00000001”, “DID=+16022521770”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-sip-external:3] Goto(“PJSIP/anonymous-00000001”, “s,1”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (from-sip-external,s,1)
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-sip-external:1] GotoIf(“PJSIP/anonymous-00000001”, “1?setlanguage:checkanon”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (from-sip-external,s,2)
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-sip-external:2] Set(“PJSIP/anonymous-00000001”, “CHANNEL(language)=en”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-sip-external:3] GotoIf(“PJSIP/anonymous-00000001”, “0?noanonymous”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-sip-external:4] Goto(“PJSIP/anonymous-00000001”, “from-trunk,+16022521770,1”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (from-trunk,+16022521770,1)
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-trunk:1] Set(“PJSIP/anonymous-00000001”, “__FROM_DID=+16022521770”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-trunk:2] NoOp(“PJSIP/anonymous-00000001”, “Received an unknown call with DID set to +16022521770”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [+16022521770@from-trunk:3] Goto(“PJSIP/anonymous-00000001”, “s,a2”) in new stack
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (from-trunk,s,2)
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-trunk:2] Answer(“PJSIP/anonymous-00000001”, “”) in new stack
[2020-11-28 02:36:20] WARNING[17178][C-00000002] chan_sip.c: This function can only be used on SIP channels.
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-trunk:3] Log(“PJSIP/anonymous-00000001”, "WARNING,Friendly Scanner from ") in new stack
[2020-11-28 02:36:20] WARNING[17178][C-00000002] Ext. s: Friendly Scanner from
[2020-11-28 02:36:20] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-trunk:4] Wait(“PJSIP/anonymous-00000001”, “2”) in new stack
[2020-11-28 02:36:22] VERBOSE[17178][C-00000002] pbx.c: Executing [s@from-trunk:5] Playback(“PJSIP/anonymous-00000001”, “ss-noservice”) in new stack
[2020-11-28 02:36:22] VERBOSE[17178][C-00000002] file.c: <PJSIP/anonymous-00000001> Playing ‘ss-noservice.ulaw’ (language ‘en’)
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [h@from-trunk:1] Macro(“PJSIP/anonymous-00000001”, “hangupcall,”) in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/anonymous-00000001”, “1?theend”) in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/anonymous-00000001”, “0?Set(CDR(recordingfile)=)”) in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/anonymous-00000001”, " montior file= ") in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [s@macro-hangupcall:5] GotoIf(“PJSIP/anonymous-00000001”, “1?skipagi”) in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Executing [s@macro-hangupcall:7] Hangup(“PJSIP/anonymous-00000001”, “”) in new stack
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘PJSIP/anonymous-00000001’ in macro ‘hangupcall’
[2020-11-28 02:36:24] VERBOSE[17178][C-00000002] pbx.c: Spawn extension (from-trunk, h, 1) exited non-zero on ‘PJSIP/anonymous-00000001’
[2020-11-28 02:36:32] VERBOSE[16761] asterisk.c: Remote UNIX connection disconnected

18

I may have just solved my issue, I enabled a pjsip trunk and it seems that all calls are going through now.

19

The usual cause of this trouble is that the provider sends calls from multiple IP addresses, some of which don’t match the SIP Server name or IP address.

To fix, find out from what addresses L3 sends calls and list them all in the Match (Permit) field of the trunk settings.

20

Stewart,
Could this possibly be caused by a change in the upstream provider settings. I have everything working now, but after thinking about this, I think that is a possibility.

This machine was working fine to my knowledge, until I rebooted the machine to recover a root password. Upon rebooting the machine, calls were going through, but no audio. I had not changed any other config. We could not get calls going until we enabled a pjsip trunk. I know for a fact that before this, there was only a chansip trunk enabled on the box, and everything was working fine. Is it possible that there was a change in the provider settings?