Fix tests on Travis #347

blueyed · 2018-07-14T19:21:49Z

No description provided.

blueyed · 2018-07-14T19:31:56Z

Can somebody please stop the jobs at https://travis-ci.org/neovim/python-client/builds/403972108 ?

Would be good if I could do this in the future myself, but as for this PR I am only running one job from now on, so it should be fine then.

blueyed · 2018-07-14T19:53:47Z

The problem is test_async_call.

The log:

@ msgpack_stream.py:send:34] 21779 - sent [2, 'nvim_call_function', ('rpcrequest', [1, 'test-event'])]
@ base.py:send:117] 21779 - Sending 'b'\x93\x02\xb2nvim_call_function\x92\xaarpcrequest\x92\x01\xaatest-event''
@ base.py:run:142] 21779 - Entering event loop
@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:61] 21779 - received message: [0, 1, b'test-event', []]
@ async_session.py:_on_request:91] 21779 - received request: b'test-event', []
@ session.py:_on_request:207] 21779 - received rpc request, greenlet <greenlet.greenlet object at 0x7f133a0af898> will handle it
@ msgpack_stream.py:send:34] 21779 - sent [0, 7, 'nvim_set_var', ('result', 17)]
@ base.py:send:117] 21779 - Sending 'b'\x94\x00\x07\xacnvim_set_var\x92\xa6result\x11''
@ session.py:_yielding_request:159] 21779 - yielding from greenlet <greenlet.greenlet object at 0x7f133a0af898> to wait for response
@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:64] 21779 - unpacker needs more data...
@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:61] 21779 - received message: [1, 7, None, None]
@ async_session.py:_on_response:100] 21779 - received response: None, None
@ session.py:response_cb:155] 21779 - response is available for greenlet <greenlet.greenlet object at 0x7f133a0af898>, switching back
@ base.py:stop:153] 21779 - Stopped event loop
@ session.py:handler:193] 21779 - greenlet <greenlet.greenlet object at 0x7f133a0af898> finished executing, sending None as response
@ async_session.py:send:138] 21779 - sending response to request 1: [1, 1, None, None]
@ msgpack_stream.py:send:34] 21779 - sent [1, 1, None, None]
@ base.py:send:117] 21779 - Sending 'b'\x94\x01\x01\xc0\xc0''
@ session.py:handler:203] 21779 - greenlet <greenlet.greenlet object at 0x7f133a0af898> is now dying...
@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:64] 21779 - unpacker needs more data...
@ base.py:run:144] 21779 - Exited event loop
@ msgpack_stream.py:send:34] 21779 - sent [0, 8, 'nvim_get_var', ('result',)]
@ base.py:send:117] 21779 - Sending 'b'\x94\x00\x08\xacnvim_get_var\x91\xa6result''
@ base.py:run:142] 21779 - Entering event loop

Running it locally adds the following at the end, which is missing on Travis:

@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:61] 21779 - received message: [1, 8, None, 17]
@ async_session.py:_on_response:100] 21779 - received response: None, 17
@ base.py:stop:153] 21779 - Stopped event loop
@ msgpack_stream.py:_on_data:59] 21779 - waiting for message...
@ msgpack_stream.py:_on_data:64] 21779 - unpacker needs more data...
@ base.py:run:144] 21779 - Exited event loop

It passed when adding logging the first time though:

test/test_client_rpc.py::test_async_call 2018-07-14 19:38:34,055 [DEBUG @ msgpack_stream.py:send:34] 1817 - sent [2, 'nvim_call_function', ('rpcrequest', [1, 'test-event'])]
2018-07-14 19:38:34,056 [DEBUG @ base.py:send:117] 1817 - Sending 'b'\x93\x02\xb2nvim_call_function\x92\xaarpcrequest\x92\x01\xaatest-event''
2018-07-14 19:38:34,056 [DEBUG @ base.py:run:142] 1817 - Entering event loop
2018-07-14 19:38:34,057 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,057 [DEBUG @ msgpack_stream.py:_on_data:61] 1817 - received message: [0, 1, b'test-event', []]
2018-07-14 19:38:34,057 [DEBUG @ async_session.py:_on_request:91] 1817 - received request: b'test-event', []
2018-07-14 19:38:34,057 [DEBUG @ session.py:_on_request:207] 1817 - received rpc request, greenlet <greenlet.greenlet object at 0x7ffa4ffa1f20> will handle it
2018-07-14 19:38:34,057 [DEBUG @ msgpack_stream.py:send:34] 1817 - sent [0, 7, 'nvim_set_var', ('result', 17)]
2018-07-14 19:38:34,057 [DEBUG @ base.py:send:117] 1817 - Sending 'b'\x94\x00\x07\xacnvim_set_var\x92\xa6result\x11''
2018-07-14 19:38:34,058 [DEBUG @ session.py:_yielding_request:159] 1817 - yielding from greenlet <greenlet.greenlet object at 0x7ffa4ffa1f20> to wait for response
2018-07-14 19:38:34,058 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,058 [DEBUG @ msgpack_stream.py:_on_data:64] 1817 - unpacker needs more data...
2018-07-14 19:38:34,058 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,058 [DEBUG @ msgpack_stream.py:_on_data:61] 1817 - received message: [1, 7, None, None]
2018-07-14 19:38:34,058 [DEBUG @ async_session.py:_on_response:100] 1817 - received response: None, None
2018-07-14 19:38:34,058 [DEBUG @ session.py:response_cb:155] 1817 - response is available for greenlet <greenlet.greenlet object at 0x7ffa4ffa1f20>, switching back
2018-07-14 19:38:34,059 [DEBUG @ base.py:stop:153] 1817 - Stopped event loop
2018-07-14 19:38:34,059 [DEBUG @ session.py:handler:193] 1817 - greenlet <greenlet.greenlet object at 0x7ffa4ffa1f20> finished executing, sending None as response
2018-07-14 19:38:34,059 [DEBUG @ async_session.py:send:138] 1817 - sending response to request 1: [1, 1, None, None]
2018-07-14 19:38:34,059 [DEBUG @ msgpack_stream.py:send:34] 1817 - sent [1, 1, None, None]
2018-07-14 19:38:34,059 [DEBUG @ base.py:send:117] 1817 - Sending 'b'\x94\x01\x01\xc0\xc0''
2018-07-14 19:38:34,059 [DEBUG @ session.py:handler:203] 1817 - greenlet <greenlet.greenlet object at 0x7ffa4ffa1f20> is now dying...
2018-07-14 19:38:34,059 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,060 [DEBUG @ msgpack_stream.py:_on_data:64] 1817 - unpacker needs more data...
2018-07-14 19:38:34,060 [DEBUG @ base.py:run:144] 1817 - Exited event loop
2018-07-14 19:38:34,060 [DEBUG @ msgpack_stream.py:send:34] 1817 - sent [0, 8, 'nvim_get_var', ('result',)]
2018-07-14 19:38:34,060 [DEBUG @ base.py:send:117] 1817 - Sending 'b'\x94\x00\x08\xacnvim_get_var\x91\xa6result''
2018-07-14 19:38:34,060 [DEBUG @ base.py:run:142] 1817 - Entering event loop
2018-07-14 19:38:34,061 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,061 [DEBUG @ msgpack_stream.py:_on_data:61] 1817 - received message: [1, 8, None, 17]
2018-07-14 19:38:34,061 [DEBUG @ async_session.py:_on_response:100] 1817 - received response: None, 17
2018-07-14 19:38:34,061 [DEBUG @ base.py:stop:153] 1817 - Stopped event loop
2018-07-14 19:38:34,061 [DEBUG @ msgpack_stream.py:_on_data:59] 1817 - waiting for message...
2018-07-14 19:38:34,061 [DEBUG @ msgpack_stream.py:_on_data:64] 1817 - unpacker needs more data...
2018-07-14 19:38:34,061 [DEBUG @ base.py:run:144] 1817 - Exited event loop
�[32mPASSED�[0m

https://travis-ci.org/neovim/python-client/jobs/403974893

So it is maybe only flaky and logging fixes it somehow?

blueyed · 2018-07-14T20:05:37Z

dead-locking is mentioned in the test: https://github.com/neovim/python-client/blob/ebeacd017abc195fd82cf00f0f85c3720b7713a6/test/test_client_rpc.py#L54 - but I do not know how it's meant. @bfredl

The last two jobs succeeded and failed, without code changes.
The last build has both a success and later a failure, so is good to investigate: https://travis-ci.org/neovim/python-client/builds/403978421.

Does c224007 (on top of the mentioned build) makes sense?

blueyed · 2018-07-14T20:11:52Z

Stopping here for now - somebody with more insight should take a look now :)

blueyed · 2018-07-15T16:06:53Z

Fixed by adding a sleep after vim.run_loop.

bfredl · 2018-07-17T08:46:23Z

.travis.yml

@@ -23,7 +24,7 @@ python:
 before_install:
  - if [ $CI_TARGET = tests ]; then
      eval "$(curl -Ss https://raw.githubusercontent.com/neovim/bot-ci/master/scripts/travis-setup.sh) nightly-x64";
-      pip install -q scrutinizer-ocular tox-travis;


What is this change for?

It is not really necessary, will remove it.

bfredl · 2018-07-17T08:49:39Z

test/test_client_rpc.py

@@ -41,6 +42,11 @@ def request_cb(name, args):
    # this would have dead-locked if not async
    vim.funcs.rpcrequest(vim.channel_id, "test-event", async_=True)
    vim.run_loop(request_cb, None, None)
+
+    # This sleep is required on Travis, where it hangs with


This shouldn't really be needed, but let's merge this for now. Let's mark it with TODO

justinmk · 2018-07-17T16:22:23Z

.travis.yml

@@ -6,6 +6,7 @@ env:
    - NOSE_VERBOSE=2
    - NOSE_WITH_COVERAGE=true
    - NOSE_COVER_PACKAGE=neovim


we don't use nose anymore, so we can remove these envs I guess?

Likely, yes. Should be a seperate PR then though.

bfredl · 2018-07-18T13:18:58Z

Very nice, thanks.

blueyed force-pushed the fix-tests branch from 0386f7a to 074d5a7 Compare July 15, 2018 16:04

blueyed changed the title ~~WIP: try to fix tests on Travis~~ [RFC] Fix tests on Travis Jul 15, 2018

blueyed force-pushed the fix-tests branch from 074d5a7 to 26eb7c6 Compare July 15, 2018 16:06

bfredl reviewed Jul 17, 2018

View reviewed changes

justinmk reviewed Jul 17, 2018

View reviewed changes

blueyed added 2 commits July 17, 2018 18:22

Fix tests on Travis (test_async_call)

40388f2

Use pytest-timeout to timeout tests after 10s

40f2d7d

blueyed force-pushed the fix-tests branch from 26eb7c6 to 40f2d7d Compare July 17, 2018 16:22

blueyed changed the title ~~[RFC] Fix tests on Travis~~ Fix tests on Travis Jul 17, 2018

bfredl merged commit 5072b7b into neovim:master Jul 18, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Fix tests on Travis #347

Fix tests on Travis #347

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 15, 2018

Uh oh!

bfredl Jul 17, 2018

Uh oh!

blueyed Jul 17, 2018

Uh oh!

bfredl Jul 17, 2018

Uh oh!

blueyed Jul 17, 2018

Uh oh!

justinmk Jul 17, 2018

Uh oh!

blueyed Jul 17, 2018

Uh oh!

bfredl commented Jul 18, 2018

Uh oh!

Uh oh!

Fix tests on Travis #347

Fix tests on Travis #347

Uh oh!

Conversation

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 14, 2018

Uh oh!

blueyed commented Jul 15, 2018

Uh oh!

bfredl Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

blueyed Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

bfredl Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

blueyed Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

justinmk Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

blueyed Jul 17, 2018

Choose a reason for hiding this comment

Uh oh!

bfredl commented Jul 18, 2018

Uh oh!

Uh oh!