Setup rails for JSON logging

openc3-cosmos-cmd-tlm-api/Gemfile

@@ -23,6 +23,9 @@ gem 'bootsnap', '>= 1.9.3', require: false
 # Use Rack CORS for handling Cross-Origin Resource Sharing (CORS), making cross-origin AJAX possible
 gem 'rack-cors', '~> 2.0'
 
+# Use gem to get JSON logs
+gem "rails_semantic_logger", '~> 4.17.0'
+
 group :development, :test do
   # Call 'byebug' anywhere in the code to stop execution and get a debugger console
   gem 'byebug', platforms: [:mri, :mingw, :x64_mingw]

openc3-cosmos-cmd-tlm-api/config/application.rb

@@ -57,5 +57,15 @@ class Application < Rails::Application
         OpenTelemetry::Instrumentation::Rack::Middlewares::TracerMiddleware
       )
     end
+
+    # Setup structured logging
+    require 'openc3/utilities/cosmos_rails_formatter'
+    config.log_level = ENV["LOG_LEVEL"] || :info
+    config.log_tags = {
+      request_id: :request_id,
+      token: -> request { request.headers['HTTP_AUTHORIZATION'] || request.query_parameters[:authorization] }
+    }
+    config.rails_semantic_logger.add_file_appender = false
+    config.semantic_logger.add_appender(io: $stdout, formatter: OpenC3::CosmosRailsFormatter.new)
   end
 end

openc3-cosmos-cmd-tlm-api/config/environments/development.rb

@@ -46,7 +46,7 @@
   # config.action_view.annotate_rendered_view_with_filenames = true
 
   # Disable ActionCable logging
-  ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
+  # ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
 
   # Uncomment if you wish to allow Action Cable access from any origin.
   # config.action_cable.disable_request_forgery_protection = true

openc3-cosmos-cmd-tlm-api/config/environments/production.rb

@@ -40,10 +40,10 @@
 
   # Include generic and useful information about system operation, but avoid logging too much
   # information to avoid inadvertent exposure of personally identifiable information (PII).
-  config.log_level = :info
+  # config.log_level = :info
 
   # Prepend all log lines with the following tags.
-  config.log_tags = [ :request_id ]
+  # config.log_tags = [ :request_id ]
 
   # Use a different cache store in production.
   # config.cache_store = :mem_cache_store
@@ -60,16 +60,16 @@
   config.active_support.report_deprecations = false
 
   # Use default logging formatter so that PID and timestamp are not suppressed.
-  config.log_formatter = ::Logger::Formatter.new
+  #config.log_formatter = ::Logger::Formatter.new
 
   # Use a different logger for distributed setups.
   # require "syslog/logger"
   # config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new "app-name")
 
-  logger           = ActiveSupport::Logger.new(STDOUT)
-  logger.formatter = config.log_formatter
-  config.logger    = ActiveSupport::TaggedLogging.new(logger)
+  # logger           = ActiveSupport::Logger.new(STDOUT)
+  # logger.formatter = config.log_formatter
+  # config.logger    = ActiveSupport::TaggedLogging.new(logger)
 
-  # Disable ActionCable logging
-  ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
+  # # Disable ActionCable logging
+  # ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
 end

openc3-cosmos-cmd-tlm-api/config/puma.rb

@@ -35,3 +35,8 @@
 
 # Allow puma to be restarted by `rails restart` command.
 plugin :tmp_restart
+
+on_worker_boot do
+  # Re-open appenders after forking the process
+  SemanticLogger.reopen
+end

openc3-cosmos-script-runner-api/Gemfile

@@ -23,6 +23,9 @@ gem 'bootsnap', '>= 1.9.3', require: false
 # Use Rack CORS for handling Cross-Origin Resource Sharing (CORS), making cross-origin AJAX possible
 gem 'rack-cors', '~> 2.0'
 
+# Use gem to get JSON logs
+gem "rails_semantic_logger", '~> 4.17.0'
+
 group :development, :test do
   # Call 'byebug' anywhere in the code to stop execution and get a debugger console
   gem 'byebug', platforms: [:mri, :mingw, :x64_mingw]

openc3-cosmos-script-runner-api/config/application.rb

@@ -54,5 +54,15 @@ class Application < Rails::Application
         OpenTelemetry::Instrumentation::Rack::Middlewares::TracerMiddleware
       )
     end
+
+    # Setup structured logging
+    require 'openc3/utilities/cosmos_rails_formatter'
+    config.log_level = ENV["LOG_LEVEL"] || :info
+    config.log_tags = {
+      request_id: :request_id,
+      token: -> request { request.headers['HTTP_AUTHORIZATION'] || request.query_parameters[:authorization] }
+    }
+    config.rails_semantic_logger.add_file_appender = false
+    config.semantic_logger.add_appender(io: $stdout, formatter: OpenC3::CosmosRailsFormatter.new)
   end
 end

openc3-cosmos-script-runner-api/config/environments/development.rb

@@ -46,7 +46,7 @@
   # config.action_view.annotate_rendered_view_with_filenames = true
 
   # Disable ActionCable logging
-  ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
+  # ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
 
   # Uncomment if you wish to allow Action Cable access from any origin.
   # config.action_cable.disable_request_forgery_protection = true

openc3-cosmos-script-runner-api/config/environments/production.rb

@@ -40,10 +40,10 @@
 
   # Include generic and useful information about system operation, but avoid logging too much
   # information to avoid inadvertent exposure of personally identifiable information (PII).
-  config.log_level = :info
+  # config.log_level = :info
 
   # Prepend all log lines with the following tags.
-  config.log_tags = [ :request_id ]
+  # config.log_tags = [ :request_id ]
 
   # Use a different cache store in production.
   # config.cache_store = :mem_cache_store
@@ -60,16 +60,16 @@
   config.active_support.report_deprecations = false
 
   # Use default logging formatter so that PID and timestamp are not suppressed.
-  config.log_formatter = ::Logger::Formatter.new
+  # config.log_formatter = ::Logger::Formatter.new
 
   # Use a different logger for distributed setups.
   # require "syslog/logger"
   # config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new "app-name")
 
-  logger           = ActiveSupport::Logger.new(STDOUT)
-  logger.formatter = config.log_formatter
-  config.logger    = ActiveSupport::TaggedLogging.new(logger)
+  # logger           = ActiveSupport::Logger.new(STDOUT)
+  # logger.formatter = config.log_formatter
+  # config.logger    = ActiveSupport::TaggedLogging.new(logger)
 
   # Disable ActionCable logging
-  ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
+  # ActionCable.server.config.logger = Logger.new(STDOUT, level: Logger::ERROR)
 end

openc3-cosmos-script-runner-api/config/puma.rb

@@ -35,3 +35,8 @@
 
 # Allow puma to be restarted by `rails restart` command.
 plugin :tmp_restart
+
+on_worker_boot do
+  # Re-open appenders after forking the process
+  SemanticLogger.reopen
+end

openc3/lib/openc3/operators/operator.rb

@@ -195,12 +195,14 @@ def output_increment
       if @process
         stdout = @process.io.stdout.extract
         if stdout.length > 0
-          STDOUT.puts "STDOUT #{stdout.length} bytes from #{cmd_line()}:"
+          message = "STDOUT #{stdout.length} bytes from #{cmd_line()}:"
+          STDOUT.puts Logger.build_log_data(Logger::INFO_LEVEL, message, user: nil, type: OpenC3::Logger::LOG, url: nil).as_json(:allow_nan => true).to_json(:allow_nan => true)
           STDOUT.puts stdout
         end
         stderr = @process.io.stderr.extract
         if stderr.length > 0
-          STDERR.puts "STDERR #{stderr.length} bytes from #{cmd_line()}:"
+          message = "STDERR #{stderr.length} bytes from #{cmd_line()}:"
+          STDERR.puts Logger.build_log_data(Logger::ERROR_LEVEL, message, user: nil, type: OpenC3::Logger::LOG, url: nil).as_json(:allow_nan => true).to_json(:allow_nan => true)
           STDERR.puts stderr
         end
       end

openc3/lib/openc3/utilities/cosmos_rails_formatter.rb

@@ -0,0 +1,60 @@
+require "json"
+require 'openc3/utilities/logger'
+require 'openc3/utilities/authorization'
+
+# Use with Rails Semantic Logger
+module OpenC3
+  class CosmosRailsFormatter
+    include OpenC3::Authorization
+
+    def call(log, _appender = nil)
+      #<SemanticLogger::Log:0x0000ffffa5002b20 @level=:info, @thread_name="puma srv tp 001", @name="MicroservicesController",
+      # @time=2024-09-22 18:04:27.955490052 +0000, @tags=[], @named_tags={}, @level_index=2, @message="Completed #traefik",
+      # @payload={:controller=>"MicroservicesController", :action=>"traefik", :format=>"HTML", :method=>"GET",
+      # :path=>"/openc3-api/traefik", :status=>200, :view_runtime=>0.41, :allocations=>1438, :status_message=>"OK",
+      # :exception_object=>#<RuntimeError: death>}, @named_tags={:request_id=>"65446ef0-734e-4488-aa5f-e85b7b573fd8"},
+      # @duration=3.2528750002384186, @metric=nil, @metric_amount=nil, @dimensions=nil, @exception=nil, @backtrace=nil>
+      message = log.message
+      other = {}
+      other[:thread_name] = log.thread_name
+      other[:duration] = log.duration if log.duration
+      named_tags = log.named_tags
+      username = nil
+      if named_tags
+        other[:request_id] = named_tags[:request_id]
+        if named_tags[:token]
+          begin
+            user = user_info(named_tags[:token])
+          rescue
+            user = {}
+          end
+          username = user['username']
+          # Open Source username (EE has the actual username)
+          username ||= 'anonymous'
+        end
+      end
+      username ||= 'anonymous'
+      payload = log.payload
+      if payload
+        other[:path] = payload[:path]
+        other[:status] = payload[:status]
+        other[:controller] = payload[:controller]
+        other[:action] = payload[:action]
+        other[:format] = payload[:format]
+        other[:method] = payload[:method]
+        other[:allocations] = payload[:allocations]
+        other[:view_runtime] = payload[:view_runtime]
+        if payload[:exception_object]
+          other[:exception_message] = payload[:exception_object].message
+          other[:exception_class] = payload[:exception_object].class.to_s
+          other[:exception_backtrace] = payload[:exception_object].backtrace.as_json
+        end
+      end
+      # This happens for a separate exception log entry which we want to not include the backtrace a second time
+      if log.exception
+        message = "Exception was raised - #{log.exception.class}:#{log.exception.message}" unless message
+      end
+      return OpenC3::Logger.build_log_data(log.level.to_s.upcase, message, user: username, type: OpenC3::Logger::LOG, url: nil, other: other).as_json(:allow_nan => true).to_json(:allow_nan => true)
+    end
+  end
+end

openc3/lib/openc3/utilities/logger.rb

@@ -97,53 +97,53 @@ def self.microservice_name=(name)
     #   below the method name log level.
     # @param block [Proc] Block to call which should return a string to append
     #   to the log message
-    def debug(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      log_message(DEBUG_LEVEL, message, scope: scope, user: user, type: type, url: url, &block) if @level <= DEBUG
+    def debug(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      log_message(DEBUG_LEVEL, message, scope: scope, user: user, type: type, url: url, other: other, &block) if @level <= DEBUG
     end
 
     # (see #debug)
-    def info(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      log_message(INFO_LEVEL, message, scope: scope, user: user, type: type, url: url, &block) if @level <= INFO
+    def info(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      log_message(INFO_LEVEL, message, scope: scope, user: user, type: type, url: url, other: other, &block) if @level <= INFO
     end
 
     # (see #debug)
-    def warn(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      log_message(WARN_LEVEL, message, scope: scope, user: user, type: type, url: url, &block) if @level <= WARN
+    def warn(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      log_message(WARN_LEVEL, message, scope: scope, user: user, type: type, url: url, other: other, &block) if @level <= WARN
     end
 
     # (see #debug)
-    def error(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      log_message(ERROR_LEVEL, message, scope: scope, user: user, type: type, url: url, &block) if @level <= ERROR
+    def error(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      log_message(ERROR_LEVEL, message, scope: scope, user: user, type: type, url: url, other: other, &block) if @level <= ERROR
     end
 
     # (see #debug)
-    def fatal(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      log_message(FATAL_LEVEL, message, scope: scope, user: user, type: type, url: url, &block) if @level <= FATAL
+    def fatal(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      log_message(FATAL_LEVEL, message, scope: scope, user: user, type: type, url: url, other: other, &block) if @level <= FATAL
     end
 
     # (see #debug)
-    def self.debug(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      self.instance.debug(message, scope: scope, user: user, type: type, url: url, &block)
+    def self.debug(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      self.instance.debug(message, scope: scope, user: user, type: type, url: url, other: other, &block)
     end
 
     # (see #debug)
-    def self.info(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      self.instance.info(message, scope: scope, user: user, type: type, url: url, &block)
+    def self.info(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      self.instance.info(message, scope: scope, user: user, type: type, url: url, other: other, &block)
     end
 
     # (see #debug)
-    def self.warn(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      self.instance.warn(message, scope: scope, user: user, type: type, url: url, &block)
+    def self.warn(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      self.instance.warn(message, scope: scope, user: user, type: type, url: url, other: other, &block)
     end
 
     # (see #debug)
-    def self.error(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      self.instance.error(message, scope: scope, user: user, type: type, url: url, &block)
+    def self.error(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      self.instance.error(message, scope: scope, user: user, type: type, url: url, other: other, &block)
     end
 
     # (see #debug)
-    def self.fatal(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, &block)
-      self.instance.fatal(message, scope: scope, user: user, type: type, url: url, &block)
+    def self.fatal(message = nil, scope: @@scope, user: nil, type: LOG, url: nil, other: nil, &block)
+      self.instance.fatal(message, scope: scope, user: user, type: type, url: url, other: other, &block)
     end
 
     # @return [Logger] The logger instance
@@ -172,23 +172,33 @@ def scope=(scope)
       @@scope = scope
     end
 
+    def build_log_data(log_level, message, user: nil, type: nil, url: nil, other: nil, &block)
+      time = Time.now.utc
+      # timestamp iso8601 with 6 decimal places to match the python output format
+      data = { time: time.to_nsec_from_epoch, '@timestamp' => time.iso8601(6), level: log_level }
+      data[:microservice_name] = @microservice_name if @microservice_name
+      data[:detail] = @detail_string if @detail_string
+      data[:user] = user if user # EE: If a user is passed, put its name. Don't include user data if no user was passed.
+      if block_given?
+        message = yield
+      end
+      data[:container_name] = @container_name
+      data[:message] = message if message
+      data[:type] = type if type
+      data[:url] = url if url
+      data = data.merge(other) if other
+      return data
+    end
+
+    def self.build_log_data(log_level, message, user: nil, type: nil, url: nil, other: nil)
+      self.instance.build_log_data(log_level, message, user: user, type: type, url: url, other: other)
+    end
+
     protected
 
-    def log_message(log_level, message, scope:, user:, type:, url:)
+    def log_message(log_level, message, scope:, user:, type:, url:, other: nil, &block)
       @@mutex.synchronize do
-        time = Time.now.utc
-        # timestamp iso8601 with 6 decimal places to match the python output format
-        data = { time: time.to_nsec_from_epoch, '@timestamp' => time.iso8601(6), level: log_level }
-        data[:microservice_name] = @microservice_name if @microservice_name
-        data[:detail] = @detail_string if @detail_string
-        data[:user] = user if user # EE: If a user is passed, put its name. Don't include user data if no user was passed.
-        if block_given?
-          message = yield
-        end
-        data[:container_name] = @container_name
-        data[:message] = message
-        data[:type] = type
-        data[:url] = url if url
+        data = build_log_data(log_level, message, user: user, type: type, url: url, other: other, &block)
         if @stdout
           case log_level
           when WARN_LEVEL, ERROR_LEVEL, FATAL_LEVEL