Can't answer ringing phone Call does not go to voicemail

I have setup 3 Asterisk/FreePBX boxes,

All are using:

Ubuntu Server 9.10
Asterisk 1.6current
Asterisk addons 1.6current
Dahdi 2.2current
Dahdi tools 2.2current
FreePBX 2.60RC2

The 1st 2 boxes work perfectly

The 3rd one on an HP with a 2ghz Celeron and 2g RAM is giving me fits.

If you call it:

  • the call rings the extension
  • If the user picks up the handset they get dead air and the caller continues to hear ringing
  • The caller never gets prompted by voice mail and it rings indefinitely
  • The extension then shows that it has a voicemail waiting
  • If you check voicemail it tells you there is a message but when you play it, it’s dead air

The only clues I have to debug with are:

  • This message when I log into call recordings for the extension that shows it has a voice mail

Voicemail recording(s) was not found.
On settings page, change voicemail audio format. It is currently set to .wav

  • And the following trace/debug

    – Goto (from-trunk,17772789640,1)
    – Executing [17772789640@from-trunk:1] Set(“SIP/66.193.176.35-00000028”, “__FROM_DID=17772789640”) in new stack
    – Executing [17772789640@from-trunk:2] Gosub(“SIP/66.193.176.35-00000028”, “app-blacklist-check,s,1”) in new stack
    – Executing [s@app-blacklist-check:1] GotoIf(“SIP/66.193.176.35-00000028”, “0?blacklisted”) in new stack
    – Executing [s@app-blacklist-check:2] Set(“SIP/66.193.176.35-00000028”, “CALLED_BLACKLIST=1”) in new stack
    – Executing [s@app-blacklist-check:3] Return(“SIP/66.193.176.35-00000028”, “”) in new stack
    – Executing [17772789640@from-trunk:3] ExecIf(“SIP/66.193.176.35-00000028”, “0 ?Set(CALLERID(name)=15132764830)”) in new stack
    – Executing [17772789640@from-trunk:4] Set(“SIP/66.193.176.35-00000028”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
    – Executing [17772789640@from-trunk:5] Set(“SIP/66.193.176.35-00000028”, “CALLERPRES()=allowed_not_screened”) in new stack
    – Executing [17772789640@from-trunk:6] Goto(“SIP/66.193.176.35-00000028”, “custom-incoming,s,1”) in new stack
    – Goto (custom-incoming,s,1)
    – Executing [s@custom-incoming:1] Set(“SIP/66.193.176.35-00000028”, “Var_FROM_DOMAIN=ss.callcentric.com”) in new stack
    – Executing [s@custom-incoming:2] GotoIf(“SIP/66.193.176.35-00000028”, “0?5:3”) in new stack
    – Goto (custom-incoming,s,3)
    – Executing [s@custom-incoming:3] GotoIf(“SIP/66.193.176.35-00000028”, “1?5:4”) in new stack
    – Goto (custom-incoming,s,5)
    – Executing [s@custom-incoming:5] Set(“SIP/66.193.176.35-00000028”, “Var_TO_DID=18595780720”) in new stack
    – Executing [s@custom-incoming:6] GotoIf(“SIP/66.193.176.35-00000028”, “1?ext-did,18595780720,1:7”) in new stack
    – Goto (ext-did,18595780720,1)
    – Executing [18595780720@ext-did:1] Set(“SIP/66.193.176.35-00000028”, “__FROM_DID=18595780720”) in new stack
    – Executing [18595780720@ext-did:2] Gosub(“SIP/66.193.176.35-00000028”, “app-blacklist-check,s,1”) in new stack
    – Executing [s@app-blacklist-check:1] GotoIf(“SIP/66.193.176.35-00000028”, “0?blacklisted”) in new stack
    – Executing [s@app-blacklist-check:2] Set(“SIP/66.193.176.35-00000028”, “CALLED_BLACKLIST=1”) in new stack
    – Executing [s@app-blacklist-check:3] Return(“SIP/66.193.176.35-00000028”, “”) in new stack
    – Executing [18595780720@ext-did:3] ExecIf(“SIP/66.193.176.35-00000028”, “0 ?Set(CALLERID(name)=15132764830)”) in new stack
    – Executing [18595780720@ext-did:4] Set(“SIP/66.193.176.35-00000028”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
    – Executing [18595780720@ext-did:5] Set(“SIP/66.193.176.35-00000028”, “CALLERPRES()=allowed_not_screened”) in new stack
    – Executing [18595780720@ext-did:6] Goto(“SIP/66.193.176.35-00000028”, “from-did-direct,6005,1”) in new stack
    – Goto (from-did-direct,6005,1)
    – Executing [6005@from-did-direct:1] Macro(“SIP/66.193.176.35-00000028”, “exten-vm,6005,6005”) in new stack
    – Executing [s@macro-exten-vm:1] Macro(“SIP/66.193.176.35-00000028”, “user-callerid”) in new stack
    – Executing [s@macro-user-callerid:1] Set(“SIP/66.193.176.35-00000028”, “AMPUSER=15132764830”) in new stack
    – Executing [s@macro-user-callerid:2] GotoIf(“SIP/66.193.176.35-00000028”, “0?report”) in new stack
    – Executing [s@macro-user-callerid:3] ExecIf(“SIP/66.193.176.35-00000028”, “1?Set(REALCALLERIDNUM=15132764830)”) in new stack
    – Executing [s@macro-user-callerid:4] Set(“SIP/66.193.176.35-00000028”, “AMPUSER=”) in new stack
    – Executing [s@macro-user-callerid:5] Set(“SIP/66.193.176.35-00000028”, “AMPUSERCIDNAME=”) in new stack
    – Executing [s@macro-user-callerid:6] GotoIf(“SIP/66.193.176.35-00000028”, “1?report”) in new stack
    – Goto (macro-user-callerid,s,10)
    – Executing [s@macro-user-callerid:10] GotoIf(“SIP/66.193.176.35-00000028”, “0?continue”) in new stack
    – Executing [s@macro-user-callerid:11] Set(“SIP/66.193.176.35-00000028”, “__TTL=64”) in new stack
    – Executing [s@macro-user-callerid:12] GotoIf(“SIP/66.193.176.35-00000028”, “1?continue”) in new stack
    – Goto (macro-user-callerid,s,19)
    – Executing [s@macro-user-callerid:19] NoOp(“SIP/66.193.176.35-00000028”, “Using CallerID “PLMS” <15132764830>”) in new stack
    – Executing [s@macro-exten-vm:2] Set(“SIP/66.193.176.35-00000028”, “RingGroupMethod=none”) in new stack
    – Executing [s@macro-exten-vm:3] Set(“SIP/66.193.176.35-00000028”, “VMBOX=6005”) in new stack
    – Executing [s@macro-exten-vm:4] Set(“SIP/66.193.176.35-00000028”, “EXTTOCALL=6005”) in new stack
    – Executing [s@macro-exten-vm:5] Set(“SIP/66.193.176.35-00000028”, “CFUEXT=”) in new stack
    – Executing [s@macro-exten-vm:6] Set(“SIP/66.193.176.35-00000028”, “CFBEXT=”) in new stack
    – Executing [s@macro-exten-vm:7] Set(“SIP/66.193.176.35-00000028”, “RT=23”) in new stack
    – Executing [s@macro-exten-vm:8] Macro(“SIP/66.193.176.35-00000028”, “record-enable,6005,IN”) in new stack
    – Executing [s@macro-record-enable:1] GotoIf(“SIP/66.193.176.35-00000028”, “1?check”) in new stack
    – Goto (macro-record-enable,s,4)
    – Executing [s@macro-record-enable:4] AGI(“SIP/66.193.176.35-00000028”, “recordingcheck,20100101-175349,1262386429.40”) in new stack
    – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
    recordingcheck,20100101-175349,1262386429.40: Inbound recording not enabled
    – <SIP/66.193.176.35-00000028>AGI Script recordingcheck completed, returning 0
    – Executing [s@macro-record-enable:5] MacroExit(“SIP/66.193.176.35-00000028”, “”) in new stack
    – Executing [s@macro-exten-vm:9] Macro(“SIP/66.193.176.35-00000028”, “dial,23,tr,6005”) in new stack
    – Executing [s@macro-dial:1] GotoIf(“SIP/66.193.176.35-00000028”, “1?dial”) in new stack
    – Goto (macro-dial,s,3)
    – Executing [s@macro-dial:3] AGI(“SIP/66.193.176.35-00000028”, “dialparties.agi”) in new stack
    – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
    dialparties.agi: Starting New Dialparties.agi
    dialparties.agi: Caller ID name is ‘PLMS’ number is ‘15132764830’
    > dialparties.agi: USE_CONFIRMATION: ‘FALSE’
    > dialparties.agi: RINGGROUP_INDEX: ''
    dialparties.agi: Methodology of ring is ‘none’
    – dialparties.agi: Added extension 6005 to extension map
    > dialparties.agi: Extension 6005 has call screening off
    – dialparties.agi: Extension 6005 cf is disabled
    – dialparties.agi: Extension 6005 do not disturb is disabled
    > dialparties.agi: extnum 6005 has: cw: 0; hascfb: 0 [] hascfu: 0 []
    dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
    dialparties.agi: Extension 6005 has ExtensionState: 0
    – dialparties.agi: Checking CW and CFB status for extension 6005
    – dialparties.agi: dbset CALLTRACE/6005 to 15132764830
    – dialparties.agi: Filtered ARG3: 6005
    – <SIP/66.193.176.35-00000028>AGI Script dialparties.agi completed, returning 0
    – Executing [s@macro-dial:7] Dial(“SIP/66.193.176.35-00000028”, “SIP/6005,23,tr”) in new stack
    == Using SIP RTP TOS bits 184
    == Using SIP RTP CoS mark 5
    == Using SIP VRTP TOS bits 136
    == Using SIP VRTP CoS mark 6
    – Called 6005
    – SIP/6005-00000029 is ringing
    – Nobody picked up in 23000 ms
    – Executing [s@macro-dial:8] Set(“SIP/66.193.176.35-00000028”, “DIALSTATUS=NOANSWER”) in new stack
    – Executing [s@macro-dial:9] GosubIf(“SIP/66.193.176.35-00000028”, “0?NOANSWER,1”) in new stack
    – Executing [s@macro-exten-vm:10] GotoIf(“SIP/66.193.176.35-00000028”, “0?exit,return”) in new stack
    – Executing [s@macro-exten-vm:11] Set(“SIP/66.193.176.35-00000028”, “SV_DIALSTATUS=NOANSWER”) in new stack
    – Executing [s@macro-exten-vm:12] GosubIf(“SIP/66.193.176.35-00000028”, “0?docfu,1”) in new stack
    – Executing [s@macro-exten-vm:13] GosubIf(“SIP/66.193.176.35-00000028”, “0?docfb,1”) in new stack
    – Executing [s@macro-exten-vm:14] Set(“SIP/66.193.176.35-00000028”, “DIALSTATUS=NOANSWER”) in new stack
    – Executing [s@macro-exten-vm:15] NoOp(“SIP/66.193.176.35-00000028”, “Voicemail is ‘6005’”) in new stack
    – Executing [s@macro-exten-vm:16] GotoIf(“SIP/66.193.176.35-00000028”, “0?s-NOANSWER,1”) in new stack
    – Executing [s@macro-exten-vm:17] NoOp(“SIP/66.193.176.35-00000028”, “Sending to Voicemail box 6005”) in new stack
    – Executing [s@macro-exten-vm:18] Macro(“SIP/66.193.176.35-00000028”, “vm,6005,NOANSWER,”) in new stack
    – Executing [s@macro-vm:1] Macro(“SIP/66.193.176.35-00000028”, “user-callerid,SKIPTTL”) in new stack
    – Executing [s@macro-user-callerid:1] Set(“SIP/66.193.176.35-00000028”, “AMPUSER=15132764830”) in new stack
    – Executing [s@macro-user-callerid:2] GotoIf(“SIP/66.193.176.35-00000028”, “0?report”) in new stack
    – Executing [s@macro-user-callerid:3] ExecIf(“SIP/66.193.176.35-00000028”, “0?Set(REALCALLERIDNUM=15132764830)”) in new stack
    – Executing [s@macro-user-callerid:4] Set(“SIP/66.193.176.35-00000028”, “AMPUSER=”) in new stack
    – Executing [s@macro-user-callerid:5] Set(“SIP/66.193.176.35-00000028”, “AMPUSERCIDNAME=”) in new stack
    – Executing [s@macro-user-callerid:6] GotoIf(“SIP/66.193.176.35-00000028”, “1?report”) in new stack
    – Goto (macro-user-callerid,s,10)
    – Executing [s@macro-user-callerid:10] GotoIf(“SIP/66.193.176.35-00000028”, “1?continue”) in new stack
    – Goto (macro-user-callerid,s,19)
    – Executing [s@macro-user-callerid:19] NoOp(“SIP/66.193.176.35-00000028”, “Using CallerID “PLMS” <15132764830>”) in new stack
    – Executing [s@macro-vm:2] Set(“SIP/66.193.176.35-00000028”, “VMGAIN=”"") in new stack
    – Executing [s@macro-vm:3] GotoIf(“SIP/66.193.176.35-00000028”, “1?vmx,1”) in new stack
    – Goto (macro-vm,vmx,1)
    – Executing [vmx@macro-vm:1] Set(“SIP/66.193.176.35-00000028”, “MEXTEN=6005”) in new stack
    – Executing [vmx@macro-vm:2] Set(“SIP/66.193.176.35-00000028”, “MMODE=NOANSWER”) in new stack
    – Executing [vmx@macro-vm:3] Set(“SIP/66.193.176.35-00000028”, “RETVM=”) in new stack
    – Executing [vmx@macro-vm:4] Set(“SIP/66.193.176.35-00000028”, “MODE=unavail”) in new stack
    – Executing [vmx@macro-vm:5] GotoIf(“SIP/66.193.176.35-00000028”, “1?chknomsg”) in new stack
    – Goto (macro-vm,vmx,7)
    – Executing [vmx@macro-vm:7] GotoIf(“SIP/66.193.176.35-00000028”, “0?s-NOANSWER,1”) in new stack
    – Executing [vmx@macro-vm:8] GotoIf(“SIP/66.193.176.35-00000028”, “1?notdirect”) in new stack
    – Goto (macro-vm,vmx,10)
    – Executing [vmx@macro-vm:10] NoOp(“SIP/66.193.176.35-00000028”, “Checking if ext 6005 is enabled: “) in new stack
    – Executing [vmx@macro-vm:11] GotoIf(“SIP/66.193.176.35-00000028”, “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-00000028”, “get-vmcontext,6005”) in new stack
    – Executing [s@macro-get-vmcontext:1] Set(“SIP/66.193.176.35-00000028”, “VMCONTEXT=default”) in new stack
    – Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/66.193.176.35-00000028”, “0?200:300”) in new stack
    – Goto (macro-get-vmcontext,s,300)
    – Executing [s@macro-get-vmcontext:300] NoOp(“SIP/66.193.176.35-00000028”, “”) in new stack
    – Executing [s-NOANSWER@macro-vm:2] VoiceMail(“SIP/66.193.176.35-00000028”, “6005@default,u”””) in new stack
    – <SIP/66.193.176.35-00000028> Playing ‘/var/spool/asterisk/voicemail/default/6005/unavail.gsm’ (language ‘en’)
    – <SIP/66.193.176.35-00000028> Playing ‘vm-intro.gsm’ (language ‘en’)
    – <SIP/66.193.176.35-00000028> Playing ‘beep.gsm’ (language ‘en’)
    – Recording the message
    – x=0, open writing: /var/spool/asterisk/voicemail/default/6005/tmp/d2Z6zx format: wav49, 0xa376020
    – x=1, open writing: /var/spool/asterisk/voicemail/default/6005/tmp/d2Z6zx format: gsm, 0xa39f018
    – User hung up
    == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘SIP/66.193.176.35-00000028’ in macro ‘vm’
    == Spawn extension (macro-exten-vm, s, 18) exited non-zero on ‘SIP/66.193.176.35-00000028’ in macro ‘exten-vm’
    == Spawn extension (from-did-direct, 6005, 1) exited non-zero on ‘SIP/66.193.176.35-00000028’


Anybody ever seen this before or see something in the log that says what is wrong?

17772789640 is from the trunk? Is it a Dadhi trunk? Have you checked /var/log/asterisk/full for clues? It is the Asterisk log file (text file).

I noticed that there is a little bit of blacklisting going on. I wonder if it is blacklisting your calls.

Also “recordingcheck,20100101-175349,1262386429.40: Inbound recording not enabled”

and

“dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 6005 has ExtensionState: 0”

Don’t know if the last one is normal state.

  • I am not using Dahdi it’s all SIP
  • Black list module is installed but I’m not blacklisting any numbers
  • I am not recording incoming or outgoing calls on 6005 so that’s correct
  • I don’t know what the "Extension_State: o means either but all of this works if I dial between extensions so I doubt the extension is disabled in any way

I am thinking it is a permissions or file/folder location issue but I’ve checked and double checked everything against the 2 working systems. I also checked Apache2 and PHP5 for problems.

Then I did a reinstall and restored FreePBX conf from a working box.

I am stumped.

Thanks again for your input.

The confusing part about your post, in trying to help, is if the problem is between the 3 PBXs or is the problem with just the HP server and its extensions.

Sorry about the confusion.

I have built 3 systems that are not connected or integrated in any way.

The 1st was built on a fit-pc with atom 533 and the 2nd was built on an intel itx board kit with atom 330, dual core, They both worked perfectly.

So,…I decided to move my home system which was running under Centos 5.4 and Asterisk 1.4 to Ubuntu 9.10 with Asterisk 1.6. This is the HP, Celeron desktop.

That system is the one that has the “Issue” and it’s not connected to either of the other 2.

Based on the symptoms it appears that there is a communication problem between the caller and PBX/phone - SIP Invites are delivered, but RTPs are not. This maybe caused by NAT device not passing the RTP packets. Try activating SIP debug (CLI command “sip debug”). This should help you to confirm (or eliminate) NAT as a cause of the problem.

On that one machine I forgot to turn off Ubuntu UFW (firewall).

I don’t know how I got so clueless over that but lgor’s comments made it all click.