[Nov 27 14:14:20] Asterisk 14.2.0 built by root @ televox-dev on a x86_64 running Linux on 2016-11-24 22:09:53 UTC
[Nov 27 14:14:37] VERBOSE[5838] dial.c: Called s@svtest1
[Nov 27 14:14:37] DEBUG[5839][C-00000020] pbx.c: Launching 'Answer'
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] pbx.c: Executing [s@svtest1:1] Answer("Local/s@svtest1-00000033;2", "") in new stack
[Nov 27 14:14:37] VERBOSE[5838] dial.c: Local/s@svtest1-00000033;1 answered
[Nov 27 14:14:37] VERBOSE[5838] pbx.c: Launching echo() on Local/s@svtest1-00000033;1
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 2 (In use)
[Nov 27 14:14:37] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 2 (In use)
[Nov 27 14:14:37] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] core_unreal.c: Blocked indication -1
[Nov 27 14:14:37] DEBUG[5839][C-00000020] channel.c: Didn't receive a media frame from Local/s@svtest1-00000033;2 within 500 ms of answering. Continuing anyway
[Nov 27 14:14:37] DEBUG[5839][C-00000020] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:37] DEBUG[5839][C-00000020] pbx.c: Launching 'Verbose'
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] pbx.c: Executing [s@svtest1:2] Verbose("Local/s@svtest1-00000033;2", "1,Answered channel:Local/s@svtest1-00000033;2") in new stack
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] app_verbose.c: Answered channel:Local/s@svtest1-00000033;2
[Nov 27 14:14:37] DEBUG[5839][C-00000020] pbx.c: Launching 'Dial'
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] pbx.c: Executing [s@svtest1:3] Dial("Local/s@svtest1-00000033;2", "Local/s@svtest2,,g") in new stack
[Nov 27 14:14:37] DEBUG[5839][C-00000020] channel_internal_api.c: Channel Call ID changing from [C-00000020] to [C-00000020]
[Nov 27 14:14:37] DEBUG[5839][C-00000020] rtp_engine.c: Can't find native functions for channel 'Local/s@svtest2-00000034;1'
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] app_dial.c: Called Local/s@svtest2
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx.c: Launching 'NoOp'
[Nov 27 14:14:37] VERBOSE[5840][C-00000020] pbx.c: Executing [s@svtest2:1] NoOp("Local/s@svtest2-00000034;2", "") in new stack
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx.c: Launching 'Set'
[Nov 27 14:14:37] VERBOSE[5840][C-00000020] pbx.c: Executing [s@svtest2:2] Set("Local/s@svtest2-00000034;2", "SHARED(sharedVar,Local/s@svtest2)="I have been set in svtest2"") in new stack
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx_variables.c: Function SHARED(sharedVar,Local/s@svtest2) result is '"I have been set in svtest2"'
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx.c: Launching 'Verbose'
[Nov 27 14:14:37] VERBOSE[5840][C-00000020] pbx.c: Executing [s@svtest2:3] Verbose("Local/s@svtest2-00000034;2", "1,***In channel:Local/s@svtest2-00000034;2 sharedVar: "I have been set in svtest2"") in new stack
[Nov 27 14:14:37] VERBOSE[5840][C-00000020] app_verbose.c: ***In channel:Local/s@svtest2-00000034;2 sharedVar: "I have been set in svtest2"
[Nov 27 14:14:37] DEBUG[5840][C-00000020] pbx.c: Launching 'Answer'
[Nov 27 14:14:37] VERBOSE[5840][C-00000020] pbx.c: Executing [s@svtest2:4] Answer("Local/s@svtest2-00000034;2", "") in new stack
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] app_dial.c: Local/s@svtest2-00000034;1 answered Local/s@svtest1-00000033;2
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge_native_rtp.c: Bridge '3018be8a-28b9-4743-837b-bc9911291cfa' can not use native RTP bridge as two channels are required
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: calling simple_bridge technology constructor
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: calling simple_bridge technology start
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 2 (In use)
[Nov 27 14:14:37] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:37] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 2 (In use)
[Nov 27 14:14:37] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:37] DEBUG[5840][C-00000020] core_unreal.c: Blocked indication -1
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bc9aded8(Local/s@svtest2-00000034;1) is joining
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: pushing 0x7f29bc9aded8(Local/s@svtest2-00000034;1)
[Nov 27 14:14:37] VERBOSE[5841][C-00000020] bridge_channel.c: Channel Local/s@svtest2-00000034;1 joined 'simple_bridge' basic-bridge <3018be8a-28b9-4743-837b-bc9911291cfa>
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge_native_rtp.c: Bridge '3018be8a-28b9-4743-837b-bc9911291cfa' can not use native RTP bridge as two channels are required
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa is already using the new technology.
[Nov 27 14:14:37] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bc9aded8(Local/s@svtest2-00000034;1) is joining simple_bridge technology
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bd05b4c8(Local/s@svtest1-00000033;2) is joining
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: pushing 0x7f29bd05b4c8(Local/s@svtest1-00000033;2)
[Nov 27 14:14:37] VERBOSE[5839][C-00000020] bridge_channel.c: Channel Local/s@svtest1-00000033;2 joined 'simple_bridge' basic-bridge <3018be8a-28b9-4743-837b-bc9911291cfa>
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge_native_rtp.c: Bridge '3018be8a-28b9-4743-837b-bc9911291cfa' can not use native RTP bridge as it was forbidden while getting details
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa is already using the new technology.
[Nov 27 14:14:37] DEBUG[5839][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bd05b4c8(Local/s@svtest1-00000033;2) is joining simple_bridge technology
[Nov 27 14:14:37] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest2-00000034;1 - start 1480256077.601636 answer 1480256077.604007 end 1480256077.604947 dispo ANSWERED
[Nov 27 14:14:38] DEBUG[5840][C-00000020] channel.c: Didn't receive a media frame from Local/s@svtest2-00000034;2 within 500 ms of answering. Continuing anyway
[Nov 27 14:14:38] DEBUG[5840][C-00000020] pbx.c: Launching 'Hangup'
[Nov 27 14:14:38] VERBOSE[5840][C-00000020] pbx.c: Executing [s@svtest2:5] Hangup("Local/s@svtest2-00000034;2", "") in new stack
[Nov 27 14:14:38] DEBUG[5840][C-00000020] channel.c: Soft-Hanging (0x20) up channel 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:38] DEBUG[5840][C-00000020] pbx.c: Spawn extension (svtest2,s,5) exited non-zero on 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:38] VERBOSE[5840][C-00000020] pbx.c: Spawn extension (svtest2, s, 5) exited non-zero on 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:38] DEBUG[5840][C-00000020] channel.c: Soft-Hanging (0x10) up channel 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:38] DEBUG[5840][C-00000020] channel.c: Hanging up channel 'Local/s@svtest2-00000034;2'
[Nov 27 14:14:38] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest2-00000034;2 - start 1480256077.601733 answer 1480256077.604288 end 1480256078.105935 dispo ANSWERED
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 1 (Not in use)
[Nov 27 14:14:38] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge_channel.c: Setting 0x7f29bc9aded8(Local/s@svtest2-00000034;1) state from:0 to:1
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: pulling 0x7f29bc9aded8(Local/s@svtest2-00000034;1)
[Nov 27 14:14:38] VERBOSE[5841][C-00000020] bridge_channel.c: Channel Local/s@svtest2-00000034;1 left 'simple_bridge' basic-bridge <3018be8a-28b9-4743-837b-bc9911291cfa>
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bc9aded8(Local/s@svtest2-00000034;1) is leaving simple_bridge technology
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: dissolving bridge with cause 16(Normal Clearing)
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge_channel.c: Setting 0x7f29bd05b4c8(Local/s@svtest1-00000033;2) state from:0 to:2
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: queueing action type:13 sub:1001
[Nov 27 14:14:38] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000033;2 - start 1480256077.098391 answer 1480256077.099851 end 1480256078.106977 dispo ANSWERED
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa is dissolved, not performing smart bridge operation.
[Nov 27 14:14:38] DEBUG[5839][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: pulling 0x7f29bd05b4c8(Local/s@svtest1-00000033;2)
[Nov 27 14:14:38] VERBOSE[5839][C-00000020] bridge_channel.c: Channel Local/s@svtest1-00000033;2 left 'simple_bridge' basic-bridge <3018be8a-28b9-4743-837b-bc9911291cfa>
[Nov 27 14:14:38] DEBUG[5839][C-00000020] bridge_channel.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: 0x7f29bd05b4c8(Local/s@svtest1-00000033;2) is leaving simple_bridge technology
[Nov 27 14:14:38] DEBUG[5839][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa is dissolved, not performing smart bridge operation.
[Nov 27 14:14:38] DEBUG[5839][C-00000020] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Nov 27 14:14:38] DEBUG[5839][C-00000020] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] DEBUG[5839][C-00000020] pbx_variables.c: Function SHARED(sharedVar,Local/s@svtest2) result is '(null)'
[Nov 27 14:14:38] DEBUG[5839][C-00000020] pbx.c: Launching 'Verbose'
[Nov 27 14:14:38] VERBOSE[5839][C-00000020] pbx.c: Executing [s@svtest1:4] Verbose("Local/s@svtest1-00000033;2", "1,***In channel:Local/s@svtest1-00000033;2 sharedVar:  ") in new stack
[Nov 27 14:14:38] VERBOSE[5839][C-00000020] app_verbose.c: ***In channel:Local/s@svtest1-00000033;2 sharedVar:  
[Nov 27 14:14:38] DEBUG[5839][C-00000020] pbx.c: Launching 'Hangup'
[Nov 27 14:14:38] VERBOSE[5839][C-00000020] pbx.c: Executing [s@svtest1:5] Hangup("Local/s@svtest1-00000033;2", "") in new stack
[Nov 27 14:14:38] DEBUG[5839][C-00000020] channel.c: Soft-Hanging (0x20) up channel 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] DEBUG[5839][C-00000020] pbx.c: Spawn extension (svtest1,s,5) exited non-zero on 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] VERBOSE[5839][C-00000020] pbx.c: Spawn extension (svtest1, s, 5) exited non-zero on 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] DEBUG[5839][C-00000020] channel.c: Soft-Hanging (0x10) up channel 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] DEBUG[5839][C-00000020] channel.c: Hanging up channel 'Local/s@svtest1-00000033;2'
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 1 (Not in use)
[Nov 27 14:14:38] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:38] DEBUG[5838] channel.c: Hanging up channel 'Local/s@svtest1-00000033;1'
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:38] DEBUG[5637] core_local.c: Checking if extension s@svtest1 exists (devicestate)
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 1 (Not in use)
[Nov 27 14:14:38] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:38] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000033;2 - start 1480256078.107498 answer 1480256078.107498 end 1480256078.108003 dispo ANSWERED
[Nov 27 14:14:38] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000033;1 - start 1480256077.098358 answer 1480256077.099424 end 1480256078.108141 dispo ANSWERED
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: actually destroying basic bridge, nobody wants it anymore
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: calling basic bridge destructor
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: calling simple_bridge technology stop
[Nov 27 14:14:38] DEBUG[5841][C-00000020] bridge.c: Bridge 3018be8a-28b9-4743-837b-bc9911291cfa: calling simple_bridge technology destructor
[Nov 27 14:14:38] DEBUG[5841][C-00000020] channel.c: Hanging up channel 'Local/s@svtest2-00000034;1'
[Nov 27 14:14:38] DEBUG[5642] cdr.c: CDR for Local/s@svtest2-00000034;1 is dialed and has no Party B; discarding
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:38] DEBUG[5637] core_local.c: Checking if extension s@svtest2 exists (devicestate)
[Nov 27 14:14:38] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 1 (Not in use)
[Nov 27 14:14:38] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:40] DEBUG[5690] res_pjsip_registrar_expire.c: Woke up at 1480256080  Interval: 30
[Nov 27 14:14:40] DEBUG[5690] res_pjsip_registrar_expire.c: Expiring 0 contacts
[Nov 27 14:14:45] VERBOSE[5842] dial.c: Called s@svtest1
[Nov 27 14:14:45] DEBUG[5843][C-00000021] pbx.c: Launching 'Answer'
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] pbx.c: Executing [s@svtest1:1] Answer("Local/s@svtest1-00000035;2", "") in new stack
[Nov 27 14:14:45] VERBOSE[5842] dial.c: Local/s@svtest1-00000035;1 answered
[Nov 27 14:14:45] VERBOSE[5842] pbx.c: Launching echo() on Local/s@svtest1-00000035;1
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 2 (In use)
[Nov 27 14:14:45] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 2 (In use)
[Nov 27 14:14:45] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] core_unreal.c: Blocked indication -1
[Nov 27 14:14:45] DEBUG[5843][C-00000021] channel.c: Didn't receive a media frame from Local/s@svtest1-00000035;2 within 500 ms of answering. Continuing anyway
[Nov 27 14:14:45] DEBUG[5843][C-00000021] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:45] DEBUG[5843][C-00000021] pbx.c: Launching 'Verbose'
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] pbx.c: Executing [s@svtest1:2] Verbose("Local/s@svtest1-00000035;2", "1,Answered channel:Local/s@svtest1-00000035;2") in new stack
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] app_verbose.c: Answered channel:Local/s@svtest1-00000035;2
[Nov 27 14:14:45] DEBUG[5843][C-00000021] pbx.c: Launching 'Dial'
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] pbx.c: Executing [s@svtest1:3] Dial("Local/s@svtest1-00000035;2", "Local/s@svtest2,,g") in new stack
[Nov 27 14:14:45] DEBUG[5843][C-00000021] channel_internal_api.c: Channel Call ID changing from [C-00000021] to [C-00000021]
[Nov 27 14:14:45] DEBUG[5843][C-00000021] rtp_engine.c: Can't find native functions for channel 'Local/s@svtest2-00000036;1'
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] app_dial.c: Called Local/s@svtest2
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx.c: Launching 'NoOp'
[Nov 27 14:14:45] VERBOSE[5844][C-00000021] pbx.c: Executing [s@svtest2:1] NoOp("Local/s@svtest2-00000036;2", "") in new stack
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx.c: Launching 'Set'
[Nov 27 14:14:45] VERBOSE[5844][C-00000021] pbx.c: Executing [s@svtest2:2] Set("Local/s@svtest2-00000036;2", "SHARED(sharedVar,Local/s@svtest2)="I have been set in svtest2"") in new stack
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx_variables.c: Function SHARED(sharedVar,Local/s@svtest2) result is '"I have been set in svtest2"'
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx.c: Launching 'Verbose'
[Nov 27 14:14:45] VERBOSE[5844][C-00000021] pbx.c: Executing [s@svtest2:3] Verbose("Local/s@svtest2-00000036;2", "1,***In channel:Local/s@svtest2-00000036;2 sharedVar: "I have been set in svtest2"") in new stack
[Nov 27 14:14:45] VERBOSE[5844][C-00000021] app_verbose.c: ***In channel:Local/s@svtest2-00000036;2 sharedVar: "I have been set in svtest2"
[Nov 27 14:14:45] DEBUG[5844][C-00000021] pbx.c: Launching 'Answer'
[Nov 27 14:14:45] VERBOSE[5844][C-00000021] pbx.c: Executing [s@svtest2:4] Answer("Local/s@svtest2-00000036;2", "") in new stack
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] app_dial.c: Local/s@svtest2-00000036;1 answered Local/s@svtest1-00000035;2
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge_native_rtp.c: Bridge 'edb82f8e-49de-44e3-a7b1-38d7e850feba' can not use native RTP bridge as two channels are required
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: calling simple_bridge technology constructor
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: calling simple_bridge technology start
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 2 (In use)
[Nov 27 14:14:45] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:45] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 2 (In use)
[Nov 27 14:14:45] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:45] DEBUG[5844][C-00000021] core_unreal.c: Blocked indication -1
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a001a0d8(Local/s@svtest2-00000036;1) is joining
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: pushing 0x7f29a001a0d8(Local/s@svtest2-00000036;1)
[Nov 27 14:14:45] VERBOSE[5845][C-00000021] bridge_channel.c: Channel Local/s@svtest2-00000036;1 joined 'simple_bridge' basic-bridge <edb82f8e-49de-44e3-a7b1-38d7e850feba>
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge_native_rtp.c: Bridge 'edb82f8e-49de-44e3-a7b1-38d7e850feba' can not use native RTP bridge as two channels are required
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba is already using the new technology.
[Nov 27 14:14:45] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a001a0d8(Local/s@svtest2-00000036;1) is joining simple_bridge technology
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a00137c8(Local/s@svtest1-00000035;2) is joining
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: pushing 0x7f29a00137c8(Local/s@svtest1-00000035;2)
[Nov 27 14:14:45] VERBOSE[5843][C-00000021] bridge_channel.c: Channel Local/s@svtest1-00000035;2 joined 'simple_bridge' basic-bridge <edb82f8e-49de-44e3-a7b1-38d7e850feba>
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge_native_rtp.c: Bridge 'edb82f8e-49de-44e3-a7b1-38d7e850feba' can not use native RTP bridge as it was forbidden while getting details
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Chose bridge technology simple_bridge
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba is already using the new technology.
[Nov 27 14:14:45] DEBUG[5843][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a00137c8(Local/s@svtest1-00000035;2) is joining simple_bridge technology
[Nov 27 14:14:45] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest2-00000036;1 - start 1480256085.543028 answer 1480256085.544857 end 1480256085.545825 dispo ANSWERED
[Nov 27 14:14:46] DEBUG[5844][C-00000021] channel.c: Didn't receive a media frame from Local/s@svtest2-00000036;2 within 500 ms of answering. Continuing anyway
[Nov 27 14:14:46] DEBUG[5844][C-00000021] pbx.c: Launching 'Hangup'
[Nov 27 14:14:46] VERBOSE[5844][C-00000021] pbx.c: Executing [s@svtest2:5] Hangup("Local/s@svtest2-00000036;2", "") in new stack
[Nov 27 14:14:46] DEBUG[5844][C-00000021] channel.c: Soft-Hanging (0x20) up channel 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:46] DEBUG[5844][C-00000021] pbx.c: Spawn extension (svtest2,s,5) exited non-zero on 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:46] VERBOSE[5844][C-00000021] pbx.c: Spawn extension (svtest2, s, 5) exited non-zero on 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:46] DEBUG[5844][C-00000021] channel.c: Soft-Hanging (0x10) up channel 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:46] DEBUG[5844][C-00000021] channel.c: Hanging up channel 'Local/s@svtest2-00000036;2'
[Nov 27 14:14:46] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest2-00000036;2 - start 1480256085.543163 answer 1480256085.545117 end 1480256086.046763 dispo ANSWERED
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 1 (Not in use)
[Nov 27 14:14:46] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge_channel.c: Setting 0x7f29a001a0d8(Local/s@svtest2-00000036;1) state from:0 to:1
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: pulling 0x7f29a001a0d8(Local/s@svtest2-00000036;1)
[Nov 27 14:14:46] VERBOSE[5845][C-00000021] bridge_channel.c: Channel Local/s@svtest2-00000036;1 left 'simple_bridge' basic-bridge <edb82f8e-49de-44e3-a7b1-38d7e850feba>
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a001a0d8(Local/s@svtest2-00000036;1) is leaving simple_bridge technology
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: dissolving bridge with cause 16(Normal Clearing)
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge_channel.c: Setting 0x7f29a00137c8(Local/s@svtest1-00000035;2) state from:0 to:2
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: queueing action type:13 sub:1001
[Nov 27 14:14:46] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000035;2 - start 1480256085.040628 answer 1480256085.041457 end 1480256086.047626 dispo ANSWERED
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba is dissolved, not performing smart bridge operation.
[Nov 27 14:14:46] DEBUG[5843][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: pulling 0x7f29a00137c8(Local/s@svtest1-00000035;2)
[Nov 27 14:14:46] VERBOSE[5843][C-00000021] bridge_channel.c: Channel Local/s@svtest1-00000035;2 left 'simple_bridge' basic-bridge <edb82f8e-49de-44e3-a7b1-38d7e850feba>
[Nov 27 14:14:46] DEBUG[5843][C-00000021] bridge_channel.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: 0x7f29a00137c8(Local/s@svtest1-00000035;2) is leaving simple_bridge technology
[Nov 27 14:14:46] DEBUG[5843][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba is dissolved, not performing smart bridge operation.
[Nov 27 14:14:46] DEBUG[5843][C-00000021] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Nov 27 14:14:46] DEBUG[5843][C-00000021] pbx_variables.c: Result of 'CHANNEL' is 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] DEBUG[5843][C-00000021] pbx_variables.c: Function SHARED(sharedVar,Local/s@svtest2) result is '"I have been set in svtest2"'
[Nov 27 14:14:46] DEBUG[5843][C-00000021] pbx.c: Launching 'Verbose'
[Nov 27 14:14:46] VERBOSE[5843][C-00000021] pbx.c: Executing [s@svtest1:4] Verbose("Local/s@svtest1-00000035;2", "1,***In channel:Local/s@svtest1-00000035;2 sharedVar: "I have been set in svtest2" ") in new stack
[Nov 27 14:14:46] VERBOSE[5843][C-00000021] app_verbose.c: ***In channel:Local/s@svtest1-00000035;2 sharedVar: "I have been set in svtest2" 
[Nov 27 14:14:46] DEBUG[5843][C-00000021] pbx.c: Launching 'Hangup'
[Nov 27 14:14:46] VERBOSE[5843][C-00000021] pbx.c: Executing [s@svtest1:5] Hangup("Local/s@svtest1-00000035;2", "") in new stack
[Nov 27 14:14:46] DEBUG[5843][C-00000021] channel.c: Soft-Hanging (0x20) up channel 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] DEBUG[5843][C-00000021] pbx.c: Spawn extension (svtest1,s,5) exited non-zero on 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] VERBOSE[5843][C-00000021] pbx.c: Spawn extension (svtest1, s, 5) exited non-zero on 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] DEBUG[5843][C-00000021] channel.c: Soft-Hanging (0x10) up channel 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] DEBUG[5843][C-00000021] channel.c: Hanging up channel 'Local/s@svtest1-00000035;2'
[Nov 27 14:14:46] DEBUG[5842] channel.c: Hanging up channel 'Local/s@svtest1-00000035;1'
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:46] DEBUG[5637] core_local.c: Checking if extension s@svtest1 exists (devicestate)
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 1 (Not in use)
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest1
[Nov 27 14:14:46] DEBUG[5637] core_local.c: Checking if extension s@svtest1 exists (devicestate)
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest1 - state 1 (Not in use)
[Nov 27 14:14:46] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:46] DEBUG[5704] app_queue.c: Device 'Local/s@svtest1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 27 14:14:46] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000035;2 - start 1480256086.048227 answer 1480256086.048227 end 1480256086.048240 dispo ANSWERED
[Nov 27 14:14:46] DEBUG[5642] cdr.c: Finalized CDR for Local/s@svtest1-00000035;1 - start 1480256085.040618 answer 1480256085.041235 end 1480256086.048378 dispo ANSWERED
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: actually destroying basic bridge, nobody wants it anymore
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: calling basic bridge destructor
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: calling simple_bridge technology stop
[Nov 27 14:14:46] DEBUG[5845][C-00000021] bridge.c: Bridge edb82f8e-49de-44e3-a7b1-38d7e850feba: calling simple_bridge technology destructor
[Nov 27 14:14:46] DEBUG[5845][C-00000021] channel.c: Hanging up channel 'Local/s@svtest2-00000036;1'
[Nov 27 14:14:46] DEBUG[5642] cdr.c: CDR for Local/s@svtest2-00000036;1 is dialed and has no Party B; discarding
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: No provider found, checking channel drivers for Local - s@svtest2
[Nov 27 14:14:46] DEBUG[5637] core_local.c: Checking if extension s@svtest2 exists (devicestate)
[Nov 27 14:14:46] DEBUG[5637] devicestate.c: Changing state for Local/s@svtest2 - state 1 (Not in use)
[Nov 27 14:14:46] DEBUG[5704] app_queue.c: Device 'Local/s@svtest2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.