New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rpc: close channel if stream was closed #7081

Merged
merged 3 commits into from Aug 26, 2017

Conversation

Projects
None yet
2 participants
@justinmk
Member

justinmk commented Jul 27, 2017

f_jobstop()/f_rpcstop() .. process_stop() .. process_close_in(proc)

closes the write-stream of a RPC channel. But there might be
a pending RPC notification on the queue, which may get processed just
before the channel is closed.

To handle that case, check the Stream.closed in
channel.c:receive_msgpack().

Before this change, the above scenario could trigger
this assert(!stream->closed) in wstream_write():

    0x00007f96e1cd3428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
    0x00007f96e1cd502a in __GI_abort () at abort.c:89
    0x00007f96e1ccbbd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x768f9b "!stream->closed",
    file=file@entry=0x768f70 "../src/nvim/event/wstream.c", line=line@entry=77,
    function=function@entry=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:92
    0x00007f96e1ccbc82 in __GI___assert_fail (assertion=0x768f9b "!stream->closed", file=0x768f70 "../src/nvim/event/wstream.c", line=77,
    function=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:101
    0x00000000004d2c1f in wstream_write (stream=0x7f96e0a35078, buffer=0x7f96e09f9b40) at ../src/nvim/event/wstream.c:77
    0x00000000005857b2 in channel_write (channel=0x7f96e0ae5800, buffer=0x7f96e09f9b40) at ../src/nvim/msgpack_rpc/channel.c:551
    0x000000000058567d in on_request_event (argv=0x7ffed792efa0) at ../src/nvim/msgpack_rpc/channel.c:523
    0x00000000005854c8 in handle_request (channel=0x7f96e0ae5800, request=0x7ffed792f1b8) at ../src/nvim/msgpack_rpc/channel.c:503
    0x00000000005850cb in parse_msgpack (channel=0x7f96e0ae5800) at ../src/nvim/msgpack_rpc/channel.c:423
    0x0000000000584f90 in receive_msgpack (stream=0x7f96e0a35218, rbuf=0x7f96e0d1d4c0, c=22, data=0x7f96e0ae5800, eof=false)
    at ../src/nvim/msgpack_rpc/channel.c:389
    0x00000000004d0b20 in read_event (argv=0x7ffed792f4a8) at ../src/nvim/event/rstream.c:190
    0x00000000004ce462 in multiqueue_process_events (this=0x7f96e18172d0) at ../src/nvim/event/multiqueue.c:150
    0x000000000059b630 in nv_event (cap=0x7ffed792f620) at ../src/nvim/normal.c:7908
    0x000000000058be69 in normal_execute (state=0x7ffed792f580, key=-25341) at ../src/nvim/normal.c:1137
    0x0000000000652463 in state_enter (s=0x7ffed792f580) at ../src/nvim/state.c:61
    0x000000000058a1fe in normal_enter (cmdwin=false, noexmode=false) at ../src/nvim/normal.c:467
    0x00000000005500c2 in main (argc=2, argv=0x7ffed792f8d8) at ../src/nvim/main.c:554

todo:

  • clean up test
@justinmk

This comment has been minimized.

Member

justinmk commented Jul 27, 2017

termclose_spec failure:

�[32m�[2m[ RUN      ]�[0m�[0m TermClose event kills pty job trapping SIGHUP and SIGTERM: �[1m�[35mFAIL�[0m�[0m
...neovim/neovim/test/functional/autocmd/termclose_spec.lua:60: Expected objects to be the same.
Passed in:
(number) 6
Expected:
(number) 4

stack traceback:
	...neovim/neovim/test/functional/autocmd/termclose_spec.lua:60: in function <...neovim/neovim/test/functional/autocmd/termclose_spec.lua:47>

�[32m�[2m[ RUN      ]�[0m�[0m TermClose event reports the correct <abuf>: �[2m13.08 ms�[0m �[1m�[32mOK�[0m�[0m
�[32m�[2m[----------]�[0m�[0m �[1m5�[0m tests from �[36m/home/travis/build/neovim/neovim/test/functional/autocmd/termclose_spec.lua�[0m �[2m(8320.45 ms total)�[0m

I'm a bit surprised that test has been reliable at all...

Update: same failure in an unrelated PR #6322 :

�[1m�[35m[  FAILED  ]�[0m�[0m �[1m1�[0m test, listed below:
�[1m�[35m[  FAILED  ]�[0m�[0m �[36m...neovim/neovim/test/functional/autocmd/termclose_spec.lua�[0m @ �[36m32�[0m: �[1mTermClose event kills job trapping SIGTERM�[0m
...neovim/neovim/test/functional/autocmd/termclose_spec.lua:44: Expected objects to be the same.
Passed in:
(number) 4
Expected:
(number) 2
@@ -0,0 +1,47 @@
local helpers = require('test.functional.helpers')(after_each)

This comment has been minimized.

@bfredl

bfredl Jul 27, 2017

Member

"Rpc spec" already exists, it is server_(requests|notifications)_spec

This comment has been minimized.

@justinmk

justinmk Jul 27, 2017

Member

@bfredl yes, but those are rather unusual in their approach (manually controlling the event loop). It can be disorienting for others when a group of tests is using many different techniques.

This comment has been minimized.

@bfredl

bfredl Jul 28, 2017

Member

The only thing "unusual" is possibly the split between files on requests vs notification does not fit all tests, it is possible it can be better organized. But arbitrarily adding some new tests in a third file will not help.

"Manually controlling the event loop" is not "unusual approach" and nothing you need to split a file on, it is something one just does in a test exactly whenever the test needs it.

This comment has been minimized.

@justinmk

justinmk Aug 19, 2017

Member

moved the test to server_requests_spec.lua

@bfredl

This comment has been minimized.

Member

bfredl commented Jul 27, 2017

Does the channels PR have the same issue?

goto end;
}
if ((chan_wstream(channel) != NULL && chan_wstream(channel)->closed)

This comment has been minimized.

@bfredl

bfredl Jul 27, 2017

Member

Can't we use close_cb of the streams?

@justinmk

This comment has been minimized.

Member

justinmk commented Aug 19, 2017

Can't we use close_cb of the streams?

@bfredl does 256e4f4 75fc12c look like what you had in mind? It doesn't pass the test, I'm guessing because close_cb is queued, which is the same problem.

@bfredl FWIW #6844 does pass the test. But I wonder, is that because the codepath of rpcstop() was changed? If so, it may only pass the test because the test I wrote depends on the current logic of rpcstop()--so the test doesn't reproduce the scenario, but the scenario could still happen if a process stream closes unexpectedly?

@bfredl

This comment has been minimized.

Member

bfredl commented Aug 19, 2017

@bfredl

This comment has been minimized.

Member

bfredl commented Aug 19, 2017

justinmk added some commits Jul 26, 2017

rpc: close channel if stream was closed
f_jobstop()/f_rpcstop() .. process_stop() .. process_close_in(proc)
closes the write-stream of a RPC channel. But there might be
a pending RPC notification on the queue, which may get processed just
before the channel is closed.

To handle that case, check the Stream.closed in
channel.c:receive_msgpack().

Before this change, the above scenario could trigger
this assert(!stream->closed) in wstream_write():

    0x00007f96e1cd3428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
    0x00007f96e1cd502a in __GI_abort () at abort.c:89
    0x00007f96e1ccbbd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x768f9b "!stream->closed",
    file=file@entry=0x768f70 "../src/nvim/event/wstream.c", line=line@entry=77,
    function=function@entry=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:92
    0x00007f96e1ccbc82 in __GI___assert_fail (assertion=0x768f9b "!stream->closed", file=0x768f70 "../src/nvim/event/wstream.c", line=77,
    function=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:101
    0x00000000004d2c1f in wstream_write (stream=0x7f96e0a35078, buffer=0x7f96e09f9b40) at ../src/nvim/event/wstream.c:77
    0x00000000005857b2 in channel_write (channel=0x7f96e0ae5800, buffer=0x7f96e09f9b40) at ../src/nvim/msgpack_rpc/channel.c:551
    0x000000000058567d in on_request_event (argv=0x7ffed792efa0) at ../src/nvim/msgpack_rpc/channel.c:523
    0x00000000005854c8 in handle_request (channel=0x7f96e0ae5800, request=0x7ffed792f1b8) at ../src/nvim/msgpack_rpc/channel.c:503
    0x00000000005850cb in parse_msgpack (channel=0x7f96e0ae5800) at ../src/nvim/msgpack_rpc/channel.c:423
    0x0000000000584f90 in receive_msgpack (stream=0x7f96e0a35218, rbuf=0x7f96e0d1d4c0, c=22, data=0x7f96e0ae5800, eof=false)
    at ../src/nvim/msgpack_rpc/channel.c:389
    0x00000000004d0b20 in read_event (argv=0x7ffed792f4a8) at ../src/nvim/event/rstream.c:190
    0x00000000004ce462 in multiqueue_process_events (this=0x7f96e18172d0) at ../src/nvim/event/multiqueue.c:150
    0x000000000059b630 in nv_event (cap=0x7ffed792f620) at ../src/nvim/normal.c:7908
    0x000000000058be69 in normal_execute (state=0x7ffed792f580, key=-25341) at ../src/nvim/normal.c:1137
    0x0000000000652463 in state_enter (s=0x7ffed792f580) at ../src/nvim/state.c:61
    0x000000000058a1fe in normal_enter (cmdwin=false, noexmode=false) at ../src/nvim/normal.c:467
    0x00000000005500c2 in main (argc=2, argv=0x7ffed792f8d8) at ../src/nvim/main.c:554

Alternative approach suggested by bfredl is to use close_cb of the
process. My unsuccessful attempt is below. (It seems close_cb is queued
too late, which is the similar problem addressed by this commit):

    commit 75fc12c
    Author: Justin M. Keyes <justinkz@gmail.com>
    Date:   Fri Aug 18 01:30:41 2017 +0200

        rpc: use Stream's close_cb instead of explicit check in receive_msgpack()

    diff --git a/src/nvim/event/process.c b/src/nvim/event/process.c
    index 8371d3cd482e..e52da23cdc40 100644
    --- a/src/nvim/event/process.c
    +++ b/src/nvim/event/process.c
    @@ -416,6 +416,10 @@ static void on_process_exit(Process *proc)
     static void on_process_stream_close(Stream *stream, void *data)
     {
       Process *proc = data;
    +  ILOG("on_process_stream_close");
    +  if (proc->stream_close_cb != NULL) {
    +    proc->stream_close_cb(stream, proc->stream_close_data);
    +  }
       decref(proc);
     }

    diff --git a/src/nvim/event/process.h b/src/nvim/event/process.h
    index 5c00e8e7ecd5..34a8d54f6f8c 100644
    --- a/src/nvim/event/process.h
    +++ b/src/nvim/event/process.h
    @@ -26,6 +26,11 @@ struct process {
       Stream *in, *out, *err;
       process_exit_cb cb;
       internal_process_cb internal_exit_cb, internal_close_cb;
    +
    +  // Called when any of the process streams (in/out/err) closes.
    +  stream_close_cb stream_close_cb;
    +  void *stream_close_data;
    +
       bool closed, detach;
       MultiQueue *events;
     };
    @@ -50,6 +55,8 @@ static inline Process process_init(Loop *loop, ProcessType type, void *data)
         .closed = false,
         .internal_close_cb = NULL,
         .internal_exit_cb = NULL,
    +    .stream_close_cb = NULL,
    +    .stream_close_data = NULL,
         .detach = false
       };
     }
    diff --git a/src/nvim/event/stream.c b/src/nvim/event/stream.c
    index 7c865bfe1e8c..c8720d1e45d9 100644
    --- a/src/nvim/event/stream.c
    +++ b/src/nvim/event/stream.c
    @@ -95,7 +95,11 @@ void stream_close(Stream *stream, stream_close_cb on_stream_close, void *data)
     void stream_close_handle(Stream *stream)
       FUNC_ATTR_NONNULL_ALL
     {
    +  ILOG("stream=%d", stream);
    +  // LOG_CALLSTACK();
       if (stream->uvstream) {
    +    // problem:  this schedules on the queue, but channel.c:receive_msgpack may
    +    // be processed before close_cb is called by libuv.
         uv_close((uv_handle_t *)stream->uvstream, close_cb);
       } else {
         uv_close((uv_handle_t *)&stream->uv.idle, close_cb);
    @@ -105,6 +109,7 @@ void stream_close_handle(Stream *stream)
     static void close_cb(uv_handle_t *handle)
     {
       Stream *stream = handle->data;
    +  ILOG(">>>>>>>>>>>>>>>>>>>>>>> stream=%p stream->internal_close_cb=%p", stream, stream->internal_close_cb);
       if (stream->buffer) {
         rbuffer_free(stream->buffer);
       }
    diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c
    index 782eabe04e4a..dc2b794e366a 100644
    --- a/src/nvim/msgpack_rpc/channel.c
    +++ b/src/nvim/msgpack_rpc/channel.c
    @@ -128,6 +128,8 @@ uint64_t channel_from_process(Process *proc, uint64_t id, char *source)
                                           source);
       incref(channel);  // process channels are only closed by the exit_cb
       channel->data.proc = proc;
    +  channel->data.proc->stream_close_cb = close_cb2;
    +  channel->data.proc->stream_close_data = channel;

       wstream_init(proc->in, 0);
       rstream_init(proc->out, 0);
    @@ -387,17 +389,6 @@ static void receive_msgpack(Stream *stream, RBuffer *rbuf, size_t c,
         goto end;
       }

    -  if ((chan_wstream(channel) != NULL && chan_wstream(channel)->closed)
    -      || (chan_rstream(channel) != NULL && chan_rstream(channel)->closed)) {
    -    char buf[256];
    -    snprintf(buf, sizeof(buf),
    -             "ch %" PRIu64 ": stream closed unexpectedly. "
    -             "closing channel",
    -             channel->id);
    -    call_set_error(channel, buf, WARN_LOG_LEVEL);
    -    goto end;
    -  }
    -
       size_t count = rbuffer_size(rbuf);
       DLOG("ch %" PRIu64 ": parsing %u bytes from msgpack Stream: %p",
            channel->id, count, stream);
    @@ -571,23 +562,6 @@ static Stream *chan_wstream(Channel *chan)
       abort();
     }

    -/// Returns the Stream that a Channel reads from.
    -static Stream *chan_rstream(Channel *chan)
    -{
    -  switch (chan->type) {
    -    case kChannelTypeSocket:
    -      return &chan->data.stream;
    -    case kChannelTypeProc:
    -      return chan->data.proc->out;
    -    case kChannelTypeStdio:
    -      return &chan->data.std.in;
    -    case kChannelTypeInternal:
    -      return NULL;
    -  }
    -  abort();
    -}
    -
    -
     static bool channel_write(Channel *channel, WBuffer *buffer)
     {
       bool success = false;
    @@ -799,6 +773,12 @@ static void close_cb(Stream *stream, void *data)
       decref(data);
     }

    +static void close_cb2(Stream *stream, void *data)
    +{
    +  ILOG("close_cb2");
    +  close_channel(data);
    +}
    +
     /// @param source description of source function, rplugin name, TCP addr, etc
     static Channel *register_channel(ChannelType type, uint64_t id,
                                      MultiQueue *events, char *source)

@justinmk justinmk merged commit 6e7a8c3 into neovim:master Aug 26, 2017

4 checks passed

QuickBuild Build pr-7081 finished with status SUCCESSFUL
Details
continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
coverage/coveralls Coverage increased (+0.0007%) to 76.458%
Details

@justinmk justinmk deleted the justinmk:rpcstop branch Aug 26, 2017

justinmk added a commit to justinmk/neovim that referenced this pull request Nov 8, 2017

NVIM v0.2.1
FEATURES:
0e873a3 Lua(Jit) built-in neovim#4411
5b32bce Windows: `:terminal` neovim#7007
7b0ceb3 UI/API: externalize cmdline neovim#7173
b67f58b UI/API: externalize wildmenu neovim#7454
b23aa1c UI: 'winhighlight' neovim#6597
17531ed UI: command-line coloring (`:help input()-highlight`) neovim#6364
244a1f9 API: execute lua directly from the remote api neovim#6704
45626de API: `get_keymap()` neovim#6236
db99982 API: `nvim_get_hl_by_name()`, `nvim_get_hl_by_id()` neovim#7082
dc68538 menu_get() function neovim#6322
9db42d4 :cquit : take an error code argument neovim#7336
9cc185d job-control: serverstart(): support ipv6 neovim#6680
1b7a9bf job-control: sockopen() neovim#6594
6efe84a clipboard: fallback to tmux clipboard neovim#6894
6016ac2 clipboard: customize clipboard with `g:clipboard` neovim#6030
3a86dd5 ruby: override ruby host via `g:ruby_host_prog` neovim#6841
16cce1a debug: $NVIM_LOG_FILE neovim#6827
0cba3da `:checkhealth` built-in, validates $VIMRUNTIME neovim#7399

FIXES:
105d680 TUI: more terminals, improve scroll/resize neovim#6816
cb912a3 :terminal : handle F1-F12, other keys neovim#7241
619838f inccommand: improve performance neovim#6949
04b3c32 inccommand: Fix matches for zero-width neovim#7487
60b1e8a inccommand: multiline, other fixes neovim#7315
f1f7f3b inccommand: Ignore leading modifiers in the command neovim#6967
1551f71 inccommand: fix 'gdefault' lockup neovim#7262
6338199 API: bufhl: support creating new groups neovim#7414
541dde3 API: allow K_EVENT during operator-pending
8c732f7 terminal: adjust for 'number' neovim#7440
5bec946 UI: preserve wildmenu during jobs/events neovim#7110
c349083 UI: disable 'lazyredraw' during ui_refresh. neovim#6259
51808a2 send FocusGained/FocusLost event instead of pseudokey neovim#7221
133f8bc shada: preserve unnamed register on restart neovim#4700
1b70a1d shada: avoid assertion on corrupt shada file neovim#6958
9f534f3 mksession: Restore tab-local working directory neovim#6859
de1084f fix buf_write() crash neovim#7140
7f76986 syntax: register 'Normal' highlight group neovim#6973
6e7a8c3 RPC: close channel if stream was closed neovim#7081
85f3084 clipboard: disallow recursion; show hint only once neovim#7203
8d1ccb6 clipboard: performance, avoid weird edge-cases neovim#7193
01487d4 'titleold' neovim#7358
01e53a5 Windows: better path-handling, separator (slash) hygiene neovim#7349
0f2873c Windows: multibyte startup arguments neovim#7060

CHANGES:
9ff0cc7 :terminal : start in normal-mode neovim#6808
032b088 lower priority of 'cursorcolumn', 'colorcolumn' neovim#7364
2a3bcd1 RPC: Don't delay notifications when request is pending neovim#6544
023f67c :terminal : Do not change 'number', 'relativenumber' neovim#6796
1ef2d76 socket.c: Disable Nagle's algorithm on TCP sockets neovim#6915
6720fe2 help: `K` tries Vim help instead of manpage neovim#3104
7068370 help, man.vim: change "outline" map to `gO` neovim#7405

@justinmk justinmk referenced this pull request Nov 8, 2017

Merged

NVIM v0.2.1 #7505

@justinmk justinmk self-assigned this Nov 8, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment