Merge pull request #37 from glennsarti/unify-logging

Unify debug logging

Author: glennsarti

server/README.md

@@ -75,6 +75,7 @@ Usage: puppet-languageserver.rb [options]
     -c, --no-stop                    Do not stop the language server once a client disconnects.  Default is to stop
     -t, --timeout=TIMEOUT            Stop the language server if a client does not connection within TIMEOUT seconds.  A value of zero will not timeout.  Default is 10 seconds
     -d, --no-preload                 Do not preload Puppet information when the language server starts.  Default is to preload
+        --debug=DEBUG                Output debug information.  Either specify a filename or 'STDOUT'.  Default is no debug output
     -h, --help                       Prints this help
 ```
 

server/lib/puppet-languageserver.rb

@@ -11,6 +11,10 @@
 
 require 'puppet'
 require 'optparse'
+require 'logger'
+
+# Global variable holding the logger class
+$logger = nil
 
 module PuppetLanguageServer
   class CommandLineParser
@@ -21,7 +25,8 @@ def self.parse(options)
         :ipaddress => '127.0.0.1',
         :stop_on_client_exit => true,
         :connection_timeout => 10,
-        :preload_puppet => true
+        :preload_puppet => true,
+        :debug => nil
       }
 
       opt_parser = OptionParser.new do |opts|
@@ -47,6 +52,10 @@ def self.parse(options)
           args[:preload_puppet] = false
         end
 
+        opts.on('--debug=DEBUG', "Output debug information.  Either specify a filename or 'STDOUT'.  Default is no debug output") do |debug|
+          args[:debug] = debug
+        end
+
         opts.on('-h', '--help', 'Prints this help') do
           puts opts
           exit
@@ -59,45 +68,68 @@ def self.parse(options)
   end
 
   def self.log_message(severity, message)
-    puts "[#{severity.upcase}] #{message}"
+    return if $logger.nil?
+    
+    case severity
+    when :debug
+      $logger.debug(message)
+    when :info
+      $logger.info(message)
+    when :warn
+      $logger.info(message)
+    when :error
+      $logger.error(message)
+    when :fatal
+      $logger.fatal(message)
+    else
+      $logger.unknown(message)
+    end
   end
 
   def self.init_puppet(options)
-    log_message('information', "Using Puppet v#{Puppet.version}")
+    if options[:debug].nil?
+      $logger = nil
+    elsif options[:debug].downcase == 'stdout'
+      $logger = Logger.new($stdout)
+    elsif !options[:debug].to_s.empty?
+      # Log to file
+      $logger = Logger.new(options[:debug])
+    end
+    log_message(:info, "Using Puppet v#{Puppet.version}")
 
-    log_message('information', 'Initializing settings...')
+    log_message(:info, 'Initializing settings...')
     Puppet.initialize_settings
 
-    log_message('information', 'Creating puppet function environment...')
+    log_message(:info, 'Creating puppet function environment...')
     autoloader = Puppet::Parser::Functions.autoloader
     autoloader.loadall
 
-    log_message('information', "Using Facter v#{Facter.version}")
+    log_message(:info, "Using Facter v#{Facter.version}")
     if options[:preload_puppet]
-      log_message('information', 'Preloading Facter (Async)...')
+      log_message(:info, 'Preloading Facter (Async)...')
       PuppetLanguageServer::FacterHelper.load_facts_async
 
-      log_message('information', 'Preloading Puppet Types (Async)...')
+      log_message(:info, 'Preloading Puppet Types (Async)...')
       PuppetLanguageServer::PuppetHelper.load_types_async
 
-      log_message('information', 'Preloading Functions (Async)...')
+      log_message(:info, 'Preloading Functions (Async)...')
       PuppetLanguageServer::PuppetHelper.load_functions_async
     else
-      log_message('information', 'Skipping preloading Puppet')
+      log_message(:info, 'Skipping preloading Puppet')
     end
 
     true
   end
 
   def self.rpc_server(options)
-    log_message('information', 'Starting RPC Server...')
+    log_message(:info, 'Starting RPC Server...')
 
     server = PuppetLanguageServer::SimpleTCPServer.new
 
     server.add_service(options[:ipaddress], options[:port])
     trap('INT') { server.stop }
     server.start(PuppetLanguageServer::MessageRouter, options, 2)
 
-    log_message('information', 'Language Server exited.')
+    log_message(:info, 'Language Server exited.')
   end
 end

server/lib/puppet-languageserver/json_rpc_handler.rb

@@ -49,11 +49,11 @@ def initialize(*_options)
     end
 
     def post_init
-      PuppetLanguageServer::LogMessage('information', 'Client has connected to the language server')
+      PuppetLanguageServer.log_message(:info, 'Client has connected to the language server')
     end
 
     def unbind
-      PuppetLanguageServer::LogMessage('information', 'Client has disconnected from the language server')
+      PuppetLanguageServer.log_message(:info, 'Client has disconnected from the language server')
     end
 
     def extract_headers(raw_header)
@@ -112,13 +112,13 @@ def receive_data(data)
     def send_response(response)
       size = response.bytesize if response.respond_to?(:bytesize)
 # DEBUG ONLY
-puts "--- OUTBOUND\n#{response}\n---"
+PuppetLanguageServer.log_message(:debug, "--- OUTBOUND\n#{response}\n---")
       send_data "Content-Length: #{size}\r\n\r\n" + response
     end
 
     def parse_data(data)
 # DEBUG ONLY
-puts "--- INBOUND\n#{data}\n---"
+PuppetLanguageServer.log_message(:debug, "--- INBOUND\n#{data}\n---")
       result = JSON.parse(data)
       received_parsed_object(result)
     end
@@ -179,12 +179,12 @@ def process(obj)
 
     # This method must be overriden in the user's inherited class.
     def receive_request(request)
-      puts "request received:\n#{request.inspect}"
+      PuppetLanguageServer.log_message(:debug, "request received:\n#{request.inspect}")
     end
 
     # This method must be overriden in the user's inherited class.
     def receive_notification(method, params)
-      puts "notification received (method: #{method.inspect}, params: #{params.inspect})"
+      PuppetLanguageServer.log_message(:debug, "notification received (method: #{method.inspect}, params: #{params.inspect})")
     end
 
     def encode_json(data)
@@ -226,17 +226,17 @@ def send_show_message_notification(msg_type, message)
 
     # This method could be overriden in the user's inherited class.
     def parsing_error(_data, exception)
-      $stderr.puts "parsing error:\n#{exception.message}"
+      PuppetLanguageServer.log_message(:error, "parsing error:\n#{exception.message}")
     end
 
     # This method could be overriden in the user's inherited class.
     def batch_not_supported_error(_obj)
-      $stderr.puts 'batch request received but not implemented'
+      PuppetLanguageServer.log_message(:error, 'batch request received but not implemented')
     end
 
     # This method could be overriden in the user's inherited class.
     def invalid_request(_obj, code, message = nil)
-      $stderr.puts "error #{code}: #{message}"
+      PuppetLanguageServer.log_message(:error, "error #{code}: #{message}")
     end
 
     class Request

server/lib/puppet-languageserver/message_router.rb

@@ -28,11 +28,11 @@ def documents
     def receive_request(request)
       case request.rpc_method
       when 'initialize'
-        PuppetLanguageServer.log_message('debug', 'Received initialize method')
+        PuppetLanguageServer.log_message(:debug, 'Received initialize method')
         request.reply_result('capabilities' => PuppetLanguageServer::ServerCapabilites.capabilities)
 
       when 'shutdown'
-        PuppetLanguageServer.log_message('debug', 'Received shutdown method')
+        PuppetLanguageServer.log_message(:debug, 'Received shutdown method')
         request.reply_result(nil)
 
       when 'puppet/getVersion'
@@ -87,15 +87,15 @@ def receive_request(request)
         begin
           request.reply_result(PuppetLanguageServer::CompletionProvider.complete(content, line_num, char_num))
         rescue => exception
-          PuppetLanguageServer.log_message('error', "(textDocument/completion) #{exception}")
+          PuppetLanguageServer.log_message(:error, "(textDocument/completion) #{exception}")
           request.reply_result(LanguageServer::CompletionList.create_nil_response)
         end
 
       when 'completionItem/resolve'
         begin
           request.reply_result(PuppetLanguageServer::CompletionProvider.resolve(request.params.clone))
         rescue => exception
-          PuppetLanguageServer.log_message('error', "(completionItem/resolve) #{exception}")
+          PuppetLanguageServer.log_message(:error, "(completionItem/resolve) #{exception}")
           # Spit back the same params if an error happens
           request.reply_result(request.params)
         end
@@ -108,42 +108,42 @@ def receive_request(request)
         begin
           request.reply_result(PuppetLanguageServer::HoverProvider.resolve(content, line_num, char_num))
         rescue => exception
-          PuppetLanguageServer.log_message('error', "(textDocument/hover) #{exception}")
+          PuppetLanguageServer.log_message(:error, "(textDocument/hover) #{exception}")
           request.reply_result(LanguageServer::Hover.create_nil_response)
         end
       else
-        PuppetLanguageServer.log_message('error', "Unknown RPC method #{request.rpc_method}")
+        PuppetLanguageServer.log_message(:error, "Unknown RPC method #{request.rpc_method}")
       end
     end
 
     def receive_notification(method, params)
       case method
       when 'initialized'
-        PuppetLanguageServer.log_message('information', 'Client has received initialization')
+        PuppetLanguageServer.log_message(:info, 'Client has received initialization')
 
       when 'exit'
-        PuppetLanguageServer.log_message('information', 'Received exit notification.  Closing connection to client...')
+        PuppetLanguageServer.log_message(:info, 'Received exit notification.  Closing connection to client...')
         close_connection
 
       when 'textDocument/didOpen'
-        PuppetLanguageServer.log_message('information', 'Received textDocument/didOpen notification.')
+        PuppetLanguageServer.log_message(:info, 'Received textDocument/didOpen notification.')
         file_uri = params['textDocument']['uri']
         content = params['textDocument']['text']
         documents.set_document(file_uri, content)
         reply_diagnostics(file_uri, PuppetLanguageServer::DocumentValidator.validate(content))
 
       when 'textDocument/didChange'
-        PuppetLanguageServer.log_message('information', 'Received textDocument/didChange notification.')
+        PuppetLanguageServer.log_message(:info, 'Received textDocument/didChange notification.')
         file_uri = params['textDocument']['uri']
         content = params['contentChanges'][0]['text'] # TODO: Bad hardcoding zero
         documents.set_document(file_uri, content)
         reply_diagnostics(file_uri, PuppetLanguageServer::DocumentValidator.validate(content))
 
       when 'textDocument/didSave'
-        PuppetLanguageServer.log_message('information', 'Received textDocument/didSave notification.')
+        PuppetLanguageServer.log_message(:info, 'Received textDocument/didSave notification.')
 
       else
-        PuppetLanguageServer.log_message('error', "Unknown RPC notification #{method}")
+        PuppetLanguageServer.log_message(:error, "Unknown RPC notification #{method}")
       end
     end
   end

server/lib/puppet-languageserver/simple_tcp_server.rb

@@ -11,17 +11,17 @@ class SimpleTCPServerConnection
     # Methods to override
     def post_init
       # Override this to recieve events after a client is connected
-      puts('Client has connected')
+      PuppetLanguageServer.log_message(:debug, 'TCPSRV: Client has connected')
     end
 
     def unbind
       # Override this to recieve events after a client is disconnected
-      puts('Client has disconnected')
+      PuppetLanguageServer.log_message(:debug, 'TCPSRV: Client has disconnected')
     end
 
     def receive_data(data)
       # Override this to recieve data
-      puts("Received #{data.length} characters")
+      PuppetLanguageServer.log_message(:debug, "TCPSRV: Received #{data.length} characters")
     end
 
     # @api public
@@ -58,7 +58,7 @@ class SimpleTCPServer
 
     def log(message)
       # Override this to recieve log messages
-      puts "[TCPSRV] #{message}"
+      PuppetLanguageServer.log_message(:debug, "TCPSRV: #{message}")
     end
 
     ####
@@ -109,6 +109,14 @@ def start(handler = PuppetLanguageServer::SimpleTCPServerConnection, connection_
       log("Will stop the server in #{connection_options[:connection_timeout]} seconds if no connection is made.") if kill_timer > 0
       log('Will stop the server when client disconnects') if !@server_options[:stop_on_client_exit].nil? && @server_options[:stop_on_client_exit]
 
+      # Output to STDOUT.  This is required by Langugage Client so it knows the server is now running
+      S_LOCKER.synchronize do
+        SERVICES.each do |service,options|
+          $stdout.write("LANGUAGE SERVER RUNNING #{options[:hostname]}:#{options[:port]}\n")
+        end
+      end
+      $stdout.flush
+
       (begin
         sleep(1)
         # The kill_timer is used to stop the server if no clients have connected in X seconds