Give Threads UUIDs for spec run so caller can be correlated
Have 'metasploit/framework/spec/threads/suite/logger' generate a UUID for each Thread. This UUID is printed on the "BEGIN Thread.new caller" line and is assigned as a thread-local variable, 'metasploit/framework/spec/threads/logger/uuid'. In `after(:suite)`, the log can be parsed to map the caller back to each UUID and then only the UUID of the still existing threads is used to look up the caller and print their stacktraces. This means only leaked threads callers will be printed.bug/bundler_fix
Luke Imhoff
parent
8f635a1d76
commit
8416985c9d
|
|
@ -1,10 +1,22 @@
|
|||
#
|
||||
# Standard Library
|
||||
#
|
||||
|
||||
require 'securerandom'
|
||||
|
||||
#
|
||||
# Project
|
||||
#
|
||||
|
||||
require 'metasploit/framework/spec/threads/suite'
|
||||
|
||||
original_thread_new = Thread.method(:new)
|
||||
|
||||
# Patches `Thread.new` so that if logs `caller` so thread leaks can be traced
|
||||
Thread.define_singleton_method(:new) { |*args, &block|
|
||||
lines = ['BEGIN Thread.new caller']
|
||||
uuid = SecureRandom.uuid
|
||||
# tag caller with uuid so that only leaked threads caller needs to be printed
|
||||
lines = ["BEGIN Thread.new caller (#{uuid})"]
|
||||
|
||||
caller.each do |frame|
|
||||
lines << " #{frame}"
|
||||
|
|
@ -19,5 +31,11 @@ Thread.define_singleton_method(:new) { |*args, &block|
|
|||
f.puts lines.join("\n")
|
||||
}
|
||||
|
||||
original_thread_new.call(*args, &block)
|
||||
options = {original_args: args, uuid: uuid}
|
||||
|
||||
original_thread_new.call(options) {
|
||||
# record uuid for thread-leak detection can used uuid to correlate log with this thread.
|
||||
Thread.current[Metasploit::Framework::Spec::Threads::Suite::UUID_THREAD_LOCAL_VARIABLE] = options.fetch(:uuid)
|
||||
block.call(*options.fetch(:original_args))
|
||||
}
|
||||
}
|
||||
|
|
@ -11,10 +11,14 @@ module Metasploit
|
|||
# CONSTANTS
|
||||
#
|
||||
|
||||
# Number of allowed threads when threads are counted in `before(:suite)`
|
||||
EXPECTED_THREAD_COUNT_BEFORE_SUITE = 1
|
||||
# Number of allowed threads when threads are counted in `after(:suite)` or `before(:suite)`
|
||||
EXPECTED_THREAD_COUNT_AROUND_SUITE = 1
|
||||
# `caller` for all Thread.new calls
|
||||
LOG_PATHNAME = Pathname.new('log/metasploit/framework/spec/threads/suite.log')
|
||||
# Regular expression for extracting the UUID out of {LOG_PATHNAME} for each Thread.new caller block
|
||||
UUID_REGEXP = /BEGIN Thread.new caller \((?<uuid>.*)\)/
|
||||
# Name of thread local variable that Thread UUID is stored
|
||||
UUID_THREAD_LOCAL_VARIABLE = "metasploit/framework/spec/threads/logger/uuid"
|
||||
|
||||
#
|
||||
# Module Methods
|
||||
|
|
@ -30,7 +34,7 @@ module Metasploit
|
|||
thread_count = Thread.list.count
|
||||
|
||||
# check with if first so that error message can be constructed lazily
|
||||
if thread_count > EXPECTED_THREAD_COUNT_BEFORE_SUITE
|
||||
if thread_count > EXPECTED_THREAD_COUNT_AROUND_SUITE
|
||||
# LOG_PATHNAME may not exist if suite run without `rake spec`
|
||||
if LOG_PATHNAME.exist?
|
||||
log = LOG_PATHNAME.read()
|
||||
|
|
@ -40,10 +44,61 @@ module Metasploit
|
|||
|
||||
raise RuntimeError,
|
||||
"#{thread_count} #{'thread'.pluralize(thread_count)} exist(s) when " \
|
||||
"only #{EXPECTED_THREAD_COUNT_BEFORE_SUITE} " \
|
||||
"#{'thread'.pluralize(EXPECTED_THREAD_COUNT_BEFORE_SUITE)} expected before suite runs:\n" \
|
||||
"only #{EXPECTED_THREAD_COUNT_AROUND_SUITE} " \
|
||||
"#{'thread'.pluralize(EXPECTED_THREAD_COUNT_AROUND_SUITE)} expected before suite runs:\n" \
|
||||
"#{log}"
|
||||
end
|
||||
|
||||
LOG_PATHNAME.parent.mkpath
|
||||
|
||||
LOG_PATHNAME.open('a') do |f|
|
||||
# separator so after(:suite) can differentiate between threads created before(:suite) and during the
|
||||
# suites
|
||||
f.puts 'before(:suite)'
|
||||
end
|
||||
end
|
||||
|
||||
config.after(:suite) do
|
||||
LOG_PATHNAME.parent.mkpath
|
||||
|
||||
LOG_PATHNAME.open('a') do |f|
|
||||
# separator so that a flip flop can be used when reading the file below. Also useful if it turns
|
||||
# out any threads are being created after this callback, which could be the case if another
|
||||
# after(:suite) accidentally created threads by creating an Msf::Simple::Framework instance.
|
||||
f.puts 'after(:suite)'
|
||||
end
|
||||
|
||||
thread_list = Thread.list
|
||||
|
||||
thread_uuids = thread_list.map { |thread|
|
||||
thread[Metasploit::Framework::Spec::Threads::Suite::UUID_THREAD_LOCAL_VARIABLE]
|
||||
}.compact
|
||||
|
||||
thread_count = thread_list.count
|
||||
|
||||
if thread_count > EXPECTED_THREAD_COUNT_AROUND_SUITE
|
||||
error_lines = []
|
||||
|
||||
if LOG_PATHNAME.exist?
|
||||
caller_by_thread_uuid = Metasploit::Framework::Spec::Threads::Suite.caller_by_thread_uuid
|
||||
|
||||
thread_uuids.each do |thread_uuid|
|
||||
caller = caller_by_thread_uuid[thread_uuid]
|
||||
|
||||
error_lines << "Thread #{thread_uuid}\n"
|
||||
|
||||
error_lines.concat(caller)
|
||||
end
|
||||
else
|
||||
error_lines << "Run `rake spec` to log where Thread.new is called."
|
||||
end
|
||||
|
||||
raise RuntimeError,
|
||||
"#{thread_count} #{'thread'.pluralize(thread_count)} exist(s) when only " \
|
||||
"#{EXPECTED_THREAD_COUNT_AROUND_SUITE} " \
|
||||
"#{'thread'.pluralize(EXPECTED_THREAD_COUNT_AROUND_SUITE)} expected after suite runs:\n" \
|
||||
"#{error_lines.join}"
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
|
|
@ -68,6 +123,77 @@ module Metasploit
|
|||
|
||||
Rake::Task.define_task(spec: 'metasploit:framework:spec:threads:suite')
|
||||
end
|
||||
|
||||
# @note Ensure {LOG_PATHNAME} exists before calling.
|
||||
#
|
||||
# Yields each line of {LOG_PATHNAME} that happened during the suite run.
|
||||
#
|
||||
# @yield [line]
|
||||
# @yieldparam line [String] a line in the {LOG_PATHNAME} between `before(:suite)` and `after(:suite)`
|
||||
# @yieldreturn [void]
|
||||
def self.each_suite_line
|
||||
in_suite = false
|
||||
|
||||
LOG_PATHNAME.each_line do |line|
|
||||
if in_suite
|
||||
if line.start_with?('after(:suite)')
|
||||
break
|
||||
else
|
||||
yield line
|
||||
end
|
||||
else
|
||||
if line.start_with?('before(:suite)')
|
||||
in_suite = true
|
||||
end
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
# @note Ensure {LOG_PATHNAME} exists before calling.
|
||||
#
|
||||
# Yield each line for each Thread UUID gathered during the suite run.
|
||||
#
|
||||
# @yield [uuid, line]
|
||||
# @yieldparam uuid [String] the UUID of thread thread
|
||||
# @yieldparam line [String] a line in the `caller` for the given `uuid`
|
||||
# @yieldreturn [void]
|
||||
def self.each_thread_line
|
||||
in_thread_caller = false
|
||||
uuid = nil
|
||||
|
||||
each_suite_line do |line|
|
||||
if in_thread_caller
|
||||
if line.start_with?('END Thread.new caller')
|
||||
in_thread_caller = false
|
||||
next
|
||||
else
|
||||
yield uuid, line
|
||||
end
|
||||
else
|
||||
match = line.match(UUID_REGEXP)
|
||||
|
||||
if match
|
||||
in_thread_caller = true
|
||||
uuid = match[:uuid]
|
||||
end
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
# The `caller` for each Thread UUID.
|
||||
#
|
||||
# @return [Hash{String => Array<String>}]
|
||||
def self.caller_by_thread_uuid
|
||||
lines_by_thread_uuid = Hash.new { |hash, uuid|
|
||||
hash[uuid] = []
|
||||
}
|
||||
|
||||
each_thread_line do |uuid, line|
|
||||
lines_by_thread_uuid[uuid] << line
|
||||
end
|
||||
|
||||
lines_by_thread_uuid
|
||||
end
|
||||
end
|
||||
end
|
||||
end
|
||||
|
|
|
|||
Loading…
Reference in New Issue