[Okta Webinar] Learn how to a build a cloud-first strategyRegister Now

x
  • Status: Solved
  • Priority: Medium
  • Security: Public
  • Views: 192
  • Last Modified:

Random incoming calls have no sound (both way)

Dear experts,

This is a fresh (and first) installation of freebpx on a virtual server, downloaded here http://schmoozecom.com/distro-download.php. It's the default installation and I haven't installed any "fancy" modules yet. The version of FreePBX is 5.211.65.

All outgoing calls work great. Randomly, we will not here our correspondent. On their side, they hear the phone ringing, but they don't know somebody has picked up the call. On our side, we hear absolutely nothing.

I'm new to this but I did my homework first. I opened all the recommended ports (http://www.freepbx.org/support/documentation/howtos/howto-resolving-audio-problems) but some of the instructions on that link are too advanced for me. The fact that the other person doesn't know that we took the call indicates (in my regards) that it's not really an audio problem (or codec), but something else.

Any pointers ? What could I test ?

Thank you for your help
0
StephRu
Asked:
StephRu
  • 13
  • 5
  • 4
1 Solution
 
José MéndezCommented:
Gather logs and make your best to try to reproduce and capture a failed call so we can analyze it together. Analyzing the signaling and the application debugs will let us have a better understanding of what is happening. Run:

asterisk -r | tee asterisk-output.txt
sip set debug on
core set verbose 9
core set debug 9

leave the console up until the issue reccurs. We'll need the calling and called number to find the affected dialog, and the exact timestamp as well. Don't worry if there are many simultaneous calls, we'll find it with those details.

After you captured a failed instance, type <quit> at the asterisk cli and then attach the resulting file.
0
 
PhonebuffCommented:
What Firewall are you going though ?
0
 
StephRuAuthor Commented:
Hi Guys,

Thank you for your help.

I took the logs from the web panel, but I don't know if this will help you. I just experience it right now, here is the log :

[2014-09-03 09:33:00] NOTICE[33560] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:33:00] VERBOSE[33562][C-000071ab] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-000056e6;2'
[2014-09-03 09:33:41] VERBOSE[1788][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[1788][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk-sip-Guest-Voip:1] Set("SIP/Guest-Voip-00001cca", "GROUP()=OUT_2") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk-sip-Guest-Voip:2] Goto("SIP/Guest-Voip-00001cca", "from-trunk,41215105051,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (from-trunk,41215105051,1)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:1] Set("SIP/Guest-Voip-00001cca", "__FROM_DID=41215105051") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:2] Gosub("SIP/Guest-Voip-00001cca", "app-blacklist-check,s,1()") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/Guest-Voip-00001cca", "0?blacklisted") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/Guest-Voip-00001cca", "CALLED_BLACKLIST=1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/Guest-Voip-00001cca", "") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:3] Set("SIP/Guest-Voip-00001cca", "CDR(did)=41215105051") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:4] ExecIf("SIP/Guest-Voip-00001cca", "0 ?Set(CALLERID(name)=0213311545)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:5] Set("SIP/Guest-Voip-00001cca", "CHANNEL(musicclass)=default") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:6] Set("SIP/Guest-Voip-00001cca", "__MOHCLASS=default") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:7] Set("SIP/Guest-Voip-00001cca", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:8] Set("SIP/Guest-Voip-00001cca", "CALLERPRES()=allowed_not_screened") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [41215105051@from-trunk:9] Goto("SIP/Guest-Voip-00001cca", "timeconditions,1,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (timeconditions,1,1)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("SIP/Guest-Voip-00001cca", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:2] GotoIf("SIP/Guest-Voip-00001cca", "0?truegoto") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:3] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:4] Set("SIP/Guest-Voip-00001cca", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:5] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [1@timeconditions:6] GotoIf("SIP/Guest-Voip-00001cca", "1?timeconditions,2,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (timeconditions,2,1)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("SIP/Guest-Voip-00001cca", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:2] GotoIf("SIP/Guest-Voip-00001cca", "0?truegoto") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:3] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:4] Set("SIP/Guest-Voip-00001cca", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:5] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [2@timeconditions:6] GotoIf("SIP/Guest-Voip-00001cca", "1?ext-group,600,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (ext-group,600,1)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:1] Macro("SIP/Guest-Voip-00001cca", "user-callerid,") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/Guest-Voip-00001cca", "TOUCH_MONITOR=1409729621.51864") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/Guest-Voip-00001cca", "AMPUSER=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/Guest-Voip-00001cca", "0?report") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/Guest-Voip-00001cca", "1?Set(REALCALLERIDNUM=0213311545)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/Guest-Voip-00001cca", "AMPUSER=") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Guest-Voip-00001cca", "0?limit") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/Guest-Voip-00001cca", "AMPUSERCIDNAME=") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/Guest-Voip-00001cca", "1?report") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (macro-user-callerid,s,16)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/Guest-Voip-00001cca", "0?continue") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:17] ExecIf("SIP/Guest-Voip-00001cca", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:18] Set("SIP/Guest-Voip-00001cca", "__TTL=64") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:19] GotoIf("SIP/Guest-Voip-00001cca", "1?continue") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (macro-user-callerid,s,30)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/Guest-Voip-00001cca", "CALLERID(number)=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/Guest-Voip-00001cca", "CALLERID(name)=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/Guest-Voip-00001cca", "CDR(cnum)=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/Guest-Voip-00001cca", "CDR(cnam)=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-user-callerid:34] Set("SIP/Guest-Voip-00001cca", "CHANNEL(language)=en") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:2] Macro("SIP/Guest-Voip-00001cca", "blkvm-setifempty,") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/Guest-Voip-00001cca", "1?init") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (macro-blkvm-setifempty,s,4)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/Guest-Voip-00001cca", "__BLKVM_CHANNEL=SIP/Guest-Voip-00001cca") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/Guest-Voip-00001cca", "SHARED(BLKVM,SIP/Guest-Voip-00001cca)=TRUE") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/Guest-Voip-00001cca", "GOSUB_RETVAL=TRUE") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/Guest-Voip-00001cca", "") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:3] GotoIf("SIP/Guest-Voip-00001cca", "1?skipov") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (ext-group,600,6)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:6] Set("SIP/Guest-Voip-00001cca", "RRNODEST=") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:7] Set("SIP/Guest-Voip-00001cca", "__NODEST=600") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:8] GosubIf("SIP/Guest-Voip-00001cca", "0?sub-rgsetcid,s,1()") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:9] Gosub("SIP/Guest-Voip-00001cca", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/Guest-Voip-00001cca", "REC_POLICY_MODE_SAVE=") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/Guest-Voip-00001cca", "1?check") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (sub-record-check,s,7)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/Guest-Voip-00001cca", "__MON_FMT=wav") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/Guest-Voip-00001cca", "1?next") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (sub-record-check,s,11)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/Guest-Voip-00001cca", "0?Return()") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/Guest-Voip-00001cca", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/Guest-Voip-00001cca", "0?rg,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/Guest-Voip-00001cca", "__REC_STATUS=INITIALIZED") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/Guest-Voip-00001cca", "NOW=1409729621") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/Guest-Voip-00001cca", "__DAY=03") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/Guest-Voip-00001cca", "__MONTH=09") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/Guest-Voip-00001cca", "__YEAR=2014") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/Guest-Voip-00001cca", "__TIMESTR=20140903-093341") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/Guest-Voip-00001cca", "__FROMEXTEN=0213311545") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/Guest-Voip-00001cca", "__CALLFILENAME=rg-600-0213311545-20140903-093341-1409729621.51864") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/Guest-Voip-00001cca", "rg,1") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (sub-record-check,rg,1)
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [rg@sub-record-check:1] GosubIf("SIP/Guest-Voip-00001cca", "0?record,1(rg,dontcare,0213311545)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [rg@sub-record-check:2] Return("SIP/Guest-Voip-00001cca", "") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:10] Set("SIP/Guest-Voip-00001cca", "RingGroupMethod=ringall") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [600@ext-group:11] Macro("SIP/Guest-Voip-00001cca", "dial,30,Ttr,6000-6001-6002-6003") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/Guest-Voip-00001cca", "0?dial") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-dial:2] SetMusicOnHold("SIP/Guest-Voip-00001cca", "default") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/Guest-Voip-00001cca", "dialparties.agi") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: dialparties.agi: Caller ID name is '0213311545' number is '0213311545'
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Added extension 6000 to extension map
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Added extension 6001 to extension map
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Added extension 6002 to extension map
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Added extension 6003 to extension map
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6000 cf is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6001 cf is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6002 cf is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6003 cf is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6000 do not disturb is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6001 do not disturb is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6002 do not disturb is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Extension 6003 do not disturb is disabled
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6000 to 0213311545
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6001 to 0213311545
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6002 to 0213311545
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6003 to 0213311545
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- dialparties.agi: Filtered ARG3: 6000-6001-6002-6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] res_agi.c: -- <SIP/Guest-Voip-00001cca>AGI Script dialparties.agi completed, returning 0
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-dial:7] Dial("SIP/Guest-Voip-00001cca", "SIP/6000&SIP/6001&SIP/6002&SIP/6003,30,TtrM(auto-blkvm)") in new stack
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6001
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6002
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6003-00001cce connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6002-00001ccd connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6001-00001ccc connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000 (queued)
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6002-00001ccd is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6001-00001ccc is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb is ringing
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6003-00001cce is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb answered SIP/Guest-Voip-00001cca
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state InUse for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:1] Set("SIP/6000-00001ccb", "__MACRO_RESULT=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:2] Set("SIP/6000-00001ccb", "CFIGNORE=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:3] Set("SIP/6000-00001ccb", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:4] Set("SIP/6000-00001ccb", "FORWARD_CONTEXT=from-internal") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:5] Set("SIP/6000-00001ccb", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:6] Macro("SIP/6000-00001ccb", "blkvm-clr,") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/6000-00001ccb", "SHARED(BLKVM,SIP/Guest-Voip-00001cca)=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/6000-00001ccb", "GOSUB_RETVAL=") in new stack
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/6000-00001ccb", "") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/6000-00001ccb", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=6000)") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/6000-00001ccb", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Reception)") in new stack
[2014-09-03 09:34:00] VERBOSE[33775] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-000056e7;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-000056e7;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056e7;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-000056e7;2", "0?truegoto") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-000056e7;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-000056e7;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-000056e7;2", "TCSTATE=false") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-000056e7;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056e7;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-000056e7;2", "0?truegoto") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-000056e7;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-000056e7;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-000056e7;2", "TCSTATE=false") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-000056e7;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:34:01] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:01] NOTICE[33775] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:34:01] VERBOSE[33776][C-000071ad] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-000056e7;2'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [h@macro-dial:1] Macro("SIP/Guest-Voip-00001cca", "hangupcall") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Guest-Voip-00001cca", "1?theend") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (macro-hangupcall,s,3)
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(CDR(recordingfile)=)") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/Guest-Voip-00001cca", "") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Guest-Voip-00001cca' in macro 'hangupcall'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/Guest-Voip-00001cca'
[2014-09-03 09:34:04] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/Guest-Voip-00001cca' in macro 'dial'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: == Spawn extension (ext-group, 600, 11) exited non-zero on 'SIP/Guest-Voip-00001cca'
[2014-09-03 09:34:25] WARNING[1788] chan_sip.c: Retransmission timeout reached on transmission 103b3aa9-210640e5-5eab61a1-bc6e@sip.iforb.com~1o for seqno 716 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response

Open in new window


My firewall is a Zyxel Zywall. I have disable the firewall, hoping that would help, but no.
0
Concerto Cloud for Software Providers & ISVs

Can Concerto Cloud Services help you focus on evolving your application offerings, while delivering the best cloud experience to your customers? From DevOps to revenue models and customer support, the answer is yes!

Learn how Concerto can help you.

 
StephRuAuthor Commented:
The same number called me a few minutes later, worked fine. No other calls in between, I didn't touch anything. Once it didn't work, once it worked :( .
0
 
StephRuAuthor Commented:
Ok so I trimed a bit the code, and you have the logs of one successful call (1st one) and one that failed (2nd one). Same phone number, same SIP phones (CISCO SPA509G). The code here starts where the logs start to differ :

Successful call :

[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state InUse&Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- Called SIP/6000
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- Called SIP/6001
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- Called SIP/6002
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- Called SIP/6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6003-00001cd9 connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cd5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6002-00001cd8 connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cd5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6001-00001cd7 connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cd5
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6000-00001cd6 connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cd5
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000 (queued)
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6001-00001cd7 is ringing
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6002-00001cd8 is ringing
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000 (queued)
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6000-00001cd6 is ringing
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state InUse&Ringing for Notify User 6003
[2014-09-03 09:52:06] VERBOSE[35400][C-000071c6] app_dial.c: -- SIP/6003-00001cd9 is ringing
[2014-09-03 09:52:06] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000 (queued)
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] app_dial.c: -- Nobody picked up in 30000 ms
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@macro-dial:8] Set("SIP/Guest-Voip-00001cd5", "DIALSTATUS=NOANSWER") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@macro-dial:9] GosubIf("SIP/Guest-Voip-00001cd5", "0?NOANSWER,1") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:12] Gosub("SIP/Guest-Voip-00001cd5", "sub-record-cancel,s,1()") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@sub-record-cancel:1] Set("SIP/Guest-Voip-00001cd5", "__REC_POLICY_MODE=") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@sub-record-cancel:2] ExecIf("SIP/Guest-Voip-00001cd5", "1?Return()") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:13] Set("SIP/Guest-Voip-00001cd5", "RingGroupMethod=") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:14] GotoIf("SIP/Guest-Voip-00001cd5", "0?nodest") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:15] Set("SIP/Guest-Voip-00001cd5", "__NODEST=") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:16] Macro("SIP/Guest-Voip-00001cd5", "blkvm-clr,") in new stack
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state InUse for Notify User 6003
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/Guest-Voip-00001cd5", "SHARED(BLKVM,SIP/Guest-Voip-00001cd5)=") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/Guest-Voip-00001cd5", "GOSUB_RETVAL=") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/Guest-Voip-00001cd5", "") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [600@ext-group:17] Goto("SIP/Guest-Voip-00001cd5", "app-blackhole,busy,1") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Goto (app-blackhole,busy,1)
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [busy@app-blackhole:1] NoOp("SIP/Guest-Voip-00001cd5", "Blackhole Dest: Busy") in new stack
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: -- Executing [busy@app-blackhole:2] Busy("SIP/Guest-Voip-00001cd5", "20") in new stack
[2014-09-03 09:52:36] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:52:36] WARNING[35400][C-000071c6] channel.c: Prodding channel 'SIP/Guest-Voip-00001cd5' failed
[2014-09-03 09:52:36] VERBOSE[35400][C-000071c6] pbx.c: == Spawn extension (app-blackhole, busy, 2) exited non-zero on 'SIP/Guest-Voip-00001cd5'
[2014-09-03 09:53:00] VERBOSE[35481] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-000056fe;2", "") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-000056fe;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-000056fe;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056fe;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-000056fe;2", "0?truegoto") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-000056fe;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-000056fe;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-000056fe;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-000056fe;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-000056fe;2", "TCSTATE=false") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-000056fe;2", "") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-000056fe;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056fe;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-000056fe;2", "0?truegoto") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-000056fe;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-000056fe;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-000056fe;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-000056fe;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-000056fe;2", "TCSTATE=false") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-000056fe;2", "") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-000056fe;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 0") in new stack
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-000056fe;2", "") in new stack
[2014-09-03 09:53:00] NOTICE[35481] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:53:00] VERBOSE[35483][C-000071c7] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-000056fe;2'
[2014-09-03 09:54:00] VERBOSE[35532] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-000056ff;2", "") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-000056ff;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-000056ff;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056ff;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-000056ff;2", "0?truegoto") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-000056ff;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-000056ff;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-000056ff;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-000056ff;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-000056ff;2", "TCSTATE=false") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-000056ff;2", "") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-000056ff;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056ff;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-000056ff;2", "0?truegoto") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-000056ff;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-000056ff;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-000056ff;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-000056ff;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-000056ff;2", "TCSTATE=false") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-000056ff;2", "") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-000056ff;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:54:00] VERBOSE[35534][C-000071c8] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-000056ff;2", "") in new stack
[2014-09-03 09:54:01] NOTICE[35532] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:54:01] VERBOSE[35534][C-000071c8] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-000056ff;2'
[2014-09-03 09:55:01] VERBOSE[35591] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005700;2", "") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005700;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005700;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005700;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005700;2", "0?truegoto") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005700;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005700;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005700;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005700;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005700;2", "TCSTATE=false") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005700;2", "") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005700;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005700;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005700;2", "0?truegoto") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005700;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005700;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005700;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005700;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005700;2", "TCSTATE=false") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005700;2", "") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005700;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 0") in new stack
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005700;2", "") in new stack
[2014-09-03 09:55:01] NOTICE[35591] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:55:01] VERBOSE[35593][C-000071c9] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005700;2'
[2014-09-03 09:56:00] VERBOSE[35657] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005701;2", "") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005701;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005701;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005701;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005701;2", "0?truegoto") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005701;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005701;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005701;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005701;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005701;2", "TCSTATE=false") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005701;2", "") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005701;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005701;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005701;2", "0?truegoto") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005701;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005701;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005701;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005701;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005701;2", "TCSTATE=false") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005701;2", "") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005701;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005701;2", "") in new stack
[2014-09-03 09:56:00] NOTICE[35657] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:56:00] VERBOSE[35659][C-000071ca] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005701;2'
[2014-09-03 09:56:05] VERBOSE[35723] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005702;2", "") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005702;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005702;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005702;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005702;2", "0?truegoto") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005702;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005702;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005702;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005702;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005702;2", "TCSTATE=false") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005702;2", "") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005702;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005702;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005702;2", "0?truegoto") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005702;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005702;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005702;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005702;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005702;2", "TCSTATE=false") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005702;2", "") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005702;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 0") in new stack
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005702;2", "") in new stack
[2014-09-03 09:56:05] NOTICE[35723] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:56:05] VERBOSE[35724][C-000071cb] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005702;2'
[2014-09-03 09:57:00] VERBOSE[35726] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005703;2", "") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005703;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005703;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005703;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005703;2", "0?truegoto") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005703;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005703;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005703;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005703;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005703;2", "TCSTATE=false") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005703;2", "") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005703;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005703;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005703;2", "0?truegoto") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005703;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005703;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005703;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005703;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005703;2", "TCSTATE=false") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005703;2", "") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005703;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005703;2", "") in new stack
[2014-09-03 09:57:00] NOTICE[35726] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:57:00] VERBOSE[35728][C-000071cc] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005703;2'
[2014-09-03 09:58:00] VERBOSE[35848] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005704;2", "") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005704;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005704;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005704;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005704;2", "0?truegoto") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005704;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005704;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005704;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005704;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005704;2", "TCSTATE=false") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005704;2", "") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005704;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005704;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005704;2", "0?truegoto") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005704;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005704;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005704;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005704;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005704;2", "TCSTATE=false") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005704;2", "") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005704;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 0") in new stack
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005704;2", "") in new stack
[2014-09-03 09:58:01] NOTICE[35848] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:58:01] VERBOSE[35849][C-000071cd] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005704;2'
[2014-09-03 09:58:03] VERBOSE[1788][C-000071ce] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:58:03] VERBOSE[1788][C-000071ce] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [00972598545473@from-sip-external:1] NoOp("SIP/109.164.232.3-00001cda", "Received incoming SIP connection from unknown peer to 00972598545473") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [00972598545473@from-sip-external:2] Set("SIP/109.164.232.3-00001cda", "DID=00972598545473") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [00972598545473@from-sip-external:3] Goto("SIP/109.164.232.3-00001cda", "s,1") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Goto (from-sip-external,s,1)
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [s@from-sip-external:1] GotoIf("SIP/109.164.232.3-00001cda", "0?checklang:noanonymous") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Goto (from-sip-external,s,5)
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [s@from-sip-external:5] Set("SIP/109.164.232.3-00001cda", "TIMEOUT(absolute)=15") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] func_timeout.c: -- Channel will hangup at 2014-09-03 09:58:18.054 CEST.
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [s@from-sip-external:6] Log("SIP/109.164.232.3-00001cda", "WARNING,"Rejecting unknown SIP connection from 62.210.84.133"") in new stack
[2014-09-03 09:58:03] WARNING[35852][C-000071ce] Ext. s: "Rejecting unknown SIP connection from 62.210.84.133"
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [s@from-sip-external:7] Answer("SIP/109.164.232.3-00001cda", "") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: == Spawn extension (from-sip-external, s, 7) exited non-zero on 'SIP/109.164.232.3-00001cda'
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: -- Executing [h@from-sip-external:1] Hangup("SIP/109.164.232.3-00001cda", "") in new stack
[2014-09-03 09:58:03] VERBOSE[35852][C-000071ce] pbx.c: == Spawn extension (from-sip-external, h, 1) exited non-zero on 'SIP/109.164.232.3-00001cda'
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: -- Executing [h@macro-dial:1] Macro("SIP/Guest-Voip-00001cd0", "hangupcall") in new stack
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Guest-Voip-00001cd0", "1?theend") in new stack
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: -- Goto (macro-hangupcall,s,3)
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Guest-Voip-00001cd0", "0?Set(CDR(recordingfile)=)") in new stack
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/Guest-Voip-00001cd0", "") in new stack
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Guest-Voip-00001cd0' in macro 'hangupcall'
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/Guest-Voip-00001cd0'
[2014-09-03 09:58:21] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/Guest-Voip-00001cd0' in macro 'dial'
[2014-09-03 09:58:21] VERBOSE[34851][C-000071bc] pbx.c: == Spawn extension (ext-group, 600, 11) exited non-zero on 'SIP/Guest-Voip-00001cd0'
[2014-09-03 09:59:00] VERBOSE[35936] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005705;2", "") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005705;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005705;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005705;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005705;2", "0?truegoto") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005705;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005705;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005705;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005705;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005705;2", "TCSTATE=false") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005705;2", "") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005705;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005705;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005705;2", "0?truegoto") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005705;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005705;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005705;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005705;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005705;2", "TCSTATE=false") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005705;2", "") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005705;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005705;2", "") in new stack
[2014-09-03 09:59:00] NOTICE[35936] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:59:00] VERBOSE[35938][C-000071cf] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005705;2'
[2014-09-03 10:00:00] VERBOSE[35998] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-00005706;2", "") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-00005706;2", "TCMAINT=RETURN") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-00005706;2", "timeconditions,1,1()") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005706;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-00005706;2", "0?truegoto") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-00005706;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-00005706;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-00005706;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-00005706;2", "0?timeconditions,2,1") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-00005706;2", "TCSTATE=false") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-00005706;2", "") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-00005706;2", "timeconditions,2,1()") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-00005706;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-00005706;2", "0?truegoto") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-00005706;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-00005706;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-00005706;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-00005706;2", "0?ext-group,600,1") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-00005706;2", "TCSTATE=false") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-00005706;2", "") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-00005706;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 0") in new stack
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-00005706;2", "") in new stack
[2014-09-03 10:00:00] NOTICE[35998] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 10:00:00] VERBOSE[36000][C-000071d0] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-00005706;2'

Open in new window


Unsuccessful call :

[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP TOS bits 184
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] netsock2.c: == Using SIP RTP CoS mark 5
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6001
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6002
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- Called SIP/6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6003-00001cce connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6002-00001ccd connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6001-00001ccc connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6000 (queued)
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6002-00001ccd is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6001-00001ccc is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Ringing for Notify User 6003
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb is ringing
[2014-09-03 09:33:41] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6003-00001cce is ringing
[2014-09-03 09:33:41] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Ringing for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb connected line has changed. Saving it until answer for SIP/Guest-Voip-00001cca
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] app_dial.c: -- SIP/6000-00001ccb answered SIP/Guest-Voip-00001cca
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state InUse for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:1] Set("SIP/6000-00001ccb", "__MACRO_RESULT=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:2] Set("SIP/6000-00001ccb", "CFIGNORE=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:3] Set("SIP/6000-00001ccb", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:4] Set("SIP/6000-00001ccb", "FORWARD_CONTEXT=from-internal") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:5] Set("SIP/6000-00001ccb", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:6] Macro("SIP/6000-00001ccb", "blkvm-clr,") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/6000-00001ccb", "SHARED(BLKVM,SIP/Guest-Voip-00001cca)=") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/6000-00001ccb", "GOSUB_RETVAL=") in new stack
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6001[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6002[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:33:53] VERBOSE[1733] chan_sip.c: == Extension Changed 6003[ext-local] new state Idle for Notify User 6000
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/6000-00001ccb", "") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/6000-00001ccb", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=6000)") in new stack
[2014-09-03 09:33:53] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/6000-00001ccb", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Reception)") in new stack
[2014-09-03 09:34:00] VERBOSE[33775] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1)
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-000056e7;2", "TCMAINT=RETURN") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-000056e7;2", "timeconditions,1,1()") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056e7;2", "12:00-13:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:2] GotoIf("Local/s@tc-maint-000056e7;2", "0?truegoto") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:3] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DB(TC/1)=)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:4] Set("Local/s@tc-maint-000056e7;2", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:5] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:6] GotoIf("Local/s@tc-maint-000056e7;2", "0?timeconditions,2,1") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:7] Set("Local/s@tc-maint-000056e7;2", "TCSTATE=false") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [1@timeconditions:8] Return("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-000056e7;2", "timeconditions,2,1()") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:1] GotoIfTime("Local/s@tc-maint-000056e7;2", "18:00-08:00,mon-fri,1-31,jan-dec?truestate") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:2] GotoIf("Local/s@tc-maint-000056e7;2", "0?truegoto") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:3] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DB(TC/2)=)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:4] Set("Local/s@tc-maint-000056e7;2", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:5] ExecIf("Local/s@tc-maint-000056e7;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:6] GotoIf("Local/s@tc-maint-000056e7;2", "0?ext-group,600,1") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:7] Set("Local/s@tc-maint-000056e7;2", "TCSTATE=false") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [2@timeconditions:8] Return("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:00] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:5] System("Local/s@tc-maint-000056e7;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack
[2014-09-03 09:34:01] VERBOSE[33776][C-000071ad] pbx.c: -- Executing [s@tc-maint:6] Answer("Local/s@tc-maint-000056e7;2", "") in new stack
[2014-09-03 09:34:01] NOTICE[33775] pbx_spool.c: Call completed to Local/s@tc-maint
[2014-09-03 09:34:01] VERBOSE[33776][C-000071ad] pbx.c: == Spawn extension (tc-maint, s, 6) exited non-zero on 'Local/s@tc-maint-000056e7;2'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [h@macro-dial:1] Macro("SIP/Guest-Voip-00001cca", "hangupcall") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Guest-Voip-00001cca", "1?theend") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Goto (macro-hangupcall,s,3)
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Guest-Voip-00001cca", "0?Set(CDR(recordingfile)=)") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/Guest-Voip-00001cca", "") in new stack
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Guest-Voip-00001cca' in macro 'hangupcall'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/Guest-Voip-00001cca'
[2014-09-03 09:34:04] VERBOSE[1733] chan_sip.c: == Extension Changed 6000[ext-local] new state Idle for Notify User 6003
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/Guest-Voip-00001cca' in macro 'dial'
[2014-09-03 09:34:04] VERBOSE[33620][C-000071ac] pbx.c: == Spawn extension (ext-group, 600, 11) exited non-zero on 'SIP/Guest-Voip-00001cca'
[2014-09-03 09:34:25] WARNING[1788] chan_sip.c: Retransmission timeout reached on transmission 103b3aa9-210640e5-5eab61a1-bc6e@sip.iforb.com~1o for seqno 716 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response

Open in new window

0
 
PhonebuffCommented:
NEVER run Asterisk with out a Firewall unless you want major issues ----  This system should be locked down and protected.  

In both cases the last line tells you what the issue is --
2014-09-03 09:34:25] WARNING[1788] chan_sip.c: Retransmission timeout reached on transmission 103b3aa9-210640e5-5eab61a1-bc6e@sip.iforb.com~1o for seqno 716 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response

[2014-09-03 09:34:25] WARNING[1788] chan_sip.c: Retransmission timeout reached on transmission 103b3aa9-210640e5-5eab61a1-bc6e@sip.iforb.com~1o for seqno 716 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response


You might try using the MTR tool to look at the link between your two end points.   You may have a bad router / switch in the link, it it may just be overloaded somewhere and not routing your voice packets.  

http://linux.die.net/man/8/mtr
0
 
StephRuAuthor Commented:
The firewall is off just for rulling it out ...

You say that's my error in both cases... well in one of the cases, it works very well. We used to have a previous VOIP setup with asterisk and we never had this kind of problem with exactly the same materiel (sip phones, switches, ...), except it wasn't a VM.

I will have a look at your suggestion, but I'm sorry to insist : the log is not the same between the two calls and one of them didn't work. Isn't there something in that log that should give us another hint ?
0
 
José MéndezCommented:
Please follow the steps I suggested in order to collect the SIP Signaling and be able to determine what happens on that layer of the communication. The web logs you collected are not going to help at this point.

asterisk -r | tee asterisk-output.txt
sip set debug on
core set verbose 9
core set debug 9

leave the console up until the issue reccurs. We'll need the calling and called number to find the affected dialog, and the exact timestamp as well
0
 
PhonebuffCommented:
As was suggested by Willy,   if you believe it to be something get the output requested --
0
 
StephRuAuthor Commented:
Here goes. I have removed a huge chunk before any missed calls. The calling number was 0763134149.

Thank you for your help !!!
0
 
StephRuAuthor Commented:
Duh ... sorry for the missing file.
asterisk-output.txt
0
 
StephRuAuthor Commented:
Oh and maybe some aditional information might help you :

The voip server has address 192.168.3.6
My sip phones have address 192.168.4.x
0
 
José MéndezCommented:
Called # please.
0
 
StephRuAuthor Commented:
The calling number was 0763134149, and my number is 0215105051.
0
 
StephRuAuthor Commented:
Help anyone :( ?
0
 
José MéndezCommented:
Apologies, I have been quite busy.

I was not able to find any INVITE with a request URI pointing to 0215105051 where the calling number was 0763134149.

I only found replies where the From header contained 0763134149, and the one below comes from the SPA, not even to the outside caller:

SIP/2.0 200 OK
To: <sip:6000@192.168.4.31:5060>;tag=c82287bdd54deae9i0
From: "0763134149" <sip:0763134149@192.168.3.6>;tag=as44b08148
Call-ID: 6650d6e11ad35437436bd8434202a482@192.168.3.6:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 192.168.3.6:5060;branch=z9hG4bK02c663d7
Contact: "Reception" <sip:6000@192.168.4.31:5060>
Server: Cisco/SPA509G-7.5.4
Content-Length: 212
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE
Supported: replaces
Content-Type: application/sdp

v=0
o=- 145908995 145908995 IN IP4 192.168.4.31
s=-
c=IN IP4 192.168.4.31
t=0 0
m=audio 16448 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv


Since the external calling party hears the ringback tone, we need to understand what signals are sent by the FreePBX to the outside and also to the SPA phone.

I am not sure if this is doing of the tee command that I suggested, but we need that signaling. PLease use Putty to log into the FreePBX system, and configure it to log all output to a text file. Then

asterisk -r
sip set debug on
core set verbose 9
core set debug 9

And reproduce the call. Please attach the resulting file from Putty.

I apologize if collecting this log and cleansing it and attaching it is a very laborious task, but its the only way I know to determine what is causing the problem.
0
 
StephRuAuthor Commented:
I have finally found the solution: I inscreased (through telnet) the UDP session timeout to 300 secondes :) !
0
 
PhonebuffCommented:
Both Experts contributed to the background this user needed to identify and resolve the problem, in fact back on 09-03 it was pointed out specifically that he had a time out issue.   This should not be closed with zero points being allocated.
0
 
StephRuAuthor Commented:
I'm sorry Phonebuff, but that is not true.

The link that you gave (that was in the logs) just points out to general SIP transmission issues.

I am no expert, but telling me "You might try using the MTR tool to look at the link between your two end points.   You may have a bad router / switch in the link, it it may just be overloaded somewhere and not routing your voice packets" didn't help me at all.

It was a wild shot, I read somewhere that I should increase UPD session timeouts on my firewall and that was it !
0
 
José MéndezCommented:
I do find Phonebuff's contribution a40300828 helpful in determining the issue (a timeout), and it was actually based on my suggestion to gather logs from contribution a40297616

If someone didn't specifically told StephRu what setting to increase, at least he was put on the right track by asking the expert community.
0
 
StephRuAuthor Commented:
Okay, fine with me :)
0
 
StephRuAuthor Commented:
After a lot of tri-al and error, this solution solve my problem.
0

Featured Post

Free Tool: SSL Checker

Scans your site and returns information about your SSL implementation and certificate. Helpful for debugging and validating your SSL configuration.

One of a set of tools we are providing to everyone as a way of saying thank you for being a part of the community.

  • 13
  • 5
  • 4
Tackle projects and never again get stuck behind a technical roadblock.
Join Now