No audio both ways on internal extension during inbound call [SOLVED]

scott1981 · September 6, 2011, 3:22am

Hi,

I am currently running freepbx distro version on a virtual machine under ubuntu. Ubuntu does have its firewall off. I also have a linksys wrt54gl running as a home router with ports 5060 and range 10000-20000 forwarded to the Asterisk vm. In the same LAN I’ve got a Grandstream bt101. All CID/DID are sent into this phone (ext 200). Every now and then when picking up a call I get no audio either on the ext nor on the remote caller (remote caller calling from pstn). I tried multiple things but nothing seem to work. I have the following settings under “Asterisk SIP Settings”

externip=external ip (static in my case)
Local NEtwork: 192.168.1.0/255.255.255.0

Codecs: alaw, ulaw, gsm

I did a sip set debug peer 200 (the extension having problems) until I could reproduce the error, here is the log.

I really hope someone can help me as I do not know what else to do.

Thank you…

Edit: I noticed that not even the vm recording will be heard when calling from the pstn after the phone rang 7 seconds (as set un the ext configt). Unplugging the phone will result in 100% successful calls into vm.

========================================================================================

localhost*CLI>
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Executing [63859652@from-sip-external:1] NoOp(“SIP/200.112.128.83:5061-0000002c”, “Received incoming SIP connection from unknown peer to 63859652”) in new stack
– Executing [63859652@from-sip-external:2] Set(“SIP/200.112.128.83:5061-0000002c”, “DID=63859652”) in new stack
– Executing [63859652@from-sip-external:3] Goto(“SIP/200.112.128.83:5061-0000002c”, “s,1”) in new stack
– Goto (from-sip-external,s,1)
– Executing [s@from-sip-external:1] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?checklang:noanonymous”) in new stack
– Goto (from-sip-external,s,2)
– Executing [s@from-sip-external:2] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?setlanguage:from-trunk,63859652,1”) in new stack
– Goto (from-trunk,63859652,1)
– Executing [63859652@from-trunk:1] NoOp(“SIP/200.112.128.83:5061-0000002c”, “Catch-All DID Match - Found 63859652 - You probably want a DID for this.”) in new stack
– Executing [63859652@from-trunk:2] Goto(“SIP/200.112.128.83:5061-0000002c”, “ext-did,s,1”) in new stack
– Goto (ext-did,s,1)
– Executing [s@ext-did:1] Set(“SIP/200.112.128.83:5061-0000002c”, “__FROM_DID=s”) in new stack
– Executing [s@ext-did:2] Gosub(“SIP/200.112.128.83:5061-0000002c”, “app-blacklist-check,s,1”) in new stack
– Executing [s@app-blacklist-check:1] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?blacklisted”) in new stack
– Executing [s@app-blacklist-check:2] Set(“SIP/200.112.128.83:5061-0000002c”, “CALLED_BLACKLIST=1”) in new stack
– Executing [s@app-blacklist-check:3] Return(“SIP/200.112.128.83:5061-0000002c”, “”) in new stack
– Executing [s@ext-did:3] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0 ?Set(CALLERID(name)=48057350)”) in new stack
– Executing [s@ext-did:4] Set(“SIP/200.112.128.83:5061-0000002c”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
– Executing [s@ext-did:5] Set(“SIP/200.112.128.83:5061-0000002c”, “CALLERPRES()=allowed_not_screened”) in new stack
– Executing [s@ext-did:6] Goto(“SIP/200.112.128.83:5061-0000002c”, “from-did-direct,200,1”) in new stack
– Goto (from-did-direct,200,1)
– Executing [200@from-did-direct:1] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “1?Set(__RINGTIMER=7)”) in new stack
– Executing [200@from-did-direct:2] Macro(“SIP/200.112.128.83:5061-0000002c”, “exten-vm,200,200,0,0,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“SIP/200.112.128.83:5061-0000002c”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/200.112.128.83:5061-0000002c”, “AMPUSER=48057350”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “1?Set(REALCALLERIDNUM=48057350)”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/200.112.128.83:5061-0000002c”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/200.112.128.83:5061-0000002c”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:14] Set(“SIP/200.112.128.83:5061-0000002c”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“SIP/200.112.128.83:5061-0000002c”, “CALLERID(number)=48057350”) in new stack
– Executing [s@macro-user-callerid:27] Set(“SIP/200.112.128.83:5061-0000002c”, “CALLERID(name)=48057350”) in new stack
– Executing [s@macro-user-callerid:28] Set(“SIP/200.112.128.83:5061-0000002c”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“SIP/200.112.128.83:5061-0000002c”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“SIP/200.112.128.83:5061-0000002c”, “__EXTTOCALL=200”) in new stack
– Executing [s@macro-exten-vm:4] Set(“SIP/200.112.128.83:5061-0000002c”, “__PICKUPMARK=200”) in new stack
– Executing [s@macro-exten-vm:5] Set(“SIP/200.112.128.83:5061-0000002c”, “RT=7”) in new stack
– Executing [s@macro-exten-vm:6] Macro(“SIP/200.112.128.83:5061-0000002c”, “record-enable,200,IN”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?check”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?MacroExit()”) in new stack
– Executing [s@macro-record-enable:5] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?Group:OUT”) in new stack
– Goto (macro-record-enable,s,14)
– Executing [s@macro-record-enable:14] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?IN”) in new stack
– Goto (macro-record-enable,s,18)
– Executing [s@macro-record-enable:18] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “1?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:7] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?macrodial”) in new stack
– Goto (macro-exten-vm,s,13)
– Executing [s@macro-exten-vm:13] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “0?clrheader,1”) in new stack
– Executing [s@macro-exten-vm:14] Macro(“SIP/200.112.128.83:5061-0000002c”, “dial-one,7,tr,200”) in new stack
– Executing [s@macro-dial-one:1] Set(“SIP/200.112.128.83:5061-0000002c”, “DEXTEN=200”) in new stack
– Executing [s@macro-dial-one:2] Set(“SIP/200.112.128.83:5061-0000002c”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “0?screen,1”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “0?cf,1”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“SIP/200.112.128.83:5061-0000002c”, “EXTHASCW=ENABLED”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,23)
– Executing [s@macro-dial-one:23] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?next3:continue”) in new stack
– Goto (macro-dial-one,s,24)
– Executing [s@macro-dial-one:24] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
– Executing [s@macro-dial-one:25] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:26] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “1?dstring,1:dlocal,1”) in new stack
– Executing [dstring@macro-dial-one:1] Set(“SIP/200.112.128.83:5061-0000002c”, “DSTRING=”) in new stack
– Executing [dstring@macro-dial-one:2] Set(“SIP/200.112.128.83:5061-0000002c”, “DEVICES=200”) in new stack
– Executing [dstring@macro-dial-one:3] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:4] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Set(DEVICES=00)”) in new stack
– Executing [dstring@macro-dial-one:5] Set(“SIP/200.112.128.83:5061-0000002c”, “LOOPCNT=1”) in new stack
– Executing [dstring@macro-dial-one:6] Set(“SIP/200.112.128.83:5061-0000002c”, “ITER=1”) in new stack
– Executing [dstring@macro-dial-one:7] Set(“SIP/200.112.128.83:5061-0000002c”, “THISDIAL=SIP/200”) in new stack
– Executing [dstring@macro-dial-one:8] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “1?zap2dahdi,1”) in new stack
– Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Return()”) in new stack
– Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/200.112.128.83:5061-0000002c”, “NEWDIAL=”) in new stack
– Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/200.112.128.83:5061-0000002c”, “LOOPCNT2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/200.112.128.83:5061-0000002c”, “ITER2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/200.112.128.83:5061-0000002c”, “THISPART2=SIP/200”) in new stack
– Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Set(THISPART2=DAHDI/200)”) in new stack
– Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/200.112.128.83:5061-0000002c”, “NEWDIAL=SIP/200&”) in new stack
– Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/200.112.128.83:5061-0000002c”, “ITER2=2”) in new stack
– Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?begin2”) in new stack
– Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/200.112.128.83:5061-0000002c”, “THISDIAL=SIP/200”) in new stack
– Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/200.112.128.83:5061-0000002c”, “”) in new stack
– Executing [dstring@macro-dial-one:9] Set(“SIP/200.112.128.83:5061-0000002c”, “DSTRING=SIP/200&”) in new stack
– Executing [dstring@macro-dial-one:10] Set(“SIP/200.112.128.83:5061-0000002c”, “ITER=2”) in new stack
– Executing [dstring@macro-dial-one:11] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?begin”) in new stack
– Executing [dstring@macro-dial-one:12] Set(“SIP/200.112.128.83:5061-0000002c”, “DSTRING=SIP/200”) in new stack
– Executing [dstring@macro-dial-one:13] Return(“SIP/200.112.128.83:5061-0000002c”, “”) in new stack
– Executing [s@macro-dial-one:27] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:28] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?skiptrace”) in new stack
– Goto (macro-dial-one,s,30)
– Executing [s@macro-dial-one:30] Set(“SIP/200.112.128.83:5061-0000002c”, “D_OPTIONS=tr”) in new stack
– Executing [s@macro-dial-one:31] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?SIPAddHeader(Alert-Info: )”) in new stack
– Executing [s@macro-dial-one:32] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?SIPAddHeader()”) in new stack
– Executing [s@macro-dial-one:33] ExecIf(“SIP/200.112.128.83:5061-0000002c”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [s@macro-dial-one:34] GosubIf(“SIP/200.112.128.83:5061-0000002c”, “0?qwait,1”) in new stack
– Executing [s@macro-dial-one:35] Set(“SIP/200.112.128.83:5061-0000002c”, “__CWIGNORE=”) in new stack
– Executing [s@macro-dial-one:36] Set(“SIP/200.112.128.83:5061-0000002c”, “__KEEPCID=TRUE”) in new stack
– Executing [s@macro-dial-one:37] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?usegoto,1”) in new stack
– Executing [s@macro-dial-one:38] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “0?godial”) in new stack
– Executing [s@macro-dial-one:39] Set(“SIP/200.112.128.83:5061-0000002c”, “CONNECTEDLINE(name,i)=Nicolas”) in new stack
– Executing [s@macro-dial-one:40] Set(“SIP/200.112.128.83:5061-0000002c”, “CONNECTEDLINE(num)=200”) in new stack
– Executing [s@macro-dial-one:41] Set(“SIP/200.112.128.83:5061-0000002c”, “D_OPTIONS=trI”) in new stack
– Executing [s@macro-dial-one:42] Dial(“SIP/200.112.128.83:5061-0000002c”, “SIP/200,7,trI”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Audio is at 5060
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x8 (alaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 192.168.1.105:5506:
INVITE sip:[email protected]:5506 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK73f2a03f;rport
Max-Forwards: 70
From: “48057350” sip:[email protected];tag=as2b37ac48
To: sip:[email protected]:5506
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Tue, 06 Sep 2011 00:04:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 283

v=0
o=root 810097006 810097006 IN IP4 192.168.1.117
s=Asterisk PBX 1.8.6.0
c=IN IP4 192.168.1.117
t=0 0
m=audio 11188 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

-- Called SIP/200
-- Connected line update to SIP/200.112.128.83:5061-0000002c prevented.

<— SIP read from UDP:192.168.1.105:5506 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK73f2a03f;rport
From: “48057350” sip:[email protected];tag=as2b37ac48
To: sip:[email protected]:5506
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: Grandstream BT120 1.1.0.26
Content-Length: 0

<------------->
— (8 headers 0 lines) —

<— SIP read from UDP:192.168.1.105:5506 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK73f2a03f;rport
From: “48057350” sip:[email protected];tag=as2b37ac48
To: sip:[email protected]:5506;tag=370206f113f141e1
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: Grandstream BT120 1.1.0.26
Content-Length: 0

<------------->
— (8 headers 0 lines) —
– SIP/200-0000002d is ringing

<— SIP read from UDP:192.168.1.105:5506 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK73f2a03f;rport
From: “48057350” sip:[email protected];tag=as2b37ac48
To: sip:[email protected]:5506;tag=370206f113f141e1
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: Grandstream BT120 1.1.0.26
Contact: sip:[email protected]:5506
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE
Content-Type: application/sdp
Supported: replaces
Content-Length: 213

v=0
o=200 8000 8000 IN IP4 192.168.1.105
s=SIP Call
c=IN IP4 192.168.1.105
t=0 0
m=audio 50240 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
<------------->
— (12 headers 11 lines) —
Found RTP audio format 0
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.1.105:50240
list_route: hop: sip:[email protected]:5506
set_destination: Parsing sip:[email protected]:5506 for address/port to send to
set_destination: set destination to 192.168.1.105:5506
Transmitting (NAT) to 192.168.1.105:5506:
ACK sip:[email protected]:5506 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK21955a50;rport
Max-Forwards: 70
From: “48057350” sip:[email protected];tag=as2b37ac48
To: sip:[email protected]:5506;tag=370206f113f141e1
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0

-- Connected line update to SIP/200.112.128.83:5061-0000002c prevented.
-- SIP/200-0000002d answered SIP/200.112.128.83:5061-0000002c

<— SIP read from UDP:192.168.1.105:5506 —>
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.105:5506;branch=z9hG4bK4bfe18345b89f879
From: sip:[email protected]:5506;tag=370206f113f141e1
To: “48057350” sip:[email protected];tag=as2b37ac48
Supported: replaces
Call-ID: [email protected]:5060
CSeq: 23821 BYE
User-Agent: Grandstream BT120 1.1.0.26
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Sending to 192.168.1.105:5506 (NAT)
Scheduling destruction of SIP dialog ‘[email protected]:5060’ in 6400 ms (Method: BYE)

<— Transmitting (NAT) to 192.168.1.105:5506 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.105:5506;branch=z9hG4bK4bfe18345b89f879;received=192.168.1.105;rport=5506
From: sip:[email protected]:5506;tag=370206f113f141e1
To: “48057350” sip:[email protected];tag=as2b37ac48
Call-ID: [email protected]:5060
CSeq: 23821 BYE
Server: FPBX-2.9.0(1.8.6.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
– Executing [h@macro-dial-one:1] Macro(“SIP/200.112.128.83:5061-0000002c”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/200.112.128.83:5061-0000002c”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [s@macro-hangupcall:3] Hangup(“SIP/200.112.128.83:5061-0000002c”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/200.112.128.83:5061-0000002c’ in macro ‘hangupcall’
== Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/200.112.128.83:5061-0000002c’
== Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/200.112.128.83:5061-0000002c’ in macro ‘dial-one’
== Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/200.112.128.83:5061-0000002c’ in macro ‘exten-vm’
== Spawn extension (from-did-direct, 200, 2) exited non-zero on 'SIP/200.112.128.83:5061-0000002c’
Reliably Transmitting (NAT) to 192.168.1.105:5506:
OPTIONS sip:[email protected]:5506 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK39881081;rport
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as6b098f39
To: sip:[email protected]:5506
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Tue, 06 Sep 2011 00:04:59 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<— SIP read from UDP:192.168.1.105:5506 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.117:5060;branch=z9hG4bK39881081;rport
From: “Unknown” sip:[email protected];tag=as6b098f39
To: sip:[email protected]:5506;tag=a68c1de1de6c7c5c
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: Grandstream BT120 1.1.0.26
Contact: sip:[email protected]:5506
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE
Supported: replaces
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Really destroying SIP dialog ‘[email protected]:5060’ Method: OPTIONS

SkykingOH · September 6, 2011, 4:44am

It looks like the RTP is not being properly constrained.

check /etc/asterisk/rtp/.conf

turn off sip and verbosity then run a ‘rtp debug’ while a call is up.

scott1981 · September 6, 2011, 2:57pm

Thanks for your reply SkykingOH…

Do you need me to post an RTP debug log from a working or non working (silenced) call?
Also what type of problem and where do you see it in the log that I posted?

Thanks!

Edit. Let me say again that this is running on a VM (virtual box). Ubuntu is the main OS and freepbx distro is running virtualized inside of it. I am not sure this might be the reason for random silent inbound calls from pstn.

scott1981 · September 6, 2011, 2:55pm

Ok here I managed to get a good rtp log for a silenced call:

Any evident problems?

[2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:27] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to [2011-09-06 08:50:28] VERBOSE[5356] res_rtp_asterisk.c: Sent RTP packet to 200.112.128.83:9 (type 00, seq 039350, ts 000160, len 000160)
200.112.128.83:9 (type 00, seq 039351, ts 000320, len 000160)
200.112.128.83:9 (type 00, seq 039352, ts 000480, len 000160)
200.112.128.83:9 (type 00, seq 039353, ts 000640, len 000160)
200.112.128.83:9 (type 00, seq 039354, ts 000800, len 000160)
200.112.128.83:9 (type 00, seq 039355, ts 000960, len 000160)
200.112.128.83:9 (type 00, seq 039356, ts 001120, len 000160)
200.112.128.83:9 (type 00, seq 039357, ts 001280, len 000160)
200.112.128.83:9 (type 00, seq 039358, ts 001440, len 000160)
200.112.128.83:9 (type 00, seq 039359, ts 001600, len 000160)
200.112.128.83:9 (type 00, seq 039360, ts 001760, len 000160)
200.112.128.83:9 (type 00, seq 039361, ts 001920, len 000160)
200.112.128.83:9 (type 00, seq 039362, ts 002080, len 000160)
200.112.128.83:9 (type 00, seq 039363, ts 002240, len 000160)
200.112.128.83:9 (type 00, seq 039364, ts 002400, len 000160)
200.112.128.83:9 (type 00, seq 039365, ts 002560, len 000160)
200.112.128.83:9 (type 00, seq 039366, ts 002720, len 000160)
200.112.128.83:9 (type 00, seq 039367, ts 002880, len 000160)
200.112.128.83:9 (type 00, seq 039368, ts 003040, len 000160)
200.112.128.83:9 (type 00, seq 039369, ts 003200, len 000160)
200.112.128.83:9 (type 00, seq 039370, ts 003360, len 000160)
200.112.128.83:9 (type 00, seq 039371, ts 003520, len 000160)
200.112.128.83:9 (type 00, seq 039372, ts 003680, len 000160)
200.112.128.83:9 (type 00, seq 039373, ts 003840, len 000160)
200.112.128.83:9 (type 00, seq 039374, ts 004000, len 000160)
200.112.128.83:9 (type 00, seq 039375, ts 004160, len 000160)
200.112.128.83:9 (type 00, seq 039376, ts 004320, len 000160)
200.112.128.83:9 (type 00, seq 039377, ts 004480, len 000160)
200.112.128.83:9 (type 00, seq 039378, ts 004640, len 000160)
200.112.128.83:9 (type 00, seq 039379, ts 004800, len 000160)
200.112.128.83:9 (type 00, seq 039380, ts 004960, len 000160)
200.112.128.83:9 (type 00, seq 039381, ts 005120, len 000160)
200.112.128.83:9 (type 00, seq 039382, ts 005280, len 000160)
200.112.128.83:9 (type 00, seq 039383, ts 005440, len 000160)
200.112.128.83:9 (type 00, seq 039384, ts 005600, len 000160)
200.112.128.83:9 (type 00, seq 039385, ts 005760, len 000160)
200.112.128.83:9 (type 00, seq 039386, ts 005920, len 000160)
200.112.128.83:9 (type 00, seq 039387, ts 006080, len 000160)
200.112.128.83:9 (type 00, seq 039388, ts 006240, len 000160)
200.112.128.83:9 (type 00, seq 039389, ts 006400, len 000160)
200.112.128.83:9 (type 00, seq 039390, ts 006560, len 000160)
200.112.128.83:9 (type 00, seq 039391, ts 006720, len 000160)
200.112.128.83:9 (type 00, seq 039392, ts 006880, len 000160)
200.112.128.83:9 (type 00, seq 039393, ts 007040, len 000160)
200.112.128.83:9 (type 00, seq 039394, ts 007200, len 000160)
200.112.128.83:9 (type 00, seq 039395, ts 007360, len 000160)
200.112.128.83:9 (type 00, seq 039396, ts 007520, len 000160)
200.112.128.83:9 (type 00, seq 039397, ts 007680, len 000160)
200.112.128.83:9 (type 00, seq 039398, ts 007840, len 000160)
200.112.128.83:9 (type 00, seq 039399, ts 008000, len 000160)
200.112.128.83:9 (type 00, seq 039400, ts 008160, len 000160)
200.112.128.83:9 (type 00, seq 039401, ts 008320, len 000160)
200.112.128.83:9 (type 00, seq 039402, ts 008480, len 000160)
200.112.128.83:9 (type 00, seq 039403, ts 008640, len 000160)
200.112.128.83:9 (type 00, seq 039404, ts 008800, len 000160)
200.112.128.83:9 (type 00, seq 039405, ts 008960, len 000160)
200.112.128.83:9 (type 00, seq 039406, ts 009120, len 000160)
200.112.128.83:9 (type 00, seq 039407, ts 009280, len 000160)
200.112.128.83:9 (type 00, seq 039408, ts 009440, len 000160)
200.112.128.83:9 (type 00, seq 039409, ts 009600, len 000160)

SkykingOH · September 6, 2011, 3:52pm

You indicated that all hosts are on the same network yet the RTP stream is going to a public IP. You have some NAT issues causing your audio problems.

scott1981 · September 6, 2011, 5:50pm

ok, I have rtp ports set on Asterisk in the 10000-20000 udp range and the firewall is open on the same range for Asterisk private IP (forwarded).
The strange thing is that the problem happens every now and then. In order to provide the log I came up with before I had to test maybe 7 o 8 calls.

Any thoughts on the rtp log?

Thanks.

EDIT: Doing further testing I realised the following:

I make a call to the pstn number, extension is unplugged, so I get vm.
Call right back and get vm.
Wait 30 mins call back and no sound whatsoever
Call right back, audio is back.

scott1981 · September 7, 2011, 1:31pm

Well I think I found a solution to my problem. My network set up is as follows:

—DDWRT Router—VM (FreePBX Distro).

Even though I had opened all relevant ports on the router, there was probably some type of firewall already active in CentOS. I created the same rules on iptables for CentOS and put it in DMZ. Now everything works great. If I remove it from the dmz and behind nat again the problem appears in such a way that in 1 call out of 10 on average will be silent both ways.
I am not sure what is causing this, maybe double nating? In any case running the machine in DMZ with proper CentOS firewall rules seems to do the trick for me.

Thanks.