Followme not providing ringback to caller

Hi…

This problem has been happening for a while, and is now happening on a brandnew, built from scratch box as well. Any ideas?

Phone A (1589 in the call log below) calls Phone B (8892). Phone B has followme with ringallv2 turned on and is set to ring 5556667777# after 4 seconds. This all works. However, the caller on Phone A only hears ringback for the first 4 seconds. After followme kicks in and starts ringing the additional phone, the ringback stops. (Even though both phones are actually ringing). The caller thinks the call has been dropped and hangs up. This only happens if the followme call is going off the system (using the # after the number). If the additional numbers are internal extension, ringback works fine.

Yes, the “Play Music on Hold” option is set to ring.

[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:1] GotoIf(“SIP/1589-b7d4acb0”, “0?ext-local|8892|1”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:2] Macro(“SIP/1589-b7d4acb0”, “user-callerid|”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:3] GotoIf(“SIP/1589-b7d4acb0”, “1?skipdb”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Goto (from-internal,8892,5)
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:5] Set(“SIP/1589-b7d4acb0”, “__NODEST=”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:6] Set(“SIP/1589-b7d4acb0”, “__BLKVM_OVERRIDE=BLKVM/8892/SIP/1589-b7d4acb0”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:7] Set(“SIP/1589-b7d4acb0”, “__BLKVM_BASE=8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:8] Set(“SIP/1589-b7d4acb0”, “DB(BLKVM/8892/SIP/1589-b7d4acb0)=TRUE”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:9] Set(“SIP/1589-b7d4acb0”, “RRNODEST=”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:10] Set(“SIP/1589-b7d4acb0”, “__NODEST=8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:11] Set(“SIP/1589-b7d4acb0”, “RecordMethod=Group”) in new stack
[Feb 6 09:26:28] DEBUG[31369] pbx.c: Function result is ‘8892-5556667777#’
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:12] Macro(“SIP/1589-b7d4acb0”, “record-enable|8892-5556667777#|Group”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:13] Set(“SIP/1589-b7d4acb0”, “RingGroupMethod=ringallv2”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:14] Set(“SIP/1589-b7d4acb0”, “_FMGRP=8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:15] GotoIf(“SIP/1589-b7d4acb0”, “0?doconfirm”) in new stack
[Feb 6 09:26:28] DEBUG[31369] pbx.c: Function result is ‘8892-5556667777#’
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [8892@from-internal:16] Macro(“SIP/1589-b7d4acb0”, “dial|29|m(FollowMe)|8892-5556667777#”) in new stack
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – dialparties.agi: Added extension 8892 to extension map
[Feb 6 09:26:28] DEBUG[31369] db.c: Unable to find key ‘8892’ in family ‘CF’
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – dialparties.agi: Extension 8892 cf is disabled
[Feb 6 09:26:28] DEBUG[31369] db.c: Unable to find key ‘8892’ in family ‘DND’
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – dialparties.agi: Extension 8892 do not disturb is disabled
[Feb 6 09:26:28] DEBUG[31369] db.c: Unable to find key ‘8892’ in family ‘CFB’
[Feb 6 09:26:28] DEBUG[31369] db.c: Unable to find key ‘8892’ in family ‘CFU’
[Feb 6 09:26:28] VERBOSE[31369] logger.c: > dialparties.agi: extnum 8892 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – dialparties.agi: dbset CALLTRACE/8892 to 1589
[Feb 6 09:26:28] VERBOSE[31369] logger.c: > dialparties.agi: NODEST: 8892 adding M(auto-blkvm) to dialopts: m(FollowMe)M(auto-blkvm)
[Feb 6 09:26:28] VERBOSE[31369] logger.c: > dialparties.agi: NODEST: 8892 blkvm enabled macro already in dialopts: m(FollowMe)M(auto-blkvm)
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Executing [s@macro-dial:10] Dial(“SIP/1589-b7d4acb0”, “Local/FMPR-8892@from-internal&Local/FMGL-5556667777#@from-internal|29|m(FollowMe)M(auto-blkvm)”) in new stack
[Feb 6 09:26:28] DEBUG[31369] rtp.c: Channel ‘Local/FMPR-8892@from-internal-7174,1’ has no RTP, not doing anything
[Feb 6 09:26:28] VERBOSE[31369] logger.c: – Called FMPR-8892@from-internal
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [FMPR-8892@from-internal:1] NoOp(“Local/FMPR-8892@from-internal-7174,2”, “In FMPR 8892 with 8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [FMPR-8892@from-internal:2] Set(“Local/FMPR-8892@from-internal-7174,2”, “RingGroupMethod=”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [FMPR-8892@from-internal:3] Set(“Local/FMPR-8892@from-internal-7174,2”, “USE_CONFIRMATION=”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [FMPR-8892@from-internal:4] Set(“Local/FMPR-8892@from-internal-7174,2”, “RINGGROUP_INDEX=”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [FMPR-8892@from-internal:5] Macro(“Local/FMPR-8892@from-internal-7174,2”, “simple-dial|8892|29”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:1] Macro(“Local/FMPR-8892@from-internal-7174,2”, “user-callerid|SKIPTTL”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:1] NoOp(“Local/FMPR-8892@from-internal-7174,2”, “user-callerid: TIM SCHREYACK 1589”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:2] Set(“Local/FMPR-8892@from-internal-7174,2”, “AMPUSER=1589”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:3] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?report”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:13] NoOp(“Local/FMPR-8892@from-internal-7174,2”, “TTL: 64 ARG1: SKIPTTL”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:14] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?continue”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-user-callerid:23] NoOp(“Local/FMPR-8892@from-internal-7174,2”, “Using CallerID “TIM SCHREYACK” <1589>”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:2] Set(“Local/FMPR-8892@from-internal-7174,2”, “EXTTOCALL=8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:3] Set(“Local/FMPR-8892@from-internal-7174,2”, “RT=29”) in new stack
[Feb 6 09:26:28] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘CFU’
[Feb 6 09:26:28] DEBUG[31373] func_db.c: DB: CFU/8892 not found in database.
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:4] Set(“Local/FMPR-8892@from-internal-7174,2”, “CFUEXT=”) in new stack
[Feb 6 09:26:28] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘CFB’
[Feb 6 09:26:28] DEBUG[31373] func_db.c: DB: CFB/8892 not found in database.
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:5] Set(“Local/FMPR-8892@from-internal-7174,2”, “CFBEXT=”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:6] Macro(“Local/FMPR-8892@from-internal-7174,2”, “record-enable|8892|IN”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “0?2:4”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-record-enable:4] AGI(“Local/FMPR-8892@from-internal-7174,2”, “recordingcheck|20080206-092628|1202307988.4943”) in new stack
[Feb 6 09:26:28] VERBOSE[31374] logger.c: – Executing [FMGL-5556667777#@from-internal:1] NoOp(“Local/FMGL-5556667777#@from-internal-0cea,2”, “In FMGL 8892 with 5556667777#”) in new stack
[Feb 6 09:26:28] DEBUG[31374] db.c: Unable to find key ‘DND/8892/SIP/1589-b7d4acb0’ in family ‘FM’
[Feb 6 09:26:28] DEBUG[31374] func_db.c: DB: FM/DND/8892/SIP/1589-b7d4acb0 not found in database.
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-record-enable:5] NoOp(“Local/FMPR-8892@from-internal-7174,2”, “No recording needed”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-simple-dial:7] Macro(“Local/FMPR-8892@from-internal-7174,2”, “dial|29||8892”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-dial:1] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?dial”) in new stack
[Feb 6 09:26:28] VERBOSE[31373] logger.c: – Executing [s@macro-dial:3] AGI(“Local/FMPR-8892@from-internal-7174,2”, “dialparties.agi”) in new stack
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – dialparties.agi: Added extension 8892 to extension map
[Feb 6 09:26:29] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘CF’
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – dialparties.agi: Extension 8892 cf is disabled
[Feb 6 09:26:29] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘DND’
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – dialparties.agi: Extension 8892 do not disturb is disabled
[Feb 6 09:26:29] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘CFB’
[Feb 6 09:26:29] DEBUG[31373] db.c: Unable to find key ‘8892’ in family ‘CFU’
[Feb 6 09:26:29] VERBOSE[31373] logger.c: > dialparties.agi: extnum 8892 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[Feb 6 09:26:29] DEBUG[31377] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:29] DEBUG[31377] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:29] VERBOSE[31373] logger.c: dialparties.agi: Extension 8892 has call waiting enabled with state: 1
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – dialparties.agi: dbset CALLTRACE/8892 to 1589
[Feb 6 09:26:29] VERBOSE[31373] logger.c: > dialparties.agi: NODEST: 8892 adding M(auto-blkvm) to dialopts: M(auto-blkvm)
[Feb 6 09:26:29] VERBOSE[31373] logger.c: > dialparties.agi: NODEST: 8892 blkvm enabled macro already in dialopts: M(auto-blkvm)
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – Executing [s@macro-dial:10] Dial(“Local/FMPR-8892@from-internal-7174,2”, “SIP/8892|29|M(auto-blkvm)”) in new stack
[Feb 6 09:26:29] DEBUG[31373] rtp.c: Channel ‘Local/FMPR-8892@from-internal-7174,2’ has no RTP, not doing anything
[Feb 6 09:26:29] DEBUG[31373] chan_sip.c: Outgoing Call for 8892
[Feb 6 09:26:29] DEBUG[31373] chan_sip.c: Call to peer ‘8892’ is 2 out of 50
[Feb 6 09:26:29] DEBUG[31373] devicestate.c: Notification of state change to be queued on device/channel SIP/8892
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:29] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: Changing state for SIP/8892 - state 7 (Ring+Inuse)
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:29] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:29] DEBUG[3403] app_queue.c: Device ‘SIP/8892’ changed to state ‘7’ (Ring+Inuse) but we don’t care because they’re not a member of any queue.
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – Called 8892
[Feb 6 09:26:29] DEBUG[3399] devicestate.c: Notification of state change to be queued on device/channel SIP/8892-0a014d20
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:29] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: Changing state for SIP/8892 - state 7 (Ring+Inuse)
[Feb 6 09:26:29] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:29] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:29] DEBUG[3403] app_queue.c: Device ‘SIP/8892’ changed to state ‘7’ (Ring+Inuse) but we don’t care because they’re not a member of any queue.
[Feb 6 09:26:29] VERBOSE[31373] logger.c: – SIP/8892-0a014d20 is ringing
[Feb 6 09:26:29] DEBUG[31373] rtp.c: Channel ‘Local/FMPR-8892@from-internal-7174,2’ has no RTP, not doing anything
[Feb 6 09:26:29] VERBOSE[31369] logger.c: – Local/FMPR-8892@from-internal-7174,1 is ringing
[Feb 6 09:26:29] DEBUG[31374] db.c: Unable to find key ‘DND/8892/SIP/1589-b7d4acb0’ in family ‘FM’
[Feb 6 09:26:29] DEBUG[31374] func_db.c: DB: FM/DND/8892/SIP/1589-b7d4acb0 not found in database.
[Feb 6 09:26:30] DEBUG[31374] db.c: Unable to find key ‘DND/8892/SIP/1589-b7d4acb0’ in family ‘FM’
[Feb 6 09:26:30] DEBUG[31374] func_db.c: DB: FM/DND/8892/SIP/1589-b7d4acb0 not found in database.
[Feb 6 09:26:31] DEBUG[31369] channel.c: Hanging up channel ‘Local/FMPR-8892@from-internal-7174,1’
[Feb 6 09:26:31] DEBUG[31369] devicestate.c: Notification of state change to be queued on device/channel Local/FMPR-8892@from-internal-7174,1
[Feb 6 09:26:31] DEBUG[31373] rtp.c: Channel ‘Local/FMPR-8892@from-internal-7174,2’ has no RTP, not doing anything
[Feb 6 09:26:31] DEBUG[31373] channel.c: Hanging up channel ‘SIP/8892-0a014d20’
[Feb 6 09:26:31] DEBUG[31373] chan_sip.c: Hangup call SIP/8892-0a014d20, SIP callid [email protected])
[Feb 6 09:26:31] DEBUG[31373] chan_sip.c: Call to peer ‘8892’ removed from call limit 50
[Feb 6 09:26:31] DEBUG[31373] devicestate.c: Notification of state change to be queued on device/channel SIP/8892
[Feb 6 09:26:31] DEBUG[31373] devicestate.c: Notification of state change to be queued on device/channel SIP/8892-0a014d20
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for Local - FMPR-8892@from-internal
[Feb 6 09:26:31] DEBUG[3384] chan_local.c: Checking if extension FMPR-8892@from-internal exists (devicestate)
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: Changing state for Local/FMPR-8892@from-internal - state 2 (In use)
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:31] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: Changing state for SIP/8892 - state 2 (In use)
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:31] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:31] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: Changing state for SIP/8892 - state 2 (In use)
[Feb 6 09:26:31] DEBUG[3384] devicestate.c: No provider found, checking channel drivers for SIP - 8892
[Feb 6 09:26:31] DEBUG[3384] chan_sip.c: Checking device state for peer 8892
[Feb 6 09:26:31] DEBUG[3403] app_queue.c: Device ‘Local/FMPR-8892@from-internal’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Feb 6 09:26:31] DEBUG[3403] app_queue.c: Device ‘SIP/8892’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Feb 6 09:26:31] DEBUG[3403] app_queue.c: Device ‘SIP/8892’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Feb 6 09:26:31] DEBUG[31369] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2008-02-06 09:26:28’,‘1589’,‘1589’,‘FMPR-8892’,‘from-internal’, ‘Local/FMPR-8892@from-internal-7174,1’,’’,’’,’’,3,0,‘NO ANSWER’,3,’’,‘1202307988.4942’)
[Feb 6 09:26:31] DEBUG[31369] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2008-02-06 09:26:28’,’“TIM SCHREYACK” <1589>’,‘1589’,‘8892’,‘from-internal’, ‘SIP/1589-b7d4acb0’,‘Local/FMGL-5556667777#@from-internal-0cea,1’,‘Dial’,‘Local/FMPR-8892@from-internal&Local/FMGL-5556667777#@from-internal|29|m(FollowM’,3,0,‘NO ANSWER’,3,’’,‘1202307988.4941’)
[Feb 6 09:26:31] VERBOSE[31369] logger.c: – Executing [s@macro-hangupcall:7] NoOp(“SIP/1589-b7d4acb0”, “Cleaning Up Block VM Flag: BLKVM/8892/SIP/1589-b7d4acb0”) in new stack
[Feb 6 09:26:31] VERBOSE[31369] logger.c: – Executing [s@macro-hangupcall:8] DBdel(“SIP/1589-b7d4acb0”, “BLKVM/8892/SIP/1589-b7d4acb0”) in new stack
[Feb 6 09:26:31] VERBOSE[31369] logger.c: – DBdel: family=BLKVM, key=8892/SIP/1589-b7d4acb0
[Feb 6 09:26:31] DEBUG[31373] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2008-02-06 09:26:29’,‘1589’,‘1589’,‘s’,‘from-internal’, ‘SIP/8892-0a014d20’,’’,’’,’’,2,0,‘NO ANSWER’,3,’’,‘1202307989.4946’)
[Feb 6 09:26:31] DEBUG[31373] app_macro.c: Spawn extension (macro-dial,s,10) exited non-zero on ‘Local/FMPR-8892@from-internal-7174,2’ in macro ‘dial’
[Feb 6 09:26:31] DEBUG[31373] app_macro.c: Spawn extension (macro-dial,s,10) exited non-zero on ‘Local/FMPR-8892@from-internal-7174,2’ in macro ‘simple-dial’
[Feb 6 09:26:31] DEBUG[31373] pbx.c: Spawn extension (macro-dial,s,10) exited non-zero on ‘Local/FMPR-8892@from-internal-7174,2’
[Feb 6 09:26:31] VERBOSE[31373] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/FMPR-8892@from-internal-7174,2’
[Feb 6 09:26:31] DEBUG[31373] channel.c: Soft-Hanging up channel ‘Local/FMPR-8892@from-internal-7174,2’
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [h@macro-dial:1] Macro(“Local/FMPR-8892@from-internal-7174,2”, “hangupcall”) in new stack
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“Local/FMPR-8892@from-internal-7174,2”, “w”) in new stack
[Feb 6 09:26:31] VERBOSE[31369] logger.c: – Executing [s@macro-hangupcall:10] DBdel(“SIP/1589-b7d4acb0”, “FM/DND/8892/SIP/1589-b7d4acb0”) in new stack
[Feb 6 09:26:31] VERBOSE[31369] logger.c: – DBdel: family=FM, key=DND/8892/SIP/1589-b7d4acb0
[Feb 6 09:26:31] DEBUG[31369] db.c: Unable to find key ‘DND/8892/SIP/1589-b7d4acb0’ in family ‘FM’
[Feb 6 09:26:31] DEBUG[31373] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2008-02-06 09:26:28’,’“TIM SCHREYACK” <1589>’,‘1589’,‘FMPR-8892’,‘from-internal’, ‘Local/FMPR-8892@from-internal-7174,2’,‘SIP/8892-0a014d20’,‘Dial’,‘SIP/8892|29|M(auto-blkvm)’,3,0,‘NO ANSWER’,3,’’,‘1202307988.4943’)
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“Local/FMPR-8892@from-internal-7174,2”, “”) in new stack
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?skiprg”) in new stack
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?skipblkvm”) in new stack
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“Local/FMPR-8892@from-internal-7174,2”, “1?theend”) in new stack
[Feb 6 09:26:31] VERBOSE[31373] logger.c: – Executing [s@macro-hangupcall:11] H

I’ve found some sequences that can result in this behavior and have not had a chance to track them down. You can usually fix it by putting an “r” option on the General Settings tab in the “Asterisk Dial command options” field. Note, do not put an “r” in the “Asterisk Outbound Dial command options.”

Thanks Philippe, that fixed it!