|
require 'logger'
|
|
require 'timeout'
|
|
|
|
# @logger is one of examples that includes a MonitorMixin somehow,
|
|
# which state can be broken unexpectedly by timeout.
|
|
@logger = Logger.new("/tmp/tmp.txt")
|
|
|
|
# mon_info_util is just a utility function composing monitor state information,
|
|
# which is only used to be logged for clarity.
|
|
def mon_info_util
|
|
logdev = @logger.instance_variable_get(:@logdev)
|
|
"mon_owned=#{logdev.mon_owned?}, mon_locked=#{logdev.mon_locked?}, mon_owner=#{logdev.instance_variable_get(:@mon_owner)}"
|
|
end
|
|
|
|
# repeat_logging_until_timeout represents a bug-reproducible function.
|
|
# It repeats writing a log until a timeout interrupts the operation.
|
|
def repeat_logging_until_timeout
|
|
# this timout block could reproduce a deadlock-ish situation caused by a timeout
|
|
Timeout.timeout(1) do
|
|
while true do
|
|
@logger.info "test"
|
|
end
|
|
end
|
|
|
|
rescue Timeout::Error => e
|
|
# check the monitor state
|
|
m = e.backtrace.join("\n")
|
|
p "#{e.message}\n#{m}\n"
|
|
p "main: #{mon_info_util}"
|
|
|
|
# tha fact that mon_owned? returns true even after finishing @logger.info is the root problem.
|
|
logdev = @logger.instance_variable_get(:@logdev)
|
|
if logdev.mon_owned?
|
|
# if you remove this comment out, calling mon_exit explicitly allows the other thread to write a log successfully.
|
|
# logdev.mon_exit
|
|
|
|
t = Thread.new do
|
|
p "t: #{mon_info_util}"
|
|
# @logger.info is blocked forever before writing because of the monitor locked by the other thread.
|
|
@logger.info "new thread writing from logger"
|
|
end
|
|
sleep 5
|
|
@logger.info "t's backtrace is #{t.backtrace.join("\n")}"
|
|
raise e
|
|
end
|
|
end
|
|
|
|
# do an endless loop until the inside function succeeds to reproduce the bug.
|
|
while true do
|
|
repeat_logging_until_timeout
|
|
end
|