Class: LogStruct::Formatter

Inherits:
Logger::Formatter
  • Object
show all
Extended by:
T::Sig
Defined in:
lib/log_struct/formatter.rb

Constant Summary collapse

MAX_RECURSION_DEPTH = 
20
RAILS_FILTERED_MASK =

The mask Rails' parameter filter puts in place of filtered values

"[FILTERED]"
LOG_FIELD_KEYS =

LogStruct's own fields, which some filters don't apply to at the top of a line

T.let(LogField.values.map(&:serialize).to_set.freeze, T::Set[T.untyped])
SCRUB_MARGIN_BYTES =

The scrubbers see a little more than a cut string keeps, so data at the cut is scrubbed whole

256

Instance Method Summary collapse

Instance Method Details

#add_metadata(data, progname:, request_id:, context:, tags:) ⇒ void

This method returns an undefined value.

The program name, request ID and job context, filtered and scrubbed like the rest of the line: an X-Request-Id header can carry anything

Parameters:

  • data (Hash{T.untyped => T.untyped})
  • progname (String, nil)
  • request_id (T.untyped)
  • context (Hash{T.untyped => T.untyped}, nil)
  • tags (Array<T.untyped>, nil) 


416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
 
# File 'lib/log_struct/formatter.rb', line 416

def add_metadata(data, progname:, request_id:, context:, tags:)
  metadata = {}
  metadata[:prog] = progname if progname.present?
  metadata[:tags] = tags if tags.is_a?(Array) && !tags.empty? && !data.key?(:tags)
  if request_id.is_a?(String) && !request_id.empty? && !data.key?(:req_id)
    metadata[:req_id] = request_id
  end
  metadata[:ctx] = symbolize_keys(context) if context.present?
  return if metadata.empty?

  processed = process_values(metadata)
  job_context = processed.delete(:ctx)
  data.merge!(processed)
  return if job_context.nil?

  line_context = data[:ctx]
  # A logged Hash's own ctx keeps its keys and gains the job's
  data[:ctx] = line_context.is_a?(Hash) ? job_context.merge(line_context) : (line_context || job_context)
end

#call(severity, time, progname, log_value, request_id: nil, context: nil, tags: nil) ⇒ String

Serializes Log (or string) into JSON. request_id: the request's ID (default: the one RequestContext stored for this thread). context: fields for the line's ctx, like the running job's ID and class. The line's own ctx keys win. tags: the logger's tags (logger.tagged("billing")), written as tags unless the line has its own.

Parameters:

  • severity (String, Symbol, Integer)
  • time (Time)
  • progname (String, nil)
  • log_value (T.untyped)
  • request_id (String, nil) (defaults to: nil)
  • context (Hash{T.untyped => T.untyped}, nil) (defaults to: nil)
  • tags (Array<T.untyped>, nil) (defaults to: nil)

Returns:

  • (String) 


359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
 
# File 'lib/log_struct/formatter.rb', line 359

def call(severity, time, progname, log_value, request_id: nil, context: nil, tags: nil)
  level_enum = Level.from_severity(severity)

  data = log_value_to_hash(log_value, time: time)

  # Filter params, scrub sensitive values, format ActiveJob GlobalID arguments
  data = process_values(data)

  # Add standard fields if not already present
  data[:src] ||= Source::App
  data[:evt] ||= Event::Log
  data[:ts] ||= time.iso8601(3)
  data[:lvl] = level_enum # Set level from severity parameter
  add_metadata(data, progname: progname, request_id: request_id || Thread.current[:logstruct_request_id], context: context, tags: tags)

  begin
    generate_json(data)
  rescue SystemStackError, StandardError => e
    unwritable_line_json(data, e)
  end
end

#clear_tags! ⇒ void

This method returns an undefined value.

Add clear_tags! method to support ActiveSupport::TaggedLogging



39
40
41
 
# File 'lib/log_struct/formatter.rb', line 39

def clear_tags!
  Thread.current[:activesupport_tagged_logging_tags] = []
end

#current_tags ⇒ Array<String>

Add current_tags method to support ActiveSupport::TaggedLogging

Returns:

  • (Array<String>) 


23
24
25
 
# File 'lib/log_struct/formatter.rb', line 23

def current_tags
  Thread.current[:activesupport_tagged_logging_tags] ||= []
end

#enum_or_string(value) ⇒ String?

Parameters:

  • value (T.untyped)

Returns:

  • (String, nil) 


437
438
439
440
441
442
443
 
# File 'lib/log_struct/formatter.rb', line 437

def enum_or_string(value)
  if value.is_a?(Source) || value.is_a?(Event)
    value.serialize.to_s
  elsif value.is_a?(String)
    value
  end
end

#generate_json(data) ⇒ String

Output as JSON with a newline. We mock this method in tests so we can inspect the data right before it gets turned into a JSON string.

Parameters:

  • data (Hash{T.untyped => T.untyped})

Returns:

  • (String) 


448
449
450
 
# File 'lib/log_struct/formatter.rb', line 448

def generate_json(data)
  "#{data.to_json}\n"
end

#log_value_to_hash(log_value, time:) ⇒ Hash{Symbol => T.untyped}

Parameters:

  • log_value (T.untyped)
  • time (Time)

Returns:

  • (Hash{Symbol => T.untyped}) 


280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
 
# File 'lib/log_struct/formatter.rb', line 280

def log_value_to_hash(log_value, time:)
  case log_value
  when Log::Interfaces::CommonFields
    # Our log classes all implement a custom #serialize method that use symbol keys
    log_value.serialize

  when T::Struct
    # Default T::Struct.serialize methods returns a hash with string keys, so convert them to symbols
    symbolize_keys(log_value.serialize)

  when Hash
    # Use hash as is and convert string keys to symbols
    symbolize_keys(log_value)

  when Exception
    # logger.error(exception): its class, message and backtrace
    Log.from_exception(Source::App, log_value, {}, time).serialize

  else
    # Create a Plain log with the message as a string and serialize it with symbol keys
    # log_value can be literally anything: Integer, Float, Boolean, NilClass, etc.
    log_message = case log_value
    # Handle all the basic types without any further processing
    when String, Symbol, TrueClass, FalseClass, NilClass, Array, Hash, Time, Numeric
      log_value
    else
      # Handle the serialization of complex objects in a useful way:
      #
      # 1. For ActiveRecord models: Use as_json which includes attributes
      # 2. For objects with custom as_json implementations: Use their implementation
      # 3. For basic objects that only have ActiveSupport's as_json: Use to_s
      begin
        method_owner = log_value.method(:as_json).owner

        # If it's ActiveRecord, ActiveModel, or a custom implementation, use as_json
        if method_owner.to_s.include?("ActiveRecord") ||
            method_owner.to_s.include?("ActiveModel") ||
            method_owner.to_s.exclude?("ActiveSupport::CoreExtensions") &&
                method_owner.to_s.exclude?("Object")
          log_value.as_json
        else
          # For plain objects with only the default ActiveSupport as_json
          log_value.to_s
        end
      rescue => e
        # Handle serialization errors
        context = {
          object_class: log_value.class.name,
          object_inspect: log_value.inspect.truncate(100)
        }
        LogStruct.handle_exception(e, source: Source::Internal, context: context)

        # Fall back to the string representation to ensure we continue processing
        log_value.to_s
      end
    end

    Log::Plain.new(
      message: log_message,
      timestamp: time
    ).serialize
  end
end

#looks_like_backtrace_array?(array) ⇒ Boolean

Check if an array looks like a backtrace (array of strings with file:line pattern)

Parameters:

  • array (Array<T.untyped>)

Returns:

  • (Boolean) 


480
481
482
483
484
485
486
 
# File 'lib/log_struct/formatter.rb', line 480

def looks_like_backtrace_array?(array)
  backtrace_like_count = array.first(5).count do |element|
    element.is_a?(String) && element.match?(/\A[^:\s]+:\d+/)
  end

  backtrace_like_count >= 3
end

#process_array(array, recursion_depth:, ancestors:, path: nil, root: nil) ⇒ Array<T.untyped>

An array's items keep the array's path, as in Rails (users.name filters each user's name)

Parameters:

  • array (Array<T.untyped>)
  • recursion_depth (Integer)
  • ancestors (Hash{T.untyped => Boolean})
  • path (Array<String>, nil) (defaults to: nil)
  • root (T.untyped) (defaults to: nil)

Returns:

  • (Array<T.untyped>) 


462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
 
# File 'lib/log_struct/formatter.rb', line 462

def process_array(array, recursion_depth:, ancestors:, path: nil, root: nil)
  return [] if array.empty?

  limits = LogStruct.config.limits
  backtrace = looks_like_backtrace_array?(array)
  max_items = backtrace ? limits.max_backtrace_lines : limits.max_array_items
  processed = array.first(max_items).map do |value|
    process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root)
  end
  if array.size > max_items
    processed << "... and #{array.size - max_items} more #{backtrace ? "lines" : "items"}"
  end

  processed
end

#process_hash(hash, recursion_depth:, ancestors:, path: nil, root: nil) ⇒ Hash{T.untyped => T.untyped}

Parameters:

  • hash (Hash{T.untyped => T.untyped})
  • recursion_depth (Integer)
  • ancestors (Hash{T.untyped => Boolean})
  • path (Array<String>, nil) (defaults to: nil)
  • root (T.untyped) (defaults to: nil)

Returns:

  • (Hash{T.untyped => T.untyped}) 


154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
 
# File 'lib/log_struct/formatter.rb', line 154

def process_hash(hash, recursion_depth:, ancestors:, path: nil, root: nil)
  result = {}

  # Path matchers' roots are built only if a matcher reads them (most don't)
  line_root = (path && recursion_depth == 0) ? ConfigStruct::LazyRoot.new(hash) : nil

  max_keys = LogStruct.config.limits.max_hash_keys
  hash.each_with_index do |(key, value), index|
    if index >= max_keys
      result[:_more_keys] = hash.size - max_keys
      break
    end

    key = valid_utf8_key(key)
    logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key)
    key_path = path && [*path, key.to_s]
    # A top-level key's root is the line; the keys below it get the top-level field's value
    key_root = (recursion_depth == 0) ? line_root : root
    children_root = (path && recursion_depth == 0) ? ConfigStruct::LazyRoot.new(value) : root
    # Check if this key should be filtered at any depth
    filtered = ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field, path: key_path, root: key_root)
    # Keys are scrubbed too: an email address can be a key
    result[StringScrubber.scrub_name(key)] = if !filtered
      process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: key_path, root: children_root)
    elsif value == RAILS_FILTERED_MASK
      # Rails' parameter filter has already replaced the value
      value
    else
      {_filtered: ParamFilters.summarize_json_attribute(key, value)}
    end
  end

  result
end

#process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity, path: nil, root: nil) ⇒ T.untyped

path and root are for filters that match a key by its path (see ParamFilters.should_filter_key?). They're only tracked when such filters exist: path is nil otherwise.

Parameters:

  • arg (T.untyped)
  • recursion_depth (Integer) (defaults to: 0)
  • ancestors (Hash{T.untyped => Boolean}) (defaults to: {}.compare_by_identity)
  • path (Array<String>, nil) (defaults to: nil)
  • root (T.untyped) (defaults to: nil)

Returns:

  • (T.untyped) 


73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
 
# File 'lib/log_struct/formatter.rb', line 73

def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity, path: nil, root: nil)
  if recursion_depth == 0 && path.nil? && !LogStruct.config.filters.path_matchers.empty?
    path = []
  end

  # Circular references and deeply nested values stop here. Values below this depth
  # would skip filtering and scrubbing, so they're summarized instead of logged.
  return summarize_unprocessed_value(arg) if recursion_depth > MAX_RECURSION_DEPTH || ancestors.key?(arg)

  case arg
  when Hash, Array
    ancestors[arg] = true
    begin
      if arg.is_a?(Hash)
        process_hash(arg, recursion_depth: recursion_depth, ancestors: ancestors, path: path, root: root)
      else
        process_array(arg, recursion_depth: recursion_depth, ancestors: ancestors, path: path, root: root)
      end
    ensure
      ancestors.delete(arg)
    end
  when GlobalID::Identification
    # Scrubbed like any String: a record's ID can be an email address
    begin
      scrub_string(arg.to_global_id.to_s)
    rescue
      begin
        object = T.cast(arg, Object)
        # Active Record is optional
        if defined?(::ActiveRecord::Base) && object.is_a?(::ActiveRecord::Base)
          scrub_string("#{object.class}(##{object.id})")
        else
          # For non-ActiveRecord objects that failed to_global_id, try to get a string representation
          # If this also fails, we want to catch it and return the error placeholder
          scrub_string(String(object))
        end
      rescue => e
        LogStruct.handle_exception(e, source: Source::Internal)
        "[GLOBALID_ERROR]"
      end
    end
  when Source, Event
    arg.serialize
  when String
    scrub_limited_string(valid_utf8(arg))
  when Time
    arg.iso8601(3)
  when Symbol
    StringScrubber.scrub_name(arg)
  when Float
    # JSON has no NaN or Infinity
    arg.finite? ? arg : arg.to_s
  when Numeric, TrueClass, FalseClass, NilClass
    arg
  else
    # Structs, ActionController::Parameters and other objects: filter and scrub what
    # to_json would write
    process_values(arg.as_json, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root)
  end
rescue SystemStackError, StandardError => e
  # A SystemStackError comes from an object whose as_json refers back to itself
  e = RuntimeError.new("#{e.class}: #{e.message}") unless e.is_a?(StandardError)
  # Report error through LogStruct's framework
  context = {
    processor_method: "process_values",
    value_type: arg.class.name,
    recursion_depth: recursion_depth
  }
  LogStruct.handle_exception(e, source: Source::Internal, context: context)
  summarize_unprocessed_value(arg)
end

#push_tags(*tags) ⇒ T.untyped

Parameters:

  • tags (Array<String>)

Returns:

  • (T.untyped) 


44
45
46
 
# File 'lib/log_struct/formatter.rb', line 44

def push_tags(*tags)
  current_tags.concat(tags)
end

#scrub_limited_string(string) ⇒ String

A string scrubbed, and cut to limits.max_string_bytes. The scrubbers see its first max_string_bytes plus SCRUB_MARGIN_BYTES: a value running past that was only partly seen, so scrub_cut_end replaces it if it can be a credential.

Parameters:

  • string (String)

Returns:

  • (String) 


219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
 
# File 'lib/log_struct/formatter.rb', line 219

def scrub_limited_string(string)
  max_bytes = LogStruct.config.limits.max_string_bytes
  return scrub_string(string) if string.bytesize <= max_bytes

  seen_bytes = max_bytes + SCRUB_MARGIN_BYTES
  scrubbed = scrub_string(string.byteslice(0, seen_bytes).to_s.scrub(""))
  if string.bytesize > seen_bytes
    scrubbed = StringScrubber.scrub_cut_end(scrubbed)
  elsif scrubbed.bytesize <= max_bytes
    # The scrubbers saw all of it, and their replacements made it short enough
    return scrubbed
  end
  kept = scrubbed.byteslice(0, max_bytes).to_s.scrub("")
  "#{kept}... (cut from #{string.bytesize} bytes)"
end

#scrub_string(string) ⇒ String

Parameters:

  • string (String)

Returns:

  • (String) 


49
50
51
52
 
# File 'lib/log_struct/formatter.rb', line 49

def scrub_string(string)
  # Use StringScrubber module to scrub sensitive information from strings
  StringScrubber.scrub(string)
end

#summarize_unprocessed_value(arg) ⇒ T.untyped

Describes a value without filtering, scrubbing or serializing it, so that values which couldn't be processed are never logged raw. Hashes and arrays are not serialized because they may contain circular references.

Parameters:

  • arg (T.untyped)

Returns:

  • (T.untyped) 


264
265
266
267
268
269
270
271
272
273
274
275
276
277
 
# File 'lib/log_struct/formatter.rb', line 264

def summarize_unprocessed_value(arg)
  case arg
  when Hash
    {_filtered: {_class: arg.class.name, _keys_count: arg.size}}
  when Array
    {_filtered: {_class: arg.class.name, _count: arg.size}}
  when String
    {_filtered: {_class: arg.class.name}}
  when Numeric, Symbol, TrueClass, FalseClass, NilClass
    arg
  else
    {_filtered: {_class: arg.class.name}}
  end
end

#symbolize_keys(value, recursion_depth: 0, ancestors: {}.compare_by_identity) ⇒ T.untyped

Like deep_symbolize_keys, but stops at circular references and at the depth where process_values stops, leaving those values for process_values to summarize

Parameters:

  • value (T.untyped)
  • recursion_depth (Integer) (defaults to: 0)
  • ancestors (Hash{T.untyped => Boolean}) (defaults to: {}.compare_by_identity)

Returns:

  • (T.untyped) 


238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
 
# File 'lib/log_struct/formatter.rb', line 238

def symbolize_keys(value, recursion_depth: 0, ancestors: {}.compare_by_identity)
  return value if recursion_depth > MAX_RECURSION_DEPTH || ancestors.key?(value)

  case value
  when Hash
    ancestors[value] = true
    result = value.each_with_object({}) do |(key, nested_value), symbolized|
      symbol_key = key.respond_to?(:to_sym) ? key.to_sym : key
      symbolized[symbol_key] = symbolize_keys(nested_value, recursion_depth: recursion_depth + 1, ancestors: ancestors)
    end
    ancestors.delete(value)
    result
  when Array
    ancestors[value] = true
    result = value.map { |item| symbolize_keys(item, recursion_depth: recursion_depth + 1, ancestors: ancestors) }
    ancestors.delete(value)
    result
  else
    value
  end
end

#tagged(*tags, &blk) ⇒ T.untyped

Add tagged method to support ActiveSupport::TaggedLogging

Parameters:

  • tags (Array<String>)
  • blk (T.proc.params(formatter: Formatter).void)

Returns:

  • (T.untyped) 


29
30
31
32
33
34
35
 
# File 'lib/log_struct/formatter.rb', line 29

def tagged(*tags, &blk)
  new_tags = tags.flatten
  current_tags.concat(new_tags) if new_tags.any?
  yield self
ensure
  current_tags.pop(new_tags.size) if new_tags&.any?
end

#unwritable_line_json(data, error) ⇒ String

A line that can't be written as JSON is replaced by one that says so, instead of being lost

Parameters:

  • data (Hash{T.untyped => T.untyped})
  • error (Exception)

Returns:

  • (String) 


383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
 
# File 'lib/log_struct/formatter.rb', line 383

def unwritable_line_json(data, error)
  level = data[:lvl]
  line = {
    src: enum_or_string(data[:src]) || Source::Internal.serialize,
    evt: enum_or_string(data[:evt]) || Event::Error.serialize,
    ts: data[:ts].is_a?(String) ? data[:ts] : Time.now.iso8601(3),
    lvl: level.is_a?(Level) ? level.serialize : Level::Error.serialize,
    msg: "LogStruct couldn't write this line as JSON",
    error_class: error.class.name
  }
  unless Thread.current[:logstruct_reporting_unwritable_line]
    begin
      Thread.current[:logstruct_reporting_unwritable_line] = true
      reported = error.is_a?(StandardError) ? error : RuntimeError.new("#{error.class}: #{error.message}")
      LogStruct.handle_exception(reported, source: Source::Internal, context: {src: line[:src], evt: line[:evt]})
    ensure
      Thread.current[:logstruct_reporting_unwritable_line] = nil
    end
  end
  "#{::JSON.generate(line)}\n"
end

#valid_utf8(string) ⇒ String

The string as valid UTF-8. JSON can't hold other bytes: Puma passes headers as binary strings, and a byte like \xFF in a User-Agent would stop the whole line from being written. Bytes that aren't valid UTF-8 become U+FFFD.

Parameters:

  • string (String)

Returns:

  • (String) 


193
194
195
 
# File 'lib/log_struct/formatter.rb', line 193

def valid_utf8(string)
  StringScrubber.valid_utf8(string)
end

#valid_utf8_key(key) ⇒ T.untyped

A String or Symbol key as valid UTF-8 (symbolize_keys makes Symbols of binary String keys)

Parameters:

  • key (T.untyped)

Returns:

  • (T.untyped) 


199
200
201
202
203
204
205
206
207
208
209
210
 
# File 'lib/log_struct/formatter.rb', line 199

def valid_utf8_key(key)
  case key
  when String
    valid_utf8(key)
  when Symbol
    name = key.name
    fixed = valid_utf8(name)
    fixed.equal?(name) ? key : fixed.to_sym
  else
    key
  end
end