Fix using log extenders from sentry and core logger

config/initializers/grape_logging.rb

@@ -1,7 +1,5 @@
 OpenProject::Application.configure do
   config.after_initialize do
-    formatter = OpenProject::Logging::Lograge.formatter_class.new
-
     ActiveSupport::Notifications.subscribe('openproject_grape_logger') do |_, _, _, _, payload|
       time = payload.delete :time
       attributes = {
@@ -10,7 +8,7 @@ OpenProject::Application.configure do
         view: time[:view]
       }.merge(payload)
 
-      string = formatter.call(attributes)
+      string = OpenProject::Logging.formatter.call(attributes)
       Rails.logger.info string
     end
   end

config/initializers/lograge.rb

@@ -1,12 +1,12 @@
 Rails.application.configure do
-  next unless OpenProject::Logging::Lograge.enabled?
+  next unless OpenProject::Logging.lograge_enabled?
 
   config.lograge.enabled = true
-  config.lograge.formatter = OpenProject::Logging::Lograge.formatter_class.new
+  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)

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/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/lograge.rb

@@ -1,15 +0,0 @@
-module OpenProject
-  module Logging
-    module Lograge
-      def self.enabled?
-        OpenProject::Configuration.lograge_formatter.present?
-      end
-
-      def self.formatter_class
-        formatter_setting = OpenProject::Configuration.lograge_formatter || 'key_value'
-
-        "Lograge::Formatters::#{formatter_setting.classify}".constantize
-      end
-    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,10 @@ module OpenProject
             sentry_scope.set_fingerprint [ref]
           end
 
-          if (extra = log_context[:extra])
-            sentry_scope.set_extras extra
-          end
-
-          # 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 +68,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