Class: Hyperion::Logger

Inherits:
Object
  • Object
show all
Defined in:
lib/hyperion/logger.rb

Overview

Structured logger.

Usage:

logger = Hyperion::Logger.new
logger.info  { { message: 'listening', host: '127.0.0.1', port: 9292 } }
logger.warn  { { message: 'parse error', error: e.message, error_class: e.class.name } }
logger.error 'plain string also works for legacy callers'

Level is set from:

1. The `level:` constructor kwarg (highest precedence).
2. ENV['HYPERION_LOG_LEVEL'] if set.
3. Defaults to :info.

Format is :text (key=value), :json (JSONL), or :auto (default — picks the right one based on the runtime environment, see #pick_format below).

Each log line is prefixed with timestamp + level + a ‘hyperion’ tag so operators can grep multi-process worker output. When the resolved format is :text and the underlying IO is a TTY, level names are ANSI-coloured for readability.

Constant Summary collapse

LEVELS = 
{ debug: 0, info: 1, warn: 2, error: 3, fatal: 4 }.freeze
LEVEL_COLORS = 
{
  debug: "\e[90m", # bright black / grey
  info: "\e[32m",  # green
  warn: "\e[33m",  # yellow
  error: "\e[31m",  # red
  fatal: "\e[35m"   # magenta
}.freeze
COLOR_RESET =

magenta

"\e[0m"
PRODUCTION_ENVS = 
%w[production staging].freeze
ERROR_LEVELS =

Levels at WARN or higher are routed to the error stream (stderr by default). info / debug go to the regular stream (stdout by default). 12-factor: app logs to stdout, errors to stderr.

%i[warn error fatal].freeze
ACCESS_FLUSH_BYTES =

Per-thread access-log buffer flush threshold. ~32 average-size lines per write(2) call, well under PIPE_BUF (4096) so writes stay atomic. Larger = fewer syscalls but higher latency-to-disk (up to ~32 reqs of delay before the line shows up in the log file). 4 KiB is a good balance: a 16-thread fleet at 24k r/s flushes ~750 buffers/sec total vs ~24 000 syscalls/sec without buffering.

4096

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(out: $stdout, err: $stderr, io: nil, level: nil, format: nil) ⇒ Logger

Returns a new instance of Logger.



49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
 
# File 'lib/hyperion/logger.rb', line 49

def initialize(out: $stdout, err: $stderr, io: nil, level: nil, format: nil)
  # `io:` is a back-compat alias for tests / single-IO use cases — it
  # routes both streams to the same target (e.g. a StringIO in specs).
  @out = io || out
  @err = io || err
  # Force line-immediate mode on real IO destinations. When stdout is
  # redirected (piped, journald, kubectl logs), Ruby/glibc default to
  # 4-KiB block buffering and small log lines never reach the consumer
  # until the buffer fills or the process exits. Operators expect to see
  # boot lines + access logs in real time. Match Puma's behaviour.
  @out.sync = true if @out.is_a?(::IO) && @out.respond_to?(:sync=)
  @err.sync = true if @err.is_a?(::IO) && @err.respond_to?(:sync=)
  @level = parse_level(level || ENV.fetch('HYPERION_LOG_LEVEL', 'info'))
  requested = format || ENV['HYPERION_LOG_FORMAT']
  @format = pick_format(requested)
  # Colorize when format is text AND the destination is a TTY. We only
  # check the regular stream here — colored text is for humans.
  @colorize = @format == :text && tty?(@out)
  @c_access_available = nil # lazy-computed on first access — see below.
  # Registry of every per-thread access buffer ever allocated through
  # this Logger instance. Walked by #flush_all on shutdown so SIGTERM
  # doesn't strand buffered lines in dying threads. The Mutex guards
  # registration on first allocation per thread (rare) and the shutdown
  # walk; the hot #access path stays lock-free.
  @access_buffers = []
  @access_buffers_mutex = Mutex.new
  # Per-instance thread-local key. A globally-shared key (e.g. a frozen
  # Symbol constant) lets a buffer created by an earlier Logger in this
  # thread be picked up by a later Logger — but the buffer is registered
  # against the *earlier* Logger's @access_buffers, so the new Logger's
  # #flush_all can't see it. Namespacing the key per-instance fixes that:
  # each Logger gets its own per-thread buffer, and the registry it
  # walks at shutdown matches the one #access wrote to. The Symbol is
  # allocated once at construction; the hot path just reads it.
  @buffer_key = :"__hyperion_access_buf_#{object_id}__"
end

Instance Attribute Details

#format ⇒ Object (readonly)

Returns the value of attribute format.



42
43
44
 
# File 'lib/hyperion/logger.rb', line 42

def format
  @format
end

#level ⇒ Object

Returns the value of attribute level.



42
43
44
 
# File 'lib/hyperion/logger.rb', line 42

def level
  @level
end

Instance Method Details

#access(method, path, query, status, duration_ms, remote_addr, http_version) ⇒ Object

Hot-path access-log emitter — bypasses the generic format_text / format_json kvs.join + hash#map allocations. The whole line is built via a single interpolation, the timestamp is cached per-thread per millisecond, and we batch lines into a per-thread buffer that flushes when full (lock-free emit; POSIX write(2) is atomic for writes <= PIPE_BUF / 4096 bytes).

Returns silently on any IO error — logging must never crash the server.



133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
 
# File 'lib/hyperion/logger.rb', line 133

def access(method, path, query, status, duration_ms, remote_addr, http_version)
  return unless emit?(:info)

  ts = cached_timestamp
  # The C extension builds the line in a stack scratch buffer (~10× faster
  # than the Ruby interpolation path). It only fires when colorization is
  # off — a colored TTY line needs ANSI escapes around the level label,
  # which the C builder doesn't emit. Production deploys (non-TTY,
  # log-aggregator destinations) take the C path; local TTY runs keep the
  # colored Ruby fallback.
  line = if !@colorize && c_access_available?
           ::Hyperion::CParser.build_access_line(@format, ts, method, path,
                                                 query, status, duration_ms,
                                                 remote_addr, http_version)
         elsif @format == :json
           build_access_json(ts, method, path, query, status, duration_ms, remote_addr, http_version)
         else
           build_access_text(ts, method, path, query, status, duration_ms, remote_addr, http_version)
         end

  buf = Thread.current[@buffer_key] || allocate_access_buffer
  buf << line
  return if buf.bytesize < ACCESS_FLUSH_BYTES

  @out.write(buf)
  buf.clear
rescue StandardError
  # Swallow logger failures — never let logging crash the server.
end

#c_access_available? ⇒ Boolean

Whether Hyperion::CParser.build_access_line is available. Probed lazily on first call (the C parser is required after Logger is required, so we can’t cache this at constant-define time — it would always be false). Memoised per-instance to keep the hot path branchless.

Returns:

  • (Boolean) 


90
91
92
93
94
95
 
# File 'lib/hyperion/logger.rb', line 90

def c_access_available?
  return @c_access_available unless @c_access_available.nil?

  @c_access_available = defined?(::Hyperion::CParser) &&
                        ::Hyperion::CParser.respond_to?(:build_access_line)
end

#flush_access_buffer ⇒ Object

Flush this thread’s buffered access-log lines. Called by the connection loop when a connection closes (so log lines from a closing keep-alive session don’t get stuck behind the buffer until the next connection).



166
167
168
169
170
171
172
173
174
 
# File 'lib/hyperion/logger.rb', line 166

def flush_access_buffer
  buf = Thread.current[@buffer_key]
  return if buf.nil? || buf.empty?

  @out.write(buf)
  buf.clear
rescue StandardError
  # Swallow logger failures — never let logging crash the server.
end

#flush_all ⇒ Object

Flush every per-thread access-log buffer ever allocated through this Logger, then sync the underlying IOs.

Why this exists: under SIGTERM, Master#shutdown_children logs the ‘master draining’ / ‘master exiting’ lines and then exits. The ‘info’ path doesn’t go through the access buffer, but it does rely on glibc stdio buffering being flushed before the process dies — and per-thread access buffers (Thread.current[:hyperion_access_buf]) are only flushed when the buffer reaches ACCESS_FLUSH_BYTES or when the owning thread closes a connection. On a clean SIGTERM both can be missed and the operator sees nothing in the captured log. This method walks every registered per-thread buffer, writes any pending bytes, then calls IO#flush on @out / @err so the kernel sees them before exec_exit.

Safe to call from any thread. Idempotent. Never raises.



191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
 
# File 'lib/hyperion/logger.rb', line 191

def flush_all
  buffers = @access_buffers_mutex.synchronize { @access_buffers.dup }
  buffers.each do |buf|
    next if buf.empty?

    begin
      @out.write(buf)
      buf.clear
    rescue StandardError
      # Continue — one bad buffer must not block the rest.
    end
  end

  flush_io(@out)
  flush_io(@err) unless @err.equal?(@out)
rescue StandardError
  # Swallow logger failures — never let logging crash the server.
end

#io_for(lvl) ⇒ Object

Pick the destination IO for a given level. warn / error / fatal → @err (stderr default). debug / info → @out (stdout default).



109
110
111
 
# File 'lib/hyperion/logger.rb', line 109

def io_for(lvl)
  ERROR_LEVELS.include?(lvl) ? @err : @out
end