Infrequent weird output in tests
nateberkopec opened this issue · 1 comments
examples were filtered out; ignoring {:focus=>true}
............................................................./host/nateberkopec/Documents/Code.nosync/upstream/rack-mini-profiler/vendor/bundle/ruby/3.1.0/gems/rack-proxy-0.7.6/lib/rack/proxy.rb:130: warning: assigned but unused variable - ssl_verify_none
............#<Rack::MiniProfiler::MemoryStore::CacheCleanupThread:0x0000ffff74dffd80 /host/nateberkopec/Documents/Code.nosync/upstream/rack-mini-profiler/lib/mini_profiler/storage/memory_store.rb:77 run> terminated with exception (report_on_exception is true):
........../host/nateberkopec/Documents/Code.nosync/upstream/rack-mini-profiler/lib/mini_profiler/storage/memory_store.rb:79:in `block in initialize_cleanup_thread': undefined method `sleepy_run' for nil:NilClass (NoMethodError)
t.sleepy_run
^^^^^^^^^^^
........................................................................................................................................................................................................
This took a while to track down (but was a lot of fun too! 😄)
The root cause is that the code block of CacheCleanupThread
is scheduled to run as soon as super
is called in CacheCleanupThread#initialize
. This results in a race condition where the thread may run before the thread class instance is fully instantiated. While this seems counterintuitive, I was tipped off to the possibility here https://www.ruby-forum.com/t/thread-super-should-be-first-line-or-last-line/150617 I later proved this was happening by the code changes that fixed the problem.
There are actually two separate race conditions
- The thread may be scheduled to run before the thread instance is returned by
CacheCleanupThread.new
. When this happenst
is undefined inside the thread block. This results in the error "undefined method `sleepy_run' for nil:NilClass" that we see in the test output
def initialize_cleanup_thread(args = {})
cleanup_interval = args.fetch(:cleanup_interval) { CLEANUP_INTERVAL }
cleanup_cycle = args.fetch(:cleanup_cycle) { CLEANUP_CYCLE }
t = CacheCleanupThread.new(cleanup_interval, cleanup_cycle, self) do
until Thread.current[:should_exit] do
t.sleepy_run # <===== t may be undefined here!
end
end
at_exit { t[:should_exit] = true }
end
This can be fixed by changing t.sleepy_run
to Thread.current.sleepy_run
- The thread may be scheduled to run before the member variables in
CacheCleanupThread#initialize
are defined. This results in "undefined method '*' for nil:NilClass" inshould_cleanup?
(this error only occurs after the first race condition is fixed)
def should_cleanup?
@cycle_count * @interval >= @cycle
end
This happens because @cycle_count
, @interval
, and @cycle
may be undefined when thread execution starts. It can be fixed by moving super
to the bottom of CacheCleanupThread#initialize
def initialize(interval, cycle, store)
@store = store
@interval = interval
@cycle = cycle
@cycle_count = 1
super
end
The race conditions causing this intermittent test output are also present in the production code, but I don't know if they actually manifest themselves?
I will open a PR shortly with the fixes