Merge branch 'sh-add-exception-backtrace-production-log' into 'master'

Add backtrace to production_json.log

Closes #36297

See merge request gitlab-org/gitlab!20122

changelogs/unreleased/sh-add-exception-backtrace-production-log.yml

+---
+title: Add backtrace to production_json.log
+merge_request: 20122
+author:
+type: changed

config/initializers/lograge.rb

@@ -10,6 +10,11 @@ unless Sidekiq.server?
     # unmaintained gem that monkey patches `Time`
     config.lograge.formatter = Lograge::Formatters::Json.new
     config.lograge.logger = ActiveSupport::Logger.new(filename)
+    config.lograge.before_format = lambda do |data, payload|
+      data.delete(:error)
+      data
+    end
+
     # Add request parameters to log output
     config.lograge.custom_options = lambda do |event|
       params = event.payload[:params]
@@ -36,6 +41,20 @@ unless Sidekiq.server?
         payload[:cpu_s] = cpu_s
       end
 
+      # https://github.com/roidrage/lograge#logging-errors--exceptions
+      exception = event.payload[:exception_object]
+
+      if exception
+        payload[:exception] = {
+          class: exception.class.name,
+          message: exception.message
+        }
+
+        if exception.backtrace
+          payload[:exception][:backtrace] = Gitlab::Profiler.clean_backtrace(exception.backtrace)
+        end
+      end
+
       payload
     end
   end

doc/administration/logs.md

@@ -42,6 +42,48 @@ User clone/fetch activity using http transport appears in this log as `action: g
 In addition, the log contains the IP address from which the request originated
 (`remote_ip`) as well as the user's ID (`user_id`), and username (`username`).
 
+NOTE: **Note:** Starting with GitLab 12.5, if an error occurs, an
+`exception` field is included with `class`, `message`, and
+`backtrace`. Previous versions included an `error` field instead of
+`exception.class` and `exception.message`. For example:
+
+```json
+{
+  "method": "GET",
+  "path": "/admin",
+  "format": "html",
+  "controller": "Admin::DashboardController",
+  "action": "index",
+  "status": 500,
+  "duration": 2584.11,
+  "view": 0,
+  "db": 9.21,
+  "time": "2019-11-14T13:12:46.156Z",
+  "params": [],
+  "remote_ip": "127.0.0.1",
+  "user_id": 1,
+  "username": "root",
+  "ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:70.0) Gecko/20100101 Firefox/70.0",
+  "queue_duration": 274.35,
+  "correlation_id": "KjDVUhNvvV3",
+  "cpu_s": 2.837645135999999,
+  "exception": {
+    "class": "NameError",
+    "message": "undefined local variable or method `adsf' for #<Admin::DashboardController:0x00007ff3c9648588>",
+    "backtrace": [
+      "app/controllers/admin/dashboard_controller.rb:11:in `index'",
+      "ee/app/controllers/ee/admin/dashboard_controller.rb:14:in `index'",
+      "ee/lib/gitlab/ip_address_state.rb:10:in `with'",
+      "ee/app/controllers/ee/application_controller.rb:43:in `set_current_ip_address'",
+      "lib/gitlab/session.rb:11:in `with_session'",
+      "app/controllers/application_controller.rb:450:in `set_session_storage'",
+      "app/controllers/application_controller.rb:444:in `set_locale'",
+      "ee/lib/gitlab/jira/middleware.rb:19:in `call'"
+    ]
+  }
+}
+```
+
 ## `production.log`
 
 This file lives in `/var/log/gitlab/gitlab-rails/production.log` for

spec/initializers/lograge_spec.rb

@@ -68,4 +68,52 @@ describe 'lograge', type: :request do
       subject
     end
   end
+
+  context 'with a log subscriber' do
+    let(:subscriber) { Lograge::RequestLogSubscriber.new }
+
+    let(:event) do
+      ActiveSupport::Notifications::Event.new(
+        'process_action.action_controller',
+        Time.now,
+        Time.now,
+        2,
+        status: 200,
+        controller: 'HomeController',
+        action: 'index',
+        format: 'application/json',
+        method: 'GET',
+        path: '/home?foo=bar',
+        params: {},
+        db_runtime: 0.02,
+        view_runtime: 0.01
+      )
+    end
+
+    let(:log_output) { StringIO.new }
+    let(:logger) do
+      Logger.new(log_output).tap { |logger| logger.formatter = ->(_, _, _, msg) { msg } }
+    end
+
+    describe 'with an exception' do
+      let(:exception) { RuntimeError.new('bad request') }
+      let(:backtrace) { caller }
+
+      before do
+        allow(exception).to receive(:backtrace).and_return(backtrace)
+        event.payload[:exception_object] = exception
+        Lograge.logger = logger
+      end
+
+      it 'adds exception data to log' do
+        subscriber.process_action(event)
+
+        log_data = JSON.parse(log_output.string)
+
+        expect(log_data['exception']['class']).to eq('RuntimeError')
+        expect(log_data['exception']['message']).to eq('bad request')
+        expect(log_data['exception']['backtrace']).to eq(Gitlab::Profiler.clean_backtrace(backtrace))
+      end
+    end
+  end
 end