FreePBX Distro Time Cond Override Code not working

FreePBX Distro 5.211.65-10
Hello,
We are seeing an intermittent issue with one client, where the override is not working. When the codes (*271 for site A or *272 for site B) are dialed, the confirmation is audible but will repeat “Time Activated” several times before finally stating “Time Deactivated” on subsequent attempts. The override works as expected when the appropriate activate/deactivate message is heard. Has anyone dealt with this before?

Thanks in advance!

Can you show us a call trace

I just went through and looked at the code a week ago about this and I can guarantee the time override does indeed work.

Not a 100% this is considrered a call trace but below is an example in the asterisk FULL log showing two back to back calls (to *271) and it failing to change the status.


     [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [*271@from-internal:1] Macro("SIP/5000-0005e17c", "toggle-tc,1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:1] Set("SIP/5000-0005e17c", "INDEXES=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:2] Set("SIP/5000-0005e17c", "TCMAINT=RETURN") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:3] Set("SIP/5000-0005e17c", "TCSTATE=false") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:4] Set("SIP/5000-0005e17c", "LOOPCNT=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:5] Set("SIP/5000-0005e17c", "ITER=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:6] Set("SIP/5000-0005e17c", "INDEX=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:7] Set("SIP/5000-0005e17c", "MODE=") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:8] GotoIf("SIP/5000-0005e17c", "1?end1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Goto (macro-toggle-tc,s,10)
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:10] Set("SIP/5000-0005e17c", "ITER=2") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:11] GotoIf("SIP/5000-0005e17c", "0?begin1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:12] Set("SIP/5000-0005e17c", "LOOPCNT=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:13] Set("SIP/5000-0005e17c", "ITER=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:14] Set("SIP/5000-0005e17c", "INDEX=1") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:15] Set("SIP/5000-0005e17c", "DB(TC/1)=false") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:16] Set("SIP/5000-0005e17c", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:17] Set("SIP/5000-0005e17c", "DEVICE_STATE(Custom:TCSTICKY1)=NOT_INUSE") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:18] Set("SIP/5000-0005e17c", "ITER=2") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:19] GotoIf("SIP/5000-0005e17c", "0?begin2") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:20] GotoIf("SIP/5000-0005e17c", "1?playback") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Goto (macro-toggle-tc,s,22)
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [s@macro-toggle-tc:22] Playback("SIP/5000-0005e17c", "beep&silence/1&time&activated") in new stack
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] file.c:     -- <SIP/5000-0005e17c> Playing 'beep.gsm' (language 'en')
   [2014-06-25 14:28:15] VERBOSE[12572][C-00075cc4] file.c:     -- <SIP/5000-0005e17c> Playing 'silence/1.gsm' (language 'en')
   [2014-06-25 14:28:16] VERBOSE[12572][C-00075cc4] file.c:     -- <SIP/5000-0005e17c> Playing 'time.gsm' (language 'en')
   [2014-06-25 14:28:17] VERBOSE[12572][C-00075cc4] file.c:     -- <SIP/5000-0005e17c> Playing 'activated.gsm' (language 'en')
   [2014-06-25 14:28:18] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [*271@from-internal:2] Hangup("SIP/5000-0005e17c", "") in new stack
   [2014-06-25 14:28:18] VERBOSE[12572][C-00075cc4] pbx.c:   == Spawn extension (from-internal, *271, 2) exited non-zero on 'SIP/5000-0005e17c'
   [2014-06-25 14:28:18] VERBOSE[12572][C-00075cc4] pbx.c:     -- Executing [h@from-internal:1] Hangup("SIP/5000-0005e17c", "") in new stack
   [2014-06-25 14:28:18] VERBOSE[12572][C-00075cc4] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/5000-0005e17c'
   [2014-06-25 14:28:25] VERBOSE[1643][C-00075cc5] netsock2.c:   == Using SIP RTP TOS bits 184
   [2014-06-25 14:28:25] VERBOSE[1643][C-00075cc5] netsock2.c:   == Using SIP RTP CoS mark 5
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [*271@from-internal:1] Macro("SIP/5000-0005e17e", "toggle-tc,1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:1] Set("SIP/5000-0005e17e", "INDEXES=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:2] Set("SIP/5000-0005e17e", "TCMAINT=RETURN") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:3] Set("SIP/5000-0005e17e", "TCSTATE=false") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:4] Set("SIP/5000-0005e17e", "LOOPCNT=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:5] Set("SIP/5000-0005e17e", "ITER=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:6] Set("SIP/5000-0005e17e", "INDEX=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:7] Set("SIP/5000-0005e17e", "MODE=") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:8] GotoIf("SIP/5000-0005e17e", "1?end1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Goto (macro-toggle-tc,s,10)
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:10] Set("SIP/5000-0005e17e", "ITER=2") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:11] GotoIf("SIP/5000-0005e17e", "0?begin1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:12] Set("SIP/5000-0005e17e", "LOOPCNT=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:13] Set("SIP/5000-0005e17e", "ITER=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:14] Set("SIP/5000-0005e17e", "INDEX=1") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:15] Set("SIP/5000-0005e17e", "DB(TC/1)=false") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:16] Set("SIP/5000-0005e17e", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:17] Set("SIP/5000-0005e17e", "DEVICE_STATE(Custom:TCSTICKY1)=NOT_INUSE") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:18] Set("SIP/5000-0005e17e", "ITER=2") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:19] GotoIf("SIP/5000-0005e17e", "0?begin2") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:20] GotoIf("SIP/5000-0005e17e", "1?playback") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Goto (macro-toggle-tc,s,22)
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [s@macro-toggle-tc:22] Playback("SIP/5000-0005e17e", "beep&silence/1&time&activated") in new stack
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] file.c:     -- <SIP/5000-0005e17e> Playing 'beep.gsm' (language 'en')
   [2014-06-25 14:28:33] VERBOSE[12574][C-00075cc6] file.c:     -- <SIP/5000-0005e17e> Playing 'silence/1.gsm' (language 'en')
   [2014-06-25 14:28:34] VERBOSE[12574][C-00075cc6] file.c:     -- <SIP/5000-0005e17e> Playing 'time.gsm' (language 'en')
   [2014-06-25 14:28:35] VERBOSE[12574][C-00075cc6] file.c:     -- <SIP/5000-0005e17e> Playing 'activated.gsm' (language 'en')
   [2014-06-25 14:28:36] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [*271@from-internal:2] Hangup("SIP/5000-0005e17e", "") in new stack
   [2014-06-25 14:28:36] VERBOSE[12574][C-00075cc6] pbx.c:   == Spawn extension (from-internal, *271, 2) exited non-zero on 'SIP/5000-0005e17e'
   [2014-06-25 14:28:36] VERBOSE[12574][C-00075cc6] pbx.c:     -- Executing [h@from-internal:1] Hangup("SIP/5000-0005e17e", "") in new stack
   [2014-06-25 14:28:36] VERBOSE[12574][C-00075cc6] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/5000-0005e17e'
   [2014-06-25 14:28:40] VERBOSE[1643][C-00075cc7] netsock2.c:   == Using SIP RTP TOS bits 184
   [2014-06-25 14:28:40] VERBOSE[1643][C-00075cc7] netsock2.c:   == Using SIP RTP CoS mark 5

Sorry, forgot to say thank you for the quick reply :slight_smile:

For me it works 100%, just because it does not work 100% for you, does not mean it doesn’t work 100% for all users out there. That is what I am trying to clarify.

Agree, as of right now it works on all our other systems (which are identical to this one) it just seems not to want to work every time on this one system.

Have you verified that the same version of Time Conditions is being run on all systems? If so what version are you running?

We are running 2.11.0.5 on the systems.

We still seem to be experiencing this issue. We updated all out servers to 5.211.65-14 and updates the Time Condition module to 2.11.0.9. Some of the servers that where having the issue are now working but the servers that where not affected are now experiencing the issue.

Does anyone have thoughts on where to start looking to resolve this issue?

Seem to be having the same issue. dial code and message says “Time Activated”, but never actually activates, once the time condition is met then it works, but manual override is not working.

[2014-12-23 12:57:24] VERBOSE[1688] netsock2.c: == Using SIP RTP TOS bits 184
[2014-12-23 12:57:24] VERBOSE[1688] netsock2.c: == Using SIP RTP TOS bits 184
[2014-12-23 12:57:24] VERBOSE[1688] netsock2.c: == Using SIP RTP CoS mark 5
[2014-12-23 12:57:24] VERBOSE[1688] netsock2.c: == Using SIP RTP CoS mark 5
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:1] Macro("SIP/9215-00000017", "user-callerid,") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:1] Macro("SIP/9215-00000017", "user-callerid,") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/9215-00000017", "TOUCH_MONITOR=1419364644.41") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/9215-00000017", "TOUCH_MONITOR=1419364644.41") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/9215-00000017", "AMPUSER=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/9215-00000017", "AMPUSER=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/9215-00000017", "0?report") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/9215-00000017", "0?report") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/9215-00000017", "1?Set(REALCALLERIDNUM=9215)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/9215-00000017", "1?Set(REALCALLERIDNUM=9215)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/9215-00000017", "AMPUSER=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/9215-00000017", "AMPUSER=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/9215-00000017", "0?limit") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/9215-00000017", "0?limit") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/9215-00000017", "AMPUSERCIDNAME=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/9215-00000017", "AMPUSERCIDNAME=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/9215-00000017", "0?report") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/9215-00000017", "0?report") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/9215-00000017", "AMPUSERCID=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/9215-00000017", "AMPUSERCID=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/9215-00000017", "__DIAL_OPTIONS=trx") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/9215-00000017", "__DIAL_OPTIONS=trx") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/9215-00000017", "CALLERID(all)="User" <9215>") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/9215-00000017", "CALLERID(all)="User" <9215>") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/9215-00000017", "0?limit") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/9215-00000017", "0?limit") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/9215-00000017", "0?Set(GROUP(concurrency_limit)=9215)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/9215-00000017", "0?Set(GROUP(concurrency_limit)=9215)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:14] ExecIf("SIP/9215-00000017", "0?Set(CHANNEL(language)=)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:14] ExecIf("SIP/9215-00000017", "0?Set(CHANNEL(language)=)") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/9215-00000017", "0?continue") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/9215-00000017", "0?continue") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:16] Set("SIP/9215-00000017", "__TTL=64") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:16] Set("SIP/9215-00000017", "__TTL=64") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:17] GotoIf("SIP/9215-00000017", "1?continue") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:17] GotoIf("SIP/9215-00000017", "1?continue") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-user-callerid,s,28)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-user-callerid,s,28)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/9215-00000017", "CALLERID(number)=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/9215-00000017", "CALLERID(number)=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/9215-00000017", "CALLERID(name)=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/9215-00000017", "CALLERID(name)=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/9215-00000017", "CDR(cnum)=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/9215-00000017", "CDR(cnum)=9215") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/9215-00000017", "CDR(cnam)=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/9215-00000017", "CDR(cnam)=User") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/9215-00000017", "CHANNEL(language)=en") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/9215-00000017", "CHANNEL(language)=en") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:2] Macro("SIP/9215-00000017", "toggle-tc,3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:2] Macro("SIP/9215-00000017", "toggle-tc,3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:1] Set("SIP/9215-00000017", "INDEXES=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:1] Set("SIP/9215-00000017", "INDEXES=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:2] Set("SIP/9215-00000017", "TCMAINT=RETURN") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:2] Set("SIP/9215-00000017", "TCMAINT=RETURN") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:3] Set("SIP/9215-00000017", "TCSTATE=false") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:3] Set("SIP/9215-00000017", "TCSTATE=false") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:4] Set("SIP/9215-00000017", "LOOPCNT=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:4] Set("SIP/9215-00000017", "LOOPCNT=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:5] Set("SIP/9215-00000017", "ITER=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:5] Set("SIP/9215-00000017", "ITER=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:6] Set("SIP/9215-00000017", "INDEX=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:6] Set("SIP/9215-00000017", "INDEX=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:7] Set("SIP/9215-00000017", "MODE=") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:7] Set("SIP/9215-00000017", "MODE=") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:8] GotoIf("SIP/9215-00000017", "1?end1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:8] GotoIf("SIP/9215-00000017", "1?end1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-toggle-tc,s,10)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-toggle-tc,s,10)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:10] Set("SIP/9215-00000017", "ITER=2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:10] Set("SIP/9215-00000017", "ITER=2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:11] GotoIf("SIP/9215-00000017", "0?begin1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:11] GotoIf("SIP/9215-00000017", "0?begin1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:12] Set("SIP/9215-00000017", "LOOPCNT=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:12] Set("SIP/9215-00000017", "LOOPCNT=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:13] Set("SIP/9215-00000017", "ITER=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:13] Set("SIP/9215-00000017", "ITER=1") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:14] Set("SIP/9215-00000017", "INDEX=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:14] Set("SIP/9215-00000017", "INDEX=3") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:15] Set("SIP/9215-00000017", "DB(TC/3)=false") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:15] Set("SIP/9215-00000017", "DB(TC/3)=false") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:16] Set("SIP/9215-00000017", "ITER=2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:16] Set("SIP/9215-00000017", "ITER=2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:17] GotoIf("SIP/9215-00000017", "0?begin2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:17] GotoIf("SIP/9215-00000017", "0?begin2") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:18] GotoIf("SIP/9215-00000017", "1?playback") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:18] GotoIf("SIP/9215-00000017", "1?playback") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-toggle-tc,s,20)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Goto (macro-toggle-tc,s,20)
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:20] Playback("SIP/9215-00000017", "beep&silence/1&time&activated") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] pbx.c: -- Executing [s@macro-toggle-tc:20] Playback("SIP/9215-00000017", "beep&silence/1&time&activated") in new stack
[2014-12-23 12:57:24] VERBOSE[3195] file.c: --  Playing 'beep.ulaw' (language 'en')
[2014-12-23 12:57:24] VERBOSE[3195] file.c: --  Playing 'beep.ulaw' (language 'en')
[2014-12-23 12:57:24] VERBOSE[3195] file.c: --  Playing 'silence/1.ulaw' (language 'en')
[2014-12-23 12:57:24] VERBOSE[3195] file.c: --  Playing 'silence/1.ulaw' (language 'en')
[2014-12-23 12:57:25] VERBOSE[3195] file.c: --  Playing 'time.ulaw' (language 'en')
[2014-12-23 12:57:25] VERBOSE[3195] file.c: --  Playing 'time.ulaw' (language 'en')
[2014-12-23 12:57:26] VERBOSE[3195] file.c: --  Playing 'activated.ulaw' (language 'en')
[2014-12-23 12:57:26] VERBOSE[3195] file.c: --  Playing 'activated.ulaw' (language 'en')
[2014-12-23 12:57:26] NOTICE[3197] manager.c: Seems to have passed...
[2014-12-23 12:57:26] NOTICE[3197] manager.c: Seems to have passed...
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:3] Hangup("SIP/9215-00000017", "") in new stack
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: -- Executing [*273@from-internal:3] Hangup("SIP/9215-00000017", "") in new stack
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: == Spawn extension (from-internal, *273, 3) exited non-zero on 'SIP/9215-00000017'
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: == Spawn extension (from-internal, *273, 3) exited non-zero on 'SIP/9215-00000017'
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/9215-00000017", "") in new stack
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/9215-00000017", "") in new stack
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/9215-00000017'
[2014-12-23 12:57:27] VERBOSE[3195] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/9215-00000017'