els_server crashes due to timeout from els_code_lens_provider, does not recover

[jesperes]

Describe the bug
Upon opening a file, els_server crashes due to a timeout from els_code_lens_provider. els_sup seems to restart it, but without success, i.e. it stops responding to commands.

[2021-04-09T08:48:32.443669+02:00] supervisor.erl:707 <0.159.0> [error] Supervisor: {local,els_sup}. Context: child_terminated. Reason: {timeout,{gen_server,call,[els_code_lens_provider,{cancel_request,<0.460.0>}]}}. Offender: id=els_server,pid=<0.188.0>.
[2021-04-09T08:48:32.443966+02:00] /home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl:105 <0.16695.0> [info] Starting els_server...
[2021-04-09T08:48:32.444111+02:00] supervisor.erl:1433 <0.159.0> [info] Supervisor: {local,els_sup}. Started: id=els_server,pid=<0.16695.0>.
[2021-04-09T08:48:32.444223+02:00] /home/jesperes/dev/erlang_ls/apps/els_core/src/els_stdio.erl:27 <0.16696.0> [info] Starting stdio server...

To Reproduce
In my setup, it is enough to simply open a file. However, the project is very large with 270+ applications and ~6000 source files, so indexing takes quite some time.

Theories
The problem is related to the suggest-spec code lens. If this lens is disabled, or if plt_path is unset, this problem does not occur. Due to the size of the project, it would not be surprising if the suggest-spec lens code times out in relation to building type signatures, or something like that.

Expected behavior
Normal behavior, e.g. code navigation should work, code lenses be displayed, and so on.

Actual behavior
erlang_ls stops responding to any requests, causing things like code navigation to stop working.

Context

• erlang_ls version (tag/sha): 0.13.0, 76fa5ff
• Editor used: Emacs
• LSP client used: lsp-mode 20210407.2348
• OTP version: 23.2.4

Workaround
Disable the suggest-spec code lens.

[jesperes]

Full crash message:

[2021-04-09T08:48:32.440339+02:00] gen_server.erl:943 <0.188.0> [error] Generic server els_server terminating. Reason: {{timeout,{gen_server,call,[els_code_lens_provider,{cancel_request,<0.460.0>}]}},[{gen_server,call,2,[{file,"gen_server.erl"},{line,238}]},{els_server,handle_request,2,[{file,"/home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl"},{line,152}]},{lists,foldl,3,[{file,"lists.erl"},{line,1267}]},{els_server,handle_cast,2,[{file,"/home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl"},{line,121}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,689}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,765}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}. Last message: {'$gen_cast',{process_requests,[#{<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"$/cancelRequest">>,<<"params">> => #{<<"id">> => 1628}}]}}. State: {state,els_stdio,<0.157.0>,17,#{status => initialized},[{1628,els_code_lens_provider,<0.460.0>},{1627,els_code_lens_provider,<0.219.0>}]}.
[2021-04-09T08:48:32.440759+02:00] proc_lib.erl:525 <0.188.0> [error] crasher: initial call: els_server:init/1, pid: <0.188.0>, registered_name: els_server, exit: {{timeout,{gen_server,call,[els_code_lens_provider,{cancel_request,<0.460.0>}]}},[{gen_server,call,2,[{file,"gen_server.erl"},{line,238}]},{els_server,handle_request,2,[{file,"/home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl"},{line,152}]},{lists,foldl,3,[{file,"lists.erl"},{line,1267}]},{els_server,handle_cast,2,[{file,"/home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl"},{line,121}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,689}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,765}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}, ancestors: [els_sup,<0.158.0>], message_queue_len: 17, messages: [{'$gen_cast',{process_requests,[#{<<"id">> => 1632,<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"textDocument/codeLens">>,<<"params">> => #{<<"textDocument">> => #{<<"uri">> => <<"file:///home/jesperes/dev/kred/lib/kred/src/kred.erl">>}}}]}},{'$gen_cast',{process_requests,[#{<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"$/cancelRequest">>,<<"params">> => #{<<"id">> => 1627}}]}},{'$gen_cast',{process_requests,[#{<<"id">> => 1633,<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"textDocument/codeLens">>,<<"params">> => #{<<"textDocument">> => #{<<"uri">> => <<"file:///home/jesperes/dev/kred/lib/log_and_alarm/src/klog.erl">>}}}]}},{'$gen_cast',{process_requests,[#{<<"id">> => 1634,<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"textDocument/codeAction">>,<<"params">> => #{<<"context">> => #{<<"diagnostics">> => []},<<"range">> => #{<<"end">> => #{<<"character">> => 21,<<"line">> => 125},<<"start">> => #{<<"character">> => 0,<<"line">> => 125}},<<"textDocument">> => #{<<"uri">> => <<"file:///home/jesperes/dev/kred/lib/kred/src/kred.erl">>}}}]}},{'$gen_cast',{process_requests,[#{<<"id">> => 1635,<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"textDocument/hover">>,<<"params">> => #{<<"position">> => #{<<"character">> => 13,<<"line">> => 125},<<"textDocument">> => #{<<"uri">> => <<"file:///home/jesperes/dev/kred/lib/kred/src/kred.erl">>}}}]}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"dbb56ff2-0f02-4ac1-8731-c657f7ff462f">>,value => #{cancellable => false,kind => report,message => <<"3 / 792">>,percentage => 0}}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"dbb56ff2-0f02-4ac1-8731-c657f7ff462f">>,value => #{cancellable => false,kind => report,message => <<"4 / 792">>,percentage => 0}}}},{'$gen_cast',{process_requests,[#{<<"id">> => 1636,<<"jsonrpc">> => <<"2.0">>,<<"method">> => <<"textDocument/codeAction">>,<<"params">> => #{<<"context">> => #{<<"diagnostics">> => []},<<"range">> => #{<<"end">> => #{<<"character">> => 13,<<"line">> => 125},<<"start">> => #{<<"character">> => 13,<<"line">> => 125}},<<"textDocument">> => #{<<"uri">> => <<"file:///home/jesperes/dev/kred/lib/kred/src/kred.erl">>}}}]}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"dbb56ff2-0f02-4ac1-8731-c657f7ff462f">>,value => #{cancellable => false,kind => report,message => <<"5 / 792">>,percentage => 0}}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"dbb56ff2-0f02-4ac1-8731-c657f7ff462f">>,value => #{cancellable => false,kind => report,message => <<"6 / 792">>,percentage => 0}}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"bb5e3277-fca0-4840-9fe0-0589073a56cd">>,value => #{cancellable => false,kind => report,message => <<"0 / 1">>,percentage => 0}}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"bb5e3277-fca0-4840-9fe0-0589073a56cd">>,value => #{kind => 'end',message => <<"1 / 1">>}}}},{'$gen_cast',{notification,<<"textDocument/publishDiagnostics">>,#{diagnostics => [#{message => <<"Bound variable in pattern: App">>,range => #{'end' => #{character => 39,line => 928},start => #{character => 36,line => 928}},severity => 4,source => <<"BoundVarInPattern">>},#{message => <<"Bound variable in pattern: App">>,range => #{'end' => #{character => 38,line => 949},start => #{character => 35,line => 949}},severity => 4,source => <<"BoundVarInPattern">>}],uri => <<"file:///home/jesperes/dev/kred/lib/kred/src/kred.erl">>}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"6dc24965-04c9-447e-a89b-7cf950a1916b">>,value => #{cancellable => false,kind => report,message => <<"0 / 1">>,percentage => 0}}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"6dc24965-04c9-447e-a89b-7cf950a1916b">>,value => #{kind => 'end',message => <<"1 / 1">>}}}},{'$gen_cast',{notification,<<"textDocument/publishDiagnostics">>,#{diagnostics => [#{message => <<"Bound variable in pattern: RecordName">>,range => #{'end' => #{character => 40,line => 150},start => #{character => 30,line => 150}},severity => 4,source => <<"BoundVarInPattern">>},#{message => <<"Bound variable in pattern: Size">>,range => #{'end' => #{character => 38,line => 489},start => #{character => 34,line => 489}},severity => 4,source => <<"BoundVarInPattern">>}],uri => <<"file:///home/jesperes/dev/kred/lib/log_and_alarm/src/klog.erl">>}}},{'$gen_cast',{notification,<<"$/progress">>,#{token => <<"dba59933-c6af-46d7-ab87-6ded071d66eb">>,value => #{cancellable => false,kind => report,message => <<"1 / 48">>,percentage => 2}}}}], links: [<0.159.0>], dictionary: [], trap_exit: false, status: running, heap_size: 46422, stack_size: 28, reductions: 6213050; neighbours:
[2021-04-09T08:48:32.443669+02:00] supervisor.erl:707 <0.159.0> [error] Supervisor: {local,els_sup}. Context: child_terminated. Reason: {timeout,{gen_server,call,[els_code_lens_provider,{cancel_request,<0.460.0>}]}}. Offender: id=els_server,pid=<0.188.0>.
[2021-04-09T08:48:32.443966+02:00] /home/jesperes/dev/erlang_ls/apps/els_lsp/src/els_server.erl:105 <0.16695.0> [info] Starting els_server...
[2021-04-09T08:48:32.444111+02:00] supervisor.erl:1433 <0.159.0> [info] Supervisor: {local,els_sup}. Started: id=els_server,pid=<0.16695.0>.
[2021-04-09T08:48:32.444223+02:00] /home/jesperes/dev/erlang_ls/apps/els_core/src/els_stdio.erl:27 <0.16696.0> [info] Starting stdio server...
[2021-04-09T08:48:32.473718+02:00] supervisor.erl:844 <0.180.0> [error] Supervisor: {local,els_background_job_sup}. Context: shutdown_error. Reason: killed. Offender: id=els_background_job,pid=<0.460.0>.

[jesperes]

After some redbugging on the els_stdio process, it seems like the issue is rather that Emacs stops sending commands to erlang_ls after the crash. A number of outgoing messages are sent (progress messages sent by erlang_ls while indexing), but after the crash, Emacs stops sending commands.