Module: PWN::Plugins::Log

Defined in:
lib/pwn/plugins/log.rb

Overview

This plugin is used to instantiate a PWN logger with a custom message format

Defined Under Namespace

Classes: DebugStderrTee

Constant Summary collapse

TRACE_SKIP_METHODS = 
%i[
  authors help to_s inspect class object_id hash eql? == equal? !
  method public_send send __send__ instance_eval class_eval
  public_class_method private_class_method
  debug_on? debug_progress start_debug_session quiet_debug_tui!
  loud_debug_tui! budget_scar? effective_count safe_check
  rank_for_request usable_preference? cause_crumb
].freeze
TRACE_SKIP_PREFIXES = 
%w[
  PWN::Plugins::Log
  PWN::Plugins::REPL
  PWN::Banner
].freeze
DEFAULT_TRACE_PREFIXES = 
%w[
  PWN::AI
  PWN::Memory
  PWN::Sessions
  PWN::Config
  PWN::Cron
  PWN::Plugins
].freeze
SECRET_KEY_RX = 
/password|passwd|secret|token|api[_-]?key|authorization|bearer|cookie|session[_-]?id|private[_-]?key|decryptor|credential|ssh[_-]?key|client[_-]?secret|refresh[_-]?token|access[_-]?token|id[_-]?token|vault|csrf/i
SECRET_VALUE_RX = 
%r{
  -----BEGIN\ [A-Z ]*PRIVATE\ KEY----- |
  Bearer\s+[A-Za-z0-9\-._~+/]+=* |
  \beyJ[A-Za-z0-9\-_]+\.[A-Za-z0-9\-_]+\.[A-Za-z0-9\-_]+ |
  \b(?:sk|rk|pk|xai|xox[baprs]|ghp|gho|ghu|ghs|ghr|glpat|AKIA|ASIA|ya29)[-_][A-Za-z0-9\-_]{16,} |
  \b(?:api[_-]?key|token|secret|password|passwd)\s*[:=]\s*\S+
}ix
DEBUG_VALUE_MAX = 
240
DEBUG_ARGS_MAX = 
1_800

Class Method Summary collapse

Class Method Details

.append(opts = {}) ⇒ Object

Supported Method Parameters

PWN::Log.create( )



47
48
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
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
 
# File 'lib/pwn/plugins/log.rb', line 47

public_class_method def self.append(opts = {})
  level = opts[:level].to_s.downcase.to_sym
  msg = opts[:msg]
  which_self = opts[:which_self].to_s

  driver_name = File.basename($PROGRAM_NAME)

  # Only attempt to exit gracefully if level == :error
  exit_gracefully = false

  # Define Date / Time Format
  datetime_str = '%Y-%m-%d %H:%M:%S.%N%z'

  # Always append to log file
  if level == :learning
    session = SecureRandom.hex
    log_file_path = "/tmp/pwn-ai-#{session}.json" if level == :learning
    log_file = File.open(log_file_path, 'w')
  else
    log_file_path = '/tmp/pwn.log'
    log_file = File.open(log_file_path, 'a')
  end

  # Leave 10 "old" log files where
  # each file is ~ 1,024,000 bytes
  logger = Logger.new(
    log_file,
    10,
    1_024_000
  )
  logger.datetime_format = datetime_str

  case level
  when :debug
    logger.level = Logger::DEBUG
  when :error
    logger.level = Logger::ERROR
    exit_gracefully = true unless driver_name == 'pwn'
    puts "\nERROR: See #{log_file_path} for more details." if driver_name == 'pwn'
  when :fatal
    logger.level = Logger::FATAL
    puts "\n FATAL ERROR: See #{log_file_path} for more details." if driver_name == 'pwn'
  when :info, :learning
    logger.level = Logger::INFO
  when :unknown
    logger.level = Logger::UNKNOWN
  when :warn
    logger.level = Logger::WARN
  else
    level_error = "ERROR: Invalid log level. Valid options are:\n"
    level_error += ":debug\n:error\n:fatal\n:info\n:learning\n:unknown\n:warn\n"
    raise level_error
  end

  if level == :learning
    log_event = msg
    logger.formatter = proc do |_severity, _datetime, _progname, learning_arr|
      JSON.pretty_generate(
        learning_data: learning_arr
      )
    end
  else
    log_event = "driver: #{driver_name}"

    if msg.instance_of?(Interrupt)
      logger.level = Logger::WARN
      note_interrupt!(where: 'CTRL+C', which_self: which_self) if debug_enabled?
      if driver_name == 'pwn'
        log_event += ' => CTRL+C Detected.'
      else
        log_event += ' => CTRL+C Detected...Exiting Session.'
        exit_gracefully = true unless driver_name == 'pwn'
      end
    else
      log_event += " => #{msg}"
      if msg.respond_to?('backtrace') && !msg.instance_of?(Errno::ECONNRESET)
        log_event += " => \n\t#{msg.backtrace.join("\n\t")}"
        log_event += "\n\n\n"
      end
    end
  end

  logger.add(logger.level, log_event, which_self)
rescue Interrupt
  note_interrupt!(where: 'CTRL+C', which_self: self) if debug_enabled?
  puts "\n#{self}.#{__method__} => Goodbye."
rescue StandardError => e
  raise e
end

.authors ⇒ Object

Author(s)

0day Inc. support@0dayinc.com



682
683
684
685
686
 
# File 'lib/pwn/plugins/log.rb', line 682

public_class_method def self.authors
  "AUTHOR(S):
    0day Inc. <support@0dayinc.com>
  "
end

.capture_stderr!(opts = {}) ⇒ Object 



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
 
# File 'lib/pwn/plugins/log.rb', line 313

public_class_method def self.capture_stderr!(opts = {})
  return unless debug_enabled?
  return if Thread.current[:pwn_log_stderr]

  text = opts[:text].to_s
  return if text.empty?
  return if (text: text)

  Thread.current[:pwn_log_stderr] = true
  begin
    io = @debug_file
    return if io.nil? || (io.respond_to?(:closed?) && io.closed?)

    clean = sanitize_debug_text(text: text.gsub(/\e\[[0-9;]*m/, ''))
    return if clean.strip.empty?
    return if (text: clean)

    io.write(clean.end_with?("\n") ? clean : "#{clean}\n")
    io.flush
  rescue StandardError
    nil
  ensure
    Thread.current[:pwn_log_stderr] = false
  end
  clean
end

.debug_enabled?(opts = {}) ⇒ Boolean

Returns:

  • (Boolean) 


137
138
139
140
141
 
# File 'lib/pwn/plugins/log.rb', line 137

public_class_method def self.debug_enabled?(opts = {})
  return @debug_enabled == true if opts.is_a?(Hash)

  @debug_enabled == true
end

.debug_log_path(opts = {}) ⇒ Object 



143
144
145
146
147
 
# File 'lib/pwn/plugins/log.rb', line 143

public_class_method def self.debug_log_path(opts = {})
  return @debug_path if opts.is_a?(Hash)

  @debug_path
end

.finish_request_log!(opts = {}) ⇒ Object 



197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
 
# File 'lib/pwn/plugins/log.rb', line 197

public_class_method def self.finish_request_log!(opts = {})
  return unless debug_enabled?
  return unless @debug_request_open || opts[:force] == true

  bits = [
    "footer iter=#{opts[:iter].to_i}",
    "tools_called=#{opts[:tools_called].to_i}",
    "engine_s=#{opts[:engine_s].to_f.round(3)}",
    "final_chars=#{opts[:final_chars].to_i}"
  ]
  bits << "nested=#{opts[:nested]}" unless opts[:nested].to_s.empty?
  progress(msg: bits.join(' '), which_self: self)
  @debug_request_open = false
  @debug_path
end

.help ⇒ Object

Display Usage for this Module



690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
 
# File 'lib/pwn/plugins/log.rb', line 690

public_class_method def self.help
  puts "USAGE:
    logger = #{self}.append(
      level: 'required - log verbosity :debug|:error|:fatal|:info|:learning|:unknown|:warn',
      msg: 'required - message to log',
      which_self: 'required - pass in self object from module calling #{self}'
    )

    path = #{self}.start_debug(
      tee: $stdout,
      session_id: 'optional - pwn-ai session id'
    )
    #{self}.next_request_log!(session_id: 'optional')
    #{self}.progress(msg: 'stage', which_self: self)
    #{self}.finish_request_log!(iter: 1, tools_called: 0, engine_s: 0.2, final_chars: 12)
    #{self}.stop_debug
    # start_debug(trace: true) enables per-call TracePoint (opt-in)
  "
end

.loud_tui!(opts = {}) ⇒ Object 



419
420
421
422
423
 
# File 'lib/pwn/plugins/log.rb', line 419

public_class_method def self.loud_tui!(opts = {})
  return if opts[:skip]

  @debug_tui_quiet = false
end

.mirror_tui!(opts = {}) ⇒ Object

Clone operator-visible TUI rows into the open RN request log (no ANSI). Used for [ ts → pwn-ai → tool ] / → result / task briefs so the file matches what the operator saw without needing a TracePoint dump.



512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
 
# File 'lib/pwn/plugins/log.rb', line 512

public_class_method def self.mirror_tui!(opts = {})
  return unless debug_enabled?
  return unless opts.is_a?(Hash)

  text = opts[:msg].to_s
  text = text.gsub(/\e\[[0-9;]*m/, '')
  text = sanitize_debug_text(text: text)
  return if text.strip.empty?

  begin
    io = @debug_file
    return if io.nil? || (io.respond_to?(:closed?) && io.closed?)

    io.write(text.end_with?("\n") ? text : "#{text}\n")
    io.flush
  rescue StandardError
    return
  end
  text
end

.next_request_log!(opts = {}) ⇒ Object 



180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
 
# File 'lib/pwn/plugins/log.rb', line 180

public_class_method def self.next_request_log!(opts = {})
  return unless debug_enabled?
  return @debug_path if @debug_request_open && opts[:force] != true

  sid = sanitize_debug_session_id(session_id: opts[:session_id])
  sid = @debug_session_id if sid.empty?
  sid = 'nosession' if sid.empty?
  @debug_session_id = sid
  n = next_debug_request_n(session_id: sid)
  path = "/tmp/pwn-ai-DEBUG-#{sid}-R#{n}.log"
  open_debug_file!(path: path)
  @debug_req_n = n
  @debug_request_open = true
  progress(msg: "request log R#{n} path=#{path}", which_self: self)
  path
end

.note_exception!(opts = {}) ⇒ Object 



492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
 
# File 'lib/pwn/plugins/log.rb', line 492

public_class_method def self.note_exception!(opts = {})
  return false unless debug_enabled?

  err = opts[:error]
  return false unless err.respond_to?(:message)

  where = opts[:where].to_s
  where = 'Loop.run' if where.empty?
  bt = Array(err.backtrace).join("\n")
  progress(
    msg: "exception #{where} #{err.class}: #{err.message}\n#{bt}",
    which_self: opts[:which_self] || self,
    keep_newlines: true,
    cap: 0
  )
end

.note_interrupt!(opts = {}) ⇒ Object 



460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
 
# File 'lib/pwn/plugins/log.rb', line 460

public_class_method def self.note_interrupt!(opts = {})
  return false unless debug_enabled?

  where = opts[:where].to_s
  where = 'CTRL+C' if where.empty?
  # CTRL+C can land mid-progress (HTTP spinner tee, tool row mirror).
  # Clear the reentrancy latch so the Interrupt stamp always lands in the
  # open RN file before the ensure footer / process unwind.
  Thread.current[:pwn_log_progress] = false
  at = Time.now
  local_ts = at.strftime('%Y-%m-%d %H:%M:%S.%L%z')
  msg = "Interrupt #{where} at=#{at.utc.iso8601(3)}"
  which = opts[:which_self] || self
  # Prefer the normal DEBUG stamp path; fall back to a direct file write
  # if progress is still unavailable for any reason.
  ok = progress(msg: msg, which_self: which)
  unless ok
    begin
      who = which.is_a?(Module) ? (which.name || which.to_s) : which.to_s
      line = "[DEBUG #{local_ts}] #{who} #{msg}".strip
      @debug_file&.puts(line)
      @debug_file&.flush
      ok = true
    rescue StandardError
      ok = false
    end
  end
  # Also clone the operator-facing TUI shape into the RN file.
  mirror_tui!(msg: "[ #{local_ts} → pwn-ai → Interrupt ] #{where}")
  ok
end

.progress(opts = {}) ⇒ Object

One progress line to the debug file and the TUI tee (same payload).



426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
 
# File 'lib/pwn/plugins/log.rb', line 426

public_class_method def self.progress(opts = {})
  return false unless debug_enabled?
  return false if Thread.current[:pwn_log_progress]

  Thread.current[:pwn_log_progress] = true
  msg = sanitize_debug_text(text: opts[:msg].to_s)
  which = opts[:which_self] || self
  line = format_progress(
    msg: msg,
    which_self: which,
    keep_newlines: opts[:keep_newlines],
    cap: opts[:cap]
  )
  begin
    @debug_file&.puts(line)
    @debug_file&.flush
  rescue StandardError
    nil
  end
  tee = opts.key?(:tee) ? opts[:tee] : @debug_tee
  if !@debug_tui_quiet && tee.respond_to?(:puts)
    begin
      tee.puts(color_progress(line: line))
      tee.flush if tee.respond_to?(:flush)
      $stdout.flush if $stdout.respond_to?(:flush)
    rescue StandardError
      nil
    end
  end
  true
ensure
  Thread.current[:pwn_log_progress] = false
end

.quiet_tui!(opts = {}) ⇒ Object 



413
414
415
416
417
 
# File 'lib/pwn/plugins/log.rb', line 413

public_class_method def self.quiet_tui!(opts = {})
  return if opts[:skip]

  @debug_tui_quiet = true
end

.raw_stderr(opts = {}) ⇒ Object 



350
351
352
353
354
 
# File 'lib/pwn/plugins/log.rb', line 350

public_class_method def self.raw_stderr(opts = {})
  return @debug_stderr_orig if opts.is_a?(Hash) && @debug_stderr_orig

  $stderr
end

.spinner_frame?(opts = {}) ⇒ Boolean

Spinner frames stay on the TTY; never persist them in the RN log.

Returns:

  • (Boolean) 


341
342
343
344
345
346
347
348
 
# File 'lib/pwn/plugins/log.rb', line 341

public_class_method def self.(opts = {})
  raw = opts[:text].to_s
  return false if raw.empty?

  stripped = raw.gsub(/\e\[[0-9;?]*[A-Za-z]/, '').delete("\r").delete("\b")
  stripped = stripped.gsub(/[\u2800-\u28FF]/, '')
  stripped.strip.empty?
end

.start_debug(opts = {}) ⇒ Object

Open a debug session. Request traces go to /tmp/pwn-ai-DEBUG-<session_id>-RN.log via next_request_log!. opts is a test override that writes to one file.



152
153
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
 
# File 'lib/pwn/plugins/log.rb', line 152

public_class_method def self.start_debug(opts = {})
  if debug_enabled? && opts[:path].to_s.empty?
    @debug_tee = opts[:tee] if opts.key?(:tee)
    sid = sanitize_debug_session_id(session_id: opts[:session_id])
    @debug_session_id = sid unless sid.empty?
    return @debug_path
  end

  stop_trace! if @debug_tp
  path = opts[:path].to_s
  @debug_tee = opts[:tee]
  @debug_tui_quiet = false
  @debug_enabled = true
  @debug_session_id = sanitize_debug_session_id(session_id: opts[:session_id])
  @debug_req_n = 0
  @debug_request_open = false
  if path.empty?
    close_debug_file!
    @debug_path = nil
  else
    open_debug_file!(path: path)
  end
  start_trace!(prefixes: opts[:prefixes]) if opts[:trace] == true
  install_stderr_tee!
  progress(msg: 'debug session start', which_self: self) if @debug_file
  @debug_path
end

.start_trace!(opts = {}) ⇒ Object 



653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
 
# File 'lib/pwn/plugins/log.rb', line 653

public_class_method def self.start_trace!(opts = {})
  return @debug_tp if @debug_tp && opts.is_a?(Hash)

  prefixes = Array(opts[:prefixes] || DEFAULT_TRACE_PREFIXES).map(&:to_s)
  prefixes = DEFAULT_TRACE_PREFIXES if prefixes.empty?
  @debug_tp = TracePoint.new(:call) do |tp|
    next unless debug_enabled?
    next unless traceable?(tp: tp, prefixes: prefixes)

    progress(
      msg: format_trace_call(tp: tp),
      which_self: ''
    )
  rescue StandardError
    nil
  end
  @debug_tp.enable
  @debug_tp
end

.stop_debug(opts = {}) ⇒ Object 



213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
 
# File 'lib/pwn/plugins/log.rb', line 213

public_class_method def self.stop_debug(opts = {})
  reason = opts[:reason].to_s if opts.is_a?(Hash)
  if debug_enabled?
    tail = reason.to_s.empty? ? 'debug session stop' : "debug session stop reason=#{reason}"
    progress(msg: tail, which_self: self)
  end
  stop_trace!
  path = @debug_path
  close_debug_file!
  @debug_path = nil
  @debug_session_id = nil
  @debug_req_n = nil
  @debug_request_open = false
  @debug_tee = nil
  @debug_tui_quiet = false
  @debug_enabled = false
  remove_stderr_tee!
  path
end

.stop_trace!(opts = {}) ⇒ Object 



673
674
675
676
677
678
 
# File 'lib/pwn/plugins/log.rb', line 673

public_class_method def self.stop_trace!(opts = {})
  return if opts[:skip]

  @debug_tp&.disable
  @debug_tp = nil
end