neovim/runtime
Justin M. Keyes 58dd5fcc01
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 ??:?
2019-07-17 11:13:57 +02:00
..
autoload jobstop(): close channel before process_stop() #10522 2019-07-17 11:13:57 +02:00
colors vim-patch:8.0.1777: cannot cleanup before loading another colorscheme (#9104) 2018-10-11 08:27:37 +02:00
compiler vim-patch:20aac6c11269 2018-10-29 23:55:45 +01:00
doc jobstop(): close channel before process_stop() #10522 2019-07-17 11:13:57 +02:00
ftplugin man.vim: set 'linebreak' 2019-02-06 22:18:34 +01:00
indent vim-patch:8.0.1845: various comment updates needed, missing white space (#10203) 2019-06-16 19:49:23 +02:00
keymap vim-patch:22f1d0e35eb0 2018-10-28 14:18:21 +01:00
lua man.vim: Handle ANSI escape sequences with ":" #10267 2019-06-30 15:25:49 +02:00
macros vim-patch:cd5c8f825078 2017-11-07 01:16:42 +01:00
pack/dist/opt termdebug.vim: vertical layout #10424 2019-07-05 20:45:26 +02:00
plugin lua/stdlib: Load runtime modules on-demand 2019-01-14 02:22:16 +01:00
print Remove dec-mcs remnants 2014-12-19 15:28:49 -05:00
spell runtime: include en.utf-8.spl 2018-01-15 23:58:52 +01:00
syntax vim-patch:8.0.1845: various comment updates needed, missing white space (#10203) 2019-06-16 19:49:23 +02:00
tools vim-patch:d2f3a8b87873 2018-10-29 09:32:29 +01:00
tutor runtime/tutor [ci skip] #9990 2019-05-09 23:32:57 +02:00
bugreport.vim options: remove ghost of :set termcap (#7102) 2017-07-31 02:50:34 +02:00
CMakeLists.txt build: fix doc_html target 2019-01-04 02:17:23 +01:00
delmenu.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
filetype.vim vim-patch:8.1.1284: detecting *.tmpl as htmlcheetah is outdated 2019-05-06 22:35:45 -04:00
ftoff.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
ftplugin.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
ftplugof.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
indent.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
indoff.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
macmap.vim re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
makemenu.vim vim-patch:fc39ec 2016-04-16 23:06:24 -07:00
menu.vim vim-patch:fc65cabb15d0 2018-10-29 23:54:15 +01:00
mswin.vim vim-patch:a9604e614517 2018-10-29 09:50:08 +01:00
nvim.appdata.xml appdata: Include more info #9974 2019-05-06 22:11:59 +02:00
nvim.desktop dist: runtime/nvim.desktop 2017-01-31 02:02:09 +01:00
nvim.png Dist: make icon a proper square (#9716) 2019-03-11 21:00:12 +01:00
optwin.vim vim-patch:8.1.0932: remove Farsi support (#9622) 2019-02-17 10:54:00 +01:00
rgb.txt re-integrate runtime/ vim-patch:0 #938 2014-07-29 02:12:31 +00:00
scripts.vim vim-patch:8.1.1593: filetype not detected for C++ header files without extension 2019-06-25 21:20:26 -04:00
synmenu.vim vim-patch:01164a6546b4 2017-11-07 23:07:03 +01:00