No step created for build

Start in src/hydra-queue-runner/queue-monitor.cc, especially getQueuedBuilds, createBuild, and the loop around the linked lines. Reproduce the queued-build state using build 558937 and the shown database query, then trace why it is skipped; done means the cause is identified and queued builds receive their expected build steps after notification without requiring a restart.

Yesterday many builds on our Hydra got queued but didn't get build. The builds from later evaluations of the same jobsets did get build successfully.

I'm now trying to understand what went wrong in Hydra to cause this to happen. I haven't restarted the hydra-queue-runner yet to preserve as much state as possible.

Let's look at one of the builds that are still queued: build 558937. Note this is a top-level build; no other builds depend on this one.

Let's first look at the log:

...
Jan 21 22:39:34 hydra hydra-evaluator[9874]: added build 558937 (...)
...
Jan 21 22:39:35 hydra hydra-queue-runner[9894]: got notification: new builds added to the queue
Jan 21 22:39:35 hydra hydra-queue-runner[9894]: checking the queue for builds > 558932...
...
Jan 21 22:39:35 hydra hydra-queue-runner[9894]: loading build 558933 (...)
...
Jan 21 22:39:35 hydra hydra-queue-runner[9894]: loading build 558934 (...)
...
Jan 21 22:39:35 hydra hydra-queue-runner[9894]: loading build 559010 (...)
...
Jan 21 22:39:37 hydra hydra-queue-runner[9894]: got notification: new builds added to the queue
Jan 21 22:39:37 hydra hydra-queue-runner[9894]: checking the queue for builds > 559010...
...

So the evaluator correctly adds build 558937. Indeed it's also present in the DB:

hydra=> SELECT * FROM builds WHERE id = 558937;
-[ RECORD 1 ]------------+---------------------------------------------------------
id                       | 558937
finished                 | 0
timestamp                | 1579646374
project                  | ...
jobset                   | ...
job                      | ...
nixname                  | ...
description              |
drvpath                  | /nix/store/gvbqrw9jygizc7ixpc02fk8gc0zi30qj-....drv
system                   | x86_64-linux
license                  |
homepage                 |
maintainers              |
maxsilent                | 7200
timeout                  | 36000
ischannel                | 0
iscurrent                | 0
nixexprinput             | src
nixexprpath              | ci/ci.nix
priority                 | 100
globalpriority           | 0
starttime                |
stoptime                 |
iscachedbuild            |
buildstatus              |
size                     |
closuresize              |
releasename              |
keep                     | 0
notificationpendingsince |

The queue-runner is woken up and starts adding unfinished builds with an id > 558932. If I manually execute the query in getQueuedBuilds I get the following:

hydra=> select id from Builds 
        where id > 558932 
        and finished = 0 
        order by globalPriority desc, id;
   id
--------
 558935
 558936
 558937
 558938
 558939
 558940
...
 565890
 565891
 565892
(111 rows)

Note that build 558937 is included.

Now I would expect this build to be added to newIDs and newBuildsByID. The only reason this won't happen is if the queue-runner was started with --build-one (which it isn't) or if the build was already added to builds (which it isn't since this is the first run of getQueuedBuilds after the build got added by the evaluator).

Since I expect build to be in newIDs I expect this loop to iterate over it and apply the createBuild function to it.

createBuild in turn should log the message: loading build 558937 (...). Although I see other builds being loaded in the log, I strangely don't see this build being loaded.

So it seems my expectation is incorrect and createBuild(558937) is never called. Indeed, no steps have been created for this build:

hydra=> SELECT * FROM buildsteps WHERE build = 558937;
(0 rows)

The last part of the log is also interesting. The queue-runner starts loading builds > 558937 (i.e. loading build 559010) then it receives a notification that new builds have been added and calls getQueuedBuilds(lastBuildId = 559010)

After restarting the queu-runner all queued jobs are building again.

Any idea where the bug might be?