Using els_client with debug log level floods the logs and causes high CPU load

[gergaly]

Describe the bug
Starting up erlang_ls in shell mode with els_fake_stdio as the IO device used by the els_client causes forever loop.

To Reproduce
Start the erlang_ls in shell mode with els_fake_stdio and els_client (rebar3 shell).

Expected behavior
Logging should not cause more logging.

Actual behavior
The 'Started erlang_ls server' log message was issued. This caused a window/logMessage from the server to the client (in our case it is the els_client). The do_handle_message/3 function discarded the message and issued a log message. And the forever loop is now in action. Take a look at the first couple line of the log:

[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>
[2025-01-10T19:58:23.251992+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<"[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>\n">>,type => 4},method => <<"window/logMessage">>,jsonrpc => <<"2.0">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>
[2025-01-10T19:58:23.252292+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<"[2025-01-10T19:58:23.251992+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\"[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>\\n\">>,type => 4},method => <<\"window/logMessage\">>,jsonrpc => <<\"2.0\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\n">>,type => 4},method => <<"window/logMessage">>,jsonrpc => <<"2.0">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>
[2025-01-10T19:58:23.252630+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<"[2025-01-10T19:58:23.252292+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\"[2025-01-10T19:58:23.251992+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\"[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>\\\\n\\\">>,type => 4},method => <<\\\"window/logMessage\\\">>,jsonrpc => <<\\\"2.0\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\n\">>,type => 4},method => <<\"window/logMessage\">>,jsonrpc => <<\"2.0\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\n">>,type => 4},method => <<"window/logMessage">>,jsonrpc => <<"2.0">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>
[2025-01-10T19:58:23.253011+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<"[2025-01-10T19:58:23.252630+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\"[2025-01-10T19:58:23.252292+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\"[2025-01-10T19:58:23.251992+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\\\\\"[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>\\\\\\\\n\\\\\\\">>,type => 4},method => <<\\\\\\\"window/logMessage\\\\\\\">>,jsonrpc => <<\\\\\\\"2.0\\\\\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\\\n\\\">>,type => 4},method => <<\\\"window/logMessage\\\">>,jsonrpc => <<\\\"2.0\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\n\">>,type => 4},method => <<\"window/logMessage\">>,jsonrpc => <<\"2.0\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\n">>,type => 4},method => <<"window/logMessage">>,jsonrpc => <<"2.0">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>
[2025-01-10T19:58:23.253619+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<"[2025-01-10T19:58:23.253011+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\"[2025-01-10T19:58:23.252630+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\"[2025-01-10T19:58:23.252292+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\\\\\"[2025-01-10T19:58:23.251992+01:00] [debug] [CLIENT] Discarding Notification [message=#{params => #{message => <<\\\\\\\\\\\\\\\"[2025-01-10T19:58:23.248396+01:00] [info] Started erlang_ls server [els_app:bertok_start/1 L65] <0.1239.0>\\\\\\\\\\\\\\\\n\\\\\\\\\\\\\\\">>,type => 4},method => <<\\\\\\\\\\\\\\\"window/logMessage\\\\\\\\\\\\\\\">>,jsonrpc => <<\\\\\\\\\\\\\\\"2.0\\\\\\\\\\\\\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\\\\\\\n\\\\\\\">>,type => 4},method => <<\\\\\\\"window/logMessage\\\\\\\">>,jsonrpc => <<\\\\\\\"2.0\\\\\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\\\n\\\">>,type => 4},method => <<\\\"window/logMessage\\\">>,jsonrpc => <<\\\"2.0\\\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\\n\">>,type => 4},method => <<\"window/logMessage\">>,jsonrpc => <<\"2.0\">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>\n">>,type => 4},method => <<"window/logMessage">>,jsonrpc => <<"2.0">>}] [els_client:do_handle_messages/3 L435] <0.1309.0>

Pretty soon the escaping in the log file goes overdrive. The log file is 71 lines and 15MB size.

Context

• erlang_ls version (tag/sha): 1.1.0
• Editor used: no editor, shell mode testing
• LSP client used: els_client.erl

[gergaly]

As a workaround, by not using erlang_ls:configure_client_logging() the problem is gone.