488 Not Accaptable : Phone Always Busy

CocoBellaDolls · January 29, 2015, 2:34am

I have two extensions setup, each with an associated inbound route but when I try to make a call between them I get a 488 Not Acceptable.

[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [exten@sub-record-check:3] GotoIf("SIP/9818-00000002", "1?caller") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Goto (sub-record-check,exten,10)
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [exten@sub-record-check:10] Set("SIP/9818-00000002", "__REC_POLICY_MODE=dontcare") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [exten@sub-record-check:11] GosubIf("SIP/9818-00000002", "0?record,1(exten,9808,9818)") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [exten@sub-record-check:12] Return("SIP/9818-00000002", "") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-exten-vm:7] Macro("SIP/9818-00000002", "dial-one,,tr,9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/9818-00000002", "DEXTEN=9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/9818-00000002", "DIALSTATUS_CW=") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("SIP/9818-00000002", "0?screen,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("SIP/9818-00000002", "0?cf,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("SIP/9818-00000002", "1?skip1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Goto (macro-dial-one,s,8)
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("SIP/9818-00000002", "0?nodial") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("SIP/9818-00000002", "0?continue") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:10] Set("SIP/9818-00000002", "EXTHASCW=ENABLED") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/9818-00000002", "0?next1:cwinusebusy") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Goto (macro-dial-one,s,23)
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:23] GotoIf("SIP/9818-00000002", "1?next3:continue") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Goto (macro-dial-one,s,24)
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:24] ExecIf("SIP/9818-00000002", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/9818-00000002", "0?nodial") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("SIP/9818-00000002", "1?dstring,1():dlocal,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/9818-00000002", "DSTRING=") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/9818-00000002", "DEVICES=9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/9818-00000002", "0?Return()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/9818-00000002", "0?Set(DEVICES=808)") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/9818-00000002", "LOOPCNT=1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/9818-00000002", "ITER=1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/9818-00000002", "THISDIAL=SIP/9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/9818-00000002", "1?zap2dahdi,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/9818-00000002", "0?Return()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/9818-00000002", "NEWDIAL=") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/9818-00000002", "LOOPCNT2=1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/9818-00000002", "ITER2=1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/9818-00000002", "THISPART2=SIP/9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/9818-00000002", "0?Set(THISPART2=DAHDI/9808)") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/9818-00000002", "NEWDIAL=SIP/9808&") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/9818-00000002", "ITER2=2") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/9818-00000002", "0?begin2") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/9818-00000002", "THISDIAL=SIP/9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/9818-00000002", "") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("SIP/9818-00000002", "DSTRING=SIP/9808&") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("SIP/9818-00000002", "ITER=2") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/9818-00000002", "0?begin") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("SIP/9818-00000002", "DSTRING=SIP/9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("SIP/9818-00000002", "") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/9818-00000002", "0?nodial") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/9818-00000002", "0?skiptrace") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("SIP/9818-00000002", "1?ctset,1():ctclear,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/9818-00000002", "DB(CALLTRACE/9808)=19045352288") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/9818-00000002", "") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/9818-00000002", "D_OPTIONS=tr") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("SIP/9818-00000002", "0?SIPAddHeader(Alert-Info: )") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/9818-00000002", "0?SIPAddHeader()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("SIP/9818-00000002", "0?Set(CHANNEL(musicclass)=)") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("SIP/9818-00000002", "0?qwait,1()") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/9818-00000002", "__CWIGNORE=") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:36] Set("SIP/9818-00000002", "__KEEPCID=TRUE") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("SIP/9818-00000002", "0?usegoto,1") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("SIP/9818-00000002", "0?godial") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:39] Set("SIP/9818-00000002", "CONNECTEDLINE(name,i)=Nadia Francis") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:40] Set("SIP/9818-00000002", "CONNECTEDLINE(num)=9808") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:41] Set("SIP/9818-00000002", "D_OPTIONS=trI") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] pbx.c: -- Executing [s@macro-dial-one:42] Dial("SIP/9818-00000002", "SIP/9808,,trI") in new stack
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] app_dial.c: -- Called SIP/9808
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] app_dial.c: -- Connected line update to SIP/9818-00000002 prevented.
[2015-01-29 02:11:22] VERBOSE[3878][C-00000002] chan_sip.c: -- Got SIP response 406 "Not Acceptable" back from 99.7.231.29:58510
[2015-01-29 02:11:22] VERBOSE[4044][C-00000002] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1)

cynjut · January 29, 2015, 3:42pm

is the phone? The 406 Not Acceptable error code means “The resource identified by the request is only capable of generating response entities that have content characteristics but not acceptable according to the Accept header field sent in the request.”

I don’t know about you, but that didn’t really help me either.

OK, so something about the call makes the ..*.99 sad. I’d start with obvious stuff like limits on IPs, or other tightened security settings.

Can you log into the asterisk app (asterisk -vr) and initiate a call to that extension from there?

I noticed in the log that you are using call options “D_OPTIONS=trI”. I recognize t and r, but what is “I”? A red herring, perhaps, but there’s something about the call from the server to the phone that the phone clearly doesn’t like. You implied that inbound calls from outside the system seem to work, but not from internal phones; maybe your calling options on the calling extension cause a problem?

CocoBellaDolls · January 30, 2015, 12:34am

How do I initiate a call from CLI?
Dial(SIP/818, 20)
does not work.

dicko · January 30, 2015, 12:39am

To “originate” a call from asterisk cli read:-

help originate

CocoBellaDolls · January 30, 2015, 1:19am

originate SIP/818 application Playback hello-world

The phone rings but it doesn’t say anything

CocoBellaDolls · January 30, 2015, 1:24am

[2015-01-30 01:18:26] DEBUG[19482] app_queue.c: Device ‘SIP/818’ changed to state ‘6’ (Ringing) but we don’t care because they’re not a member of any queue.
[2015-01-30 01:18:29] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:99.7.231.29:63514 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.31.60.169:5060;received=54.174.104.183;branch=z9hG4bK6665f848
Call-ID: [email protected]:5060
From: “Anonymous” sip:[email protected];tag=as3c63afd1
To: sip:[email protected]:51158;tag=bJRfRuICsc0MW0Mr4TMRNp7krxygCoLe
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS, MESSAGE
Contact: “Rufus Peoples” sip:[email protected]:63514
Supported: replaces, 100rel, timer, norefersub, eventlist
Content-Type: application/sdp
Content-Length: 167

v=0
o=- 3631569506 3631569507 IN IP4 99.7.231.29
s=v
b=AS:84
t=0 0
m=audio 50936 RTP/AVP 8
c=IN IP4 99.7.231.29
b=TIAS:64000
a=sendrecv
a=rtpmap:8 PCMA/8000
<------------->
[2015-01-30 01:18:29] VERBOSE[19451] chan_sip.c: — (11 headers 10 lines) —
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] logger.c: CALL_ID [C-0000004f] bound to thread.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Acked pending invite 102
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED OR FAILED.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing session-level SDP o=- 3631569506 3631569507 IN IP4 99.7.231.29… OK.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing session-level SDP s=v… UNSUPPORTED OR FAILED.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing session-level SDP b=AS:84… UNSUPPORTED OR FAILED.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED OR FAILED.
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Found RTP audio format 8
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] rtp_engine.c: Setting payload 8 based on m type on 0x7f8d04935460
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 99.7.231.29… OK.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000… UNSUPPORTED OR FAILED.
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing media-level (audio) SDP a=sendrecv… OK.
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Found audio description format PCMA for ID 8
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000… OK.
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Capabilities: us - (ulaw|alaw|g722), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw)
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing)
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7f8d38029828’
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Peer audio RTP is at port 99.7.231.29:50936
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] rtp_engine.c: Copying payload 8 from 0x7f8d04935460 to 0x7f8d380299f0
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance ‘0x7f8d38029828’
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: We’re settling with these formats: (alaw)
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Setting native formats after processing SDP. peer joint formats (alaw), old nativeformats (g722)
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] channel.c: Set channel SIP/818-00000005 to read format g722
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] channel.c: Set channel SIP/818-00000005 to write format g722
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Updating call counter for outgoing call
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: build_route: Contact hop: “Rufus Peoples” sip:[email protected]:63514
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: list_route: hop: sip:[email protected]:63514
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Strict routing enforced for session [email protected]:5060
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: set_destination: Parsing sip:[email protected]:63514 for address/port to send to
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: set_destination: set destination to 99.7.231.29:63514
[2015-01-30 01:18:29] VERBOSE[19451][C-0000004f] chan_sip.c: Transmitting (no NAT) to 99.7.231.29:63514:
ACK sip:[email protected]:63514 SIP/2.0
Via: SIP/2.0/UDP 172.31.60.169:5060;branch=z9hG4bK42e29791
Max-Forwards: 70
From: “Anonymous” sip:[email protected];tag=as3c63afd1
To: sip:[email protected]:63514;tag=bJRfRuICsc0MW0Mr4TMRNp7krxygCoLe
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: FPBX-2.11.0(11.2.1)
Content-Length: 0

[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] chan_sip.c: Trying to put ‘ACK sip:818’ onto UDP socket destined for 99.7.231.29:63514
[2015-01-30 01:18:29] DEBUG[19451][C-0000004f] logger.c: Call_ID [C-0000004f] being removed from thread.
[2015-01-30 01:18:29] DEBUG[453][C-0000004f] logger.c: Call_ID [C-0000004f] being removed from thread.
[2015-01-30 01:18:29] DEBUG[19439] chan_sip.c: Checking device state for peer 818
[2015-01-30 01:18:29] DEBUG[19439] devicestate.c: Changing state for SIP/818 - state 2 (In use)
[2015-01-30 01:18:29] DEBUG[19439] devicestate.c: device ‘SIP/818’ state ‘2’
[2015-01-30 01:18:29] DEBUG[19439] chan_sip.c: Checking device state for peer 818
[2015-01-30 01:18:29] DEBUG[19439] devicestate.c: Changing state for SIP/818 - state 2 (In use)
[2015-01-30 01:18:29] DEBUG[19439] devicestate.c: device ‘SIP/818’ state ‘2’
[2015-01-30 01:18:29] DEBUG[19525] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/818-00000005
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 818
CallerIDName: Rufus Peoples
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1422580706.5

[2015-01-30 01:18:29] DEBUG[19433] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2015-01-30 01:18:29] DEBUG[19482] app_queue.c: Device ‘SIP/818’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2015-01-30 01:18:29] DEBUG[19482] app_queue.c: Device ‘SIP/818’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] logger.c: CALL_ID [C-0000004f] bound to thread.
[2015-01-30 01:18:29] VERBOSE[458][C-0000004f] pbx.c: – Launching Playback(hello-world) on SIP/818-00000005
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] channel.c: Set channel SIP/818-00000005 to write format gsm
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance ‘0x7f8d38029828’
[2015-01-30 01:18:29] DEBUG[458][C-0000004f] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-01-30 01:18:29] VERBOSE[458][C-0000004f] file.c: – <SIP/818-00000005> Playing ‘hello-world.gsm’ (language ‘en’)
[2015-01-30 01:18:30] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:66.87.99.91:24818 —>

<------------->
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] channel.c: Set channel SIP/818-00000005 to write format g722
[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[19433] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] channel.c: Hanging up channel ‘SIP/818-00000005’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: Hangup call SIP/818-00000005, SIP callid [email protected]:5060
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: update_call_counter(818) - decrement call limit counter on hangup
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: Updating call counter for outgoing call
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: Call to peer ‘818’ removed from call limit 2147483647
[2015-01-30 01:18:31] DEBUG[19439] chan_sip.c: Checking device state for peer 818
[2015-01-30 01:18:31] DEBUG[19439] devicestate.c: Changing state for SIP/818 - state 1 (Not in use)
[2015-01-30 01:18:31] DEBUG[19439] devicestate.c: device ‘SIP/818’ state ‘1’
[2015-01-30 01:18:31] DEBUG[19482] app_queue.c: Device ‘SIP/818’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7f8d38029828’
[2015-01-30 01:18:31] VERBOSE[458][C-0000004f] chan_sip.c: Scheduling destruction of SIP dialog ‘[email protected]:5060’ in 32000 ms (Method: INVITE)
[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: RTPAUDIOQOS
Value: ssrc=1097974198;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=76;rlp=0;rtt=0.000000
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: RTPAUDIOQOSJITTER
Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: RTPAUDIOQOSLOSS
Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/818-00000005
Variable: RTPAUDIOQOS
Value: ssrc=1097974198;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=76;rlp=0;rtt=0.000000
Uniqueid: 1422580706.5

[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: Strict routing enforced for session [email protected]:5060
[2015-01-30 01:18:31] VERBOSE[458][C-0000004f] chan_sip.c: set_destination: Parsing sip:[email protected]:63514 for address/port to send to
[2015-01-30 01:18:31] VERBOSE[458][C-0000004f] chan_sip.c: set_destination: set destination to 99.7.231.29:63514
[2015-01-30 01:18:31] VERBOSE[458][C-0000004f] chan_sip.c: Reliably Transmitting (no NAT) to 99.7.231.29:63514:
BYE sip:[email protected]:63514 SIP/2.0
Via: SIP/2.0/UDP 172.31.60.169:5060;branch=z9hG4bK0104ee3b
Max-Forwards: 70
From: “Anonymous” sip:[email protected];tag=as3c63afd1
To: sip:[email protected]:63514;tag=bJRfRuICsc0MW0Mr4TMRNp7krxygCoLe
Call-ID: [email protected]:5060
CSeq: 103 BYE
User-Agent: FPBX-2.11.0(11.2.1)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

[2015-01-30 01:18:31] DEBUG[458][C-0000004f] chan_sip.c: Trying to put ‘BYE sip:818’ onto UDP socket destined for 99.7.231.29:63514
[2015-01-30 01:18:31] DEBUG[19525] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: SIP/818-00000005
Uniqueid: 1422580706.5
CallerIDNum: 818
CallerIDName: Rufus Peoples
ConnectedLineNum:
ConnectedLineName:
AccountCode:
Cause: 16
Cause-txt: Normal Clearing

[2015-01-30 01:18:31] DEBUG[458][C-0000004f] cdr_mysql.c: Inserting a CDR record.
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES (‘2015-01-30 01:18:26’,’“Rufus Peoples” <818>’,‘818’,‘s’,‘from-internal’,‘SIP/818-00000005’,‘Playback’,‘hello-world’,‘5’,‘2’,‘ANSWERED’,‘3’,‘1422580706.5’)
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] cdr_radius.c: Unable to create RADIUS record. CDR not recorded!
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘2015-01-30 01:18:26’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘“Rufus Peoples” <818>’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘from-internal’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘SIP/818-00000005’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘(null)’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘Playback’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘hello-world’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘5’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘2’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘ANSWERED’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘DOCUMENTATION’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘(null)’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘1422580706.5’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘(null)’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] pbx.c: Function result is ‘(null)’
[2015-01-30 01:18:31] DEBUG[458][C-0000004f] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES (‘2015-01-30 01:18:26’,’“Rufus Peoples” <818>’,‘from-internal’,‘SIP/818-00000005’,’’,‘Playback’,‘hello-world’,‘5’,‘2’,‘ANSWERED’,‘DOCUMENTATION’,’’,‘1422580706.5’,’’,’’)
[2015-01-30 01:18:31] DEBUG[19433] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2015-01-30 01:18:31] DEBUG[19433] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2015-01-30 01:18:31] DEBUG[19439] chan_sip.c: Checking device state for peer 818
[2015-01-30 01:18:31] DEBUG[19439] devicestate.c: Changing state for SIP/818 - state 1 (Not in use)
[2015-01-30 01:18:31] DEBUG[19439] devicestate.c: device ‘SIP/818’ state ‘1’
[2015-01-30 01:18:31] DEBUG[19482] app_queue.c: Device ‘SIP/818’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2015-01-30 01:18:31] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:99.7.231.29:63514 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.31.60.169:5060;received=54.174.104.183;branch=z9hG4bK0104ee3b
Call-ID: [email protected]:5060
From: “Anonymous” sip:[email protected];tag=as3c63afd1
To: sip:[email protected]:63514;tag=bJRfRuICsc0MW0Mr4TMRNp7krxygCoLe
CSeq: 103 BYE
Content-Length: 0

<------------->
[2015-01-30 01:18:31] VERBOSE[19451] chan_sip.c: — (7 headers 0 lines) —
[2015-01-30 01:18:31] DEBUG[19451][C-0000004f] logger.c: CALL_ID [C-0000004f] bound to thread.
[2015-01-30 01:18:31] DEBUG[19451][C-0000004f] chan_sip.c: Stopping retransmission on ‘[email protected]:5060’ of Request 103: Match Found
[2015-01-30 01:18:31] DEBUG[19451][C-0000004f] logger.c: Call_ID [C-0000004f] being removed from thread.
[2015-01-30 01:18:31] DEBUG[19451] chan_sip.c: Destroying SIP dialog [email protected]:5060
[2015-01-30 01:18:31] VERBOSE[19451] chan_sip.c: Really destroying SIP dialog ‘[email protected]:5060’ Method: INVITE
[2015-01-30 01:18:31] DEBUG[19451] rtp_engine.c: Destroyed RTP instance ‘0x7f8d38029828’
[2015-01-30 01:18:32] DEBUG[19451] chan_sip.c: Auto destroying SIP dialog ‘[email protected]:5060’
[2015-01-30 01:18:32] DEBUG[19451] chan_sip.c: Destroying SIP dialog [email protected]:5060
[2015-01-30 01:18:32] VERBOSE[19451] chan_sip.c: Really destroying SIP dialog ‘[email protected]:5060’ Method: INVITE
[2015-01-30 01:18:32] DEBUG[19451] rtp_engine.c: Destroyed RTP instance ‘0x7f8d38011028’
[2015-01-30 01:18:40] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:99.7.231.29:63514 —>

<------------->
[2015-01-30 01:18:52] DEBUG[19467] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2015-01-30 01:19:10] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:66.87.99.91:24818 —>

<------------->
[2015-01-30 01:19:10] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:99.7.231.29:63514 —>

<------------->
[2015-01-30 01:19:37] DEBUG[465] manager.c: Running action ‘Login’
[2015-01-30 01:19:40] VERBOSE[19451] chan_sip.c:
<— SIP read from UDP:99.7.231.29:63514 —>

dicko · January 30, 2015, 1:28am

If you can’t hear the call then traffic on 99.7.231.29:50936 and 50936 is not getting through your routers correctly.

CocoBellaDolls · January 30, 2015, 1:30am

This is not my IP, where would that come from?

dicko · January 30, 2015, 1:36am

AT&T don’t know who particularly it is a /9 network.

whois 99.7.231.29

.
.
.

whois NetRange: 99.0.0.0 - 99.127.255.255
CIDR: 99.0.0.0/9
NetName: SBCIS-SBIS
NetHandle: NET-99-0-0-0-1
Parent: NET99 (NET-99-0-0-0-0)
NetType: Direct Allocation
OriginAS: AS7132
Organization: AT&T Internet Services (SIS-80)
RegDate: 2008-02-25
Updated: 2012-03-02
Comment: Contact [email protected] for technical supportissues
Comment: For policy abuse Issues contact [email protected]
Comment: For Law Enforcement Requests for Information Fax or E-mail
Comment: 130 E TRAVIS ST. Rm. 3P01, San Antonio, TX
Comment: 78205-1601
Comment: Fax Number: (210)370-1073
Ref: http://whois.arin.net/rest/net/NET-99-0-0-0-1
.
.
.

CocoBellaDolls · January 30, 2015, 2:15am

I think I see my problem. I was assuming that if I created the extensions with corresponding inbound routes then I could make internal calls. But after looking closer at the dialplans it seems as if I need to create a custom dial plan. The problem is I tried to create it in

/etc/asterisk/extensions_custom.conf

as this:

[internal]
exten => 8XX,1,Log(NOTICE, Incoming call from ${CALLERID(all)})
exten => 8XX,n,Dial(SIP/${EXTEN},20)
exten => 8XX,n,Hangup()
; End of the "internal" context

I then uncommented the line
include extensions_custom.conf
in

/etc/asterisk/extensions_custom.conf

Then I restarted Asterisk and reloaded the dialplan but it doesn’t show.

> dialplan reload
Dialplan reloaded.
> dialplan show internal
There is no existence of 'internal' context
Command 'dialplan show internal' failed.

The comments in the conf files say not to add it directly to extensions.conf and that what ever is in extensions_custom.conf will be picked up automatically but that doesn’t seem to be happening

CocoBellaDolls · January 30, 2015, 3:50am

I figured it out. I can’t uncomment that line. Once I added it back a lot more contexts were loaded.

dicko · January 30, 2015, 4:05am

In asterisk (because phone dials have a # ) , you comment a line with ; , # is for "including, just as it says

CocoBellaDolls · January 30, 2015, 4:35am

I’m still having a problem.
I’m obviously new to this and trying to learn but I can’t seem to get this dialplan thing working. I created this in extension conf:

[knock-knock]
exten => s,1,Log(NOTICE, Incoming Call From ${CALLERID(all)} to ${EXTENa} using ${SIPDOMAIN})
exten => s,n,GotoIf($["${SIPDOMAIN}" = "sip.twilio.com"]?from-internal,${EXTEN},1:from-sip-external,${EXTEN},1)
exten => s,n,Hangup()
; End of the "knock-knock" context

And when I dial my phone from Twilio I get the following error:

[2015-01-30 04:29:40] DEBUG[7367][C-00000000] chan_sip.c: Updating call counter for incoming call
[2015-01-30 04:29:40] VERBOSE[7367][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '[email protected]' in 32000 ms (Method: INVITE)
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] logger.c: Call_ID [C-00000000] being removed from thread.
[2015-01-30 04:29:40] VERBOSE[7367] chan_sip.c: 
<--- SIP read from UDP:107.21.222.153:5060 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 107.21.222.153:5060;branch=z9hG4bKa8df.5235aa01.0
From: "+19045352288" <sip:[email protected]>;tag=92384571_6772d868_dfc6cdd3-b2b6-4b04-ad1c-15c3f0a61188
Call-ID: [email protected]
To: <sip:[email protected]>;tag=as5d6d1d2e
CSeq: 102 ACK
Max-Forwards: 70
User-Agent: Twilio Gateway
Content-Length: 0

<------------->
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 0 [ 44]: ACK sip:[email protected] SIP/2.0
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 107.21.222.153:5060;branch=z9hG4bKa8df.5235aa01.0
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 2 [113]: From: "+19045352288" <sip:[email protected]>;tag=92384571_6772d868_dfc6cdd3-b2b6-4b04-ad1c-15c3f0a61188
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 3 [ 49]: Call-ID: [email protected]
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 4 [ 53]: To: <sip:[email protected]>;tag=as5d6d1d2e
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 7 [ 26]: User-Agent: Twilio Gateway
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Header 8 [ 17]: Content-Length: 0
[2015-01-30 04:29:40] VERBOSE[7367] chan_sip.c: --- (9 headers 0 lines) ---
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: = Looking for Call ID: [email protected] (Checking From) --From tag 92384571_6772d868_dfc6cdd3-b2b6-4b04-ad1c-15c3f0a61188 --To-tag as5d6d1d2e 
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] chan_sip.c: Stopping retransmission on '[email protected]' of Response 102: Match Found
[2015-01-30 04:29:40] DEBUG[7367][C-00000000] logger.c: Call_ID [C-00000000] being removed from thread.
[2015-01-30 04:29:40] DEBUG[7367] chan_sip.c: Destroying SIP dialog [email protected]
[2015-01-30 04:29:40] VERBOSE[7367] chan_sip.c: Really destroying SIP dialog '[email protected]' Method: ACK
[2015-01-30 04:29:40] DEBUG[7367] rtp_engine.c: Destroyed RTP instance '0x1d1b9e8'
[2015-01-30 04:29:40] DEBUG[7367] rtp_engine.c: Destroyed RTP instance '0x1d23708'
[2015-01-30 04:29:47] VERBOSE[7367] chan_sip.c: 
<--- SIP read from UDP:99.7.231.29:63514 --->

<------------->
[2015-01-30 04:29:53] VERBOSE[7367] chan_sip.c: 
<--- SIP read from UDP:107.21.211.20:5060 --->
INVITE sip:[email protected] SIP/2.0
Record-Route: <sip:107.21.211.20:5060;lr;ftag=06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4>
From: "+19045352288" <sip:[email protected]>;tag=06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4
To: <sip:[email protected]>
CSeq: 102 INVITE
Max-Forwards: 68
Date: Fri, 30 Jan 2015 04:29:53 GMT
Call-ID: [email protected]
Via: SIP/2.0/UDP 107.21.211.20:5060;branch=z9hG4bK0c68.47df40e2.0
Via: SIP/2.0/UDP 10.31.198.154:5060;branch=z9hG4bK3043e00c-3f32-4e25-86f7-f4a727c9f8c4_6772d868_2701672406467309
Contact: "+19045352288" <sip:[email protected]:5060;transport=udp>
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE
User-Agent: Twilio Gateway
X-Twilio-ApiVersion: 2010-04-01
X-Twilio-AccountSid: AC69a23aa0be76748f039734a7df847e37
Content-Type: application/sdp
X-Twilio-CallSid: CAaf9954dc3555b67506d1ac5ec2ccb044
Content-Length: 247

v=0
o=- 208350152 208350152 IN IP4 54.211.24.146
s=session
c=IN IP4 54.211.24.146
t=0 0
m=audio 19360 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
<------------->
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 0 [ 47]: INVITE sip:[email protected] SIP/2.0
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 1 [101]: Record-Route: <sip:107.21.211.20:5060;lr;ftag=06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4>
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 2 [113]: From: "+19045352288" <sip:[email protected]>;tag=06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 3 [ 38]: To: <sip:[email protected]>
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 5 [ 16]: Max-Forwards: 68
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 6 [ 35]: Date: Fri, 30 Jan 2015 04:29:53 GMT
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 7 [ 49]: Call-ID: [email protected]
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 8 [ 65]: Via: SIP/2.0/UDP 107.21.211.20:5060;branch=z9hG4bK0c68.47df40e2.0
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 9 [112]: Via: SIP/2.0/UDP 10.31.198.154:5060;branch=z9hG4bK3043e00c-3f32-4e25-86f7-f4a727c9f8c4_6772d868_2701672406467309
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 10 [ 75]: Contact: "+19045352288" <sip:[email protected]:5060;transport=udp>
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 11 [ 36]: Allow: INVITE,ACK,CANCEL,OPTIONS,BYE
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 12 [ 26]: User-Agent: Twilio Gateway
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 13 [ 31]: X-Twilio-ApiVersion: 2010-04-01
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 14 [ 55]: X-Twilio-AccountSid: AC69a23aa0be76748f039734a7df847e37
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 16 [ 52]: X-Twilio-CallSid: CAaf9954dc3555b67506d1ac5ec2ccb044
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 17 [ 19]: Content-Length: 247
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Header 18 [ 0]: 
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 0 [ 3]: v=0
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 1 [ 44]: o=- 208350152 208350152 IN IP4 54.211.24.146
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 2 [ 9]: s=session
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 3 [ 22]: c=IN IP4 54.211.24.146
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 4 [ 5]: t=0 0
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 5 [ 27]: m=audio 19360 RTP/AVP 0 101
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - -
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 10 [ 10]: a=ptime:20
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Body 11 [ 10]: a=sendrecv
[2015-01-30 04:29:53] VERBOSE[7367] chan_sip.c: --- (18 headers 12 lines) ---
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: = Looking for Call ID: [email protected] (Checking From) --From tag 06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4 --To-tag 
[2015-01-30 04:29:53] DEBUG[7367] logger.c: CALL_ID [C-00000001] created by thread.
[2015-01-30 04:29:53] DEBUG[7367] acl.c: For destination '107.21.211.20', our source address is '172.31.60.169'.
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.31.60.169:5060
[2015-01-30 04:29:53] DEBUG[7367] chan_sip.c: Allocating new SIP dialog for [email protected] - INVITE (No RTP)
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting '107.21.211.20:5060' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host '107.21.211.20' and port '5060'.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Sending to 107.21.211.20:5060 (NAT)
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid [email protected]
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Using INVITE request as basis request - [email protected]
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting 'sip.twilio.com' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host 'sip.twilio.com' and port ''.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: No matching peer for '+19045352288' from '107.21.211.20:5060'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x1d1b9e8'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Allocated port 14488 for RTP instance '0x1d1b9e8'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting '172.31.60.169' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host '172.31.60.169' and port ''.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: RTP instance '0x1d1b9e8' is setup and ready to go
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x1d23708'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Allocated port 16626 for RTP instance '0x1d23708'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting '172.31.60.169' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host '172.31.60.169' and port ''.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: RTP instance '0x1d23708' is setup and ready to go
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x1d23708'
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] netsock2.c: == Using SIP VIDEO TOS bits 136
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] netsock2.c: == Using SIP VIDEO CoS mark 6
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x1d1b9e8'
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Setting NAT on RTP to On
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Setting NAT on VRTP to On
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing session-level SDP o=- 208350152 208350152 IN IP4 54.211.24.146... OK.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED OR FAILED.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting '54.211.24.146' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host '54.211.24.146' and port ''.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 54.211.24.146... OK.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Found RTP audio format 0
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x7f005d2ccc00
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Found RTP audio format 101
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Setting payload 101 based on m type on 0x7f005d2ccc00
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Capabilities: us - (ulaw|alaw|g729|g722|h264), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1d1b9e8'
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Peer audio RTP is at port 54.211.24.146:19360
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Copying payload 0 from 0x7f005d2ccc00 to 0x1d1bbb0
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] rtp_engine.c: Copying payload 101 from 0x7f005d2ccc00 to 0x1d1bbb0
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x1d1b9e8'
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1d23708'
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Peer doesn't provide video
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: We're settling with these formats: (ulaw)
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Checking SIP call limits for device 
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Updating call counter for incoming call
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: Splitting 'sip.twilio.com' into...
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] netsock2.c: ...host 'sip.twilio.com' and port ''.
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: Looking for 818 in knock-knock (domain phone.cocobelladolls.com)
[2015-01-30 04:29:53] VERBOSE[7367][C-00000001] chan_sip.c: 
<--- Reliably Transmitting (NAT) to 107.21.211.20:5060 --->
SIP/2.0 404 Not Found 
Via: SIP/2.0/UDP 107.21.211.20:5060;branch=z9hG4bK0c68.47df40e2.0;received=107.21.211.20;rport=5060 
Via: SIP/2.0/UDP 10.31.198.154:5060;branch=z9hG4bK3043e00c-3f32-4e25-86f7-f4a727c9f8c4_6772d868_2701672406467309 
From: "+19045352288" <sip:[email protected]>;tag=06200308_6772d868_3043e00c-3f32-4e25-86f7-f4a727c9f8c4 
To: <sip:[email protected]>;tag=as294410a7 
Call-ID: [email protected] 
CSeq: 102 INVITE 
Server: FPBX-2.11.0(11.2.1) 
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH 
Supported: replaces, timer 
Content-Length: 0 


<------------>
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #12
[2015-01-30 04:29:53] DEBUG[7367][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 107.21.211.20:5060
[2015-01-30 04:29:53] NOTICE[7367][C-00000001] chan_sip.c: Call from '' (107.21.211.20:5060) to extension '818' rejected because extension not found in context 'knock-knock'.

CocoBellaDolls · January 30, 2015, 4:39am

I had to re-edit the logs. I pulled the wrong part.

CocoBellaDolls · January 30, 2015, 4:42am

Why is it rejecting this number when 818 is one of my extensions? If I sent it to from-internal then shouldn’t it treat it as 818@internal?

dicko · January 30, 2015, 4:46am

you only have an “s” extension in knock-knock, it won’t work that way, (the “s” extension indicates start and if there are no ${EXTEN} in your context it will “start” there), back to the “thinkers statue” posture

I would suggest you read the whole of

http://www.asteriskdocs.org/

to save us all time and wasted effort