SIP Softphones (3CX) Intermittently Go To Busy Voicemail When User Is Not On Phone

General Help
1

Hello Everyone,

I have an intermittent problem and it’s difficult to catch so I apologize if my log files are not adequate at this time. We have three Windows 7 x64 Ultimate machines (up-to-date) running 3CX (version 6.0.20943.0) softphones. Once in a while when a call is transferred to the 3CX softphones it will go straight to the users busy voicemail even though the phone is not being used. I am running FreePBX 2.10.1.2 on top off Asterisk 1.8.10.0 installed from the FreePBX Distro and all modules have been upgraded. We are also using two Cisco SPA525G2 hardphones which never have this problem if that has any relevancy. I have setup FreePBX and Asterisk to operate in the Device/User mode; qualify is set to yes and qualifyfreq is set to 5 for each Device. Here is the Asterisk log and extension 1002 is the culprit that goes to busy voicemail when an incoming call is transferred. Any help is always greatly appreciated!

[2012-09-14 12:15:35] VERBOSE[-1] netsock2.c: == Using SIP RTP TOS bits 184 [2012-09-14 12:15:35] VERBOSE[-1] netsock2.c: == Using SIP RTP CoS mark 5 [2012-09-14 12:15:35] VERBOSE[-1] app_dial.c: -- Called SIP/1006 [2012-09-14 12:15:35] VERBOSE[-1] app_dial.c: -- SIP/1006-0000021c is ringing [2012-09-14 12:15:35] VERBOSE[-1] app_mixmonitor.c: == Begin MixMonitor Recording SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:15:38] VERBOSE[-1] app_dial.c: -- SIP/1006-0000021c answered SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:15:50] VERBOSE[-1] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:15:53] VERBOSE[-1] res_musiconhold.c: -- Stopped music on hold on SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:15:53] VERBOSE[-1] app_macro.c: == Spawn extension (from-internal-xfer, 1002, 1) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' in macro 'dial-one' [2012-09-14 12:15:53] VERBOSE[-1] app_macro.c: == Spawn extension (from-internal-xfer, 1002, 1) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' in macro 'exten-vm' [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: == Spawn extension (from-internal-xfer, 1002, 1) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [1002@from-internal-xfer:1] Set("SIP/fpbx-2-83f78513-0000021b", "__RINGTIMER=15") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [1002@from-internal-xfer:2] Macro("SIP/fpbx-2-83f78513-0000021b", "exten-vm,1002,1002,0,0,0") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/fpbx-2-83f78513-0000021b", "user-callerid,") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSER=5555554949") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?report") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(REALCALLERIDNUM=5555554949)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSER=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSERCIDNAME=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?report") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-user-callerid,s,13) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?continue") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:14] Set("SIP/fpbx-2-83f78513-0000021b", "__TTL=63") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?continue") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-user-callerid,s,26) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/fpbx-2-83f78513-0000021b", "CALLERID(number)=5555554949") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/fpbx-2-83f78513-0000021b", "CALLERID(name)=Smith, Bob") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/fpbx-2-83f78513-0000021b", "CHANNEL(language)=en") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:2] Set("SIP/fpbx-2-83f78513-0000021b", "RingGroupMethod=none") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:3] Set("SIP/fpbx-2-83f78513-0000021b", "__EXTTOCALL=1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:4] Set("SIP/fpbx-2-83f78513-0000021b", "__PICKUPMARK=1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:5] Set("SIP/fpbx-2-83f78513-0000021b", "RT=15") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:6] Gosub("SIP/fpbx-2-83f78513-0000021b", "sub-record-check,s,1(exten,1002,)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?check") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:2] ResetCDR("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:3] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?check") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/fpbx-2-83f78513-0000021b", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:5] MixMonitor("SIP/fpbx-2-83f78513-0000021b", "2012/09/14/exten-1006-5555554949-20120914-121535-1347639335.601.wav,a,") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/fpbx-2-83f78513-0000021b", "__MON_FMT=wav") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?next") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/fpbx-2-83f78513-0000021b", "CDR(recordingfile)=exten-1006-5555554949-20120914-121535-1347639335.601.wav") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@sub-record-check:9] Return("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:7] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?macrodial") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-exten-vm,s,13) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:13] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?clrheader,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:14] Macro("SIP/fpbx-2-83f78513-0000021b", "dial-one,15,tr,1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/fpbx-2-83f78513-0000021b", "DEXTEN=1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/fpbx-2-83f78513-0000021b", "DIALSTATUS_CW=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?screen,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?cf,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?skip1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-dial-one,s,8) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?nodial") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?continue") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:10] Set("SIP/fpbx-2-83f78513-0000021b", "EXTHASCW=ENABLED") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?next1:cwinusebusy") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-dial-one,s,23) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:23] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?next3:continue") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-dial-one,s,24) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:24] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(DIALSTATUS_CW=BUSY)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?nodial") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("SIP/fpbx-2-83f78513-0000021b", "1?dstring,1():dlocal,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/fpbx-2-83f78513-0000021b", "DSTRING=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/fpbx-2-83f78513-0000021b", "DEVICES=1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Return()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(DEVICES=002)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/fpbx-2-83f78513-0000021b", "LOOPCNT=1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/fpbx-2-83f78513-0000021b", "ITER=1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/fpbx-2-83f78513-0000021b", "THISDIAL=SIP/1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/fpbx-2-83f78513-0000021b", "1?zap2dahdi,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Return()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-2-83f78513-0000021b", "NEWDIAL=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/fpbx-2-83f78513-0000021b", "LOOPCNT2=1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/fpbx-2-83f78513-0000021b", "ITER2=1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/fpbx-2-83f78513-0000021b", "THISPART2=SIP/1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(THISPART2=DAHDI/1002)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/fpbx-2-83f78513-0000021b", "NEWDIAL=SIP/1002&") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/fpbx-2-83f78513-0000021b", "ITER2=2") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?begin2") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/fpbx-2-83f78513-0000021b", "THISDIAL=SIP/1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("SIP/fpbx-2-83f78513-0000021b", "DSTRING=SIP/1002&") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("SIP/fpbx-2-83f78513-0000021b", "ITER=2") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?begin") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("SIP/fpbx-2-83f78513-0000021b", "DSTRING=SIP/1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?nodial") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?skiptrace") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("SIP/fpbx-2-83f78513-0000021b", "1?ctset,1():ctclear,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/fpbx-2-83f78513-0000021b", "DB(CALLTRACE/1002)=5555554949") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/fpbx-2-83f78513-0000021b", "D_OPTIONS=tr") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?SIPAddHeader(Alert-Info: )") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?SIPAddHeader()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(CHANNEL(musicclass)=)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?qwait,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/fpbx-2-83f78513-0000021b", "__CWIGNORE=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:36] Set("SIP/fpbx-2-83f78513-0000021b", "__KEEPCID=TRUE") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?usegoto,1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?godial") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-dial-one,s,42) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:42] Dial("SIP/fpbx-2-83f78513-0000021b", "SIP/1002,15,tr") in new stack [2012-09-14 12:15:53] VERBOSE[-1] netsock2.c: == Using SIP RTP TOS bits 184 [2012-09-14 12:15:53] VERBOSE[-1] netsock2.c: == Using SIP RTP CoS mark 5 [2012-09-14 12:15:53] VERBOSE[-1] app_dial.c: -- Called SIP/1002 [2012-09-14 12:15:53] VERBOSE[-1] app_mixmonitor.c: == Begin MixMonitor Recording SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:15:53] VERBOSE[-1] chan_sip.c: -- Got SIP response 486 "Busy Here" back from 192.168.1.3:5060 [2012-09-14 12:15:53] VERBOSE[-1] app_dial.c: -- SIP/1002-0000021d is ringing [2012-09-14 12:15:53] VERBOSE[-1] app_dial.c: -- SIP/1002-0000021d is busy [2012-09-14 12:15:53] VERBOSE[-1] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:43] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(DIALSTATUS=)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:44] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?s-BUSY,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-dial-one:45] MacroExit("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:15] Set("SIP/fpbx-2-83f78513-0000021b", "SV_DIALSTATUS=BUSY") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:16] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?docfu,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:17] GosubIf("SIP/fpbx-2-83f78513-0000021b", "0?docfb,1()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:18] Set("SIP/fpbx-2-83f78513-0000021b", "DIALSTATUS=BUSY") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:19] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?MacroExit()") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:20] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?s-BUSY,1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-exten-vm:21] Macro("SIP/fpbx-2-83f78513-0000021b", "vm,1002,BUSY,") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-vm:1] Macro("SIP/fpbx-2-83f78513-0000021b", "user-callerid,SKIPTTL") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSER=5555554949") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?report") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(REALCALLERIDNUM=5555554949)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSER=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-2-83f78513-0000021b", "AMPUSERCIDNAME=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?report") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-user-callerid,s,13) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?continue") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-user-callerid,s,26) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/fpbx-2-83f78513-0000021b", "CALLERID(number)=5555554949") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/fpbx-2-83f78513-0000021b", "CALLERID(name)=Smith, Bob") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/fpbx-2-83f78513-0000021b", "CHANNEL(language)=en") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-vm:2] Set("SIP/fpbx-2-83f78513-0000021b", "VMGAIN=""") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-vm:3] Macro("SIP/fpbx-2-83f78513-0000021b", "blkvm-check,") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-blkvm-check:1] Set("SIP/fpbx-2-83f78513-0000021b", "GOSUB_RETVAL=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-blkvm-check:2] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-blkvm-check:3] MacroExit("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-vm:4] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?vmx,1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-vm,vmx,1) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:1] Set("SIP/fpbx-2-83f78513-0000021b", "MEXTEN=1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:2] Set("SIP/fpbx-2-83f78513-0000021b", "MMODE=BUSY") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:3] Set("SIP/fpbx-2-83f78513-0000021b", "RETVM=") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:4] Set("SIP/fpbx-2-83f78513-0000021b", "MODE=busy") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:5] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?chknomsg") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-vm,vmx,8) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:8] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?s-BUSY,1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:9] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?notdirect") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-vm,vmx,11) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:11] NoOp("SIP/fpbx-2-83f78513-0000021b", "Checking if ext 1002 is enabled: ") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [vmx@macro-vm:12] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?s-BUSY,1") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-vm,s-BUSY,1) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s-BUSY@macro-vm:1] NoOp("SIP/fpbx-2-83f78513-0000021b", "BUSY voicemail") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s-BUSY@macro-vm:2] Macro("SIP/fpbx-2-83f78513-0000021b", "get-vmcontext,1002") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/fpbx-2-83f78513-0000021b", "VMCONTEXT=default") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/fpbx-2-83f78513-0000021b", "0?200:300") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Goto (macro-get-vmcontext,s,300) [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:15:53] VERBOSE[-1] pbx.c: -- Executing [s-BUSY@macro-vm:3] VoiceMail("SIP/fpbx-2-83f78513-0000021b", "1002@default,b""") in new stack [2012-09-14 12:15:53] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'vm-theperson.ulaw' (language 'en') [2012-09-14 12:15:55] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'digits/1.ulaw' (language 'en') [2012-09-14 12:15:55] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'digits/0.ulaw' (language 'en') [2012-09-14 12:15:56] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'digits/0.ulaw' (language 'en') [2012-09-14 12:15:57] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'digits/2.ulaw' (language 'en') [2012-09-14 12:15:57] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'vm-isonphone.ulaw' (language 'en') [2012-09-14 12:15:59] VERBOSE[-1] file.c: -- <SIP/fpbx-2-83f78513-0000021b> Playing 'vm-intro.ulaw' (language 'en') [2012-09-14 12:16:01] VERBOSE[-1] app_macro.c: == Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' in macro 'vm' [2012-09-14 12:16:01] VERBOSE[-1] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' in macro 'exten-vm' [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: == Spawn extension (from-internal-xfer, 1002, 2) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: -- Executing [h@from-internal-xfer:1] Macro("SIP/fpbx-2-83f78513-0000021b", "hangupcall") in new stack [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/fpbx-2-83f78513-0000021b", "1?theend") in new stack [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: -- Goto (macro-hangupcall,s,3) [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/fpbx-2-83f78513-0000021b", "0?Set(CDR(recordingfile)=)") in new stack [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/fpbx-2-83f78513-0000021b", "") in new stack [2012-09-14 12:16:01] VERBOSE[-1] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' in macro 'hangupcall' [2012-09-14 12:16:01] VERBOSE[-1] pbx.c: == Spawn extension (from-internal-xfer, h, 1) exited non-zero on 'SIP/fpbx-2-83f78513-0000021b' [2012-09-14 12:16:01] VERBOSE[-1] app_mixmonitor.c: == MixMonitor close filestream [2012-09-14 12:16:01] VERBOSE[-1] app_mixmonitor.c: == MixMonitor close filestream [2012-09-14 12:16:01] VERBOSE[-1] app_mixmonitor.c: == End MixMonitor Recording SIP/fpbx-2-83f78513-0000021b [2012-09-14 12:16:01] VERBOSE[-1] app_mixmonitor.c: == End MixMonitor Recording SIP/fpbx-2-83f78513-0000021b

2

The log says it all:-

[2012-09-14 12:15:53] VERBOSE[-1] chan_sip.c: – Got SIP response 486 “Busy Here” back from 192.168.1.3:5060

You will need to look into why your windoze/3CX settings are sending a 486 response back when you call 1002.

sip show peers

and

sip show peer 1002

might be indicative, as might

sip debug ip 192.168.1.3 , is it possible that they are all using the same connection, IP/port ?

3

Thank you for the info. Everything is working (as of right now) for that extension; does anything look suspicious to you?

* Name : 1002 Secret : <Set> MD5Secret : <Not set> Remote Secret: <Not set> Context : from-internal Subscr.Cont. : <Not set> Language : AMA flags : Unknown Transfer mode: open CallingPres : Presentation Allowed, Not Screened Callgroup : Pickupgroup : MOH Suggest : Mailbox : 1002@default VM Extension : *97 LastMsgsSent : 32767/65535 Call limit : 2147483647 Max forwards : 0 Dynamic : Yes Callerid : "Bob Smith" <1002> MaxCallBR : 384 kbps Expire : 60 Insecure : no Force rport : Yes ACL : Yes DirectMedACL : No T.38 support : No T.38 EC mode : Unknown T.38 MaxDtgrm: -1 DirectMedia : No PromiscRedir : No User=Phone : No Video Support: No Text Support : No Ign SDP ver : No Trust RPID : Yes Send RPID : Yes Subscriptions: Yes Overlap dial : Yes DTMFmode : rfc2833 Timer T1 : 500 Timer B : 32000 ToHost : Addr->IP : 192.168.1.3:5060 Defaddr->IP : (null) Prim.Transp. : UDP Allowed.Trsp : UDP Def. Username: 1002 SIP Options : (none) Codecs : 0xe (gsm|ulaw|alaw) Codec Order : (ulaw:20,alaw:20,gsm:20) Auto-Framing : No Status : OK (108 ms) Useragent : 3CXPhone 6.0.20943.0 Reg. Contact : sip:[email protected]:5060;rinstance=acec54690845550d Qualify Freq : 5000 ms Sess-Timers : Accept Sess-Refresh : uas Sess-Expires : 1800 secs Min-Sess : 90 secs RTP Engine : asterisk Parkinglot : Use Reason : No Encryption : No

4

No that looks fine,

sip show peers

and then

sip debug ip 192.168.1.3

and watch a failed callm if they are intermittent then look into

/var/log/asterisk/full

postmortem

5

Two things to consider:

  1. I know there is a newer version of the 3CX windows client available, I am running 6.0.25732.0 and it’s possible a newer version may be available.
  2. You want to make sure the user is not accidentally setting the softphone to DND. When started, the client defaults to “available” but a stray click on that word and it will be set to DND with no obvious clue to the user that you are in DND mode. Design flaw IMO, there should be a flashing red warning. Clicking again will put the client in auto answer mode, do your users complain of that too?
6

[quote]Two things to consider:

  1. I know there is a newer version of the 3CX windows client available, I am running 6.0.25732.0 and it’s possible a newer version may be available.
  2. You want to make sure the user is not accidentally setting the softphone to DND. When started, the client defaults to “available” but a stray click on that word and it will be set to DND with no obvious clue to the user that you are in DND mode. Design flaw IMO, there should be a flashing red warning. Clicking again will put the client in auto answer mode, do your users complain of that too?[/quote]

Hmmmm, you’re right…the 3CXPhone Windoze installer on their website is a newer build but for some strange reason they decided not to indicate the build number (the version is indicated but no build). In fact, one cannot determine the build number until after the 3CX softphone is already installed!!! I believe the 3CX devs need to take: “Binary Building 101”! I can’t help but laugh at the: “stray click DND mode problem”! This caused so many headaches when we first installed the 3CX softphones. Luckily with some associate training it has been resolved and was not the cause of this busy voicemail incident…it still gives me nightmares to this day though! As you stated, it is definitely a design flaw on 3CX’s part though. My associates do not ever use the DND feature so I haven’t heard any complaints in that regard either.

[quote]No that looks fine,

sip show peers

and then

sip debug ip 192.168.1.3

and watch a failed callm if they are intermittent then look into

/var/log/asterisk/full

postmortem[/quote]

When I type in: sip debug ip 192.168.1.3 I get: No such command ‘sip debug ip 192.168.1.3’ (type ‘core show help sip debug ip’ for other possible commands). Is there a certain utility package I need to install?

7

sorry it should be

sip set debug ip x.x.x.x

8

Here is the sip debug log: http://pastebin.com/78ESLxWE. If the 3CX soft phone client does not repsond to Asterisk within a specified time frame will Asterisk default the extension to: SIP/2.0 486 Busy Here? I was just curious if this could be a latency issue or something? I have upgraded the 3CX soft phone to version: 6.0.26523.0 and disabled all of Windoze network adapter Power Saving Settings but the problem still exists. Please let me know if you need additional details and also know your help is very much appreciated!

9

No, you will get a 408 (timeout) usually, you are getting 486 in a timely fashion that says that the station at 192.168.1.3:5060 is busy in response to the server’s invite and after 1002 accepted the invite and replied with a 180 (ringing), the call then goes to voicemail-busy as expected. Timeouts would go to voicemail-unavailable.

10

Is there anything Asterisk could be sending to the 3CX soft phone that causes it to reply with: SIP/2.0 486 Busy Here? I checked the debug log on the 3CX soft phone and upon startup I occasionally see this: Phone requested as local port 5060 and then right below that line it lists: Phone requested local port busy in red warning text. However, immediately after that it says: Phone is now connected. I have the 3CX soft phone set at: Local SIP port: 5060 which is my Asterisk SIP port. Do I have some kind of SIP port conflict because it appears the 3CX soft phone might be taking this “busy” warning and sending it to Asterisk as: SIP/2.0 486 Busy Here?

11

maybe you have other software on that machine that is also using UDP/5060, the windoze version of

netstat -aunp |grep 5060

would show that if you shutdown your softphone.

You could try using another port than 5060

12

Oh boy, am I misinterpreting the Local SIP port: 5060 setting on the 3CX soft phone? Is it saying: Local as in localhost and not Local as in local network? I thought it was asking for the Asterisk SIP port on my LAN? I will run the command in the morning when I get back in the office and let you know the results.

13

5060 udp is the satndard port that SIP uses you can change it to something else if both the client and the server use the same port, I am suggesting that in the extension in FreePBX and the softphone both, you might want to try 5062 for example. any unknown software that is “claiming” 5060, and that might even be a browser extension or perhaps two different soft-phones will continue to use 5060 and the SIP session to Asterisk will be uninterrupted

14

Sorry for the delayed response, I opened the command prompt in windoze and ran: netstat -aunp |grep 5060 but unfortunately windoze gave me errors…I was only able to use netstat -a. The command reported UDP 5060 in use but it disappeared when I closed 3CX and ran netstat -a again. Is it standard practice to change SIP ports for each soft phone so they are all different?

15

Normally you use 5060 all the time. An exception might be if you have a single phone with 2 extensions configured on the same system.

BF

16

Windoze is not posix compliant so grep is not there, (you can install cygwin). Sorry but Windoze/3CX seem to be tripping over themselves on 5060, try as I said 5062 for example on both ends. Each of your softphones behind each individual IP address will need to use a different SIP port to register to a server, Some PNAT/routers will handle that but don’t rely on M$ to get anything network wise correct.

17

Well…I was hoping to share some good news but unfortunately my experiment failed. I set the 3CX windoze soft phones to use the WAN dynamic IP instead of the LAN static IP and then loopback to my Asterisk server (3CX soft phones and Asterisk server are all on LAN). It worked well up until late last week and then a whole new can of worms opened up. Now the 3CX soft phones are logging: Server unreachable and calls are answered and then immediately dropped every so often. I’m going to stop screwing around and change the SIP ports to something other than 5060 as suggested in this forum. I’ll post the results after a week or so.

18

It has been a few weeks since I changed the local SIP ports on my 3CX Windows soft phones. This change seems to have fixed the: Phone requested local port busy error that was showing up in the phone’s debug log and I have not seen any additional errors up to this point. However, the problem still exists and transferred calls still intermittently go to the end user’s Busy Voicemail. The Asterisk log still shows: Got SIP response 486 “Busy Here” for the 3CX Windows soft phones when the problem occurs. Considering these facts: the 3CX Windows soft phones no longer show any errors in the debug log, our Cisco SPA525G2 hard phones never experience this problem and the busy response is coming from the 3CX soft phone itself…I’m going to say the problem lies with the 3CX soft phones and not my Asterisk system. This smells like poorly developed software or maybe 3CX flat out geared the soft phone for their proprietary server and nothing else; even though 3CX claims it works with Asterisk http://www.3cx.com/VOIP/voip-phone.html. I’m clueless at this point but appreciate all the help I have received from this community!