CI sporadically fails `due to signal 9 (Killed)`

mentioned in merge request !187 (merged)

Hmm, it sounds like we may be running out of memory although this is hard to believe given that we are just building Setup. Are these failures always in the 9.0 job?

I've seen this happen in the build-9.0, build-9.2, and build-master jobs.

mentioned in merge request !188 (merged)

I just saw this again in a CI job for a MR here:

$ nix run -f ./ci -c \ # collapsed multi-line command
builder for '/nix/store/j8k0b4qdk0znxqicdca1j385zh4fzgb8-head-hackage-ci-0.1.0.0.drv' failed due to signal 9 (Killed); last 10 log lines:
  Using strip version 2.35 found on system at:
  /nix/store/276p5pgfjf9ia9jljgkbmb7zky73p5ag-gcc-wrapper-10.3.0/bin/strip
  Using tar found on system at:
  /nix/store/1v0ryqy409fiwjgj0186v74clp44l04r-gnutar-1.34/bin/tar
  No uhc found
  building
  Preprocessing executable 'head-hackage-ci' for head-hackage-ci-0.1.0.0..
  Building executable 'head-hackage-ci' for head-hackage-ci-0.1.0.0..
  [1 of 6] Compiling LatestVersion    ( LatestVersion.hs, dist/build/head-hackage-ci/head-hackage-ci-tmp/LatestVersion.o, dist/build/head-hackage-ci/head-hackage-ci-tmp/LatestVersion.dyn_o )
  [2 of 6] Compiling Types            ( Types.hs, dist/build/head-hackage-ci/head-hackage-ci-tmp/Types.o, dist/build/head-hackage-ci/head-hackage-ci-tmp/Types.dyn_o )
cannot build derivation '/nix/store/1c0dcvg53bp950dxwbcx1jd5zzgss547-repo.drv': 1 dependencies couldn't be built
error: build of '/nix/store/1c0dcvg53bp950dxwbcx1jd5zzgss547-repo.drv' failed

Interestingly, the logs stop in yet another location this time.

Yet another one here. I've also reported this to the intermittent CI failures spreadsheet in ghc#21591, as it is extremely tiresome having to babysit every job and restart it due to what feels like 50/50 odds of it randomly dying due to this issue.

I spotted another occurrence of this in ghc-debug's CI here:

[ 1 of 18] Compiling Network.HTTP.Base64 ( Network/HTTP/Base64.hs, dist/build/Network/HTTP/Base64.p_o )
error: builder for '/nix/store/80kxc1395rnq4wa04ss61c0dx8jvq3xv-HTTP-4000.3.15.drv' failed due to signal 9 (Killed)
error: 1 dependencies of derivation '/nix/store/74svkafnlp4kql3yk4w0alhavyfnn5jf-cabal-install-3.4.0.0.drv' failed to build

I wonder if this is a Nix thing in general.

I wonder if this is a Nix thing in general.

Possibly so. See:

Interesting! But will an issue with builders that close file descriptors be relevant in the middle of a Cabal build?

My first thought leans towards the OOM killer, but the truth of the matter remains to be seen.

I'll probably look at these "signal 9" failures not long after "Cannot connect to Docker daemon" failures.

marked this issue as related to ghc#21591

Un?fortunately, I don't see any of these on ghc or head.hackage in the last month of jobs. But clearly they're still happening since it happened on ghc-debug last week. I'll start tracking it on https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?from=now-60d&to=now&orgId=2 soon.

I don't see any of these on ghc or head.hackage in the last month of jobs

Where are you looking? If I look for the pipelines of the most recent commit here, then the three most recent jobs failed due to this issue.

I'll start tracking it on https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?from=now-60d&to=now&orgId=2 soon.

Oh, this is interesting! Is there a writeup somewhere of how this works?

Where are you looking? If I look for the pipelines of the most recent commit here, then the three most recent jobs failed due to this issue.

Oh great. Those all happened right after I pulled the 18000 most recent jobs.

Oh, this is interesting! Is there a writeup somewhere of how this works?

Not yet, but I was planning on writing something to the ghc-devs list pretty soon.

@RyanGlScott fyi I've added the webhook that logs spurious failures to the ghc-debug project (localhost:7088).

@angerman determined that Docker simply sends kill -9 signals to containers when the system is under moderate load. We are unlikely to fix this, but the workaround is in place: my system for tracking spurious failures recognizes jobs that fail with a -9 and automatically restarts them. I'd suggest we accept that as the solution to this ticket (i.e., wontfix + workaround exists).

How exactly does the automatic restart workaround function? I've recently discovered a job that failed due to signal 9 (Killed) here, but it was not restarted automatically.

The system is currently out of commission. :( See ghc#22440 (closed)

fyi @bgamari

The system was added into the existing ghc-perf-import bot, which gets triggered for each job event. The bot is now misconfigured so not doing any of its jobs. I will probably spin my failure handling stuff into its own service soon.

This is now happening on nearly every job in !277 (closed).

It looks like signal 9 has increased dramatically in December.

https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?orgId=2&from=now-120d&to=now&var-types=signal_9&refresh=15m

@angerman this is happening on the zw3rk runners. (Sorry I haven't updated the graph above to use runner name instead of runner id—it's still on my list.) It's only happening on head.hackage jobs, so maybe there's something special about how they run.

@bgamari, @mpickering fyi

I think it's because the head.hackage jobs are running nix build to build dependencies which for some reason triggers these errors.

Did something change in December to make the problem worse?

Maybe more stuff was being pulled from binary caches before?

I think #73 (closed) will fix this. Initial testing looks good. I'll try to fix it in the next few days

The signal 9 have been rather elusive. They appear to be a bit load related and only happen inside docker iirc.

They're not so elusive anymore. :) It used to be that they happened 1-2 times a day. Yesterday, there were 283 of them.

Elusive as to why they happen ;-) Increasing load does increase them. If you can figure out why that would be great! What is triggering the kill. It's not me personally .

mentioned in merge request !277 (closed)

mentioned in issue #73 (closed)

A little status update:

There seem to be four epochs.

Until mid December, occurrences were fairly low.
For 2 months, the count was noticeably higher.
For one week in February, things were out of control.
After @teo and @mpickering's changes, the situation is back to the recent baseline.

It looks like we can still expect dozens of failures per day on average, so we'll need to circle back and try to improve things again sometime soon.

https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?orgId=2&from=now-6M&to=now&var-types=signal_9

I suspect that this may be due to a nix bug: https://github.com/NixOS/nix/issues/2176.

Moreover, I am seeing this quite often in !228 (closed), which builds a bit more Haskell code than master.

I discussed on #nix-haskell:matrix.org and @sterni, for one, didn't think it likely that any standard packages would be affected. https://matrix.to/#/!RbXGJhHMsnQcNIDFWN:nixos.org/$nMop4V1R4O3Ud0EmOk56Q4TCHgn7AzdwW14qUwe9b8o?via=nixos.org&via=matrix.org&via=tchncs.de

"depends on what you use to build haskell packages, but anything based on stdenv.mkDerivation (e.g. pkgs.haskell.packages.*) [should] not be affected"

changed the description

Last week, this happened over 1800 times.

@angerman , I don't think this looks very good for the continued use of these machines for GHC CI.

failure count	runner_name	runner_url
428	x86_64-linux-2.zw3rk	https://gitlab.haskell.org/admin/runners/608
349	x86_64-linux-5.zw3rk	https://gitlab.haskell.org/admin/runners/612
320	x86_64-linux-4.zw3rk	https://gitlab.haskell.org/admin/runners/611
267	x86_64-linux-7.zw3rk	https://gitlab.haskell.org/admin/runners/613
208	x86_64-linux-3.zw3rk	https://gitlab.haskell.org/admin/runners/607
190	x86_64-linux-6.zw3rk	https://gitlab.haskell.org/admin/runners/609
1 (the outlier)	lab.smart-cactus.org-lint	https://gitlab.haskell.org/admin/runners/615

@chreekat you have access to the machines. I’m at a loss what is going and why they are being killed. I’m happy to make any changes to the configuration; I simply don’t understand what’s going on with docker here.

@chreekat I've been going though the first 20+ or so listed here: https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?orgId=2&from=now-120d&to=now&var-types=signal_9&refresh=15m,

And they are all head.hackage or ghcs-nix. I don't have the ability to debug what those two repos do right now. Maybe it would yield something useful.

Looking at the runners, they seem to be green of fail legitimately for the overwhelming amount of builds in ghc/ghc.

Maybe the solution is to lock them to the ghc/ghc project instead?

@chreekat can you break down the failure rate per repo?

The breakdown is

 count |       repo
-------+---------------------
     1 |
  2071 | bgamari/ghcs-nix
    31 | ghc/ghc-debug
    50 | ghc/ghc
     1 | ghc/ghc-perf-import
  3232 | ghc/head.hackage

So yes, it looks like it's mostly ghcs-nix and head.hackage.

I've managed to reproduce this locally. I'm running on a 32 core AMD computer, which is somewhat busy/noisy.

❯ docker --version
Docker version 20.10.21, build v20.10.21

Here's what I ran:

docker run -it --rm nixos/nix:2.13.1
git clone https://gitlab.haskell.org/ghc/head.hackage.git
cd head.hackage
nix --extra-experimental-features nix-command\ flakes print-dev-env -j200 -L
# wait for some Haskell packages to start building
# then cancel the build
nix-collect-garbage -d # not sure if this is necessary
nix --extra-experimental-features nix-command\ flakes print-dev-env -j200 -L
# run the build again and it should fail this time. Or if not rinse and repeat

Further investigation confirms that this still happens with -j1 and this seems to be caused by this issue: https://github.com/NixOS/nix/issues/2176.

strace reveals that nix notices that its pipe to the builder is closed, and then SIGKILLS everything.

It might be helpful to grep for kill or EIO in the strace logs to find this

I can also confirm that this still happens when passing --privileged to docker or when using the latest tag of the image

I'm pretty sure that this is being triggered by the extra preConfigurePhases added by the haskell generic builder, which in turn call "date +%s" which I can see in strace. Why this in particular breaks though and why only under docker is a mystery

Where does the preConfigurePhase call date +%s exactly? I can't find it in the generic-builder.nix file.

I think this is coming from here: https://github.com/NixOS/nixpkgs/blob/97ec5b4c089d3d6636e2292c3ecf3e24913bb0af/pkgs/stdenv/generic/setup.sh#L1591

That's the implementation for the build phase took such and such time thing

Here is an strace trace I managed to capturout.zst

Also if it makes it any easier to decipher what's going on the last build is of the SHA package. Stdout looks like this:

SHA> Preprocessing library for SHA-1.6.4.4..
SHA> Building library for SHA-1.6.4.4..
SHA> [1 of 1] Compiling Data.Digest.Pure.SHA ( src/Data/Digest/Pure/SHA.hs, dist/build/Data/Digest/Pure/SHA.o, dist/build/Data/Digest/Pure/SHA.dyn_o )
error: builder for '/nix/store/24sxc21gbhbfxdrpgfgj47rdrgnqsqaa-SHA-1.6.4.4.drv' failed due to signal 9 (Killed)
error: 1 dependencies of derivation '/nix/store/yzcjcdv8b6w0gjjjs904k7m2yvcgn136-authenticate-oauth-1.7.drv' failed to build
error: 1 dependencies of derivation '/nix/store/bh7lz8cn1rcp52a3d1x0hwd0swawnj79-wreq-0.5.4.2.drv' failed to build
error: 1 dependencies of derivation '/nix/store/2812d96ihn3nqsjdxf6v7qdgji1d4j4b-head-hackage-ci-0.1.0.0.drv' failed to build
error: 1 dependencies of derivation '/nix/store/l2d62qcfkmxnkvsl47w0vqfmcjgdc25f-repo.drv' failed to build
error: 1 dependencies of derivation '/nix/store/cnnqqv6vyfyshb0v0yw4ir9v5m0dizxk-head-hackage-build-env-env.drv' failed to build

The relevant kill call in the strace output is:

...
880   futex(0x16eeed0, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=4065421, tv_nsec=592049995}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
2447  ioctl(2, TCGETS, {c_iflag=ICRNL|IXON, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ISIG|ICANON|ECHO|ECHOE|ECHOK|IEXTEN|ECHOCTL|ECHOKE, ...}) = 0
2447  prctl(PR_SET_PDEATHSIG, SIGKILL)  = 0
2447  setuid(30001)                     = 0
2447  kill(-1, SIGKILL)                 = 0
2447  exit_group(0)                     = ?
2447  +++ exited with 0 +++
878   <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 2447
878   --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2447, si_uid=30001, si_status=0, si_utime=0, si_stime=0} ---
...

which looks suspiciously similar to what is done by nix in killUser: https://github.com/NixOS/nix/blob/301623f3a3aa2b9bc6f116b7456f1528bd6bad47/src/libutil/util.cc#L1057.

This is called by LocalDerivationGoal::killSandbox.

One possible explanation is that the host is running a nix daemon, which too tries to clean up sandboxes by killing all processes under a uid. But that also ends up killing processes in the docker container with the same uid. I've checked that running pkill -u nixbld1 outside the container reproduces the behaviour we see.

@teo whst you are saying is, that:

running a nix build in the container is not insulated from the host.
running a container with the same range of user ids as the host is dangerous.
running nix inside a container and outside a container (both choosing the same nixbld user), can result in the outer one terminating the inner one because the ended up having the same numerical id?
this is intentional docker behavior?

Indeed, that's what it looks like. It does seem somewhat unexpected to say the least!

User namespaces were mentioned on IRC and they seem like the solution to these strange semantics but IIRC they are still somewhat experimental.

So in essence then: we should not be running docker containers of nixOS/or OSs with nix on nix-enabled hosts?

I mean if we are using nix anyway, the extra layer of docker probably makes things worse in almost any direction; but this seems still to be a pretty significant limitation.

It also means if any uids between docker containers and the host collide things are on a “good luck” basis?

User namespaces were mentioned on IRC and they seem like the solution to these strange semantics but IIRC they are still somewhat experimental.

FWIW flakes are also considered experimental

if the nix builds have to happen in a container, it might be worth trying adding the following to nix.conf:

auto-allocate-uids = true
experimental-features = auto-allocate-uids

so that nix builds would not use a pre-allocated nixbld user.

I think all the options offered so far sound good!

Another possibility is just shifting the uid/guids over a bit in the container say instead of starting at 3000 start at 6000. All we need to ensure is that these two sets don't overlap so I think that would be pretty safe

If the host has nix, using that instead of the container will most likely give you /nix/store caching as well. ‍♂️

Passing the nix daemon socket through is quite a nice solution. We use that at work exclusively for nix Gitlab CI builds and it works quite well

I've created an issue for this upstream: https://github.com/NixOS/nix/issues/9142

Here's a snippet from the NixOS config we use to set up the socket passing stuff. I feel like some of this stuff isn't minimal so could be slimmed down a bit. This is originally based on the example from the nixos docs (see: https://github.com/NixOS/nixpkgs/blob/f99e5f03cc0aa231ab5950a15ed02afec45ed51a/nixos/modules/services/continuous-integration/gitlab-runner.nix#L217):

Had to split this out to a snippet to appease the spam filter $5735

I see this was fixed in head.hackage with fa02a975 .

According to https://nixos.org/manual/nix/stable/command-ref/conf-file.html#conf-build-users-group, the nixbld users are only used if nix is run as root.

Unfortunately, the nixos/nix images, used by CI in a few places, do use root:

$ docker run -it --rm nixos/nix:2.14.1
bash-5.1# echo $USER
root

So we have three potential long-term fixes:

Share the daemon socket
Don't run nix as root in Docker
cgroups?

At work we do (1), which is quite nice because you get to share the same store. I think it's worth considering the security implications though (I guess we are trading off one type of sandboxing for another). I can help set this up. Here's an example config extracted from the docs/my work config: $5735

(3) is what they recommended when I raised this upstream: https://github.com/NixOS/nix/issues/9142

A con of both (1) and (3) is that it requires making changes to each runner's host.

Another option is to do nothing for now. The current workaround seems to work.

Actually, yeah. The implication of running nix as root on the ephemeral Docker image is pretty minor, I guess.

I think doing (3) would be nice eventually, so as to reduce complexity in the CI jobs. But right now it wouldn't hurt to just add --option build-users-group "" to the few jobs that use the nixos/nix images. (I mean, in GHC).

mentioned in merge request ghc!12507 (closed)

mentioned in issue ci-config#7

This is now resolved for head.hackage and GHC thanks to changes to those repos' CI scripts. Ideally we would fix it in our CI config instead. So I opened ci-config#7 to track it.

Closing this one.

closed

CI sporadically fails `due to signal 9 (Killed)`

Designs

Child items ...

Activity

CI sporadically fails `due to signal 9 (Killed)`

Relates to

Activity