jobstop(): close channel before process_stop() #10522
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**
- af993da435 (`receive_msgpack`) tried to hack around same/similar issue.
- Hack was removed in 5215e3205a.
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 ??:?
58dd5fcc01