pages-action#131: make logs more verbose for errors in octo

lib/fbe/middleware/logging_formatter.rb

@@ -0,0 +1,63 @@
+# frozen_string_literal: true
+
+# MIT License
+#
+# Copyright (c) 2024 Zerocracy
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy
+# of this software and associated documentation files (the "Software"), to deal
+# in the Software without restriction, including without limitation the rights
+# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+# copies of the Software, and to permit persons to whom the Software is
+# furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in all
+# copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+# SOFTWARE.
+
+require 'faraday'
+
+# Faraday logging formatter show verbose log for only error response
+class Fbe::Middleware::LoggingFormatter < Faraday::Logging::Formatter
+  AUTHORIZATION_FILTER = [/(Authorization: )([^&]+)([^&]{5})/, '\1********\3'].freeze
+
+  def initialize(**)
+    super
+    filter(*AUTHORIZATION_FILTER)
+  end
+
+  def request(env)
+    super unless log_only_errors?
+  end
+
+  def response(env)
+    return super unless log_only_errors?
+    request_with_response(env) if env.status.nil? || env.status >= 400
+  end
+
+  def request_with_response(env)
+    old_log_level = @options[:log_level]
+    @options[:log_level] = :error
+    public_send(log_level, 'request') do
+      "#{env.method.upcase} #{apply_filters(env.url.to_s)}"
+    end
+    log_headers('request', env.request_headers) if log_headers?(:request)
+    log_body('request', env[:request_body]) if env[:request_body] && log_body?(:request)
+    public_send(log_level, 'response') { "Status #{env.status}" }
+    log_headers('response', env.response_headers) if log_headers?(:response)
+    log_body('response', env[:response_body]) if env[:response_body] && log_body?(:response)
+    @options[:log_level] = old_log_level
+    nil
+  end
+
+  def log_only_errors?
+    @options[:log_only_errors]
+  end
+end

lib/fbe/octo.rb

@@ -32,6 +32,7 @@
 require_relative '../fbe'
 require_relative 'middleware'
 require_relative 'middleware/quota'
+require_relative 'middleware/logging_formatter'
 
 # Interface to GitHub API.
 #
@@ -91,7 +92,17 @@ def Fbe.octo(options: $options, global: $global, loog: $loog)
             builder.use(Fbe::Middleware::Quota, loog:, pause: options.github_api_pause || 60)
             builder.use(Faraday::HttpCache, serializer: Marshal, shared_cache: false, logger: Loog::NULL)
             builder.use(Octokit::Response::RaiseError)
-            builder.use(Faraday::Response::Logger, Loog::NULL)
+            builder.use(
+              Faraday::Response::Logger,
+              loog,
+              {
+                formatter: Fbe::Middleware::LoggingFormatter,
+                log_only_errors: true,
+                headers: true,
+                bodies: true,
+                errors: false
+              }
+            )
             builder.adapter(Faraday.default_adapter)
           end
         o.middleware = stack

test/fbe/middleware/test_logging_formatter.rb

@@ -0,0 +1,99 @@
+# frozen_string_literal: true
+
+# MIT License
+#
+# Copyright (c) 2024 Zerocracy
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy
+# of this software and associated documentation files (the "Software"), to deal
+# in the Software without restriction, including without limitation the rights
+# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+# copies of the Software, and to permit persons to whom the Software is
+# furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in all
+# copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+# SOFTWARE.
+
+require 'minitest/autorun'
+require 'faraday'
+require 'loog'
+require_relative '../../../lib/fbe/middleware'
+require_relative '../../../lib/fbe/middleware/logging_formatter'
+
+class LoggingFormatterTest < Minitest::Test
+  def test_success_response_with_debug_log_level
+    run_logging_formatter(status: 200, log_level: Logger::DEBUG) do |logger|
+      assert_empty(logger.to_s)
+    end
+  end
+
+  def test_success_response_with_error_log_level
+    run_logging_formatter(status: 307, log_level: Logger::ERROR) do |logger|
+      assert_empty(logger.to_s)
+    end
+  end
+
+  def test_error_response_with_debug_log_level
+    run_logging_formatter(status: 400, log_level: Logger::DEBUG) do |logger|
+      str = logger.to_s
+      refute_empty(str)
+      assert_match(%r{http://example.com}, str)
+      assert_match(/Authorization: [\*]{8}cret"/, str)
+      assert_match(/Status 400/, str)
+      assert_match(/x-github-api-version-selected: "2022-11-28"/, str)
+      assert_match(/some response body/, str)
+    end
+  end
+
+  def test_error_response_with_error_log_level
+    run_logging_formatter(method: :post, status: 500, log_level: Logger::ERROR) do |logger|
+      str = logger.to_s
+      refute_empty(str)
+      assert_match(%r{http://example.com}, str)
+      assert_match(/Authorization: [\*]{8}cret"/, str)
+      assert_match(/some request body/, str)
+      assert_match(/Status 500/, str)
+      assert_match(/x-github-api-version-selected: "2022-11-28"/, str)
+      assert_match(/some response body/, str)
+    end
+  end
+
+  private
+
+  def run_logging_formatter(status:, log_level:, method: :get)
+    logger = Loog::Buffer.new(level: log_level)
+    options = {
+      log_only_errors: true,
+      headers: true,
+      bodies: true,
+      errors: false
+    }
+    formatter = Fbe::Middleware::LoggingFormatter.new(logger:, options:)
+    env = Faraday::Env.from(
+      {
+        method:,
+        request_body: method == :get ? nil : 'some request body',
+        url: URI('http://example.com'),
+        request_headers: {
+          'Authorization' => 'Bearer github_pat_11AAsecret'
+        }
+      }
+    )
+    formatter.request(env)
+    env[:response_headers] = {
+      'x-github-api-version-selected' => '2022-11-28'
+    }
+    env[:status] = status
+    env[:response_body] = 'some response body'
+    formatter.response(env)
+    yield logger
+  end
+end