FreePBX extension voicemail not work any more

vcba79 · July 30, 2020, 6:34am

Hi, all

I got a strange problem recently. I has extension 200 which is a grandstream phone. If I use IVR in inbound route and direct call to this extension’s voicemail, it works. If I set up ring group or direct call to this extension. the call will hang up when ringtime reached. Here is the full log

[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:8] GotoIf("DAHDI/1-1", "1?normdial") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-dial,s,11)
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:11] NoOp("DAHDI/1-1", "Returned from dialparties with groups to dial") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:12] NoOp("DAHDI/1-1", "ringall array  ") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:13] Set("DAHDI/1-1", "__FMGL_DIAL=") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:14] Set("DAHDI/1-1", "LOOPCNT=2") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:15] Set("DAHDI/1-1", "ITER=1") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:16] Set("DAHDI/1-1", "__EXTTOCALL=100") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:17] NoOp("DAHDI/1-1", "Working with 100") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:18] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:19] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:20] Set("DAHDI/1-1", "ITER=2") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:21] GotoIf("DAHDI/1-1", "1?ndloopbegin") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-dial,s,16)
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:16] Set("DAHDI/1-1", "__EXTTOCALL=200") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:17] NoOp("DAHDI/1-1", "Working with 200") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:18] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:19] ExecIf("DAHDI/1-1", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:20] Set("DAHDI/1-1", "ITER=3") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:21] GotoIf("DAHDI/1-1", "0?ndloopbegin") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:22] Macro("DAHDI/1-1", "dial-ringall-predial-hook,") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:23] ExecIf("DAHDI/1-1", "0?Set(CWRING=r(callwaiting)):Set(CWRING=)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:24] ExecIf("DAHDI/1-1", "0?Set(ds=DAHDI/3&PJSIP/200/sip:[email protected]:5060,15,HhtrQ(NO_ANSWER)M(auto-blkvm)g)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:25] Dial("DAHDI/1-1", "DAHDI/3&PJSIP/200/sip:[email protected]:5060,15,HhtrQ(NO_ANSWER)M(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) start
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("DAHDI/3-1", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("DAHDI/3-1", "Applying SIP Headers to channel DAHDI/3-1") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:3] Set("DAHDI/3-1", "TECH=DAHDI") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:4] Set("DAHDI/3-1", "SIPHEADERKEYS=") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:5] While("DAHDI/3-1", "0") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_while.c: Jumping to priority 13
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:14] Return("DAHDI/3-1", "") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'DAHDI/3-1'
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: PJSIP/200-0000001a Internal Gosub(func-apply-sipheaders,s,1) start
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/200-0000001a", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/200-0000001a", "Applying SIP Headers to channel PJSIP/200-0000001a") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/200-0000001a", "TECH=PJSIP") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/200-0000001a", "SIPHEADERKEYS=") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/200-0000001a", "0") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_while.c: Jumping to priority 13
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@func-apply-sipheaders:14] Return("PJSIP/200-0000001a", "") in new stack
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'PJSIP/200-0000001a'
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_stack.c: PJSIP/200-0000001a Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: Called DAHDI/3
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: Called PJSIP/200/sip:[email protected]:5060
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: DAHDI/3-1 is ringing
[2020-07-30 14:09:06] VERBOSE[8822] netsock2.c: Using SIP RTP Audio TOS bits 184
[2020-07-30 14:09:06] VERBOSE[8822] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2020-07-30 14:09:06] VERBOSE[8822] netsock2.c: Using SIP RTP Audio CoS mark 5
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: PJSIP/200-0000001a connected line has changed. Saving it until answer for DAHDI/1-1
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: PJSIP/200-0000001a is ringing
[2020-07-30 14:09:06] VERBOSE[5949][C-0000001b] app_dial.c: PJSIP/200-0000001a is ringing
[2020-07-30 14:09:07] VERBOSE[5949][C-0000001b] app_dial.c: DAHDI/3-1 is ringing
[2020-07-30 14:09:12] VERBOSE[5949][C-0000001b] app_dial.c: DAHDI/3-1 is ringing
[2020-07-30 14:09:17] VERBOSE[5949][C-0000001b] app_dial.c: DAHDI/3-1 is ringing
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_dial.c: Nobody picked up in 15000 ms
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/3-1 Internal Gosub(crm-hangup,s,1) start
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:1] NoOp("DAHDI/3-1", "Sending Hangup to CRM") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:2] NoOp("DAHDI/3-1", "HANGUP CAUSE: 0") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:3] ExecIf("DAHDI/3-1", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:4] NoOp("DAHDI/3-1", "MASTER CHANNEL: 1596089346.63 = 1596089336.62") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:5] GotoIf("DAHDI/3-1", "1?return") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (crm-hangup,s,8)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:8] Return("DAHDI/3-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'DAHDI/3-1'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/3-1 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] sig_analog.c: Hanging up on 'DAHDI/3-1'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] chan_dahdi.c: Hungup 'DAHDI/3-1'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: PJSIP/200-0000001a Internal Gosub(crm-hangup,s,1) start
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/200-0000001a", "Sending Hangup to CRM") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/200-0000001a", "HANGUP CAUSE: 0") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/200-0000001a", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/200-0000001a", "MASTER CHANNEL: 1596089346.64 = 1596089336.62") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/200-0000001a", "1?return") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (crm-hangup,s,8)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/200-0000001a", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'PJSIP/200-0000001a'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: PJSIP/200-0000001a Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:26] Set("DAHDI/1-1", "DIALSTATUS=NOANSWER") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:27] GosubIf("DAHDI/1-1", "0?NOANSWER,1()") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:28] NoOp("DAHDI/1-1", "Returning since nobody answered") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-dial:29] MacroExit("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:19] Gosub("DAHDI/1-1", "sub-record-cancel,s,1()") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@sub-record-cancel:1] Return("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:20] Set("DAHDI/1-1", "RingGroupMethod=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:21] GotoIf("DAHDI/1-1", "0?nodest") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:22] Set("DAHDI/1-1", "__NODEST=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:23] Macro("DAHDI/1-1", "blkvm-clr,") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-clr:1] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/1-1)=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-clr:2] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [1@ext-group:24] Goto("DAHDI/1-1", "ext-local,vmu200,1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (ext-local,vmu200,1)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmu200@ext-local:1] Macro("DAHDI/1-1", "vm,200,NOANSWER,") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-vm:1] Macro("DAHDI/1-1", "user-callerid,SKIPTTL") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:1] Set("DAHDI/1-1", "TOUCH_MONITOR=1596089336.62") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:2] Set("DAHDI/1-1", "AMPUSER=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:3] Set("DAHDI/1-1", "HOTDESCKCHAN=1-1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:4] Set("DAHDI/1-1", "HOTDESKEXTEN=1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:5] Set("DAHDI/1-1", "HOTDESKCALL=0") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("DAHDI/1-1", "0?Set(HOTDESKCALL=1)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("DAHDI/1-1", "0?Set(CALLERID(name)=)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("DAHDI/1-1", "0?report") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:9] ExecIf("DAHDI/1-1", "1?Set(REALCALLERIDNUM=)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:10] Set("DAHDI/1-1", "AMPUSER=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:11] GotoIf("DAHDI/1-1", "0?limit") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:12] Set("DAHDI/1-1", "AMPUSERCIDNAME=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("DAHDI/1-1", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("DAHDI/1-1", "1?report") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-user-callerid,s,23)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:23] NoOp("DAHDI/1-1", "Macro Depth is 2") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:24] GotoIf("DAHDI/1-1", "1?report2:macroerror") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-user-callerid,s,25)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:25] GotoIf("DAHDI/1-1", "1?continue") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-user-callerid,s,44)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:44] Set("DAHDI/1-1", "CALLERID(number)=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:45] Set("DAHDI/1-1", "CALLERID(name)=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:46] GotoIf("DAHDI/1-1", "1?cnum") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-user-callerid,s,48)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:48] Set("DAHDI/1-1", "CDR(cnum)=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-user-callerid:49] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-vm:2] Set("DAHDI/1-1", "VMGAIN=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-vm:3] Macro("DAHDI/1-1", "blkvm-check,") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-check:1] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-check:2] ExecIf("DAHDI/1-1", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-blkvm-check:3] MacroExit("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-vm:4] GotoIf("DAHDI/1-1", "1?vmx,1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-vm,vmx,1)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:1] Set("DAHDI/1-1", "__EXTTOCALL=200") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:2] Set("DAHDI/1-1", "__CRM_VOICEMAIL=200") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:3] Set("DAHDI/1-1", "MEXTEN=200") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:4] Set("DAHDI/1-1", "MMODE=NOANSWER") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:5] Set("DAHDI/1-1", "RETVM=") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:6] Set("DAHDI/1-1", "MODE=unavail") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:7] Macro("DAHDI/1-1", "get-vmcontext,200") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:1] Set("DAHDI/1-1", "VMCONTEXT=default") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("DAHDI/1-1", "0?200:300") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:8] Set("DAHDI/1-1", "MODE=unavail") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:9] NoOp("DAHDI/1-1", "MODE IS: unavail") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:10] GotoIf("DAHDI/1-1", "1?chknomsg") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-vm,vmx,12)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:12] GotoIf("DAHDI/1-1", "0?s-NOANSWER,1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:13] GotoIf("DAHDI/1-1", "1?notdirect") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-vm,vmx,15)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:15] NoOp("DAHDI/1-1", "Checking if ext 200 is enabled: ") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [vmx@macro-vm:16] GotoIf("DAHDI/1-1", "1?s-NOANSWER,1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-vm,s-NOANSWER,1)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s-NOANSWER@macro-vm:1] Macro("DAHDI/1-1", "get-vmcontext,200") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:1] Set("DAHDI/1-1", "VMCONTEXT=default") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("DAHDI/1-1", "0?200:300") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s-NOANSWER@macro-vm:2] VoiceMail("DAHDI/1-1", "200@default,u") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] file.c: <DAHDI/1-1> Playing 'vm-theperson.ulaw' (language 'en')
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_macro.c: Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'DAHDI/1-1' in macro 'vm'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Spawn extension (ext-local, vmu200, 1) exited non-zero on 'DAHDI/1-1'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [h@ext-local:1] Macro("DAHDI/1-1", "hangupcall,") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("DAHDI/1-1", "1?theend") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("DAHDI/1-1", "0?Set(CDR(recordingfile)=)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-hangupcall:4] NoOp("DAHDI/1-1", " montior file= /var/spool/asterisk/monitor/2020/07/30/in-s-unknown-20200730-140906-1596089336.62.wav") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-hangupcall:5] GotoIf("DAHDI/1-1", "1?skipagi") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@macro-hangupcall:7] Hangup("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'DAHDI/1-1' in macro 'hangupcall'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'DAHDI/1-1'
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/1-1 Internal Gosub(crm-hangup,s,1) start
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:1] NoOp("DAHDI/1-1", "Sending Hangup to CRM") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:2] NoOp("DAHDI/1-1", "HANGUP CAUSE: 16") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:3] ExecIf("DAHDI/1-1", "1?Set(__CRM_VOICEMAIL=FAILED)") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:4] NoOp("DAHDI/1-1", "MASTER CHANNEL: 1596089336.62 = 1596089336.62") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:5] GotoIf("DAHDI/1-1", "0?return") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:6] Set("DAHDI/1-1", "__CRM_HANGUP=1") in new stack
[2020-07-30 14:09:21] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:7] AGI("DAHDI/1-1", "agi://127.0.0.1/sangomacrm.agi") in new stack
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] res_agi.c: <DAHDI/1-1>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] pbx.c: Executing [s@crm-hangup:8] Return("DAHDI/1-1", "") in new stack
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on 'DAHDI/1-1'
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] app_stack.c: DAHDI/1-1 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] sig_analog.c: Hanging up on 'DAHDI/1-1'
[2020-07-30 14:09:22] VERBOSE[5949][C-0000001b] chan_dahdi.c: Hungup 'DAHDI/1-1'
[2020-07-30 14:09:22] VERBOSE[6005][C-0000001b] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2020-07-30 14:09:22] VERBOSE[6005][C-0000001b] app_mixmonitor.c: End MixMonitor Recording DAHDI/1-1

PitzKey · July 30, 2020, 9:20am

Please provide a full call trace using pastebin

https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs-PartII

Also, it seems that it did go to voicemail, but hung up as soon as it started playing “The person at extension…”
Can please explain who is in that ring group? I’m a little confused with these Dahdi devices ringing.

vcba79 · July 30, 2020, 9:36am

There are 2 extensions in this ring group, 100 (a fxs line) and 200 (a grandstream sip phone). The full log is attached.

Thanks for your help,
20200730.tgz (8.6 KB)

PitzKey · July 30, 2020, 9:40am

What is the failover destination in the ring group?

vcba79 · July 30, 2020, 2:35pm

Destination if no answer: Voicemail (200 Grandstram GXP1610 Unavailable message)

Thanks for your help.

system · August 30, 2020, 2:35pm

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.