Fix "log_writer.rb:59:in `write': deadlock; recursive locking (ThreadError)"

[MSP-Greg]

Description

CI intermittently fails with "log_writer.rb:59:in `write': deadlock; recursive locking (ThreadError)". This is happening in log writes/puts, and this code maybe called in signal handlers. Mutex and other locking mechanisms cannot be used in signal handlers, so this PR is an attempt to fix the problem.

Example log:

/Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `write': deadlock; recursive locking (ThreadError)
	from /Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `puts'
	from /Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `log'
	from /Users/runner/work/puma/puma/lib/puma/launcher.rb:329:in `log'
	from /Users/runner/work/puma/puma/lib/puma/launcher.rb:205:in `close_binder_listeners'
	from /Users/runner/work/puma/puma/lib/puma/cluster.rb:329:in `block in setup_signals'
	from /Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `write'
	from /Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `puts'
	from /Users/runner/work/puma/puma/lib/puma/log_writer.rb:59:in `log'
	from /Users/runner/work/puma/puma/lib/puma/runner.rb:44:in `log'
	from /Users/runner/work/puma/puma/lib/puma/cluster.rb:460:in `run'

While doing recent work in my fork I have also seen the error. Can't repo locally, and tried to get code independent of Puma to fail, again, no luck.

Wondering if anyone has a better idea?

Second commit contains minor test fixes for intermittent issues.

Your checklist for this pull request

• I have reviewed the guidelines for contributing to this repository.
• I have added (or updated) appropriate tests if this PR fixes a bug or adds a feature.
• My pull request is 100 lines added/removed or less so that it can be easily reviewed.
• If this PR doesn't need tests (docs change), I added [ci skip] to the title of the PR.
• If this closes any issues, I have added "Closes #issue" to the PR description or my commit messages.
• I have updated the documentation accordingly.
• All new and existing tests passed, including Rubocop.

[dentarg]

https://ruby-doc.org/stdlib-2.7.1/libdoc/io/wait/rdoc/IO.html#wait_writable-method

Waits until IO is writable without blocking and returns self or nil when times out.

Sounds like this shouldn't hurt to have

[MSP-Greg]

Sounds like this shouldn't hurt to have

My thought also. Also, catching 'bad io' errors so a restart or shutdown isn't interrupted.

I intend to run it a few times in my fork to see if the intermittent error occurs...

[MSP-Greg]

Since this was merged, I've seen one "log_writer.rb:59:in `write': deadlock; recursive locking (ThreadError)" error running in my fork.

The following doesn't afford really perfect locking, but it's better than what we have now. Any thoughts? It runs fine locally, haven't tried it on Actions...

WRITE_QUEUE = Thread::Queue.new
def lock
  locked = false
  @stdout.is_a?(IO) and @stdout.wait_writable(1)
  sleep 0.005 until WRITE_QUEUE.empty?
  WRITE_QUEUE.push Process.pid
  locked = true
  yield
  @stdout.flush unless @stdout.sync
rescue Errno::EPIPE, Errno::EBADF
ensure
  WRITE_QUEUE.pop if locked
end

# Write +str+ to +@stdout+
def log(str)
  lock { @stdout.puts(format str) } if @stdout.respond_to? :puts
end

def write(str)
  lock { @stdout.write format(str) }
end