Just gone live with 18 phones - HAVING TROUBLE!

Hi All,

I need help.

Just moved away from traditional phone lines to SIP with FReepbx 2.10.

For the most part everything is working.

We have IVR and call queue.

Randomly - sometimes when transfering to another phone - the phone will not accept the call. Stating in the log

Everyone is busy/congested at this time

…even though they are not busy.

There are no concurrency limits or anything on the route or trunk.

Im not sure where to start trying to fix this.

Heres a sip log.

Thanks in advance.

– Called SIP/106
– Connected line update to SIP/501-00000663 prevented.
== Everyone is busy/congested at this time (1:0/0/1)
– Executing [s@macro-dial-one:43] ExecIf(“SIP/501-00000663”, “0?Set(DIALSTATUS=)”) in new stack
– Executing [s@macro-dial-one:44] GosubIf(“SIP/501-00000663”, “0?s-CHANUNAVAIL,1()”) in new stack
– Executing [s@macro-dial-one:45] MacroExit(“SIP/501-00000663”, “”) in new stack
– Executing [s@macro-exten-vm:15] Set(“SIP/501-00000663”, “SV_DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:16] GosubIf(“SIP/501-00000663”, “0?docfu,1()”) in new stack
– Executing [s@macro-exten-vm:17] GosubIf(“SIP/501-00000663”, “0?docfb,1()”) in new stack
– Executing [s@macro-exten-vm:18] Set(“SIP/501-00000663”, “DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:19] ExecIf(“SIP/501-00000663”, “0?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:20] GotoIf(“SIP/501-00000663”, “1?s-CHANUNAVAIL,1”) in new stack
– Goto (macro-exten-vm,s-CHANUNAVAIL,1)
– Executing [s-CHANUNAVAIL@macro-exten-vm:1] GotoIf(“SIP/501-00000663”, “0?exit,1”) in new stack
– Executing [s-CHANUNAVAIL@macro-exten-vm:2] PlayTones(“SIP/501-00000663”, “congestion”) in new stack
– Executing [s-CHANUNAVAIL@macro-exten-vm:3] Congestion(“SIP/501-00000663”, “10”) in new stack
== Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 3) exited non-zero on ‘SIP/501-00000663’ in macro ‘exten-vm’
== Spawn extension (sidekick-AQL, 106, 2) exited non-zero on ‘SIP/501-00000663’
– Executing [h@sidekick-AQL:1] Macro(“SIP/501-00000663”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/501-00000663”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [s@macro-hangupcall:3] ExecIf(“SIP/501-00000663”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:4] Hangup(“SIP/501-00000663”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/501-00000663’ in macro ‘hangupcall’
== Spawn extension (sidekick-AQL, h, 1) exited non-zero on ‘SIP/501-00000663’
– Executing [100@ext-queues:9] Set(“SIP/003064-0000065e”, “__MOHCLASS=JAYP-HOLD-MUSIC”) in new stack
– Executing [100@ext-queues:10] Set(“SIP/003064-0000065e”, “__CWIGNORE=TRUE”) in new stack
– Executing [100@ext-queues:11] QueueLog(“SIP/003064-0000065e”, “100,1373559697.1808,NONE,DID,441454615050”) in new stack
– Executing [100@ext-queues:12] Queue(“SIP/003064-0000065e”, “100,t,”) in new stack
– Started music on hold, class ‘LifeStyle-Hold-Music’, on SIP/003064-0000065e
– Executing [600@from-queue:1] Set(“Local/600@from-queue-00000059;2”, “QAGENT=600”) in new stack
– Called Local/600@from-queue/n
– Executing [600@from-queue:2] Goto(“Local/600@from-queue-00000059;2”, “100,1”) in new stack
– Goto (from-queue,100,1)
– Executing [100@from-queue:1] Goto(“Local/600@from-queue-00000059;2”, “from-internal,600,1”) in new stack
– Goto (from-internal,600,1)
– Executing [600@from-internal:1] Macro(“Local/600@from-queue-00000059;2”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“Local/600@from-queue-00000059;2”, “AMPUSER=07824896414”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“Local/600@from-queue-00000059;2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] GotoIf(“Local/600@from-queue-00000059;2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:14] Set(“Local/600@from-queue-00000059;2”, “__TTL=62”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“Local/600@from-queue-00000059;2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“Local/600@from-queue-00000059;2”, “CALLERID(number)=07824896414”) in new stack
– Executing [s@macro-user-callerid:27] Set(“Local/600@from-queue-00000059;2”, “CALLERID(name)=- LifeStyle Sales: 07824896414”) in new stack
– Executing [s@macro-user-callerid:28] Set(“Local/600@from-queue-00000059;2”, “CHANNEL(language)=en”) in new stack
– Executing [600@from-internal:2] Macro(“Local/600@from-queue-00000059;2”, “blkvm-setifempty,”) in new stack
– Executing [s@macro-blkvm-setifempty:1] GotoIf(“Local/600@from-queue-00000059;2”, “0?init”) in new stack
– Executing [s@macro-blkvm-setifempty:2] Set(“Local/600@from-queue-00000059;2”, “GOSUB_RETVAL=TRUE”) in new stack
– Executing [s@macro-blkvm-setifempty:3] MacroExit(“Local/600@from-queue-00000059;2”, “”) in new stack
– Executing [600@from-internal:3] GotoIf(“Local/600@from-queue-00000059;2”, “1?skipov”) in new stack
– Goto (from-internal,600,6)
– Executing [600@from-internal:6] Set(“Local/600@from-queue-00000059;2”, “RRNODEST=100”) in new stack
– Executing [600@from-internal:7] Set(“Local/600@from-queue-00000059;2”, “__NODEST=600”) in new stack
– Executing [600@from-internal:8] GosubIf(“Local/600@from-queue-00000059;2”, “0?sub-rgsetcid,s,1()”) in new stack
– Executing [600@from-internal:9] Set(“Local/600@from-queue-00000059;2”, “__CWIGNORE=TRUE”) in new stack
– Executing [600@from-internal:10] Gosub(“Local/600@from-queue-00000059;2”, “sub-record-check,s,1(rg,600,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“Local/600@from-queue-00000059;2”, “1?check”) in new stack
– Goto (sub-record-check,s,6)
– Executing [s@sub-record-check:6] Set(“Local/600@from-queue-00000059;2”, “__MON_FMT=WAV”) in new stack
– Executing [s@sub-record-check:7] GotoIf(“Local/600@from-queue-00000059;2”, “0?next”) in new stack
– Executing [s@sub-record-check:8] Set(“Local/600@from-queue-00000059;2”, “CDR(recordingfile)=q-100-07824896414-20130711-172211-1373559697.1808.WAV”) in new stack
– Executing [s@sub-record-check:9] Return(“Local/600@from-queue-00000059;2”, “”) in new stack
– Executing [600@from-internal:11] Set(“Local/600@from-queue-00000059;2”, “RingGroupMethod=ringall”) in new stack
– Executing [600@from-internal:12] GotoIf(“Local/600@from-queue-00000059;2”, “1?DIALGRP”) in new stack
– Goto (from-internal,600,16)
– Executing [600@from-internal:16] Macro(“Local/600@from-queue-00000059;2”, “dial,15,trM(auto-blkvm),102-103-104-105-106-107-108-110-111-112-109”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Local/600@from-queue-00000059;2”, “0?dial”) in new stack
– Executing [s@macro-dial:2] SetMusicOnHold(“Local/600@from-queue-00000059;2”, “JAYP-HOLD-MUSIC”) in new stack
– Executing [s@macro-dial:3] AGI(“Local/600@from-queue-00000059;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 ‘- LifeStyle Sales: 07824896414’ number is ‘07824896414’
> dialparties.agi: Setting Alert-Info: SIPCENTRIC
– AGI Script Executing Application: (SIPAddHeader) Options: (Alert-Info:SIPCENTRIC)
> dialparties.agi: USE_CONFIRMATION: ‘FALSE’
> dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is ‘ringall’
– dialparties.agi: Added extension 102 to extension map
– dialparties.agi: Added extension 103 to extension map
– dialparties.agi: Added extension 104 to extension map
– dialparties.agi: Added extension 105 to extension map
– dialparties.agi: Added extension 106 to extension map
– dialparties.agi: Added extension 107 to extension map
– dialparties.agi: Added extension 108 to extension map
– dialparties.agi: Added extension 110 to extension map
– dialparties.agi: Added extension 111 to extension map
– dialparties.agi: Added extension 112 to extension map
– dialparties.agi: Added extension 109 to extension map
– dialparties.agi: Extension 102 cf is disabled
– dialparties.agi: Extension 103 cf is disabled
– dialparties.agi: Extension 104 cf is disabled
– dialparties.agi: Extension 105 cf is disabled
– dialparties.agi: Extension 106 cf is disabled
– dialparties.agi: Extension 107 cf is disabled
– dialparties.agi: Extension 108 cf is disabled
– dialparties.agi: Extension 110 cf is disabled
– dialparties.agi: Extension 111 cf is disabled
– dialparties.agi: Extension 112 cf is disabled
– dialparties.agi: Extension 109 cf is disabled
– dialparties.agi: Extension 102 do not disturb is disabled
– dialparties.agi: Extension 103 do not disturb is disabled
– dialparties.agi: Extension 104 do not disturb is disabled
– dialparties.agi: Extension 105 do not disturb is disabled
– dialparties.agi: Extension 106 do not disturb is disabled
– dialparties.agi: Extension 107 do not disturb is disabled
– dialparties.agi: Extension 108 do not disturb is disabled
– dialparties.agi: Extension 110 do not disturb is disabled
– dialparties.agi: Extension 111 do not disturb is disabled
– dialparties.agi: Extension 112 do not disturb is disabled
– dialparties.agi: Extension 109 do not disturb is disabled
> dialparties.agi: extnum 102 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 102 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 102
– dialparties.agi: dbset CALLTRACE/102 to 07824896414
> dialparties.agi: extnum 103 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 103 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 103
– dialparties.agi: dbset CALLTRACE/103 to 07824896414
> dialparties.agi: extnum 104 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 104 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 104
– dialparties.agi: dbset CALLTRACE/104 to 07824896414
> dialparties.agi: extnum 105 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 105 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 105
– dialparties.agi: dbset CALLTRACE/105 to 07824896414
> dialparties.agi: extnum 106 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 106 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 106
– dialparties.agi: dbset CALLTRACE/106 to 07824896414
> dialparties.agi: extnum 107 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 107 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 107
– dialparties.agi: dbset CALLTRACE/107 to 07824896414
> dialparties.agi: extnum 108 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 108 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 108
– dialparties.agi: dbset CALLTRACE/108 to 07824896414
> dialparties.agi: extnum 110 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 110 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 110
– dialparties.agi: dbset CALLTRACE/110 to 07824896414
> dialparties.agi: extnum 111 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 111 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 111
– dialparties.agi: dbset CALLTRACE/111 to 07824896414
> dialparties.agi: extnum 112 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 112 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 112
– dialparties.agi: dbset CALLTRACE/112 to 07824896414
> dialparties.agi: extnum 109 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 109 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 109
– dialparties.agi: dbset CALLTRACE/109 to 07824896414
– dialparties.agi: Filtered ARG3: 102-103-104-105-106-107-108-110-111-112-109
> dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: trM(auto-blkvm)
> dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: trM(auto-blkvm)
– <Local/600@from-queue-00000059;2>AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:7] Dial(“Local/600@from-queue-00000059;2”, “SIP/102&SIP/103&SIP/104&SIP/105&SIP/106&SIP/107&SIP/108&SIP/110&SIP/111&SIP/112&SIP/109,15,trM(auto-blkvm)”) in new stack
== Using SIP RTP TOS bits 184

or from FreePBX, Reports - Asterisk Info - SIP and watch to see if anything goes to UNREACHABLE - Sounds like you are having transient connectivity problems - Are all the phones on the same subnet as the Asterisk? I have seen this with remote phones when the connections are sub-optimal.

Greg