[Jul 25 08:57:56] VERBOSE[4267] logger.c: Asterisk Event Logger restarted
[Jul 25 08:57:56] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:57:58] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:00] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:02] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:02] VERBOSE[4248] logger.c: unknown1 in handle_stimulus_message is '0'
[Jul 25 08:58:02] WARNING[4248] chan_skinny.c: Could not find subchannel with reference '0' on '5502'
[Jul 25 08:58:02] VERBOSE[4248] logger.c: Received Stimulus: Line(1)
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] logger.c: Setting ringer mode to '1'.
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] logger.c: skinny_new: tmp->nativeformats=12 fmt=4
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] logger.c: Attempting to Clear display on Skinny 5502@5502
[Jul 25 08:58:02] VERBOSE[4248] logger.c: Clearing Display
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 009A (12 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0082 (28 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4248] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 16
[Jul 25 08:58:02] VERBOSE[4280] logger.c:     -- Starting simple switch on '5502@5502'
[Jul 25 08:58:03] VERBOSE[4248] logger.c: Collected digit: [5]
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5502@5502-4
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4248] logger.c: Collected digit: [5]
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5502@5502-4
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4248] logger.c: Collected digit: [0]
[Jul 25 08:58:03] VERBOSE[4248] logger.c: Collected digit: [0]
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] DEBUG[4280] devicestate.c: Notification of state change to be queued on device/channel Skinny/5502@5502-4
[Jul 25 08:58:03] DEBUG[4280] pbx.c: Launching 'Macro'
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Executing [5500@longdistance:1] Macro("Skinny/5502@5502-4", "stdexten|5500|Skinny/5500@5500") in new stack
[Jul 25 08:58:03] DEBUG[4280] pbx.c: Launching 'Set'
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Executing [s@macro-stdexten:1] Set("Skinny/5502@5502-4", "TIMEOUT(absolute)=0") in new stack
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Channel hangup cancelled.
[Jul 25 08:58:03] DEBUG[4280] app_macro.c: Executed application: Set
[Jul 25 08:58:03] DEBUG[4280] pbx.c: Launching 'Answer'
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Executing [s@macro-stdexten:2] Answer("Skinny/5502@5502-4", "") in new stack
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0105 (100 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] logger.c: skinny_answer(Skinny/5502@5502-4) on 5502@5502-4
[Jul 25 08:58:03] DEBUG[4280] devicestate.c: Notification of state change to be queued on device/channel Skinny/5502@5502-4
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Setting Callinfo to Everett Lecates(5502) from s(s) on 5502(1)
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 008F (396 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 16
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Displaying Prompt Status 'Connected'
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 16
[Jul 25 08:58:03] DEBUG[4280] app_macro.c: Executed application: Answer
[Jul 25 08:58:03] DEBUG[4280] pbx.c: Launching 'Dial'
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Executing [s@macro-stdexten:3] Dial("Skinny/5502@5502-4", "Skinny/5500@5500|20|tr") in new stack
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Found device: 5500
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- skinny_request(5500@5500)
[Jul 25 08:58:03] VERBOSE[4280] logger.c: skinny_new: tmp->nativeformats=12 fmt=4
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable STACK-macro-stdexten-s-3.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable MACRO_DEPTH.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable STACK-macro-stdexten-s-2.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable STACK-macro-stdexten-s-1.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable ARG2.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable ARG1.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable MACRO_PRIORITY.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable MACRO_CONTEXT.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable MACRO_EXTEN.
[Jul 25 08:58:03] DEBUG[4280] channel.c: Not copying variable STACK-longdistance-5500-1.
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- skinny_call(Skinny/5500@5500-5)
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 18
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Displaying Prompt Status 'Ring-In'
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0112 (56 bytes) to socket 18
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Setting Callinfo to Everett Lecates(5502) from Scott Bisker(5500) on 5500(1)
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 008F (396 bytes) to socket 18
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:58:03] VERBOSE[4280] logger.c: Setting ringer mode to '2'.
[Jul 25 08:58:03] VERBOSE[4280] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 18
[Jul 25 08:58:03] DEBUG[4280] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-5
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Called 5500@5500
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5502@5502-4
[Jul 25 08:58:03] DEBUG[4280] channel.c: Driver for channel 'Skinny/5502@5502-4' does not support indication 3, emulating it
[Jul 25 08:58:03] DEBUG[4280] channel.c: Set channel Skinny/5502@5502-4 to write format slin
[Jul 25 08:58:03] DEBUG[4280] channel.c: Scheduling timer at 160 sample intervals
[Jul 25 08:58:03] VERBOSE[4280] logger.c:     -- Skinny/5500@5500-5 is ringing
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5502@5502
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: Changing state for Skinny/5502@5502 - state 2 (In use)
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5502@5502
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: Changing state for Skinny/5502@5502 - state 2 (In use)
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:58:03] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 6 (Ringing)
[Jul 25 08:58:03] DEBUG[4281] app_queue.c: Device 'Skinny/5502@5502' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:58:03] DEBUG[4282] app_queue.c: Device 'Skinny/5502@5502' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 25 08:58:03] DEBUG[4283] 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:58:03] VERBOSE[4248] logger.c: Received Open Receive Channel Ack
[Jul 25 08:58:03] VERBOSE[4248] logger.c: ipaddr = 192.168.0.205:29110
[Jul 25 08:58:03] VERBOSE[4248] logger.c: ourip = 192.168.1.12:17000
[Jul 25 08:58:03] VERBOSE[4248] logger.c: Setting payloadType to '4' (20 ms)
[Jul 25 08:58:03] VERBOSE[4248] chan_skinny.c: writing packet type 008A (116 bytes) to socket 16
[Jul 25 08:58:03] DEBUG[4280] rtp.c: Ooh, format changed from unknown to ulaw
[Jul 25 08:58:03] DEBUG[4280] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jul 25 08:58:03] DEBUG[4280] chan_skinny.c: Oooh, format changed to 4
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Generator got voice, switching to phase locked mode
[Jul 25 08:58:03] DEBUG[4280] channel.c: Scheduling timer at 0 sample intervals
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:03] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4268] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] DEBUG[4280] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40)
[Jul 25 08:58:04] VERBOSE[4250] logger.c: Received Softkey Event: Answer(1)
[Jul 25 08:58:04] VERBOSE[4250] logger.c: Setting ringer mode to '1'.
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0110 (28 bytes) to socket 18
[Jul 25 08:58:04] VERBOSE[4250] chan_skinny.c: writing packet type 0105 (100 bytes) to socket 18
[Jul 25 08:58:04] DEBUG[4250] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-5
[Jul 25 08:58:04] VERBOSE[4280] logger.c:     -- Skinny/5500@5500-5 answered Skinny/5502@5502-4
[Jul 25 08:58:04] VERBOSE[4280] logger.c:     -- Asked to indicate 'Stop tone' condition on channel Skinny/5502@5502-4
[Jul 25 08:58:04] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:04] DEBUG[4280] channel.c: Set channel Skinny/5502@5502-4 to write format ulaw
[Jul 25 08:58:04] DEBUG[4280] channel.c: Scheduling timer at 0 sample intervals
[Jul 25 08:58:04] DEBUG[4280] channel.c: Dropping duplicate answer!
[Jul 25 08:58:04] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:58:04] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 2 (In use)
[Jul 25 08:58:04] DEBUG[4284] 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:58:05] VERBOSE[4250] logger.c: Received Open Receive Channel Ack
[Jul 25 08:58:05] VERBOSE[4250] logger.c: ipaddr = 192.168.0.218:23552
[Jul 25 08:58:05] VERBOSE[4250] logger.c: ourip = 192.168.1.12:18382
[Jul 25 08:58:05] VERBOSE[4250] logger.c: Setting payloadType to '4' (20 ms)
[Jul 25 08:58:05] VERBOSE[4250] chan_skinny.c: writing packet type 008A (116 bytes) to socket 18
[Jul 25 08:58:05] DEBUG[4280] rtp.c: Ooh, format changed from unknown to ulaw
[Jul 25 08:58:05] DEBUG[4280] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jul 25 08:58:05] DEBUG[4280] chan_skinny.c: Oooh, format changed to 4
[Jul 25 08:58:05] DEBUG[4280] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:06] VERBOSE[4249] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4249] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4249] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4249] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4249] chan_skinny.c: writing packet type 008B (32 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4249] logger.c: Skinny 5245@5245 went on hook
[Jul 25 08:58:06] DEBUG[4268] channel.c: Didn't get a frame from channel: Skinny/5245@5245-1
[Jul 25 08:58:06] DEBUG[4268] channel.c: Bridge stops bridging channels Skinny/5245@5245-1 and IAX2/192.168.1.15:4569-1
[Jul 25 08:58:06] DEBUG[4268] channel.c: Hanging up channel 'IAX2/192.168.1.15:4569-1'
[Jul 25 08:58:06] DEBUG[4268] chan_iax2.c: We're hanging up IAX2/192.168.1.15:4569-1 now...
[Jul 25 08:58:06] VERBOSE[4268] logger.c:     -- Hungup 'IAX2/192.168.1.15:4569-1'
[Jul 25 08:58:06] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel IAX2/192.168.1.15:4569-1
[Jul 25 08:58:06] DEBUG[4268] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 25 08:58:06] DEBUG[4268] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Spawn extension (longdistance,5228,1) exited non-zero on 'Skinny/5245@5245-1'
[Jul 25 08:58:06] VERBOSE[4268] logger.c:   == Spawn extension (longdistance, 5228, 1) exited non-zero on 'Skinny/5245@5245-1'
[Jul 25 08:58:06] DEBUG[4268] channel.c: Soft-Hanging up channel 'Skinny/5245@5245-1'
[Jul 25 08:58:06] DEBUG[4268] channel.c: Hanging up channel 'Skinny/5245@5245-1'
[Jul 25 08:58:06] VERBOSE[4268] logger.c: skinny_hangup(Skinny/5245@5245-1) on 5245@5245
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 008B (32 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] logger.c: Setting ringer mode to '1'.
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 17
[Jul 25 08:58:06] VERBOSE[4268] chan_skinny.c: writing packet type 0094 (48 bytes) to socket 17
[Jul 25 08:58:06] DEBUG[4268] devicestate.c: Notification of state change to be queued on device/channel Skinny/5245@5245-1
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '"Tom Campbell" <5245>'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '5245'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '5228'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'longdistance'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'Skinny/5245@5245-1'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'IAX2/192.168.1.15:4569-1'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'Dial'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'IAX2/isdpbx:password@isdpbx/5228'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '2007-07-25 08:57:42'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '2007-07-25 08:57:52'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '2007-07-25 08:58:06'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '24'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '14'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'ANSWERED'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is 'DOCUMENTATION'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is ''
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is '1185368262.0'
[Jul 25 08:58:06] DEBUG[4268] pbx.c: Function result is ''
[Jul 25 08:58:06] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for IAX2 - 192.168.1.15:4569
[Jul 25 08:58:06] DEBUG[4199] chan_iax2.c: Checking device state for device 192.168.1.15
[Jul 25 08:58:06] DEBUG[4199] devicestate.c: Changing state for IAX2/192.168.1.15:4569 - state 4 (Invalid)
[Jul 25 08:58:06] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5245@5245
[Jul 25 08:58:06] DEBUG[4199] devicestate.c: Changing state for Skinny/5245@5245 - state 0 (Unknown)
[Jul 25 08:58:06] DEBUG[4285] 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:58:06] DEBUG[4286] app_queue.c: Device 'Skinny/5245@5245' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jul 25 08:58:07] DEBUG[4280] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:09] DEBUG[4280] rtp.c: Got RTCP report of 72 bytes
[Jul 25 08:58:09] VERBOSE[4248] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4248] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4248] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4248] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4248] chan_skinny.c: writing packet type 008B (32 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4248] logger.c: Skinny 5502@5502 went on hook
[Jul 25 08:58:09] DEBUG[4280] channel.c: Didn't get a frame from channel: Skinny/5502@5502-4
[Jul 25 08:58:09] DEBUG[4280] channel.c: Bridge stops bridging channels Skinny/5502@5502-4 and Skinny/5500@5500-5
[Jul 25 08:58:09] DEBUG[4280] channel.c: Hanging up channel 'Skinny/5500@5500-5'
[Jul 25 08:58:09] VERBOSE[4280] logger.c: skinny_hangup(Skinny/5500@5500-5) on 5500@5500
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 008B (32 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 18
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 18
[Jul 25 08:58:09] DEBUG[4280] devicestate.c: Notification of state change to be queued on device/channel Skinny/5500@5500-5
[Jul 25 08:58:09] DEBUG[4280] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 25 08:58:09] DEBUG[4280] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jul 25 08:58:09] DEBUG[4280] app_macro.c: Spawn extension (macro-stdexten,s,3) exited non-zero on 'Skinny/5502@5502-4' in macro 'stdexten'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Spawn extension (macro-stdexten,s,3) exited non-zero on 'Skinny/5502@5502-4'
[Jul 25 08:58:09] VERBOSE[4280] logger.c:   == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5502@5502-4'
[Jul 25 08:58:09] DEBUG[4280] channel.c: Soft-Hanging up channel 'Skinny/5502@5502-4'
[Jul 25 08:58:09] DEBUG[4280] channel.c: Hanging up channel 'Skinny/5502@5502-4'
[Jul 25 08:58:09] VERBOSE[4280] logger.c: skinny_hangup(Skinny/5502@5502-4) on 5502@5502
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0111 (36 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0116 (16 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0106 (28 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 008B (32 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0088 (16 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] logger.c: Setting ringer mode to '1'.
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0085 (32 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0083 (20 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0086 (24 bytes) to socket 16
[Jul 25 08:58:09] VERBOSE[4280] chan_skinny.c: writing packet type 0094 (48 bytes) to socket 16
[Jul 25 08:58:09] DEBUG[4280] devicestate.c: Notification of state change to be queued on device/channel Skinny/5502@5502-4
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '"Everett Lecates" <5502>'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '5502'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '5500'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'longdistance'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'Skinny/5502@5502-4'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'Skinny/5500@5500-5'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'Dial'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'Skinny/5500@5500|20|tr'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '2007-07-25 08:58:02'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '2007-07-25 08:58:03'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '2007-07-25 08:58:09'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '7'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '6'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'ANSWERED'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is 'DOCUMENTATION'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is ''
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is '1185368282.4'
[Jul 25 08:58:09] DEBUG[4280] pbx.c: Function result is ''
[Jul 25 08:58:09] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5500@5500
[Jul 25 08:58:09] DEBUG[4199] devicestate.c: Changing state for Skinny/5500@5500 - state 0 (Unknown)
[Jul 25 08:58:09] DEBUG[4199] devicestate.c: No provider found, checking channel drivers for Skinny - 5502@5502
[Jul 25 08:58:09] DEBUG[4199] devicestate.c: Changing state for Skinny/5502@5502 - state 0 (Unknown)
[Jul 25 08:58:09] DEBUG[4287] 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:58:09] DEBUG[4288] app_queue.c: Device 'Skinny/5502@5502' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.