==== start log session ====
  0.001208 : Test_call()
  0.001347 : Starting job: python  test_channel.py
  0.001387 on 0: Created channel
  0.014860 : looking for messages on channels
  0.078204 on 1: Created channel
  0.079180 on 1: Connecting to localhost port 54482
  0.079671 on 1: Waiting for connection (waiting 1 msec)...
  0.079703 on 1: Connection made
  0.079777 SEND on 1: '[1,"call-func"]'
  0.079844 on 1: Reading JSON
  0.079855 : looking for messages on channels
  0.079863 on 1: Waiting for up to 2000 msec
  0.080816 RECV on 1: '["call","MyFunction",[1,2,3], 0][1, "ok"]'
  0.080833 on 1: Getting JSON message 1
  0.092424 : looking for messages on channels
  0.092495 on 1: Calling 'MyFunction'
  0.092635 SEND on 1: '[0,0]'
  0.093033 on 1: Closing channel
  0.093257 on 1: Clearing channel
  0.093275 on 1: Freeing channel
  0.093341 on 0: Stopping job with ''
  0.093389 on 0: detaching channel from job
  0.093401 on 0: Closing channel
  0.093426 on 0: Clearing channel
  0.093436 on 0: Freeing channel
  0.093779 : Test_channel_handler()
  0.093888 : Starting job: python  test_channel.py
  0.093922 on 2: Created channel
  0.110416 : looking for messages on channels
  0.168568 on 3: Created channel
  0.169153 on 3: Connecting to localhost port 54484
  0.169240 on 3: Waiting for connection (waiting 1 msec)...
  0.169406 on 3: Connection made
  0.169472 SEND on 3: '[1,"call me"]'
  0.169532 on 3: Reading JSON
  0.169543 : looking for messages on channels
  0.169551 on 3: Waiting for up to 2000 msec
  0.170027 RECV on 3: '[0,"we called you"]'
  0.170038 : looking for messages on channels
  0.170051 on 3: Getting JSON message 0
  0.170059 on 3: Invoking channel callback s:Handler
  0.170109 : looking for messages on channels
  0.170117 on 3: Waiting for up to 2000 msec
  0.170133 RECV on 3: '[1, "ok"]'
  0.170138 on 3: Getting JSON message 1
  0.170230 SEND on 3: '[2,"call me again"]'
  0.181014 RECV on 3: '[0,"we did call you"]'
  0.181044 : looking for messages on channels
  0.181123 on 3: Getting JSON message 0
  0.181157 on 3: Invoking channel callback s:Handler
  0.181544 on 2: Stopping job with ''
  0.181667 on 2: detaching channel from job
  0.181703 on 2: Closing channel
  0.181756 on 2: Clearing channel
  0.181777 on 2: Freeing channel
  0.182154 : Starting job: python  test_channel.py
  0.182227 on 4: Created channel
  0.194480 ERR on 3: channel_select_check(): Cannot read from channel
  0.194514 on 3: Closing channel
  0.194525 : looking for messages on channels
  0.194534 on 3: Closing channel
  0.194541 on 3: Clearing channel
  0.194552 on 3: Freeing channel
  0.207182 : looking for messages on channels
  0.253904 on 5: Created channel
  0.254425 on 5: Connecting to localhost port 54486
  0.254509 on 5: Waiting for connection (waiting 1 msec)...
  0.254648 on 5: Connection made
  0.254707 SEND on 5: '[1,"call me"]'
  0.254764 on 5: Reading JSON
  0.254775 : looking for messages on channels
  0.254783 on 5: Waiting for up to 2000 msec
  0.255292 RECV on 5: '[0,"we called you"]'
  0.255301 : looking for messages on channels
  0.255312 on 5: Getting JSON message 0
  0.255320 on 5: Invoking channel callback <SNR>3_Handler
  0.255362 : looking for messages on channels
  0.255370 on 5: Waiting for up to 2000 msec
  0.255386 RECV on 5: '[1, "ok"]'
  0.255391 on 5: Getting JSON message 1
  0.255482 SEND on 5: '[2,"call me again"]'
  0.266950 RECV on 5: '[0,"we did call you"]'
  0.266969 : looking for messages on channels
  0.267023 on 5: Getting JSON message 0
  0.267047 on 5: Invoking channel callback <SNR>3_Handler
  0.267388 on 4: Stopping job with ''
  0.267457 on 4: detaching channel from job
  0.267481 on 4: Closing channel
  0.267531 on 4: Clearing channel
  0.267551 on 4: Freeing channel
  0.268242 : Test_close_callback()
  0.268353 : Starting job: python  test_channel.py
  0.268388 on 6: Created channel
  0.280481 ERR on 5: channel_select_check(): Cannot read from channel
  0.280510 on 5: Closing channel
  0.280519 : looking for messages on channels
  0.280527 on 5: Closing channel
  0.280533 on 5: Clearing channel
  0.280570 on 5: Freeing channel
  0.293313 : looking for messages on channels
  0.341083 on 7: Created channel
  0.341578 on 7: Connecting to localhost port 54488
  0.341659 on 7: Waiting for connection (waiting 1 msec)...
  0.341775 on 7: Connection made
  0.341834 SEND on 7: '[1,"close me"]'
  0.341861 on 7: Reading JSON
  0.341870 : looking for messages on channels
  0.341877 on 7: Waiting for up to 2000 msec
  0.342409 ERR on 7: channel_read_json_block(): Cannot read from channel
  0.342423 on 7: Closing channel
  0.342447 on 7: Invoking close callback MyCloseCb
  0.342486 : looking for messages on channels
  0.342565 on 7: Closing channel
  0.342573 on 7: Clearing channel
  0.342580 on 7: Freeing channel
  0.342618 on 6: Stopping job with ''
  0.342643 on 6: detaching channel from job
  0.342651 on 6: Closing channel
  0.342670 on 6: Clearing channel
  0.342678 on 6: Freeing channel
  0.342894 : Test_close_handle()
  0.342971 : Starting job: python  test_channel.py
  0.342996 on 8: Created channel
  0.354445 : looking for messages on channels
  0.416438 on 9: Created channel
  0.416944 on 9: Connecting to localhost port 54490
  0.417027 on 9: Waiting for connection (waiting 1 msec)...
  0.417153 on 9: Connection made
  0.417208 SEND on 9: '[1,"test"]'
  0.430031 RECV on 9: '[1, "what?"]'
  0.430057 : looking for messages on channels
  0.430120 on 9: Getting JSON message 1
  0.430145 on 9: Invoking one-time callback <SNR>3_CloseHandler
  0.430250 on 9: Closing channel
  0.430396 on 9: Clearing channel
  0.430704 on 8: Stopping job with ''
  0.430778 on 8: detaching channel from job
  0.430802 on 8: Closing channel
  0.431011 on 8: Clearing channel
  0.431042 on 8: Freeing channel
  0.431504 : Test_close_partial()
  0.431619 : Starting job: python  test_channel.py
  0.431654 on 10: Created channel
  0.443771 : looking for messages on channels
  0.507590 on 11: Created channel
  0.508116 on 11: Connecting to localhost port 54492
  0.508200 on 11: Waiting for connection (waiting 1 msec)...
  0.508327 on 11: Connection made
  0.508442 SEND on 11: '[1,"close me"]'
  0.508472 on 11: Reading JSON
  0.508481 : looking for messages on channels
  0.508489 on 11: Waiting for up to 2000 msec
  0.508975 ERR on 11: channel_read_json_block(): Cannot read from channel
  0.508990 on 11: Closing channel
  0.509019 on 11: Invoking close callback 1
  0.509053 : looking for messages on channels
  0.509137 on 11: Closing channel
  0.509146 on 11: Clearing channel
  0.509153 on 11: Freeing channel
  0.509191 on 10: Stopping job with ''
  0.509216 on 10: detaching channel from job
  0.509224 on 10: Closing channel
  0.509241 on 10: Clearing channel
  0.509250 on 10: Freeing channel
  0.509442 : Test_communicate()
  0.509523 : Starting job: python  test_channel.py
  0.509546 on 12: Created channel
  0.521912 : looking for messages on channels
  0.579926 on 13: Created channel
  0.580450 on 13: Connecting to localhost port 54494
  0.580535 on 13: Waiting for connection (waiting 1 msec)...
  0.580675 on 13: Connection made
  0.580801 SEND on 13: '[1,"hello!"]'
  0.580860 on 13: Reading JSON
  0.580872 : looking for messages on channels
  0.580879 on 13: Waiting for up to 2000 msec
  0.581312 RECV on 13: '[1, "got it"]'
  0.581321 on 13: Getting JSON message 1
  0.581357 SEND on 13: '[2,"malformed1"]'
  0.581387 on 13: Reading JSON
  0.581395 : looking for messages on channels
  0.581402 on 13: Waiting for up to 2000 msec
  0.581556 RECV on 13: '["ex",":"]wrong!["ex","smi"]'
  0.581578 ERR on 13: Decoding failed - discarding input
  0.581589 : looking for messages on channels
  0.581597 on 13: Executing ex command ':'
  0.581608 : looking for messages on channels
  0.581615 on 13: Waiting for up to 2000 msec
  0.581631 RECV on 13: '[2, "ok"]'
  0.581636 on 13: Getting JSON message 2
  0.581659 SEND on 13: '[3,"malformed2"]'
  0.581682 on 13: Reading JSON
  0.581690 : looking for messages on channels
  0.581697 on 13: Waiting for up to 2000 msec
  0.581826 RECV on 13: '"unterminated string'
  0.581831 on 13: Incomplete message - wait for more
  0.581861 : looking for messages on channels
  0.581870 on 13: still waiting on incomplete message
  0.581878 on 13: Waiting for up to 100 msec
  0.683271 ERR on 13: Decoding failed - discarding input
  0.683348 : looking for messages on channels
  0.683373 on 13: Waiting for up to 2000 msec
  0.785059 RECV on 13: '[3, "ok"]'
  0.785101 on 13: Getting JSON message 3
  0.785253 SEND on 13: '[4,"malformed3"]'
  0.785328 on 13: Reading JSON
  0.785353 : looking for messages on channels
  0.785376 on 13: Waiting for up to 2000 msec
  0.785829 RECV on 13: '["ex","missing ]"'
  0.785848 on 13: Incomplete message - wait for more
  0.785875 : looking for messages on channels
  0.785902 on 13: still waiting on incomplete message
  0.785925 on 13: Waiting for up to 100 msec
  0.891002 ERR on 13: Decoding failed - discarding input
  0.891085 : looking for messages on channels
  0.891113 on 13: Waiting for up to 2000 msec
  0.986917 RECV on 13: '[4, "ok"]'
  0.986957 on 13: Getting JSON message 4
  0.987109 SEND on 13: '[5,"split"]'
  0.987184 on 13: Reading JSON
  0.987209 : looking for messages on channels
  0.987231 on 13: Waiting for up to 2000 msec
  0.987686 RECV on 13: '["ex","let '
  0.987707 on 13: Incomplete message - wait for more
  0.987739 : looking for messages on channels
  0.987766 on 13: still waiting on incomplete message
  0.987790 on 13: Waiting for up to 100 msec
  0.999921 RECV on 13: 'g:split = 123"]'
  0.999959 : looking for messages on channels
  1.000018 on 13: Executing ex command 'let g:split = 123'
  1.000113 : looking for messages on channels
  1.000137 on 13: Waiting for up to 2000 msec
  1.000180 RECV on 13: '[5, "ok"]'
  1.000194 on 13: Getting JSON message 5
  1.000481 SEND on 13: '[6,"make change"]'
  1.000556 on 13: Reading JSON
  1.000581 : looking for messages on channels
  1.000601 on 13: Waiting for up to 2000 msec
  1.001071 RECV on 13: '["ex","call append(\"$\",\"added1\")"]["ex","call append(\"$\",\"added2\")"][6, "ok"]'
  1.001118 on 13: Getting JSON message 6
  1.014060 : looking for messages on channels
  1.014146 on 13: Executing ex command 'call append("$","added1")'
  1.014582 on 13: Executing ex command 'call append("$","added2")'
  1.014935 SEND on 13: '[7,"bad command"]'
  1.015138 on 13: Reading JSON
  1.015179 : looking for messages on channels
  1.015200 on 13: Waiting for up to 2000 msec
  1.015532 RECV on 13: '["ex","foo bar"]'
  1.015545 : looking for messages on channels
  1.015562 on 13: Executing ex command 'foo bar'
  1.015627 on 13: Ex command error: 'E492: Not an editor command: foo bar'
  1.015642 : looking for messages on channels
  1.015652 on 13: Waiting for up to 2000 msec
  1.015674 RECV on 13: '[7, "ok"]'
  1.015682 on 13: Getting JSON message 7
  1.015933 SEND on 13: '[8,"do normal"]'
  1.016038 on 13: Reading JSON
  1.016053 : looking for messages on channels
  1.016063 on 13: Waiting for up to 100 msec
  1.016257 RECV on 13: '["normal","G$s more\u001b"]'
  1.016269 : looking for messages on channels
  1.016283 on 13: Executing normal command 'G$s more'
  1.016646 : looking for messages on channels
  1.016659 on 13: Waiting for up to 100 msec
  1.016680 RECV on 13: '[8, "ok"]'
  1.016686 on 13: Getting JSON message 8
  1.016805 SEND on 13: '[9,"hello!"]'
  1.029397 RECV on 13: '[9, "got it"]'
  1.029433 : looking for messages on channels
  1.029521 on 13: Getting JSON message 9
  1.029546 on 13: Invoking one-time callback s:RequestHandler
  1.029978 SEND on 13: '[10,"hello!"]'
  1.042398 RECV on 13: '[10, "got it"]'
  1.042420 : looking for messages on channels
  1.042497 on 13: Getting JSON message 10
  1.042523 on 13: Invoking one-time callback <SNR>3_RequestHandler
  1.043104 SEND on 13: '[11,"eval-works"]'
  1.043239 on 13: Reading JSON
  1.043266 : looking for messages on channels
  1.043288 on 13: Waiting for up to 1111 msec
  1.043900 RECV on 13: '["expr","\"foo\" . 123", -1][11, "ok"]'
  1.043917 on 13: Getting JSON message 11
  1.054615 : looking for messages on channels
  1.054673 on 13: Evaluating expression '"foo" . 123'
  1.054718 SEND on 13: '[-1,"foo123"]'
  1.054903 SEND on 13: '[12,"eval-result"]'
  1.055034 on 13: Reading JSON
  1.055049 : looking for messages on channels
  1.055058 on 13: Waiting for up to 1111 msec
  1.055448 RECV on 13: '[12, [-1, "foo123"]]'
  1.055460 on 13: Getting JSON message 12
  1.055505 SEND on 13: '[13,"eval-special"]'
  1.055534 on 13: Reading JSON
  1.055545 : looking for messages on channels
  1.055554 on 13: Waiting for up to 1111 msec
  1.055752 RECV on 13: '["expr","\"foo
bar\"", -2][13, "ok"]'
  1.055763 on 13: Getting JSON message 13
  1.067018 : looking for messages on channels
  1.067093 on 13: Evaluating expression '"foo
bar"'
  1.067155 SEND on 13: '[-2,"foo\u0010\u0001bar"]'
  1.067369 SEND on 13: '[14,"eval-result"]'
  1.067450 on 13: Reading JSON
  1.067466 : looking for messages on channels
  1.067477 on 13: Waiting for up to 1111 msec
  1.067836 RECV on 13: '[14, [-2, "foo\u007f\u0010\u0001bar"]]'
  1.067851 on 13: Getting JSON message 14
  1.068075 SEND on 13: '[15,"eval-getline"]'
  1.068121 on 13: Reading JSON
  1.068134 : looking for messages on channels
  1.068161 on 13: Waiting for up to 1111 msec
  1.068380 RECV on 13: '["expr","getline(3)", -3]'
  1.068401 : looking for messages on channels
  1.068414 on 13: Evaluating expression 'getline(3)'
  1.068437 SEND on 13: '[-3,"a\nb\rc\u0001de"]'
  1.068469 : looking for messages on channels
  1.068479 on 13: Waiting for up to 1111 msec
  1.068499 RECV on 13: '[15, "ok"]'
  1.068506 on 13: Getting JSON message 15
  1.081144 : looking for messages on channels
  1.081262 SEND on 13: '[16,"eval-result"]'
  1.081371 on 13: Reading JSON
  1.081397 : looking for messages on channels
  1.081417 on 13: Waiting for up to 1111 msec
  1.081955 RECV on 13: '[16, [-3, "a\nb\rc\u0001d\u007fe"]]'
  1.081980 on 13: Getting JSON message 16
  1.082069 SEND on 13: '[17,"eval-fails"]'
  1.082140 on 13: Reading JSON
  1.082165 : looking for messages on channels
  1.082185 on 13: Waiting for up to 1111 msec
  1.082777 RECV on 13: '["expr","xxx", -4][17, "ok"]'
  1.082804 on 13: Getting JSON message 17
  1.095602 : looking for messages on channels
  1.095687 on 13: Evaluating expression 'xxx'
  1.095755 SEND on 13: '[-4,"ERROR"]'
  1.096015 SEND on 13: '[18,"eval-result"]'
  1.096202 on 13: Reading JSON
  1.096235 : looking for messages on channels
  1.096256 on 13: Waiting for up to 1111 msec
  1.096747 RECV on 13: '[18, [-4, "ERROR"]]'
  1.096770 on 13: Getting JSON message 18
  1.096855 SEND on 13: '[19,"eval-error"]'
  1.096922 on 13: Reading JSON
  1.096946 : looking for messages on channels
  1.096966 on 13: Waiting for up to 1111 msec
  1.097387 RECV on 13: '["expr","function(\"tr\")", -5][19, "ok"]'
  1.097413 on 13: Getting JSON message 19
  1.109476 : looking for messages on channels
  1.109632 on 13: Evaluating expression 'function("tr")'
  1.109768 SEND on 13: '[-5,"ERROR"]'
  1.110138 SEND on 13: '[20,"eval-result"]'
  1.110461 on 13: Reading JSON
  1.110495 : looking for messages on channels
  1.110516 on 13: Waiting for up to 1111 msec
  1.111036 RECV on 13: '[20, [-5, "ERROR"]]'
  1.111048 on 13: Getting JSON message 20
  1.111098 SEND on 13: '[21,"eval-bad"]'
  1.111185 on 13: Reading JSON
  1.111200 : looking for messages on channels
  1.111210 on 13: Waiting for up to 1111 msec
  1.111523 RECV on 13: '["expr","xxx"][21, "ok"]'
  1.111536 on 13: Getting JSON message 21
  1.124019 : looking for messages on channels
  1.124046 on 13: Evaluating expression 'xxx'
  1.124089 SEND on 13: '[22,"eval-result"]'
  1.124179 on 13: Reading JSON
  1.124189 : looking for messages on channels
  1.124196 on 13: Waiting for up to 1111 msec
  1.124427 RECV on 13: '[22, [-5, "ERROR"]]'
  1.124435 on 13: Getting JSON message 22
  1.124466 SEND on 13: '[23,"an expr"]'
  1.124524 on 13: Reading JSON
  1.124533 : looking for messages on channels
  1.124540 on 13: Waiting for up to 1111 msec
  1.124750 RECV on 13: '["expr","setline(\"$\", [\"one\",\"two\",\"three\"])"][23, "ok"]'
  1.124760 on 13: Getting JSON message 23
  1.136663 : looking for messages on channels
  1.136704 on 13: Evaluating expression 'setline("$", ["one","two","three"])'
  1.136899 SEND on 13: '[24,"redraw"]'
  1.136983 on 13: Reading JSON
  1.137003 : looking for messages on channels
  1.137011 on 13: Waiting for up to 1111 msec
  1.137274 RECV on 13: '["redraw",""]'
  1.137285 : looking for messages on channels
  1.137298 on 13: redraw
  1.138452 : looking for messages on channels
  1.138471 on 13: Waiting for up to 1111 msec
  1.138489 RECV on 13: '[24, "ok"]'
  1.138495 on 13: Getting JSON message 24
  1.138534 SEND on 13: '[25,"redraw!"]'
  1.138571 on 13: Reading JSON
  1.138579 : looking for messages on channels
  1.138586 on 13: Waiting for up to 1111 msec
  1.138821 RECV on 13: '["redraw","force"][25, "ok"]'
  1.138830 on 13: Getting JSON message 25
  1.138859 SEND on 13: '[26,"empty-request"]'
  1.138883 on 13: Reading JSON
  1.138891 : looking for messages on channels
  1.138900 on 13: redraw
  1.139572 : looking for messages on channels
  1.139584 on 13: Waiting for up to 1111 msec
  1.139601 RECV on 13: '[][26, "ok"]'
  1.139604 ERR on 13: Expected list with two items, got 0
  1.139615 on 13: Getting JSON message 26
  1.139641 on 13: Reading JSON
  1.139649 : looking for messages on channels
  1.139659 on 13: Timed out
  1.139684 on 13: Reading JSON
  1.139692 : looking for messages on channels
  1.139699 on 13: Waiting for up to 333 msec
  1.477735 on 13: Timed out
  1.478099 SEND on 13: '[27,"wait a bit"]'
  1.478340 on 13: Reading JSON
  1.478386 : looking for messages on channels
  1.478409 on 13: Waiting for up to 1111 msec
  1.684365 RECV on 13: '[27, "waited"]'
  1.684406 on 13: Getting JSON message 27
  1.684647 SEND on 13: '[28,"!quit!"]'
  1.684739 on 13: Closing channel
  1.685019 on 13: Clearing channel
  1.685064 on 13: Freeing channel
  1.685225 on 12: Stopping job with ''
  1.685301 on 12: detaching channel from job
  1.685325 on 12: Closing channel
  1.685372 on 12: Clearing channel
  1.685393 on 12: Freeing channel
  1.685807 : Test_connect_waittime()
  1.685840 on 14: Created channel
  1.687139 on 14: Connecting to localhost port 9876
  1.687311 on 14: Waiting for connection (waiting 1 msec)...
  1.687336 ERR on 14: Connection timed out
  1.687351 on 14: Closing channel
  1.687360 on 14: Clearing channel
  1.687369 on 14: Freeing channel
  1.687459 on 15: Created channel
  1.688599 on 15: Connecting to localhost port 9867
  1.688803 on 15: Waiting for connection (waiting 50 msec)...
  1.740783 on 15: Connecting to localhost port 9867
  1.741026 on 15: Waiting for connection (waiting 50 msec)...
  1.796551 on 15: Connecting to localhost port 9867
  1.796813 on 15: Waiting for connection (waiting 50 msec)...
  1.852326 on 15: Connecting to localhost port 9867
  1.852562 on 15: Waiting for connection (waiting 50 msec)...
  1.904803 on 15: Connecting to localhost port 9867
  1.904942 on 15: Waiting for connection (waiting 50 msec)...
  1.957049 on 15: Connecting to localhost port 9867
  1.957317 on 15: Waiting for connection (waiting 50 msec)...
  2.009510 on 15: Connecting to localhost port 9867
  2.009770 on 15: Waiting for connection (waiting 50 msec)...
  2.062941 on 15: Connecting to localhost port 9867
  2.063187 on 15: Waiting for connection (waiting 50 msec)...
  2.118620 on 15: Connecting to localhost port 9867
  2.118855 on 15: Waiting for connection (waiting 50 msec)...
  2.173373 on 15: Connecting to localhost port 9867
  2.173635 on 15: Waiting for connection (waiting 50 msec)...
  2.227429 on 15: Connecting to localhost port 9867
  2.227788 on 15: Waiting for connection (waiting 1 msec)...
  2.227881 ERR on 15: Connection timed out
  2.227927 on 15: Closing channel
  2.227976 on 15: Clearing channel
  2.227999 on 15: Freeing channel
  2.228413 : Test_exit_callback()
  2.228520 : Starting job: python  test_channel.py
  2.228556 on 16: Created channel
  2.240708 : looking for messages on channels
  2.300871 on 16: Stopping job with ''
  2.313605 ERR on 16: channel_select_check(): Cannot read from channel
  2.313660 PUT on 16: 'DETACH
'
  2.313662 on 16: Closing channel
  2.313680 : looking for messages on channels
  2.313718 on 16: Dropping message 'DETACH
'
  2.313762 on 16: Job ended
  2.313854 on 16: Freeing job
  2.313862 on 16: Closing channel
  2.313868 on 16: Clearing channel
  2.313875 on 16: Freeing channel
  2.314070 : Freeing job
  2.314094 : Freeing job