==== start log session ==== 0.000015 : Test_out_close_cb() 0.000114 : Starting job: python test_channel_pipe.py quit now 0.000148 on 26: Created channel 0.012371 ERR on 25: channel_select_check(): Cannot read from channel 0.012463 on 25: Closing channel 0.012479 : looking for messages on channels 0.038454 RECV on 26: 'quit ' 0.038475 on 26: Invoking channel callback OutHandler 0.049656 ERR on 26: channel_select_check(): Cannot read from channel 0.049742 PUT on 26: 'DETACH ' 0.049750 on 26: Closing channel 0.049805 on 26: Invoking channel callback OutHandler 0.049953 on 26: Invoking close callback CloseHandler 0.050014 : looking for messages on channels 0.050232 on 26: Stopping job with '' 0.050323 on 26: detaching channel from job 0.050346 on 26: Closing channel 0.050365 on 26: Clearing channel 0.050385 on 26: Freeing channel 0.050927 on 27: Created channel 0.069720 ERR on 27: in gethostbyname() in channel_open() 0.069782 on 27: Closing channel 0.069793 on 27: Clearing channel 0.069803 on 27: Freeing channel 0.070192 : Test_pipe_both_to_buffer() 0.070228 : Starting job: python test_channel_pipe.py 0.070253 on 28: Created channel 0.071297 on 28: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.071342 on 28: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.071431 SEND on 28: 'echo line one ' 0.071465 SEND on 28: 'echoerr line two ' 0.071485 SEND on 28: 'double this ' 0.071504 SEND on 28: 'doubleerr that ' 0.071523 SEND on 28: 'quit ' 0.083943 : looking for messages on channels 0.117209 RECV on 28: 'line one line two this AND this that AND that Goodbye! ' 0.117244 on 28: appending line 2 to buffer 0.117364 on 28: appending line 3 to buffer 0.117405 on 28: appending line 4 to buffer 0.117444 on 28: appending line 5 to buffer 0.117482 on 28: appending line 6 to buffer 0.117520 on 28: appending line 7 to buffer 0.117560 on 28: appending line 8 to buffer 0.118458 on 28: Stopping job with '' 0.118492 on 28: detaching channel from job 0.118504 on 28: Closing channel 0.118528 on 28: Clearing channel 0.118538 on 28: Freeing channel 0.118791 : Test_pipe_err_to_buffer() 0.118856 : Starting job: python test_channel_pipe.py 0.118892 on 29: Created channel 0.119958 on 29: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.120091 SEND on 29: 'echoerr line one ' 0.120127 SEND on 29: 'echoerr line two ' 0.120147 SEND on 29: 'doubleerr this ' 0.120166 SEND on 29: 'quit ' 0.131284 : looking for messages on channels 0.167619 RECV on 29: 'Goodbye! ' 0.167646 RECV on 29: 'line one line two this AND this ' 0.167654 on 29: Dropping message 'Goodbye! ' 0.167698 on 29: appending line 2 to buffer 0.167741 on 29: appending line 3 to buffer 0.167756 on 29: appending line 4 to buffer 0.167769 on 29: appending line 5 to buffer 0.168212 on 29: Stopping job with '' 0.168237 on 29: detaching channel from job 0.168245 on 29: Closing channel 0.168267 on 29: Clearing channel 0.168274 on 29: Freeing channel 0.168468 : Test_pipe_err_to_buffer() 0.170435 : Starting job: python test_channel_pipe.py 0.170465 on 30: Created channel 0.170941 on 30: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.171079 SEND on 30: 'echoerr line one ' 0.171105 SEND on 30: 'echoerr line two ' 0.171121 SEND on 30: 'doubleerr this ' 0.171136 SEND on 30: 'quit ' 0.182514 : looking for messages on channels 0.208709 RECV on 30: 'Goodbye! ' 0.208731 RECV on 30: 'line one line two this AND this ' 0.208737 on 30: Dropping message 'Goodbye! ' 0.208767 on 30: appending line 2 to buffer 0.208827 ERR on 30: channel_select_check(): Cannot read from channel 0.208837 PUT on 30: 'DETACH ' 0.208839 on 30: Closing channel 0.208867 on 30: Dropping message 'DETACH ' 0.208967 on 30: appending line 3 to buffer 0.208992 on 30: appending line 4 to buffer 0.209006 on 30: appending line 5 to buffer 0.209791 on 30: Stopping job with '' 0.209849 on 30: detaching channel from job 0.209859 on 30: Closing channel 0.209865 on 30: Clearing channel 0.209872 on 30: Freeing channel 0.210096 : Test_pipe_from_buffer() 0.211619 : Starting job: python test_channel_pipe.py 0.211663 on 31: Created channel 0.212423 on 31: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.212511 SEND on 31: 'echo one ' 0.212532 on 31: FAKED Input not ready for writing 0.212539 on 31: written line 1 to channel 0.212546 on 31: Still 2 more lines to write 0.212659 on 31: Blocking NL read, timeout: 2000 msec 0.212669 on 31: Waiting for up to 2000 msec 0.212684 SEND on 31: 'echo two ' 0.212694 on 31: FAKED Input not ready for writing 0.212701 on 31: written line 2 to channel 0.212708 on 31: Still 1 more lines to write 0.212719 SEND on 31: 'echo three ' 0.212728 on 31: written line 3 to channel 0.212734 on 31: Finished writing all lines to channel 0.248593 RECV on 31: 'one two three ' 0.248606 on 31: Returning 3 bytes 0.248677 on 31: Blocking NL read, timeout: 2000 msec 0.248686 on 31: Returning 3 bytes 0.248701 on 31: Blocking NL read, timeout: 2000 msec 0.248710 on 31: Returning 5 bytes 0.249368 on 31: Stopping job with '' 0.249410 on 31: detaching channel from job 0.249420 on 31: Closing channel 0.249439 on 31: Clearing channel 0.249446 on 31: Freeing channel 0.249715 : Test_pipe_from_buffer() 0.251062 : Starting job: python test_channel_pipe.py 0.251095 on 32: Created channel 0.252937 on 32: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.253101 SEND on 32: 'echo one ' 0.253128 on 32: FAKED Input not ready for writing 0.253136 on 32: written line 1 to channel 0.253143 on 32: Still 2 more lines to write 0.253333 on 32: Blocking NL read, timeout: 2000 msec 0.253344 on 32: Waiting for up to 2000 msec 0.253362 SEND on 32: 'echo two ' 0.253373 on 32: FAKED Input not ready for writing 0.253380 on 32: written line 2 to channel 0.253386 on 32: Still 1 more lines to write 0.253398 SEND on 32: 'echo three ' 0.253407 on 32: written line 3 to channel 0.253413 on 32: Finished writing all lines to channel 0.288563 RECV on 32: 'one two three ' 0.288576 on 32: Returning 3 bytes 0.288643 on 32: Blocking NL read, timeout: 2000 msec 0.288652 on 32: Returning 3 bytes 0.288667 on 32: Blocking NL read, timeout: 2000 msec 0.288676 on 32: Returning 5 bytes 0.289392 on 32: Stopping job with '' 0.289434 on 32: detaching channel from job 0.289443 on 32: Closing channel 0.289460 on 32: Clearing channel 0.289468 on 32: Freeing channel 0.289694 : Test_pipe_io_one_buffer() 0.291100 : Starting job: python test_channel_pipe.py 0.291143 on 33: Created channel 0.293924 on 33: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.293973 on 33: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.294168 SEND on 33: 'Reading from channel output... ' 0.294182 on 33: written line 1 to channel 0.294259 on 33: FAKED Input not ready for writing 0.294269 on 33: Still 1 more lines to write 0.294305 SEND on 33: 'echo hello ' 0.294315 on 33: written line 2 to channel 0.304710 : looking for messages on channels 0.330298 RECV on 33: 'hello ' 0.330317 on 33: appending line 3 to buffer 0.330516 on 33: FAKED Input not ready for writing 0.330526 on 33: Still 1 more lines to write 0.330560 SEND on 33: 'double this ' 0.330574 on 33: written line 4 to channel 0.340874 RECV on 33: 'this AND this ' 0.340884 : looking for messages on channels 0.340911 on 33: appending line 5 to buffer 0.340990 on 33: appending line 6 to buffer 0.341877 on 33: Stopping job with '' 0.341915 on 33: detaching channel from job 0.341923 on 33: Closing channel 0.341940 on 33: Clearing channel 0.341947 on 33: Freeing channel 0.342128 : Test_pipe_io_two_buffers() 0.343898 : Starting job: python test_channel_pipe.py 0.343927 on 34: Created channel 0.346195 on 34: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.346239 on 34: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.346483 SEND on 34: 'echo hello ' 0.346496 on 34: written line 1 to channel 0.360851 : looking for messages on channels 0.395874 RECV on 34: 'hello ' 0.395906 on 34: appending line 2 to buffer 0.396521 on 34: FAKED Input not ready for writing 0.396551 on 34: Still 1 more lines to write 0.396642 SEND on 34: 'double this ' 0.396678 on 34: written line 2 to channel 0.396794 RECV on 34: 'this AND this ' 0.408553 : looking for messages on channels 0.408616 on 34: appending line 3 to buffer 0.408678 on 34: appending line 4 to buffer 0.410607 on 34: Stopping job with '' 0.410649 on 34: detaching channel from job 0.410661 on 34: Closing channel 0.410684 on 34: Clearing channel 0.410694 on 34: Freeing channel 0.410948 : Test_pipe_null() 0.410990 : Starting job: python test_channel_pipe.py something 0.411017 on 35: Created channel 0.411643 on 35: Blocking NL read, timeout: 2000 msec 0.411694 on 35: Waiting for up to 2000 msec 0.446005 RECV on 35: 'something ' 0.446016 on 35: Returning 9 bytes 0.446068 on 35: Stopping job with '' 0.446116 : Starting job: python test_channel_pipe.py err-out 0.446136 on 36: Created channel 0.446679 on 35: detaching channel from job 0.446726 on 35: Closing channel 0.446735 on 35: Clearing channel 0.446742 on 35: Freeing channel 0.446797 on 36: Blocking NL read, timeout: 2000 msec 0.446813 on 36: Waiting for up to 2000 msec 0.479676 RECV on 36: 'err-out ' 0.479687 on 36: Returning 7 bytes 0.479742 on 36: Stopping job with '' 0.479784 : Starting job: python test_channel_pipe.py something 0.479804 on 37: Created channel 0.480342 on 36: detaching channel from job 0.480390 on 36: Closing channel 0.480400 on 36: Clearing channel 0.480407 on 36: Freeing channel 0.480473 on 37: Blocking NL read, timeout: 2000 msec 0.480488 on 37: Waiting for up to 2000 msec 0.514520 RECV on 37: 'something ' 0.514531 on 37: Returning 9 bytes 0.514585 on 37: Stopping job with '' 0.514633 : Starting job: python test_channel_pipe.py something 0.514649 on 38: Created channel 0.515173 on 37: detaching channel from job 0.515216 on 37: Closing channel 0.515226 on 37: Clearing channel 0.515233 on 37: Freeing channel 0.515288 on 38: Stopping job with '' 0.515324 : Starting job: python test_channel_pipe.py something 0.516299 on 38: detaching channel from job 0.516351 on 38: Closing channel 0.516362 on 38: Clearing channel 0.516369 on 38: Freeing channel 0.516492 : Stopping job with '' 0.516787 : Test_pipe_to_buffer_json() 0.516812 : Starting job: python test_channel_pipe.py 0.516842 on 39: Created channel 0.520194 on 39: writing out to buffer '(null)' 0.520344 SEND on 39: 'echo [0, "hello"] ' 0.520374 SEND on 39: 'echo [-2, 12.34] ' 0.533099 : looking for messages on channels 0.647870 RECV on 39: '[0, "hello"] [-2, 12.34] ' 0.647886 on 39: Getting JSON message 0 0.647915 on 39: appending line 2 to buffer 0.647992 on 39: Getting JSON message -2 0.648034 on 39: appending line 3 to buffer 0.648343 on 39: Stopping job with '' 0.648370 on 39: detaching channel from job 0.648379 on 39: Closing channel 0.648397 on 39: Clearing channel 0.648404 on 39: Freeing channel 0.648587 : Test_pipe_to_buffer() 0.648632 : Starting job: python test_channel_pipe.py 0.648653 on 40: Created channel 0.650512 on 40: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.650626 SEND on 40: 'echo line one ' 0.650653 SEND on 40: 'echo line two ' 0.650668 SEND on 40: 'double this ' 0.650683 SEND on 40: 'quit ' 0.661641 : looking for messages on channels 0.708553 RECV on 40: 'line one line two this AND this Goodbye! ' 0.708568 ERR on 40: channel_select_check(): Cannot read from channel 0.708589 PUT on 40: 'DETACH ' 0.708591 on 40: Closing channel 0.708630 : looking for messages on channels 0.708640 on 40: appending line 2 to buffer 0.708669 on 40: appending line 3 to buffer 0.708682 on 40: appending line 4 to buffer 0.708694 on 40: appending line 5 to buffer 0.708706 on 40: appending line 6 to buffer 0.708719 on 40: Dropping message 'DETACH ' 0.709088 on 40: Stopping job with '' 0.709107 on 40: detaching channel from job 0.709115 on 40: Closing channel 0.709122 on 40: Clearing channel 0.709128 on 40: Freeing channel 0.709302 : Test_pipe_to_buffer() 0.710798 : Starting job: python test_channel_pipe.py 0.710829 on 41: Created channel 0.712299 on 41: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.712426 SEND on 41: 'echo line one ' 0.712452 SEND on 41: 'echo line two ' 0.712468 SEND on 41: 'double this ' 0.712482 SEND on 41: 'quit ' 0.724264 : looking for messages on channels 0.758314 RECV on 41: 'line one line two this AND this Goodbye! ' 0.758328 ERR on 41: channel_select_check(): Cannot read from channel 0.758350 PUT on 41: 'DETACH ' 0.758352 on 41: Closing channel 0.758370 : looking for messages on channels 0.758380 on 41: appending line 2 to buffer 0.758482 on 41: appending line 3 to buffer 0.758496 on 41: appending line 4 to buffer 0.758508 on 41: appending line 5 to buffer 0.758522 on 41: appending line 6 to buffer 0.758535 on 41: Dropping message 'DETACH ' 0.759133 on 41: Stopping job with '' 0.759157 on 41: detaching channel from job 0.759165 on 41: Closing channel 0.759172 on 41: Clearing channel 0.759178 on 41: Freeing channel 0.759361 : Test_pipe_to_nameless_buffer() 0.759383 : Starting job: python test_channel_pipe.py 0.759405 on 42: Created channel 0.761162 on 42: writing out to buffer '(null)' 0.761258 SEND on 42: 'echo line one ' 0.761285 SEND on 42: 'echo line two ' 0.772822 : looking for messages on channels 0.797392 RECV on 42: 'line one line two ' 0.797404 on 42: appending line 2 to buffer 0.797453 on 42: appending line 3 to buffer 0.797804 on 42: Stopping job with '' 0.797832 on 42: detaching channel from job 0.797840 on 42: Closing channel 0.797857 on 42: Clearing channel 0.797863 on 42: Freeing channel 0.798029 : Test_raw_one_time_callback() 0.798193 : Starting job: python test_channel.py 0.798216 on 43: Created channel 0.812925 : looking for messages on channels 0.886722 on 44: Created channel 0.887305 on 44: Connecting to localhost port 56973 0.887400 on 44: Waiting for connection (waiting 1 msec)... 0.887489 on 44: Connection made 0.887548 SEND on 44: '[1, "hello!"]' 0.897847 : looking for messages on channels 0.908176 RECV on 44: '[1, "got it"]' 0.908182 on 44: Invoking one-time callback s:HandleRaw1 0.908273 SEND on 44: '[2, "echo something"]' 0.908311 SEND on 44: '[3, "wait a bit"]' 0.918573 RECV on 44: '[2, "something"]' 0.918578 : looking for messages on channels 0.918592 on 44: Invoking one-time callback s:HandleRaw2 0.929548 : looking for messages on channels 1.118654 RECV on 44: '[3, "waited"]' 1.118664 on 44: Invoking one-time callback s:HandleRaw3 1.118757 on 44: Closing channel 1.118791 on 44: Clearing channel 1.118802 on 44: Freeing channel 1.118846 on 43: Stopping job with '' 1.118870 on 43: detaching channel from job 1.118877 on 43: Closing channel 1.118894 on 43: Clearing channel 1.118961 on 43: Freeing channel 1.119225 : Test_raw_pipe() 1.119248 : Starting job: python test_channel_pipe.py 1.119271 on 45: Created channel 1.120915 SEND on 45: 'echo something ' 1.120991 on 45: Blocking RAW read, timeout: 2000 msec 1.121008 on 45: Waiting for up to 2000 msec 1.157511 RECV on 45: 'something ' 1.157522 on 45: Returning 10 bytes 1.157652 SEND on 45: 'double this ' 1.157671 on 45: Blocking RAW read, timeout: 2000 msec 1.157679 on 45: Waiting for up to 2000 msec 1.157722 RECV on 45: 'this AND this ' 1.157726 on 45: Returning 14 bytes 1.157758 SEND on 45: 'quit ' 1.157767 on 45: Blocking RAW read, timeout: 100 msec 1.157792 on 45: Waiting for up to 100 msec 1.157830 RECV on 45: 'Goodbye! ' 1.157833 on 45: Returning 9 bytes 1.157865 on 45: Stopping job with '' 1.168925 ERR on 45: channel_select_check(): Cannot read from channel 1.168963 PUT on 45: 'DETACH ' 1.168966 on 45: Closing channel 1.168986 : looking for messages on channels 1.168995 on 45: Dropping message 'DETACH ' 1.169059 on 45: Job ended 1.169312 : Test_read_in_close_cb() 1.169349 : Starting job: python test_channel_pipe.py quit now 1.169371 on 46: Created channel 1.181585 : looking for messages on channels 1.215733 RECV on 46: 'quit ' 1.215751 ERR on 46: channel_select_check(): Cannot read from channel 1.215778 PUT on 46: 'DETACH ' 1.215780 on 46: Closing channel 1.215800 on 46: Invoking close callback CloseHandler 1.215862 on 46: Blocking NL read, timeout: 2000 msec 1.215873 on 46: Returning 4 bytes 1.215892 on 46: Dropping message 'DETACH ' 1.215901 : looking for messages on channels 1.215967 on 46: Stopping job with '' 1.215994 on 46: detaching channel from job 1.216002 on 46: Closing channel 1.216008 on 46: Clearing channel 1.216014 on 46: Freeing channel 1.216207 : Test_reuse_channel() 1.216227 : Starting job: python test_channel_pipe.py 1.216250 on 47: Created channel 1.217821 SEND on 47: 'echo something ' 1.217873 on 47: Blocking NL read, timeout: 2000 msec 1.217888 on 47: Waiting for up to 2000 msec 1.250876 RECV on 47: 'something ' 1.250889 on 47: Returning 9 bytes 1.250947 on 47: Stopping job with '' 1.251041 : Starting job: python test_channel_pipe.py 1.252568 on 47: detaching channel from job 1.252689 SEND on 47: 'echo again ' 1.252718 on 47: Blocking NL read, timeout: 2000 msec 1.252734 on 47: Waiting for up to 2000 msec 1.285348 RECV on 47: 'again ' 1.285360 on 47: Returning 5 bytes 1.285412 on 47: Stopping job with '' 1.285440 on 47: detaching channel from job 1.285448 on 47: Closing channel 1.285465 on 47: Clearing channel 1.285472 on 47: Freeing channel 1.285727 : Test_server_crash() 1.285790 : Starting job: python test_channel.py 1.285814 on 48: Created channel 1.287308 on 45: Freeing job 1.287363 on 45: Closing channel 1.287371 on 45: Clearing channel 1.287378 on 45: Freeing channel 1.299714 : looking for messages on channels 1.368911 on 49: Created channel 1.369397 on 49: Connecting to localhost port 56975 1.369478 on 49: Waiting for connection (waiting 1 msec)... 1.369576 on 49: Connection made 1.369628 SEND on 49: '[1,"!crash!"]' 1.369655 on 49: Reading JSON 1.369664 : looking for messages on channels 1.369671 on 49: Waiting for up to 2000 msec 1.380978 ERR on 49: channel_read_json_block(): Cannot read from channel 1.380999 on 49: Closing channel 1.381023 : looking for messages on channels 1.391430 RECV on 48: 'Traceback (most recent call last): File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 599, in process_request_thread self.finish_request(request, client_address) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 334, in finish_request self.RequestHandlerClass(request, client_address, self) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 655, in __init__ self.handle() File "test_channel.py", line 211, in handle 42 / 0 ZeroDivisionError: integer division or modulo by zero ' 1.391436 on 48: Dropping message 'Traceback (most recent call last): File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 599, in process_request_thread self.finish_request(request, client_address) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 334, in finish_request self.RequestHandlerClass(request, client_address, self) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/SocketServer.py", line 655, in __init__ self.handle() File "test_channel.py", line 211, in handle 42 / 0 ZeroDivisionError: integer division or modulo by zero ' 1.391471 on 49: Closing channel 1.391478 on 49: Clearing channel 1.391486 on 49: Freeing channel 1.391540 on 48: Stopping job with '' 1.391567 on 48: detaching channel from job 1.391574 on 48: Closing channel 1.391591 on 48: Clearing channel 1.391597 on 48: Freeing channel 1.391893 : Test_two_channels() 1.391963 : Starting job: python test_channel.py 1.391985 on 50: Created channel 1.405592 : looking for messages on channels 1.478314 on 51: Created channel 1.478782 on 51: Connecting to localhost port 56977 1.478868 on 51: Waiting for connection (waiting 1 msec)... 1.478964 on 51: Connection made 1.479015 SEND on 51: '[1,"hello!"]' 1.479046 on 51: Reading JSON 1.479055 : looking for messages on channels 1.479063 on 51: Waiting for up to 2000 msec 1.489624 RECV on 51: '[1, "got it"]' 1.489635 on 51: Getting JSON message 1 1.489672 on 52: Created channel 1.490097 on 52: Connecting to localhost port 56977 1.490157 on 52: Waiting for connection (waiting 1 msec)... 1.490242 on 52: Connection made 1.490293 SEND on 52: '[1,"hello!"]' 1.490319 on 52: Reading JSON 1.490327 : looking for messages on channels 1.490335 on 52: Waiting for up to 2000 msec 1.500735 RECV on 52: '[1, "got it"]' 1.500743 on 52: Getting JSON message 1 1.500774 SEND on 51: '[2,"hello!"]' 1.500798 on 51: Reading JSON 1.500806 : looking for messages on channels 1.500815 on 51: Waiting for up to 2000 msec 1.500944 RECV on 51: '[2, "got it"]' 1.500951 on 51: Getting JSON message 2 1.500972 on 51: Closing channel 1.501000 on 51: Clearing channel 1.501024 SEND on 52: '[2,"hello!"]' 1.501078 on 52: Reading JSON 1.501088 : looking for messages on channels 1.501095 on 52: Waiting for up to 2000 msec 1.501278 RECV on 52: '[2, "got it"]' 1.501284 on 52: Getting JSON message 2 1.501305 on 52: Closing channel 1.501330 on 52: Clearing channel 1.501344 on 52: Closing channel 1.501351 on 52: Clearing channel 1.501358 on 52: Freeing channel 1.501365 on 51: Closing channel 1.501371 on 51: Clearing channel 1.501377 on 51: Freeing channel 1.501471 on 50: Stopping job with '' 1.501498 on 50: detaching channel from job 1.501506 on 50: Closing channel 1.501523 on 50: Clearing channel 1.501530 on 50: Freeing channel 1.501763 : Test_unlet_handle() 1.501843 : Starting job: python test_channel.py 1.501867 on 53: Created channel 1.515888 : looking for messages on channels 1.578603 on 54: Created channel 1.579132 on 54: Connecting to localhost port 56980 1.579214 on 54: Waiting for connection (waiting 1 msec)... 1.579353 on 54: Connection made 1.579376 on 9: Closing channel 1.579384 on 9: Clearing channel 1.579391 on 9: Freeing channel 1.579431 SEND on 54: '[1,"test"]' 1.579620 on 53: Stopping job with '' 1.579647 on 53: detaching channel from job 1.579654 on 53: Closing channel 1.579672 on 53: Clearing channel 1.579679 on 53: Freeing channel 1.579910 : Starting job: ls 1.579934 on 55: Created channel 1.593830 RECV on 55: 'Make_all.mak Make_amiga.mak Make_dos.mak Make_ming.mak Make_vms.mms Makefile README.txt amiga.vim bench_re_freeze.in bench_re_freeze.vim channellog dos.vim dotest.in lua.vim main.aap mbyte.vim mzscheme.vim python2 python3 python_after python_before pythonx runtest.vim samples sautest small.vim test1.in test1.ok test1.out test101.in test101.ok test101.out test102.in test102.ok test102.out test103.in test103.ok test103.out test104.in test104.ok test104.out test107.in test107.ok test107.out test108.in test108.ok test108.out test11.in test11.ok test11.out test12.in test12.ok test12.out test13.in test13.ok test13.out test14.in test14.ok test14.out test15.in test15.ok test15.out test16.in test16.ok test16.out test17.in test17.ok test17.out test17a.in test18.in test18.ok test18.out test19.in test19.ok test19.out test2.in test2.ok test2.out test20.in test20.ok test20.out test21.in test21.ok test21.out test22.in test22.ok test22.out test23.in test23.ok test23.out test24.in test24.ok test24.out test25.in test25.ok test25.out test26.in test26.ok test26.out test28.in test28.ok test28.out test29.in test29.ok test29.out test3.in test3.ok test3.out test30.in test30.ok test30.out test31.in test31.ok test31.out test32.in test32.ok test32.out test33.in test33.ok test33.out test34.in test34.ok test34.out test35.in test35.ok test35.out test36.in test36.ok test36.out test37.in test37.ok test37.out test38.in test38.ok test38.out test39.in test39.ok test39.out test4.in test4.ok test4.out test40.in test40.ok test40.out test41.in test41.ok test41.out test42.in test42.ok test42.out test43.in test43.ok test43.out test44.in test44.ok test44.out test45.in test45.ok test45.out test46.in test46.ok test46.out test47.in test47.ok test47.out test48.in test48.ok test48.out test49.in test49.ok test49.out test49.vim test5.in test5.ok test5.out test50.in test50.ok test51.in test51.ok test51.out test52.in test52.ok test52.out test53.in test53.ok test53.out test54.in test54.ok test54.out test55.in test55.ok test55.out test56.in test56.ok test56.out test57.in test57.ok test57.out test58.in test58.ok test58.out test59.in test59.ok test59.out test6.in test6.ok test6.out test60.in test60.ok test60.out test60.vim test61.in test61.ok test61.out test62.in test62.ok test62.out test63.in test63.ok test63.out test64.in test64.ok test64.out test65.in test65.ok test65.out test66.in test66.ok test66.out test67.in test67.ok test67.out test68.in test68.ok test68.out test69.in test69.ok test69.out test7.in test7.ok test7.out test70.in test70.ok test70.out test71.in test71.ok test71.out test71a.in test72.in test72.ok test72.out test73.in test73.ok test73.out test75.in test75.ok test75.out test76.in test76.ok test76.out test77.in test77.ok test77.out test77a.com test77a.in test77a.ok test78.in test78.ok test78.out test79.in test79.ok test79.out test8.in test8.ok test8.out test80.in test80.ok test80.out test81.in test81.ok test81.out test82.in test82.ok test82.out test83-tags2 test83-tags3 test83.in test83.ok test83.out test84.in test84.ok test84.out test85.in test85.ok test85.out test86.in test86.ok test86.out test87.in test87.ok test87.out test88.in test88.ok test88.out test89.in test89.ok test89.out test9.in test9.ok test9.out test90.in test90.ok test90.out test91.in test91.ok test91.out test92.in test92.ok test92.out test93.in test93.ok test93.out test94.in test94.ok test94.out test95.in test95.ok test95.out test97.in test97.ok test97.out test98.in test98.ok test98.out test99.in test99.ok test99.out test_alot.res test_alot.vim test_alot_latin.res test_alot_latin.vim test_alot_utf8.res test_alot_utf8.vim test_arglist.res test_arglist.vim test_assert.res test_assert.vim test_assign.vim test_autocmd.vim test_autocmd_option.in test_autocmd_option.ok test_autocmd_option.out test_autoformat_join.in test_autoformat_join.ok test_autoformat_join.out test_backspace_opt.res test_backspace_opt.vim test_breakindent.in test_breakindent.ok test_breakindent.out test_cdo.res test_cdo.vim test_changelist.in test_changelist.ok test_changelist.out test_channel.py test_channel.res test_channel.v' 1.593909 RECV on 55: 'im test_channel_pipe.py test_charsearch.in test_charsearch.ok test_charsearch.out test_close_count.in test_close_count.ok test_close_count.out test_command_count.in test_command_count.ok test_command_count.out test_comparators.in test_comparators.ok test_comparators.out test_cursor_func.vim test_delete.vim test_erasebackword.in test_erasebackword.ok test_erasebackword.out test_eval.in test_eval.ok test_eval.out test_eval_func.vim test_ex_undo.vim test_expand.vim test_expand_dllpath.vim test_expr.vim test_expr_utf8.vim test_feedkeys.vim test_file_perm.vim test_fixeol.in test_fixeol.ok test_fixeol.out test_fnamemodify.vim test_getcwd.in test_getcwd.ok test_getcwd.out test_glob2regpat.vim test_goto.vim test_hardcopy.res test_hardcopy.vim test_help_tagjump.vim test_history.res test_history.vim test_increment.res test_increment.vim test_insertcount.in test_insertcount.ok test_insertcount.out test_join.vim test_json.res test_json.vim test_langmap.res test_langmap.vim test_lispwords.vim test_listchars.in test_listchars.ok test_listchars.out test_listlbr.in test_listlbr.ok test_listlbr.out test_listlbr_utf8.in test_listlbr_utf8.ok test_listlbr_utf8.out test_mapping.in test_mapping.ok test_mapping.out test_marks.in test_marks.ok test_marks.out test_matchadd_conceal.res test_matchadd_conceal.vim test_matchadd_conceal_utf8.vim test_matchstrpos.vim test_menu.vim test_messages.vim test_nested_function.in test_nested_function.ok test_nested_function.out test_options.in test_options.ok test_options.out test_packadd.res test_packadd.vim test_partial.vim test_perl.res test_perl.vim test_quickfix.res test_quickfix.vim test_regexp_latin.vim test_regexp_utf8.vim test_reltime.vim test_ruby.in test_ruby.ok test_ruby.out test_search_mbyte.in test_search_mbyte.ok test_search_mbyte.out test_searchpos.vim test_set.vim test_signs.in test_signs.ok test_signs.out test_sort.vim test_statusline.vim test_syn_attr.vim test_syntax.res test_syntax.vim test_tabline.vim test_tagcase.in test_tagcase.ok test_tagcase.out test_tagjump.vim test_textobjects.in test_textobjects.ok test_textobjects.out test_timers.vim test_undolevels.vim test_unlet.vim test_utf8.in test_utf8.ok test_utf8.out test_viminfo.res test_viminfo.vim test_viml.res test_viml.vim test_visual.res test_visual.vim test_window_id.res test_window_id.vim test_wordcount.in test_wordcount.ok test_wordcount.out test_writefile.in test_writefile.ok test_writefile.out tiny.vim unix.vim viminfo vms.vim ' 1.593916 ERR on 55: channel_select_check(): Cannot read from channel 1.593936 PUT on 55: 'DETACH ' 1.593938 on 55: Closing channel 1.593963 ERR on 54: channel_select_check(): Cannot read from channel 1.593971 on 54: Closing channel 1.594032 : looking for messages on channels 1.594042 on 55: Dropping message 'Make_all.mak Make_amiga.mak Make_dos.mak Make_ming.mak Make_vms.mms Makefile README.txt amiga.vim bench_re_freeze.in bench_re_freeze.vim channellog dos.vim dotest.in lua.vim main.aap mbyte.vim mzscheme.vim python2 python3 python_after python_before pythonx runtest.vim samples sautest small.vim test1.in test1.ok test1.out test101.in test101.ok test101.out test102.in test102.ok test102.out test103.in test103.ok test103.out test104.in test104.ok test104.out test107.in test107.ok test107.out test108.in test108.ok test108.out test11.in test11.ok test11.out test12.in test12.ok test12.out test13.in test13.ok test13.out test14.in test14.ok test14.out test15.in test15.ok test15.out test16.in test16.ok test16.out test17.in test17.ok test17.out test17a.in test18.in test18.ok test18.out test19.in test19.ok test19.out test2.in test2.ok test2.out test20.in test20.ok test20.out test21.in test21.ok test21.out test22.in test22.ok test22.out test23.in test23.ok test23.out test24.in test24.ok test24.out test25.in test25.ok test25.out test26.in test26.ok test26.out test28.in test28.ok test28.out test29.in test29.ok test29.out test3.in test3.ok test3.out test30.in test30.ok test30.out test31.in test31.ok test31.out test32.in test32.ok test32.out test33.in test33.ok test33.out test34.in test34.ok test34.out test35.in test35.ok test35.out test36.in test36.ok test36.out test37.in test37.ok test37.out test38.in test38.ok test38.out test39.in test39.ok test39.out test4.in test4.ok test4.out test40.in test40.ok test40.out test41.in test41.ok test41.out test42.in test42.ok test42.out test43.in test43.ok test43.out test44.in test44.ok test44.out test45.in test45.ok test45.out test46.in test46.ok test46.out test47.in test47.ok test47.out test48.in test48.ok test48.out test49.in test49.ok test49.out test49.vim test5.in test5.ok test5.out test50.in test50.ok test51.in test51.ok test51.out test52.in test52.ok test52.out test53.in test53.ok test53.out test54.in test54.ok test54.out test55.in test55.ok test55.out test56.in test56.ok test56.out test57.in test57.ok test57.out test58.in test58.ok test58.out test59.in test59.ok test59.out test6.in test6.ok test6.out test60.in test60.ok test60.out test60.vim test61.in test61.ok test61.out test62.in test62.ok test62.out test63.in test63.ok test63.out test64.in test64.ok test64.out test65.in test65.ok test65.out test66.in test66.ok test66.out test67.in test67.ok test67.out test68.in test68.ok test68.out test69.in test69.ok test69.out test7.in test7.ok test7.out test70.in test70.ok test70.out test71.in test71.ok test71.out test71a.in test72.in test72.ok test72.out test73.in test73.ok test73.out test75.in test75.ok test75.out test76.in test76.ok test76.out test77.in test77.ok test77.out test77a.com test77a.in test77a.ok test78.in test78.ok test78.out test79.in test79.ok test79.out test8.in test8.ok test8.out test80.in test80.ok test80.out test81.in test81.ok test81.out test82.in test82.ok test82.out test83-tags2 test83-tags3 test83.in test83.ok test83.out test84.in test84.ok test84.out test85.in test85.ok test85.out test86.in test86.ok test86.out test87.in test87.ok test87.out test88.in test88.ok test88.out test89.in test89.ok test89.out test9.in test9.ok test9.out test90.in test90.ok test90.out test91.in test91.ok test91.out test92.in test92.ok test92.out test93.in test93.ok test93.out test94.in test94.ok test94.out test95.in test95.ok test95.out test97.in test97.ok test97.out test98.in test98.ok test98.out test99.in test99.ok test99.out test_alot.res test_alot.vim test_alot_latin.res test_alot_latin.vim test_alot_utf8.res test_alot_utf8.vim test_arglist.res test_arglist.vim test_assert.res test_assert.vim test_assign.vim test_autocmd.vim test_autocmd_option.in test_autocmd_option.ok test_autocmd_option.out test_autoformat_join.in test_autoformat_join.ok test_autoformat_join.out test_backspace_opt.res test_backspace_opt.vim test_breakindent.in test_breakindent.ok test_breakindent.out test_cdo.res test_cdo.vim test_changelist.in test_changelist.ok test_changelist.out test_channel.py test_channel.res test_channel.v' 1.594070 on 55: Dropping message 'im test_channel_pipe.py test_charsearch.in test_charsearch.ok test_charsearch.out test_close_count.in test_close_count.ok test_close_count.out test_command_count.in test_command_count.ok test_command_count.out test_comparators.in test_comparators.ok test_comparators.out test_cursor_func.vim test_delete.vim test_erasebackword.in test_erasebackword.ok test_erasebackword.out test_eval.in test_eval.ok test_eval.out test_eval_func.vim test_ex_undo.vim test_expand.vim test_expand_dllpath.vim test_expr.vim test_expr_utf8.vim test_feedkeys.vim test_file_perm.vim test_fixeol.in test_fixeol.ok test_fixeol.out test_fnamemodify.vim test_getcwd.in test_getcwd.ok test_getcwd.out test_glob2regpat.vim test_goto.vim test_hardcopy.res test_hardcopy.vim test_help_tagjump.vim test_history.res test_history.vim test_increment.res test_increment.vim test_insertcount.in test_insertcount.ok test_insertcount.out test_join.vim test_json.res test_json.vim test_langmap.res test_langmap.vim test_lispwords.vim test_listchars.in test_listchars.ok test_listchars.out test_listlbr.in test_listlbr.ok test_listlbr.out test_listlbr_utf8.in test_listlbr_utf8.ok test_listlbr_utf8.out test_mapping.in test_mapping.ok test_mapping.out test_marks.in test_marks.ok test_marks.out test_matchadd_conceal.res test_matchadd_conceal.vim test_matchadd_conceal_utf8.vim test_matchstrpos.vim test_menu.vim test_messages.vim test_nested_function.in test_nested_function.ok test_nested_function.out test_options.in test_options.ok test_options.out test_packadd.res test_packadd.vim test_partial.vim test_perl.res test_perl.vim test_quickfix.res test_quickfix.vim test_regexp_latin.vim test_regexp_utf8.vim test_reltime.vim test_ruby.in test_ruby.ok test_ruby.out test_search_mbyte.in test_search_mbyte.ok test_search_mbyte.out test_searchpos.vim test_set.vim test_signs.in test_signs.ok test_signs.out test_sort.vim test_statusline.vim test_syn_attr.vim test_syntax.res test_syntax.vim test_tabline.vim test_tagcase.in test_tagcase.ok test_tagcase.out test_tagjump.vim test_textobjects.in test_textobjects.ok test_textobjects.out test_timers.vim test_undolevels.vim test_unlet.vim test_utf8.in test_utf8.ok test_utf8.out test_viminfo.res test_viminfo.vim test_viml.res test_viml.vim test_visual.res test_visual.vim test_window_id.res test_window_id.vim test_wordcount.in test_wordcount.ok test_wordcount.out test_writefile.in test_writefile.ok test_writefile.out tiny.vim unix.vim viminfo vms.vim ' 1.594087 on 55: Dropping message 'DETACH ' 1.594196 on 25: Closing channel 1.594205 on 25: Clearing channel 1.594221 on 25: Freeing channel 1.594417 : Test_zero_reply() 1.594509 : Starting job: python test_channel.py 1.594535 on 56: Created channel 1.608702 : looking for messages on channels 1.671162 on 57: Created channel 1.671691 on 57: Connecting to localhost port 56982 1.671777 on 57: Waiting for connection (waiting 1 msec)... 1.671906 on 57: Connection made 1.671960 SEND on 57: '[1,"hello!"]' 1.672016 on 57: Reading JSON 1.672027 : looking for messages on channels 1.672035 on 57: Waiting for up to 2000 msec 1.682476 RECV on 57: '[1, "got it"]' 1.682486 on 57: Getting JSON message 1 1.682536 SEND on 57: '[2,"send zero"]' 1.682561 on 57: Reading JSON 1.682569 : looking for messages on channels 1.682601 on 57: Waiting for up to 2000 msec 1.682706 RECV on 57: '[0,"zero index"]' 1.682713 : looking for messages on channels 1.682722 on 57: Getting JSON message 0 1.682730 on 57: Invoking channel callback s:ChHandler 1.682767 : looking for messages on channels 1.682775 on 57: Waiting for up to 2000 msec 1.682791 RECV on 57: '[2, "sent zero"]' 1.682796 on 57: Getting JSON message 2 1.682905 SEND on 57: '[3,"send zero"]' 1.694673 RECV on 57: '[0,"zero index"][3, "sent zero"]' 1.695069 : looking for messages on channels 1.695373 on 57: Getting JSON message 0 1.695382 on 57: Invoking channel callback s:ChHandler 1.695420 on 57: Getting JSON message 3 1.695428 on 57: Invoking one-time callback s:OneHandler 1.695551 on 56: Stopping job with '' 1.695576 on 56: detaching channel from job 1.695584 on 56: Closing channel 1.695602 on 56: Clearing channel 1.695609 on 56: Freeing channel 1.695721 : Starting job: python test_channel.py 1.695744 on 58: Created channel 1.708836 ERR on 57: channel_select_check(): Cannot read from channel 1.709234 on 57: Closing channel 1.709245 : looking for messages on channels 1.709252 on 57: Closing channel 1.709259 on 57: Clearing channel 1.709271 on 57: Freeing channel 1.719618 : looking for messages on channels 1.756615 on 59: Created channel 1.757178 on 59: Connecting to localhost port 56984 1.757272 on 59: Waiting for connection (waiting 1 msec)... 1.757641 on 59: Connection made 1.757712 SEND on 59: '[1,"hello!"]' 1.757784 on 59: Reading JSON 1.757796 : looking for messages on channels 1.757804 on 59: Waiting for up to 2000 msec 1.768078 RECV on 59: '[1, "got it"]' 1.768093 on 59: Getting JSON message 1 1.768155 SEND on 59: '[2,"send zero"]' 1.768180 on 59: Reading JSON 1.768188 : looking for messages on channels 1.768217 on 59: Waiting for up to 2000 msec 1.768332 RECV on 59: '[0,"zero index"]' 1.768340 : looking for messages on channels 1.768348 on 59: Getting JSON message 0 1.768356 on 59: Dropping message 1.768364 : looking for messages on channels 1.768371 on 59: Waiting for up to 2000 msec 1.768387 RECV on 59: '[2, "sent zero"]' 1.768392 on 59: Getting JSON message 2 1.790156 : looking for messages on channels 1.790205 SEND on 59: '[3,"send zero"]' 1.800630 RECV on 59: '[0,"zero index"][3, "sent zero"]' 1.800635 : looking for messages on channels 1.800653 on 59: Getting JSON message 0 1.800661 on 59: Dropping message 1.800671 on 59: Getting JSON message 3 1.800678 on 59: Invoking one-time callback s:OneHandler 1.800801 on 59: Closing channel 1.800840 on 59: Clearing channel 1.800850 on 59: Freeing channel 1.800993 on 58: Stopping job with '' 1.801019 on 58: detaching channel from job 1.801027 on 58: Closing channel 1.801044 on 58: Clearing channel 1.801051 on 58: Freeing channel