==== start log session ==== 0.000013 : Test_out_close_cb() 0.000109 : Starting job: python test_channel_pipe.py quit now 0.000144 on 26: Created channel 0.011683 ERR on 25: channel_select_check(): Cannot read from channel 0.011749 on 25: Closing channel 0.011761 : looking for messages on channels 0.043944 RECV on 26: 'quit ' 0.043966 ERR on 26: channel_select_check(): Cannot read from channel 0.043996 PUT on 26: 'DETACH ' 0.043999 on 26: Closing channel 0.044021 on 26: Invoking channel callback OutHandler 0.044118 on 26: Invoking close callback CloseHandler 0.044141 on 26: Dropping message 'DETACH ' 0.044152 : looking for messages on channels 0.044226 on 26: Stopping job with '' 0.044277 on 26: detaching channel from job 0.044285 on 26: Closing channel 0.044291 on 26: Clearing channel 0.044298 on 26: Freeing channel 0.044492 on 27: Created channel 0.045377 ERR on 27: in gethostbyname() in channel_open() 0.045415 on 27: Closing channel 0.045423 on 27: Clearing channel 0.045429 on 27: Freeing channel 0.045629 : Test_pipe_both_to_buffer() 0.045654 : Starting job: python test_channel_pipe.py 0.045671 on 28: Created channel 0.046514 on 28: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.046552 on 28: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.046638 SEND on 28: 'echo line one ' 0.046664 SEND on 28: 'echoerr line two ' 0.046679 SEND on 28: 'double this ' 0.046695 SEND on 28: 'doubleerr that ' 0.046710 SEND on 28: 'quit ' 0.058113 : looking for messages on channels 0.092478 RECV on 28: 'line one line two this AND this that AND that Goodbye! ' 0.092495 on 28: appending line 2 to buffer 0.092572 on 28: appending line 3 to buffer 0.092587 on 28: appending line 4 to buffer 0.092599 on 28: appending line 5 to buffer 0.092612 on 28: appending line 6 to buffer 0.092627 on 28: appending line 7 to buffer 0.092641 on 28: appending line 8 to buffer 0.092970 on 28: Stopping job with '' 0.092988 on 28: detaching channel from job 0.092996 on 28: Closing channel 0.093010 on 28: Clearing channel 0.093017 on 28: Freeing channel 0.093185 : Test_pipe_err_to_buffer() 0.093229 : Starting job: python test_channel_pipe.py 0.093250 on 29: Created channel 0.094099 on 29: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.094189 SEND on 29: 'echoerr line one ' 0.094216 SEND on 29: 'echoerr line two ' 0.094232 SEND on 29: 'doubleerr this ' 0.094248 SEND on 29: 'quit ' 0.105285 : looking for messages on channels 0.131233 RECV on 29: 'line one line two' 0.131251 on 29: appending line 2 to buffer 0.143774 RECV on 29: 'Goodbye! ' 0.143815 RECV on 29: ' this AND this ' 0.143823 : looking for messages on channels 0.143875 on 29: Dropping message 'Goodbye! ' 0.143909 on 29: appending line 3 to buffer 0.143998 on 29: appending line 4 to buffer 0.144039 on 29: appending line 5 to buffer 0.144958 on 29: Stopping job with '' 0.144987 on 29: detaching channel from job 0.144998 on 29: Closing channel 0.145022 on 29: Clearing channel 0.145032 on 29: Freeing channel 0.145355 : Test_pipe_err_to_buffer() 0.147297 : Starting job: python test_channel_pipe.py 0.147333 on 30: Created channel 0.147954 on 30: writing err to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-err' 0.148138 SEND on 30: 'echoerr line one ' 0.148172 SEND on 30: 'echoerr line two ' 0.148193 SEND on 30: 'doubleerr this ' 0.148213 SEND on 30: 'quit ' 0.160067 : looking for messages on channels 0.194978 RECV on 30: 'Goodbye! ' 0.195000 RECV on 30: 'line one line two this AND this ' 0.195006 on 30: Dropping message 'Goodbye! ' 0.195038 on 30: appending line 2 to buffer 0.195156 ERR on 30: channel_select_check(): Cannot read from channel 0.195178 PUT on 30: 'DETACH ' 0.195182 on 30: Closing channel 0.195216 on 30: Dropping message 'DETACH ' 0.195231 on 30: appending line 3 to buffer 0.195251 on 30: appending line 4 to buffer 0.195317 on 30: appending line 5 to buffer 0.196111 on 30: Stopping job with '' 0.196153 on 30: detaching channel from job 0.196161 on 30: Closing channel 0.196168 on 30: Clearing channel 0.196175 on 30: Freeing channel 0.196383 : Test_pipe_from_buffer() 0.197480 : Starting job: python test_channel_pipe.py 0.197507 on 31: Created channel 0.198018 on 31: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.198103 SEND on 31: 'echo one ' 0.198123 on 31: FAKED Input not ready for writing 0.198131 on 31: written line 1 to channel 0.198137 on 31: Still 2 more lines to write 0.198296 on 31: Blocking NL read, timeout: 2000 msec 0.198308 on 31: Waiting for up to 2000 msec 0.198324 SEND on 31: 'echo two ' 0.198336 on 31: FAKED Input not ready for writing 0.198343 on 31: written line 2 to channel 0.198349 on 31: Still 1 more lines to write 0.198361 SEND on 31: 'echo three ' 0.198369 on 31: written line 3 to channel 0.198376 on 31: Finished writing all lines to channel 0.234012 RECV on 31: 'one two three ' 0.234026 on 31: Returning 3 bytes 0.234095 on 31: Blocking NL read, timeout: 2000 msec 0.234105 on 31: Returning 3 bytes 0.234121 on 31: Blocking NL read, timeout: 2000 msec 0.234129 on 31: Returning 5 bytes 0.234958 on 31: Stopping job with '' 0.235019 on 31: detaching channel from job 0.235028 on 31: Closing channel 0.235049 on 31: Clearing channel 0.235056 on 31: Freeing channel 0.235316 : Test_pipe_from_buffer() 0.236860 : Starting job: python test_channel_pipe.py 0.236904 on 32: Created channel 0.237857 on 32: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.237957 SEND on 32: 'echo one ' 0.237978 on 32: FAKED Input not ready for writing 0.237985 on 32: written line 1 to channel 0.237992 on 32: Still 2 more lines to write 0.238116 on 32: Blocking NL read, timeout: 2000 msec 0.238125 on 32: Waiting for up to 2000 msec 0.238140 SEND on 32: 'echo two ' 0.238151 on 32: FAKED Input not ready for writing 0.238158 on 32: written line 2 to channel 0.238164 on 32: Still 1 more lines to write 0.238175 SEND on 32: 'echo three ' 0.238184 on 32: written line 3 to channel 0.238190 on 32: Finished writing all lines to channel 0.274312 RECV on 32: 'one two three ' 0.274340 on 32: Returning 3 bytes 0.274563 on 32: Blocking NL read, timeout: 2000 msec 0.274576 on 32: Returning 3 bytes 0.274593 on 32: Blocking NL read, timeout: 2000 msec 0.274601 on 32: Returning 5 bytes 0.275569 on 32: Stopping job with '' 0.275675 on 32: detaching channel from job 0.275684 on 32: Closing channel 0.275703 on 32: Clearing channel 0.275710 on 32: Freeing channel 0.275942 : Test_pipe_io_one_buffer() 0.277232 : Starting job: python test_channel_pipe.py 0.277305 on 33: Created channel 0.278497 on 33: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.278542 on 33: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-io' 0.278756 SEND on 33: 'Reading from channel output... ' 0.278769 on 33: written line 1 to channel 0.278848 on 33: FAKED Input not ready for writing 0.278857 on 33: Still 1 more lines to write 0.278892 SEND on 33: 'echo hello ' 0.278902 on 33: written line 2 to channel 0.289613 : looking for messages on channels 0.323230 RECV on 33: 'hello ' 0.323251 on 33: appending line 3 to buffer 0.323463 on 33: FAKED Input not ready for writing 0.323474 on 33: Still 1 more lines to write 0.323510 SEND on 33: 'double this ' 0.323526 on 33: written line 4 to channel 0.336485 RECV on 33: 'this AND this ' 0.336517 : looking for messages on channels 0.336586 on 33: appending line 5 to buffer 0.336662 on 33: appending line 6 to buffer 0.338098 on 33: Stopping job with '' 0.338149 on 33: detaching channel from job 0.338162 on 33: Closing channel 0.338186 on 33: Clearing channel 0.338197 on 33: Freeing channel 0.338442 : Test_pipe_io_two_buffers() 0.341263 : Starting job: python test_channel_pipe.py 0.341314 on 34: Created channel 0.342237 on 34: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.342280 on 34: reading from buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-input' 0.342609 SEND on 34: 'echo hello ' 0.342626 on 34: written line 1 to channel 0.355079 : looking for messages on channels 0.389600 RECV on 34: 'hello ' 0.389636 on 34: appending line 2 to buffer 0.389986 on 34: FAKED Input not ready for writing 0.389997 on 34: Still 1 more lines to write 0.390030 SEND on 34: 'double this ' 0.390044 on 34: written line 2 to channel 0.401712 RECV on 34: 'this AND this ' 0.401726 : looking for messages on channels 0.401756 on 34: appending line 3 to buffer 0.401789 on 34: appending line 4 to buffer 0.403218 on 34: Stopping job with '' 0.403275 on 34: detaching channel from job 0.403283 on 34: Closing channel 0.403301 on 34: Clearing channel 0.403308 on 34: Freeing channel 0.403487 : Test_pipe_null() 0.403512 : Starting job: python test_channel_pipe.py something 0.403530 on 35: Created channel 0.404119 on 35: Blocking NL read, timeout: 2000 msec 0.404164 on 35: Waiting for up to 2000 msec 0.438990 RECV on 35: 'something ' 0.439001 on 35: Returning 9 bytes 0.439053 on 35: Stopping job with '' 0.439094 : Starting job: python test_channel_pipe.py err-out 0.439168 on 36: Created channel 0.439692 on 35: detaching channel from job 0.439736 on 35: Closing channel 0.439745 on 35: Clearing channel 0.439752 on 35: Freeing channel 0.439819 on 36: Blocking NL read, timeout: 2000 msec 0.439835 on 36: Waiting for up to 2000 msec 0.474739 RECV on 36: 'err-out ' 0.474749 on 36: Returning 7 bytes 0.474804 on 36: Stopping job with '' 0.474845 : Starting job: python test_channel_pipe.py something 0.474865 on 37: Created channel 0.475420 on 36: detaching channel from job 0.475463 on 36: Closing channel 0.475473 on 36: Clearing channel 0.475480 on 36: Freeing channel 0.475541 on 37: Blocking NL read, timeout: 2000 msec 0.475557 on 37: Waiting for up to 2000 msec 0.508702 RECV on 37: 'something ' 0.508713 on 37: Returning 9 bytes 0.508765 on 37: Stopping job with '' 0.508809 : Starting job: python test_channel_pipe.py something 0.508826 on 38: Created channel 0.510318 on 37: detaching channel from job 0.510363 on 37: Closing channel 0.510373 on 37: Clearing channel 0.510380 on 37: Freeing channel 0.510508 on 38: Stopping job with '' 0.510723 : Starting job: python test_channel_pipe.py something 0.511114 on 38: detaching channel from job 0.511158 on 38: Closing channel 0.511167 on 38: Clearing channel 0.511174 on 38: Freeing channel 0.511401 : Stopping job with '' 0.511750 : Test_pipe_to_buffer_json() 0.511775 : Starting job: python test_channel_pipe.py 0.511798 on 39: Created channel 0.522873 on 39: writing out to buffer '(null)' 0.523400 SEND on 39: 'echo [0, "hello"] ' 0.523427 SEND on 39: 'echo [-2, 12.34] ' 0.552038 RECV on 39: '[0, "hello"] [-2, 12.34] ' 0.552051 : looking for messages on channels 0.552083 on 39: Getting JSON message 0 0.552105 on 39: appending line 2 to buffer 0.552146 on 39: Getting JSON message -2 0.552172 on 39: appending line 3 to buffer 0.552495 on 39: Stopping job with '' 0.554010 on 39: detaching channel from job 0.554036 on 39: Closing channel 0.554054 on 39: Clearing channel 0.554061 on 39: Freeing channel 0.554261 : Test_pipe_to_buffer() 0.554307 : Starting job: python test_channel_pipe.py 0.554329 on 40: Created channel 0.588431 on 40: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.588526 SEND on 40: 'echo line one ' 0.588596 SEND on 40: 'echo line two ' 0.588636 SEND on 40: 'double this ' 0.588674 SEND on 40: 'quit ' 0.603527 RECV on 40: 'line one line two this AND this Goodbye! ' 0.603542 ERR on 40: channel_select_check(): Cannot read from channel 0.603567 PUT on 40: 'DETACH ' 0.603569 on 40: Closing channel 0.603618 : looking for messages on channels 0.603629 on 40: appending line 2 to buffer 0.603666 on 40: appending line 3 to buffer 0.603679 on 40: appending line 4 to buffer 0.603696 on 40: appending line 5 to buffer 0.603709 on 40: appending line 6 to buffer 0.603722 on 40: Dropping message 'DETACH ' 0.604699 on 40: Stopping job with '' 0.604726 on 40: detaching channel from job 0.604734 on 40: Closing channel 0.604741 on 40: Clearing channel 0.604748 on 40: Freeing channel 0.604915 : Test_pipe_to_buffer() 0.606733 : Starting job: python test_channel_pipe.py 0.606762 on 41: Created channel 0.607397 on 41: writing out to buffer '/Users/kazu/Documents/projects/vim/src/testdir/pipe-output' 0.607536 SEND on 41: 'echo line one ' 0.607563 SEND on 41: 'echo line two ' 0.607579 SEND on 41: 'double this ' 0.607594 SEND on 41: 'quit ' 0.623455 : looking for messages on channels 0.660004 RECV on 41: 'line one line two this AND this Goodbye! ' 0.660024 ERR on 41: channel_select_check(): Cannot read from channel 0.660054 PUT on 41: 'DETACH ' 0.660056 on 41: Closing channel 0.660076 : looking for messages on channels 0.660087 on 41: appending line 2 to buffer 0.660189 on 41: appending line 3 to buffer 0.660203 on 41: appending line 4 to buffer 0.660216 on 41: appending line 5 to buffer 0.660229 on 41: appending line 6 to buffer 0.660241 on 41: Dropping message 'DETACH ' 0.661041 on 41: Stopping job with '' 0.661082 on 41: detaching channel from job 0.661093 on 41: Closing channel 0.661100 on 41: Clearing channel 0.661107 on 41: Freeing channel 0.661331 : Test_pipe_to_nameless_buffer() 0.661354 : Starting job: python test_channel_pipe.py 0.661380 on 42: Created channel 0.662974 on 42: writing out to buffer '(null)' 0.663094 SEND on 42: 'echo line one ' 0.663121 SEND on 42: 'echo line two ' 0.677162 : looking for messages on channels 0.700800 RECV on 42: 'line one line two ' 0.700818 on 42: appending line 2 to buffer 0.700873 on 42: appending line 3 to buffer 0.701380 on 42: Stopping job with '' 0.701424 on 42: detaching channel from job 0.701479 on 42: Closing channel 0.701497 on 42: Clearing channel 0.701505 on 42: Freeing channel 0.701677 : Test_raw_one_time_callback() 0.701842 : Starting job: python test_channel.py 0.701864 on 43: Created channel 0.716120 : looking for messages on channels 0.793914 on 44: Created channel 0.794572 on 44: Connecting to localhost port 59082 0.794693 on 44: Waiting for connection (waiting 1 msec)... 0.794830 on 44: Connection made 0.794896 SEND on 44: '[1, "hello!"]' 0.807646 RECV on 44: '[1, "got it"]' 0.807656 : looking for messages on channels 0.807674 on 44: Invoking one-time callback s:HandleRaw1 0.807782 SEND on 44: '[2, "echo something"]' 0.807834 SEND on 44: '[3, "wait a bit"]' 0.819916 RECV on 44: '[2, "something"]' 0.819920 : looking for messages on channels 0.819930 on 44: Invoking one-time callback s:HandleRaw2 0.832310 : looking for messages on channels 1.011760 RECV on 44: '[3, "waited"]' 1.011770 on 44: Invoking one-time callback s:HandleRaw3 1.011864 on 44: Closing channel 1.011903 on 44: Clearing channel 1.011913 on 44: Freeing channel 1.011981 on 43: Stopping job with '' 1.012007 on 43: detaching channel from job 1.012071 on 43: Closing channel 1.012091 on 43: Clearing channel 1.012098 on 43: Freeing channel 1.012346 : Test_raw_pipe() 1.012369 : Starting job: python test_channel_pipe.py 1.012392 on 45: Created channel 1.014082 SEND on 45: 'echo something ' 1.014158 on 45: Blocking RAW read, timeout: 2000 msec 1.014175 on 45: Waiting for up to 2000 msec 1.046874 RECV on 45: 'something ' 1.046885 on 45: Returning 10 bytes 1.047010 SEND on 45: 'double this ' 1.047031 on 45: Blocking RAW read, timeout: 2000 msec 1.047040 on 45: Waiting for up to 2000 msec 1.047054 RECV on 45: 'this AND this ' 1.047056 on 45: Returning 14 bytes 1.047086 SEND on 45: 'quit ' 1.047097 on 45: Blocking RAW read, timeout: 100 msec 1.047124 on 45: Waiting for up to 100 msec 1.047138 RECV on 45: 'Goodbye! ' 1.047140 on 45: Returning 9 bytes 1.047170 on 45: Stopping job with '' 1.060013 ERR on 45: channel_select_check(): Cannot read from channel 1.060048 PUT on 45: 'DETACH ' 1.060051 on 45: Closing channel 1.060071 : looking for messages on channels 1.060079 on 45: Dropping message 'DETACH ' 1.060136 on 45: Job ended 1.060431 : Test_read_in_close_cb() 1.060465 : Starting job: python test_channel_pipe.py quit now 1.060487 on 46: Created channel 1.072790 : looking for messages on channels 1.104595 RECV on 46: 'quit ' 1.104611 ERR on 46: channel_select_check(): Cannot read from channel 1.104637 PUT on 46: 'DETACH ' 1.104640 on 46: Closing channel 1.104658 on 46: Invoking close callback CloseHandler 1.104723 on 46: Blocking NL read, timeout: 2000 msec 1.104735 on 46: Returning 4 bytes 1.104753 on 46: Dropping message 'DETACH ' 1.104762 : looking for messages on channels 1.104830 on 46: Stopping job with '' 1.104855 on 46: detaching channel from job 1.104863 on 46: Closing channel 1.104870 on 46: Clearing channel 1.104876 on 46: Freeing channel 1.105064 : Test_reuse_channel() 1.105083 : Starting job: python test_channel_pipe.py 1.105105 on 47: Created channel 1.105695 SEND on 47: 'echo something ' 1.105748 on 47: Blocking NL read, timeout: 2000 msec 1.105763 on 47: Waiting for up to 2000 msec 1.139562 RECV on 47: 'something ' 1.139573 on 47: Returning 9 bytes 1.139626 on 47: Stopping job with '' 1.139667 : Starting job: python test_channel_pipe.py 1.141586 on 47: detaching channel from job 1.141734 SEND on 47: 'echo again ' 1.141763 on 47: Blocking NL read, timeout: 2000 msec 1.141778 on 47: Waiting for up to 2000 msec 1.174068 RECV on 47: 'again ' 1.174080 on 47: Returning 5 bytes 1.174137 on 47: Stopping job with '' 1.174167 on 47: detaching channel from job 1.174175 on 47: Closing channel 1.174191 on 47: Clearing channel 1.174198 on 47: Freeing channel 1.174453 : Test_server_crash() 1.174521 : Starting job: python test_channel.py 1.174547 on 48: Created channel 1.176438 on 45: Freeing job 1.176496 on 45: Closing channel 1.176505 on 45: Clearing channel 1.176511 on 45: Freeing channel 1.188780 : looking for messages on channels 1.249083 on 49: Created channel 1.249619 on 49: Connecting to localhost port 59084 1.249705 on 49: Waiting for connection (waiting 1 msec)... 1.249838 on 49: Connection made 1.249895 SEND on 49: '[1,"!crash!"]' 1.249952 on 49: Reading JSON 1.249962 : looking for messages on channels 1.249971 on 49: Waiting for up to 2000 msec 1.251163 ERR on 49: channel_read_json_block(): Cannot read from channel 1.251178 on 49: Closing channel 1.251207 : looking for messages on channels 1.263173 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.263184 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.263237 on 49: Closing channel 1.263245 on 49: Clearing channel 1.263252 on 49: Freeing channel 1.263316 on 48: Stopping job with '' 1.263344 on 48: detaching channel from job 1.263352 on 48: Closing channel 1.263368 on 48: Clearing channel 1.263375 on 48: Freeing channel 1.263626 : Test_two_channels() 1.263699 : Starting job: python test_channel.py 1.263722 on 50: Created channel 1.278708 : looking for messages on channels 1.340550 on 51: Created channel 1.341111 on 51: Connecting to localhost port 59086 1.341555 on 51: Waiting for connection (waiting 1 msec)... 1.341578 on 51: Connection made 1.341633 SEND on 51: '[1,"hello!"]' 1.341691 on 51: Reading JSON 1.341701 : looking for messages on channels 1.341710 on 51: Waiting for up to 2000 msec 1.342918 RECV on 51: '[1, "got it"]' 1.342934 on 51: Getting JSON message 1 1.342986 on 52: Created channel 1.343564 on 52: Connecting to localhost port 59086 1.343651 on 52: Waiting for connection (waiting 1 msec)... 1.343790 on 52: Connection made 1.343867 SEND on 52: '[1,"hello!"]' 1.343929 on 52: Reading JSON 1.343940 : looking for messages on channels 1.343949 on 52: Waiting for up to 2000 msec 1.344337 RECV on 52: '[1, "got it"]' 1.344346 on 52: Getting JSON message 1 1.344376 SEND on 51: '[2,"hello!"]' 1.344401 on 51: Reading JSON 1.344409 : looking for messages on channels 1.344438 on 51: Waiting for up to 2000 msec 1.344552 RECV on 51: '[2, "got it"]' 1.344558 on 51: Getting JSON message 2 1.344579 on 51: Closing channel 1.344607 on 51: Clearing channel 1.344663 SEND on 52: '[2,"hello!"]' 1.344766 on 52: Reading JSON 1.344777 : looking for messages on channels 1.344784 on 52: Waiting for up to 2000 msec 1.344874 RECV on 52: '[2, "got it"]' 1.344881 on 52: Getting JSON message 2 1.344901 on 52: Closing channel 1.344928 on 52: Clearing channel 1.344973 on 52: Closing channel 1.345024 on 52: Clearing channel 1.345033 on 52: Freeing channel 1.345042 on 51: Closing channel 1.345048 on 51: Clearing channel 1.345055 on 51: Freeing channel 1.345105 on 50: Stopping job with '' 1.345131 on 50: detaching channel from job 1.345139 on 50: Closing channel 1.345156 on 50: Clearing channel 1.345163 on 50: Freeing channel 1.345365 : Test_unlet_handle() 1.345446 : Starting job: python test_channel.py 1.345468 on 53: Created channel 1.360305 : looking for messages on channels 1.415489 on 54: Created channel 1.415964 on 54: Connecting to localhost port 59089 1.416046 on 54: Waiting for connection (waiting 1 msec)... 1.416144 on 54: Connection made 1.416163 on 9: Closing channel 1.416171 on 9: Clearing channel 1.416178 on 9: Freeing channel 1.416212 SEND on 54: '[1,"test"]' 1.416349 on 53: Stopping job with '' 1.416375 on 53: detaching channel from job 1.416383 on 53: Closing channel 1.416400 on 53: Clearing channel 1.416407 on 53: Freeing channel 1.416729 : Starting job: ls 1.416755 on 55: Created channel 1.429254 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.429357 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.429364 ERR on 55: channel_select_check(): Cannot read from channel 1.429383 PUT on 55: 'DETACH ' 1.429386 on 55: Closing channel 1.429408 ERR on 54: channel_select_check(): Cannot read from channel 1.429416 on 54: Closing channel 1.429497 : looking for messages on channels 1.429510 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.429536 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.429552 on 55: Dropping message 'DETACH ' 1.429612 on 25: Closing channel 1.429621 on 25: Clearing channel 1.429638 on 25: Freeing channel 1.429848 : Test_zero_reply() 1.429937 : Starting job: python test_channel.py 1.429964 on 56: Created channel 1.442224 : looking for messages on channels 1.500859 on 57: Created channel 1.501335 on 57: Connecting to localhost port 59091 1.501416 on 57: Waiting for connection (waiting 1 msec)... 1.501510 on 57: Connection made 1.501561 SEND on 57: '[1,"hello!"]' 1.501588 on 57: Reading JSON 1.501597 : looking for messages on channels 1.501604 on 57: Waiting for up to 2000 msec 1.502562 RECV on 57: '[1, "got it"]' 1.502577 on 57: Getting JSON message 1 1.502692 SEND on 57: '[2,"send zero"]' 1.502756 on 57: Reading JSON 1.502767 : looking for messages on channels 1.502775 on 57: Waiting for up to 2000 msec 1.503021 RECV on 57: '[0,"zero index"][2, "sent zero"]' 1.503029 on 57: Getting JSON message 2 1.515731 : looking for messages on channels 1.515755 on 57: Getting JSON message 0 1.515764 on 57: Invoking channel callback s:ChHandler 1.515897 SEND on 57: '[3,"send zero"]' 1.528422 RECV on 57: '[0,"zero index"][3, "sent zero"]' 1.528428 : looking for messages on channels 1.528443 on 57: Getting JSON message 0 1.528451 on 57: Invoking channel callback s:ChHandler 1.528480 on 57: Getting JSON message 3 1.528488 on 57: Invoking one-time callback s:OneHandler 1.528594 on 56: Stopping job with '' 1.528619 on 56: detaching channel from job 1.528627 on 56: Closing channel 1.528645 on 56: Clearing channel 1.528652 on 56: Freeing channel 1.528763 : Starting job: python test_channel.py 1.528785 on 58: Created channel 1.541766 ERR on 57: channel_select_check(): Cannot read from channel 1.541794 on 57: Closing channel 1.541805 : looking for messages on channels 1.541812 on 57: Closing channel 1.541818 on 57: Clearing channel 1.541829 on 57: Freeing channel 1.552566 : looking for messages on channels 1.596625 on 59: Created channel 1.597125 on 59: Connecting to localhost port 59093 1.597207 on 59: Waiting for connection (waiting 1 msec)... 1.597302 on 59: Connection made 1.597355 SEND on 59: '[1,"hello!"]' 1.597382 on 59: Reading JSON 1.597390 : looking for messages on channels 1.597398 on 59: Waiting for up to 2000 msec 1.598041 RECV on 59: '[1, "got it"]' 1.598051 on 59: Getting JSON message 1 1.598099 SEND on 59: '[2,"send zero"]' 1.598123 on 59: Reading JSON 1.598132 : looking for messages on channels 1.598139 on 59: Waiting for up to 2000 msec 1.598270 RECV on 59: '[0,"zero index"]' 1.598277 : looking for messages on channels 1.598287 on 59: Getting JSON message 0 1.598294 on 59: Dropping message 1.598303 : looking for messages on channels 1.598310 on 59: Waiting for up to 2000 msec 1.598324 RECV on 59: '[2, "sent zero"]' 1.598329 on 59: Getting JSON message 2 1.618775 : looking for messages on channels 1.618886 SEND on 59: '[3,"send zero"]' 1.631566 RECV on 59: '[0,"zero index"][3, "sent zero"]' 1.631571 : looking for messages on channels 1.631586 on 59: Getting JSON message 0 1.631594 on 59: Dropping message 1.631605 on 59: Getting JSON message 3 1.631612 on 59: Invoking one-time callback s:OneHandler 1.631701 on 59: Closing channel 1.631731 on 59: Clearing channel 1.631740 on 59: Freeing channel 1.631781 on 58: Stopping job with '' 1.631805 on 58: detaching channel from job 1.631812 on 58: Closing channel 1.631881 on 58: Clearing channel 1.631892 on 58: Freeing channel