==== start log session ==== 0.000011 : Test_out_close_cb() 0.000115 : Starting job: python test_channel_pipe.py quit now 0.000152 on 26: Created channel 0.014385 ERR on 25: channel_select_check(): Cannot read from channel 0.014421 on 25: Closing channel 0.014433 : looking for messages on channels 0.040572 RECV on 26: 'quit ' 0.040590 on 26: Invoking channel callback OutHandler 0.053474 ERR on 26: channel_select_check(): Cannot read from channel 0.053538 PUT on 26: 'DETACH ' 0.053542 on 26: Closing channel 0.053568 on 26: Invoking channel callback OutHandler 0.053616 on 26: Invoking close callback CloseHandler 0.053648 : looking for messages on channels 0.053756 on 26: Stopping job with '' 0.053805 on 26: detaching channel from job 0.053821 on 26: Closing channel 0.053829 on 26: Clearing channel 0.053839 on 26: Freeing channel 0.054134 on 27: Created channel 0.054996 ERR on 27: in gethostbyname() in channel_open() 0.055040 on 27: Closing channel 0.055048 on 27: Clearing channel 0.055055 on 27: Freeing channel 0.055299 : Test_pipe_both_to_buffer() 0.055324 : Starting job: python test_channel_pipe.py 0.055342 on 28: Created channel 0.056174 on 28: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.056206 on 28: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.056279 SEND on 28: 'echo line one ' 0.056307 SEND on 28: 'echoerr line two ' 0.056322 SEND on 28: 'double this ' 0.056338 SEND on 28: 'doubleerr that ' 0.056353 SEND on 28: 'quit ' 0.067909 : looking for messages on channels 0.095298 RECV on 28: 'line one line two this AND this that AND that Goodbye! ' 0.095314 on 28: appending line 2 to buffer 0.095373 on 28: appending line 3 to buffer 0.095387 on 28: appending line 4 to buffer 0.095399 on 28: appending line 5 to buffer 0.095411 on 28: appending line 6 to buffer 0.095424 on 28: appending line 7 to buffer 0.095436 on 28: appending line 8 to buffer 0.095888 on 28: Stopping job with '' 0.095908 on 28: detaching channel from job 0.095916 on 28: Closing channel 0.095932 on 28: Clearing channel 0.095939 on 28: Freeing channel 0.096104 : Test_pipe_err_to_buffer() 0.096149 : Starting job: python test_channel_pipe.py 0.096174 on 29: Created channel 0.097104 on 29: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.097205 SEND on 29: 'echoerr line one ' 0.097233 SEND on 29: 'echoerr line two ' 0.097249 SEND on 29: 'doubleerr this ' 0.097264 SEND on 29: 'quit ' 0.108140 : looking for messages on channels 0.141353 RECV on 29: 'Goodbye! ' 0.141369 RECV on 29: 'line one line two this AND this ' 0.141374 on 29: Dropping message 'Goodbye! ' 0.141397 on 29: appending line 2 to buffer 0.141426 on 29: appending line 3 to buffer 0.141439 on 29: appending line 4 to buffer 0.141451 on 29: appending line 5 to buffer 0.141937 on 29: Stopping job with '' 0.141960 on 29: detaching channel from job 0.141968 on 29: Closing channel 0.141985 on 29: Clearing channel 0.141992 on 29: Freeing channel 0.142172 : Test_pipe_err_to_buffer() 0.143990 : Starting job: python test_channel_pipe.py 0.144021 on 30: Created channel 0.144501 on 30: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.144686 SEND on 30: 'echoerr line one ' 0.144713 SEND on 30: 'echoerr line two ' 0.144729 SEND on 30: 'doubleerr this ' 0.144744 SEND on 30: 'quit ' 0.157260 : looking for messages on channels 0.190838 RECV on 30: 'Goodbye! ' 0.190854 RECV on 30: 'line one line two this AND this ' 0.190859 on 30: Dropping message 'Goodbye! ' 0.190883 on 30: appending line 2 to buffer 0.190940 ERR on 30: channel_select_check(): Cannot read from channel 0.190948 PUT on 30: 'DETACH ' 0.190951 on 30: Closing channel 0.190974 on 30: Dropping message 'DETACH ' 0.190982 on 30: appending line 3 to buffer 0.190994 on 30: appending line 4 to buffer 0.191005 on 30: appending line 5 to buffer 0.191612 on 30: Stopping job with '' 0.191645 on 30: detaching channel from job 0.191654 on 30: Closing channel 0.191660 on 30: Clearing channel 0.191667 on 30: Freeing channel 0.191855 : Test_pipe_from_buffer() 0.192928 : Starting job: python test_channel_pipe.py 0.192955 on 31: Created channel 0.193452 on 31: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.193534 SEND on 31: 'echo one ' 0.193554 on 31: FAKED Input not ready for writing 0.193561 on 31: written line 1 to channel 0.193568 on 31: Still 2 more lines to write 0.193629 on 31: Blocking NL read, timeout: 2000 msec 0.193638 on 31: Waiting for up to 2000 msec 0.193652 SEND on 31: 'echo two ' 0.193663 on 31: FAKED Input not ready for writing 0.193670 on 31: written line 2 to channel 0.193676 on 31: Still 1 more lines to write 0.193688 SEND on 31: 'echo three ' 0.193696 on 31: written line 3 to channel 0.193703 on 31: Finished writing all lines to channel 0.229343 RECV on 31: 'one two three ' 0.229353 on 31: Returning 3 bytes 0.229407 on 31: Blocking NL read, timeout: 2000 msec 0.229416 on 31: Returning 3 bytes 0.229431 on 31: Blocking NL read, timeout: 2000 msec 0.229439 on 31: Returning 5 bytes 0.230108 on 31: Stopping job with '' 0.230142 on 31: detaching channel from job 0.230151 on 31: Closing channel 0.230168 on 31: Clearing channel 0.230175 on 31: Freeing channel 0.230396 : Test_pipe_from_buffer() 0.232108 : Starting job: python test_channel_pipe.py 0.232141 on 32: Created channel 0.234019 on 32: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.234110 SEND on 32: 'echo one ' 0.234137 on 32: FAKED Input not ready for writing 0.234145 on 32: written line 1 to channel 0.234152 on 32: Still 2 more lines to write 0.234583 on 32: Blocking NL read, timeout: 2000 msec 0.234601 on 32: Waiting for up to 2000 msec 0.234618 SEND on 32: 'echo two ' 0.234629 on 32: FAKED Input not ready for writing 0.234636 on 32: written line 2 to channel 0.234643 on 32: Still 1 more lines to write 0.234655 SEND on 32: 'echo three ' 0.234664 on 32: written line 3 to channel 0.234671 on 32: Finished writing all lines to channel 0.272750 RECV on 32: 'one two three ' 0.272761 on 32: Returning 3 bytes 0.272851 on 32: Blocking NL read, timeout: 2000 msec 0.272861 on 32: Returning 3 bytes 0.272876 on 32: Blocking NL read, timeout: 2000 msec 0.272884 on 32: Returning 5 bytes 0.273462 on 32: Stopping job with '' 0.273495 on 32: detaching channel from job 0.273504 on 32: Closing channel 0.273520 on 32: Clearing channel 0.273527 on 32: Freeing channel 0.273742 : Test_pipe_io_one_buffer() 0.275006 : Starting job: python test_channel_pipe.py 0.275037 on 33: Created channel 0.275882 on 33: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.275927 on 33: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.276143 SEND on 33: 'Reading from channel output... ' 0.276156 on 33: written line 1 to channel 0.276229 on 33: FAKED Input not ready for writing 0.276238 on 33: Still 1 more lines to write 0.276273 SEND on 33: 'echo hello ' 0.276282 on 33: written line 2 to channel 0.287588 : looking for messages on channels 0.322126 RECV on 33: 'hello ' 0.322144 on 33: appending line 3 to buffer 0.322342 on 33: FAKED Input not ready for writing 0.322355 on 33: Still 1 more lines to write 0.322394 SEND on 33: 'double this ' 0.322412 on 33: written line 4 to channel 0.333292 RECV on 33: 'this AND this ' 0.333305 : looking for messages on channels 0.333332 on 33: appending line 5 to buffer 0.333359 on 33: appending line 6 to buffer 0.334168 on 33: Stopping job with '' 0.334200 on 33: detaching channel from job 0.334209 on 33: Closing channel 0.334225 on 33: Clearing channel 0.334232 on 33: Freeing channel 0.334421 : Test_pipe_io_two_buffers() 0.336889 : Starting job: python test_channel_pipe.py 0.336929 on 34: Created channel 0.337838 on 34: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.337881 on 34: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.338186 SEND on 34: 'echo hello ' 0.338203 on 34: written line 1 to channel 0.348953 : looking for messages on channels 0.382706 RECV on 34: 'hello ' 0.382726 on 34: appending line 2 to buffer 0.383130 on 34: FAKED Input not ready for writing 0.383147 on 34: Still 1 more lines to write 0.383200 SEND on 34: 'double this ' 0.383220 on 34: written line 2 to channel 0.396448 RECV on 34: 'this AND this ' 0.396467 : looking for messages on channels 0.396510 on 34: appending line 3 to buffer 0.396568 on 34: appending line 4 to buffer 0.398305 on 34: Stopping job with '' 0.398347 on 34: detaching channel from job 0.398360 on 34: Closing channel 0.398382 on 34: Clearing channel 0.398394 on 34: Freeing channel 0.398645 : Test_pipe_null() 0.398689 : Starting job: python test_channel_pipe.py something 0.398714 on 35: Created channel 0.399474 on 35: Blocking NL read, timeout: 2000 msec 0.399533 on 35: Waiting for up to 2000 msec 0.435056 RECV on 35: 'something ' 0.435067 on 35: Returning 9 bytes 0.435125 on 35: Stopping job with '' 0.435169 : Starting job: python test_channel_pipe.py err-out 0.435192 on 36: Created channel 0.435732 on 35: detaching channel from job 0.435783 on 35: Closing channel 0.435792 on 35: Clearing channel 0.435799 on 35: Freeing channel 0.435964 on 36: Blocking NL read, timeout: 2000 msec 0.435979 on 36: Waiting for up to 2000 msec 0.469159 RECV on 36: 'err-out ' 0.469170 on 36: Returning 7 bytes 0.469223 on 36: Stopping job with '' 0.469264 : Starting job: python test_channel_pipe.py something 0.469304 on 37: Created channel 0.469842 on 36: detaching channel from job 0.469886 on 36: Closing channel 0.469896 on 36: Clearing channel 0.469902 on 36: Freeing channel 0.469957 on 37: Blocking NL read, timeout: 2000 msec 0.469974 on 37: Waiting for up to 2000 msec 0.502999 RECV on 37: 'something ' 0.503010 on 37: Returning 9 bytes 0.503064 on 37: Stopping job with '' 0.503112 : Starting job: python test_channel_pipe.py something 0.503128 on 38: Created channel 0.503648 on 37: detaching channel from job 0.503698 on 37: Closing channel 0.503714 on 37: Clearing channel 0.503722 on 37: Freeing channel 0.503770 on 38: Stopping job with '' 0.503799 : Starting job: python test_channel_pipe.py something 0.504720 on 38: detaching channel from job 0.504771 on 38: Closing channel 0.504781 on 38: Clearing channel 0.504788 on 38: Freeing channel 0.504916 : Stopping job with '' 0.505467 : Test_pipe_to_buffer_json() 0.505495 : Starting job: python test_channel_pipe.py 0.505519 on 39: Created channel 0.508741 on 39: writing out to buffer '(null)' 0.508920 SEND on 39: 'echo [0, "hello"] ' 0.508950 SEND on 39: 'echo [-2, 12.34] ' 0.521042 : looking for messages on channels 0.579430 RECV on 39: '[0, "hello"] [-2, 12.34] ' 0.579445 on 39: Getting JSON message 0 0.579475 on 39: appending line 2 to buffer 0.579515 on 39: Getting JSON message -2 0.579563 on 39: appending line 3 to buffer 0.580009 on 39: Stopping job with '' 0.580041 on 39: detaching channel from job 0.580050 on 39: Closing channel 0.580068 on 39: Clearing channel 0.580075 on 39: Freeing channel 0.580307 : Test_pipe_to_buffer() 0.580354 : Starting job: python test_channel_pipe.py 0.580377 on 40: Created channel 0.593784 on 40: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.593926 SEND on 40: 'echo line one ' 0.593953 SEND on 40: 'echo line two ' 0.593969 SEND on 40: 'double this ' 0.593984 SEND on 40: 'quit ' 0.618352 : looking for messages on channels 0.682533 RECV on 40: 'line one line two this AND this Goodbye! ' 0.682547 ERR on 40: channel_select_check(): Cannot read from channel 0.682569 PUT on 40: 'DETACH ' 0.682571 on 40: Closing channel 0.682615 : looking for messages on channels 0.682625 on 40: appending line 2 to buffer 0.682761 on 40: appending line 3 to buffer 0.682775 on 40: appending line 4 to buffer 0.682788 on 40: appending line 5 to buffer 0.682800 on 40: appending line 6 to buffer 0.682813 on 40: Dropping message 'DETACH ' 0.683177 on 40: Stopping job with '' 0.683197 on 40: detaching channel from job 0.683205 on 40: Closing channel 0.683211 on 40: Clearing channel 0.683217 on 40: Freeing channel 0.683395 : Test_pipe_to_buffer() 0.685240 : Starting job: python test_channel_pipe.py 0.685276 on 41: Created channel 0.687770 on 41: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.688240 SEND on 41: 'echo line one ' 0.688274 SEND on 41: 'echo line two ' 0.688290 SEND on 41: 'double this ' 0.688305 SEND on 41: 'quit ' 0.703095 : looking for messages on channels 0.732847 RECV on 41: 'line one line two this AND this Goodbye! ' 0.732861 ERR on 41: channel_select_check(): Cannot read from channel 0.732882 PUT on 41: 'DETACH ' 0.732884 on 41: Closing channel 0.732903 : looking for messages on channels 0.732913 on 41: appending line 2 to buffer 0.732973 on 41: appending line 3 to buffer 0.732986 on 41: appending line 4 to buffer 0.732997 on 41: appending line 5 to buffer 0.733009 on 41: appending line 6 to buffer 0.733021 on 41: Dropping message 'DETACH ' 0.733617 on 41: Stopping job with '' 0.733639 on 41: detaching channel from job 0.733647 on 41: Closing channel 0.733653 on 41: Clearing channel 0.733659 on 41: Freeing channel 0.734096 : Test_pipe_to_nameless_buffer() 0.734121 : Starting job: python test_channel_pipe.py 0.734145 on 42: Created channel 0.737865 on 42: writing out to buffer '(null)' 0.738446 SEND on 42: 'echo line one ' 0.738537 SEND on 42: 'echo line two ' 0.750533 : looking for messages on channels 0.776477 RECV on 42: 'line one line two ' 0.776490 on 42: appending line 2 to buffer 0.776536 on 42: appending line 3 to buffer 0.776860 on 42: Stopping job with '' 0.776887 on 42: detaching channel from job 0.776896 on 42: Closing channel 0.776912 on 42: Clearing channel 0.776919 on 42: Freeing channel 0.777090 : Test_raw_one_time_callback() 0.777268 : Starting job: python test_channel.py 0.777292 on 43: Created channel 0.791759 : looking for messages on channels 0.853087 on 44: Created channel 0.853702 on 44: Connecting to localhost port 59031 0.853818 on 44: Waiting for connection (waiting 1 msec)... 0.853949 on 44: Connection made 0.854014 SEND on 44: '[1, "hello!"]' 0.864302 : looking for messages on channels 0.874681 RECV on 44: '[1, "got it"]' 0.874688 on 44: Invoking one-time callback s:HandleRaw1 0.874783 SEND on 44: '[2, "echo something"]' 0.874822 SEND on 44: '[3, "wait a bit"]' 0.885078 RECV on 44: '[2, "something"]' 0.885082 : looking for messages on channels 0.885091 on 44: Invoking one-time callback s:HandleRaw2 0.895238 : looking for messages on channels 1.083448 RECV on 44: '[3, "waited"]' 1.083453 on 44: Invoking one-time callback s:HandleRaw3 1.083523 on 44: Closing channel 1.083554 on 44: Clearing channel 1.083565 on 44: Freeing channel 1.083607 on 43: Stopping job with '' 1.083631 on 43: detaching channel from job 1.083639 on 43: Closing channel 1.083705 on 43: Clearing channel 1.083715 on 43: Freeing channel 1.083949 : Test_raw_pipe() 1.083972 : Starting job: python test_channel_pipe.py 1.083994 on 45: Created channel 1.085655 SEND on 45: 'echo something ' 1.085733 on 45: Blocking RAW read, timeout: 2000 msec 1.085750 on 45: Waiting for up to 2000 msec 1.118572 RECV on 45: 'something ' 1.118583 on 45: Returning 10 bytes 1.118686 SEND on 45: 'double this ' 1.118707 on 45: Blocking RAW read, timeout: 2000 msec 1.118715 on 45: Waiting for up to 2000 msec 1.118760 RECV on 45: 'this AND this ' 1.118765 on 45: Returning 14 bytes 1.118929 SEND on 45: 'quit ' 1.118942 on 45: Blocking RAW read, timeout: 100 msec 1.118968 on 45: Waiting for up to 100 msec 1.119006 RECV on 45: 'Goodbye! ' 1.119009 on 45: Returning 9 bytes 1.119043 on 45: Stopping job with '' 1.131876 ERR on 45: channel_select_check(): Cannot read from channel 1.131915 PUT on 45: 'DETACH ' 1.131917 on 45: Closing channel 1.131939 : looking for messages on channels 1.131947 on 45: Dropping message 'DETACH ' 1.132006 on 45: Job ended 1.132260 : Test_read_in_close_cb() 1.132297 : Starting job: python test_channel_pipe.py quit now 1.132320 on 46: Created channel 1.145165 : looking for messages on channels 1.180714 RECV on 46: 'quit ' 1.180728 ERR on 46: channel_select_check(): Cannot read from channel 1.180751 PUT on 46: 'DETACH ' 1.180753 on 46: Closing channel 1.180770 on 46: Invoking close callback CloseHandler 1.180830 on 46: Blocking NL read, timeout: 2000 msec 1.180842 on 46: Returning 4 bytes 1.180859 on 46: Dropping message 'DETACH ' 1.180868 : looking for messages on channels 1.180934 on 46: Stopping job with '' 1.180961 on 46: detaching channel from job 1.180969 on 46: Closing channel 1.180975 on 46: Clearing channel 1.180982 on 46: Freeing channel 1.181171 : Test_reuse_channel() 1.181190 : Starting job: python test_channel_pipe.py 1.181212 on 47: Created channel 1.182818 SEND on 47: 'echo something ' 1.182871 on 47: Blocking NL read, timeout: 2000 msec 1.182888 on 47: Waiting for up to 2000 msec 1.217148 RECV on 47: 'something ' 1.217159 on 47: Returning 9 bytes 1.217210 on 47: Stopping job with '' 1.217288 : Starting job: python test_channel_pipe.py 1.218842 on 47: detaching channel from job 1.218993 SEND on 47: 'echo again ' 1.219022 on 47: Blocking NL read, timeout: 2000 msec 1.219038 on 47: Waiting for up to 2000 msec 1.252049 RECV on 47: 'again ' 1.252061 on 47: Returning 5 bytes 1.252153 on 47: Stopping job with '' 1.252184 on 47: detaching channel from job 1.252192 on 47: Closing channel 1.252209 on 47: Clearing channel 1.252216 on 47: Freeing channel 1.252442 : Test_server_crash() 1.252514 : Starting job: python test_channel.py 1.252541 on 48: Created channel 1.254651 on 45: Freeing job 1.254716 on 45: Closing channel 1.254725 on 45: Clearing channel 1.254732 on 45: Freeing channel 1.266904 : looking for messages on channels 1.323750 on 49: Created channel 1.324340 on 49: Connecting to localhost port 59033 1.324428 on 49: Waiting for connection (waiting 1 msec)... 1.324528 on 49: Connection made 1.324586 SEND on 49: '[1,"!crash!"]' 1.324614 on 49: Reading JSON 1.324622 : looking for messages on channels 1.324631 on 49: Waiting for up to 2000 msec 1.335977 ERR on 49: channel_read_json_block(): Cannot read from channel 1.335999 on 49: Closing channel 1.336023 : looking for messages on channels 1.346139 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.346144 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.346179 on 49: Closing channel 1.346187 on 49: Clearing channel 1.346194 on 49: Freeing channel 1.346249 on 48: Stopping job with '' 1.346275 on 48: detaching channel from job 1.346283 on 48: Closing channel 1.346298 on 48: Clearing channel 1.346305 on 48: Freeing channel 1.346553 : Test_two_channels() 1.346624 : Starting job: python test_channel.py 1.346646 on 50: Created channel 1.359085 : looking for messages on channels 1.416950 on 51: Created channel 1.417429 on 51: Connecting to localhost port 59035 1.417512 on 51: Waiting for connection (waiting 1 msec)... 1.417610 on 51: Connection made 1.417660 SEND on 51: '[1,"hello!"]' 1.417719 on 51: Reading JSON 1.417730 : looking for messages on channels 1.417737 on 51: Waiting for up to 2000 msec 1.428300 RECV on 51: '[1, "got it"]' 1.428312 on 51: Getting JSON message 1 1.428353 on 52: Created channel 1.428787 on 52: Connecting to localhost port 59035 1.428846 on 52: Waiting for connection (waiting 1 msec)... 1.428927 on 52: Connection made 1.428978 SEND on 52: '[1,"hello!"]' 1.429004 on 52: Reading JSON 1.429013 : looking for messages on channels 1.429021 on 52: Waiting for up to 2000 msec 1.439467 RECV on 52: '[1, "got it"]' 1.439475 on 52: Getting JSON message 1 1.439509 SEND on 51: '[2,"hello!"]' 1.439535 on 51: Reading JSON 1.439543 : looking for messages on channels 1.439550 on 51: Waiting for up to 2000 msec 1.439675 RECV on 51: '[2, "got it"]' 1.439681 on 51: Getting JSON message 2 1.439703 on 51: Closing channel 1.439734 on 51: Clearing channel 1.439757 SEND on 52: '[2,"hello!"]' 1.439811 on 52: Reading JSON 1.439821 : looking for messages on channels 1.439828 on 52: Waiting for up to 2000 msec 1.440017 RECV on 52: '[2, "got it"]' 1.440024 on 52: Getting JSON message 2 1.440045 on 52: Closing channel 1.440074 on 52: Clearing channel 1.440087 on 52: Closing channel 1.440095 on 52: Clearing channel 1.440101 on 52: Freeing channel 1.440108 on 51: Closing channel 1.440115 on 51: Clearing channel 1.440121 on 51: Freeing channel 1.440213 on 50: Stopping job with '' 1.440239 on 50: detaching channel from job 1.440247 on 50: Closing channel 1.440264 on 50: Clearing channel 1.440271 on 50: Freeing channel 1.440521 : Test_unlet_handle() 1.440601 : Starting job: python test_channel.py 1.440624 on 53: Created channel 1.455044 : looking for messages on channels 1.513639 on 54: Created channel 1.514227 on 54: Connecting to localhost port 59038 1.514696 on 54: Waiting for connection (waiting 1 msec)... 1.514724 on 54: Connection made 1.514746 on 9: Closing channel 1.514754 on 9: Clearing channel 1.514761 on 9: Freeing channel 1.514808 SEND on 54: '[1,"test"]' 1.514993 on 53: Stopping job with '' 1.515026 on 53: detaching channel from job 1.515035 on 53: Closing channel 1.515056 on 53: Clearing channel 1.515065 on 53: Freeing channel 1.515323 : Starting job: ls 1.515350 on 55: Created channel 1.531925 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.vim test_channel_p' 1.532037 RECV on 55: 'ipe.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.532043 ERR on 55: channel_select_check(): Cannot read from channel 1.532061 PUT on 55: 'DETACH ' 1.532064 on 55: Closing channel 1.532098 ERR on 54: channel_select_check(): Cannot read from channel 1.532106 on 54: Closing channel 1.532181 : looking for messages on channels 1.532192 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.vim test_channel_p' 1.532217 on 55: Dropping message 'ipe.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.532234 on 55: Dropping message 'DETACH ' 1.532389 on 25: Closing channel 1.532399 on 25: Clearing channel 1.532416 on 25: Freeing channel 1.532649 : Test_zero_reply() 1.532754 : Starting job: python test_channel.py 1.532782 on 56: Created channel 1.547509 : looking for messages on channels 1.612772 on 57: Created channel 1.613280 on 57: Connecting to localhost port 59040 1.613366 on 57: Waiting for connection (waiting 1 msec)... 1.613627 on 57: Connection made 1.613696 SEND on 57: '[1,"hello!"]' 1.613758 on 57: Reading JSON 1.613769 : looking for messages on channels 1.613777 on 57: Waiting for up to 2000 msec 1.614217 RECV on 57: '[1, "got it"]' 1.614228 on 57: Getting JSON message 1 1.614277 SEND on 57: '[2,"send zero"]' 1.614303 on 57: Reading JSON 1.614311 : looking for messages on channels 1.614340 on 57: Waiting for up to 2000 msec 1.614464 RECV on 57: '[0,"zero index"][2, "sent zero"]' 1.614476 on 57: Getting JSON message 2 1.630769 : looking for messages on channels 1.630799 on 57: Getting JSON message 0 1.630809 on 57: Invoking channel callback s:ChHandler 1.630954 SEND on 57: '[3,"send zero"]' 1.641821 RECV on 57: '[0,"zero index"][3, "sent zero"]' 1.641826 : looking for messages on channels 1.641842 on 57: Getting JSON message 0 1.641850 on 57: Invoking channel callback s:ChHandler 1.641879 on 57: Getting JSON message 3 1.641887 on 57: Invoking one-time callback s:OneHandler 1.641994 on 56: Stopping job with '' 1.642017 on 56: detaching channel from job 1.642025 on 56: Closing channel 1.642044 on 56: Clearing channel 1.642051 on 56: Freeing channel 1.642166 : Starting job: python test_channel.py 1.642191 on 58: Created channel 1.655167 ERR on 57: channel_select_check(): Cannot read from channel 1.655196 on 57: Closing channel 1.655207 : looking for messages on channels 1.655241 on 57: Closing channel 1.655250 on 57: Clearing channel 1.655374 on 57: Freeing channel 1.667668 : looking for messages on channels 1.712727 on 59: Created channel 1.713492 on 59: Connecting to localhost port 59042 1.713589 on 59: Waiting for connection (waiting 1 msec)... 1.713725 on 59: Connection made 1.713790 SEND on 59: '[1,"hello!"]' 1.713848 on 59: Reading JSON 1.713858 : looking for messages on channels 1.713867 on 59: Waiting for up to 2000 msec 1.724337 RECV on 59: '[1, "got it"]' 1.724348 on 59: Getting JSON message 1 1.724395 SEND on 59: '[2,"send zero"]' 1.724426 on 59: Reading JSON 1.724435 : looking for messages on channels 1.724467 on 59: Waiting for up to 2000 msec 1.724557 RECV on 59: '[0,"zero index"]' 1.724577 : looking for messages on channels 1.724586 on 59: Getting JSON message 0 1.724594 on 59: Dropping message 1.724603 : looking for messages on channels 1.724610 on 59: Waiting for up to 2000 msec 1.724625 RECV on 59: '[2, "sent zero"]' 1.724630 on 59: Getting JSON message 2 1.753669 : looking for messages on channels 1.753801 SEND on 59: '[3,"send zero"]' 1.765770 RECV on 59: '[0,"zero index"][3, "sent zero"]' 1.765776 : looking for messages on channels 1.765800 on 59: Getting JSON message 0 1.765808 on 59: Dropping message 1.765819 on 59: Getting JSON message 3 1.765827 on 59: Invoking one-time callback s:OneHandler 1.765929 on 59: Closing channel 1.765971 on 59: Clearing channel 1.765980 on 59: Freeing channel 1.766024 on 58: Stopping job with '' 1.766049 on 58: detaching channel from job 1.766057 on 58: Closing channel 1.766073 on 58: Clearing channel 1.766080 on 58: Freeing channel