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/315@… 334XXXXXX "SupportJOHNSON XXXN " <334XXXXXX4> 315 NO ANSWER 00:01

Here is the debug:

  1. 2009-07-27 13:21:00 Local/315@… 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 [315@from-internal:1] Macro(“Local/315@from-internal-4d3a,2”, “exten-vm|315|315”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [s@macro-exten-vm:1] Macro(“Local/315@from-internal-4d3a,2”, “user-callerid”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [s@macro-user-callerid:1] Set(“Local/315@from-internal-4d3a,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 [s@macro-user-callerid:2] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-user-callerid:10] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-user-callerid:11] Set(“Local/315@from-internal-4d3a,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 [s@macro-user-callerid:12] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-user-callerid:19] NoOp(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:2] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:3] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:4] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:5] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:6] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:7] Set(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:8] Macro(“Local/315@from-internal-4d3a,2”, “record-enable|315|IN”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-record-enable:4] AGI(“Local/315@from-internal-4d3a,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 [s@macro-record-enable:5] MacroExit(“Local/315@from-internal-4d3a,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 [s@macro-exten-vm:9] Macro(“Local/315@from-internal-4d3a,2”, “dial|15|trM(auto-blkvm)|315”) in new stack
[Jul 27 13:21:00] VERBOSE[29678] logger.c: – Executing [s@macro-dial:1] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-dial:2] SetMusicOnHold(“Local/315@from-internal-4d3a,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 [s@macro-dial:3] AGI(“Local/315@from-internal-4d3a,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 [s@macro-dial:7] Dial(“Local/315@from-internal-4d3a,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/315@from-internal-4d3a,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/315@from-internal-4d3a,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/315@from-internal-4d3a,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/315@from-internal-4d3a,2’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [h@macro-dial:1] Macro(“Local/315@from-internal-4d3a,2”, “hangupcall”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“Local/315@from-internal-4d3a,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 [s@macro-hangupcall:2] NoCDR(“Local/315@from-internal-4d3a,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 [s@macro-hangupcall:3] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-hangupcall:6] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-hangupcall:9] GotoIf(“Local/315@from-internal-4d3a,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 [s@macro-hangupcall:11] Hangup(“Local/315@from-internal-4d3a,2”, “”) in new stack
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extensiion (macro-hangupcall, s, 11) exited non-zero on ‘Local/315@from-internal-4d3a,2’ in macro ‘hangupcall’
[Jul 27 13:21:01] VERBOSE[29678] logger.c: == Spawn extension (macro-dial, h, 1) exited non-zero on ‘Local/315@from-internal-4d3a,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