[Jan 12 10:56:43] VERBOSE[4355]: [Jan 12 10:56:43] Asterisk Event Logger restarted
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:43] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26896]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26896]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26888]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26888]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26899]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26899]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26898]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_add()
[Jan 12 10:56:44] DEBUG[26898]: Asterisk Schedule Dump (1 in Q, 4486 Total, 5 Cache)
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:44] DEBUG[26898]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:44] DEBUG[26898]: |4486 | 0xb6efe3e7      | 0x821f178       | 000000 : 999996 |
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_add()
[Jan 12 10:56:44] DEBUG[26898]: Asterisk Schedule Dump (2 in Q, 4487 Total, 4 Cache)
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:44] DEBUG[26898]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:44] DEBUG[26898]: |4486 | 0xb6efe3e7      | 0x821f178       | 000000 : 999533 |
[Jan 12 10:56:44] DEBUG[26898]: |4487 | 0xb6f2ec1a      | 0x821e3d8       | 000003 : 999996 |
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:44] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:44] DEBUG[26898]: = Found Their Call ID: 7e09f9f846f4b72b2e7a9078300f5a8f@66.235.239.233 Their Tag  Our tag: as76d022af
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_del()
[Jan 12 10:56:44] DEBUG[26898]: Asterisk Schedule Dump (1 in Q, 4487 Total, 6 Cache)
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:44] DEBUG[26898]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:44] DEBUG[26898]: |4487 | 0xb6f2ec1a      | 0x821e3d8       | 000003 : 929887 |
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: Stopping retransmission on '7e09f9f846f4b72b2e7a9078300f5a8f@66.235.239.233' of Request 102: Match Found
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_del()
[Jan 12 10:56:44] DEBUG[26898]: Asterisk Schedule Dump (0 in Q, 4487 Total, 7 Cache)
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:44] DEBUG[26898]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: ast_sched_add()
[Jan 12 10:56:44] DEBUG[26898]: Asterisk Schedule Dump (1 in Q, 4488 Total, 6 Cache)
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
[Jan 12 10:56:44] DEBUG[26898]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:44] DEBUG[26898]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:44] DEBUG[26898]: |4488 | 0xb6f12964      | 0x821e3d8       | 000059 : 999996 |
[Jan 12 10:56:44] DEBUG[26898]: =============================================================
..chop
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (1 in Q, 4132 Total, 11 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4132 | 0xb709f245      | 0x1             | 000019 : 999995 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (2 in Q, 4133 Total, 10 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4133 | 0xb709f326      | 0x1             | 000009 : 999996 |
[Jan 12 10:56:48] DEBUG[26894]: |4132 | 0xb709f245      | 0x1             | 000019 : 999599 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26883]: Checking device state for device kevin
[Jan 12 10:56:48] DEBUG[26883]: iax2_devicestate(kevin): Found peer. What's device state of kevin? addr=0, defaddr=0 maxms=0, lastms=0
[Jan 12 10:56:48] DEBUG[26883]: Changing state for IAX2/kevin - state 5 (Unavailable)
[Jan 12 10:56:48] DEBUG[6182]: Device 'IAX2/kevin' changed to state '5' (Unavailable)
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (3 in Q, 4134 Total, 9 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4134 | 0xb70a2834      | 0x82215b8       | 000001 : 999996 |
[Jan 12 10:56:48] DEBUG[26894]: |4133 | 0xb709f326      | 0x1             | 000009 : 993158 |
[Jan 12 10:56:48] DEBUG[26894]: |4132 | 0xb709f245      | 0x1             | 000019 : 992761 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:48] DEBUG[26883]: Checking device state for device kevin
[Jan 12 10:56:48] DEBUG[26883]: iax2_devicestate(kevin): Found peer. What's device state of kevin? addr=-462298556, defaddr=0 maxms=0, lastms=0
[Jan 12 10:56:48] DEBUG[26883]: Changing state for IAX2/kevin - state 1 (Not in use)
[Jan 12 10:56:48] DEBUG[6183]: Device 'IAX2/kevin' changed to state '1' (Not in use)
[Jan 12 10:56:48] DEBUG[26896]: ast_sched_runq()
[Jan 12 10:56:48] DEBUG[26896]: ast_sched_wait()
[Jan 12 10:56:48] VERBOSE[26894]: [Jan 12 10:56:48]     -- Registered IAX2 'kevin' (AUTHENTICATED) at 68.226.113.228:4569
[Jan 12 10:56:48] NOTICE[26894]: Restricting registration for peer 'kevin' to 60 seconds (requested 300)
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (4 in Q, 4135 Total, 8 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4134 | 0xb70a2834      | 0x82215b8       | 000001 : 961831 |
[Jan 12 10:56:48] DEBUG[26894]: |4133 | 0xb709f326      | 0x1             | 000009 : 954993 |
[Jan 12 10:56:48] DEBUG[26894]: |4132 | 0xb709f245      | 0x1             | 000019 : 954596 |
[Jan 12 10:56:48] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000069 : 999995 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_del()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (3 in Q, 4135 Total, 9 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4134 | 0xb70a2834      | 0x82215b8       | 000001 : 961214 |
[Jan 12 10:56:48] DEBUG[26894]: |4133 | 0xb709f326      | 0x1             | 000009 : 954376 |
[Jan 12 10:56:48] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000069 : 999378 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_del()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (2 in Q, 4135 Total, 10 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4134 | 0xb70a2834      | 0x82215b8       | 000001 : 960703 |
[Jan 12 10:56:48] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000069 : 998867 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:48] DEBUG[26894]: Asterisk Schedule Dump (3 in Q, 4136 Total, 9 Cache)
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:48] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:48] DEBUG[26894]: |4134 | 0xb70a2834      | 0x82215b8       | 000001 : 960095 |
[Jan 12 10:56:48] DEBUG[26894]: |4136 | 0xb70a2834      | 0x82213b0       | 000001 : 999996 |
[Jan 12 10:56:48] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000069 : 998259 |
[Jan 12 10:56:48] DEBUG[26894]: =============================================================
[Jan 12 10:56:48] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:48] DEBUG[26883]: Checking device state for device kevin
[Jan 12 10:56:48] DEBUG[26883]: iax2_devicestate(kevin): Found peer. What's device state of kevin? addr=-462298556, defaddr=0 maxms=0, lastms=0
[Jan 12 10:56:48] DEBUG[26883]: Changing state for IAX2/kevin - state 1 (Not in use)
[Jan 12 10:56:48] DEBUG[6184]: Device 'IAX2/kevin' changed to state '1' (Not in use)
..chop
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:54] DEBUG[26894]: Asterisk Schedule Dump (2 in Q, 4137 Total, 10 Cache)
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:54] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:54] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000019 : 999996 |
[Jan 12 10:56:54] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000063 : 595293 |
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:54] DEBUG[26894]: Asterisk Schedule Dump (3 in Q, 4138 Total, 9 Cache)
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:54] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:54] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000009 : 999996 |
[Jan 12 10:56:54] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000019 : 999500 |
[Jan 12 10:56:54] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000063 : 594797 |
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:54] DEBUG[26894]: Asterisk Schedule Dump (4 in Q, 4139 Total, 8 Cache)
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:54] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:54] DEBUG[26894]: |4139 | 0xb70a2834      | 0x8229528       | 000001 : 999996 |
[Jan 12 10:56:54] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000009 : 999294 |
[Jan 12 10:56:54] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000019 : 998798 |
[Jan 12 10:56:54] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000063 : 594095 |
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] VERBOSE[26894]: [Jan 12 10:56:54]     -- Accepting AUTHENTICATED call from 68.226.113.228:
       > requested format = ulaw,
       > requested prefs = (),
       > actual format = ulaw,
       > host prefs = (ulaw),
       > priority = mine
[Jan 12 10:56:54] DEBUG[26883]: Checking device state for device kevin
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:54] DEBUG[26894]: Asterisk Schedule Dump (5 in Q, 4140 Total, 7 Cache)
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:54] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:54] DEBUG[26894]: |4139 | 0xb70a2834      | 0x8229528       | 000001 : 969584 |
[Jan 12 10:56:54] DEBUG[26894]: |4140 | 0xb70a2834      | 0x823a010       | 000001 : 999995 |
[Jan 12 10:56:54] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000009 : 968882 |
[Jan 12 10:56:54] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000019 : 968386 |
[Jan 12 10:56:54] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000063 : 563683 |
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[6189]: Launching 'Queue'
[Jan 12 10:56:54] VERBOSE[6189]: [Jan 12 10:56:54]     -- Executing Queue("IAX2/kevin-2", "testtype1|r") in new stack
[Jan 12 10:56:54] DEBUG[6189]: NO QUEUE_PRIO variable found. Using default.
[Jan 12 10:56:54] DEBUG[6189]: queue: testtype1, options: r, url: (null), announce: (null), expires: 0, priority: 0
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:54] DEBUG[26894]: Asterisk Schedule Dump (6 in Q, 4141 Total, 6 Cache)
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:54] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:54] DEBUG[26894]: |4139 | 0xb70a2834      | 0x8229528       | 000001 : 967990 |
[Jan 12 10:56:54] DEBUG[26894]: |4140 | 0xb70a2834      | 0x823a010       | 000001 : 998401 |
[Jan 12 10:56:54] DEBUG[26894]: |4141 | 0xb70a2834      | 0x82215b8       | 000001 : 999996 |
[Jan 12 10:56:54] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000009 : 967288 |
[Jan 12 10:56:54] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000019 : 966792 |
[Jan 12 10:56:54] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000063 : 562089 |
[Jan 12 10:56:54] DEBUG[26894]: =============================================================
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[6189]: It's our turn (IAX2/kevin-2).
[Jan 12 10:56:54] DEBUG[6189]: IAX2/kevin-2 is trying to call a queue member.
[Jan 12 10:56:54] DEBUG[6189]: Simple queue (no URL)
[Jan 12 10:56:54] DEBUG[6189]: Simple queue (no URL)
[Jan 12 10:56:54] DEBUG[6189]: Trying 'Agent/11000' with metric 0
[Jan 12 10:56:54] DEBUG[6189]: Trying 'Agent/11001' with metric 2000000
[Jan 12 10:56:54] ERROR[6189]: app_queue.c line 1322 (compare_weight): mutex '&qlock' freed more times than we've locked!
[Jan 12 10:56:54] ERROR[6189]: app_queue.c line 1322 (compare_weight): Error releasing mutex: Operation not permitted
[Jan 12 10:56:54] DEBUG[6189]: Nobody left to try ringing in queue
[Jan 12 10:56:54] ERROR[6189]: app_queue.c line 2108 (try_calling): mutex '&qlock' freed more times than we've locked!
[Jan 12 10:56:54] ERROR[6189]: app_queue.c line 2108 (try_calling): Error releasing mutex: Operation not permitted
[Jan 12 10:56:54] DEBUG[6189]: Everyone is busy at this time
[Jan 12 10:56:54] DEBUG[6189]: IAX2/kevin-2: Nobody answered.
[Jan 12 10:56:54] DEBUG[26883]: iax2_devicestate(kevin): Found peer. What's device state of kevin? addr=-462298556, defaddr=0 maxms=0, lastms=0
[Jan 12 10:56:54] DEBUG[26883]: Changing state for IAX2/kevin - state 2 (In use)
[Jan 12 10:56:54] DEBUG[6190]: Device 'IAX2/kevin' changed to state '2' (In use)
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:54] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:54] DEBUG[26894]: Ooh, voice format changed to 4
[Jan 12 10:56:54] DEBUG[26894]: Set channel IAX2/kevin-2 to read format ulaw
..chop
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_add()
[Jan 12 10:56:56] DEBUG[26894]: Asterisk Schedule Dump (7 in Q, 4142 Total, 5 Cache)
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:56] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:56] DEBUG[26894]: |4139 | 0xb70a2834      | 0x8229528       | 000000 : 001918 |
[Jan 12 10:56:56] DEBUG[26894]: |4140 | 0xb70a2834      | 0x823a010       | 000000 : 032329 |
[Jan 12 10:56:56] DEBUG[26894]: |4141 | 0xb70a2834      | 0x82215b8       | 000000 : 033924 |
[Jan 12 10:56:56] DEBUG[26894]: |4142 | 0xb70a2834      | 0x8244c30       | 000001 : 999995 |
[Jan 12 10:56:56] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000008 : 001216 |
[Jan 12 10:56:56] DEBUG[26894]: |4137 | 0xb709f245      | 0x2             | 000018 : 000720 |
[Jan 12 10:56:56] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000061 : 596017 |
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] DEBUG[26894]: Immediately destroying 2, having received hangup
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_del()
[Jan 12 10:56:56] DEBUG[26894]: Asterisk Schedule Dump (3 in Q, 4142 Total, 9 Cache)
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:56] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:56] DEBUG[26894]: |4142 | 0xb70a2834      | 0x8244c30       | 000001 : 952073 |
[Jan 12 10:56:56] DEBUG[26894]: |4138 | 0xb709f326      | 0x2             | 000007 : 953294 |
[Jan 12 10:56:56] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000061 : 548095 |
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_del()
[Jan 12 10:56:56] DEBUG[26894]: Asterisk Schedule Dump (2 in Q, 4142 Total, 10 Cache)
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: |ID    Callback          Data              Time  (sec:ms)   |
[Jan 12 10:56:56] DEBUG[26894]: +-----+-----------------+-----------------+-----------------+
[Jan 12 10:56:56] DEBUG[26894]: |4142 | 0xb70a2834      | 0x8244c30       | 000001 : 951564 |
[Jan 12 10:56:56] DEBUG[26894]: |4135 | 0xb70b1868      | 0x81f24e0       | 000061 : 547586 |
[Jan 12 10:56:56] DEBUG[26894]: =============================================================
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_runq()
[Jan 12 10:56:56] DEBUG[26894]: ast_sched_wait()
[Jan 12 10:56:56] VERBOSE[6189]: [Jan 12 10:56:56]     -- User disconnected from queue testtype1 when they almost made it
[Jan 12 10:56:56] DEBUG[6189]: Spawn extension (default,301,1) exited non-zero on 'IAX2/kevin-2'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'Agent 1'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '(null)'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '301'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'default'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'IAX2/kevin-2'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '(null)'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'Queue'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'testtype1|r'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '2006-01-12 10:56:54'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '(null)'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '2006-01-12 10:56:56'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '2'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '0'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'BUSY'
[Jan 12 10:56:56] DEBUG[6189]: Function result is 'DOCUMENTATION'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '(null)'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '1137088614.5'
[Jan 12 10:56:56] DEBUG[6189]: Function result is '(null)'
[Jan 12 10:56:56] DEBUG[6189]: Hanging up channel 'IAX2/kevin-2'
[Jan 12 10:56:56] DEBUG[6189]: We're hanging up IAX2/kevin-2 now...
[Jan 12 10:56:56] DEBUG[6189]: Really destroying IAX2/kevin-2 now...
[Jan 12 10:56:56] VERBOSE[6189]: [Jan 12 10:56:56]     -- Hungup 'IAX2/kevin-2'
[Jan 12 10:56:56] DEBUG[26883]: Checking device state for device kevin
[Jan 12 10:56:56] DEBUG[26883]: iax2_devicestate(kevin): Found peer. What's device state of kevin? addr=-462298556, defaddr=0 maxms=0, lastms=0
[Jan 12 10:56:56] DEBUG[26883]: Changing state for IAX2/kevin - state 1 (Not in use)
[Jan 12 10:56:56] DEBUG[6195]: Device 'IAX2/kevin' changed to state '1' (Not in use)
..chop