Merge pull request #102 from icyleaf/refactor/improve-logging-format

Improve logging format

.github/workflows/linux-ci.yml

@@ -12,6 +12,7 @@ jobs:
   specs:
     runs-on: ubuntu-latest
     strategy:
+      fail-fast: false
       matrix:
         crystal: [ '0.35.0', '0.35.1', '0.36.0', 'latest', 'nightly' ]
     name: Crystal ${{ matrix.crystal }} tests

spec/halite_spec.cr

@@ -1,5 +1,67 @@
 require "./spec_helper"
 
+private def without_timezone(&block)
+  with_timezone(nil, &block)
+end
+
+private def with_timezone(timezone : String? = nil, &block)
+  current_timezone = ENV["TZ"]?
+  restore_timezone = false
+
+  if current_timezone && timezone.nil?
+    restore_timezone = true
+    ENV.delete("TZ")
+  end
+
+  if timezone
+    restore_timezone = true
+    ENV["TZ"] = timezone.not_nil!
+  end
+
+  block.call
+
+  ENV["TZ"] = current_timezone if restore_timezone
+end
+
+describe Halite::Helper do
+  describe "#timestamp" do
+    it "should use utc timezone as default location" do
+      without_timezone do
+        ENV["TZ"]?.should be_nil
+        t = Time.utc(2021, 2, 10, 22, 5, 13)
+        Halite::Helper.to_rfc3339(t).should eq "2021-02-10T22:05:13Z"
+      end
+    end
+
+    it "should use given timezone" do
+      without_timezone do
+        ENV["TZ"]?.should be_nil
+        t = Time.utc(2021, 2, 10, 22, 5, 13)
+        timezone = "Asia/Shanghai"
+        Halite::Helper.to_rfc3339(t, timezone: timezone).should eq "2021-02-11T06:05:13+08:00"
+      end
+    end
+
+    it "should use `TZ` timezone from ENV" do
+      timezone = "Asia/Shanghai"
+      with_timezone(timezone) do
+        ENV["TZ"].should eq timezone
+        t = Time.utc(2021, 2, 10, 22, 5, 13)
+        Halite::Helper.to_rfc3339(t).should eq "2021-02-11T06:05:13+08:00"
+      end
+    end
+
+    it "should overwrite given timezone" do
+      timezone = "Asia/Shanghai"
+      with_timezone(timezone) do
+        ENV["TZ"].should eq timezone
+        t = Time.utc(2021, 2, 10, 22, 5, 13)
+        Halite::Helper.to_rfc3339(t, timezone: "Europe/Berlin").should eq "2021-02-10T23:05:13+01:00"
+      end
+    end
+  end
+end
+
 describe Halite do
   describe ".new" do
     it "returns a instance class" do

src/halite.cr

@@ -6,6 +6,29 @@ module Halite
 
   VERSION = "0.10.9"
 
+  module Helper
+    # Parses a `Time` into a [RFC 3339](https://tools.ietf.org/html/rfc3339) datetime format string
+    # ([ISO 8601](http://xml.coverpages.org/ISO-FDIS-8601.pdf) profile).
+    #
+    # > Load Enviroment named "TZ" as high priority
+    def self.to_rfc3339(time : Time, *, timezone = ENV["TZ"]?, fraction_digits : Int = 0)
+      Time::Format::RFC_3339.format(time.in(configure_location(timezone)), fraction_digits: fraction_digits)
+    end
+
+    # Parses a `Time` into a [RFC 3339](https://tools.ietf.org/html/rfc3339) datetime format string to `IO`
+    # ([ISO 8601](http://xml.coverpages.org/ISO-FDIS-8601.pdf) profile).
+    #
+    # > Load Enviroment named "TZ" as high priority
+    def self.to_rfc3339(time : Time, io : IO, *, timezone = ENV["TZ"]?, fraction_digits : Int = 0)
+      Time::Format::RFC_3339.format(time.in(configure_location(timezone)), io, fraction_digits)
+    end
+
+    # :nodoc:
+    private def self.configure_location(timezone = ENV["TZ"]?)
+      timezone ? Time::Location.load(timezone.not_nil!) : Time::Location::UTC
+    end
+  end
+
   @@features = {} of String => Feature.class
 
   module FeatureRegister

src/halite/features/logging.cr

@@ -2,7 +2,10 @@ require "log"
 require "colorize"
 require "file_utils"
 
-Log.setup("halite")
+Log.setup do |c|
+  backend = Log::IOBackend.new(formatter: Halite::Logging::ShortFormat)
+  c.bind("halite", :info, backend)
+end
 
 module Halite
   # Logging feature
@@ -92,6 +95,22 @@ module Halite
       end
     end
 
+    # Similar to `Log::ShortFormat`
+    #
+    # **NOTE**: It invalid by calling `Log.setup` or `Log.setup_from_env` outside of Halite.
+    #
+    # Copy from https://github.com/crystal-lang/crystal/blob/3c48f311f/src/log/format.cr#L197
+    struct ShortFormat < Log::StaticFormatter
+      def run
+        "#{timestamp} - #{source(before: " ", after: ": ")}#{message}" \
+        "#{data(before: " -- ")}#{context(before: " -- ")}#{exception}"
+      end
+
+      def timestamp
+        Helper.to_rfc3339(@entry.timestamp, @io)
+      end
+    end
+
     extend Register
 
     Halite.register_feature "logging", self

src/halite/features/logging/common.cr

@@ -17,7 +17,7 @@ class Halite::Logging
   class Common < Abstract
     def request(request)
       message = String.build do |io|
-        io << "> | request  | " << current_timestamp << colorful_method(request.verb)
+        io << "> | request  | " << colorful_method(request.verb)
         io << "| " << request.uri
         unless request.body.empty? || @skip_request_body
           io << "\n" << request.body
@@ -31,7 +31,7 @@ class Halite::Logging
     def response(response)
       message = String.build do |io|
         content_type = response.content_type || "Unknown MIME"
-        io << "< | response | " << current_timestamp << colorful_status_code(response.status_code)
+        io << "< | response | " << colorful_status_code(response.status_code)
         io << "| " << response.uri
         if !@skip_benchmark && (request_time = @request_time)
           elapsed = Time.utc - request_time
@@ -89,10 +89,6 @@ class Halite::Logging
       message.colorize.fore(fore).back(back)
     end
 
-    private def current_timestamp
-      Time::Format::RFC_3339.format(Time.local, 0)
-    end
-
     # return `true` if is binary types with MIME type
     #
     # MIME types list: https://developer.mozilla.org/docs/Web/HTTP/Basics_of_HTTP/MIME_types/Complete_list_of_MIME_types

src/halite/features/logging/json.cr

@@ -60,7 +60,7 @@ class Halite::Logging
       end
 
       {
-        "created_at" => Time::Format::RFC_3339.format(@request_time.not_nil!, 0),
+        "created_at" => Helper.to_rfc3339(@request_time.not_nil!),
         "elapsed"    => elapsed,
         "entry"      => {
           "request"  => @request.not_nil!.to_h,
@@ -80,7 +80,7 @@ class Halite::Logging
           "headers"   => @request.headers.to_flat_h,
           "method"    => @request.verb,
           "url"       => @request.uri.to_s,
-          "timestamp" => Time::Format::RFC_3339.format(Time.local, 0),
+          "timestamp" => Helper.to_rfc3339(Time.utc),
         }
       end
     end
@@ -96,7 +96,7 @@ class Halite::Logging
           "header"       => @response.headers.to_flat_h,
           "status_code"  => @response.status_code,
           "http_version" => @response.version,
-          "timestamp"    => Time::Format::RFC_3339.format(Time.local, 0),
+          "timestamp"    => Helper.to_rfc3339(Time.utc),
         }
       end
     end