Inbound routing big error or big mistake?

Hi,
I believe FreePBX 2.5.1 (or PiaF) has a big error in the inbound routing!!

I installed a new system (second time); Asterisk 1.4 with IAX2 trunk.
There is no phone connected (only an IAX-device during tests).

I created an extension with the number 0049123456789 and a “follow me” to a mobile (special outbound route).
If I ring this number internally from the IAX-device all works as expected (no sip-phone connected! >> follow me to external >> oubound route >> the mobile is ringing).

BUT!! a ring from outside produces a completely different picture: they will get immediately the message “.ext. 0049123456789 is not available please leave a message” (if VM is activated).

And also disturbing:

Later I created an inbound route (0049987654321) and directed it to the phone directory (which means a clear and very, very simple routing!!). But in this case the routing dosn’t work (number not available), see following:

[2009-05-20 15:01:01] NOTICE[3090] chan_iax2.c: Rejected connect attempt from 217.xxx.xxx.xx, request ‘[email protected]’ does not exist

If I create an extension with a two digit number and then direct an inbound route to it the same result appears: the caller gets a carrier-network message that the number is currently not available.

If the IAX device is connected I can ring that extension (0049123456788) and the iax-device rings. If I create an inbound route it dosn’t work.

What the hell is that?
I had never before such problems, used the same trunk parameters and the same or similar routing (at least 2-5 years).

Can anybody help? Thanks in advance

Is there a precondition which has to be fullfilled from the carrier?
What I have to consider?
Should I use two digit extension and use the inbound route (which would be automatically created) OR should I use the long 0049123456789-extension (which dosn’t need a special inbound routing)?

If it is necessary to test a special configuration I will post the trace - please let me know.

Many thanks for any advice.

This certainly works, no issue so it is something on your end.

Sounds to me as if you are calling from your cell phone to test. Since it forwards back to your cell phone the carriers network ‘sees’ you as yourself and dumps to the voicemail box.

If this is not the case call traces would help us diagnose.

No, no…
called from Mobile but as well from Landline…
But in both situations the same result.

And also I can see a second call is comming in, which worked in a previous version perfectely :slight_smile:

So this is not the stumbling block.

Greetings, an thanks for your answer.

As SkykingOH said in his last statement. “call traces would help us”. So please set the verbose level to at least 3 if not 5, start capturing the data and make the call attempt. Once you have the call tract post it here for us to review otherwise we are just guessing and shooting in the dark while attempting to help you.

Hi,
sorry for the delay, some public holidays in Germany :wink:

Below you can find a trace which I hope will help you.

I created an extension 0049________11 which got an external call (0049_CALLER____).
The phone was NOT connected!

Follow me was enabled in this way:
(VmX Locator: Disabled)
(no special inbound route created)

  • Initial ring time: 1
  • ring strategy: ringallv2-prim
  • ring time : 60
  • Follow me list: 0049________11 and 99110049________78 (via outbound route)
  • Play music on hold xxxx
  • Destination if no answer: Terminate Call: Hangup !!!

After ringing the voicebox automatically appears an no Hangup!!

Hope this trace can help, if not I can create another one, please let me know in which kind of call routing.

Best regards
Jochen

Trace:

[2009-05-25 17:43:29] VERBOSE[3088] logger.c: – Accepting AUTHENTICATED call from 217.74.xxx.xxx:

requested format = alaw,

requested prefs = (alaw|g729|gsm),

actual format = alaw,

host prefs = (alaw|g729|gsm),

priority = mine

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Macro(“IAX2/bs_out_25-3033”, “exten-vm|0049________11|0049________11”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Macro(“IAX2/bs_out_25-3033”, “user-callerid”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Set(“IAX2/bs_out_25-3033”, “AMPUSER=0049_CALLER____”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] GotoIf(“IAX2/bs_out_25-3033”, “0?report”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] ExecIf(“IAX2/bs_out_25-3033”, “1|Set|REALCALLERIDNUM=0049_CALLER____”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: ExecIf

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: DEVICE/0049_CALLER____/user not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:4] Set(“IAX2/bs_out_25-3033”, “AMPUSER=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: AMPUSER//cidname not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:5] Set(“IAX2/bs_out_25-3033”, “AMPUSERCIDNAME=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:6] GotoIf(“IAX2/bs_out_25-3033”, “1?report”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-user-callerid,s,11)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:11] GotoIf(“IAX2/bs_out_25-3033”, “0?continue”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:12] Set(“IAX2/bs_out_25-3033”, “__TTL=64”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:13] GotoIf(“IAX2/bs_out_25-3033”, “1?continue”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-user-callerid,s,20)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:20] NoOp(“IAX2/bs_out_25-3033”, “Using CallerID “” <0049_CALLER____>”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Noop

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Macro

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] Set(“IAX2/bs_out_25-3033”, “RingGroupMethod=none”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] Set(“IAX2/bs_out_25-3033”, “VMBOX=0049________11”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:4] Set(“IAX2/bs_out_25-3033”, “EXTTOCALL=0049________11”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: CFU/0049________11 not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:5] Set(“IAX2/bs_out_25-3033”, “CFUEXT=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: CFB/0049________11 not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:6] Set(“IAX2/bs_out_25-3033”, “CFBEXT=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:7] Set(“IAX2/bs_out_25-3033”, “RT=45”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:8] Macro(“IAX2/bs_out_25-3033”, “record-enable|0049________11|IN”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] GotoIf(“IAX2/bs_out_25-3033”, “1?check”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-record-enable,s,4)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:4] AGI(“IAX2/bs_out_25-3033”, “recordingcheck|20090525-174329|1243266209.277”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: recordingcheck|20090525-174329|1243266209.277: Inbound recording enabled.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: recordingcheck|20090525-174329|1243266209.277: CALLFILENAME=20090525-174329-1243266209.277

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – AGI Script recordingcheck completed, returning 0

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: AGI

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:999] MixMonitor(“IAX2/bs_out_25-3033”, “20090525-174329-1243266209.277.wav||”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: MixMonitor

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Macro

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:9] Macro(“IAX2/bs_out_25-3033”, “dial|45|tr|0049________11”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] GotoIf(“IAX2/bs_out_25-3033”, “1?dial”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-dial,s,3)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] AGI(“IAX2/bs_out_25-3033”, “dialparties.agi”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi

[2009-05-25 17:43:29] VERBOSE[19832] logger.c: == Begin MixMonitor Recording IAX2/bs_out_25-3033

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: dialparties.agi: Starting New Dialparties.agi

[2009-05-25 17:43:29] VERBOSE[19834] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [2009-05-25 17:43:29] VERBOSE[19834] logger.c: Found

[2009-05-25 17:43:29] VERBOSE[19834] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [2009-05-25 17:43:29] VERBOSE[19834] logger.c: Found

[2009-05-25 17:43:29] VERBOSE[19834] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [2009-05-25 17:43:29] VERBOSE[19834] logger.c: Found

[2009-05-25 17:43:29] VERBOSE[19834] logger.c: == Manager ‘admin’ logged on from 127.0.0.1

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: dialparties.agi: Caller ID name is ‘unknown’ number is ‘0049_CALLER____’

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: dialparties.agi: Methodology of ring is ‘none’

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: Added extension 0049________11 to extension map

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: Extension 0049________11 cf is disabled

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: Extension 0049________11 do not disturb is disabled

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: dialparties.agi: Extension 0049________11 has ExtensionState: 4

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: Checking CW and CFB status for extension 0049________11

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: dbset CALLTRACE/0049________11 to 0049_CALLER____

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – dialparties.agi: Filtered ARG3: 0049________11

[2009-05-25 17:43:29] VERBOSE[19834] logger.c: == Manager ‘admin’ logged off from 127.0.0.1

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – AGI Script dialparties.agi completed, returning 0

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: AGI

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:7] Dial(“IAX2/bs_out_25-3033”, “SIP/0049________11|45|tr”) in new stack

[2009-05-25 17:43:29] WARNING[19830] app_dial.c: Unable to create channel of type ‘SIP’ (cause 3 - No route to destination)

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: == Everyone is busy/congested at this time (1:0/0/1)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Dial

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:8] Set(“IAX2/bs_out_25-3033”, “DIALSTATUS=CHANUNAVAIL”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:9] GosubIf(“IAX2/bs_out_25-3033”, “0?CHANUNAVAIL|1”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GosubIf

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Macro

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:10] GotoIf(“IAX2/bs_out_25-3033”, “0?exit|return”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:11] Set(“IAX2/bs_out_25-3033”, “SV_DIALSTATUS=CHANUNAVAIL”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:12] GosubIf(“IAX2/bs_out_25-3033”, “0?docfu|1”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GosubIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:13] GosubIf(“IAX2/bs_out_25-3033”, “0?docfb|1”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GosubIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:14] Set(“IAX2/bs_out_25-3033”, “DIALSTATUS=CHANUNAVAIL”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:15] NoOp(“IAX2/bs_out_25-3033”, “Voicemail is 0049________11”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: NoOp

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:16] GotoIf(“IAX2/bs_out_25-3033”, “0?s-CHANUNAVAIL|1”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:17] NoOp(“IAX2/bs_out_25-3033”, “Sending to Voicemail box 0049________11”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: NoOp

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:18] Macro(“IAX2/bs_out_25-3033”, “vm|0049________11|CHANUNAVAIL|”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Macro(“IAX2/bs_out_25-3033”, “user-callerid|SKIPTTL”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Set(“IAX2/bs_out_25-3033”, “AMPUSER=0049_CALLER____”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] GotoIf(“IAX2/bs_out_25-3033”, “0?report”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] ExecIf(“IAX2/bs_out_25-3033”, “0|Set|REALCALLERIDNUM=0049_CALLER____”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: ExecIf

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: DEVICE/0049_CALLER____/user not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:4] Set(“IAX2/bs_out_25-3033”, “AMPUSER=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] DEBUG[19830] func_db.c: DB: AMPUSER//cidname not found in database.

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:5] Set(“IAX2/bs_out_25-3033”, “AMPUSERCIDNAME=”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:6] GotoIf(“IAX2/bs_out_25-3033”, “1?report”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-user-callerid,s,11)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:11] GotoIf(“IAX2/bs_out_25-3033”, “1?continue”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-user-callerid,s,20)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:20] NoOp(“IAX2/bs_out_25-3033”, “Using CallerID “” <0049_CALLER____>”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Noop

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Macro

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] Set(“IAX2/bs_out_25-3033”, “VMGAIN=”"") in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] WARNING[19830] func_db.c: DB requires an argument, DB(/)

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] GotoIf(“IAX2/bs_out_25-3033”, “1?vmx|1”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-vm,vmx,1)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] GotoIf(“IAX2/bs_out_25-3033”, “0?s-CHANUNAVAIL|1”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] Set(“IAX2/bs_out_25-3033”, “MODE=unavail”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:3] GotoIf(“IAX2/bs_out_25-3033”, “1?notdirect”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-vm,vmx,5)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:5] NoOp(“IAX2/bs_out_25-3033”, “Checking if ext 0049________11 is enabled: blocked”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Noop

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:6] GotoIf(“IAX2/bs_out_25-3033”, “1?s-CHANUNAVAIL|1”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-vm,s-CHANUNAVAIL,1)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Macro(“IAX2/bs_out_25-3033”, “get-vmcontext|0049________11”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:1] Set(“IAX2/bs_out_25-3033”, “VMCONTEXT=default”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Set

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] GotoIf(“IAX2/bs_out_25-3033”, “0?200:300”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Goto (macro-get-vmcontext,s,300)

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: GotoIf

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:300] NoOp(“IAX2/bs_out_25-3033”, “”) in new stack

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: NoOp

[2009-05-25 17:43:29] DEBUG[19830] app_macro.c: Executed application: Macro

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – Executing [[email protected]:2] VoiceMail(“IAX2/bs_out_25-3033”, “[email protected]|u”) in new stack

[2009-05-25 17:43:29] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘vm-theperson’ (language ‘en’)

[2009-05-25 17:43:31] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/0’ (language ‘en’)

[2009-05-25 17:43:31] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/0’ (language ‘en’)

[2009-05-25 17:43:32] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/4’ (language ‘en’)

[2009-05-25 17:43:33] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/9’ (language ‘en’)

[2009-05-25 17:43:34] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/3’ (language ‘en’)

[2009-05-25 17:43:34] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/0’ (language ‘en’)

[2009-05-25 17:43:35] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:36] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:36] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:37] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:38] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:38] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/x’ (language ‘en’)

[2009-05-25 17:43:39] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/1’ (language ‘en’)

[2009-05-25 17:43:40] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘digits/1’ (language ‘en’)

[2009-05-25 17:43:41] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘vm-isunavail’ (language ‘en’)

[2009-05-25 17:43:42] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘vm-intro’ (language ‘en’)

[2009-05-25 17:43:47] VERBOSE[19830] logger.c: – <IAX2/bs_out_25-3033> Playing ‘beep’ (language ‘en’)

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – Recording the message

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – x=0, open writing: /var/spool/asterisk/voicemail/default/0049________11/tmp/2PO58N format: wav49, 0x901ac28

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – x=1, open writing: /var/spool/asterisk/voicemail/default/0049________11/tmp/2PO58N format: wav, 0x90a1a98

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – User hung up

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – Recording was 0 seconds long but needs to be at least 3 - abandoning

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘IAX2/bs_out_25-3033’ in macro ‘vm’

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘IAX2/bs_out_25-3033’ in macro ‘exten-vm’

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘IAX2/bs_out_25-3033’

[2009-05-25 17:43:48] VERBOSE[19830] logger.c: – Hungup ‘IAX2/bs_out_25-3033’

fyi - it’s usually a better idea to print out a CLI trace first, they are more readable and the full log + debug traces are only needed if one needs to dig deeper.