I'm sorry, an error has occurred - voice mail - new install

rmalerman · March 5, 2009, 7:07pm

When ever voicemail should be picking up, a message is played: “I’m sorry, an error has occurred” instead of voice mail picking up. It happens on all extensions, even after reset.

CentOS 5.2
Kernel version 2.6.18-92.1.18.el5 (SMP)
Free PBX

Can anyone point me in the right direction?

fskrotzki · March 5, 2009, 7:12pm

please provide the following information:

version of FreePBX, Version of Asterisk, this a distro build or hand build?

Lastly a call trace showing the problem.

It sounds like a permissions problem but it’s hard to tell with what you have provided.

rmalerman · March 5, 2009, 7:32pm

Thank you for the quick response!
FreePBX 2.5.1
Trixbox CE distro
I’m not sure how to check the asterisk version, but here’s the log file:

[Mar 5 14:26:42] VERBOSE[4199] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 14:26:42] VERBOSE[4199] logger.c: Found
[Mar 5 14:26:42] VERBOSE[4199] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 14:26:42] VERBOSE[4199] logger.c: Found
[Mar 5 14:26:42] VERBOSE[4199] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 14:26:42] VERBOSE[4199] logger.c: Found
[Mar 5 14:26:42] VERBOSE[4199] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 14:26:42] VERBOSE[4199] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 14:26:56] VERBOSE[4203] logger.c: – Executing [11@from-internal:1] ResetCDR(“SIP/503-08e76d68”, “”) in new stack
[Mar 5 14:26:56] VERBOSE[4203] logger.c: – Executing [11@from-internal:2] NoCDR(“SIP/503-08e76d68”, “”) in new stack
[Mar 5 14:26:56] VERBOSE[4203] logger.c: – Executing [11@from-internal:3] Wait(“SIP/503-08e76d68”, “1”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: == Spawn extension (from-internal, 11, 3) exited non-zero on ‘SIP/503-08e76d68’
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [h@from-internal:1] Macro(“SIP/503-08e76d68”, “hangupcall”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/503-08e76d68”, “w”) in new stack
[Mar 5 14:26:57] DEBUG[4203] app_macro.c: Executed application: ResetCDR
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“SIP/503-08e76d68”, “”) in new stack
[Mar 5 14:26:57] DEBUG[4203] app_macro.c: Executed application: NoCDR
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“SIP/503-08e76d68”, “1?skiprg”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Goto (macro-hangupcall,s,6)
[Mar 5 14:26:57] DEBUG[4203] app_macro.c: Executed application: GotoIf
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“SIP/503-08e76d68”, “1?skipblkvm”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Goto (macro-hangupcall,s,9)
[Mar 5 14:26:57] DEBUG[4203] app_macro.c: Executed application: GotoIf
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“SIP/503-08e76d68”, “1?theend”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Goto (macro-hangupcall,s,11)
[Mar 5 14:26:57] DEBUG[4203] app_macro.c: Executed application: GotoIf
[Mar 5 14:26:57] VERBOSE[4203] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“SIP/503-08e76d68”, “”) in new stack
[Mar 5 14:26:57] VERBOSE[4203] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/503-08e76d68’ in macro ‘hangupcall’
[Mar 5 14:26:57] VERBOSE[4203] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/503-08e76d68’
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [500@from-internal:1] Macro(“SIP/503-08e76d68”, “exten-vm|500|500”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/503-08e76d68”, “user-callerid”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/503-08e76d68”, “AMPUSER=503”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/503-08e76d68”, “0?report”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/503-08e76d68”, “1|Set|REALCALLERIDNUM=503”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: ExecIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/503-08e76d68”, “AMPUSER=503”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/503-08e76d68”, “AMPUSERCIDNAME=Office”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/503-08e76d68”, “0?report”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/503-08e76d68”, “AMPUSERCID=503”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/503-08e76d68”, “CALLERID(all)=“Office” <503>”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/503-08e76d68”, “REALCALLERIDNUM=503”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/503-08e76d68”, “0|Set|CHANNEL(language)=”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: ExecIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/503-08e76d68”, “0?continue”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:12] Set(“SIP/503-08e76d68”, “__TTL=64”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/503-08e76d68”, “1?continue”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Goto (macro-user-callerid,s,20)
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/503-08e76d68”, “Using CallerID “Office” <503>”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Noop
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Macro
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:2] Set(“SIP/503-08e76d68”, “RingGroupMethod=none”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:3] Set(“SIP/503-08e76d68”, “VMBOX=500”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:4] Set(“SIP/503-08e76d68”, “EXTTOCALL=500”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] DEBUG[4207] func_db.c: DB: CFU/500 not found in database.
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:5] Set(“SIP/503-08e76d68”, “CFUEXT=”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] DEBUG[4207] func_db.c: DB: CFB/500 not found in database.
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:6] Set(“SIP/503-08e76d68”, “CFBEXT=”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:7] Set(“SIP/503-08e76d68”, “RT=15”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Set
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:8] Macro(“SIP/503-08e76d68”, “record-enable|500|IN”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/503-08e76d68”, “1?check”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Goto (macro-record-enable,s,4)
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/503-08e76d68”, “recordingcheck|20090305-142703|1236281223.11”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 5 14:27:03] VERBOSE[4207] logger.c: recordingcheck|20090305-142703|1236281223.11: Inbound recording not enabled
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – AGI Script recordingcheck completed, returning 0
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: AGI
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“SIP/503-08e76d68”, “”) in new stack
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: Macro
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-exten-vm:9] Macro(“SIP/503-08e76d68”, “dial|15|tr|500”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-dial:1] GotoIf(“SIP/503-08e76d68”, “1?dial”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Goto (macro-dial,s,3)
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: GotoIf
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-dial:3] AGI(“SIP/503-08e76d68”, “dialparties.agi”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Mar 5 14:27:03] VERBOSE[4207] logger.c: dialparties.agi: Starting New Dialparties.agi
[Mar 5 14:27:03] VERBOSE[4210] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 14:27:03] VERBOSE[4210] logger.c: Found
[Mar 5 14:27:03] VERBOSE[4210] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 14:27:03] VERBOSE[4210] logger.c: Found
[Mar 5 14:27:03] VERBOSE[4210] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 14:27:03] VERBOSE[4210] logger.c: Found
[Mar 5 14:27:03] VERBOSE[4210] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 14:27:03] VERBOSE[4207] logger.c: dialparties.agi: Caller ID name is ‘Office’ number is ‘503’
[Mar 5 14:27:03] VERBOSE[4207] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – dialparties.agi: Added extension 500 to extension map
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – dialparties.agi: Extension 500 cf is disabled
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – dialparties.agi: Extension 500 do not disturb is disabled
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – dialparties.agi: dbset CALLTRACE/500 to 503
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – dialparties.agi: Filtered ARG3: 500
[Mar 5 14:27:03] VERBOSE[4210] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – AGI Script dialparties.agi completed, returning 0
[Mar 5 14:27:03] DEBUG[4207] app_macro.c: Executed application: AGI
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Executing [s@macro-dial:7] Dial(“SIP/503-08e76d68”, “SIP/500|15|tr”) in new stack
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – Called 500
[Mar 5 14:27:03] VERBOSE[4207] logger.c: – SIP/500-08f1e140 is ringing
[Mar 5 14:27:18] VERBOSE[4207] logger.c: – Nobody picked up in 15000 ms
[Mar 5 14:27:18] DEBUG[4207] app_macro.c: Executed application: Dial
[Mar 5 14:27:18] VERBOSE[4207] logger.c: – Executing [s@macro-dial:8] Set(“SIP/503-08e76d68”, “DIALSTATUS=NOANSWER”) in new stack

fskrotzki · March 5, 2009, 8:31pm

I trimmed your post as we didn’t need the top 3/4 of it. It also looks like you didn’t get the very end of it either as the last line is where it is about to dial the extension.

you can get the asterisk version by typing asterisk -r at the linux command line and it will show it when it opens the connection to asterisk. It looks like a 1.4.x version.

A more complete trace to the end (basically the next 50 lines or so) would help. But first at the linus prompt type “amportal chown” without the quotes and see if that solves the problem.

rmalerman · March 5, 2009, 11:37pm

I tried the amportal chown but it did not help. I noticed in the log dump recording is not enabled, if that is significant.

Here’s the latest dump. Thanks again!

[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [500@from-internal:1] Macro(“SIP/503-08f1a1c8”, “exten-vm|500|500”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/503-08f1a1c8”, “user-callerid”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/503-08f1a1c8”, “AMPUSER=503”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/503-08f1a1c8”, “0?report”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/503-08f1a1c8”, “1|Set|REALCALLERIDNUM=503”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: ExecIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/503-08f1a1c8”, “AMPUSER=503”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/503-08f1a1c8”, “AMPUSERCIDNAME=Office”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/503-08f1a1c8”, “0?report”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/503-08f1a1c8”, “AMPUSERCID=503”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/503-08f1a1c8”, “CALLERID(all)=“Office” <503>”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/503-08f1a1c8”, “REALCALLERIDNUM=503”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/503-08f1a1c8”, “0|Set|CHANNEL(language)=”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: ExecIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/503-08f1a1c8”, “0?continue”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:12] Set(“SIP/503-08f1a1c8”, “__TTL=64”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/503-08f1a1c8”, “1?continue”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Goto (macro-user-callerid,s,20)
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/503-08f1a1c8”, “Using CallerID “Office” <503>”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Noop
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Macro
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:2] Set(“SIP/503-08f1a1c8”, “RingGroupMethod=none”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:3] Set(“SIP/503-08f1a1c8”, “VMBOX=500”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:4] Set(“SIP/503-08f1a1c8”, “EXTTOCALL=500”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] DEBUG[5159] func_db.c: DB: CFU/500 not found in database.
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:5] Set(“SIP/503-08f1a1c8”, “CFUEXT=”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] DEBUG[5159] func_db.c: DB: CFB/500 not found in database.
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:6] Set(“SIP/503-08f1a1c8”, “CFBEXT=”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:7] Set(“SIP/503-08f1a1c8”, “RT=15”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:8] Macro(“SIP/503-08f1a1c8”, “record-enable|500|IN”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/503-08f1a1c8”, “1?check”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Goto (macro-record-enable,s,4)
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/503-08f1a1c8”, “recordingcheck|20090305-172209|1236291729.13”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 5 17:22:09] VERBOSE[5159] logger.c: recordingcheck|20090305-172209|1236291729.13: Inbound recording not enabled
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – AGI Script recordingcheck completed, returning 0
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: AGI
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“SIP/503-08f1a1c8”, “”) in new stack
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: Macro
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:9] Macro(“SIP/503-08f1a1c8”, “dial|15|tr|500”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-dial:1] GotoIf(“SIP/503-08f1a1c8”, “1?dial”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Goto (macro-dial,s,3)
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-dial:3] AGI(“SIP/503-08f1a1c8”, “dialparties.agi”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Mar 5 17:22:09] VERBOSE[5159] logger.c: dialparties.agi: Starting New Dialparties.agi
[Mar 5 17:22:09] VERBOSE[5162] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:22:09] VERBOSE[5162] logger.c: Found
[Mar 5 17:22:09] VERBOSE[5162] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:22:09] VERBOSE[5162] logger.c: Found
[Mar 5 17:22:09] VERBOSE[5162] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:22:09] VERBOSE[5162] logger.c: Found
[Mar 5 17:22:09] VERBOSE[5162] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:22:09] VERBOSE[5159] logger.c: dialparties.agi: Caller ID name is ‘Office’ number is ‘503’
[Mar 5 17:22:09] VERBOSE[5159] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – dialparties.agi: Added extension 500 to extension map
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – dialparties.agi: Extension 500 cf is disabled
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – dialparties.agi: Extension 500 do not disturb is disabled
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – dialparties.agi: dbset CALLTRACE/500 to 503
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – dialparties.agi: Filtered ARG3: 500
[Mar 5 17:22:09] VERBOSE[5162] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – AGI Script dialparties.agi completed, returning 0
[Mar 5 17:22:09] DEBUG[5159] app_macro.c: Executed application: AGI
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Executing [s@macro-dial:7] Dial(“SIP/503-08f1a1c8”, “SIP/500|15|tr”) in new stack
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – Called 500
[Mar 5 17:22:09] VERBOSE[5159] logger.c: – SIP/500-08f1e140 is ringing
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Nobody picked up in 15000 ms
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Dial
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-dial:8] Set(“SIP/503-08f1a1c8”, “DIALSTATUS=NOANSWER”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-dial:9] GosubIf(“SIP/503-08f1a1c8”, “0?NOANSWER|1”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GosubIf
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Macro
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:10] GotoIf(“SIP/503-08f1a1c8”, “0?exit|return”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:11] Set(“SIP/503-08f1a1c8”, “SV_DIALSTATUS=NOANSWER”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:12] GosubIf(“SIP/503-08f1a1c8”, “0?docfu|1”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GosubIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:13] GosubIf(“SIP/503-08f1a1c8”, “0?docfb|1”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GosubIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:14] Set(“SIP/503-08f1a1c8”, “DIALSTATUS=NOANSWER”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:15] NoOp(“SIP/503-08f1a1c8”, “Voicemail is 500”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: NoOp
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:16] GotoIf(“SIP/503-08f1a1c8”, “0?s-NOANSWER|1”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:17] NoOp(“SIP/503-08f1a1c8”, “Sending to Voicemail box 500”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: NoOp
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-exten-vm:18] Macro(“SIP/503-08f1a1c8”, “vm|500|NOANSWER|”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-vm:1] Macro(“SIP/503-08f1a1c8”, “user-callerid|SKIPTTL”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/503-08f1a1c8”, “AMPUSER=503”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/503-08f1a1c8”, “0?report”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/503-08f1a1c8”, “0|Set|REALCALLERIDNUM=503”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: ExecIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/503-08f1a1c8”, “AMPUSER=503”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/503-08f1a1c8”, “AMPUSERCIDNAME=Office”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/503-08f1a1c8”, “0?report”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/503-08f1a1c8”, “AMPUSERCID=503”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/503-08f1a1c8”, “CALLERID(all)=“Office” <503>”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/503-08f1a1c8”, “REALCALLERIDNUM=503”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/503-08f1a1c8”, “0|Set|CHANNEL(language)=”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: ExecIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/503-08f1a1c8”, “1?continue”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-user-callerid,s,20)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/503-08f1a1c8”, “Using CallerID “Office” <503>”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Noop
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Macro
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-vm:2] Set(“SIP/503-08f1a1c8”, “VMGAIN=”"") in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] WARNING[5159] func_db.c: DB requires an argument, DB(/)
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-vm:3] GotoIf(“SIP/503-08f1a1c8”, “1?vmx|1”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-vm,vmx,1)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [vmx@macro-vm:1] GotoIf(“SIP/503-08f1a1c8”, “0?s-NOANSWER|1”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [vmx@macro-vm:2] Set(“SIP/503-08f1a1c8”, “MODE=unavail”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [vmx@macro-vm:3] GotoIf(“SIP/503-08f1a1c8”, “1?notdirect”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-vm,vmx,5)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] DEBUG[5159] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [vmx@macro-vm:5] NoOp(“SIP/503-08f1a1c8”, "Checking if ext 500 is enabled: ") in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Noop
[Mar 5 17:22:24] DEBUG[5159] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [vmx@macro-vm:6] GotoIf(“SIP/503-08f1a1c8”, “1?s-NOANSWER|1”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-vm,s-NOANSWER,1)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s-NOANSWER@macro-vm:1] Macro(“SIP/503-08f1a1c8”, “get-vmcontext|500”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-get-vmcontext:1] Set(“SIP/503-08f1a1c8”, “VMCONTEXT=default”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Set
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/503-08f1a1c8”, “0?200:300”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-get-vmcontext,s,300)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s@macro-get-vmcontext:300] NoOp(“SIP/503-08f1a1c8”, “”) in new stack
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: NoOp
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Macro
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s-NOANSWER@macro-vm:2] VoiceMail(“SIP/503-08f1a1c8”, “500@default|u”) in new stack
[Mar 5 17:22:24] WARNING[5159] app_voicemail.c: No entry in voicemail config file for ‘500’
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Voicemail
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [s-NOANSWER@macro-vm:3] Goto(“SIP/503-08f1a1c8”, “exit-FAILED|1”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Goto (macro-vm,exit-FAILED,1)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Goto
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – Executing [exit-FAILED@macro-vm:1] Playback(“SIP/503-08f1a1c8”, “im-sorry&an-error-has-occured”) in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: – <SIP/503-08f1a1c8> Playing ‘im-sorry’ (language ‘en’)
[Mar 5 17:22:25] VERBOSE[5159] logger.c: – <SIP/503-08f1a1c8> Playing ‘an-error-has-occured’ (language ‘en’)
[Mar 5 17:22:27] DEBUG[5159] app_macro.c: Executed application: Playback
[Mar 5 17:22:27] VERBOSE[5159] logger.c: – Executing [exit-FAILED@macro-vm:2] GotoIf(“SIP/503-08f1a1c8”, “0?exit-RETURN|1”) in new stack
[Mar 5 17:22:27] DEBUG[5159] app_macro.c: Executed application: GotoIf
[Mar 5 17:22:27] VERBOSE[5159] logger.c: – Executing [exit-FAILED@macro-vm:3] Hangup(“SIP/503-08f1a1c8”, “”) in new stack
[Mar 5 17:22:27] VERBOSE[5159] logger.c: == Spawn extension (macro-vm, exit-FAILED, 3) exited non-zero on ‘SIP/503-08f1a1c8’ in macro ‘vm’
[Mar 5 17:22:27] VERBOSE[5159] logger.c: == Spawn extension (macro-vm, exit-FAILED, 3) exited non-zero on ‘SIP/503-08f1a1c8’ in macro ‘exten-vm’
[Mar 5 17:22:27] VERBOSE[5159] logger.c: == Spawn extension (macro-vm, exit-FAILED, 3) exited non-zero on ‘SIP/503-08f1a1c8’
[Mar 5 17:23:27] VERBOSE[5165] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:23:27] VERBOSE[5165] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5165] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:23:27] VERBOSE[5165] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5165] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:23:27] VERBOSE[5165] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5165] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:23:27] VERBOSE[5166] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:23:27] VERBOSE[5166] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5166] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:23:27] VERBOSE[5166] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5166] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:23:27] VERBOSE[5166] logger.c: Found
[Mar 5 17:23:27] VERBOSE[5166] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:23:27] VERBOSE[5166] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:23:27] VERBOSE[5156] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:24:27] VERBOSE[5169] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:24:27] VERBOSE[5169] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5169] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:24:27] VERBOSE[5169] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5169] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:24:27] VERBOSE[5169] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5169] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:24:27] VERBOSE[5170] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:24:27] VERBOSE[5170] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5170] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:24:27] VERBOSE[5170] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5170] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:24:27] VERBOSE[5170] logger.c: Found
[Mar 5 17:24:27] VERBOSE[5170] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:24:27] VERBOSE[5170] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:24:27] VERBOSE[5165] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:25:27] VERBOSE[5171] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:25:27] VERBOSE[5171] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5171] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:25:27] VERBOSE[5171] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5171] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:25:27] VERBOSE[5171] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5171] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:25:27] VERBOSE[5172] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:25:27] VERBOSE[5172] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5172] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:25:27] VERBOSE[5172] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5172] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:25:27] VERBOSE[5172] logger.c: Found
[Mar 5 17:25:27] VERBOSE[5172] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:25:27] VERBOSE[5172] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:25:27] VERBOSE[5169] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:26:27] VERBOSE[5171] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:26:27] VERBOSE[5175] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:26:27] VERBOSE[5175] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5175] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:26:27] VERBOSE[5175] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5175] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:26:27] VERBOSE[5175] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5175] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:26:27] VERBOSE[5176] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:26:27] VERBOSE[5176] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5176] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:26:27] VERBOSE[5176] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5176] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:26:27] VERBOSE[5176] logger.c: Found
[Mar 5 17:26:27] VERBOSE[5176] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:26:27] VERBOSE[5176] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:27:27] VERBOSE[5179] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:27:27] VERBOSE[5179] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5179] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:27:27] VERBOSE[5179] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5179] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:27:27] VERBOSE[5179] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5179] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:27:27] VERBOSE[5175] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:28:27] VERBOSE[5183] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:28:27] VERBOSE[5183] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5183] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:28:27] VERBOSE[5183] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5183] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:28:27] VERBOSE[5183] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5183] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:28:27] VERBOSE[5184] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:28:27] VERBOSE[5184] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5184] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:28:27] VERBOSE[5184] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5184] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:28:27] VERBOSE[5184] logger.c: Found
[Mar 5 17:28:27] VERBOSE[5184] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:28:27] VERBOSE[5184] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:28:27] VERBOSE[5179] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:29:27] VERBOSE[5187] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:29:27] VERBOSE[5187] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5187] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:29:27] VERBOSE[5187] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5187] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:29:27] VERBOSE[5187] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5187] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:29:27] VERBOSE[5188] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:29:27] VERBOSE[5188] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5188] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:29:27] VERBOSE[5188] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5188] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:29:27] VERBOSE[5188] logger.c: Found
[Mar 5 17:29:27] VERBOSE[5188] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:29:27] VERBOSE[5188] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:29:27] VERBOSE[5183] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:30:27] VERBOSE[5189] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:30:27] VERBOSE[5189] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5189] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:30:27] VERBOSE[5189] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5189] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:30:27] VERBOSE[5189] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5189] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:30:27] VERBOSE[5190] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:30:27] VERBOSE[5190] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5190] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:30:27] VERBOSE[5190] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5190] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:30:27] VERBOSE[5190] logger.c: Found
[Mar 5 17:30:27] VERBOSE[5190] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:30:27] VERBOSE[5190] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:30:27] VERBOSE[5187] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:31:27] VERBOSE[5193] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:31:27] VERBOSE[5193] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5193] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:31:27] VERBOSE[5193] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5193] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:31:27] VERBOSE[5193] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5193] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:31:27] VERBOSE[5194] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:31:27] VERBOSE[5194] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5194] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:31:27] VERBOSE[5194] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5194] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:31:27] VERBOSE[5194] logger.c: Found
[Mar 5 17:31:27] VERBOSE[5194] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Mar 5 17:31:27] VERBOSE[5194] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:31:27] VERBOSE[5189] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Mar 5 17:32:27] VERBOSE[5197] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Mar 5 17:32:27] VERBOSE[5197] logger.c: Found
[Mar 5 17:32:27] VERBOSE[5197] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Mar 5 17:32:27] VERBOSE[5197] logger.c: Found
[Mar 5 17:32:27] VERBOSE[5197] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Mar 5 17:32:27] VERBOSE[5197] logger.c: Found

rmalerman · March 5, 2009, 11:46pm

Yes, it’s 1.4.22-3

fskrotzki · March 6, 2009, 2:38pm

Ok I see the error, why it is happening I don’t know. But let’s show you how to read the logs a bit so you can chase it down.

First off see these lines:

[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 5 17:27:27] VERBOSE[5180] logger.c: Found
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 5 17:27:27] VERBOSE[5180] logger.c: == Manager 'admin' logged off from 127.0.0.1

unless you are having AMI (asterisk management interface) issues they are not important. It’s just showing that it get’s a login request, it walks the files to valid users, checks and allows the admin to login and then it logs out (it’s a part of the dashboard checking that asterisk is ok when it displays the status).

Next below is where the error is. So that you know 95% of all of the standard audio is named exactly what say’s so if you searched for the word sorry you’d find it playing the audio. Then you work backwards as it determined the error before playing the audio…

[Mar 5 17:22:24] WARNING[5159] app_voicemail.c: No entry in voicemail config file for '500'
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Voicemail
[Mar 5 17:22:24] VERBOSE[5159] logger.c: -- Executing [s-NOANSWER@macro-vm:3] Goto("SIP/503-08f1a1c8", "exit-FAILED|1") in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: -- Goto (macro-vm,exit-FAILED,1)
[Mar 5 17:22:24] DEBUG[5159] app_macro.c: Executed application: Goto
[Mar 5 17:22:24] VERBOSE[5159] logger.c: -- Executing [exit-FAILED@macro-vm:1] Playback("SIP/503-08f1a1c8", "im-sorry&an-error-has-occured") in new stack
[Mar 5 17:22:24] VERBOSE[5159] logger.c: -- Playing 'im-sorry' (language 'en')
[Mar 5 17:22:25] VERBOSE[5159] logger.c: -- Playing 'an-error-has-occured' (language 'en')
[Mar 5 17:22:27] DEBUG[5159] app_macro.c: Executed application: Playback

Now working backwards look for something that does not look right and I made it easy but the first line I started with is the error. You configured extension 500 for voicemail but when the system went to read the voicemail.conf file which contains the info about voicemail for all extensions it didn’t find a entry in the file for it. That’s why you are getting the error. Something is wrong with the file and/or when you created the extensions it could not write the data to the file.

rmalerman · March 7, 2009, 1:21pm

I wonder if the permissions are not set correctly on the voicemail.conf file, because I am having this issue with all extensions. Can you tell me what the correct permissions are and how one goes about setting them? I really appreciate all your help! Thank you.

sonny · March 17, 2009, 11:02pm

My version is 1.4.23.1 on CentOS 5.2. I looked at the voicemail.conf and I do see all the extentions… Please help. I am using AsteriskNow and I am also new to AsteriskNOw/FreePBX. I have not made any manual changes to voicemail.conf. All the ext are giving the same message “sorry, an error has occurred”.

fskrotzki · March 18, 2009, 5:58pm

rmalerman,
Sorry I lost track of this thread when I was away from the office for a few days. Did you solve it? rights for the file are asterisk:asterisk and permissions are 664. You never provided your voicemail.conf file which if there is a formatting error in it someplace can easly cause all kinds of issues.

fskrotzki · March 18, 2009, 6:00pm

voicemail will not work until the extension has has gone in and accessed it once, preferably recording a greeting so that one can be played when it is put into action.

sonny · March 19, 2009, 2:23am

Thanx for the feedback… I try to setup a voice mail by using *98 and *97 and I am keep getting “login incorrect” voicemail.conf has the entry for all the extentions under defualt. I also made sure that rfc2833 is set for DTMFMode on FreePBX/Ext. as well as on one of the softphone which did allow an option to pick under setting. I also tired few different softphone software including x-lite,sjphone, global IP, etc and they are doing the same thing. I am having this problem on all the ext. and they are just created. This is a new install with CentOS 5.2.

sonny · March 19, 2009, 3:03am

Thank you fskrotzki for leading me into the right direction. I updated the voicemail.conf and removed two lines after [defualt], which were blank [] and added [general] and [default] on the last two lines. After that I went to one of the extention disable voice mail - reload and then enable the voice mail - reload and that seem to fix it. I am very new to this, so I am not sure what all happen and why it didn’t work to start with. I didn’t make any changes to any conf files before until now so I would think that it should work right out of the box, but oh well we dont’ live in perfect world :)… Thanx Asterisk and FreePBX for the great! product and for havng this forum.

fskrotzki · March 19, 2009, 2:07pm

voicemail has a huge problem with a empty context (the [] line). You should not have needed to reload anything as every time voicemail is started inside asterisk it reloads the voicemail.conf file.

if AsteriskNow started with a blank voicemail.conf file that had one it’s a bug and needs to get reported. (I’m loading a copy on test box currently and will find out in a bit if that is the case).

fskrotzki · March 19, 2009, 3:21pm

ok I have a test copy of AsteriskNow 1.5 Beta2 running and if all you do it install it, apply changes and create extensions with voicemail yes it will have a problem.

Specifically the issue is that it creates a blank context in the voicemail.conf file and once that happens voicemail has issues.

So step one is to upgrade the FreePBX modules to current before you go creating anything as the ISO is using a older verison of FreePBX that happens to have that bug in it and was fixed already.

gohuge · December 17, 2009, 11:23pm

I have the same issue but I can’t figure out how to get to the file system from the CentOS login. Is there some command I need to use to get past the limited login screen? I can only see 3 files when I login as root!

nighthawks80 · January 8, 2010, 3:45am

To login to your CentOS
At the login screen type: root :Hit Enter
type in your password:*******:Hit Enter

Once logged in type:
cd /etc/asterisk/

Hit Enter

now type:

vi voicemail.conf

Hit Enter

Go to “[]” and delete this. With “DELETE”

Type “:x” hit Enter

and your done.

Just reset your voicemail in the “Extension” menu…

stretchhenry · February 10, 2010, 3:28pm

Thanks fskrotzki I was having the same problem, that worked for me.

\Mark

zeane · January 23, 2012, 9:04am

Using FreePBX 2.10 RC, and was having same issues, but the last post sorted it out - Thank You!

emcompnut09 · June 13, 2012, 11:21pm

I’m running FreePBX 2.10 on Asterisk 1.8.12.0, and somehow my VM began to issue the same errors in this thread. System has been working flawlessly for 5 weeks, and I’m just about ready to put it into full production this week. Surprised when the errors started coming. I tried everything, but it wasn’t until I got to the post from nighthawks80 that I had success.

I just wanted everyone to know that this erros is still a possibility, although I’m not really sure why. Nice to know there’s a relatively simple fix.

I appreciate this community!

– emcompnut a.k.a. Ed