Error on release to K8s - ERROR: logging before flag.Parse: E0513 19:07:15.459086 3388 portforward.go:271] error creating error stream for port 53343 -> 44134: Timeout occurred

[rhollins]

I have strange behaviour where releasing phase fails but when I run draft up shortly after again it deploys successfully.

Also subsequent changes to code and deployments works fine.

It might be connected somehow to longer build phase as it usually fails when I don't have any images locally and build phase needs to download them first, I build using local docker. This error is quite consistent now for few weeks.

I'm deploying on AKS (1.9.2) in Azure, client is on Windows 10.

Draft version: &version.Version{SemVer:"v0.14.1", GitCommit:"fdc29c553a45600ac4f795f3485d4bb9a80c7862", GitTreeState:"clean"}

Helm version: Client: &version.Version{SemVer:"v2.9.0-rc1", GitCommit:"280863d2362345450125ce15c3db504471dde2cf", GitTreeState:"clean"} Server: &version.Version{SemVer:"v2.9.0-rc1", GitCommit:"280863d2362345450125ce15c3db504471dde2cf", GitTreeState:"clean"}

Error:

C:\Temp\gs-spring-boot-docker> draft up
?[94;40;4mDraft Up Started?[0m: '?[36;40mgs-spring-boot-docker?[0m': ?[93;40;1m01CDDAM4F9RN2MGB8E4YPP819C?[0m
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mBuilding Docker Image?[0m: SUCCESS ⚓  (289.2899s)
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mPushing Docker Image?[0m: SUCCESS ⚓  (29.8734s)
?[36;40mgs-spring-boot-docker?[0m: ?[93;40;1mReleasing Application?[0m /ERROR: logging before flag.Parse: E0513 19:07:04.615417    3388 portforward.go:178] lost connection to pod
?[36;40mgs-spring-boot-docker?[0m: ?[93;40;1mReleasing Application?[0m |ERROR: logging before flag.Parse: E0513 19:07:15.459086    3388 portforward.go:271] error creating error stream for port 53343 -> 44134: Timeout occurred
2018/05/13 19:07:15 transport: http2Client.notifyError got notified that the client transport was broken read tcp 127.0.0.1:53881->127.0.0.1:53343: wsarecv: An existing connection was forcibly closed by the remote host..
2018/05/13 19:07:15 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 127.0.0.1:53343: operation was canceled"; Reconnecting to {127.0.0.1:53343 <nil>}
2018/05/13 19:07:15 grpc: addrConn.transportMonitor exits due to: grpc: the connection is closing
?[36;40mgs-spring-boot-docker?[0m: ?[93;40;1mReleasing Application?[0m \2018/05/13 19:07:16 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 127.0.0.1:53343: connectex: No connection could be made because the target machine actively refused it."; Reconnecting to {127.0.0.1:53343 <nil>}
?[36;40mgs-spring-boot-docker?[0m: ?[93;40;1mReleasing Application?[0m \2018/05/13 19:07:17 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 127.0.0.1:53343: connectex: No connection could be made because the target machine actively refused it."; Reconnecting to {127.0.0.1:53343 <nil>}
?[36;40mgs-spring-boot-docker?[0m: ?[93;40;1mReleasing Application?[0m -2018/05/13 19:07:19 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 127.0.0.1:53343: connectex: No connection could be made because the target machine actively refused it."; Reconnecting to {127.0.0.1:53343 <nil>}
?[36;40mgs-spring-boot-docker?[0m: ?[91;40;3mReleasing Application?[0m: FAIL ❌  (35.2097s)
?[94;40;4mInspect the logs with?[0m `?[93;40;1mdraft logs 01CDDAM4F9RN2MGB8E4YPP819C?[0m`

Then I run it again shortly after and this time it works:

C:\Temp\gs-spring-boot-docker> draft up
?[94;40;4mDraft Up Started?[0m: '?[36;40mgs-spring-boot-docker?[0m': ?[93;40;1m01CDDB2N7FK7MTQM82G5VSHK3Q?[0m
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mBuilding Docker Image?[0m: SUCCESS ⚓  (1.0003s)
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mPushing Docker Image?[0m: SUCCESS ⚓  (2.1195s)
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mReleasing Application?[0m: SUCCESS ⚓  (3.2142s)
?[94;40;4mInspect the logs with?[0m `?[93;40;1mdraft logs 01CDDB2N7FK7MTQM82G5VSHK3Q?[0m`

Then all subsequent builds and deployments works fine:

C:\Temp\gs-spring-boot-docker> draft up
?[94;40;4mDraft Up Started?[0m: '?[36;40mgs-spring-boot-docker?[0m': ?[93;40;1m01CDDB6C23XQYRS2G1XDBFAXRB?[0m
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mBuilding Docker Image?[0m: SUCCESS ⚓  (134.1228s)
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mPushing Docker Image?[0m: SUCCESS ⚓  (28.5321s)
?[36;40mgs-spring-boot-docker?[0m: ?[92;40;1mReleasing Application?[0m: SUCCESS ⚓  (3.1599s)
?[94;40;4mInspect the logs with?[0m `?[93;40;1mdraft logs 01CDDB6C23XQYRS2G1XDBFAXRB?[0m`

[bacongobbler]

wsarecv: An existing connection was forcibly closed by the remote host..

That's an interesting one. Basically the kubernetes API forcibly closed the tunneled connection to tiller. I'm not aware of any tickets in Helm referencing this issue and haven't seen it before. Perhaps it was just a networking hiccup in AKS. Are you still able to reproduce this issue?

This seems relevant: https://github.com/Azure/AKS/issues/213

[rhollins]

HI, I think this can be closed for now as indeed it seems to be related to my specific situation.

I will also recreate AKS in custom vnet and use different site2site connection and monitor it closely for disconnects.

[bacongobbler]

Awesome. Thanks for checking in! Good to hear about these issues in the field.