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

Recently, I've noted head.hackage CI jobs failing due to some variation of the following error:

$ nix run -f ./ci -c curl -L "$GHC_TARBALL" > ghc.tar.xz
trace: Warning: `stdenv.lib` is deprecated and will be removed in the next release. Please use `lib` instead. For more information see https://github.com/NixOS/nixpkgs/issues/108938
builder for '/nix/store/fv8zgvlrq596axmxwwlv63hxn28185fg-head-hackage-ci-0.1.0.0.drv' failed due to signal 9 (Killed); last 10 log lines:
  setupCompilerEnvironmentPhase
  Build with /nix/store/qabwi7rkqwppxbp575vq7khy6v2vqv81-ghc-8.10.4.
  unpacking sources
  unpacking source archive /nix/store/6cggp66y182f88lcz0kf9mzpba0mx1h9-ci
  source root is ci
  patching sources
  compileBuildDriverPhase
  setupCompileFlags: -package-db=/tmp/nix-build-head-hackage-ci-0.1.0.0.drv-0/setup-package.conf.d -j16 +RTS -A64M -RTS -threaded -rtsopts
  [1 of 1] Compiling Main             ( Setup.hs, /tmp/nix-build-head-hackage-ci-0.1.0.0.drv-0/Main.o )
  Linking Setup ...
cannot build derivation '/nix/store/jj1kfsb60c3zqq2jm7bmablawdjqf7dg-repo.drv': 1 dependencies couldn't be built
error: build of '/nix/store/jj1kfsb60c3zqq2jm7bmablawdjqf7dg-repo.drv' failed

Note that it's not always head-hackage-ci that fails to build. For instance, this one fails when building optparse-applicative, but otherwise the error appears quite similar.

This appears to be somewhat nondeterministic, as it happens on some CI jobs on not on others.

---

FYI: A record of jobs that die with Signal 9 can be explored at https://grafana.gitlab.haskell.org/d/167r9v6nk/ci-spurious-failures?orgId=2&refresh=15m&var-types=signal_9&from=now-14d&to=now -Bryan

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:

• https://github.com/NixOS/nix/issues/2176
• https://releases.nixos.org/nix-dev/2011-January/005769.html

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.

1. Until mid December, occurrences were fairly low.
2. For 2 months, the count was noticeably higher.
3. For one week in February, things were out of control.
4. 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.