Strange issue

I installed the distro FreePBX-3.211.63-10-i386-Full-1370290511.iso and selected Asterisk 11.4 and have a great PBX working with a couple of soft phones and a Callcentric trunk.

In-bound and outbound calls work great except…

When I call in via the Callcentric trunk and the call is not answered the calling party continues to hear a ring tone but the extension stops ringing and I get a blank VM email. The caller does not receive any VM prompts

Would anyone be able to help me get started in analysing the log below so I can figure out what is going wrong.

Thanks,
Sean.

-- Executing [[email protected]:4] GosubIf("SIP/66.193.176.35-00000012", "0?cf,1()") in new stack
-- Executing [[email protected]:5] GotoIf("SIP/66.193.176.35-00000012", "1?skip1") in new stack
-- Goto (macro-dial-one,s,8)
-- Executing [[email protected]:8] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/66.193.176.35-00000012", "0?continue") in new stack
-- Executing [[email protected]:10] Set("SIP/66.193.176.35-00000012", "EXTHASCW=ENABLED") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/66.193.176.35-00000012", "0?next1:cwinusebusy") in new stack
-- Goto (macro-dial-one,s,23)
-- Executing [[email protected]:23] GotoIf("SIP/66.193.176.35-00000012", "1?next3:continue") in new stack
-- Goto (macro-dial-one,s,24)
-- Executing [[email protected]:24] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
-- Executing [[email protected]:25] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [[email protected]:26] GosubIf("SIP/66.193.176.35-00000012", "1?dstring,1():dlocal,1()") in new stack
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "DSTRING=") in new stack
-- Executing [[email protected]:2] Set("SIP/66.193.176.35-00000012", "DEVICES=104") in new stack
-- Executing [[email protected]:3] ExecIf("SIP/66.193.176.35-00000012", "0?Return()") in new stack
-- Executing [[email protected]:4] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DEVICES=04)") in new stack
-- Executing [[email protected]:5] Set("SIP/66.193.176.35-00000012", "LOOPCNT=1") in new stack
-- Executing [[email protected]:6] Set("SIP/66.193.176.35-00000012", "ITER=1") in new stack
-- Executing [[email protected]:7] Set("SIP/66.193.176.35-00000012", "THISDIAL=IAX2/104") in new stack
-- Executing [[email protected]:8] GosubIf("SIP/66.193.176.35-00000012", "1?zap2dahdi,1()") in new stack
-- Executing [[email protected]:1] ExecIf("SIP/66.193.176.35-00000012", "0?Return()") in new stack
-- Executing [[email protected]:2] Set("SIP/66.193.176.35-00000012", "NEWDIAL=") in new stack
-- Executing [[email protected]:3] Set("SIP/66.193.176.35-00000012", "LOOPCNT2=1") in new stack
-- Executing [[email protected]:4] Set("SIP/66.193.176.35-00000012", "ITER2=1") in new stack
-- Executing [[email protected]:5] Set("SIP/66.193.176.35-00000012", "THISPART2=IAX2/104") in new stack
-- Executing [[email protected]:6] ExecIf("SIP/66.193.176.35-00000012", "0?Set(THISPART2=DAHDI2/104)") in new stack
-- Executing [[email protected]:7] Set("SIP/66.193.176.35-00000012", "NEWDIAL=IAX2/104&") in new stack
-- Executing [[email protected]:8] Set("SIP/66.193.176.35-00000012", "ITER2=2") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/66.193.176.35-00000012", "0?begin2") in new stack
-- Executing [[email protected]:10] Set("SIP/66.193.176.35-00000012", "THISDIAL=IAX2/104") in new stack
-- Executing [[email protected]:11] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:9] Set("SIP/66.193.176.35-00000012", "DSTRING=IAX2/104&") in new stack
-- Executing [[email protected]:10] Set("SIP/66.193.176.35-00000012", "ITER=2") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/66.193.176.35-00000012", "0?begin") in new stack
-- Executing [[email protected]:12] Set("SIP/66.193.176.35-00000012", "DSTRING=IAX2/104") in new stack
-- Executing [[email protected]:13] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:27] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [[email protected]:28] GotoIf("SIP/66.193.176.35-00000012", "0?skiptrace") in new stack
-- Executing [[email protected]:29] GosubIf("SIP/66.193.176.35-00000012", "1?ctset,1():ctclear,1()") in new stack
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "DB(CALLTRACE/104)=13098340362") in new stack
-- Executing [[email protected]:2] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:30] Set("SIP/66.193.176.35-00000012", "D_OPTIONS=Ttr") in new stack
-- Executing [[email protected]:31] ExecIf("SIP/66.193.176.35-00000012", "0?SIPAddHeader(Alert-Info: )") in new stack
-- Executing [[email protected]:32] ExecIf("SIP/66.193.176.35-00000012", "0?SIPAddHeader()") in new stack
-- Executing [[email protected]:33] ExecIf("SIP/66.193.176.35-00000012", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [[email protected]:34] GosubIf("SIP/66.193.176.35-00000012", "0?qwait,1()") in new stack
-- Executing [[email protected]:35] Set("SIP/66.193.176.35-00000012", "__CWIGNORE=") in new stack
-- Executing [[email protected]:36] Set("SIP/66.193.176.35-00000012", "__KEEPCID=TRUE") in new stack
-- Executing [[email protected]:37] GotoIf("SIP/66.193.176.35-00000012", "0?usegoto,1") in new stack
-- Executing [[email protected]:38] GotoIf("SIP/66.193.176.35-00000012", "1?godial") in new stack
-- Goto (macro-dial-one,s,42)
-- Executing [[email protected]:42] Dial("SIP/66.193.176.35-00000012", "IAX2/104,15,Ttr") in new stack
-- Called IAX2/104
-- Call accepted by 192.168.1.81 (format ulaw)
-- Format for call is (ulaw)
-- IAX2/104-4284 is ringing
-- Nobody picked up in 15000 ms
-- Hungup 'IAX2/104-4284'
-- Executing [[email protected]:43] ExecIf("SIP/66.193.176.35-00000012", "0?MacroExit()") in new stack
-- Executing [[email protected]:44] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DIALSTATUS=)") in new stack
-- Executing [[email protected]:45] GosubIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1()") in new stack
-- Executing [[email protected]:46] MacroExit("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:15] Set("SIP/66.193.176.35-00000012", "SV_DIALSTATUS=NOANSWER") in new stack
-- Executing [[email protected]:16] GosubIf("SIP/66.193.176.35-00000012", "0?docfu,1()") in new stack
-- Executing [[email protected]:17] GosubIf("SIP/66.193.176.35-00000012", "0?docfb,1()") in new stack
-- Executing [[email protected]:18] Set("SIP/66.193.176.35-00000012", "DIALSTATUS=NOANSWER") in new stack
-- Executing [[email protected]:19] ExecIf("SIP/66.193.176.35-00000012", "0?MacroExit()") in new stack
-- Executing [[email protected]:20] GotoIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1") in new stack
-- Executing [[email protected]:21] Macro("SIP/66.193.176.35-00000012", "vm,104,NOANSWER,") in new stack
-- Executing [[email protected]:1] Macro("SIP/66.193.176.35-00000012", "user-callerid,SKIPTTL") in new stack
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "TOUCH_MONITOR=1373554340.31") in new stack
-- Executing [[email protected]:2] Set("SIP/66.193.176.35-00000012", "AMPUSER=13098340362") in new stack
-- Executing [[email protected]:3] GotoIf("SIP/66.193.176.35-00000012", "0?report") in new stack
-- Executing [[email protected]:4] ExecIf("SIP/66.193.176.35-00000012", "0?Set(REALCALLERIDNUM=13098340362)") in new stack
-- Executing [[email protected]:5] Set("SIP/66.193.176.35-00000012", "AMPUSER=") in new stack
-- Executing [[email protected]:6] Set("SIP/66.193.176.35-00000012", "AMPUSERCIDNAME=") in new stack
-- Executing [[email protected]:7] GotoIf("SIP/66.193.176.35-00000012", "1?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [[email protected]:15] GotoIf("SIP/66.193.176.35-00000012", "1?continue") in new stack
-- Goto (macro-user-callerid,s,28)
-- Executing [[email protected]:28] Set("SIP/66.193.176.35-00000012", "CALLERID(number)=13098340362") in new stack
-- Executing [[email protected]:29] Set("SIP/66.193.176.35-00000012", "CALLERID(name)=13098340362") in new stack
-- Executing [[email protected]:30] Set("SIP/66.193.176.35-00000012", "CDR(cnum)=13098340362") in new stack
-- Executing [[email protected]:31] Set("SIP/66.193.176.35-00000012", "CDR(cnam)=13098340362") in new stack
-- Executing [[email protected]:32] Set("SIP/66.193.176.35-00000012", "CHANNEL(language)=en") in new stack
-- Executing [[email protected]:2] Set("SIP/66.193.176.35-00000012", "VMGAIN=") in new stack
-- Executing [[email protected]:3] Macro("SIP/66.193.176.35-00000012", "blkvm-check,") in new stack
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "GOSUB_RETVAL=") in new stack
-- Executing [[email protected]:2] ExecIf("SIP/66.193.176.35-00000012", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
-- Executing [[email protected]:3] MacroExit("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:4] GotoIf("SIP/66.193.176.35-00000012", "1?vmx,1") in new stack
-- Goto (macro-vm,vmx,1)
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "MEXTEN=104") in new stack
-- Executing [[email protected]:2] Set("SIP/66.193.176.35-00000012", "MMODE=NOANSWER") in new stack
-- Executing [[email protected]:3] Set("SIP/66.193.176.35-00000012", "RETVM=") in new stack
-- Executing [[email protected]:4] Set("SIP/66.193.176.35-00000012", "MODE=unavail") in new stack
-- Executing [[email protected]:5] GotoIf("SIP/66.193.176.35-00000012", "1?chknomsg") in new stack
-- Goto (macro-vm,vmx,7)
-- Executing [[email protected]:7] GotoIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1") in new stack
-- Executing [[email protected]:8] GotoIf("SIP/66.193.176.35-00000012", "1?notdirect") in new stack
-- Goto (macro-vm,vmx,10)
-- Executing [[email protected]:10] NoOp("SIP/66.193.176.35-00000012", "Checking if ext 104 is enabled: ") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/66.193.176.35-00000012", "1?s-NOANSWER,1") in new stack
-- Goto (macro-vm,s-NOANSWER,1)
-- Executing [[email protected]:1] Macro("SIP/66.193.176.35-00000012", "get-vmcontext,104") in new stack
-- Executing [[email protected]:1] Set("SIP/66.193.176.35-00000012", "VMCONTEXT=default") in new stack
-- Executing [[email protected]:2] GotoIf("SIP/66.193.176.35-00000012", "0?200:300") in new stack
-- Goto (macro-get-vmcontext,s,300)
-- Executing [[email protected]:300] NoOp("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [[email protected]:2] VoiceMail("SIP/66.193.176.35-00000012", "[email protected],u") in new stack
-- <SIP/66.193.176.35-00000012> Playing 'vm-theperson.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'digits/1.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'digits/0.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'digits/4.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'vm-isunavail.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'vm-intro.ulaw' (language 'en')
-- <SIP/66.193.176.35-00000012> Playing 'beep.ulaw' (language 'en')
-- Recording the message
-- x=0, open writing:  /var/spool/asterisk/voicemail/default/104/tmp/oW0UX4 format: wav, 0xb73791c4
-- User hung up

== Parsing ‘/var/spool/asterisk/voicemail/default/104/INBOX/msg0005.txt’: Found
== Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘SIP/66.193.176.35-00000012’ in macro ‘vm’
== Spawn extension (macro-exten-vm, s, 21) exited non-zero on ‘SIP/66.193.176.35-00000012’ in macro ‘exten-vm’
== Spawn extension (from-did-direct, 104, 2) exited non-zero on ‘SIP/66.193.176.35-00000012’
– Executing [[email protected]:1] Macro(“SIP/66.193.176.35-00000012”, “hangupcall,”) in new stack
– Executing [[email protected]:1] GotoIf(“SIP/66.193.176.35-00000012”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [[email protected]:3] ExecIf(“SIP/66.193.176.35-00000012”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [[email protected]:4] Hangup(“SIP/66.193.176.35-00000012”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/66.193.176.35-00000012’ in macro ‘hangupcall’
== Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/66.193.176.35-00000012’
localhost*CLI>

PS Does anyone know where I can get a cheap kitchen :slight_smile:

VM issue is resolved.

I figured I had to start somewhere and the trunk seemed to me to be a good place to start. I deleted the existing trunk and created a new one, and that fixed the problem. Afraid I don’t know why, but sometimes better to be lucky than good.

PS. Moderator you can remove my comment about kitchens if you like.

Sean.

According to the IP addresses of our resident Kitchen Spammer Indonesia would be a good place to look.