Repository navigation
fix(microvm-worker): log timer failures after lock - #838
Merged
Merged
Conversation
A timer that could not start was logged under the listener lock. A logger that calls the listener then deadlocked it. Now the failure is recorded under the lock and logged after the lock is released. Fixes #832.
This addresses the review of #838. A timer start now raises RuntimeError outside _locked(), and the tests and docstrings are fixed.
This branch was successfully deployed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes #832.
Summary
When a timer cannot start, the MicroVM worker now logs the failure after it releases the listener lock. The log text and fields are unchanged.
Why
_start_idle_timeand_start_graceholdsself._lock.threading.Timer.start()raised, each method logged through the caller's logger while it still held that lock.close(), deadlocked it.Changes
_start_idle_timeand_start_gracerecord a failure in_timer_failuresunder the lock. They no longer call the logger._locked(), takes the lock and runs the block. In afinally, it takes the recorded failures, releases the lock, and logs each one withdescribe(error). So the logging also runs when the block raises or returns early._end_suspendingor_suspend_call_ended, useswith self._locked():. That is 10 blocks._start_idle_timeand_start_gracefirst check that a_locked()block runs, and raiseRuntimeErrorotherwise. So a later block that takesself._lockdirectly and starts a timer fails at once, instead of leaving its failure for an unrelated block to log.Testing
describe,str,repr, or caller code while the lock is held.error()callslistener.close()or sends a hook over HTTP. They fail onmain(a deadlock, and aTimeoutError) and pass here. Each test is bounded by a timeout.hatch run dev-microvm-worker:cov: 453 tests,worker.py100 %. Typecheck andhatch fmt --checkpass. A stress run with-n 8passed 3 times.By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.