Use log trace instead of printing to stderr (#461)

Author: vinistock

lib/ruby_lsp/ruby_lsp_rails/addon.rb

@@ -28,14 +28,15 @@ def initialize
         # the real client is initialized, features that depend on it will not be blocked by using the NullClient
         @rails_runner_client = T.let(NullClient.new, RunnerClient)
         @global_state = T.let(nil, T.nilable(GlobalState))
+        @outgoing_queue = T.let(nil, T.nilable(Thread::Queue))
         @addon_mutex = T.let(Mutex.new, Mutex)
         @client_mutex = T.let(Mutex.new, Mutex)
         @client_mutex.lock
 
         Thread.new do
           @addon_mutex.synchronize do
             # We need to ensure the Rails client is fully loaded before we activate the server addons
-            @client_mutex.synchronize { @rails_runner_client = RunnerClient.create_client }
+            @client_mutex.synchronize { @rails_runner_client = RunnerClient.create_client(T.must(@outgoing_queue)) }
           end
         end
       end
@@ -45,11 +46,13 @@ def rails_runner_client
         @addon_mutex.synchronize { @rails_runner_client }
       end
 
-      sig { override.params(global_state: GlobalState, message_queue: Thread::Queue).void }
-      def activate(global_state, message_queue)
+      sig { override.params(global_state: GlobalState, outgoing_queue: Thread::Queue).void }
+      def activate(global_state, outgoing_queue)
         @global_state = global_state
-        $stderr.puts("Activating Ruby LSP Rails add-on v#{version}")
-        register_additional_file_watchers(global_state: global_state, message_queue: message_queue)
+        @outgoing_queue = outgoing_queue
+        @outgoing_queue << Notification.window_log_message("Activating Ruby LSP Rails add-on v#{VERSION}")
+
+        register_additional_file_watchers(global_state: global_state, outgoing_queue: outgoing_queue)
         @global_state.index.register_enhancement(IndexingEnhancement.new)
 
         # Start booting the real client in a background thread. Until this completes, the client will be a NullClient
@@ -123,11 +126,11 @@ def workspace_did_change_watched_files(changes)
         end
       end
 
-      sig { params(global_state: GlobalState, message_queue: Thread::Queue).void }
-      def register_additional_file_watchers(global_state:, message_queue:)
+      sig { params(global_state: GlobalState, outgoing_queue: Thread::Queue).void }
+      def register_additional_file_watchers(global_state:, outgoing_queue:)
         return unless global_state.supports_watching_files
 
-        message_queue << Request.new(
+        outgoing_queue << Request.new(
           id: "ruby-lsp-rails-file-watcher",
           method: "client/registerCapability",
           params: Interface::RegistrationParams.new(

lib/ruby_lsp/ruby_lsp_rails/runner_client.rb

@@ -10,20 +10,34 @@ class RunnerClient
       class << self
         extend T::Sig
 
-        sig { returns(RunnerClient) }
-        def create_client
+        sig { params(outgoing_queue: Thread::Queue).returns(RunnerClient) }
+        def create_client(outgoing_queue)
           if File.exist?("bin/rails")
-            new
+            new(outgoing_queue)
           else
-            $stderr.puts(<<~MSG)
-              Ruby LSP Rails failed to locate bin/rails in the current directory: #{Dir.pwd}"
-            MSG
-            $stderr.puts("Server dependent features will not be available")
+            unless outgoing_queue.closed?
+              outgoing_queue << RubyLsp::Notification.window_log_message(
+                <<~MESSAGE.chomp,
+                  Ruby LSP Rails failed to locate bin/rails in the current directory: #{Dir.pwd}
+                  Server dependent features will not be available
+                MESSAGE
+                type: RubyLsp::Constant::MessageType::WARNING,
+              )
+            end
+
             NullClient.new
           end
         rescue Errno::ENOENT, StandardError => e # rubocop:disable Lint/ShadowedException
-          $stderr.puts("Ruby LSP Rails failed to initialize server: #{e.message}\n#{e.backtrace&.join("\n")}")
-          $stderr.puts("Server dependent features will not be available")
+          unless outgoing_queue.closed?
+            outgoing_queue << RubyLsp::Notification.window_log_message(
+              <<~MESSAGE.chomp,
+                Ruby LSP Rails failed to initialize server: #{e.full_message}
+                Server dependent features will not be available
+              MESSAGE
+              type: Constant::MessageType::ERROR,
+            )
+          end
+
           NullClient.new
         end
       end
@@ -39,8 +53,9 @@ class EmptyMessageError < StandardError; end
       sig { returns(String) }
       attr_reader :rails_root
 
-      sig { void }
-      def initialize
+      sig { params(outgoing_queue: Thread::Queue).void }
+      def initialize(outgoing_queue)
+        @outgoing_queue = T.let(outgoing_queue, Thread::Queue)
         @mutex = T.let(Mutex.new, Mutex)
         # Spring needs a Process session ID. It uses this ID to "attach" itself to the parent process, so that when the
         # parent ends, the spring process ends as well. If this is not set, Spring will throw an error while trying to
@@ -69,24 +84,23 @@ def initialize
         @stdout.binmode
         @stderr.binmode
 
-        $stderr.puts("Ruby LSP Rails booting server")
+        log_message("Ruby LSP Rails booting server")
         count = 0
 
         begin
           count += 1
           initialize_response = T.must(read_response)
           @rails_root = T.let(initialize_response[:root], String)
         rescue EmptyMessageError
-          $stderr.puts("Ruby LSP Rails is retrying initialize (#{count})")
+          log_message("Ruby LSP Rails is retrying initialize (#{count})")
           retry if count < MAX_RETRIES
         end
 
-        $stderr.puts("Finished booting Ruby LSP Rails server")
+        log_message("Finished booting Ruby LSP Rails server")
 
         unless ENV["RAILS_ENV"] == "test"
           at_exit do
             if @wait_thread.alive?
-              $stderr.puts("Ruby LSP Rails is force killing the server")
               sleep(0.5) # give the server a bit of time if we already issued a shutdown notification
               force_kill
             end
@@ -100,15 +114,21 @@ def initialize
       def register_server_addon(server_addon_path)
         send_notification("server_addon/register", server_addon_path: server_addon_path)
       rescue IncompleteMessageError
-        $stderr.puts("Ruby LSP Rails failed to register server addon #{server_addon_path}")
+        log_message(
+          "Ruby LSP Rails failed to register server addon #{server_addon_path}",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
         nil
       end
 
       sig { params(name: String).returns(T.nilable(T::Hash[Symbol, T.untyped])) }
       def model(name)
         make_request("model", name: name)
       rescue IncompleteMessageError
-        $stderr.puts("Ruby LSP Rails failed to get model information: #{@stderr.read}")
+        log_message(
+          "Ruby LSP Rails failed to get model information: #{@stderr.read}",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
         nil
       end
 
@@ -125,37 +145,50 @@ def association_target_location(model_name:, association_name:)
           association_name: association_name,
         )
       rescue => e
-        $stderr.puts("Ruby LSP Rails failed with #{e.message}: #{@stderr.read}")
+        log_message(
+          "Ruby LSP Rails failed with #{e.message}: #{@stderr.read}",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
+        nil
       end
 
       sig { params(name: String).returns(T.nilable(T::Hash[Symbol, T.untyped])) }
       def route_location(name)
         make_request("route_location", name: name)
       rescue IncompleteMessageError
-        $stderr.puts("Ruby LSP Rails failed to get route location: #{@stderr.read}")
+        log_message(
+          "Ruby LSP Rails failed to get route location: #{@stderr.read}",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
         nil
       end
 
       sig { params(controller: String, action: String).returns(T.nilable(T::Hash[Symbol, T.untyped])) }
       def route(controller:, action:)
         make_request("route_info", controller: controller, action: action)
       rescue IncompleteMessageError
-        $stderr.puts("Ruby LSP Rails failed to get route information: #{@stderr.read}")
+        log_message(
+          "Ruby LSP Rails failed to get route information: #{@stderr.read}",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
         nil
       end
 
       sig { void }
       def trigger_reload
-        $stderr.puts("Reloading Rails application")
+        log_message("Reloading Rails application")
         send_notification("reload")
       rescue IncompleteMessageError
-        $stderr.puts("Ruby LSP Rails failed to trigger reload")
+        log_message(
+          "Ruby LSP Rails failed to trigger reload",
+          type: RubyLsp::Constant::MessageType::ERROR,
+        )
         nil
       end
 
       sig { void }
       def shutdown
-        $stderr.puts("Ruby LSP Rails shutting down server")
+        log_message("Ruby LSP Rails shutting down server")
         send_message("shutdown")
         sleep(0.5) # give the server a bit of time to shutdown
         [@stdin, @stdout, @stderr].each(&:close)
@@ -214,7 +247,10 @@ def read_response
         response = JSON.parse(T.must(raw_response), symbolize_names: true)
 
         if response[:error]
-          $stderr.puts("Ruby LSP Rails error: " + response[:error])
+          log_message(
+            "Ruby LSP Rails error: #{response[:error]}",
+            type: RubyLsp::Constant::MessageType::ERROR,
+          )
           return
         end
 
@@ -229,6 +265,13 @@ def force_kill
         # Windows does not support the `TERM` signal, so we're forced to use `KILL` here
         Process.kill(T.must(Signal.list["KILL"]), @wait_thread.pid)
       end
+
+      sig { params(message: ::String, type: ::Integer).void }
+      def log_message(message, type: RubyLsp::Constant::MessageType::LOG)
+        return if @outgoing_queue.closed?
+
+        @outgoing_queue << RubyLsp::Notification.window_log_message(message, type: type)
+      end
     end
 
     class NullClient < RunnerClient
@@ -255,6 +298,11 @@ def rails_root
 
       private
 
+      sig { params(message: ::String, type: ::Integer).void }
+      def log_message(message, type: RubyLsp::Constant::MessageType::LOG)
+        # no-op
+      end
+
       sig { override.params(request: String, params: T.nilable(T::Hash[Symbol, T.untyped])).void }
       def send_message(request, params = nil)
         # no-op

test/ruby_lsp_rails/code_lens_test.rb

@@ -410,9 +410,7 @@ def generate_code_lens_for_source(source, file: "/fake.rb")
             params: { textDocument: { uri: uri }, position: { line: 0, character: 0 } },
           )
 
-          result = server.pop_response
-
-          assert_instance_of(RubyLsp::Result, result)
+          result = pop_result(server)
           result.response
         end
       end

test/ruby_lsp_rails/definition_test.rb

@@ -233,8 +233,7 @@ def generate_definitions_for_source(source, position)
             params: { textDocument: { uri: uri }, position: position },
           )
 
-          result = server.pop_response
-          assert_instance_of(RubyLsp::Result, result)
+          result = pop_result(server)
           result.response
         end
       end

test/ruby_lsp_rails/document_symbol_test.rb

@@ -437,7 +437,8 @@ def generate_document_symbols_for_source(source)
             params: { textDocument: { uri: uri }, position: { line: 0, character: 0 } },
           )
 
-          server.pop_response.response
+          result = pop_result(server)
+          result.response
         end
       end
     end

test/ruby_lsp_rails/hover_test.rb

@@ -197,7 +197,8 @@ def hover_on_source(source, position)
             params: { textDocument: { uri: uri }, position: position },
           )
 
-          server.pop_response.response
+          result = pop_result(server)
+          result.response
         end
       end
     end

test/ruby_lsp_rails/runner_client_test.rb

@@ -8,7 +8,8 @@ module RubyLsp
   module Rails
     class RunnerClientTest < ActiveSupport::TestCase
       setup do
-        @client = T.let(RunnerClient.new, RunnerClient)
+        @outgoing_queue = Thread::Queue.new
+        @client = T.let(RunnerClient.new(@outgoing_queue), RunnerClient)
       end
 
       teardown do
@@ -17,6 +18,7 @@ class RunnerClientTest < ActiveSupport::TestCase
         # On Windows, the server process sometimes takes a lot longer to shutdown and may end up getting force killed,
         # which makes this assertion flaky
         assert_predicate(@client, :stopped?) unless Gem.win_platform?
+        @outgoing_queue.close
       end
 
       # These are integration tests which start the server. For the more fine-grained tests, see `server_test.rb`.
@@ -44,30 +46,37 @@ class RunnerClientTest < ActiveSupport::TestCase
       test "falls back to null client when bin/rails is not found" do
         FileUtils.mv("bin/rails", "bin/rails_backup")
 
-        assert_output("", %r{Ruby LSP Rails failed to locate bin/rails in the current directory}) do
-          client = RunnerClient.create_client
+        outgoing_queue = Thread::Queue.new
+        client = RunnerClient.create_client(outgoing_queue)
 
-          assert_instance_of(NullClient, client)
-          assert_nil(client.model("User"))
-          assert_predicate(client, :stopped?)
-        end
+        assert_instance_of(NullClient, client)
+        assert_nil(client.model("User"))
+        assert_predicate(client, :stopped?)
+        log = pop_log_notification(outgoing_queue, RubyLsp::Constant::MessageType::WARNING)
+
+        assert_instance_of(RubyLsp::Notification, log)
+        assert_match("Ruby LSP Rails failed to locate bin/rails in the current directory", log.params.message)
       ensure
+        T.must(outgoing_queue).close
         FileUtils.mv("bin/rails_backup", "bin/rails")
       end
 
       test "failing to spawn server creates a null client" do
         FileUtils.mv("test/dummy/config/application.rb", "test/dummy/config/application.rb.bak")
-        assert_output(
-          "",
-          /Ruby LSP Rails failed to initialize server/,
-        ) do
-          client = RunnerClient.create_client
-
-          assert_instance_of(NullClient, client)
-          assert_nil(client.model("User"))
-          assert_predicate(client, :stopped?)
-        end
+
+        outgoing_queue = Thread::Queue.new
+        client = RunnerClient.create_client(outgoing_queue)
+
+        assert_instance_of(NullClient, client)
+        assert_nil(client.model("User"))
+        assert_predicate(client, :stopped?)
+
+        log = pop_log_notification(outgoing_queue, RubyLsp::Constant::MessageType::ERROR)
+
+        assert_instance_of(RubyLsp::Notification, log)
+        assert_match("Ruby LSP Rails failed to initialize server", log.params.message)
       ensure
+        T.must(outgoing_queue).close
         FileUtils.mv("test/dummy/config/application.rb.bak", "test/dummy/config/application.rb")
       end
 
@@ -78,14 +87,25 @@ class RunnerClientTest < ActiveSupport::TestCase
         File.write("test/dummy/config/application.rb", content + junk)
 
         capture_subprocess_io do
-          client = RunnerClient.create_client
+          outgoing_queue = Thread::Queue.new
+          client = RunnerClient.create_client(outgoing_queue)
 
           response = T.must(client.model("User"))
           assert(response.key?(:columns))
+        ensure
+          T.must(outgoing_queue).close
         end
       ensure
         FileUtils.mv("test/dummy/config/application.rb.bak", "test/dummy/config/application.rb")
       end
+
+      private
+
+      def pop_log_notification(message_queue, type)
+        log = message_queue.pop
+        log = message_queue.pop until log.params.type == type
+        log
+      end
     end
 
     class NullClientTest < ActiveSupport::TestCase