Strange issue

swbm · July 11, 2013, 3:04pm

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 [s@macro-dial-one:4] GosubIf("SIP/66.193.176.35-00000012", "0?cf,1()") in new stack
-- Executing [s@macro-dial-one:5] GotoIf("SIP/66.193.176.35-00000012", "1?skip1") in new stack
-- Goto (macro-dial-one,s,8)
-- Executing [s@macro-dial-one:8] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [s@macro-dial-one:9] GotoIf("SIP/66.193.176.35-00000012", "0?continue") in new stack
-- Executing [s@macro-dial-one:10] Set("SIP/66.193.176.35-00000012", "EXTHASCW=ENABLED") in new stack
-- Executing [s@macro-dial-one:11] GotoIf("SIP/66.193.176.35-00000012", "0?next1:cwinusebusy") in new stack
-- Goto (macro-dial-one,s,23)
-- Executing [s@macro-dial-one:23] GotoIf("SIP/66.193.176.35-00000012", "1?next3:continue") in new stack
-- Goto (macro-dial-one,s,24)
-- Executing [s@macro-dial-one:24] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
-- Executing [s@macro-dial-one:25] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [s@macro-dial-one:26] GosubIf("SIP/66.193.176.35-00000012", "1?dstring,1():dlocal,1()") in new stack
-- Executing [dstring@macro-dial-one:1] Set("SIP/66.193.176.35-00000012", "DSTRING=") in new stack
-- Executing [dstring@macro-dial-one:2] Set("SIP/66.193.176.35-00000012", "DEVICES=104") in new stack
-- Executing [dstring@macro-dial-one:3] ExecIf("SIP/66.193.176.35-00000012", "0?Return()") in new stack
-- Executing [dstring@macro-dial-one:4] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DEVICES=04)") in new stack
-- Executing [dstring@macro-dial-one:5] Set("SIP/66.193.176.35-00000012", "LOOPCNT=1") in new stack
-- Executing [dstring@macro-dial-one:6] Set("SIP/66.193.176.35-00000012", "ITER=1") in new stack
-- Executing [dstring@macro-dial-one:7] Set("SIP/66.193.176.35-00000012", "THISDIAL=IAX2/104") in new stack
-- Executing [dstring@macro-dial-one:8] GosubIf("SIP/66.193.176.35-00000012", "1?zap2dahdi,1()") in new stack
-- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/66.193.176.35-00000012", "0?Return()") in new stack
-- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/66.193.176.35-00000012", "NEWDIAL=") in new stack
-- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/66.193.176.35-00000012", "LOOPCNT2=1") in new stack
-- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/66.193.176.35-00000012", "ITER2=1") in new stack
-- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/66.193.176.35-00000012", "THISPART2=IAX2/104") in new stack
-- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/66.193.176.35-00000012", "0?Set(THISPART2=DAHDI2/104)") in new stack
-- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/66.193.176.35-00000012", "NEWDIAL=IAX2/104&") in new stack
-- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/66.193.176.35-00000012", "ITER2=2") in new stack
-- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/66.193.176.35-00000012", "0?begin2") in new stack
-- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/66.193.176.35-00000012", "THISDIAL=IAX2/104") in new stack
-- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [dstring@macro-dial-one:9] Set("SIP/66.193.176.35-00000012", "DSTRING=IAX2/104&") in new stack
-- Executing [dstring@macro-dial-one:10] Set("SIP/66.193.176.35-00000012", "ITER=2") in new stack
-- Executing [dstring@macro-dial-one:11] GotoIf("SIP/66.193.176.35-00000012", "0?begin") in new stack
-- Executing [dstring@macro-dial-one:12] Set("SIP/66.193.176.35-00000012", "DSTRING=IAX2/104") in new stack
-- Executing [dstring@macro-dial-one:13] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [s@macro-dial-one:27] GotoIf("SIP/66.193.176.35-00000012", "0?nodial") in new stack
-- Executing [s@macro-dial-one:28] GotoIf("SIP/66.193.176.35-00000012", "0?skiptrace") in new stack
-- Executing [s@macro-dial-one:29] GosubIf("SIP/66.193.176.35-00000012", "1?ctset,1():ctclear,1()") in new stack
-- Executing [ctset@macro-dial-one:1] Set("SIP/66.193.176.35-00000012", "DB(CALLTRACE/104)=13098340362") in new stack
-- Executing [ctset@macro-dial-one:2] Return("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [s@macro-dial-one:30] Set("SIP/66.193.176.35-00000012", "D_OPTIONS=Ttr") in new stack
-- Executing [s@macro-dial-one:31] ExecIf("SIP/66.193.176.35-00000012", "0?SIPAddHeader(Alert-Info: )") in new stack
-- Executing [s@macro-dial-one:32] ExecIf("SIP/66.193.176.35-00000012", "0?SIPAddHeader()") in new stack
-- Executing [s@macro-dial-one:33] ExecIf("SIP/66.193.176.35-00000012", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [s@macro-dial-one:34] GosubIf("SIP/66.193.176.35-00000012", "0?qwait,1()") in new stack
-- Executing [s@macro-dial-one:35] Set("SIP/66.193.176.35-00000012", "__CWIGNORE=") in new stack
-- Executing [s@macro-dial-one:36] Set("SIP/66.193.176.35-00000012", "__KEEPCID=TRUE") in new stack
-- Executing [s@macro-dial-one:37] GotoIf("SIP/66.193.176.35-00000012", "0?usegoto,1") in new stack
-- Executing [s@macro-dial-one:38] GotoIf("SIP/66.193.176.35-00000012", "1?godial") in new stack
-- Goto (macro-dial-one,s,42)
-- Executing [s@macro-dial-one: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 [s@macro-dial-one:43] ExecIf("SIP/66.193.176.35-00000012", "0?MacroExit()") in new stack
-- Executing [s@macro-dial-one:44] ExecIf("SIP/66.193.176.35-00000012", "0?Set(DIALSTATUS=)") in new stack
-- Executing [s@macro-dial-one:45] GosubIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1()") in new stack
-- Executing [s@macro-dial-one:46] MacroExit("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [s@macro-exten-vm:15] Set("SIP/66.193.176.35-00000012", "SV_DIALSTATUS=NOANSWER") in new stack
-- Executing [s@macro-exten-vm:16] GosubIf("SIP/66.193.176.35-00000012", "0?docfu,1()") in new stack
-- Executing [s@macro-exten-vm:17] GosubIf("SIP/66.193.176.35-00000012", "0?docfb,1()") in new stack
-- Executing [s@macro-exten-vm:18] Set("SIP/66.193.176.35-00000012", "DIALSTATUS=NOANSWER") in new stack
-- Executing [s@macro-exten-vm:19] ExecIf("SIP/66.193.176.35-00000012", "0?MacroExit()") in new stack
-- Executing [s@macro-exten-vm:20] GotoIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1") in new stack
-- Executing [s@macro-exten-vm:21] Macro("SIP/66.193.176.35-00000012", "vm,104,NOANSWER,") in new stack
-- Executing [s@macro-vm:1] Macro("SIP/66.193.176.35-00000012", "user-callerid,SKIPTTL") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/66.193.176.35-00000012", "TOUCH_MONITOR=1373554340.31") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/66.193.176.35-00000012", "AMPUSER=13098340362") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/66.193.176.35-00000012", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("SIP/66.193.176.35-00000012", "0?Set(REALCALLERIDNUM=13098340362)") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/66.193.176.35-00000012", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:6] Set("SIP/66.193.176.35-00000012", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:7] GotoIf("SIP/66.193.176.35-00000012", "1?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [s@macro-user-callerid:15] GotoIf("SIP/66.193.176.35-00000012", "1?continue") in new stack
-- Goto (macro-user-callerid,s,28)
-- Executing [s@macro-user-callerid:28] Set("SIP/66.193.176.35-00000012", "CALLERID(number)=13098340362") in new stack
-- Executing [s@macro-user-callerid:29] Set("SIP/66.193.176.35-00000012", "CALLERID(name)=13098340362") in new stack
-- Executing [s@macro-user-callerid:30] Set("SIP/66.193.176.35-00000012", "CDR(cnum)=13098340362") in new stack
-- Executing [s@macro-user-callerid:31] Set("SIP/66.193.176.35-00000012", "CDR(cnam)=13098340362") in new stack
-- Executing [s@macro-user-callerid:32] Set("SIP/66.193.176.35-00000012", "CHANNEL(language)=en") in new stack
-- Executing [s@macro-vm:2] Set("SIP/66.193.176.35-00000012", "VMGAIN=") in new stack
-- Executing [s@macro-vm:3] Macro("SIP/66.193.176.35-00000012", "blkvm-check,") in new stack
-- Executing [s@macro-blkvm-check:1] Set("SIP/66.193.176.35-00000012", "GOSUB_RETVAL=") in new stack
-- Executing [s@macro-blkvm-check:2] ExecIf("SIP/66.193.176.35-00000012", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
-- Executing [s@macro-blkvm-check:3] MacroExit("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [s@macro-vm:4] GotoIf("SIP/66.193.176.35-00000012", "1?vmx,1") in new stack
-- Goto (macro-vm,vmx,1)
-- Executing [vmx@macro-vm:1] Set("SIP/66.193.176.35-00000012", "MEXTEN=104") in new stack
-- Executing [vmx@macro-vm:2] Set("SIP/66.193.176.35-00000012", "MMODE=NOANSWER") in new stack
-- Executing [vmx@macro-vm:3] Set("SIP/66.193.176.35-00000012", "RETVM=") in new stack
-- Executing [vmx@macro-vm:4] Set("SIP/66.193.176.35-00000012", "MODE=unavail") in new stack
-- Executing [vmx@macro-vm:5] GotoIf("SIP/66.193.176.35-00000012", "1?chknomsg") in new stack
-- Goto (macro-vm,vmx,7)
-- Executing [vmx@macro-vm:7] GotoIf("SIP/66.193.176.35-00000012", "0?s-NOANSWER,1") in new stack
-- Executing [vmx@macro-vm:8] GotoIf("SIP/66.193.176.35-00000012", "1?notdirect") in new stack
-- Goto (macro-vm,vmx,10)
-- Executing [vmx@macro-vm:10] NoOp("SIP/66.193.176.35-00000012", "Checking if ext 104 is enabled: ") in new stack
-- Executing [vmx@macro-vm:11] GotoIf("SIP/66.193.176.35-00000012", "1?s-NOANSWER,1") in new stack
-- Goto (macro-vm,s-NOANSWER,1)
-- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/66.193.176.35-00000012", "get-vmcontext,104") in new stack
-- Executing [s@macro-get-vmcontext:1] Set("SIP/66.193.176.35-00000012", "VMCONTEXT=default") in new stack
-- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/66.193.176.35-00000012", "0?200:300") in new stack
-- Goto (macro-get-vmcontext,s,300)
-- Executing [s@macro-get-vmcontext:300] NoOp("SIP/66.193.176.35-00000012", "") in new stack
-- Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/66.193.176.35-00000012", "104@default,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 [h@from-did-direct:1] Macro(“SIP/66.193.176.35-00000012”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/66.193.176.35-00000012”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [s@macro-hangupcall:3] ExecIf(“SIP/66.193.176.35-00000012”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall: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>

swbm · July 11, 2013, 4:02pm

PS Does anyone know where I can get a cheap kitchen

swbm · July 11, 2013, 6:29pm

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.

reconwireless · July 12, 2013, 1:44pm

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