Merge branch 'add-timestamps-to-puma-stdout-log' into 'master'

Save puma_stdout[stderr].log in JSON format with timestamp added

See merge request gitlab-org/gitlab!21101

changelogs/unreleased/add-timestamps-to-puma-stdout-log.yml

+---
+title: Change Puma log format to JSON
+merge_request: 21101
+author:
+type: other

config/initializers/snowplow_tracker.rb

+# frozen_string_literal: true
+
+# Gitlab.com uses Snowplow for identifying users and events.
+# https://gitlab.com/gitlab-org/gitlab/issues/6329
+#
+# SnowplowTracker write log into STDERR
+# https://github.com/snowplow/snowplow-ruby-tracker/blob/39fcfa2be793f2e25e73087a9700abc93f43b5e8/lib/snowplow-tracker/emitters.rb#L23
+#     `LOGGER = Logger.new(STDERR)`
+#
+# In puma.rb, if `stdout_redirect` specify stderr, Puma will overwrite STDERR in:
+# https://github.com/puma/puma/blob/b41205f5cacbc2ad0060472bdce68ba636f42175/lib/puma/runner.rb#L134
+#    `STDERR.reopen stderr, (append ? "a" : "w")`
+# As a result, SnowplowTracker will log into Puma stderr, when Puma enabled.
+#
+# By default, SnowplowTracker uses default log formatter.
+# When enable Puma, SnowplowTracker log is expected to be JSON format, as part of puma_stderr.log.
+# Hence overwrite ::SnowplowTracker::LOGGER.formatter to JSON formatter
+
+if defined?(::Puma) && defined?(::SnowplowTracker::LOGGER)
+  ::SnowplowTracker::LOGGER.formatter = proc do |severity, datetime, progname, msg|
+    { severity: severity, timestamp: datetime.utc.iso8601(3), pid: $$, progname: progname, message: msg }.to_json << "\n"
+  end
+end

config/puma.example.development.rb

@@ -78,3 +78,11 @@ tag 'gitlab-puma-worker'
 # value is 60 seconds.
 #
 worker_timeout 60
+
+# Use json formatter
+require_relative "/home/git/gitlab/lib/gitlab/puma_logging/json_formatter"
+
+json_formatter = Gitlab::PumaLogging::JSONFormatter.new
+log_formatter do |str|
+  json_formatter.call(str)
+end

config/puma.rb.example

@@ -68,3 +68,11 @@ tag 'gitlab-puma-worker'
 # value is 60 seconds.
 #
 worker_timeout 60
+
+# Use json formatter
+require_relative "/home/git/gitlab/lib/gitlab/puma_logging/json_formatter"
+
+json_formatter = Gitlab::PumaLogging::JSONFormatter.new
+log_formatter do |str|
+  json_formatter.call(str)
+end
\ No newline at end of file

lib/gitlab/puma_logging/json_formatter.rb

+# frozen_string_literal: true
+
+require 'json'
+
+module Gitlab
+  module PumaLogging
+    class JSONFormatter
+      def call(str)
+        { timestamp: Time.now.utc.iso8601(3), pid: $$, message: str }.to_json
+      end
+    end
+  end
+end

spec/lib/gitlab/puma_logging/json_formatter_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::PumaLogging::JSONFormatter do
+  it "generate json format with timestamp and pid" do
+    Timecop.freeze( Time.utc(2019, 12, 04, 9, 10, 11, 123456)) do
+      expect(subject.call('log message')).to eq "{\"timestamp\":\"2019-12-04T09:10:11.123Z\",\"pid\":#{Process.pid},\"message\":\"log message\"}"
+    end
+  end
+end