Crystal Minitest and the Shutdown Order Problem

TL;DR: Optimizing Minitest setup by moving initialization from before_setup to module-level broke logging: Log::AsyncDispatcher creates resources early, and they're cleaned up before tests run (which happens in at_exit). Solution: use DirectDispatcher for tests instead.

Story: The Optimization and Discovery

When setting up a Marten¹ application to work with Minitest², I moved all initialization instructions to before_setup hooks:

class Minitest::Test
  def before_setup
    Marten.setup if Marten.apps.app_configs.empty?    # Runs before EVERY test
    Marten::Spec.setup_databases
  end
end

After tests were working reliably, I optimized: why run this repetitive setup for every test? If I moved it to module-level initialization, it would run once when test file loads:

require "minitest/autorun"
require "../src/project"

Marten.setup                      # Runs once at module load
Marten::Spec.setup_databases

Tests passed initially. But when I ran with DEBUG=1 to enable verbose output, something broke:

DEBUG=1 crystal run test/users_test.cr

Channel::ClosedError: Channel is closed
    /usr/share/crystal/src/channel.cr:142:8 in 'send'
    /usr/share/crystal/src/log/dispatch.cr:55:7 in 'dispatch'

The logging channel was closed. I reverted to before_setup as a workaround, but I needed to understand: Why does when setup runs matter more than that it runs?

Investigation: The Key Discovery

Why Minitest Is Different

Minitest doesn't run tests during normal program execution. Instead:

# minitest/src/autorun.cr:8-11
at_exit do
  exit(Minitest.run(ARGV))  # Tests run during shutdown!
end

This creates a timing problem. With module-level setup:

1. Marten.setup initialize a Log³ instance with Log::AsyncDispatcher⁴ on booting
2. Log::AsyncDispatcher spawns a background fiber with a channel
3. Main program completes → Crystal runtime cleanup begins
4. Channel may be closed by garbage collection (this is where my assumption lies)
5. at_exit fires → Minitest runs tests
6. Tests call Log.info → channel already closed → Channel::ClosedError

With before_setup, setup happens inside at_exit, so the Log instance is created during shutdown, not during normal execution.

How Log::AsyncDispatcher Works

# Simplified from: crystal/src/log/dispatch.cr
class Log::AsyncDispatcher
  @channel = Channel(Entry).new

  def initialize
    @fiber = spawn do
      loop do
        entry = @channel.receive
        write_entry(entry)
      end
    end
  end

  def dispatch(entry)
    @channel.send(entry)  # ← Assumes channel is open!
  end

  def close : Nil
    # TODO: this might fail if being closed from different threads
    unless @channel.closed?
      @channel.close
      @done.receive
    end
  end

  def finalize : Nil
    close  # ← Channel gets closed here during GC/shutdown
  end
end

During shutdown, garbage collection calls finalize() -> close (), which closes the channel. But at_exit hooks run after some cleanup, creating the race condition.

Solution: The Fix

The issue isn't optimization itself—it's that Log::AsyncDispatcher isn't suitable for code that runs before at_exit. The solution is to use a dispatcher without background resources for tests:

# config/settings/test.cr
Marten.configure :test do |config|
  config.log_backend = Log::IOBackend.new(
    dispatcher: Log::DispatchMode::Direct  # No background fiber
  )

  if ENV.has_key?("DEBUG")
    config.debug = true
    config.log_level = Log::Severity::Trace
  end
end

Dispatcher Options

Dispatcher	Best For	Pros	Cons
AsyncDispatcher	Production	Non-blocking, efficient	Unreliable at shutdown
SyncDispatcher	Threaded tests	Thread-safe, reliable	Slight mutex overhead
DirectDispatcher	Single-threaded tests	Zero overhead, simple	Not thread-safe

For tests with module-level init, Log::DirectDispatcher is ideal.

Conclusion

The optimization itself was sound—module-level initialization is faster. The issue was incompatibility with Log::AsyncDispatcher in a shutdown context.

More broadly, any code that relies on objects with finalize methods could be affected by garbage collection events and at_exit timing—background resources created during normal execution may be cleaned up before tests run.

The fix is simple (one configuration change) but reveals a broader principle:

Test infrastructure must account for shutdown order and resource cleanup timing, regardless of framework. Some libraries use at_exit handlers for cleanup in multi-threaded applications, and when tests run after these handlers, any finalized objects (channels, connections, files, caches) become inaccessible.

---

References

---

1. Marten Framework ↩

2. Minitest Crystal Port ↩

3. Crystal Log Documentation ↩

4. class Log::AsyncDispatcher ↩