Skip to content
This repository has been archived by the owner on Nov 30, 2021. It is now read-only.

deis-builder 1.10.0 is spitting 'Failed handshake: EOF' once per ~5 seconds #4431

Closed
kalbasit opened this issue Sep 8, 2015 · 14 comments · Fixed by #4935
Closed

deis-builder 1.10.0 is spitting 'Failed handshake: EOF' once per ~5 seconds #4431

kalbasit opened this issue Sep 8, 2015 · 14 comments · Fixed by #4935
Assignees
Milestone

Comments

@kalbasit
Copy link
Contributor

kalbasit commented Sep 8, 2015

Log as seen in papertrail:

Sep 08 15:07:11 52.22.0.199 logger:  2015-09-08T22:07:11UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc82046a2a0}})
Sep 08 15:07:11 52.22.0.199 logger:  2015-09-08T22:07:11UTC deis-builder[1]: [info] Accepted connection.
Sep 08 15:07:11 52.22.0.199 logger:  2015-09-08T22:07:11UTC deis-builder[1]: [info] Checking closer.
Sep 08 15:07:17 52.22.0.199 logger:  2015-09-08T22:07:17UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc82017f7a0}})
Sep 08 15:07:21 52.22.0.199 logger:  2015-09-08T22:07:21UTC deis-builder[1]: [info] Accepted connection.
Sep 08 15:07:21 52.22.0.199 logger:  2015-09-08T22:07:21UTC deis-builder[1]: [info] Checking closer.
Sep 08 15:07:24 52.22.0.199 logger:  2015-09-08T22:07:24UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc820436770}})
Sep 08 15:07:25 52.22.0.199 logger:  2015-09-08T22:07:25UTC deis-builder[1]: [info] Accepted connection.
Sep 08 15:07:25 52.22.0.199 logger:  2015-09-08T22:07:25UTC deis-builder[1]: [info] Checking closer.
Sep 08 15:07:29 52.22.0.199 logger:  2015-09-08T22:07:29UTC deis-builder[1]: [info] Checking closer.
Sep 08 15:07:29 52.22.0.199 logger:  2015-09-08T22:07:29UTC deis-builder[1]: [info] Accepted connection.
Sep 08 15:07:29 52.22.0.199 logger:  2015-09-08T22:07:29UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc820048fc0}})
Sep 08 15:07:32 52.22.0.199 logger:  2015-09-08T22:07:32UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc8202682a0}})
Sep 08 15:07:33 52.22.0.199 logger:  2015-09-08T22:07:33UTC deis-builder[1]: [info] Checking closer.
Sep 08 15:07:33 52.22.0.199 logger:  2015-09-08T22:07:33UTC deis-builder[1]: [info] Accepted connection.
Sep 08 15:07:40 52.22.0.199 logger:  2015-09-08T22:07:40UTC deis-builder[1]: [error] Failed handshake: EOF (&{{0xc8201bc7e0}})
@krancour
Copy link
Contributor

krancour commented Sep 8, 2015

I haven't seen this so frequently as every five seconds, but I've at least noticed it toward the end of the trace every time I start builder. AFAICT, it's not causing any issue, but the word "error" is sufficiently alarming that I think we need to either get to the bottom of this or else silence it if it is benign.

@sgoings
Copy link
Member

sgoings commented Sep 8, 2015

Could @technosophos chime in? I remember he had an answer to why this might be happening...

@mboersma
Copy link
Member

Ping @technosophos--any idea why this would show up so often?

@mboersma
Copy link
Member

A customer has also reported this issue in a production cluster. Need to figure out what the conditions are that provokes this, since it isn't happening on new provisions we've tested.

@technosophos
Copy link
Member

Missed this one. I would guess that this is happening because something is opening an SSH connection and then immediately closing it again. Probably this is a health check.

@technosophos
Copy link
Member

Here is the line emitting the error:

https://github.com/deis/deis/blob/master/builder/sshd/server.go#L137

We could downgrade that to a warning if you'd like. It is, after all, not really a cause for concern if we're dealing with TCP probes that check that the port is listening, but have no intention of actually initializing an SSH session.

@kalbasit
Copy link
Contributor Author

Here's my SSH config:

Host *
  ControlMaster auto
  ControlPath /tmp/ssh-%r@%h:%p
  ControlPersist yes
  ServerAliveInterval 20
  SendEnv yes
  Protocol 2
  TCPKeepAlive yes
  ServerAliveCountMax 6
  Compression yes

So perhaps it's the ServerAliveInterval ?

@laurrentt
Copy link
Contributor

+1 I'm starting to have there midway during a build. Not over and over though. Any workaround yet ?

@olalonde
Copy link
Contributor

Having same error message after stopping/starting deis-builder. Also, git push deis hangs at Waiting for git-receive to run. Waiting for deploy..

@sstarcher
Copy link
Contributor

Nov 25th I created a new test Deis cluster and everything was good. This morning I started up a new Deis cluster using the same scripts as previously and I'm running into this issue.

I first noticed it via what @olalonde mentioned. After the cluster was up git push deis was hanging. I noticed the Deis builder box was at near peak CPU. I have destroyed the cluster 3 times now and am getting the same issue each time.
AWS
Stateless
Deis 1.12.1

My existing cluster is a 1.12.1 that I stood up a few weeks back and did not have this issue.

Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Finished pushing deis/slugrunner:latest to 10.0.30.143:5000.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [debug] Name: EXTERNAL_PORT, Val: 2223
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Added hostkey.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Added hostkey.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Added hostkey.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Listening on 0.0.0.0:2223
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Accepting new connections.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Checking closer.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Builder is running.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Checking closer.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [info] Accepted connection.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal systemd[1]: Started deis-builder.
Nov 30 18:54:39 ip-10-0-40-118.ec2.internal sh[2041]: [error] Failed handshake: EOF (&{{0xc8201b83f0}})
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Checking closer.
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Accepted connection.
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [error] Failed handshake: EOF (&{{0xc8201b8460}})
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Checking closer.
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Accepted connection.
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [error] Failed handshake: EOF (&{{0xc820151880}})
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Checking closer.
Nov 30 18:54:41 ip-10-0-40-118.ec2.internal sh[2041]: [info] Accepted connection.

@sstarcher
Copy link
Contributor

My issue was related to changing the AWS ELB. Port 2222 was TCP->TCP and I changed it to HTTP->HTTP when I removed proxyProtocol. This was a mistake on my part and should of been left as TCP->TCP as this is used for SSH and is unrelated to any setting of proxyProtocol.

@olalonde
Copy link
Contributor

olalonde commented Dec 1, 2015

I did an in place upgrade to 1.21.1 and had some problem with the registry so re-installed 1.11.2 which solved the issue I was having with the builder.

@kenaniah
Copy link

kenaniah commented Dec 6, 2015

I can verify that deis-builder throws the Failed handshake: EOF errors on a new 1.12.1 cluster (on AWS) as well. Restarting the deis-builder service produces the following log:

Dec 06 23:12:06 deis-1 systemd[1]: Starting deis-builder...
Dec 06 23:12:07 deis-1 sh[31278]: deis-builder
Dec 06 23:12:07 deis-1 sh[31291]: /dev/loop0
Dec 06 23:12:07 deis-1 sh[31295]: Waiting for builder on 2223/tcp...
Dec 06 23:12:07 deis-1 sh[31294]: [debug] Name: HOST, Val: 10.0.20.77
Dec 06 23:12:07 deis-1 sh[31294]: [debug] Name: ETCD_PORT, Val: 4001
Dec 06 23:12:07 deis-1 sh[31294]: [debug] Name: ETCD_PATH, Val: /deis/builder
Dec 06 23:12:07 deis-1 sh[31294]: [debug] Name: ETCD_TTL, Val: 20
Dec 06 23:12:07 deis-1 sh[31294]: [debug] Name: ETCD, Val: 10.0.20.77:4001
Dec 06 23:12:07 deis-1 sh[31294]: [info] Starting docker with -d --bip=172.19.42.1/16 --insecure-registry 10.0.0.0/8 --insecure-registry 172.16.0.0/12 --insecure-registry 192.168.0.0/16 --insecure-registry 100.64.0.0/10 --storage-driver=overlay
Dec 06 23:12:08 deis-1 sh[31294]: [info] Docker is running.
Dec 06 23:12:08 deis-1 sh[31294]: [info] Starting build for /usr/local/src/slugbuilder/ (tag: deis/slugbuilder)
Dec 06 23:12:08 deis-1 sh[31294]: [110B blob data]
Dec 06 23:12:08 deis-1 sh[31294]: Step 0 : FROM heroku/cedar:14
Dec 06 23:12:08 deis-1 sh[31294]: ---> 56b31ddc05ad
Dec 06 23:12:08 deis-1 sh[31294]: Step 1 : RUN mkdir /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> b3c2ec6ee57d
Dec 06 23:12:08 deis-1 sh[31294]: Step 2 : RUN addgroup --quiet --gid 2000 slug &&   useradd slug --uid=2000 --gid=2000 --home-dir /app --no-create-home
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 70347c5fae1b
Dec 06 23:12:08 deis-1 sh[31294]: Step 3 : RUN chown -R slug:slug /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 0f9699f40329
Dec 06 23:12:08 deis-1 sh[31294]: Step 4 : USER slug
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 54f240ece931
Dec 06 23:12:08 deis-1 sh[31294]: Step 5 : ENV HOME /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> a926734b6a31
Dec 06 23:12:08 deis-1 sh[31294]: Step 6 : ADD ./builder/ /tmp/builder
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 5d05196fde04
Dec 06 23:12:08 deis-1 sh[31294]: Step 7 : RUN /tmp/builder/install-buildpacks
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 4e68764e3976
Dec 06 23:12:08 deis-1 sh[31294]: Step 8 : ENTRYPOINT /tmp/builder/build.sh
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> b8a74e1191c8
Dec 06 23:12:08 deis-1 sh[31294]: Step 9 : ENV DEIS_RELEASE 1.12.1
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> d85e2481e7b4
Dec 06 23:12:08 deis-1 sh[31294]: Successfully built d85e2481e7b4
Dec 06 23:12:08 deis-1 sh[31294]: [info] Starting build for /usr/local/src/slugrunner/ (tag: deis/slugrunner)
Dec 06 23:12:08 deis-1 sh[31294]: [info] Sleeping
Dec 06 23:12:08 deis-1 sh[31294]: [110B blob data]
Dec 06 23:12:08 deis-1 sh[31294]: Step 0 : FROM heroku/cedar:14
Dec 06 23:12:08 deis-1 sh[31294]: ---> 56b31ddc05ad
Dec 06 23:12:08 deis-1 sh[31294]: Step 1 : RUN mkdir /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> b3c2ec6ee57d
Dec 06 23:12:08 deis-1 sh[31294]: Step 2 : RUN addgroup --quiet --gid 2000 slug &&     useradd slug --uid=2000 --gid=2000 --home-dir /app --no-create-home         --shell /bin/bash
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 132d20c9eef1
Dec 06 23:12:08 deis-1 sh[31294]: Step 3 : RUN chown slug:slug /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> f4f8ded5157a
Dec 06 23:12:08 deis-1 sh[31294]: Step 4 : WORKDIR /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> f45057a5ea1d
Dec 06 23:12:08 deis-1 sh[31294]: Step 5 : ENV PORT 5000
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> d68fdf4939eb
Dec 06 23:12:08 deis-1 sh[31294]: Step 6 : EXPOSE 5000
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 417e631877df
Dec 06 23:12:08 deis-1 sh[31294]: Step 7 : ADD ./runner /runner
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> cbf5d14deae1
Dec 06 23:12:08 deis-1 sh[31294]: Step 8 : RUN chown slug:slug /runner/init
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 2ba0676b1ea8
Dec 06 23:12:08 deis-1 sh[31294]: Step 9 : USER slug
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 4bcd9b1dfd70
Dec 06 23:12:08 deis-1 sh[31294]: Step 10 : ENV HOME /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> b83f633cb5f1
Dec 06 23:12:08 deis-1 sh[31294]: Step 11 : ENTRYPOINT /runner/init
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 4f6d01e34609
Dec 06 23:12:08 deis-1 sh[31294]: Step 12 : ENV DEIS_RELEASE 1.12.1
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> fd64afe9a73c
Dec 06 23:12:08 deis-1 sh[31294]: Step 13 : ONBUILD run mkdir -p /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 46e05c9b3cf5
Dec 06 23:12:08 deis-1 sh[31294]: Step 14 : ONBUILD workdir /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> 90db5c12611b
Dec 06 23:12:08 deis-1 sh[31294]: Step 15 : ONBUILD add slug.tgz /app
Dec 06 23:12:08 deis-1 sh[31294]: ---> Using cache
Dec 06 23:12:08 deis-1 sh[31294]: ---> a1b65596f340
Dec 06 23:12:08 deis-1 sh[31294]: Successfully built a1b65596f340
Dec 06 23:12:29 deis-1 sh[31294]: [info] Woke up.
Dec 06 23:12:29 deis-1 sh[31294]: warnContinuing after Recoverable Error on route boot: 105: Key already exists (/deis/builder/users) [3155182]
Dec 06 23:12:29 deis-1 sh[31294]: [info] Parsed host key /etc/ssh/ssh_host_rsa_key.
Dec 06 23:12:29 deis-1 sh[31294]: [info] Parsed host key /etc/ssh/ssh_host_dsa_key.
Dec 06 23:12:29 deis-1 sh[31294]: [info] Parsed host key /etc/ssh/ssh_host_ecdsa_key.
Dec 06 23:12:29 deis-1 sh[31294]: [info] Building confd templates. This may take a moment.
Dec 06 23:12:29 deis-1 sh[31294]: [info] Templates generated for 10.0.20.77:4001 on run 0
Dec 06 23:12:29 deis-1 sh[31294]: [info] Watching confd.
Dec 06 23:12:29 deis-1 sh[31294]: [info] Downloading Docker images. This may take a long time. https://xkcd.com/303/
Dec 06 23:12:29 deis-1 sh[31294]: [info] Images downloaded
Dec 06 23:12:29 deis-1 sh[31294]: [info] Pushing deis/slugrunner:latest to 10.0.20.77:5000. This may take some time.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Finished pushing deis/slugrunner:latest to 10.0.20.77:5000.
Dec 06 23:12:36 deis-1 sh[31294]: [debug] Name: EXTERNAL_PORT, Val: 2223
Dec 06 23:12:36 deis-1 sh[31294]: [info] Added hostkey.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Added hostkey.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Added hostkey.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Listening on 0.0.0.0:2223
Dec 06 23:12:36 deis-1 sh[31294]: [info] Accepting new connections.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Builder is running.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:12:36 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:12:36 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc8201c0bd0}})
Dec 06 23:12:36 deis-1 systemd[1]: Started deis-builder.
Dec 06 23:12:57 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:12:57 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:14:03 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:14:03 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:14:04 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc8201cda40}})
Dec 06 23:14:05 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc820243960}})
Dec 06 23:14:05 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:14:05 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:14:07 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc820380bd0}})
Dec 06 23:14:56 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:14:56 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:14:58 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc8201cc930}})
Dec 06 23:15:22 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:15:22 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:15:24 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc8204fb3b0}})
Dec 06 23:15:24 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:15:24 deis-1 sh[31294]: [info] Accepted connection.
Dec 06 23:15:26 deis-1 sh[31294]: [error] Failed handshake: EOF (&{{0xc8202ba070}})
Dec 06 23:22:06 deis-1 sh[31294]: [info] Checking closer.
Dec 06 23:22:06 deis-1 sh[31294]: [info] Accepted connection.

I haven't had time to look into it, but there was a suspicious line in the log that caught my attention:
Dec 06 23:12:29 deis-1 sh[31294]: warnContinuing after Recoverable Error on route boot: 105: Key already exists (/deis/builder/users) [3155182]

@bacongobbler bacongobbler added this to the v1.13 LTS milestone Jan 21, 2016
@wgrrrr
Copy link
Contributor

wgrrrr commented Jan 22, 2016

I'm also seeing the same behaviour on 1.12.2. It seems this is pretty well documented/understood at this point, but thought I'd add the following log in case it is helpful for anyone.

...
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Added hostkey.
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Added hostkey.
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Added hostkey.
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Listening on 0.0.0.0:2223
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Accepting new connections.
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Checking closer.
Jan 22 17:45:36 ip-10-0-32-175 sh[28479]: [info] Builder is running.
Jan 22 17:45:37 ip-10-0-32-175 sh[28479]: [info] Checking closer.
Jan 22 17:45:37 ip-10-0-32-175 sh[28479]: [info] Accepted connection.
Jan 22 17:45:37 ip-10-0-32-175 sh[28479]: [error] Failed handshake: EOF (&{{0xc8201a75e0}})
Jan 22 17:45:37 ip-10-0-32-175 systemd[1]: Started deis-builder.

The result is intermittent failures to git push to the cluster by various users. Interestingly, it seems some users can push while others can't.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.