Cisco Call Manager and FreePBX "all circuits are busy now"

mikeisfly1 · June 12, 2014, 8:18pm

Hello all I have a interesting problem that I can seem to figure out. I’m hoping someone will be able to help. I have Cisco Call Manager 4.3 and FreePBX 5.211.65-12 Asterisk 11 connected via a SIP trunk. I can call any phone via freepbx and vise versa. I’m using Freepbx as a voicemail server as well as my voip server for my mobile users. The hole system works great, but here it he problem.

If a Freepbx user calls a Call Manager user and the Call Manager the call gets route out of the SIP trunk (so far so good), if the Call Manager user in not available to answer the phone then the call needs to get sent back to Freepbx so that the voicemail system can answer the call, and that is when I get the all circuits are busy message. Looking at the asterisk cli i get the following:

    -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/5552000-000000b0", "0?customtrunk") in new stack
    -- Executing [s@macro-dialout-trunk:22] Dial("SIP/5552000-000000b0", "SIP/toCCM/5551045,300,M(setmusic^MotownHits)tr") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Called SIP/toCCM/5551045
[2014-06-12 15:40:44] WARNING[46699][C-000000af]: chan_sip.c:23107 handle_response_invite: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as28a446c3'
[2014-06-12 15:40:44] WARNING[46699][C-000000af]: chan_sip.c:23107 handle_response_invite: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as28a446c3'
  == Everyone is busy/congested at this time (1:0/0/1)
    -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/5552000-000000b0", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 21") in new stack
    -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/5552000-000000b0", "0?continue,1:s-CHANUNAVAIL,1") in new stack
    -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("SIP/5552000-000000b0", "RC=21") in new stack
    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("SIP/5552000-000000b0", "21,1") in new stack
    -- Goto (macro-dialout-trunk,21,1)
    -- Executing [21@macro-dialout-trunk:1] Goto("SIP/5552000-000000b0", "continue,1") in new stack
    -- Goto (macro-dialout-trunk,continue,1)
    -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/5552000-000000b0", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 21 - failing through to other trunks") in new stack
    -- Executing [continue@macro-dialout-trunk:2] Set("SIP/5552000-000000b0", "CALLERID(number)=5552000") in new stack
    -- Executing [1045@from-internal:9] Macro("SIP/5552000-000000b0", "outisbusy,") in new stack
    -- Executing [s@macro-outisbusy:1] Progress("SIP/5552000-000000b0", "") in new stack
    -- Executing [s@macro-outisbusy:2] GotoIf("SIP/5552000-000000b0", "0?emergency,1") in new stack
    -- Executing [s@macro-outisbusy:3] GotoIf("SIP/5552000-000000b0", "1?intracompany,1") in new stack
    -- Goto (macro-outisbusy,intracompany,1)

here is the setup for my sip trunk:

type=peer
context=from-internal
host=ccm
disallow=all
allow=ulaw
nat=no
canreinvite=yes
qualify=yes
insecure=very
fromdomain=michaelgatesworld.us
dtmf=rfc2833

I’m thinking that my problem lies in the fact that the call is coming from freepbx then going to ccm and then back to asterisk again. Just as another data point, I am off site when I get “all circuits are busy now, please try your call again later.” message. I will try onsite (my home) when I get home. Any help would be appreciated.

Thanks,

mikeisfly1 · June 12, 2014, 8:22pm

Sorry I meant to say I can’t figure it out.

SkykingOH · June 12, 2014, 8:49pm

It’s insecure=port,invite

Do you have a host entry for ccm

Why the fromdomain tag?

type needs to be friend.

Don’t need dial plan debugs please send sip peer debug

mikeisfly1 · June 12, 2014, 10:12pm

Here are the results of a sip debug:

e[0K  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:1] e[1;36mMacroe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35muser-callerid,LIMIT,EXTERNAL,e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:1] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mTOUCH_MONITOR=1402608625.204e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:2] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mAMPUSER=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:3] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?reporte[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:4] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(REALCALLERIDNUM=5552000)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:5] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mAMPUSER=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:6] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?limite[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:7] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mAMPUSERCIDNAME=Michael A Gatese[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:8] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?reporte[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:9] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mAMPUSERCID=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:10] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__DIAL_OPTIONS=tre[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:11] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCALLERID(all)="Michael A Gates" <5552000>e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:12] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?limite[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:13] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(GROUP(concurrency_limit)=5552000)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:14] e[1;36mGosubIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m7?sub-ccss,s,1(from-internal,1045)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-ccss:1] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Return()e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-ccss:2] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCCSS_SETUP=TRUEe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-ccss:3] e[1;36mGosubIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?monitor_config,1(from-internal,1045):monitor_default,1(from-internal,1045)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [monitor_default@sub-ccss:1] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?is_extene[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [monitor_default@sub-ccss:2] e[1;36mStackPope[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [monitor_default@sub-ccss:3] e[1;36mReturne[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mFALSEe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:15] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Set(CHANNEL(language)=)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:16] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?continuee[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-user-callerid,s,30)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:30] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCALLERID(number)=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:31] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCALLERID(name)=Michael A Gatese[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:32] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCDR(cnum)=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:33] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCDR(cnam)=Michael A Gatese[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-user-callerid:34] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCHANNEL(language)=ene[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:2] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0 ?Set(CDR(accountcode)=)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:3] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mINTRACOMPANYROUTE=YESe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:4] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mMOHCLASS=MotownHitse[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:5] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(TRUNKCIDOVERRIDE=freepbx)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:6] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m_NODEST=e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:7] e[1;36mGosube[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35msub-record-check,s,1(out,1045,)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:1] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mREC_POLICY_MODE_SAVE=e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:2] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?checke[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (sub-record-check,s,7)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:7] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__MON_FMT=wave[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:8] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?nexte[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (sub-record-check,s,11)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:11] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Return()e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:12] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Set(__REC_POLICY_MODE=)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:13] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?out,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:14] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__REC_STATUS=INITIALIZEDe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:15] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mNOW=1402608625e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:16] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__DAY=12e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:17] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__MONTH=06e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:18] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__YEAR=2014e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:19] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__TIMESTR=20140612-173025e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:20] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__FROMEXTEN=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:21] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m__CALLFILENAME=out-1045-5552000-20140612-173025-1402608625.204e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-record-check:22] e[1;36mGotoe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mout,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (sub-record-check,out,1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [out@sub-record-check:1] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(__REC_POLICY_MODE=dontcare)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [out@sub-record-check:2] e[1;36mGosubIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?record,1(exten,1045,5552000)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [out@sub-record-check:3] e[1;36mReturne[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:8] e[1;36mMacroe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mdialout-trunk,2,5551045,,offe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:1] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mDIAL_TRUNK=2e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:2] e[1;36mGosubIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?sub-pincheck,s,1()e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:3] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?disabletrunk,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:4] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mDIAL_NUMBER=5551045e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:5] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mDIAL_TRUNK_OPTIONS=tre[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:6] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mOUTBOUND_GROUP=OUT_2e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:7] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?nomaxe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-dialout-trunk,s,9)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:9] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?skipoutcide[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-dialout-trunk,s,12)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:12] e[1;36mGosubIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?sub-flp-2,s,1()e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:1] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Set(TARGET_FLP_2=5555551045)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:2] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?matche[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:3] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Set(TARGET_FLP_2=551045)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:4] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?matche[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:5] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Return()e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@sub-flp-2:6] e[1;36mReturne[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:13] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mOUTNUM=5551045e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:14] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mcustom=SIP/toCCMe[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:15] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(DIAL_TRUNK_OPTIONS=M(setmusic^MotownHits)tr)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:16] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^MotownHits)trM(confirm))e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:17] e[1;36mMacroe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mdialout-trunk-predial-hook,e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk-predial-hook:1] e[1;36mMacroExite[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:18] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?bypass,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:19] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(CONNECTEDLINE(num,i)=5551045)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:20] e[1;36mExecIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?Set(CONNECTEDLINE(name,i)=CID:5552000)e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:21] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?customtrunke[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:22] e[1;36mDiale[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mSIP/toCCM/5551045,300,M(setmusic^MotownHits)tre[0m") in new stack

e[Kfreepbx*CLI> 
e[0K  == Using SIP RTP TOS bits 184

e[Kfreepbx*CLI> 
e[0K  == Using SIP RTP CoS mark 5

e[Kfreepbx*CLI> 
e[0KAudio is at 16542

e[Kfreepbx*CLI> 
e[0KAdding codec 100003 (ulaw) to SDP

e[Kfreepbx*CLI> 
e[0KAdding non-codec 0x1 (telephone-event) to SDP

e[Kfreepbx*CLI> 
e[0KReliably Transmitting (no NAT) to 192.168.3.13:5060:
INVITE sip:5551045@ccm SIP/2.0Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK7f5d14bcMax-Forwards: 70From: "Michael A Gates" <sip:[email protected]>;tag=as0e67723dTo: <sip:5551045@ccm>Contact: <sip:[email protected]:5060>Call-ID: [email protected]: 102 INVITEUser-Agent: FPBX-2.11.0(11.9.0)Date: Thu, 12 Jun 2014 21:30:25 GMTAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGESupported: replaces, timerContent-Type: application/sdpContent-Length: 233v=0o=root 500934233 500934233 IN IP4 192.168.3.19s=Asterisk PBX 11.9.0c=IN IP4 192.168.3.19t=0 0m=audio 16542 RTP/AVP 0 101a=rtpmap:0 PCMU/8000a=rtpmap:101 telephone-event/8000a=fmtp:101 0-16a=ptime:20a=sendrecv
---

e[Kfreepbx*CLI> 
e[0K    -- Called SIP/toCCM/5551045

e[Kfreepbx*CLI> 
e[0K
<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK7f5d14bc
From: "Michael A Gates" <sip:[email protected]>;tag=as0e67723d
To: <sip:5551045@ccm>;tag=16814989
Date: Thu, 12 Jun 2014 22:01:52 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

e[Kfreepbx*CLI> 
e[0K
<--- SIP read from UDP:192.168.3.13:5060 --->
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK5310a62
From: "Michael A Gates" <sip:[email protected]>;tag=16814991
To: <sip:[email protected]>
Date: Thu, 12 Jun 2014 22:01:52 GMT
Call-ID: [email protected]
Supported: timer
Min-SE: 1800
User-Agent: Cisco-CCM4.1
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "Michael A Gates" <sip:[email protected]>;party=calling;screen=no;privacy=off
Contact: <sip:[email protected]:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 227

v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 192.168.3.13
s=SIP Call
c=IN IP4 192.168.3.13
t=0 0
m=audio 25006 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
--- (18 headers 11 lines) ---
Sending to 192.168.3.13:5060 (NAT)
Sending to 192.168.3.13:5060 (NAT)
Using INVITE request as basis request - [email protected]
Found peer '5552000' for '5552000' from 192.168.3.13:5060

<--- Reliably Transmitting (NAT) to 192.168.3.13:5060 --->
SIP/2.0 401 UnauthorizedVia: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK5310a62;received=192.168.3.13;rport=5060From: "Michael A Gates" <sip:[email protected]>;tag=16814991To: <sip:[email protected]>;tag=as5dc856cfCall-ID: [email protected]: 101 INVITEServer: FPBX-2.11.0(11.9.0)Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGESupported: replaces, timerWWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4365eee6"Content-Length: 0
<------------>
Scheduling destruction of SIP dialog '[email protected]' in 7808 ms (Method: INVITE)

e[Kfreepbx*CLI> 
e[0K
<--- SIP read from UDP:192.168.3.13:5060 --->
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK5310a62
From: "Michael A Gates" <sip:[email protected]>;tag=16814991
To: <sip:[email protected]>;tag=as5dc856cf
Date: Thu, 12 Jun 2014 22:01:52 GMT
Call-ID: [email protected]
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

<------------->

e[Kfreepbx*CLI> 
e[0K--- (9 headers 0 lines) ---

e[Kfreepbx*CLI> 
e[0K
<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK7f5d14bc
From: "Michael A Gates" <sip:[email protected]>;tag=as0e67723d
To: <sip:5551045@ccm>;tag=16814989
Date: Thu, 12 Jun 2014 22:01:52 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->

e[Kfreepbx*CLI> 
e[0K--- (9 headers 0 lines) ---

e[Kfreepbx*CLI> 
e[0KTransmitting (no NAT) to 192.168.3.13:5060:
ACK sip:5551045@ccm SIP/2.0Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK7f5d14bcMax-Forwards: 70From: "Michael A Gates" <sip:[email protected]>;tag=as0e67723dTo: <sip:5551045@ccm>;tag=16814989Contact: <sip:[email protected]:5060>Call-ID: [email protected]: 102 ACKUser-Agent: FPBX-2.11.0(11.9.0)Content-Length: 0
---

e[Kfreepbx*CLI> 
e[0K[2014-06-12 17:30:25] e[1;31mWARNINGe[0m[46699][C-000000c4]: e[1;37mchan_sip.ce[0m:e[1;37m23107e[0m e[1;37mhandle_response_invitee[0m: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as0e67723d'

e[Kfreepbx*CLI> 
e[0K[2014-06-12 17:30:25] e[1;31mWARNINGe[0m[46699][C-000000c4]: e[1;37mchan_sip.ce[0m:e[1;37m23107e[0m e[1;37mhandle_response_invitee[0m: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as0e67723d'

e[Kfreepbx*CLI> 
e[0KScheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: INVITE)

e[Kfreepbx*CLI> 
e[0K  == Everyone is busy/congested at this time (1:0/0/1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:23] e[1;36mNoOpe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mDial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 21e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-dialout-trunk:24] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?continue,1:s-CHANUNAVAIL,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mRC=21e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] e[1;36mGotoe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m21,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-dialout-trunk,21,1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [21@macro-dialout-trunk:1] e[1;36mGotoe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mcontinue,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-dialout-trunk,continue,1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [continue@macro-dialout-trunk:1] e[1;36mNoOpe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mTRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 21 - failing through to other trunkse[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [continue@macro-dialout-trunk:2] e[1;36mSete[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mCALLERID(number)=5552000e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [1045@from-internal:9] e[1;36mMacroe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35moutisbusy,e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-outisbusy:1] e[1;36mProgresse[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-outisbusy:2] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m0?emergency,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Executing [s@macro-outisbusy:3] e[1;36mGotoIfe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m1?intracompany,1e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- Goto (macro-outisbusy,intracompany,1)

e[Kfreepbx*CLI> 
e[0K    -- Executing [intracompany@macro-outisbusy:1] e[1;36mPlaybacke[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35mall-circuits-busy-now&pls-try-call-later, noanswere[0m") in new stack

e[Kfreepbx*CLI> 
e[0K    -- <SIP/5552000-000000c2> Playing 'all-circuits-busy-now.ulaw' (language 'en')

e[Kfreepbx*CLI> 
e[0K       > 0x7fe0f0037f80 -- Probation passed - setting RTP source address to 192.168.3.92:10004

e[Kfreepbx*CLI> 
e[0K       > 0x7fe0f0037f80 -- Probation passed - setting RTP source address to 192.168.3.92:10004

e[Kfreepbx*CLI> 
e[0K    -- <SIP/5552000-000000c2> Playing 'pls-try-call-later.ulaw' (language 'en')

e[Kfreepbx*CLI> 
e[0K    -- Executing [intracompany@macro-outisbusy:2] e[1;36mCongestione[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35m20e[0m") in new stack

e[Kfreepbx*CLI> 
e[0K[2014-06-12 17:30:29] e[1;31mWARNINGe[0m[57090][C-000000c4]: e[1;37mchannel.ce[0m:e[1;37m4840e[0m e[1;37mast_prode[0m: Prodding channel 'SIP/5552000-000000c2' failed
[2014-06-12 17:30:29] e[1;31mWARNINGe[0m[57090][C-000000c4]: e[1;37mchannel.ce[0m:e[1;37m4840e[0m e[1;37mast_prode[0m: Prodding channel 'SIP/5552000-000000c2' failed

e[Kfreepbx*CLI> 
e[0K  == Spawn extension (macro-outisbusy, intracompany, 2) exited non-zero on 'SIP/5552000-000000c2' in macro 'outisbusy'

e[Kfreepbx*CLI> 
e[0K  == Spawn extension (from-internal, 1045, 9) exited non-zero on 'SIP/5552000-000000c2'

e[Kfreepbx*CLI> 
e[0K    -- Executing [h@from-internal:1] e[1;36mHangupe[0m("e[1;35mSIP/5552000-000000c2e[0m", "e[1;35me[0m") in new stack

e[Kfreepbx*CLI> 
e[0K  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/5552000-000000c2'

e[Kfreepbx*CLI> 
e[0KReally destroying SIP dialog '[email protected]' Method: INVITE

e[Kfreepbx*CLI> 
e[0KReally destroying SIP dialog '[email protected]' Method: ACK

e[Kfreepbx*CLI> 
e[0KReliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK76aa0fafMax-Forwards: 70From: "Unknown" <sip:[email protected]>;tag=as7bf6408fTo: <sip:ccm>Contact: <sip:[email protected]:5060>Call-ID: [email protected]:5060CSeq: 102 OPTIONSUser-Agent: FPBX-2.11.0(11.9.0)Date: Thu, 12 Jun 2014 21:30:42 GMTAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGESupported: replaces, timerContent-Length: 0
---

e[Kfreepbx*CLI> 
e[0K
<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:5060;branch=z9hG4bK76aa0faf
From: "Unknown" <sip:[email protected]>;tag=as7bf6408f
To: <sip:ccm>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS

e[Kfreepbx*CLI>

I have a dns server so I didn’t need to make a entry in my freepbx’s host file. As far a the fromdomain tag I just followed the instructions from voip-info.org (I think that was the url).

Thanks for the help.

SkykingOH · June 12, 2014, 11:39pm

That’s not a SIP debug. It’s a dialplan debug.

Stewart1 · June 13, 2014, 12:20am

Per your SIP Debug, Asterisk is still trying to authenticate the returning INVITE from the Cisco. Did you put
insecure=port,invite
into the peer definition as Skyking requested?

SkykingOH · June 13, 2014, 3:18am

I didn’t notice the scroll bar in your text box. There was also a pile of dialplan crap in front of the SIP debug (core set verbose 0 to get rid of that)

In addition to Stewart reinforcing what I told you to do I notice that the Cisco and the Asterisk box are in 2 different networks.

I am going to make the assumption that these are connected routes and no NAT is involved.

If this is a correct assumption you need to make sure the Cisco subnet, and all other subnets that contain phones (since you have reinvite on) are declared in sip settings module localnet section. Localnet tells Asterisk to exclude those networks from NAT processing.

mikeisfly1 · June 13, 2014, 9:14pm

[quote]Per your SIP Debug, Asterisk is still trying to authenticate the returning INVITE from the Cisco. Did you put
insecure=port,invite
into the peer definition as Skyking requested?[/quote]

Yes I did change insecure=very to insecure=port,invite

My Call Manager and FreePBX box are in the same subnet. My call manager is 192.168.3.13/26 and my FreePBX box is 192.168.3.19/26. My Bria for Android Softphone is on a site to site VPN site which is in a different network. I did adjust the subnet mask to include the whole site (forgot I added some address) but the problem is still happening. It’s really weird I can call Cisco to Asterisk fine, and vise versa. Cisco to Cisco will forward calls to Asterisk as a voicemail server works fine too. The problem is when I call a Cisco from Asterisk which will go over the SIP trunk and the Call get’s forwarded back to Asterisk because it went to voice mail or the phone is unregistered that’s when I get the all circuits are busy.

I think the problem might have to do with this:

[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 7 [219]: Accept: application/sdp, application/pidf+xml, application/xpidf+xml, application/simple-message-summary, message/sipfrag;version=2.0, application/im-iscomposing+xml, text/plain, text/html, application/sopi-address-book
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 8 [ 46]: Supported: replaces, 100rel, timer, norefersub
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 9 [ 60]: Allow-Events: presence, message-summary, refer, address-book
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 10 [ 30]: User-Agent: Bria Android 3.0.5
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 12 [ 19]: Content-Length: 640
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Header 13 [ 0]:
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 0 [ 3]: v=0
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 1 [ 48]: o=- 3611682300 3611682300 IN IP4 192.168.121.113
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 2 [ 9]: s=cpc_med
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 3 [ 5]: t=0 0
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 4 [ 42]: m=audio 38416 RTP/AVP 0 9 8 18 103 107 101
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 5 [ 24]: c=IN IP4 192.168.121.113
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 6 [ 10]: a=sendrecv
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 8 [ 20]: a=rtpmap:9 G722/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 10 [ 21]: a=rtpmap:18 G729/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 11 [ 19]: a=fmtp:18 annexb=no
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 12 [ 25]: a=rtpmap:103 AMR-WB/16000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 13 [ 24]: a=fmtp:103 octet-align=0
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 14 [ 22]: a=rtpmap:107 SILK/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 15 [ 25]: a=fmtp:107 useinbandfec=1
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 16 [ 33]: a=rtpmap:101 telephone-event/8000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 17 [ 15]: a=fmtp:101 0-16
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 18 [ 10]: a=ptime:20
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 19 [ 28]: m=video 38420 RTP/AVP 97 102
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 20 [ 24]: c=IN IP4 192.168.121.113
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 21 [ 13]: b=TIAS:512000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 22 [ 10]: a=sendrecv
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 23 [ 22]: a=rtpmap:97 H264/90000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 24 [ 33]: a=fmtp:97 profile-level-id=42800c
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 25 [ 22]: a=rtpmap:102 VP8/90000
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 26 [ 17]: a=orient:portrait
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Body 27 [ 20]: a=rtcp-fb:* nack pli
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: That's odd... Got a response on a call we don't know about. Callid [email protected]:45895
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Invalid SIP message - rejected , no callid, len 1421
[2014-06-13 17:05:40] DEBUG[46713] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2014-06-13 17:05:40] DEBUG[46699] chan_sip.c: Header 0 [ 0]:
[2014-06-13 17:05:42] DEBUG[46699] chan_sip.c: Auto destroying SIP dialog 'MWE0MTUwNzM0YTBkNDM2N2QwNTEwMDNjNDg2NjYzYmY.'
[2014-06-13 17:05:42] DEBUG[46699] chan_sip.c: Destroying SIP dialog MWE0MTUwNzM0YTBkNDM2N2QwNTEwMDNjNDg2NjYzYmY.
[2014-06-13 17:05:43] DEBUG[11188] manager.c: Running action 'Login'
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Allocating new SIP dialog for [email protected]:45895 - OPTIONS (No RTP)
[2014-06-13 17:05:43] DEBUG[46699] acl.c: For destination '192.168.3.13', our source address is '192.168.3.19'.
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.3.19:45895
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: SIP call-id changed from '[email protected]:45895' to '[email protected]:45895'
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]:45895
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 0 [ 23]: OPTIONS sip:ccm SIP/2.0
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK009d24a2
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 3 [ 63]: From: "Unknown" <sip:[email protected]:45895>;tag=as33fa92a4
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 4 [ 13]: To: <sip:ccm>
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 5 [ 41]: Contact: <sip:[email protected]:45895>
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 6 [ 60]: Call-ID: [email protected]:45895
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.11.0(11.9.0)
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 9 [ 35]: Date: Fri, 13 Jun 2014 21:05:43 GMT
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #72264
[2014-06-13 17:05:43] DEBUG[46699] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.3.13:45895
[2014-06-13 17:05:44] DEBUG[11192] manager.c: Running action 'Login'
[2014-06-13 17:05:44] DEBUG[46699] chan_sip.c: SIP TIMER: Not rescheduling id #72264:OPTIONS (Method 3) (No timer T1)
[2014-06-13 17:05:44] DEBUG[46699] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.3.13:45895
[2014-06-13 17:05:45] DEBUG[46699] chan_sip.c: SIP TIMER: Not rescheduling id #72264:OPTIONS (Method 3) (No timer T1)
[2014-06-13 17:05:45] DEBUG[46699] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.3.13:45895
[2014-06-13 17:05:46] DEBUG[46699] chan_sip.c: SIP TIMER: Not rescheduling id #72264:OPTIONS (Method 3) (No timer T1)
[2014-06-13 17:05:46] DEBUG[46699] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.3.13:45895
[2014-06-13 17:05:47] DEBUG[46699] chan_sip.c: SIP TIMER: Not rescheduling id #72264:OPTIONS (Method 3) (No timer T1)
[2014-06-13 17:05:47] DEBUG[46699] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.3.13:45895
[2014-06-13 17:05:47] DEBUG[46699] chan_sip.c: Destroying SIP dialog [email protected]:45895
[2014-06-13 17:05:50] DEBUG[11195] manager.c: Running action 'Login'

In particular this section:

[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: That's odd... Got a response on a call we don't know about. Callid [email protected]:45895
[2014-06-13 17:05:39] DEBUG[46699] chan_sip.c: Invalid SIP message - rejected , no callid, len 1421

I’m interested to hear your thoughts. I’m new to Freepbx (Asterisk) I’m more of a Cisco / Microsoft guy so I appreciate the help.

SkykingOH · June 13, 2014, 9:33pm

Now you have a public IP in the mix. You need to explain the network.

mikeisfly1 · June 13, 2014, 11:18pm

This might help.

I have my dns server setup so that when I’m home I get the private IP address of my freepbx server. When I’m not home I get the public IP address of the Pfsense Server. I have a site to site vpn (open VPN via PfSense) from home to work. Since I’m not home my phone is using freepbx’s public IP. From the diagram you can see that I have Cisco phones at home as well as work where I can make voip calls via Cisco’s SCCP (Skinny protocol). I can also make SIP to SIP calls from my house to my job no problem. I can even call Skinny to SIP no problem. I only have a problem if a SIP to Skinny phone call in not answered and the call is bounced back to Freepbx. The public IP address that you see is the address of my home. (I probably should have obscured the last 3 octets).

mikeisfly1 · June 15, 2014, 1:45pm

So doing another debug without all the noise:

Here is a successful call:

freepbx*CLI> sip set debug peer toCCM 
SIP Debugging Enabled for IP: 192.168.3.13
Audio is at 10750
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
INVITE sip:5551045@ccm:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0013b790
Max-Forwards: 70
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]
CSeq: 102 INVITE
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:35:11 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 233

v=0
o=root 889763186 889763186 IN IP4 192.168.3.19
s=Asterisk PBX 11.9.0
c=IN IP4 192.168.3.19
t=0 0
m=audio 10750 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0013b790
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Date: Sun, 15 Jun 2014 10:34:38 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0013b790
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Date: Sun, 15 Jun 2014 10:34:38 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
Allow-Events: telephone-event
Remote-Party-ID: "Michael Gates Laptop" <sip:[email protected]>;party=called;screen=no;privacy=off
Contact: <sip:[email protected]:5060>
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---
list_route: hop: <sip:[email protected]:5060>
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK21808785
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as6e63157b
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:35:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK21808785
From: "Unknown" <sip:[email protected]:45895>;tag=as6e63157b
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0013b790
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Date: Sun, 15 Jun 2014 10:34:38 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
Allow-Events: telephone-event
Remote-Party-ID: "Michael Gates Laptop" <sip:[email protected]>;party=called;screen=yes;privacy=off
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Content-Length: 227

v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 192.168.3.13
s=SIP Call
c=IN IP4 192.168.3.13
t=0 0
m=audio 25190 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
--- (13 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 - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (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.3.13:25190
list_route: hop: <sip:[email protected]:5060>
set_destination: Parsing <sip:[email protected]:5060> for address/port to send to
set_destination: set destination to 192.168.3.13:5060
Transmitting (no NAT) to 192.168.3.13:5060:
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK1e2cb315
Max-Forwards: 70
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]
CSeq: 102 ACK
User-Agent: FPBX-2.11.0(11.9.0)
Content-Length: 0


---
Scheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: INVITE)
set_destination: Parsing <sip:[email protected]:5060> for address/port to send to
set_destination: set destination to 192.168.3.13:5060
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK524aed95
Max-Forwards: 70
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Call-ID: [email protected]
CSeq: 103 BYE
User-Agent: FPBX-2.11.0(11.9.0)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK524aed95
From: "Michael A Gates" <sip:[email protected]>;tag=as24845ee8
To: <sip:5551045@ccm:5060>;tag=16820025
Date: Sun, 15 Jun 2014 10:34:56 GMT
Call-ID: [email protected]
Content-Length: 0
CSeq: 103 BYE

<------------->
--- (8 headers 0 lines) ---
Really destroying SIP dialog '[email protected]' Method: INVITE
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0f6aff68
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as79f7c89a
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:36:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK0f6aff68
From: "Unknown" <sip:[email protected]:45895>;tag=as79f7c89a
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK49b3afe7
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as3ce757c7
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:37:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK49b3afe7
From: "Unknown" <sip:[email protected]:45895>;tag=as3ce757c7
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

Here is a unsuccessful forward to voicemail (8888) if a sip (Freepbx) user calls a skinny (cisco call manager user) and they don’t answer the phone or if the phone is a unregistered state.

Audio is at 17086
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
INVITE sip:5551045@ccm:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK285f5e8f
Max-Forwards: 70
From: "Michael A Gates" <sip:[email protected]>;tag=as43febe0f
To: <sip:5551045@ccm:5060>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]
CSeq: 102 INVITE
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:39:08 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 1533488752 1533488752 IN IP4 192.168.3.19
s=Asterisk PBX 11.9.0
c=IN IP4 192.168.3.19
t=0 0
m=audio 17086 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK285f5e8f
From: "Michael A Gates" <sip:[email protected]>;tag=as43febe0f
To: <sip:5551045@ccm:5060>;tag=16820032
Date: Sun, 15 Jun 2014 10:38:34 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK285f5e8f
From: "Michael A Gates" <sip:[email protected]>;tag=as43febe0f
To: <sip:5551045@ccm:5060>;tag=16820032
Date: Sun, 15 Jun 2014 10:38:34 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
Allow-Events: telephone-event
Remote-Party-ID: "Michael Gates Laptop" <sip:[email protected]>;party=called;screen=no;privacy=off
Contact: <sip:[email protected]:5060>
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---
list_route: hop: <sip:[email protected]:5060>
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK62558fad
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as7a6a2308
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:39:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK62558fad
From: "Unknown" <sip:[email protected]:45895>;tag=as7a6a2308
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

<--- SIP read from UDP:192.168.3.13:5060 --->
INVITE sip:[email protected]:45895 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK23234646
From: "Michael A Gates" <sip:[email protected]>;tag=16820035
To: <sip:[email protected]>
Date: Sun, 15 Jun 2014 10:38:41 GMT
Call-ID: [email protected]
Supported: timer
Min-SE: 1800
User-Agent: Cisco-CCM4.1
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "Michael A Gates" <sip:[email protected]>;party=calling;screen=no;privacy=off
Contact: <sip:[email protected]:5060>
Diversion: <sip:[email protected]>;reason=no-answer
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 227

v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 192.168.3.13
s=SIP Call
c=IN IP4 192.168.3.13
t=0 0
m=audio 25194 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
--- (19 headers 11 lines) ---
Sending to 192.168.3.13:5060 (NAT)
Sending to 192.168.3.13:5060 (NAT)
Using INVITE request as basis request - [email protected]
Found peer '5552000' for '5552000' from 192.168.3.13:5060

<--- Reliably Transmitting (NAT) to 192.168.3.13:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK23234646;received=192.168.3.13;rport=5060
From: "Michael A Gates" <sip:[email protected]>;tag=16820035
To: <sip:[email protected]>;tag=as21403f69
Call-ID: [email protected]
CSeq: 101 INVITE
Server: FPBX-2.11.0(11.9.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1da0a324"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: INVITE)

<--- SIP read from UDP:192.168.3.13:5060 --->
ACK sip:[email protected]:45895 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK23234646
From: "Michael A Gates" <sip:[email protected]>;tag=16820035
To: <sip:[email protected]>;tag=as21403f69
Date: Sun, 15 Jun 2014 10:38:41 GMT
Call-ID: [email protected]
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK285f5e8f
From: "Michael A Gates" <sip:[email protected]>;tag=as43febe0f
To: <sip:5551045@ccm:5060>;tag=16820032
Date: Sun, 15 Jun 2014 10:38:34 GMT
Call-ID: [email protected]
CSeq: 102 INVITE
Allow-Events: telephone-event
Remote-Party-ID: "Michael Gates Laptop" <sip:[email protected]>;party=called;screen=no;privacy=off
Content-Length: 0

<------------->
--- (10 headers 0 lines) ---
Transmitting (no NAT) to 192.168.3.13:5060:
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK285f5e8f
Max-Forwards: 70
From: "Michael A Gates" <sip:[email protected]>;tag=as43febe0f
To: <sip:5551045@ccm:5060>;tag=16820032
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]
CSeq: 102 ACK
User-Agent: FPBX-2.11.0(11.9.0)
Content-Length: 0


---
[2014-06-15 09:39:15] WARNING[1852][C-00000053]: chan_sip.c:23107 handle_response_invite: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as43febe0f'
[2014-06-15 09:39:15] WARNING[1852][C-00000053]: chan_sip.c:23107 handle_response_invite: Received response: "Forbidden" from '"Michael A Gates" <sip:[email protected]>;tag=as43febe0f'
Scheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: INVITE)
[2014-06-15 09:39:19] WARNING[29252][C-00000053]: channel.c:4840 ast_prod: Prodding channel 'SIP/5552000-00000061' failed
[2014-06-15 09:39:19] WARNING[29252][C-00000053]: channel.c:4840 ast_prod: Prodding channel 'SIP/5552000-00000061' failed
Really destroying SIP dialog '[email protected]' Method: ACK
Really destroying SIP dialog '[email protected]' Method: INVITE
[2014-06-15 09:40:06] NOTICE[1852]: chan_sip.c:16534 check_auth: Correct auth, but based on stale nonce received from '"Michael A. Gates"<sip:[email protected]:45895>;tag=8d3d3821'
[2014-06-15 09:40:06] NOTICE[1852]: chan_sip.c:16534 check_auth: Correct auth, but based on stale nonce received from '"Michael A. Gates"<sip:[email protected]:45895>;tag=8d3d3821'
[2014-06-15 09:40:13] WARNING[1852]: chan_sip.c:4176 retrans_pkt: Retransmission timeout reached on transmission NzFkYmM0MDU2MDcyODdkOGJhYjNjOWI1MjQyNjgwZTA. for seqno 108 (Non-critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
[2014-06-15 09:40:13] WARNING[1852]: chan_sip.c:4176 retrans_pkt: Retransmission timeout reached on transmission NzFkYmM0MDU2MDcyODdkOGJhYjNjOWI1MjQyNjgwZTA. for seqno 108 (Non-critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK08211b5b
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as2e77011a
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Sun, 15 Jun 2014 13:40:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK08211b5b
From: "Unknown" <sip:[email protected]:45895>;tag=as2e77011a
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

Now what is interesting is it looks like the call manager send the call to voicemail (8888) but then the phone that I’m calling from rejects the forward. I have looked under extensions to see if there is anything there that might give me a clue but I don’t see anything.

Stewart1 · June 15, 2014, 5:39pm

What we know is:
Cisco sends apparently good INVITE sip:[email protected]:45895 .
Asterisk inappropriately and unexpectedly challenges for authentication with a 401 Unauthorized.
Cisco propagates the error by sending back to Asterisk a 403 Forbidden for the original call.

What we don’t know is how is this case different from “ordinary” calls from Cisco to Asterisk.
Can you please post a similar log for an unanswered call from Skinny to Skinny that goes to Asterisk voicemail?

My suspicion is that somehow the From: showing an internal extension is confusing Asterisk.

mikeisfly1 · June 16, 2014, 12:05am

First, thanks for the reply.

Here is a capture from skinny to skinny that was not answered that results in a forward the Freepbx for voice mail.

Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK4198cb9d
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as393bc93a
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Mon, 16 Jun 2014 02:58:55 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK4198cb9d
From: "Unknown" <sip:[email protected]:45895>;tag=as393bc93a
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

<--- SIP read from UDP:192.168.3.13:5060 --->
INVITE sip:[email protected]:45895 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK3ecc7d98
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>
Date: Sun, 15 Jun 2014 23:58:53 GMT
Call-ID: [email protected]
Supported: timer
Min-SE: 1800
User-Agent: Cisco-CCM4.1
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "Livingroom" <sip:[email protected]>;party=calling;screen=no;privacy=off
Contact: <sip:[email protected]:5060>
Diversion: <sip:[email protected]>;reason=no-answer
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 227

v=0
o=CiscoSystemsCCM-SIP 2000 1000 IN IP4 192.168.3.13
s=SIP Call
c=IN IP4 192.168.3.13
t=0 0
m=audio 25294 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
--- (19 headers 11 lines) ---
Sending to 192.168.3.13:5060 (NAT)
Sending to 192.168.3.13:5060 (NAT)
Using INVITE request as basis request - [email protected]
Found peer 'toCCM' for '5551006' from 192.168.3.13:5060
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 - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (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.3.13:25294
Looking for 8888 in from-internal (domain 192.168.3.19)
list_route: hop: <sip:[email protected]:5060>
RDNIS for this call is 5551045 (reason no-answer)

<--- Transmitting (no NAT) to 192.168.3.13:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK3ecc7d98;received=192.168.3.13
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>
Call-ID: [email protected]
CSeq: 101 INVITE
Server: FPBX-2.11.0(11.9.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:45895>
Content-Length: 0


<------------>
Audio is at 17966
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<--- Reliably Transmitting (no NAT) to 192.168.3.13:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK3ecc7d98;received=192.168.3.13
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>;tag=as605168bf
Call-ID: [email protected]
CSeq: 101 INVITE
Server: FPBX-2.11.0(11.9.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:45895>
Content-Type: application/sdp
Require: timer
Content-Length: 233

v=0
o=root 114535299 114535299 IN IP4 192.168.3.19
s=Asterisk PBX 11.9.0
c=IN IP4 192.168.3.19
t=0 0
m=audio 17966 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>

<--- SIP read from UDP:192.168.3.13:5060 --->
ACK sip:[email protected]:45895 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK740ce818
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>;tag=as605168bf
Date: Sun, 15 Jun 2014 23:58:53 GMT
Call-ID: [email protected]
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:192.168.3.13:5060 --->
BYE sip:[email protected]:45895 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK2026404c
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>;tag=as605168bf
Date: Sun, 15 Jun 2014 23:58:53 GMT
Call-ID: [email protected]
User-Agent: Cisco-CCM4.1
Max-Forwards: 70
CSeq: 102 BYE
Content-Length: 0

<------------->
--- (10 headers 0 lines) ---
Sending to 192.168.3.13:5060 (no NAT)
Scheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: BYE)

<--- Transmitting (no NAT) to 192.168.3.13:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.13:5060;branch=z9hG4bK2026404c;received=192.168.3.13
From: "Livingroom" <sip:[email protected]>;tag=16821058
To: <sip:[email protected]>;tag=as605168bf
Call-ID: [email protected]
CSeq: 102 BYE
Server: FPBX-2.11.0(11.9.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
Audio is at 14530
Adding codec 100003 (ulaw) to SDP
Adding codec 100012 (g722) to SDP
Adding codec 100008 (g729) to SDP
Adding codec 100004 (alaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 192.168.3.13:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK7e08ba42;rport
Max-Forwards: 70
From: <sip:[email protected]:45895>;tag=as1a52bd30
To: <sip:[email protected]>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 INVITE
User-Agent: FPBX-2.11.0(11.9.0)
Date: Mon, 16 Jun 2014 02:59:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 328

v=0
o=root 757326545 757326545 IN IP4 192.168.3.19
s=Asterisk PBX 11.9.0
c=IN IP4 192.168.3.19
t=0 0
m=audio 14530 RTP/AVP 0 9 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK7e08ba42;rport
From: <sip:[email protected]:45895>;tag=as1a52bd30
To: <sip:[email protected]>;tag=16821059
Date: Sun, 15 Jun 2014 23:59:11 GMT
Call-ID: [email protected]:45895
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK7e08ba42;rport
From: <sip:[email protected]:45895>;tag=as1a52bd30
To: <sip:[email protected]>;tag=16821059
Date: Sun, 15 Jun 2014 23:59:11 GMT
Call-ID: [email protected]:45895
CSeq: 102 INVITE
Allow-Events: telephone-event
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---
Transmitting (NAT) to 192.168.3.13:5060:
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK7e08ba42;rport
Max-Forwards: 70
From: <sip:[email protected]:45895>;tag=as1a52bd30
To: <sip:[email protected]>;tag=16821059
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 ACK
User-Agent: FPBX-2.11.0(11.9.0)
Content-Length: 0


---
[2014-06-15 22:59:47] NOTICE[40173]: pbx_spool.c:389 attempt_thread: Call failed to go through, reason (8) Congestion (circuits busy)
[2014-06-15 22:59:47] NOTICE[40173]: pbx_spool.c:389 attempt_thread: Call failed to go through, reason (8) Congestion (circuits busy)
[2014-06-15 22:59:47] NOTICE[40173]: pbx_spool.c:392 attempt_thread: Queued call to SIP/[email protected] expired without completion after 0 attempts
[2014-06-15 22:59:47] NOTICE[40173]: pbx_spool.c:392 attempt_thread: Queued call to SIP/[email protected] expired without completion after 0 attempts
Really destroying SIP dialog '[email protected]:45895' Method: INVITE
Really destroying SIP dialog '[email protected]' Method: BYE
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK16ce1138
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as27e0a0fe
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Mon, 16 Jun 2014 02:59:55 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK16ce1138
From: "Unknown" <sip:[email protected]:45895>;tag=as27e0a0fe
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS
Reliably Transmitting (no NAT) to 192.168.3.13:5060:
OPTIONS sip:ccm SIP/2.0
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK007f3191
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:45895>;tag=as758644c6
To: <sip:ccm>
Contact: <sip:[email protected]:45895>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.9.0)
Date: Mon, 16 Jun 2014 03:00:55 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:192.168.3.13:5060 --->
SIP/2.0 400 Bad Request - 'Malformed/Missing URL'
Via: SIP/2.0/UDP 192.168.3.19:45895;branch=z9hG4bK007f3191
From: "Unknown" <sip:[email protected]:45895>;tag=as758644c6
To: <sip:ccm>
Call-ID: [email protected]:45895
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '[email protected]:45895' Method: OPTIONS

Additionally the successful call above was from sip (asterisk) to Skinny. I’m thinking the problem might be on the Cisco side. Cisco may won’t allow me to transfer a off net call to a offnet site. Even though I have typed the trunk and the call route as “On-Net”

Stewart1 · June 16, 2014, 12:41am

I see what’s happening but don’t know how to fix it.

In the good case, Cisco’s INVITE matches the trunk and all is well.

In the bad case, Cisco’s INVITE matches the calling extension, that requires authentication, Cisco treats it as an error and rejects the call.

I don’t know why the From: match apparently takes precedence over the host match. If it’s just the order the peers are in the config file, you may be able to workaround it with a slight customization.

Another possible option is to have the Cisco rewrite the caller ID so it doesn’t match anything (the trunk match will prevail), then have Asterisk rewrite it back so the voicemail message correctly identifies the caller.

However, I know very little about Asterisk; I hope that a more knowledgeable member will chime in with the proper fix.

mikeisfly1 · June 16, 2014, 12:50am

Thanks you are correct and I had discovered it almost at the same time. The problem was on the Cisco side under the SIP trunk I had to change the setting under outbound Calls “Calling Party Selection”. I had it set to “originator” but changed it to “Last Redirect Number” and the problem is solved. Thanks to both you guys Stewart1 and SkyingOH for helping me track down this problem. It really has been a good Father’s Day. I hope you guys are enjoying yours.

Stewart1 · June 16, 2014, 1:20am

When you do that, I would expect the voicemail system to not know who made the original call, i.e. notifications, envelope playback, etc. wouldn’t work right. Does the Cisco put the originator number in Remote-Party-ID (or another header) that gets found by voicemail?

mikeisfly1 · June 16, 2014, 1:46am

You are correct the call envelope has the calling party as the phone that was being called. So I guest the problem is not solved but we seem to be very close.

mikeisfly1 · June 17, 2014, 2:56am

Okay so I finally fixed the issue and it was not the Call Manager. The problem was I needed the “insecure=port,invite” just like you gentlemen indicated. Previously I was applying this setting under the trunk->Peer Details. However having this setting had no effect weather I had it set or removed it. So I went to Settings->Asterisk SIP Settings. About half-way down the page you will find a option for other sip settings so I added it there and now everything works. I also wanted to make sure that the individual extensions settings would override this setting. So I purposely put the wrong password in a soft-phone and got a forbidden message on the phone (That’s good). I then tried to get my phone to register an extension that I had not configured and got the forbidden message as well (still good). So It looks like the problem is solved. I’m not sure if I have discovered a bug but it is my understanding that the insecure option should be set under the trunk under Peer Details.

I’m running FreePBX 5.211.65-14, PBX Service Pack: 1.0.0.0, Asterisk version 11.10.2 and have the following licensed modules: EndPoint, Sysadmin. I am running FreePBX as a VM under Hyper-V. I don’t remember this being a issue with previous versions of freepbx but I can’t say for sure I can only say that voicemail worked when a skinny phone called another skinny phone. If this was me just being a dumb noob I apologies but all the documentation that I have read lead me to believe that this option should be set under the trunk.

Thanks guys for the help.

SkykingOH · June 17, 2014, 5:01am

This should be applied at the trunk level. http://www.voip-info.org/wiki/view/Asterisk+config+sip.conf the chart clearly shows it’s a peer only parameter.

My guess is that you were never matching on the peer level.