A deploy of a client’s Rails app sat in its release step for ten minutes and printed nothing. The release step is where Railyard runs rails db:prepare in a one-off container before the new code takes traffic. At ten minutes the agent’s release timeout fired, the deploy failed with “Release step exceeded 10m0s and was stopped”, and the log above that line gave no hint of what the step had been doing.

The databases were fresh. There was no traffic, no other deploy, no long query from the live app, because there was no live app yet. A migration hung on a lock with nothing else in the building.

Two pools, one database

The app uses Solid Cable, the Rails 8 Action Cable adapter that stores broadcast messages in a database table instead of Redis. Like Solid Queue and Solid Cache, it usually gets its own entry in database.yml, with its own schema file (db/cable_schema.rb) and its own migrations folder (db/cable_migrate).

A connection pool is the set of open database connections Active Record keeps for one database configuration. Code checks a connection out, runs its queries, and gives it back. Every configuration a process uses gets its own pool. Solid Cable’s models inherit from SolidCable::Record, which calls connects_to with the cable configuration, so SolidCable::Message queries go through the cable pool. When db:prepare migrates the cable database, the migration runs on a separate connection that the migration task opens for that configuration. Both point at the same database. To Postgres they are two separate sessions, each served by its own backend process, and Postgres has no idea they belong to the same Ruby process.

The app’s cable_schema.rb was at version: 1. After db:prepare loaded that schema, it looked in db/cable_migrate, found Solid Cable’s upgrade migration, and ran it as pending. That migration comes from Solid Cable’s update generator:

class CreateCompactChannel < ActiveRecord::Migration[7.2]
  def up
    change_column :solid_cable_messages, :channel, :binary, limit: 1024, null: false
    add_column :solid_cable_messages, :channel_hash, :integer, limit: 8, if_not_exists: true
    add_index :solid_cable_messages, :channel_hash, if_not_exists: true
    change_column :solid_cable_messages, :payload, :binary, limit: 536_870_912, null: false

    SolidCable::Message.find_each do |msg|
      msg.update(channel_hash: SolidCable::Message.channel_hash_for(msg.channel))
    end
  end
end

The first four lines are schema changes on the migration’s connection. The loop is a data backfill through a model, on the cable pool’s connection.

What the locks were doing

Every statement in Postgres takes locks, and table-level locks come in eight modes that conflict according to a fixed table in the docs. A plain SELECT takes ACCESS SHARE, the weakest mode, which conflicts with exactly one other: ACCESS EXCLUSIVE. ALTER TABLE takes ACCESS EXCLUSIVE unless the docs say otherwise for a particular subcommand, and changing a column’s type is one of the forms that takes it. ACCESS EXCLUSIVE conflicts with every mode, including ACCESS SHARE. Table locks are held until the transaction ends, not until the statement ends.

On Postgres, Rails runs each migration inside a transaction, because Postgres DDL is transactional and a half-applied migration is worse than none. So the sequence was:

Session A, the migration’s connection, opens a transaction and runs ALTER TABLE solid_cable_messages .... It now holds ACCESS EXCLUSIVE on the table until the migration commits.
Ruby reaches find_each. SolidCable::Message lives in the cable pool, so Active Record checks out session B and sends SELECT ... FROM solid_cable_messages ORDER BY id LIMIT 1000.
Session B needs ACCESS SHARE, which conflicts with A’s lock. B waits.
The Ruby thread blocks on B’s result. Session A sits with its transaction open, waiting for its client to send the next command. The client is that same blocked thread.

A won’t commit until Ruby finishes the loop. Ruby won’t finish the loop until B returns. B won’t return until A commits. That’s a deadlock, and Postgres has a deadlock detector. It didn’t fire.

Postgres doesn’t check for deadlocks continuously, since the check is expensive and most lock waits end quickly. When a backend has waited on a lock for deadlock_timeout (1 second by default), it runs the check. The check builds a wait-for graph from the lock manager’s shared state: each waiting backend is a node, with an edge to every backend that holds a conflicting lock or is queued ahead of it for one. If the edges lead from the waiter back to itself, there’s a cycle, and Postgres aborts one of the transactions with ERROR: deadlock detected.

In this graph there is one edge: B waits for A. Session A isn’t waiting on any lock. From the server’s side it’s a session in state idle in transaction: it ran a statement, got the result, and is waiting for its client to say something. That’s a normal state for an app doing work between queries. Postgres can’t tell “the client is computing” from “the client is stuck waiting on another session”.

The edge that closes the cycle, A waiting for B, exists only inside the Ruby process, as a thread blocked on a socket read. Postgres can’t see it, so the graph has no cycle, and as far as the server knows B is waiting on a lock that will be released eventually. With the defaults (lock_timeout = 0 and statement_timeout = 0, both meaning no limit), “eventually” has no upper bound.

A small reproduction

The whole thing reproduces with Active Record and an empty database. One abstract class gets its own pool pointed at the same database, standing in for SolidCable::Record, and a migration alters the table and then reads through that pool:

require "active_record"
URL = "postgres:///deadlock_repro"
ActiveRecord::Base.establish_connection(URL)
ActiveRecord::Schema.define { create_table(:messages, force: true) { |t| t.string :channel } }

class SecondaryRecord < ActiveRecord::Base
  self.abstract_class = true
  establish_connection(URL) # a second pool, same database
end
class Message < SecondaryRecord; end
Message.create!(channel: "x")

class ChangeChannel < ActiveRecord::Migration[8.1]
  def up
    change_column :messages, :channel, :text   # ACCESS EXCLUSIVE until commit
    Message.find_each { |m| m.update!(channel: m.channel) } # other pool: waits forever
  end
end

pool = ActiveRecord::Base.connection_pool
ActiveRecord::Migrator.new(:up, [ChangeChannel.new("ChangeChannel", 1)],
                           pool.schema_migration, pool.internal_metadata).migrate

The last two lines matter. Calling ChangeChannel.migrate(:up) directly doesn’t open a transaction, so the ALTER TABLE commits at once and the script finishes. Running it through ActiveRecord::Migrator, which is what db:migrate and db:prepare do, wraps the migration in a transaction, and the script hangs well past the one-second deadlock check. Run it with PGOPTIONS="-c lock_timeout=3s" and it fails after three seconds with PG::LockNotAvailable: ERROR: canceling statement due to lock timeout on the SELECT.

The same shape appears whenever one thread holds a transaction on one connection and reads the same table on another. Multi-database Rails apps make it easy to write without noticing, because the second pool hides behind an ordinary model call.

Seeing it from the database

While it’s hung, Postgres will show you both halves even though it can’t connect them. pg_blocking_pids() takes a backend’s PID and returns the PIDs blocking it. Joined against pg_stat_activity twice, it puts waiter and holder side by side:

SELECT waiting.pid                                          AS waiting_pid,
       waiting.wait_event_type || ':' || waiting.wait_event AS waiting_on,
       left(waiting.query, 50)                              AS waiting_query,
       holder.pid                                           AS holder_pid,
       holder.state                                         AS holder_state,
       left(holder.query, 50)                               AS holder_last_query
FROM pg_stat_activity AS waiting
CROSS JOIN LATERAL unnest(pg_blocking_pids(waiting.pid)) AS b(pid)
JOIN pg_stat_activity AS holder ON holder.pid = b.pid;

Against the reproduction it returns one row. The waiter is SELECT "messages".* FROM "messages" ORDER BY ..., waiting on Lock:relation. The holder is in state idle in transaction, and its last query is ALTER TABLE "messages" ALTER COLUMN "channel" TYPE .... For a session that isn’t running anything, pg_stat_activity.query shows the last statement it ran, which is exactly what you want here. Filtering pg_locks on relation = 'messages'::regclass shows the lock itself: the holder’s backend with AccessExclusiveLock, granted, and the waiter’s with AccessShareLock, not granted.

That combination is the signature. A holder that is active means you’re waiting behind real work. A holder that is idle in transaction means the database is waiting on the application, and if waiter and holder come from the same client process, the application is waiting on itself.

Why the log was empty

Two separate things hid the output.

One was Ruby’s output buffering. When $stdout is a terminal, Ruby writes each line as you print it. When it’s a pipe or a file, Ruby collects writes in a buffer and flushes when the buffer fills or the process exits cleanly. docker run without -t gives the container a pipe. So the migration banner and everything after it were sitting in a buffer inside the container. An app can opt out with $stdout.sync = true, but that’s the app’s choice, and Railyard doesn’t edit app code to make a deploy work.

The other was how the agent enforced the timeout. It ran docker run through Go’s exec.CommandContext with a ten-minute context, and when that context expires the agent sends SIGKILL to the child’s whole process group (the fix from the deploy that hung for an hour). That group was the docker command-line client, not the container. Killing the client doesn’t stop the container: the Docker daemon owns it and keeps it running. So the release container outlived the failed deploy, with Ruby still blocked and session A still holding ACCESS EXCLUSIVE on the cable table. That lock would have blocked the next deploy’s release step, and the app’s Action Cable once it was serving.

SIGKILL and SIGTERM differ in who gets a say. SIGKILL can’t be caught: the kernel removes the process, nothing in it runs again, and any buffer in its memory is lost. SIGTERM is a request. Ruby’s default handler raises SignalException in the main thread, which unwinds the stack, runs ensure blocks and at_exit hooks, and flushes $stdout on the way out. docker stop sends SIGTERM first and SIGKILL only after a grace period.

The reproduction shows the difference. With its output redirected to a file, the file stays at zero bytes while the script hangs. Send SIGTERM and the file fills with the migration banner and the change_column line, which is where it stopped. Send SIGKILL instead and the file stays empty.

The fix

Both changes are in the agent, and neither touches the app.

The release container now gets a name, and the deadline is enforced on the container instead of the client: docker stop --time 10 (SIGTERM, then SIGKILL ten seconds later), followed by docker rm -f. A cancelled deploy removes it too, so nothing is left holding locks.

Rails database steps also run with a lock timeout:

const releaseLockTimeout = "60s"

func releaseLockTimeoutArgs(req *pb.DeployRequest, cmd string) []string {
	if _, set := req.GetEnvVars()["PGOPTIONS"]; set || !railsDBTaskRe.MatchString(cmd) {
		return nil
	}
	return []string{"-e", "PGOPTIONS=-c lock_timeout=" + releaseLockTimeout}
}

PGOPTIONS is read by libpq when it opens a connection, and -c lock_timeout=60s sets that parameter for the session, the same as running SET lock_timeout right after connecting. Every connection the release process opens gets it, whichever pool it belongs to, so session B’s SELECT gives up after 60 seconds with canceling statement due to lock timeout. The migration raises, its transaction rolls back, and the lock is released. The agent watches the output for that message and follows it with a plain explanation of the usual causes: a migration reading or writing through a model on another connection while its own transaction holds the table, or a long transaction in the running app. The timeout is a setting, 0 turns it off, and an app that sets its own PGOPTIONS or lock_timeout in database.yml keeps its own.

I chose lock_timeout over statement_timeout on purpose. statement_timeout limits a statement’s total time, lock wait included. A legitimate backfill that updates ten million rows can run for many minutes, and killing it at 60 seconds would break a working migration. lock_timeout limits only how long a statement waits to acquire a lock. Once it has the lock, it runs as long as it needs.

It also covers the more common production case. When a migration’s ALTER TABLE waits for ACCESS EXCLUSIVE behind a long transaction in the live app, its request sits in the lock queue, and every new query on that table queues behind it, plain reads included. The table is effectively down until the migration gets its lock. With a lock timeout the migration gives up and the queue drains: a failed deploy instead of an outage.

The client’s migration still fails, but in about a minute and with a named error instead of a silent ten-minute hang. The app still needs a one-line change of its own. On a fresh database the migration is redundant, since the schema file already has channel_hash, so either bump cable_schema.rb to the migration’s version or delete the migration. Until then, a fresh db:prepare would hang the same way on Kamal or Heroku, since neither sets a lock timeout on migrations.

I had seen this hang once before. In mid-September a deploy of the same app stalled in its release step, and with no output to check against, I put it down to live Solid Cable traffic holding locks on the table. It was the same self-lock, and I found that out only once the container could tell me where it was when it stopped.

A deadlock Postgres can't see