rpc: close channel if stream was closed #7081
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This comment has been minimized.
This comment has been minimized.
bfredl
reviewed
Jul 27, 2017
|
Does the channels PR have the same issue? |
bfredl
reviewed
Jul 27, 2017
| goto end; | ||
| } | ||
|
|
||
| if ((chan_wstream(channel) != NULL && chan_wstream(channel)->closed) |
There was a problem hiding this comment.
Can't we use close_cb of the streams?
e6dc98e to
9f823d4
Compare
@bfredl does @bfredl FWIW #6844 does pass the test. But I wonder, is that because the codepath of |
|
@justinmk I managed to mess up event handling in very subtly ways (because
streams getting events queue assigned in different places, depending on the
transport kind, which changes their semantics) in the rpc+stderr PR; event
handing should be better in the channels PR so that close_cb gets called at
the right time.
|
|
Also `rpcstop()` is _strongly_ deprecated with the channels PR. It should
only ever be used in a test to test the b/c of that very function, not to
test "event handling in general". But the semantics are not "changed" in
any way, it was just wrong to start with...
|
be2031b to
d03a81e
Compare
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 8371d3c..e52da23 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 5c00e8e..34a8d54 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 7c865bf..c8720d1 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 782eabe..dc2b794 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)
3 tasks
justinmk
added a commit
to justinmk/neovim
that referenced
this pull request
Nov 8, 2017
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
Merged
justinmk
added a commit
to justinmk/neovim
that referenced
this pull request
Jul 16, 2019
fix neovim#9799 regression of neovim#7081 Helped-by: Björn Linse <bjorn.linse@gmail.com> Problem: :UpdateRemotePlugins (which calls rpcstop()) sometimes crashes: remote/host: python3 host registered plugins [] nvim: ../src/nvim/event/wstream.c:78: _Bool wstream_write(Stream *, WBuffer *): Assertion `!stream->closed' failed. Aborted (core dumped) Order of events (channel 163, see logs below): 1. Channel's in-stream (0x2ba86c0) is **closed** by `f_rpcstop`..`process_stop`. 2. `receive_msgpack` parses the channel out-stream (0x2ba8860) 3. Invokes "nvim_command_output" API method. 4. Writes result to the **closed** in-stream => **abort** - af993da (`receive_msgpack`) tried to hack around same/similar issue. - Hack was removed in 5215e32. Solution: in jobstop(), close the channel before process_stop(). Log: DEBUG 2019-07-16T20:54:12.191 25159 stream_close:96: closing Stream: 0x2b01a90 DEBUG 2019-07-16T20:54:12.210 25159 process_spawn:124: new: pid=28407 argv=[/usr/bin/python3] DEBUG 2019-07-16T20:54:12.210 25159 rpc_start:72: rpc ch 163 in-stream=0x2ba86c0 out-stream=0x2ba8860 INFO 2019-07-16T20:54:12.210 25159 channel_create_event:199: new channel 163 (function <SNR>61_on_exit[4]..<SNR>60_job_exit_cb[101]..<SNR>60_decrement_job_count[8]..remote#host#UpdateRemotePlugins[6]..<SNR>31_RegistrationCommands[15]..remote#host#Require[10]..provider#pythonx#Require[13]..provider#Poll:3) : {"id": 163, "client": {}, "mode": "rpc", "stream": "job"} DEBUG 2019-07-16T20:54:12.211 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 1, "poll", []] DEBUG 2019-07-16T20:54:12.355 25159 receive_msgpack:227: ch 163: parsing 21 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.355 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 1, "vim_get_api_info", []] DEBUG 2019-07-16T20:54:12.355 25159 RPC: <-ch 163: invoke nvim_get_api_info DEBUG 2019-07-16T20:54:12.357 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 1, nil, [163, {"version"=>{"major"=>0, "minor"=>4, }, ... DEBUG 2019-07-16T20:54:12.377 25159 receive_msgpack:227: ch 163: parsing 85 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 2, "nvim_eval", ["((&number||&relativenumber) ? &numberwidth : 0) + &foldcolumn"]] DEBUG 2019-07-16T20:54:12.377 25159 handle_request:359: RPC: scheduled nvim_eval DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 1, nil, "ok"] DEBUG 2019-07-16T20:54:12.378 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 2, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/__pycache__"]] DEBUG 2019-07-16T20:54:12.378 25159 RPC: <-ch 163: invoke nvim_eval DEBUG 2019-07-16T20:54:12.379 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.379 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.379 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.380 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 3, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/foo.py"]] DEBUG 2019-07-16T20:54:12.380 25159 receive_msgpack:227: ch 163: parsing 79 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.380 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 3, "nvim_command", ["redir =>a |exe "sil sign place buffer=".bufnr('')|redir end"]] DEBUG 2019-07-16T20:54:12.381 25159 handle_request:359: RPC: scheduled nvim_command DEBUG 2019-07-16T20:54:12.381 25159 RPC: <-ch 163: invoke nvim_command DEBUG 2019-07-16T20:54:12.381 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 3, nil, nil] DEBUG 2019-07-16T20:54:12.381 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.381 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 3, nil, 0] DEBUG 2019-07-16T20:54:12.382 25159 stream_close:95: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 stream_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:95 stream_may_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:111 process_stop at /home/vagrant/neovim/build/../src/nvim/event/process.c:230 f_jobstop at /home/vagrant/neovim/build/../src/nvim/eval.c:12231 f_rpcstop at /home/vagrant/neovim/build/../src/nvim/eval.c:14533 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6564 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 eval7 at /home/vagrant/neovim/build/../src/nvim/eval.c:4407 eval6 at /home/vagrant/neovim/build/../src/nvim/eval.c:4104 eval5 at /home/vagrant/neovim/build/../src/nvim/eval.c:3985 eval4 at /home/vagrant/neovim/build/../src/nvim/eval.c:3688 eval3 at /home/vagrant/neovim/build/../src/nvim/eval.c:3606 eval2 at /home/vagrant/neovim/build/../src/nvim/eval.c:3537 eval1 at /home/vagrant/neovim/build/../src/nvim/eval.c:3464 eval0 at /home/vagrant/neovim/build/../src/nvim/eval.c:3424 ex_let_const at /home/vagrant/neovim/build/../src/nvim/eval.c:1604 ex_let at /home/vagrant/neovim/build/../src/nvim/eval.c:1546 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 do_ucmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:5803 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2243 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 callback_call at /home/vagrant/neovim/build/../src/nvim/eval.c:17917 channel_callback_call at /home/vagrant/neovim/build/../src/nvim/channel.c:675 on_channel_event at /home/vagrant/neovim/build/../src/nvim/channel.c:581 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:? DEBUG 2019-07-16T20:54:12.417 25159 stream_close:96: closing Stream: 0x2ba86c0 INFO 2019-07-16T20:54:12.417 25159 os_proc_tree_kill:96: sending SIGTERM to process group: -28407 DEBUG 2019-07-16T20:54:12.417 25159 receive_msgpack:227: ch 163: parsing 31 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.417 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 4, "nvim_command_output", ["echo a"]] DEBUG 2019-07-16T20:54:12.417 25159 handle_request:359: RPC: scheduled nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 RPC: <-ch 163: invoke nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 4, [0, "Vim(echo):E121: Undefined variable: a"], nil] ERROR 2019-07-16T20:54:12.424 25159 wstream_write:78: xxx stream=0x2ba86c0 DEBUG 2019-07-16T20:54:12.425 25159 wstream_write:79: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 wstream_write at /home/vagrant/neovim/build/../src/nvim/event/wstream.c:82 channel_write at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:407 request_event at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:383 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:?
justinmk
added a commit
to justinmk/neovim
that referenced
this pull request
Jul 16, 2019
fix neovim#9799 regression of neovim#7081 Helped-by: Björn Linse <bjorn.linse@gmail.com> Problem: :UpdateRemotePlugins (which calls rpcstop()) sometimes crashes: remote/host: python3 host registered plugins [] nvim: ../src/nvim/event/wstream.c:78: _Bool wstream_write(Stream *, WBuffer *): Assertion `!stream->closed' failed. Aborted (core dumped) Order of events (channel 163, see logs below): 1. Channel's in-stream (0x2ba86c0) is **closed** by `f_rpcstop`..`process_stop`. 2. `receive_msgpack` parses the channel out-stream (0x2ba8860) 3. Invokes "nvim_command_output" API method. 4. Writes result to the **closed** in-stream => **abort** - af993da (`receive_msgpack`) tried to hack around same/similar issue. - Hack was removed in 5215e32. Solution: in jobstop(), close the channel before process_stop(). Log: DEBUG 2019-07-16T20:54:12.191 25159 stream_close:96: closing Stream: 0x2b01a90 DEBUG 2019-07-16T20:54:12.210 25159 process_spawn:124: new: pid=28407 argv=[/usr/bin/python3] DEBUG 2019-07-16T20:54:12.210 25159 rpc_start:72: rpc ch 163 in-stream=0x2ba86c0 out-stream=0x2ba8860 INFO 2019-07-16T20:54:12.210 25159 channel_create_event:199: new channel 163 (function <SNR>61_on_exit[4]..<SNR>60_job_exit_cb[101]..<SNR>60_decrement_job_count[8]..remote#host#UpdateRemotePlugins[6]..<SNR>31_RegistrationCommands[15]..remote#host#Require[10]..provider#pythonx#Require[13]..provider#Poll:3) : {"id": 163, "client": {}, "mode": "rpc", "stream": "job"} DEBUG 2019-07-16T20:54:12.211 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 1, "poll", []] DEBUG 2019-07-16T20:54:12.355 25159 receive_msgpack:227: ch 163: parsing 21 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.355 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 1, "vim_get_api_info", []] DEBUG 2019-07-16T20:54:12.355 25159 RPC: <-ch 163: invoke nvim_get_api_info DEBUG 2019-07-16T20:54:12.357 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 1, nil, [163, {"version"=>{"major"=>0, "minor"=>4, }, ... DEBUG 2019-07-16T20:54:12.377 25159 receive_msgpack:227: ch 163: parsing 85 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 2, "nvim_eval", ["((&number||&relativenumber) ? &numberwidth : 0) + &foldcolumn"]] DEBUG 2019-07-16T20:54:12.377 25159 handle_request:359: RPC: scheduled nvim_eval DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 1, nil, "ok"] DEBUG 2019-07-16T20:54:12.378 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 2, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/__pycache__"]] DEBUG 2019-07-16T20:54:12.378 25159 RPC: <-ch 163: invoke nvim_eval DEBUG 2019-07-16T20:54:12.379 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.379 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.379 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.380 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 3, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/foo.py"]] DEBUG 2019-07-16T20:54:12.380 25159 receive_msgpack:227: ch 163: parsing 79 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.380 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 3, "nvim_command", ["redir =>a |exe "sil sign place buffer=".bufnr('')|redir end"]] DEBUG 2019-07-16T20:54:12.381 25159 handle_request:359: RPC: scheduled nvim_command DEBUG 2019-07-16T20:54:12.381 25159 RPC: <-ch 163: invoke nvim_command DEBUG 2019-07-16T20:54:12.381 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 3, nil, nil] DEBUG 2019-07-16T20:54:12.381 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.381 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 3, nil, 0] DEBUG 2019-07-16T20:54:12.382 25159 stream_close:95: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 stream_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:95 stream_may_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:111 process_stop at /home/vagrant/neovim/build/../src/nvim/event/process.c:230 f_jobstop at /home/vagrant/neovim/build/../src/nvim/eval.c:12231 f_rpcstop at /home/vagrant/neovim/build/../src/nvim/eval.c:14533 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6564 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 eval7 at /home/vagrant/neovim/build/../src/nvim/eval.c:4407 eval6 at /home/vagrant/neovim/build/../src/nvim/eval.c:4104 eval5 at /home/vagrant/neovim/build/../src/nvim/eval.c:3985 eval4 at /home/vagrant/neovim/build/../src/nvim/eval.c:3688 eval3 at /home/vagrant/neovim/build/../src/nvim/eval.c:3606 eval2 at /home/vagrant/neovim/build/../src/nvim/eval.c:3537 eval1 at /home/vagrant/neovim/build/../src/nvim/eval.c:3464 eval0 at /home/vagrant/neovim/build/../src/nvim/eval.c:3424 ex_let_const at /home/vagrant/neovim/build/../src/nvim/eval.c:1604 ex_let at /home/vagrant/neovim/build/../src/nvim/eval.c:1546 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 do_ucmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:5803 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2243 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 callback_call at /home/vagrant/neovim/build/../src/nvim/eval.c:17917 channel_callback_call at /home/vagrant/neovim/build/../src/nvim/channel.c:675 on_channel_event at /home/vagrant/neovim/build/../src/nvim/channel.c:581 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:? DEBUG 2019-07-16T20:54:12.417 25159 stream_close:96: closing Stream: 0x2ba86c0 INFO 2019-07-16T20:54:12.417 25159 os_proc_tree_kill:96: sending SIGTERM to process group: -28407 DEBUG 2019-07-16T20:54:12.417 25159 receive_msgpack:227: ch 163: parsing 31 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.417 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 4, "nvim_command_output", ["echo a"]] DEBUG 2019-07-16T20:54:12.417 25159 handle_request:359: RPC: scheduled nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 RPC: <-ch 163: invoke nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 4, [0, "Vim(echo):E121: Undefined variable: a"], nil] ERROR 2019-07-16T20:54:12.424 25159 wstream_write:78: xxx stream=0x2ba86c0 DEBUG 2019-07-16T20:54:12.425 25159 wstream_write:79: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 wstream_write at /home/vagrant/neovim/build/../src/nvim/event/wstream.c:82 channel_write at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:407 request_event at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:383 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:?
justinmk
added a commit
that referenced
this pull request
Jul 17, 2019
fix #9799 regression of #7081 Helped-by: Björn Linse <bjorn.linse@gmail.com> Problem: :UpdateRemotePlugins (which calls rpcstop()) sometimes crashes: remote/host: python3 host registered plugins [] nvim: ../src/nvim/event/wstream.c:78: _Bool wstream_write(Stream *, WBuffer *): Assertion `!stream->closed' failed. Aborted (core dumped) Order of events (channel 163, see logs below): 1. Channel's in-stream (0x2ba86c0) is **closed** by `f_rpcstop`..`process_stop`. 2. `receive_msgpack` parses the channel out-stream (0x2ba8860) 3. Invokes "nvim_command_output" API method. 4. Writes result to the **closed** in-stream => **abort** - af993da (`receive_msgpack`) tried to hack around same/similar issue. - Hack was removed in 5215e32. Solution: in jobstop(), close the channel before process_stop(). Log: DEBUG 2019-07-16T20:54:12.191 25159 stream_close:96: closing Stream: 0x2b01a90 DEBUG 2019-07-16T20:54:12.210 25159 process_spawn:124: new: pid=28407 argv=[/usr/bin/python3] DEBUG 2019-07-16T20:54:12.210 25159 rpc_start:72: rpc ch 163 in-stream=0x2ba86c0 out-stream=0x2ba8860 INFO 2019-07-16T20:54:12.210 25159 channel_create_event:199: new channel 163 (function <SNR>61_on_exit[4]..<SNR>60_job_exit_cb[101]..<SNR>60_decrement_job_count[8]..remote#host#UpdateRemotePlugins[6]..<SNR>31_RegistrationCommands[15]..remote#host#Require[10]..provider#pythonx#Require[13]..provider#Poll:3) : {"id": 163, "client": {}, "mode": "rpc", "stream": "job"} DEBUG 2019-07-16T20:54:12.211 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 1, "poll", []] DEBUG 2019-07-16T20:54:12.355 25159 receive_msgpack:227: ch 163: parsing 21 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.355 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 1, "vim_get_api_info", []] DEBUG 2019-07-16T20:54:12.355 25159 RPC: <-ch 163: invoke nvim_get_api_info DEBUG 2019-07-16T20:54:12.357 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 1, nil, [163, {"version"=>{"major"=>0, "minor"=>4, }, ... DEBUG 2019-07-16T20:54:12.377 25159 receive_msgpack:227: ch 163: parsing 85 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 2, "nvim_eval", ["((&number||&relativenumber) ? &numberwidth : 0) + &foldcolumn"]] DEBUG 2019-07-16T20:54:12.377 25159 handle_request:359: RPC: scheduled nvim_eval DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 1, nil, "ok"] DEBUG 2019-07-16T20:54:12.378 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 2, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/__pycache__"]] DEBUG 2019-07-16T20:54:12.378 25159 RPC: <-ch 163: invoke nvim_eval DEBUG 2019-07-16T20:54:12.379 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.379 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.379 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.380 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 3, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/foo.py"]] DEBUG 2019-07-16T20:54:12.380 25159 receive_msgpack:227: ch 163: parsing 79 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.380 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 3, "nvim_command", ["redir =>a |exe "sil sign place buffer=".bufnr('')|redir end"]] DEBUG 2019-07-16T20:54:12.381 25159 handle_request:359: RPC: scheduled nvim_command DEBUG 2019-07-16T20:54:12.381 25159 RPC: <-ch 163: invoke nvim_command DEBUG 2019-07-16T20:54:12.381 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 3, nil, nil] DEBUG 2019-07-16T20:54:12.381 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.381 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 3, nil, 0] DEBUG 2019-07-16T20:54:12.382 25159 stream_close:95: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 stream_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:95 stream_may_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:111 process_stop at /home/vagrant/neovim/build/../src/nvim/event/process.c:230 f_jobstop at /home/vagrant/neovim/build/../src/nvim/eval.c:12231 f_rpcstop at /home/vagrant/neovim/build/../src/nvim/eval.c:14533 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6564 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 eval7 at /home/vagrant/neovim/build/../src/nvim/eval.c:4407 eval6 at /home/vagrant/neovim/build/../src/nvim/eval.c:4104 eval5 at /home/vagrant/neovim/build/../src/nvim/eval.c:3985 eval4 at /home/vagrant/neovim/build/../src/nvim/eval.c:3688 eval3 at /home/vagrant/neovim/build/../src/nvim/eval.c:3606 eval2 at /home/vagrant/neovim/build/../src/nvim/eval.c:3537 eval1 at /home/vagrant/neovim/build/../src/nvim/eval.c:3464 eval0 at /home/vagrant/neovim/build/../src/nvim/eval.c:3424 ex_let_const at /home/vagrant/neovim/build/../src/nvim/eval.c:1604 ex_let at /home/vagrant/neovim/build/../src/nvim/eval.c:1546 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 do_ucmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:5803 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2243 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 callback_call at /home/vagrant/neovim/build/../src/nvim/eval.c:17917 channel_callback_call at /home/vagrant/neovim/build/../src/nvim/channel.c:675 on_channel_event at /home/vagrant/neovim/build/../src/nvim/channel.c:581 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:? DEBUG 2019-07-16T20:54:12.417 25159 stream_close:96: closing Stream: 0x2ba86c0 INFO 2019-07-16T20:54:12.417 25159 os_proc_tree_kill:96: sending SIGTERM to process group: -28407 DEBUG 2019-07-16T20:54:12.417 25159 receive_msgpack:227: ch 163: parsing 31 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.417 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 4, "nvim_command_output", ["echo a"]] DEBUG 2019-07-16T20:54:12.417 25159 handle_request:359: RPC: scheduled nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 RPC: <-ch 163: invoke nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 4, [0, "Vim(echo):E121: Undefined variable: a"], nil] ERROR 2019-07-16T20:54:12.424 25159 wstream_write:78: xxx stream=0x2ba86c0 DEBUG 2019-07-16T20:54:12.425 25159 wstream_write:79: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 wstream_write at /home/vagrant/neovim/build/../src/nvim/event/wstream.c:82 channel_write at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:407 request_event at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:383 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:?
timeyyy
pushed a commit
to timeyyy/neovim
that referenced
this pull request
Aug 9, 2019
fix neovim#9799 regression of neovim#7081 Helped-by: Björn Linse <bjorn.linse@gmail.com> Problem: :UpdateRemotePlugins (which calls rpcstop()) sometimes crashes: remote/host: python3 host registered plugins [] nvim: ../src/nvim/event/wstream.c:78: _Bool wstream_write(Stream *, WBuffer *): Assertion `!stream->closed' failed. Aborted (core dumped) Order of events (channel 163, see logs below): 1. Channel's in-stream (0x2ba86c0) is **closed** by `f_rpcstop`..`process_stop`. 2. `receive_msgpack` parses the channel out-stream (0x2ba8860) 3. Invokes "nvim_command_output" API method. 4. Writes result to the **closed** in-stream => **abort** - af993da (`receive_msgpack`) tried to hack around same/similar issue. - Hack was removed in 5215e32. Solution: in jobstop(), close the channel before process_stop(). Log: DEBUG 2019-07-16T20:54:12.191 25159 stream_close:96: closing Stream: 0x2b01a90 DEBUG 2019-07-16T20:54:12.210 25159 process_spawn:124: new: pid=28407 argv=[/usr/bin/python3] DEBUG 2019-07-16T20:54:12.210 25159 rpc_start:72: rpc ch 163 in-stream=0x2ba86c0 out-stream=0x2ba8860 INFO 2019-07-16T20:54:12.210 25159 channel_create_event:199: new channel 163 (function <SNR>61_on_exit[4]..<SNR>60_job_exit_cb[101]..<SNR>60_decrement_job_count[8]..remote#host#UpdateRemotePlugins[6]..<SNR>31_RegistrationCommands[15]..remote#host#Require[10]..provider#pythonx#Require[13]..provider#Poll:3) : {"id": 163, "client": {}, "mode": "rpc", "stream": "job"} DEBUG 2019-07-16T20:54:12.211 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 1, "poll", []] DEBUG 2019-07-16T20:54:12.355 25159 receive_msgpack:227: ch 163: parsing 21 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.355 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 1, "vim_get_api_info", []] DEBUG 2019-07-16T20:54:12.355 25159 RPC: <-ch 163: invoke nvim_get_api_info DEBUG 2019-07-16T20:54:12.357 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 1, nil, [163, {"version"=>{"major"=>0, "minor"=>4, }, ... DEBUG 2019-07-16T20:54:12.377 25159 receive_msgpack:227: ch 163: parsing 85 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 2, "nvim_eval", ["((&number||&relativenumber) ? &numberwidth : 0) + &foldcolumn"]] DEBUG 2019-07-16T20:54:12.377 25159 handle_request:359: RPC: scheduled nvim_eval DEBUG 2019-07-16T20:54:12.377 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 1, nil, "ok"] DEBUG 2019-07-16T20:54:12.378 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 2, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/__pycache__"]] DEBUG 2019-07-16T20:54:12.378 25159 RPC: <-ch 163: invoke nvim_eval DEBUG 2019-07-16T20:54:12.379 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.379 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.379 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 2, nil, 0] DEBUG 2019-07-16T20:54:12.380 25159 log_server_msg:729: RPC ->ch 163: [request] [0, 3, "specs", ["/home/vagrant/.config/nvim/rplugin/python3/foo.py"]] DEBUG 2019-07-16T20:54:12.380 25159 receive_msgpack:227: ch 163: parsing 79 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.380 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 3, "nvim_command", ["redir =>a |exe "sil sign place buffer=".bufnr('')|redir end"]] DEBUG 2019-07-16T20:54:12.381 25159 handle_request:359: RPC: scheduled nvim_command DEBUG 2019-07-16T20:54:12.381 25159 RPC: <-ch 163: invoke nvim_command DEBUG 2019-07-16T20:54:12.381 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 3, nil, nil] DEBUG 2019-07-16T20:54:12.381 25159 receive_msgpack:227: ch 163: parsing 5 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.381 25159 log_client_msg:766: RPC <-ch 163: [response] [1, 3, nil, 0] DEBUG 2019-07-16T20:54:12.382 25159 stream_close:95: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 stream_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:95 stream_may_close at /home/vagrant/neovim/build/../src/nvim/event/stream.c:111 process_stop at /home/vagrant/neovim/build/../src/nvim/event/process.c:230 f_jobstop at /home/vagrant/neovim/build/../src/nvim/eval.c:12231 f_rpcstop at /home/vagrant/neovim/build/../src/nvim/eval.c:14533 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6564 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 eval7 at /home/vagrant/neovim/build/../src/nvim/eval.c:4407 eval6 at /home/vagrant/neovim/build/../src/nvim/eval.c:4104 eval5 at /home/vagrant/neovim/build/../src/nvim/eval.c:3985 eval4 at /home/vagrant/neovim/build/../src/nvim/eval.c:3688 eval3 at /home/vagrant/neovim/build/../src/nvim/eval.c:3606 eval2 at /home/vagrant/neovim/build/../src/nvim/eval.c:3537 eval1 at /home/vagrant/neovim/build/../src/nvim/eval.c:3464 eval0 at /home/vagrant/neovim/build/../src/nvim/eval.c:3424 ex_let_const at /home/vagrant/neovim/build/../src/nvim/eval.c:1604 ex_let at /home/vagrant/neovim/build/../src/nvim/eval.c:1546 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 do_ucmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:5803 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2243 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 get_func_tv at /home/vagrant/neovim/build/../src/nvim/eval.c:6304 ex_call at /home/vagrant/neovim/build/../src/nvim/eval.c:2903 do_one_cmd at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:2249 do_cmdline at /home/vagrant/neovim/build/../src/nvim/ex_docmd.c:593 call_user_func at /home/vagrant/neovim/build/../src/nvim/eval.c:22666 call_func at /home/vagrant/neovim/build/../src/nvim/eval.c:6550 callback_call at /home/vagrant/neovim/build/../src/nvim/eval.c:17917 channel_callback_call at /home/vagrant/neovim/build/../src/nvim/channel.c:675 on_channel_event at /home/vagrant/neovim/build/../src/nvim/channel.c:581 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:? DEBUG 2019-07-16T20:54:12.417 25159 stream_close:96: closing Stream: 0x2ba86c0 INFO 2019-07-16T20:54:12.417 25159 os_proc_tree_kill:96: sending SIGTERM to process group: -28407 DEBUG 2019-07-16T20:54:12.417 25159 receive_msgpack:227: ch 163: parsing 31 bytes from msgpack Stream: 0x2ba8860 DEBUG 2019-07-16T20:54:12.417 25159 log_client_msg:766: RPC <-ch 163: [request] [0, 4, "nvim_command_output", ["echo a"]] DEBUG 2019-07-16T20:54:12.417 25159 handle_request:359: RPC: scheduled nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 RPC: <-ch 163: invoke nvim_command_output DEBUG 2019-07-16T20:54:12.424 25159 log_server_msg:729: RPC ->ch 163: [response] [1, 4, [0, "Vim(echo):E121: Undefined variable: a"], nil] ERROR 2019-07-16T20:54:12.424 25159 wstream_write:78: xxx stream=0x2ba86c0 DEBUG 2019-07-16T20:54:12.425 25159 wstream_write:79: trace: log_callstack at /home/vagrant/neovim/build/../src/nvim/log.c:256 wstream_write at /home/vagrant/neovim/build/../src/nvim/event/wstream.c:82 channel_write at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:407 request_event at /home/vagrant/neovim/build/../src/nvim/msgpack_rpc/channel.c:383 multiqueue_process_events at /home/vagrant/neovim/build/../src/nvim/event/multiqueue.c:147 nv_event at /home/vagrant/neovim/build/../src/nvim/normal.c:7987 normal_execute at /home/vagrant/neovim/build/../src/nvim/normal.c:1133 state_enter at /home/vagrant/neovim/build/../src/nvim/state.c:73 normal_enter at /home/vagrant/neovim/build/../src/nvim/normal.c:462 main at /home/vagrant/neovim/build/../src/nvim/main.c:570 ?? ??:0 _start at ??:?
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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():
todo: