Merge branch 'ag-add-multi-destination-logger' into 'master'

Add Multi destination logger

See merge request gitlab-org/gitlab!22341

changelogs/unreleased/ag-add-app-multi-logger.yml

+---
+title: Add structured logging for application logs
+merge_request: 22379
+author:
+type: other

doc/development/logging.md

@@ -127,6 +127,88 @@ importer progresses. Here's what to do:
    logger.info(message: "Import error", error_code: 1, error: "I/O failure")
    ```
 
+## Multi-destination Logging
+
+GitLab is transitioning from unstructured/plaintext logs to structured/JSON logs.  During this transition period some logs will be recorded in multiple formats through multi-destination logging.
+
+### How to use multi-destination logging
+
+Create a new logger class, inheriting from `MultiDestinationLogger` and add an array of loggers to a `LOGGERS` constant. The loggers should be classes that descend from `Gitlab::Logger`. e.g. the user defined loggers in the following examples, could be inheriting from `Gitlab::Logger` and `Gitlab::JsonLogger`, respectively.
+
+You must specify one of the loggers as the `primary_logger`. The `primary_logger` will be used when information about this multi-destination logger is displayed in the app, e.g. using the `Gitlab::Logger.read_latest` method.
+
+The following example sets one of the defined `LOGGERS` as a `primary_logger`.
+
+```ruby
+module Gitlab
+  class FancyMultiLogger < Gitlab::MultiDestinationLogger
+    LOGGERS = [UnstructuredLogger, StructuredLogger].freeze
+
+    def self.loggers
+      LOGGERS
+    end
+
+    def primary_logger
+      UnstructuredLogger
+    end
+  end
+end
+```
+
+You can now call the usual logging methods on this multi-logger, e.g.
+
+```ruby
+FancyMultiLogger.info(message: "Information")
+```
+
+This message will be logged by each logger registered in `FancyMultiLogger.loggers`.
+
+### Passing a string or hash for logging
+
+When passing a string or hash to a `MultiDestinationLogger`, the log lines could be formatted differently, depending on the kinds of `LOGGERS` set.
+
+e.g. let's partially define the loggers from the previous example:
+
+```ruby
+module Gitlab
+  # Similar to AppTextLogger
+  class UnstructuredLogger < Gitlab::Logger
+    ...
+  end
+
+  # Similar to AppJsonLogger
+  class StructuredLogger < Gitlab::JsonLogger
+    ...
+  end
+end
+```
+
+Here are some examples of how messages would be handled by both the loggers.
+
+1. When passing a string
+
+```ruby
+FancyMultiLogger.info("Information")
+
+# UnstructuredLogger
+I, [2020-01-13T12:02:41.566219 #6652]  INFO -- : Information
+
+# StructuredLogger
+{:severity=>"INFO", :time=>"2020-01-13T11:02:41.559Z", :correlation_id=>"b1701f7ecc4be4bcd4c2d123b214e65a", :message=>"Information"}
+```
+
+1. When passing a hash
+
+```ruby
+FancyMultiLogger.info({:message=>"This is my message", :project_id=>123})
+
+# UnstructuredLogger
+I, [2020-01-13T12:06:09.856766 #8049]  INFO -- : {:message=>"This is my message", :project_id=>123}
+
+# StructuredLogger
+{:severity=>"INFO", :time=>"2020-01-13T11:06:09.851Z", :correlation_id=>"d7e0886f096db9a8526a4f89da0e45f6", :message=>"This is my message", :project_id=>123}
+```
+
 ## Exception Handling
 
 It often happens that you catch the exception and want to track it.

lib/gitlab/app_json_logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  class AppJsonLogger < Gitlab::JsonLogger
+    def self.file_name_noext
+      'application_json'
+    end
+  end
+end

lib/gitlab/app_logger.rb

 # frozen_string_literal: true
 
 module Gitlab
-  class AppLogger < Gitlab::Logger
-    def self.file_name_noext
-      'application'
+  class AppLogger < Gitlab::MultiDestinationLogger
+    LOGGERS = [Gitlab::AppTextLogger, Gitlab::AppJsonLogger].freeze
+
+    def self.loggers
+      LOGGERS
     end
 
-    def format_message(severity, timestamp, progname, msg)
-      "#{timestamp.to_s(:long)}: #{msg}\n"
+    def self.primary_logger
+      Gitlab::AppTextLogger
     end
   end
 end

lib/gitlab/app_text_logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  class AppTextLogger < Gitlab::Logger
+    def self.file_name_noext
+      'application'
+    end
+
+    def format_message(severity, timestamp, progname, msg)
+      "#{timestamp.to_s(:long)}: #{msg}\n"
+    end
+  end
+end

lib/gitlab/multi_destination_logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  class MultiDestinationLogger < ::Logger
+    def close
+      loggers.each(&:close)
+    end
+
+    def self.debug(message)
+      loggers.each { |logger| logger.build.debug(message) }
+    end
+
+    def self.error(message)
+      loggers.each { |logger| logger.build.error(message) }
+    end
+
+    def self.warn(message)
+      loggers.each { |logger| logger.build.warn(message) }
+    end
+
+    def self.info(message)
+      loggers.each { |logger| logger.build.info(message) }
+    end
+
+    def self.read_latest
+      primary_logger.read_latest
+    end
+
+    def self.file_name
+      primary_logger.file_name
+    end
+
+    def self.full_log_path
+      primary_logger.full_log_path
+    end
+
+    def self.file_name_noext
+      primary_logger.file_name_noext
+    end
+
+    def self.loggers
+      raise NotImplementedError
+    end
+
+    def self.primary_logger
+      raise NotImplementedError
+    end
+  end
+end

spec/lib/gitlab/app_json_logger_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::AppJsonLogger do
+  subject { described_class.new('/dev/null') }
+
+  let(:hash_message) { { 'message' => 'Message', 'project_id' => '123' } }
+  let(:string_message) { 'Information' }
+
+  it 'logs a hash as a JSON' do
+    expect(JSON.parse(subject.format_message('INFO', Time.now, nil, hash_message))).to include(hash_message)
+  end
+
+  it 'logs a string as a JSON' do
+    expect(JSON.parse(subject.format_message('INFO', Time.now, nil, string_message))).to include('message' => string_message)
+  end
+end

spec/lib/gitlab/app_logger_spec.rb

@@ -2,13 +2,21 @@
 
 require 'spec_helper'
 
-describe Gitlab::AppLogger, :request_store do
+describe Gitlab::AppLogger do
   subject { described_class }
 
-  it 'builds a logger once' do
-    expect(::Logger).to receive(:new).and_call_original
+  it 'builds a Gitlab::Logger object twice' do
+    expect(Gitlab::Logger).to receive(:new)
+      .exactly(described_class.loggers.size)
+      .and_call_original
 
-    subject.info('hello world')
-    subject.error('hello again')
+    subject.info('Hello World!')
+  end
+
+  it 'logs info to AppLogger and AppJsonLogger' do
+    expect_any_instance_of(Gitlab::AppTextLogger).to receive(:info).and_call_original
+    expect_any_instance_of(Gitlab::AppJsonLogger).to receive(:info).and_call_original
+
+    subject.info('Hello World!')
   end
 end

spec/lib/gitlab/app_text_logger_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::AppTextLogger do
+  subject { described_class.new('/dev/null') }
+
+  let(:hash_message) { { message: 'Message', project_id: 123 } }
+  let(:string_message) { 'Information' }
+
+  it 'logs a hash as string' do
+    expect(subject.format_message('INFO', Time.now, nil, hash_message )).to include(hash_message.to_s)
+  end
+
+  it 'logs a string unchanged' do
+    expect(subject.format_message('INFO', Time.now, nil, string_message)).to include(string_message)
+  end
+end

spec/lib/gitlab/multi_destination_logger_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+class FakeLogger
+end
+
+class LoggerA < Gitlab::Logger
+  def self.file_name_noext
+    'loggerA'
+  end
+end
+
+class LoggerB < Gitlab::JsonLogger
+  def self.file_name_noext
+    'loggerB'
+  end
+end
+
+class TestLogger < Gitlab::MultiDestinationLogger
+  LOGGERS = [LoggerA, LoggerB].freeze
+
+  def self.loggers
+    LOGGERS
+  end
+end
+
+class EmptyLogger < Gitlab::MultiDestinationLogger
+  def self.loggers
+    []
+  end
+end
+
+describe Gitlab::MultiDestinationLogger do
+  after(:all) do
+    TestLogger.loggers.each do |logger|
+      log_file_path = "#{Rails.root}/log/#{logger.file_name}"
+      File.delete(log_file_path)
+    end
+  end
+
+  context 'with no primary logger set' do
+    subject { EmptyLogger }
+
+    it 'primary_logger raises an error' do
+      expect { subject.primary_logger }.to raise_error(NotImplementedError)
+    end
+  end
+
+  context 'with 2 loggers set' do
+    subject { TestLogger }
+
+    it 'logs info to 2 loggers' do
+      expect(subject.loggers).to all(receive(:build).and_call_original)
+
+      subject.info('Hello World')
+    end
+  end
+end