[Jul 25 08:57:24] VERBOSE[4267] logger.c: Asterisk Event Logger restarted
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0100 (12 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0094 (48 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] logger.c: unknown1 in handle_stimulus_message is '0'
[Jul 25 08:57:42] WARNING[4249] chan_skinny.c: Could not find subchannel with reference '0' on '5245'
[Jul 25 08:57:42] VERBOSE[4249] logger.c: Received Stimulus: Line(1)
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] logger.c: Setting ringer mode to '1'.
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] logger.c: skinny_new: tmp->nativeformats=12 fmt=4
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] logger.c: Attempting to Clear display on Skinny 5245@5245
[Jul 25 08:57:42] VERBOSE[4249] logger.c: Clearing Display
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 009A (12 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0082 (28 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4249] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4268] logger.c:     -- Starting simple switch on '5245@5245'
[Jul 25 08:57:42] WARNING[4260] chan_skinny.c: Could not find subchannel with reference '0' on '5501'
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Received Softkey Event: New Call(1)
[Jul 25 08:57:42] VERBOSE[4260] logger.c: skinny_new: tmp->nativeformats=12 fmt=4
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Attempting to Clear display on Skinny 5501@5501
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Clearing Display
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 009A (12 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 0082 (28 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4269] logger.c:     -- Starting simple switch on '5501@5501'
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Collected digit: [5]
[Jul 25 08:57:42] VERBOSE[4249] logger.c: Collected digit: [5]
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4269] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5501@5501-2
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4268] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5245@5245-1
[Jul 25 08:57:42] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Collected digit: [5]
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4269] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5501@5501-2
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4260] logger.c: Collected digit: [0]
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:42] VERBOSE[4269] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5501@5501-2
[Jul 25 08:57:42] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4249] logger.c: Collected digit: [2]
[Jul 25 08:57:43] VERBOSE[4260] logger.c: Collected digit: [0]
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4268] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5245@5245-1
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4249] logger.c: Collected digit: [2]
[Jul 25 08:57:43] VERBOSE[4249] logger.c: Collected digit: [8]
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:43] DEBUG[4269] devicestate.c: Notification of state change to be queued on device/channel Skinny/5501@5501-2
[Jul 25 08:57:43] DEBUG[4269] pbx.c: Launching 'Macro'
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Executing [5500@longdistance:1] Macro("Skinny/5501@5501-2", "stdexten|5500|Skinny/5500@5500") in new stack
[Jul 25 08:57:43] DEBUG[4269] pbx.c: Launching 'Set'
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Executing [s@macro-stdexten:1] Set("Skinny/5501@5501-2", "TIMEOUT(absolute)=0") in new stack
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Channel hangup cancelled.
[Jul 25 08:57:43] DEBUG[4269] app_macro.c: Executed application: Set
[Jul 25 08:57:43] DEBUG[4269] pbx.c: Launching 'Answer'
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Executing [s@macro-stdexten:2] Answer("Skinny/5501@5501-2", "") in new stack
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0105 (100 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4269] logger.c: skinny_answer(Skinny/5501@5501-2) on 5501@5501-2
[Jul 25 08:57:43] DEBUG[4269] devicestate.c: Notification of state change to be queued on device/channel Skinny/5501@5501-2
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Setting Callinfo to Everett Lecates(5501) from s(s) on 5501(1)
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 008F (396 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 28
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Displaying Prompt Status 'Connected'
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 28
[Jul 25 08:57:43] DEBUG[4269] app_macro.c: Executed application: Answer
[Jul 25 08:57:43] DEBUG[4269] pbx.c: Launching 'Dial'
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Executing [s@macro-stdexten:3] Dial("Skinny/5501@5501-2", "Skinny/5500@5500|20|tr") in new stack
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Found device: 5500
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- skinny_request(5500@5500)
[Jul 25 08:57:43] VERBOSE[4269] logger.c: skinny_new: tmp->nativeformats=12 fmt=4
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable STACK-macro-stdexten-s-3.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable MACRO_DEPTH.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable STACK-macro-stdexten-s-2.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable STACK-macro-stdexten-s-1.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable ARG2.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable ARG1.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable MACRO_PRIORITY.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable MACRO_CONTEXT.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable MACRO_EXTEN.
[Jul 25 08:57:43] DEBUG[4269] channel.c: Not copying variable STACK-longdistance-5500-1.
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- skinny_call(Skinny/5500@5500-3)
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 18
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Displaying Prompt Status 'Ring-In'
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 18
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Setting Callinfo to Everett Lecates(5501) from Scott Bisker(5500) on 5500(1)
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 008F (396 bytes) to socket 18
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:57:43] VERBOSE[4269] logger.c: Setting ringer mode to '2'.
[Jul 25 08:57:43] VERBOSE[4269] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 18
[Jul 25 08:57:43] DEBUG[4269] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-3
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Called 5500@5500
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5501@5501-2
[Jul 25 08:57:43] DEBUG[4269] channel.c: Driver for channel 'Skinny/5501@5501-2' does not support indication 3, emulating it
[Jul 25 08:57:43] DEBUG[4269] channel.c: Set channel Skinny/5501@5501-2 to write format slin
[Jul 25 08:57:43] DEBUG[4269] channel.c: Scheduling timer at 160 sample intervals
[Jul 25 08:57:43] VERBOSE[4269] logger.c:     -- Skinny/5500@5500-3 is ringing
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5501@5501
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: Changing state for Skinny/5501@5501 - state 2 (In use)
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5501@5501
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: Changing state for Skinny/5501@5501 - state 2 (In use)
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 6 (Ringing)
[Jul 25 08:57:43] DEBUG[4270] app_queue.c: Device 'Skinny/5501@5501' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:57:43] DEBUG[4271] app_queue.c: Device 'Skinny/5501@5501' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:57:43] DEBUG[4272] app_queue.c: Device 'Skinny/5500@5500' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jul 25 08:57:43] VERBOSE[4260] logger.c: Received Open Receive Channel Ack
[Jul 25 08:57:43] VERBOSE[4260] logger.c: ipaddr = 192.168.0.217:25984
[Jul 25 08:57:43] VERBOSE[4260] logger.c: ourip = 192.168.1.12:15024
[Jul 25 08:57:43] VERBOSE[4260] logger.c: Setting payloadType to '4' (20 ms)
[Jul 25 08:57:43] VERBOSE[4260] chan_skinny.c: writing packet type 008A (116 bytes) to socket 28
[Jul 25 08:57:43] DEBUG[4269] rtp.c: Ooh, format changed from unknown to ulaw
[Jul 25 08:57:43] DEBUG[4269] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:43] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel Skinny/5245@5245-1
[Jul 25 08:57:43] DEBUG[4268] pbx.c: Launching 'Dial'
[Jul 25 08:57:43] VERBOSE[4268] logger.c:     -- Executing [5228@longdistance:1] Dial("Skinny/5245@5245-1", "IAX2/isdpbx:password@isdpbx/5228") in new stack
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5245@5245
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: Changing state for Skinny/5245@5245 - state 2 (In use)
[Jul 25 08:57:43] DEBUG[4273] app_queue.c: Device 'Skinny/5245@5245' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:57:43] DEBUG[4268] rtp.c: Channel 'IAX2/192.168.1.15:4569-1' has no RTP, not doing anything
[Jul 25 08:57:43] DEBUG[4268] channel.c: Not copying variable STACK-longdistance-5228-1.
[Jul 25 08:57:43] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel IAX2/192.168.1.15:4569-1
[Jul 25 08:57:43] VERBOSE[4268] logger.c:     -- Called isdpbx:password@isdpbx/5228
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for IAX2 - 192.168.1.15:4569
[Jul 25 08:57:43] DEBUG[4199] chan_iax2.c: Checking device state for device 192.168.1.15
[Jul 25 08:57:43] DEBUG[4199] devicestate.c: Changing state for IAX2/192.168.1.15:4569 - state 4 (Invalid)
[Jul 25 08:57:43] DEBUG[4274] app_queue.c: Device 'IAX2/192.168.1.15:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 25 08:57:43] VERBOSE[4234] logger.c:     -- Call accepted by 192.168.1.15 (format ulaw)
[Jul 25 08:57:43] VERBOSE[4234] logger.c:     -- Format for call is ulaw
[Jul 25 08:57:43] DEBUG[4234] channel.c: Set channel IAX2/192.168.1.15:4569-1 to write format ulaw
[Jul 25 08:57:43] DEBUG[4234] channel.c: Set channel IAX2/192.168.1.15:4569-1 to read format ulaw
[Jul 25 08:57:43] VERBOSE[4268] logger.c:     -- IAX2/192.168.1.15:4569-1 is ringing
[Jul 25 08:57:43] DEBUG[4268] rtp.c: Channel 'IAX2/192.168.1.15:4569-1' has no RTP, not doing anything
[Jul 25 08:57:43] VERBOSE[4268] logger.c:     -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5245@5245-1
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0082 (28 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 011D (44 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4268] logger.c: Displaying Prompt Status 'Ring Out'
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 17
[Jul 25 08:57:43] VERBOSE[4268] logger.c: Setting Callinfo to Tom Campbell(5245) from 5228(5228) on 5245(1)
[Jul 25 08:57:43] VERBOSE[4268] chan_skinny.c: writing packet type 008F (396 bytes) to socket 17
[Jul 25 08:57:43] DEBUG[4269] chan_skinny.c: Oooh, format changed to 4
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Generator got voice, switching to phase locked mode
[Jul 25 08:57:43] DEBUG[4269] channel.c: Scheduling timer at 0 sample intervals
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:43] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] DEBUG[4269] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38)
[Jul 25 08:57:44] VERBOSE[4250] logger.c: Received Softkey Event: Answer(1)
[Jul 25 08:57:44] VERBOSE[4250] logger.c: Setting ringer mode to '1'.
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 18
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 0105 (100 bytes) to socket 18
[Jul 25 08:57:44] DEBUG[4250] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-3
[Jul 25 08:57:44] VERBOSE[4269] logger.c:     -- Skinny/5500@5500-3 answered Skinny/5501@5501-2
[Jul 25 08:57:44] VERBOSE[4269] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5501@5501-2
[Jul 25 08:57:44] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 28
[Jul 25 08:57:44] DEBUG[4269] channel.c: Set channel Skinny/5501@5501-2 to write format ulaw
[Jul 25 08:57:44] DEBUG[4269] channel.c: Scheduling timer at 0 sample intervals
[Jul 25 08:57:44] DEBUG[4269] channel.c: Dropping duplicate answer!
[Jul 25 08:57:44] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:57:44] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 2 (In use)
[Jul 25 08:57:44] DEBUG[4275] app_queue.c: Device 'Skinny/5500@5500' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:57:44] VERBOSE[4250] logger.c: Received Open Receive Channel Ack
[Jul 25 08:57:44] VERBOSE[4250] logger.c: ipaddr = 192.168.0.218:18688
[Jul 25 08:57:44] VERBOSE[4250] logger.c: ourip = 192.168.1.12:16724
[Jul 25 08:57:44] VERBOSE[4250] logger.c: Setting payloadType to '4' (20 ms)
[Jul 25 08:57:44] VERBOSE[4250] chan_skinny.c: writing packet type 008A (116 bytes) to socket 18
[Jul 25 08:57:44] DEBUG[4269] rtp.c: Ooh, format changed from unknown to ulaw
[Jul 25 08:57:44] DEBUG[4269] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jul 25 08:57:44] DEBUG[4269] chan_skinny.c: Oooh, format changed to 4
[Jul 25 08:57:49] VERBOSE[4250] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4250] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4250] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4250] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4250] chan_skinny.c: writing packet type 008B (32 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4250] logger.c: Skinny 5500@5500 went on hook
[Jul 25 08:57:49] DEBUG[4269] channel.c: Didn't get a frame from channel: Skinny/5500@5500-3
[Jul 25 08:57:49] DEBUG[4269] channel.c: Bridge stops bridging channels Skinny/5501@5501-2 and Skinny/5500@5500-3
[Jul 25 08:57:49] DEBUG[4269] channel.c: Hanging up channel 'Skinny/5500@5500-3'
[Jul 25 08:57:49] VERBOSE[4269] logger.c: skinny_hangup(Skinny/5500@5500-3) on 5500@5500
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 008B (32 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] logger.c: Setting ringer mode to '1'.
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0094 (48 bytes) to socket 18
[Jul 25 08:57:49] DEBUG[4269] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-3
[Jul 25 08:57:49] DEBUG[4269] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 25 08:57:49] DEBUG[4269] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jul 25 08:57:49] DEBUG[4269] app_macro.c: Spawn extension (macro-stdexten,s,3) exited non-zero on 'Skinny/5501@5501-2' in macro 'stdexten'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Spawn extension (macro-stdexten,s,3) exited non-zero on 'Skinny/5501@5501-2'
[Jul 25 08:57:49] VERBOSE[4269] logger.c:   == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5501@5501-2'
[Jul 25 08:57:49] DEBUG[4269] channel.c: Soft-Hanging up channel 'Skinny/5501@5501-2'
[Jul 25 08:57:49] DEBUG[4269] channel.c: Hanging up channel 'Skinny/5501@5501-2'
[Jul 25 08:57:49] VERBOSE[4269] logger.c: skinny_hangup(Skinny/5501@5501-2) on 5501@5501
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 008B (32 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 28
[Jul 25 08:57:49] VERBOSE[4269] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 28
[Jul 25 08:57:49] DEBUG[4269] devicestate.c: Notification of state change to be queued on device/channel Skinny/5501@5501-2
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '"Everett Lecates" <5501>'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '5501'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '5500'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'longdistance'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'Skinny/5501@5501-2'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'Skinny/5500@5500-3'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'Dial'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'Skinny/5500@5500|20|tr'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '2007-07-25 08:57:42'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '2007-07-25 08:57:43'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '2007-07-25 08:57:49'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '7'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '6'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'ANSWERED'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is 'DOCUMENTATION'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is ''
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is '1185368262.1'
[Jul 25 08:57:49] DEBUG[4269] pbx.c: Function result is ''
[Jul 25 08:57:49] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:57:49] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 0 (Unknown)
[Jul 25 08:57:49] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5501@5501
[Jul 25 08:57:49] DEBUG[4199] devicestate.c: Changing state for Skinny/5501@5501 - state 0 (Unknown)
[Jul 25 08:57:49] DEBUG[4276] app_queue.c: Device 'Skinny/5500@5500' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jul 25 08:57:49] DEBUG[4277] app_queue.c: Device 'Skinny/5501@5501' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jul 25 08:57:52] VERBOSE[4268] logger.c:     -- IAX2/192.168.1.15:4569-1 stopped sounds
[Jul 25 08:57:52] VERBOSE[4268] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5245@5245-1
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:52] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel IAX2/192.168.1.15:4569-1
[Jul 25 08:57:52] VERBOSE[4268] logger.c:     -- IAX2/192.168.1.15:4569-1 answered Skinny/5245@5245-1
[Jul 25 08:57:52] DEBUG[4268] rtp.c: Channel 'IAX2/192.168.1.15:4569-1' has no RTP, not doing anything
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0105 (100 bytes) to socket 17
[Jul 25 08:57:52] VERBOSE[4268] logger.c: skinny_answer(Skinny/5245@5245-1) on 5245@5245-1
[Jul 25 08:57:52] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel Skinny/5245@5245-1
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:57:52] VERBOSE[4268] logger.c: Setting Callinfo to Tom Campbell(5245) from 5228(5228) on 5245(1)
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 008F (396 bytes) to socket 17
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 17
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 17
[Jul 25 08:57:52] VERBOSE[4268] logger.c: Displaying Prompt Status 'Connected'
[Jul 25 08:57:52] VERBOSE[4268] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 17
[Jul 25 08:57:52] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for IAX2 - 192.168.1.15:4569
[Jul 25 08:57:52] DEBUG[4199] chan_iax2.c: Checking device state for device 192.168.1.15
[Jul 25 08:57:52] DEBUG[4199] devicestate.c: Changing state for IAX2/192.168.1.15:4569 - state 4 (Invalid)
[Jul 25 08:57:52] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5245@5245
[Jul 25 08:57:52] DEBUG[4199] devicestate.c: Changing state for Skinny/5245@5245 - state 2 (In use)
[Jul 25 08:57:52] DEBUG[4278] app_queue.c: Device 'IAX2/192.168.1.15:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 25 08:57:52] DEBUG[4279] app_queue.c: Device 'Skinny/5245@5245' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:57:52] DEBUG[4240] chan_iax2.c: Ooh, voice format changed to 4
[Jul 25 08:57:52] VERBOSE[4249] logger.c: Received Open Receive Channel Ack
[Jul 25 08:57:52] VERBOSE[4249] logger.c: ipaddr = 192.168.0.200:29106
[Jul 25 08:57:52] VERBOSE[4249] logger.c: ourip = 192.168.1.12:19488
[Jul 25 08:57:52] VERBOSE[4249] logger.c: Setting payloadType to '4' (20 ms)
[Jul 25 08:57:52] VERBOSE[4249] chan_skinny.c: writing packet type 008A (116 bytes) to socket 17
[Jul 25 08:57:52] DEBUG[4268] rtp.c: Ooh, format changed from unknown to ulaw
[Jul 25 08:57:52] DEBUG[4268] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jul 25 08:57:52] DEBUG[4268] rtp.c: Got RTCP report of 52 bytes
[Jul 25 08:57:52] DEBUG[4268] chan_skinny.c: Oooh, format changed to 4
[Jul 25 08:57:54] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes