Enhance logging and request context in API and Auth modules

- Added start_time to request_context for better performance tracking.
- Improved log messages for request processing and authentication validation.
- Introduced a logger instance for the Auth module to streamline logging.
- Updated tests to mock the logger instance for integration tests.

Author: GrantBirki

lib/hooks/app/api.rb

@@ -51,21 +51,23 @@ def self.create(config:, endpoints:, log:)
 
             post(full_path) do
               request_id = uuid
+              start_time = Time.now
+
               request_context = {
                 request_id:,
                 path: full_path,
-                handler: handler_class_name,
-                start_time: Time.now,
+                handler: handler_class_name
               }
 
+              # everything wrapped in the log context has access to the request context and includes it in log messages
+              # ex: Hooks::Log.info("message") will include request_id, path, handler, etc
               Core::LogContext.with(request_context) do
                 begin
                   enforce_request_limits(config)
                   request.body.rewind
                   raw_body = request.body.read
 
                   if endpoint_config[:auth]
-                    log.info "validating request (id: #{request_id}, handler: #{handler_class_name})"
                     validate_auth!(raw_body, headers, endpoint_config, config)
                   end
 
@@ -79,10 +81,11 @@ def self.create(config:, endpoints:, log:)
                     config: endpoint_config
                   )
 
-                  log.info "request processed successfully (id: #{request_id}, handler: #{handler_class_name})"
+                  log.info "request processed successfully by handler: #{handler_class_name}"
+                  log.debug "request duration: #{Time.now - start_time}s"
                   status 200
                   content_type "application/json"
-                  (response || { status: "ok" }).to_json
+                  response.to_json
                 rescue => e
                   log.error "request failed: #{e.message} (id: #{request_id}, handler: #{handler_class_name})"
                   error_response = {

lib/hooks/app/auth/auth.rb

@@ -22,7 +22,7 @@ module Auth
       def validate_auth!(payload, headers, endpoint_config, global_config = {})
         auth_config = endpoint_config[:auth]
 
-        # Security: Ensure auth type is present and valid
+        # Ensure auth type is present and valid
         auth_type = auth_config&.dig(:type)
         unless auth_type&.is_a?(String) && !auth_type.strip.empty?
           error!("authentication configuration missing or invalid", 500)
@@ -32,9 +32,12 @@ def validate_auth!(payload, headers, endpoint_config, global_config = {})
         begin
           auth_class = Core::PluginLoader.get_auth_plugin(auth_type)
         rescue => e
+          log.error("failed to load auth plugin '#{auth_type}': #{e.message}")
           error!("unsupported auth type '#{auth_type}'", 400)
         end
 
+        log.debug("validating auth for request with auth_class: #{auth_class.name}")
+
         unless auth_class.valid?(
           payload:,
           headers:,
@@ -43,6 +46,16 @@ def validate_auth!(payload, headers, endpoint_config, global_config = {})
           error!("authentication failed", 401)
         end
       end
+
+      private
+
+      # Short logger accessor for auth module
+      # @return [Hooks::Log] Logger instance
+      #
+      # Provides access to the application logger for authentication operations.
+      def log
+        Hooks::Log.instance
+      end
     end
   end
 end

spec/unit/lib/hooks/app/auth/custom_auth_integration_spec.rb

@@ -3,6 +3,7 @@
 require_relative "../../../../spec_helper"
 
 describe "Custom Auth Plugin Integration" do
+  let(:log) { instance_double(Logger).as_null_object }
   let(:custom_auth_plugin_dir) { "/tmp/test_auth_plugins" }
   let(:plugin_file_content) do
     <<~RUBY
@@ -51,6 +52,10 @@ def self.valid?(payload:, headers:, config:)
     Hooks::Core::PluginLoader.load_all_plugins(global_config)
   end
 
+  before(:each) do
+    Hooks::Log.instance = log
+  end
+
   after do
     FileUtils.rm_rf(custom_auth_plugin_dir) if Dir.exist?(custom_auth_plugin_dir)
     ENV.delete("SUPER_COOL_SECRET")