x/build: trybots not running due to maintner resource temporarily unavailable errors

[bradfitz]

Trybots aren't running because maintner isn't noticing that there's new stuff on Gerrit, due to:

2018/02/02 20:07:17 Temporary error from gerrit go.googlesource.com/example: running git remote -v in /cache/go.googlesource.com%2Fexample: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 gerrit go.googlesource.com/time: init: running git remote -v in /cache/go.googlesource.com%2Ftime: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Ftime: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 Temporary error from gerrit go.googlesource.com/time: running git remote -v in /cache/go.googlesource.com%2Ftime: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 gerrit go.googlesource.com/build: init: running git remote -v in /cache/go.googlesource.com%2Fbuild: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Fbuild: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 Temporary error from gerrit go.googlesource.com/build: running git remote -v in /cache/go.googlesource.com%2Fbuild: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 gerrit code.googlesource.com/gocloud: init: running git remote -v in /cache/code.googlesource.com%2Fgocloud: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/code.googlesource.com%2Fgocloud: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:18 Temporary error from gerrit code.googlesource.com/gocloud: running git remote -v in /cache/code.googlesource.com%2Fgocloud: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:19 gerrit go.googlesource.com/gddo: init: running git remote -v in /cache/go.googlesource.com%2Fgddo: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:19 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Fgddo: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:19 Temporary error from gerrit go.googlesource.com/gddo: running git remote -v in /cache/go.googlesource.com%2Fgddo: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 gerrit go.googlesource.com/scratch: init: running git remote -v in /cache/go.googlesource.com%2Fscratch: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Fscratch: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 Temporary error from gerrit go.googlesource.com/scratch: running git remote -v in /cache/go.googlesource.com%2Fscratch: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 gerrit go.googlesource.com/proposal: init: running git remote -v in /cache/go.googlesource.com%2Fproposal: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Fproposal: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 Temporary error from gerrit go.googlesource.com/proposal: running git remote -v in /cache/go.googlesource.com%2Fproposal: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 gerrit go.googlesource.com/tour: init: running git remote -v in /cache/go.googlesource.com%2Ftour: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Ftour: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:20 Temporary error from gerrit go.googlesource.com/tour: running git remote -v in /cache/go.googlesource.com%2Ftour: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 gerrit go.googlesource.com/oauth2: init: running git remote -v in /cache/go.googlesource.com%2Foauth2: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Foauth2: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 Temporary error from gerrit go.googlesource.com/oauth2: running git remote -v in /cache/go.googlesource.com%2Foauth2: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 gerrit go.googlesource.com/exp: init: running git remote -v in /cache/go.googlesource.com%2Fexp: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 IS TEMP ERROR? *errors.errorString running git remote -v in /cache/go.googlesource.com%2Fexp: fork/exec /usr/bin/git: resource temporarily unavailable
2018/02/02 20:07:21 Temporary error from gerrit go.googlesource.com/exp: running git remote -v in /cache/go.googlesource.com%2Fexp: fork/exec /usr/bin/git: resource temporarily unavailable^C

This smells just like #23686 in a different binary.

Both of these were just updated for the LetsEncrypt ACME changes.

So what changed in the meantime?

What resource isn't available?

/cc @andybons @ianlancetaylor

[bradfitz]

Can't even bash in to debug:

$ kubectl exec -ti maintnerd-deployment-2926465623-tjsxh /bin/bash
rpc error: code = 2 desc = "fork/exec /usr/bin/containerd-shim: resource temporarily unavailable"command terminated with exit code 126

Process limit? FD leak?

[bradfitz]

Killed container and let it get restarted. Then ran bash in it and:

root@maintnerd-deployment-2926465623-7trps:/# ulimit -a
core file size          (blocks, -c) unlimited
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 60077
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1048576
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 1048576
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

[ianlancetaylor]

This may have happened again, as https://golang.org/cl/92155 has had no trybot initiation after ten minutes.

[ianlancetaylor]

The trybots did start running on CL 92155 after 32 minutes.

[bradfitz]

Well, @andybons updated our GKE cluster from 1.5.6 to 1.8.whatever the latests GKE option is, and the errors persist, but they've changed. Now I see:

2018/02/08 17:00:25 Pubsub event on topic "gerrit:go.googlesource.com/go" discarded; already syncing?
2018/02/08 17:00:37 error fetching 9 hashes from gerrit project go.googlesource.com/go: 
2018/02/08 17:00:37 gerrit go.googlesource.com/go: sync: signal: killed; stderr=""
2018/02/08 17:00:37 IS TEMP ERROR? *errors.errorString signal: killed; stderr=""
2018/02/08 17:00:37 Temporary error from gerrit go.googlesource.com/go: signal: killed; stderr=""
2018/02/08 17:01:07 gerrit go.googlesource.com/go: git directory exists.
2018/02/08 17:01:10 gerrit go.googlesource.com/go: 9 new refs
2018/02/08 17:01:10 gerrit go.googlesource.com/go: fetching 9 hashes...
2018/02/08 17:01:11 error fetching 9 hashes from gerrit project go.googlesource.com/go: 
2018/02/08 17:01:11 gerrit go.googlesource.com/go: sync: signal: killed; stderr=""
2018/02/08 17:01:11 IS TEMP ERROR? *errors.errorString signal: killed; stderr=""
2018/02/08 17:01:11 Temporary error from gerrit go.googlesource.com/go: signal: killed; stderr=""
2018/02/08 17:01:14 Got pubsubhelper event: {
        "Time": "2018-02-08T17:01:14.022043045Z",
        "Gerrit": {
                "URL": "https://go-review.googlesource.com/92815",
                "Project": "go",
                "CommitHash": "d069c928b4e5108c10621d3190761abf6a5ece9a",
                "ChangeNumber": 92815
        }       
}       
2018/02/08 17:01:14 Pubsub event on topic "gerrit:go.googlesource.com/go" discarded; already syncing?
2018/02/08 17:01:41 gerrit go.googlesource.com/go: git directory exists.
2018/02/08 17:01:42 gerrit go.googlesource.com/go: sync: git fetch origin: signal: killed, 
2018/02/08 17:01:42 IS TEMP ERROR? *errors.errorString git fetch origin: signal: killed, 
2018/02/08 17:01:42 Temporary error from gerrit go.googlesource.com/go: git fetch origin: signal: killed, 

2018/02/08 17:02:12 gerrit go.googlesource.com/go: git directory exists.
2018/02/08 17:02:13 gerrit go.googlesource.com/go: sync: git fetch origin: signal: killed, 
2018/02/08 17:02:13 IS TEMP ERROR? *errors.errorString git fetch origin: signal: killed, 
2018/02/08 17:02:13 Temporary error from gerrit go.googlesource.com/go: git fetch origin: signal: killed, 

Not sure what Temporary error from gerrit go.googlesource.com/go: signal: killed; stderr="" means.

[bradfitz]

Looks like something's leaking. Bunch of defunct processes:

root@maintnerd-deployment-2926465623-g8q6z:/# ps ax | wc -l
145
root@maintnerd-deployment-2926465623-g8q6z:/# ps ax | head -20
  PID TTY      STAT   TIME COMMAND
    1 ?        Ssl   40:02 /maintnerd --config=go --bucket=golang-maintner-log --verbose --data-dir=/cache --listen=:80 --autocert=maintner.golang.org --autocert-bucket=golang-maintner-autocert
 2611 ?        Z      0:00 [git-remote-http] <defunct>
 3986 ?        Z      0:00 [git-remote-http] <defunct>
 3990 ?        Z      0:00 [git-remote-http] <defunct>
 4012 ?        Z      0:00 [git-remote-http] <defunct>
 4038 ?        Z      0:00 [git-remote-http] <defunct>
 4042 ?        Z      0:00 [git-remote-http] <defunct>
 4093 ?        Z      0:00 [git-remote-http] <defunct>
 4250 ?        Z      0:00 [git-remote-http] <defunct>
 4258 ?        Z      0:00 [git-remote-http] <defunct>
 4265 ?        Z      0:00 [git] <defunct>
 4283 ?        Z      0:00 [git-remote-http] <defunct>
 4363 ?        Z      0:00 [git-remote-http] <defunct>
 4385 ?        Z      0:00 [git-remote-http] <defunct>
 4407 ?        Z      0:00 [git-remote-http] <defunct>
 4420 ?        Z      0:00 [git-remote-http] <defunct>
 4423 ?        Z      0:04 [git] <defunct>
 4464 ?        Z      0:00 [git-remote-http] <defunct>
 4468 ?        Z      0:00 [git-remote-http] <defunct>

[bradfitz]

I have no idea where these defunct processes are coming from. I audited all the os/exec callers in golang.org/x/build/maintner/... and don't see anything suspicious.

@ianlancetaylor, any debugging tips?

[ianlancetaylor]

Sorry, no good ideas. Just the obvious one of double-checking that the parent process is what you think it is.

[bradfitz]

Updates from research & chats with others.

This is a GKE issue. Apparently GKE 1.7 automatically reaped zombie processes like an init would, using a "pause container", but that was reverted in GKE 1.8 and hasn't been fixed in GKE 1.8 yet.

Some links:

https://news.ycombinator.com/item?id=14524253
kubernetes/kubernetes#1615
https://github.com/krallin/tini
https://stackoverflow.com/questions/43122080/how-to-use-init-parameter-in-docker-run

[gopherbot]

Change https://golang.org/cl/93077 mentions this issue: maintner/maintnerd: wrap maintnerd in tini init process to reap zombies

[bradfitz]

Deployed:

root@maintnerd-deployment-7fdd7bdfff-77dcp:/# ps afx
  PID TTY      STAT   TIME COMMAND
   18 ?        Ss     0:00 /bin/bash
   26 ?        R+     0:00  \_ ps afx
    1 ?        Ss     0:00 /tini -- /maintnerd --config=go --bucket=golang-maintner-log --verbose --data-dir=/cache --listen=:80 --autocert=maintner.golang
    7 ?        Sl     0:22 /maintnerd --config=go --bucket=golang-maintner-log --verbose --data-dir=/cache --listen=:80 --autocert=maintner.golang.org --au

[gopherbot]

Change https://golang.org/cl/93082 mentions this issue: maintner/maintnerd: fix use of tini