Users phone rings only once in call queue

I have users whos phones only ring once with a call comes to them from the queue.

The CDR

says:

  1. 2009-07-27 13:21:00 Local/[email protected]… 334XXXXXX "SupportJOHNSON XXXN " <334XXXXXX4> 315 NO ANSWER 00:01

Here is the debug:

  1. 2009-07-27 13:21:00 Local/[email protected]… 3343893584 "SupportJOHNSON JEAN " <3343893584> 315 NO ANSWER 00:01

[Jul 27 13:21:00] VERBOSE[29622] logger.c: – Nobody picked up in 15000 ms
[Jul 27 13:21:00] WARNING[29622] channel.c: No channel type registered for ‘ZAP’
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:1] Macro(“Local/[email protected],2”, “exten-vm|315|315”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:1] Macro(“Local/[email protected],2”, “user-callerid”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:1] Set(“Local/[email protected],2”, “AMPUSER=334XXXXXX”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:2] GotoIf(“Local/[email protected],2”, “1?report”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Goto (macro-user-callerid,s,10)
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:10] GotoIf(“Local/[email protected],2”, “0?continue”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:11] Set(“Local/[email protected],2”, “__TTL=63”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:12] GotoIf(“Local/[email protected],2”, “1?continue”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Goto (macro-user-callerid,s,19)
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:19] NoOp(“Local/[email protected],2”, "Using CallerID “SupportJOHNSON JEAN " <334XXXXXX4>”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Noop
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Macro
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:2] Set(“Local/[email protected],2”, “RingGroupMethod=none”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:3] Set(“Local/[email protected],2”, “VMBOX=315”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:4] Set(“Local/[email protected],2”, “EXTTOCALL=315”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] DEBUG[29678] func_db.c: DB: CFU/315 not found in database.
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:5] Set(“Local/[email protected],2”, “CFUEXT=”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] DEBUG[29678] func_db.c: DB: CFB/315 not found in database.
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:6] Set(“Local/[email protected],2”, “CFBEXT=”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:7] Set(“Local/[email protected],2”, “RT=15”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Set
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:8] Macro(“Local/[email protected],2”, “record-enable|315|IN”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:1] GotoIf(“Local/[email protected],2”, “1?check”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Goto (macro-record-enable,s,4)
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:4] AGI(“Local/[email protected],2”, “recordingcheck|20090727-132100|1248718860.6277”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul 27 13:21:00] VERBOSE[29678] logger.c: recordingcheck|20090727-132100|1248718860.6277: Inbound recording not enabled
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – AGI Script recordingcheck completed, returning 0
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: AGI
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:5] MacroExit(“Local/[email protected],2”, “”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: Macro
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:9] Macro(“Local/[email protected],2”, “dial|15|trM(auto-blkvm)|315”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:1] GotoIf(“Local/[email protected],2”, “0?dial”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:2] SetMusicOnHold(“Local/[email protected],2”, “default”) in new stack
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: SetMusicOnHold
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:3] AGI(“Local/[email protected],2”, “dialparties.agi”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jul 27 13:21:00] VERBOSE[29678] logger.c: dialparties.agi: Starting New Dialparties.agi
[Jul 27 13:21:00] VERBOSE[29681] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jul 27 13:21:00] VERBOSE[29681] logger.c: Found
[Jul 27 13:21:00] VERBOSE[29681] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jul 27 13:21:00] VERBOSE[29681] logger.c: Found
[Jul 27 13:21:00] VERBOSE[29681] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jul 27 13:21:00] VERBOSE[29681] logger.c: Found
[Jul 27 13:21:00] VERBOSE[29681] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Jul 27 13:21:00] VERBOSE[29678] logger.c: dialparties.agi: Caller ID name is ‘SupportJOHNSON XXXN’ number is ‘334XXXXXX’
[Jul 27 13:21:00] VERBOSE[29678] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: Added extension 315 to extension map
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: Extension 315 cf is disabled
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: Extension 315 do not disturb is disabled
[Jul 27 13:21:00] VERBOSE[29678] logger.c: dialparties.agi: Extension 315 has ExtensionState: 0
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: Checking CW and CFB status for extension 315
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: dbset CALLTRACE/315 to 334XXXXXX
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – dialparties.agi: Filtered ARG3: 315
[Jul 27 13:21:00] VERBOSE[29681] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – AGI Script dialparties.agi completed, returning 0
[Jul 27 13:21:00] DEBUG[29678] app_macro.c: Executed application: AGI
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [[email protected]:7] Dial(“Local/[email protected],2”, “SIP/315|15|trM(auto-blkvm)”) in new stack
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 313
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 301 (queued)
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 509 (queued)
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 349
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 310
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 341
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 335
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 308
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 320
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 319
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Called 315
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 317
[Jul 27 13:21:00] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Ringing for Notify User 510
[Jul 27 13:21:00] VERBOSE[29622] logger.c: – Local/[email protected],1 is ringing
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – SIP/315-09c26d20 is ringing
[Jul 27 13:21:01] VERBOSE[29622] logger.c: – Nobody picked up in 15000 ms
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘Local/[email protected],2’ in macro ‘dial’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extension (macro-exten-vm, s, 9) exited non-zero on ‘Local/[email protected],2’ in macro ‘exten-vm’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extension (from-internal, 315, 1) exited non-zero on ‘Local/[email protected],2’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:1] Macro(“Local/[email protected],2”, “hangupcall”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:1] ResetCDR(“Local/[email protected],2”, “vw”) in new stack
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 313
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 301 (queued)
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 509 (queued)
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 349
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 310
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 341
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 335
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 308
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 320
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 319
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 317
[Jul 27 13:21:01] VERBOSE[2890] logger.c: Extension Changed 315[ext-local] new state Idle for Notify User 510
[Jul 27 13:21:01] DEBUG[29678] app_macro.c: Executed application: ResetCDR
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:2] NoCDR(“Local/[email protected],2”, “”) in new stack
[Jul 27 13:21:01] DEBUG[29678] app_macro.c: Executed application: NoCDR
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:3] GotoIf(“Local/[email protected],2”, “1?skiprg”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Goto (macro-hangupcall,s,6)
[Jul 27 13:21:01] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:6] GotoIf(“Local/[email protected],2”, “1?skipblkvm”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Goto (macro-hangupcall,s,9)
[Jul 27 13:21:01] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:9] GotoIf(“Local/[email protected],2”, “1?theend”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Goto (macro-hangupcall,s,11)
[Jul 27 13:21:01] DEBUG[29678] app_macro.c: Executed application: GotoIf
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [[email protected]:11] Hangup(“Local/[email protected],2”, “”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extensiion (macro-hangupcall, s, 11) exited non-zero on ‘Local/[email protected],2’ in macro ‘hangupcall’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extension (macro-dial, h, 1) exited non-zero on ‘Local/[email protected],2’

I have this same problem, and am attempting to debug. Anyone have any other experience with this?

Version is Trixbox 2.2.13

I found this: http://76.164.171.234/svn/asterisk?view=revision&revision=138694