Failure to actually run the builds in the queue

Problem description

Our private hydra build server (with @basvandijk) has had its database cleaned and currently holds one project with one jobset containing one (fresh) job. This job is put inside the Queue (as seen in Status > Queue), but it is never actually built.

When looking at the job's Summary page, the Status shows Scheduled to be built, part of evaluation 1. The build steps tab is empty. The build dependencies tab, though, shows a whole bunch of dependencies.

The Status > Latest steps page is empty, as is the Status > Latest builds. The Status > Running builds says there are no running builds. The machines in Machine status are shown as Idle.

Background

The issue has started since hydra was updated a month or so ago. In a debugging session (together with @basvandijk), the version was upgraded to revision de55303197d997c4fc5, where the issue still occurs. Jobs just wouldn't build. Only when actually running nix-store --realize <drv path> does hydra mark the job as finished.

Somewhat related to this issue is #431, in which @basvandijk describes some error with a Raspberry Pi 3 build server. He thought the Raspberry Pi stuff might cause Hydra to act this weird, but the one job currently active has nothing to do with the Raspberry Pi, which should exclude it as a cause.

Debug information

With all lvlChat print messages changed to lvlInfo (because we're too lazy to figure out how to set verbose mode), the following is printed in the journal when the configuration is switched (and hydra is started):

hydra-queue-runner[9884]: adding new machine ‘root@rpibuild3’
hydra-queue-runner[9884]: checking the queue for builds > 0...
hydra-queue-runner[9884]: loading build 1 (lumi:staging:test-stalling-net)
nix-daemon[1629]: accepted connection from pid 9884, user hydra-queue-runner (trusted)
hydra-queue-runner[9884]: status: {"status":"up","time":1481904748,"uptime":0,"pid":9884,"nrQueuedBuilds":0,"nrUnfinishedSteps":49,"nrRunnableSteps":0,"nrActiveSteps":0,"nrStepsBuilding":0,"nrStepsCopyingTo":0,"nrStepsCopyingFrom":0,"nrStepsWaiting":0,"bytesSent":0,"bytesReceived":0,"nrBuildsRead":0,"buildReadTimeMs":0,"buildReadTimeAvgMs":0,"nrBuildsDone":0,"nrStepsStarted":0,"nrStepsDone":0,"nrRetries":0,"maxNrRetries":0,"nrQueueWakeups":0,"nrDispatcherWakeups":3,"dispatchTimeMs":0,"dispatchTimeAvgMs":0,"nrDbConnections":2,"nrActiveDbUpdates":0,"memoryTokensInUse":0,"machines":{"root@rpibuild3":{"enabled":true,"currentJobs":0,"idleSince":0,"nrStepsDone":0,"disabledUntil":0,"lastFailure":0,"consecutiveFailures":0}},"jobsets":{"lumi:staging":{"shareUsed":0,"seconds":0}},"machineTypes":{},"store":{"narInfoRead":0,"narInfoReadAverted":0,"narInfoMissing":0,"narInfoWrite":0,"narInfoCacheSize":0,"narRead":0,"narReadBytes":0,"narReadCompressedBytes":0,"narWrite":0,"narWriteAverted":0,"narWriteBytes":0,"narWriteCompressedBytes":0,"narWriteCompressionTimeMs":0,"narCompressionSavings":0,"narCompressionSpeed":0}}
lumi-hydra-setup-start[9877]: updating existing user `xxxxxxx'
systemd[1]: Started lumi-hydra-setup.service.
nixos[9650]: finished switching to system configuration /nix/store/5b8d70z8x8kqkbdp55hn747kz2yp7paz-nixos-system-hera-nixos-16.09pre-git_lumi-60950208ee3b2250f46839f8f69027b3234f17a7
hydra-server[9882]: [warn] Unicode::Encoding plugin is auto-applied, please remove this from your appclass and make sure to define "encoding" config
hydra-queue-runner[9884]: added build 1 (top-level step /nix/store/9kf5k2gi719ysbqx7bnz6fnsvkhkawnw-<our-derivation>.drv, 2869 new steps)
hydra-queue-runner[9884]: got 77 new runnable steps from 1 new builds
hydra-queue-runner[9884]: step ‘/nix/store/05dqd3kryhlsg0pw8c3xxmwnwvc8d7fc-bash43-029.drv’ is now runnable

... (similar message for the other 76 new runnable steps)

hydra-queue-runner[9884]: Finished getting queued builds
hydra-server[9882]: DEPRECATION WARNING: The Regex dispatch type is deprecated.
hydra-server[9882]:   It is recommended that you convert Regex and LocalRegex
hydra-server[9882]:   methods to Chained methods. at /nix/store/0npj59p4gdzssrpf6p03j1pjgfi5xi3w-hydra-perl-deps/lib/perl5/site_perl/5.22.2/Catalyst/DispatchType/Regex.pm line 210.
hydra-server[9882]: 2016/12/16-17:12:29 Starman::Server (type Net::Server::PreFork) starting! pid(9882)
hydra-server[9882]: Resolved [*]:3000 to [0.0.0.0]:3000, IPv4
hydra-server[9882]: Binding to TCP port 3000 on host 0.0.0.0 with IPv4
hydra-server[9882]: Setting gid to "122 122 122"
hydra-server[9882]: Starman: Accepting connections at http://*:3000/
hydra-evaluator[9879]: starting evaluation of jobset ‘lumi:staging’
hydra-evaluator[9879]: considering jobset lumi:staging (last checked 1s ago)
nix-daemon[1629]: accepted connection from pid 9925, user hydra
hydra-evaluator[9879]:   jobset is unchanged, skipping
hydra-evaluator[9879]: evaluation of jobset ‘lumi:staging’ succeeded

Subsequently, this is what hydra tells us every now and then afterwards:

hydra-evaluator[9879]: starting evaluation of jobset ‘lumi:staging’
hydra-evaluator[9879]: considering jobset lumi:staging (last checked 1s ago)
nix-daemon[1629]: accepted connection from pid 9955, user hydra
hydra-evaluator[9879]:   jobset is unchanged, skipping
hydra-evaluator[9879]: evaluation of jobset ‘lumi:staging’ succeeded

Dec 16 17:50:12 hera hydra-queue-runner[11345]: status: {"status":"up","time":1481907012,"uptime":300,"pid":11345,"nrQueuedBuilds":1,"nrUnfinishedSteps":2869,"nrRunnableSteps":77,"nrActiveSteps":0,"nrStepsBuilding":0,"nrStepsCopyingTo":0,"nrStepsCopyingFrom":0,"nrStepsWaiting":0,"bytesSent":0,"bytesReceived":0,"nrBuildsRead":1,"buildReadTimeMs":622,"buildReadTimeAvgMs":622,"nrBuildsDone":0,"nrStepsStarted":0,"nrStepsDone":0,"nrRetries":0,"maxNrRetries":0,"nrQueueWakeups":0,"nrDispatcherWakeups":74,"dispatchTimeMs":0,"dispatchTimeAvgMs":0,"nrDbConnections":2,"nrActiveDbUpdates":0,"memoryTokensInUse":0,"machines":{"root@rpibuild3":{"enabled":true,"currentJobs":0,"idleSince":0,"nrStepsDone":0,"disabledUntil":0,"lastFailure":0,"consecutiveFailures":0}},"jobsets":{"lumi:staging":{"shareUsed":0,"seconds":0}},"machineTypes":{"x86_64-linux:local":{"runnable":77,"running":0,"waitTime":23100,"lastActive":0}},"store":{"narInfoRead":0,"narInfoReadAverted":0,"narInfoMissing":0,"narInfoWrite":0,"narInfoCacheSize":0,"narRead":0,"narReadBytes":0,"narReadCompressedBytes":0,"narWrite":0,"narWriteAverted":0,"narWriteBytes":0,"narWriteCompressedBytes":0,"narWriteCompressionTimeMs":0,"narCompressionSavings":0,"narCompressionSpeed":0}}

With some debug messages I figured out that hydra-queue-runner blocks on this line after mentioning that those 77 steps are "now runnable". From that point it never unblocks until the process is manually restarted.

So somehow the steps are marked as "runnable", but nothing is actually built. Restarting hydra doesn't change anything and just reproduces the exact same output as posted above.

Further debugging

I'm actually kind of lost on ideas as to what could cause this. I'll update the issue with more info as I continue, but where should I even look?

In my current setup it's easy to put debug prints in arbitrary places in the code of hydra, if necessary.

Start with src/hydra-queue-runner/queue-monitor.cc at line 44 and reproduce the single queued-job setup described in the issue. Inspect why hydra-queue-runner remains blocked after reporting runnable steps, using the status output and journal messages as checkpoints. Done means queued steps are dispatched and the build appears in the running or completed status views.