Merge pull request #9679 from opf/grape-logging

Allow request logging for grape with lograge and optional JSON logging

Gemfile

@@ -295,6 +295,7 @@ gem 'bootsnap', '~> 1.7.0', require: false
 
 # API gems
 gem 'grape', '~> 1.5.0'
+gem 'grape_logging', '~> 1.8.4'
 gem 'roar', '~> 1.1.0'
 
 # CORS for API

Gemfile.lock

@@ -511,6 +511,9 @@ GEM
       mustermann-grape (~> 1.0.0)
       rack (>= 1.3.0)
       rack-accept
+    grape_logging (1.8.4)
+      grape
+      rack
     gravatar_image_tag (1.2.0)
     hashdiff (1.0.1)
     hashery (2.1.2)
@@ -1003,6 +1006,7 @@ DEPENDENCIES
   fuubar (~> 2.5.0)
   gon (~> 6.4.0)
   grape (~> 1.5.0)
+  grape_logging (~> 1.8.4)
   grids!
   html-pipeline (~> 2.14.0)
   htmldiff

config/initializers/grape_logging.rb

@@ -0,0 +1,14 @@
+OpenProject::Application.configure do
+  config.after_initialize do
+    ActiveSupport::Notifications.subscribe('openproject_grape_logger') do |_, _, _, _, payload|
+      time = payload[:time]
+      attributes = {
+        duration: time[:total],
+        db: time[:db],
+        view: time[:view]
+      }.merge(payload.except(:time))
+
+      Rails.logger.info OpenProject::Logging.formatter.call(attributes)
+    end
+  end
+end

config/initializers/lograge.rb

@@ -1,9 +1,12 @@
 Rails.application.configure do
-  config.lograge.enabled = Rails.env.production? || ENV['OPENPROJECT_LOGRAGE_ENABLED']
+  next unless OpenProject::Logging.lograge_enabled?
+
+  config.lograge.enabled = true
+  config.lograge.formatter = OpenProject::Logging.formatter
   config.lograge.base_controller_class = %w[ActionController::Base]
 
   # Add custom data to event payload
   config.lograge.custom_payload do |controller|
-    ::OpenProject::Logging::LogDelegator.controller_payload_hash controller
+    ::OpenProject::Logging.extend_payload!({}, { controller: controller })
   end
 end

config/initializers/sentry.rb

@@ -29,6 +29,9 @@ if OpenProject::Logging::SentryLogger.enabled?
     # Submit events as delayed job
     config.async = lambda { |event, hint| ::SentryJob.perform_later(event, hint) }
 
+    # Don't send loaded modules
+    config.send_modules = false
+
     # Cleanup backtrace
     config.backtrace_cleanup_callback = lambda do |backtrace|
       Rails.backtrace_cleaner.clean(backtrace)

frontend/src/app/sentry/sentry-reporter.ts

@@ -181,6 +181,7 @@ export class SentryReporter implements ErrorReporter {
    * @param scope
    */
   private setupContext(scope:Scope) {
+    scope.setTag('code_origin', 'frontend');
     scope.setTag('locale', window.I18n.locale);
     scope.setTag('domain', window.location.hostname);
     scope.setTag('url_path', window.location.pathname);

lib/api/root_api.rb

@@ -39,6 +39,10 @@ module API
     include OpenProject::Authentication::Scope
     extend API::Utilities::GrapeHelper
 
+    insert_before Grape::Middleware::Error,
+                  ::GrapeLogging::Middleware::RequestLogger,
+                  { instrumentation_key: 'openproject_grape_logger' }
+
     content_type :json, 'application/json; charset=utf-8'
 
     use OpenProject::Authentication::Manager

lib/open_project.rb

@@ -31,7 +31,7 @@
 require 'redmine/menu_manager'
 require 'redmine/search'
 require 'open_project/custom_field_format'
-require 'open_project/logging/log_delegator'
+require 'open_project/logging'
 require 'open_project/patches'
 require 'redmine/mime_type'
 require 'open_project/custom_styles/design'

lib/open_project/configuration.rb

@@ -204,7 +204,10 @@ module OpenProject
       'ldap_groups_disable_sync_job' => false,
 
       # Slow query logging threshold in ms
-      'sql_slow_query_threshold' => 2000
+      'sql_slow_query_threshold' => 2000,
+
+      # Use lograge to format logs, off by default
+      'lograge_formatter' => nil
     }
 
     @config = nil

lib/open_project/logging.rb

@@ -0,0 +1,59 @@
+require_relative 'logging/log_delegator'
+
+module OpenProject
+  module Logging
+    class << self
+      ##
+      # Do we use lograge in the end to perform the payload output
+      def lograge_enabled?
+        OpenProject::Configuration.lograge_formatter.present?
+      end
+
+      ##
+      # The lograge class to output the payload object
+      def formatter
+        @formatter ||= begin
+          formatter_setting = OpenProject::Configuration.lograge_formatter || 'key_value'
+          "Lograge::Formatters::#{formatter_setting.classify}"
+            .constantize
+            .new
+        end
+      end
+
+      ##
+      # Extend a payload to be logged with additional information
+      # @param context {Hash} The context of the log, might contain controller or sentry related keys
+      def extend_payload!(payload, context)
+        payload_extenders.reduce(payload.dup) do |hash, handler|
+          res = handler.call(context)
+          hash.merge!(res) if res.is_a?(Hash)
+          hash
+        rescue StandardError => e
+          Rails.logger.error "Failed to extend payload in #{handler.inspect}: #{e.message}"
+          hash
+        end
+      end
+
+      ##
+      # Get a set of extenders that may add to the logging context payload
+      def payload_extenders
+        @payload_extenders ||= [
+          method(:default_payload)
+        ]
+      end
+
+      ##
+      # Register a new payload extender
+      # for all logging purposes
+      def add_payload_extender(&block)
+        payload_extenders << block
+      end
+
+      private
+
+      def default_payload(_context)
+        { user: User.current.try(:id) }
+      end
+    end
+  end
+end

lib/open_project/logging/log_delegator.rb

@@ -73,14 +73,6 @@ module OpenProject
           @handlers[key] = handler
         end
 
-        ##
-        # Create a payload for lograge from a controller request line
-        def controller_payload_hash(_controller)
-          {
-            user: User.current.try(:id)
-          }
-        end
-
         private
 
         def default_handlers
@@ -100,16 +92,9 @@ module OpenProject
         ##
         # Create a context string
         def context_string(context)
-          %i[current_user project reference]
-            .map do |key|
-              value = context[key]
-
-              if value
-                "[#{key}=#{value}]"
-              end
-            end
-            .compact
-            .join(' ')
+          payload = context.slice(%i[current_user project reference]).compact
+          extended = OpenProject::Logging.extend_payload!(payload, context)
+          OpenProject::Logging.formatter.call extended
         end
       end
     end

lib/open_project/logging/sentry_logger.rb

@@ -23,18 +23,6 @@ module OpenProject
           @sentry_dsn ||= OpenProject::Configuration.sentry_dsn.presence || ENV["SENTRY_DSN"].presence
         end
 
-        ##
-        # The active set of callback handlers
-        def scope_extenders
-          @scope_extenders ||= []
-        end
-
-        ##
-        # Register a new context builder callback
-        def register_scope(&block)
-          scope_extenders << block
-        end
-
         private
 
         ##
@@ -68,14 +56,12 @@ module OpenProject
             sentry_scope.set_fingerprint [ref]
           end
 
-          if (extra = log_context[:extra])
-            sentry_scope.set_extras extra
-          end
+          sentry_scope.set_tags code_origin: 'backend'
 
-          # Collect additional data to send
-          scope_extenders.each do |builder|
-            builder.call(sentry_scope, log_context)
-          end
+          # Collect extra information from payload extender
+          # e.g., with saas tenant information
+          extra = ::OpenProject::Logging.extend_payload! log_context[:extra] || {}, { sentry_scope: sentry_scope }
+          sentry_scope.set_extras extra
         end
 
         def filter_params(params)
@@ -84,7 +70,7 @@ module OpenProject
 
           # make sure to return plain hash rather than ActionController::Parameters
           res.respond_to?(:to_unsafe_h) ? res.to_unsafe_h : res.to_h
-        rescue => e
+        rescue StandardError => e
           { filter_failed: e.message }
         end
       end

spec/lib/open_project/logging/log_extender_spec.rb

@@ -0,0 +1,95 @@
+#-- copyright
+# OpenProject is an open source project management software.
+# Copyright (C) 2012-2021 the OpenProject GmbH
+#
+# This program is free software; you can redistribute it and/or
+# modify it under the terms of the GNU General Public License version 3.
+#
+# OpenProject is a fork of ChiliProject, which is a fork of Redmine. The copyright follows:
+# Copyright (C) 2006-2013 Jean-Philippe Lang
+# Copyright (C) 2010-2013 the ChiliProject Team
+#
+# This program is free software; you can redistribute it and/or
+# modify it under the terms of the GNU General Public License
+# as published by the Free Software Foundation; either version 2
+# of the License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+#
+# See docs/COPYRIGHT.rdoc for more details.
+#++
+
+require 'spec_helper'
+
+describe OpenProject::Logging, 'Log extenders' do
+  subject { described_class.extend_payload!(payload, input_context) }
+
+  let(:payload) do
+    { method: 'GET', action: 'something', controller: 'SomeController' }
+  end
+
+  let(:input_context) do
+    {}
+  end
+
+  context 'with an extender returning keys' do
+    let(:return_value) do
+      { some_hash: 123 }
+    end
+
+    let(:extender) do
+      ->(_context) do
+        return_value
+      end
+    end
+
+    before do
+      described_class.add_payload_extender(&extender)
+    end
+
+    after do
+      described_class.instance_variable_set('@payload_extenders', nil)
+    end
+
+    it 'calls that extender as well as the default one' do
+      allow(extender).to receive(:call).and_call_original
+
+      expect(subject.keys).to contain_exactly :method, :action, :controller, :some_hash, :user
+      expect(subject[:some_hash]).to eq 123
+    end
+  end
+
+  context 'with an extender raising an error' do
+    let(:return_value) do
+      { some_hash: 123 }
+    end
+
+    let(:extender) do
+      ->(_context) do
+        raise "This is not good."
+      end
+    end
+
+    before do
+      described_class.add_payload_extender(&extender)
+    end
+
+    after do
+      described_class.instance_variable_set('@payload_extenders', nil)
+    end
+
+    it 'does not break the returned payload' do
+      allow(extender).to receive(:call).and_call_original
+
+      expect(subject.keys).to contain_exactly :method, :action, :controller, :user
+      expect(subject[:some_hash]).to eq nil
+    end
+  end
+end