Short rings when queue rings an extension

This problem is very odd, and I’m not sure where to look in my configuration to resolve it. What happens is sometimes (at this point, it seems random) when a call comes in to my queue if it rings past the first agent that it chooses to another agent SOMETIMES that agent will receive a very short ring (perhaps half a normal ring) then the call will instantly go to another member of the queue. Generally this will only happen with one member of the queue at a time, and it does not seem to happen with the first member the queue tries to ring. Oddly, if the call goes around the whole queue without an answer back to the member that got the short ring, it will ring short again.

This seems to happen quite a bit, but so far I have not been able to determine a specific set of conditions that will cause it to occur.

I’ve included the output on the console below. What happened was I simulated an incoming call (7777), the first agent let the call timeout, and the second agent got the short ring, then it went back to the first agent and I hung up. The short ring lasts for approximately half a second.

I’d appreciate any tips on where to look or what to try to resolve this. Thanks!

– Executing [7777@from-internal:1] Goto(“SIP/315-091bae88”, “from-pstn|s|1”) in new stack
– Goto (from-pstn,s,1)
– Executing [s@from-pstn:1] Set(“SIP/315-091bae88”, “__FROM_DID=s”) in new stack
– Executing [s@from-pstn:2] GotoIf(“SIP/315-091bae88”, “1 ?cidok”) in new stack
– Goto (from-pstn,s,4)
– Executing [s@from-pstn:4] NoOp(“SIP/315-091bae88”, “CallerID is “device” <315>”) in new stack
– Executing [s@from-pstn:5] Goto(“SIP/315-091bae88”, “app-announcement-3|s|1”) in new stack
– Goto (app-announcement-3,s,1)
– Executing [s@app-announcement-3:1] GotoIf(“SIP/315-091bae88”, “0?begin”) in new stack
– Executing [s@app-announcement-3:2] Answer(“SIP/315-091bae88”, “”) in new stack
– Executing [s@app-announcement-3:3] Wait(“SIP/315-091bae88”, “1”) in new stack
– Executing [s@app-announcement-3:4] NoOp(“SIP/315-091bae88”, “Playing announcement Greeting”) in new stack
– Executing [s@app-announcement-3:5] Playback(“SIP/315-091bae88”, “custom/Greeting|noanswer”) in new stack
– Playing ‘custom/Greeting’ (language ‘en’)
– Executing [s@app-announcement-3:6] Goto(“SIP/315-091bae88”, “timeconditions|1|1”) in new stack
– Goto (timeconditions,1,1)
– Executing [1@timeconditions:1] GotoIfTime(“SIP/315-091bae88”, “08:00-19:00|mon-fri||?ext-queues|700|1”) in new stack
– Goto (ext-queues,700,1)
– Executing [700@ext-queues:1] Macro(“SIP/315-091bae88”, “user-callerid|”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“SIP/315-091bae88”, “user-callerid: device 315”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/315-091bae88”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“SIP/315-091bae88”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] GotoIf(“SIP/315-091bae88”, “0?start”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/315-091bae88”, “REALCALLERIDNUM=315”) in new stack
– Executing [s@macro-user-callerid:6] NoOp(“SIP/315-091bae88”, “REALCALLERIDNUM is 315”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/315-091bae88”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:8] Set(“SIP/315-091bae88”, “AMPUSERCIDNAME=Nick Bright”) in new stack
– Executing [s@macro-user-callerid:9] GotoIf(“SIP/315-091bae88”, “0?report”) in new stack
– Executing [s@macro-user-callerid:10] Set(“SIP/315-091bae88”, “AMPUSERCID=315”) in new stack
– Executing [s@macro-user-callerid:11] Set(“SIP/315-091bae88”, “CALLERID(all)=“Nick Bright” <315>”) in new stack
– Executing [s@macro-user-callerid:12] Set(“SIP/315-091bae88”, “REALCALLERIDNUM=315”) in new stack
– Executing [s@macro-user-callerid:13] NoOp(“SIP/315-091bae88”, “TTL: ARG1: “) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“SIP/315-091bae88”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:15] Set(“SIP/315-091bae88”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:16] GotoIf(“SIP/315-091bae88”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“SIP/315-091bae88”, “Using CallerID “Nick Bright” <315>”) in new stack
– Executing [700@ext-queues:2] Answer(“SIP/315-091bae88”, “”) in new stack
– Executing [700@ext-queues:3] Set(“SIP/315-091bae88”, “__BLKVM_OVERRIDE=BLKVM/700/SIP/315-091bae88”) in new stack
– Executing [700@ext-queues:4] Set(“SIP/315-091bae88”, “__BLKVM_BASE=700”) in new stack
– Executing [700@ext-queues:5] Set(“SIP/315-091bae88”, “DB(BLKVM/700/SIP/315-091bae88)=TRUE”) in new stack
– Executing [700@ext-queues:6] Set(“SIP/315-091bae88”, “_DIAL_OPTIONS=trM(auto-blkvm)”) in new stack
– Executing [700@ext-queues:7] Set(“SIP/315-091bae88”, “__NODEST=700”) in new stack
– Executing [700@ext-queues:8] Set(“SIP/315-091bae88”, “MONITOR_FILENAME=/var/spool/asterisk/monitor/q700-20080305-124449-1204742686.99”) in new stack
– Executing [700@ext-queues:9] Playback(“SIP/315-091bae88”, “custom/QueueGreeting”) in new stack
– Playing ‘custom/QueueGreeting’ (language ‘en’)
– Executing [700@ext-queues:10] Queue(“SIP/315-091bae88”, “700|t||”) in new stack
– Started music on hold, class ‘default’, on SIP/315-091bae88
– Executing [314@from-internal:1] Macro(“Local/314@from-internal-7d1e,2”, “exten-vm|314|314”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“Local/314@from-internal-7d1e,2”, “user-callerid”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Local/314@from-internal-7d1e,2”, “user-callerid: Nick Bright 315”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/314@from-internal-7d1e,2”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/314@from-internal-7d1e,2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Local/314@from-internal-7d1e,2”, “TTL: 64 ARG1: 314”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Local/314@from-internal-7d1e,2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:15] Set(“Local/314@from-internal-7d1e,2”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:16] GotoIf(“Local/314@from-internal-7d1e,2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Local/314@from-internal-7d1e,2”, “Using CallerID “Nick Bright” <315>”) in new stack
– Executing [s@macro-exten-vm:2] Set(“Local/314@from-internal-7d1e,2”, “FROMCONTEXT=exten-vm”) in new stack
– Executing [s@macro-exten-vm:3] Set(“Local/314@from-internal-7d1e,2”, “VMBOX=314”) in new stack
– Executing [s@macro-exten-vm:4] Set(“Local/314@from-internal-7d1e,2”, “EXTTOCALL=314”) in new stack
– Executing [s@macro-exten-vm:5] Set(“Local/314@from-internal-7d1e,2”, “CFUEXT=”) in new stack
– Executing [s@macro-exten-vm:6] Set(“Local/314@from-internal-7d1e,2”, “CFBEXT=”) in new stack
– Executing [s@macro-exten-vm:7] Set(“Local/314@from-internal-7d1e,2”, “RT=30”) in new stack
– Executing [s@macro-exten-vm:8] Macro(“Local/314@from-internal-7d1e,2”, “record-enable|314|IN”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“Local/314@from-internal-7d1e,2”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] AGI(“Local/314@from-internal-7d1e,2”, “recordingcheck|20080305-124454|1204742694.101”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck|20080305-124454|1204742694.101: Inbound recording not enabled
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] NoOp(“Local/314@from-internal-7d1e,2”, “No recording needed”) in new stack
– Executing [s@macro-exten-vm:9] Macro(“Local/314@from-internal-7d1e,2”, “dial|30|trM(auto-blkvm)|314”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Local/314@from-internal-7d1e,2”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“Local/314@from-internal-7d1e,2”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
dialparties.agi: Caller ID name is ‘Nick Bright’ number is '315’
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 314 to extension map
– dialparties.agi: Extension 314 cf is disabled
– dialparties.agi: Extension 314 do not disturb is disabled
dialparties.agi: Extension 314 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 314
– dialparties.agi: dbset CALLTRACE/314 to 315
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:10] Dial(“Local/314@from-internal-7d1e,2”, “SIP/314|30|trM(auto-blkvm)”) in new stack
– Called 314
– Local/314@from-internal-7d1e,1 is ringing
– SIP/314-091c6d50 is ringing
– Nobody picked up in 30000 ms
– Executing [s@macro-dial:11] Set(“Local/314@from-internal-7d1e,2”, “DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:10] Set(“Local/314@from-internal-7d1e,2”, “SV_DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:11] GosubIf(“Local/314@from-internal-7d1e,2”, “0?docfu|1”) in new stack
– Executing [s@macro-exten-vm:12] GosubIf(“Local/314@from-internal-7d1e,2”, “0?docfb|1”) in new stack
– Executing [s@macro-exten-vm:13] Set(“Local/314@from-internal-7d1e,2”, “DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:14] NoOp(“Local/314@from-internal-7d1e,2”, “Voicemail is 314”) in new stack
– Executing [s@macro-exten-vm:15] GotoIf(“Local/314@from-internal-7d1e,2”, “0?s-NOANSWER|1”) in new stack
– Executing [s@macro-exten-vm:16] NoOp(“Local/314@from-internal-7d1e,2”, “Sending to Voicemail box 314”) in new stack
– Executing [s@macro-exten-vm:17] Macro(“Local/314@from-internal-7d1e,2”, “vm|314|NOANSWER”) in new stack
– Executing [s@macro-vm:1] Macro(“Local/314@from-internal-7d1e,2”, “user-callerid|SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Local/314@from-internal-7d1e,2”, “user-callerid: Nick Bright 315”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/314@from-internal-7d1e,2”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/314@from-internal-7d1e,2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Local/314@from-internal-7d1e,2”, “TTL: 63 ARG1: SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Local/314@from-internal-7d1e,2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Local/314@from-internal-7d1e,2”, “Using CallerID “Nick Bright” <315>”) in new stack
– Executing [s@macro-vm:2] Set(“Local/314@from-internal-7d1e,2”, “VMGAIN=”””) in new stack
– Executing [s@macro-vm:3] GotoIf(“Local/314@from-internal-7d1e,2”, “0?vmx|1”) in new stack
– Executing [s@macro-vm:4] NoOp(“Local/314@from-internal-7d1e,2”, "CAME FROM: 700 - Blocking VM cause of key: ") in new stack
– Executing [314@from-internal:2] Hangup(“Local/314@from-internal-7d1e,2”, “”) in new stack
== Spawn extension (from-internal, 314, 2) exited non-zero on ‘Local/314@from-internal-7d1e,2’
– Executing [h@from-internal:1] Macro(“Local/314@from-internal-7d1e,2”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] ResetCDR(“Local/314@from-internal-7d1e,2”, “w”) in new stack
– Executing [s@macro-hangupcall:2] NoCDR(“Local/314@from-internal-7d1e,2”, “”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“Local/314@from-internal-7d1e,2”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing [s@macro-hangupcall:6] GotoIf(“Local/314@from-internal-7d1e,2”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,9)
– Executing [s@macro-hangupcall:9] GotoIf(“Local/314@from-internal-7d1e,2”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Hangup(“Local/314@from-internal-7d1e,2”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/314@from-internal-7d1e,2’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/314@from-internal-7d1e,2’
– Nobody picked up in 30000 ms
– Executing [308@from-internal:1] Macro(“Local/308@from-internal-830e,2”, “exten-vm|308|308”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“Local/308@from-internal-830e,2”, “user-callerid”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Local/308@from-internal-830e,2”, “user-callerid: Nick Bright 315”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/308@from-internal-830e,2”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/308@from-internal-830e,2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Local/308@from-internal-830e,2”, “TTL: 64 ARG1: 308”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Local/308@from-internal-830e,2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:15] Set(“Local/308@from-internal-830e,2”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:16] GotoIf(“Local/308@from-internal-830e,2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Local/308@from-internal-830e,2”, “Using CallerID “Nick Bright” <315>”) in new stack
– Executing [s@macro-exten-vm:2] Set(“Local/308@from-internal-830e,2”, “FROMCONTEXT=exten-vm”) in new stack
– Executing [s@macro-exten-vm:3] Set(“Local/308@from-internal-830e,2”, “VMBOX=308”) in new stack
– Executing [s@macro-exten-vm:4] Set(“Local/308@from-internal-830e,2”, “EXTTOCALL=308”) in new stack
– Executing [s@macro-exten-vm:5] Set(“Local/308@from-internal-830e,2”, “CFUEXT=”) in new stack
– Executing [s@macro-exten-vm:6] Set(“Local/308@from-internal-830e,2”, “CFBEXT=”) in new stack
– Executing [s@macro-exten-vm:7] Set(“Local/308@from-internal-830e,2”, “RT=30”) in new stack
– Executing [s@macro-exten-vm:8] Macro(“Local/308@from-internal-830e,2”, “record-enable|308|IN”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“Local/308@from-internal-830e,2”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] AGI(“Local/308@from-internal-830e,2”, “recordingcheck|20080305-124524|1204742724.104”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck|20080305-124524|1204742724.104: Inbound recording not enabled
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] NoOp(“Local/308@from-internal-830e,2”, “No recording needed”) in new stack
– Executing [s@macro-exten-vm:9] Macro(“Local/308@from-internal-830e,2”, “dial|30|trM(auto-blkvm)|308”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Local/308@from-internal-830e,2”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“Local/308@from-internal-830e,2”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
dialparties.agi: Caller ID name is ‘Nick Bright’ number is '315’
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 308 to extension map
– dialparties.agi: Extension 308 cf is disabled
– dialparties.agi: Extension 308 do not disturb is disabled
– dialparties.agi: dbset CALLTRACE/308 to 315
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:10] Dial(“Local/308@from-internal-830e,2”, “SIP/308|30|trM(auto-blkvm)”) in new stack
– Called 308
– Local/308@from-internal-830e,1 is ringing
– Nobody picked up in 30000 ms
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/308@from-internal-830e,2’ in macro ‘dial’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/308@from-internal-830e,2’ in macro ‘exten-vm’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/308@from-internal-830e,2’
– Executing [h@macro-dial:1] Macro(“Local/308@from-internal-830e,2”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] ResetCDR(“Local/308@from-internal-830e,2”, “w”) in new stack
– Executing [s@macro-hangupcall:2] NoCDR(“Local/308@from-internal-830e,2”, “”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“Local/308@from-internal-830e,2”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing [s@macro-hangupcall:6] GotoIf(“Local/308@from-internal-830e,2”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,9)
– Executing [s@macro-hangupcall:9] GotoIf(“Local/308@from-internal-830e,2”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Hangup(“Local/308@from-internal-830e,2”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/308@from-internal-830e,2’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/308@from-internal-830e,2’
– Stopped music on hold on SIP/315-091bae88
– Playing ‘queue-youarenext’ (language ‘en’)
– Told SIP/315-091bae88 in 700 their queue position (which was 1)
– Playing ‘queue-thankyou’ (language ‘en’)
– Started music on hold, class ‘default’, on SIP/315-091bae88
– Executing [314@from-internal:1] Macro(“Local/314@from-internal-3e89,2”, “exten-vm|314|314”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“Local/314@from-internal-3e89,2”, “user-callerid”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Local/314@from-internal-3e89,2”, “user-callerid: Nick Bright 315”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/314@from-internal-3e89,2”, “AMPUSER=315”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/314@from-internal-3e89,2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Local/314@from-internal-3e89,2”, “TTL: 64 ARG1: 314”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Local/314@from-internal-3e89,2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:15] Set(“Local/314@from-internal-3e89,2”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:16] GotoIf(“Local/314@from-internal-3e89,2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Local/314@from-internal-3e89,2”, “Using CallerID “Nick Bright” <315>”) in new stack
– Executing [s@macro-exten-vm:2] Set(“Local/314@from-internal-3e89,2”, “FROMCONTEXT=exten-vm”) in new stack
– Executing [s@macro-exten-vm:3] Set(“Local/314@from-internal-3e89,2”, “VMBOX=314”) in new stack
– Executing [s@macro-exten-vm:4] Set(“Local/314@from-internal-3e89,2”, “EXTTOCALL=314”) in new stack
– Executing [s@macro-exten-vm:5] Set(“Local/314@from-internal-3e89,2”, “CFUEXT=”) in new stack
– Executing [s@macro-exten-vm:6] Set(“Local/314@from-internal-3e89,2”, “CFBEXT=”) in new stack
– Executing [s@macro-exten-vm:7] Set(“Local/314@from-internal-3e89,2”, “RT=30”) in new stack
– Executing [s@macro-exten-vm:8] Macro(“Local/314@from-internal-3e89,2”, “record-enable|314|IN”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“Local/314@from-internal-3e89,2”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] AGI(“Local/314@from-internal-3e89,2”, “recordingcheck|20080305-124542|1204742742.107”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck|20080305-124542|1204742742.107: Inbound recording not enabled
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] NoOp(“Local/314@from-internal-3e89,2”, “No recording needed”) in new stack
– Executing [s@macro-exten-vm:9] Macro(“Local/314@from-internal-3e89,2”, “dial|30|trM(auto-blkvm)|314”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Local/314@from-internal-3e89,2”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“Local/314@from-internal-3e89,2”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
dialparties.agi: Caller ID name is ‘Nick Bright’ number is '315’
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 314 to extension map
– dialparties.agi: Extension 314 cf is disabled
– dialparties.agi: Extension 314 do not disturb is disabled
dialparties.agi: Extension 314 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 314
– dialparties.agi: dbset CALLTRACE/314 to 315
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:10] Dial(“Local/314@from-internal-3e89,2”, “SIP/314|30|trM(auto-blkvm)”) in new stack
– Called 314
– Local/314@from-internal-3e89,1 is ringing
– SIP/314-09141378 is ringing
– Stopped music on hold on SIP/315-091bae88
== Spawn extension (ext-queues, 700, 10) exited non-zero on ‘SIP/315-091bae88’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/314@from-internal-3e89,2’ in macro ‘dial’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/314@from-internal-3e89,2’ in macro ‘exten-vm’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘Local/314@from-internal-3e89,2’
– Executing [h@macro-dial:1] Macro(“Local/314@from-internal-3e89,2”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] ResetCDR(“Local/314@from-internal-3e89,2”, “w”) in new stack
– Executing [s@macro-hangupcall:2] NoCDR(“Local/314@from-internal-3e89,2”, “”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“Local/314@from-internal-3e89,2”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing [s@macro-hangupcall:6] GotoIf(“Local/314@from-internal-3e89,2”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,9)
– Executing [s@macro-hangupcall:9] GotoIf(“Local/314@from-internal-3e89,2”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Hangup(“Local/314@from-internal-3e89,2”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/314@from-internal-3e89,2’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/314@from-internal-3e89,2’

from the trace - the dialplan sees it as no one was able to answer on the subsequent call. There isn’t any immediate sign that something in the dialplan stopped it like one of the queue parameters. As a next step, I would turn on sip debug for the extension in question and see if the phone itself is prematurely rejecting the call for some reason.

I’ll take a look at the SIP debugging, it’s possible it could be related to the phones - all are the same model (Aastra 480i) using the latest firmware. The problem occurs randomly on all SIP extensions; so far the only way I’ve seen to get it to stop happening is to reboot the whole PBX.