Summary

When backend-worker or backend-listener processes crash due to an unhandled exception, the actual error message is not logged. Instead, a log shifting failed. closed stream error appears because the Backend logger is initialized with a file path and log rotation enabled, which conflicts with container logging to stdout.

Problem Description

The Backend.logger is initialized with /tmp/backend_logger.log and log rotation enabled (shift_age=10), inherited from the container image's default CONFIG_LOG_PATH=/tmp/.

When an exception occurs during a crash:

1. Exception is caught and Worker.logger.notify(exception) is called
2. This delegates to Backend.logger.notify(exception)
3. Backend.logger attempts to write the error AND rotate the log file
4. During a crash, file descriptors close, causing "log shifting failed. closed stream"
5. The actual exception message never appears in logs

Logging Architecture in Apisonator

Three Distinct Logging Systems

Backend Logger (Backend.logger)

Configuration:

• Environment variables: CONFIG_LOG_PATH or CONFIG_LOG_FILE
• Code: lib/3scale/backend/configuration.rb:99-113 and lib/3scale/backend/logging.rb:34-39

Initialization logic:

  lib/3scale/backend/configuration.rb:99-113

  log_file = config.log_file
  if !log_file || log_file.empty?
    log_path = config.log_path
    config.log_file = if log_path && !log_path.empty?
                        if File.stat(log_path).ftype == 'directory'
                          "#{log_path}/backend_logger.log"
                        else
                          log_path
                        end
                      else
                        ENV['CONFIG_LOG_FILE'] || STDOUT
                      end
  end
  

  lib/3scale/backend/logging.rb:34-39

  def enable_logging
    Logging.enable! on: self.singleton_class,
      with_args: [configuration.log_file, 10] do |logger|  # 10 = log rotation enabled
      logger.define_singleton_method(:notify, logger_notify_proc(logger))
    end
  end
  

Special notify() method:

• Used specifically for exception handling
• Chains to external error reporting (Bugsnag if configured)
• Worker.logger.notify() delegates to Backend.logger.notify()

Worker Logger (Worker.logger)

Configuration:

• Environment variable: CONFIG_WORKERS_LOG_FILE
• Code: lib/3scale/backend/logging/worker.rb:85-97

Key behavior:

• Regular logging (info, debug): Uses its own logger instance → CONFIG_WORKERS_LOG_FILE
• Exception logging via notify(): Delegates to Backend.logger.notify()

  lib/3scale/backend/logging/worker.rb:95, 101-103

  def configure_logging(worker_class, workers_log_file)
  ...

    logger.define_singleton_method(:notify, backend_logger_notify_proc)
  end

  def backend_logger_notify_proc
    Backend.logger.method(:notify).to_proc
  end
  

Request Logger

Configuration:

• Environment variable: CONFIG_REQUEST_LOGGERS (comma-separated: text, json)
• Used by listener only for HTTP request/response logging

Environment Variables

Logging Configuration

External Error Reporting

Logging Behavior by Component

Listener (bin/3scale_backend start)

Worker (bin/3scale_backend_worker)

Cron (backend-cron)

Root Cause Analysis

Why the Bug Occurs

In containers (from Dockerfile openshift/distro/ubi/9/Dockerfile:79):

CONFIG_LOG_PATH=/tmp/

This causes:

  config.log_file = "#{log_path}/backend_logger.log"  # "/tmp/backend_logger.log"

Backend.logger is created with rotation:

  Logging.enable! on: self.singleton_class,
    with_args: ["/tmp/backend_logger.log", 10]  # 10 = shift_age (rotation enabled)

The problem:
Ruby's Logger.new(filepath, shift_age) with a file path string enables log rotation. When using STDOUT constant, Ruby recognizes it as an IO stream and skips rotation.

  Logger.new("/tmp/backend_logger.log", 10)  # File path = rotation enabled ❌
  Logger.new(STDOUT)                          # IO constant = NO rotation ✅

Why notify() Logs to a Different Location

The notify() method is designed to integrate with external error reporting services like Bugsnag:

• When CONFIG_HOPTOAD_SERVICE=bugsnag and CONFIG_HOPTOAD_API_KEY are set, exceptions are sent to Bugsnag
• The notify() method chains both local logging (Backend.logger.error) AND external reporting (Bugsnag.notify)
• Code reference: lib/3scale/backend/logging.rb:41-47

  def logger_notify_proc(logger)
    external_notify_proc = Logging::External.notify_proc
    proc do |exception, *args, &block|
      logger.error('Exception') { {exception: {class: exception.class, message: exception.message, backtrace: exception.backtrace[0..3]}} }
      external_notify_proc&.call(exception, *args, &block)
    end
  end

Worker.logger delegates its notify() to Backend.logger to ensure exceptions go through the centralized error reporting pipeline.

Must-Gather Verification

Verified in must-gather from THREESCALE-11940:

• Both listener and worker pods use image: registry.redhat.io/3scale-amp2/backend-rhel8@sha256:eb2288de900dc42ead755b28cdb2509b25ecc8dd256781beaa4a2a86e7cbe532
• Neither pod explicitly sets CONFIG_LOG_PATH environment variable
• Both inherit CONFIG_LOG_PATH=/tmp/ from Dockerfile
• Both are affected by the bug for exception logging

Solutions

Solution 1: Fix Midstream Dockerfile (Recommended)

Reference: Midstream Dockerfile

Change from:

CONFIG_LOG_PATH=/tmp/

To:

CONFIG_LOG_PATH=

This causes Backend.logger to use STDOUT constant (no rotation), preventing the bug.

Solution 2: Alternative - Explicit CONFIG_LOG_FILE

Set:

CONFIG_LOG_FILE=/dev/stdout 

But using STDOUT constant (via empty CONFIG_LOG_PATH) is cleaner.

Suggestion: Code Fix (Upstream)

Modify lib/3scale/backend/logging.rb to detect /dev/stdout and /dev/stderr paths and use IO constants:

  def enable_logging
    log_file = configuration.log_file
    args = if log_file == '/dev/stdout'
             [STDOUT]  # No rotation
           elsif log_file == '/dev/stderr'
             [STDERR]  # No rotation
           else
             [log_file, 10]  # Enable rotation for regular files
           end

    Logging.enable! on: self.singleton_class, with_args: args do |logger|
      logger.define_singleton_method(:notify, logger_notify_proc(logger))
    end
  end
  

Impact

• Listener: HTTP request logs work fine (go to stdout), but application exceptions are masked
• Worker: Activity logs work fine (go to stdout), but exceptions are masked
• Both components show "log shifting failed. closed stream" instead of actual error messages during crashes
• Makes debugging production issues extremely difficult