Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TestDevPortForwardDeletePod failing integration test against Minikube on Darwin #4733

Closed
gsquared94 opened this issue Aug 28, 2020 · 4 comments · Fixed by #5107
Closed

TestDevPortForwardDeletePod failing integration test against Minikube on Darwin #4733

gsquared94 opened this issue Aug 28, 2020 · 4 comments · Fixed by #5107
Labels
meta/testing Issues focused on testing Skaffold itself priority/p1 High impact feature/bug.

Comments

@gsquared94
Copy link
Contributor

Error log 
=== Failed Tests ===
/integration/TestDevPortForwardDeletePod
time="2020-08-28T10:21:47Z" level=info msg="Namespace: skaffoldqcht4"
time="2020-08-28T10:21:47Z" level=info msg="[skaffold dev --namespace skaffoldqcht4 --default-repo gcr.io/k8s-skaffold --port-forward --rpc-port 63274]"
    rpc_test.go:377: waiting for connection...
    rpc_test.go:377: waiting for connection...
    dev_test.go:267: event received timestamp:<seconds:1598610108 nanos:533826000 > event:<metaEvent:<entry:"Starting Skaffold: &{Version:67e81bc ConfigVersion:skaffold/v2beta7 GitVersion: GitCommit:67e81bce7eba453dcca2b57a92e8157dbca3ecc3 GitTreeState:clean BuildDate:2020-08-28T06:00:45Z GoVersion:go1.14.2 Compiler:gc Platform:darwin/amd64}" metadata:<build:<numberOfArtifacts:2 builders:<type:DOCKER count:2 > type:LOCAL > deploy:<deployers:<type:KUBECTL count:1 > cluster:MINIKUBE > > > > 
    dev_test.go:267: event received timestamp:<seconds:1598610108 nanos:533920000 > event:<devLoopEvent:<status:"In Progress" > > entry:"Update initiated due to file change" 
    dev_test.go:267: event received timestamp:<seconds:1598610110 nanos:375950000 > event:<buildEvent:<artifact:"leeroy-web" status:"In Progress" > > entry:"Build started for artifact leeroy-web" 
WARNING: Could not open the configuration file: [/Users/runner/.config/gcloud/configurations/config_default].
ERROR: (gcloud.auth.docker-helper) You do not currently have an active account selected.
Please run:

  $ gcloud auth login

to obtain new credentials, or if you have already logged in with a
different account:

  $ gcloud config set account ACCOUNT

to select an already authenticated account to use.
    dev_test.go:253: timed out waiting for port forwarding event
time="2020-08-28T10:22:49Z" level=info msg="Ran in 1m2.012523065s"
--- FAIL: TestDevPortForwardDeletePod (62.04s)

Failed run: here
@gsquared94 gsquared94 added meta/testing Issues focused on testing Skaffold itself priority/p1 High impact feature/bug. labels Aug 28, 2020
@briandealwis
Copy link
Member

dev_test.go:253: timed out waiting for port forwarding event

Looks like the build "hung" in some way as we should have seen a deployEvent too. (The gcloud.auth.docker-helper errors are spurious: b/165805916.)

I restarted the job. Let's see if it fails again.

@nkubala nkubala added this to the Backlog milestone Sep 1, 2020
@briandealwis
Copy link
Member

I've been seeing this on Travis with k3d and kind.

@briandealwis
Copy link
Member

What we should see:

=== RUN   TestDevPortForwardDeletePod
time="2020-11-30T15:19:15-05:00" level=info msg="Namespace: skaffold2rkvf"
time="2020-11-30T15:19:15-05:00" level=info msg="[skaffold dev --namespace skaffold2rkvf --default-repo gcr.io/k8s-skaffold --port-forward --rpc-port 35235]"
    rpc_test.go:378: waiting for connection...
    rpc_test.go:378: waiting for connection...
    dev_test.go:265: event received timestamp:<seconds:1606767555 nanos:981644000 > event:<metaEvent:<entry:"Starting Skaffold: &{Version: ConfigVersion:skaffold/v2beta10 GitVersion: GitCommit: GitTreeState: BuildDate: GoVersion:go1.15.3 Compiler:gc Platform:darwin/amd64}" metadata:<build:<numberOfArtifacts:3 builders:<type:DOCKER count:3 > type:LOCAL > deploy:<deployers:<type:KUBECTL count:1 > cluster:OTHER > > > > 
    dev_test.go:265: event received timestamp:<seconds:1606767557 nanos:216028000 > event:<devLoopEvent:<status:"In Progress" > > entry:"Update initiated" 
    dev_test.go:265: event received timestamp:<seconds:1606767557 nanos:403718000 > event:<buildEvent:<artifact:"base" status:"In Progress" > > entry:"Build started for artifact base" 
    dev_test.go:265: event received timestamp:<seconds:1606767562 nanos:202043000 > event:<buildEvent:<artifact:"base" status:"Complete" > > entry:"Build completed for artifact base" 
    dev_test.go:265: event received timestamp:<seconds:1606767562 nanos:202061000 > event:<buildEvent:<artifact:"leeroy-web" status:"In Progress" > > entry:"Build started for artifact leeroy-web" 
    dev_test.go:265: event received timestamp:<seconds:1606767569 nanos:335167000 > event:<buildEvent:<artifact:"leeroy-web" status:"Complete" > > entry:"Build completed for artifact leeroy-web" 
    dev_test.go:265: event received timestamp:<seconds:1606767569 nanos:335176000 > event:<buildEvent:<artifact:"leeroy-app" status:"In Progress" > > entry:"Build started for artifact leeroy-app" 
    dev_test.go:265: event received timestamp:<seconds:1606767576 nanos:58266000 > event:<buildEvent:<artifact:"leeroy-app" status:"Complete" > > entry:"Build completed for artifact leeroy-app" 
    dev_test.go:265: event received timestamp:<seconds:1606767582 nanos:535131000 > event:<deployEvent:<status:"In Progress" > > entry:"Deploy started" 
time="2020-11-30T15:19:43-05:00" level=warning msg="image [base] is not used by the deployment"
    dev_test.go:265: event received timestamp:<seconds:1606767583 nanos:738525000 > event:<deployEvent:<status:"Complete" > > entry:"Deploy completed" 
    dev_test.go:265: event received timestamp:<seconds:1606767583 nanos:738563000 > event:<statusCheckEvent:<status:"Started" > > entry:"Status check started" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:986923000 > event:<resourceStatusCheckEvent:<resource:"skaffold2rkvf:pod/leeroy-app-98c7db65b-swmzz" status:"Succeeded" message:"Succeeded" statusCode:STATUSCHECK_SUCCESS > > entry:"Resource skaffold2rkvf:pod/leeroy-app-98c7db65b-swmzz status completed successfully" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:986934000 > event:<resourceStatusCheckEvent:<resource:"skaffold2rkvf:deployment/leeroy-app" status:"Succeeded" message:"Succeeded" statusCode:STATUSCHECK_SUCCESS > > entry:"Resource skaffold2rkvf:deployment/leeroy-app status completed successfully" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:991567000 > event:<resourceStatusCheckEvent:<resource:"skaffold2rkvf:pod/leeroy-web-c7665958c-78m99" status:"Succeeded" message:"Succeeded" statusCode:STATUSCHECK_SUCCESS > > entry:"Resource skaffold2rkvf:pod/leeroy-web-c7665958c-78m99 status completed successfully" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:991577000 > event:<resourceStatusCheckEvent:<resource:"skaffold2rkvf:deployment/leeroy-web" status:"Succeeded" message:"Succeeded" statusCode:STATUSCHECK_SUCCESS > > entry:"Resource skaffold2rkvf:deployment/leeroy-web status completed successfully" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:991595000 > event:<statusCheckEvent:<status:"Succeeded" > > entry:"Status check succeeded" 
    dev_test.go:265: event received timestamp:<seconds:1606767584 nanos:999153000 > event:<devLoopEvent:<status:"Succeeded" > > entry:"Update succeeded" 
    dev_test.go:255: event received timestamp:<seconds:1606767585 nanos:999582000 > event:<portEvent:<localPort:9002 remotePort:8080 namespace:"skaffold2rkvf" resourceType:"deployment" resourceName:"leeroy-web" address:"127.0.0.1" targetPort:<intVal:8080 > > > entry:"Forwarding container  to local port 9002" 
    dev_test.go:255: event received timestamp:<seconds:1606767587 nanos:2410000 > event:<portEvent:<localPort:9003 namespace:"skaffold2rkvf" resourceType:"deployment" resourceName:"leeroy-app" address:"127.0.0.1" targetPort:<type:1 strVal:"http" > > > entry:"Forwarding container  to local port 9003" 
    dev_test.go:255: event received timestamp:<seconds:1606767588 nanos:24281000 > event:<portEvent:<localPort:50053 remotePort:50051 namespace:"skaffold2rkvf" resourceType:"service" resourceName:"leeroy-app" address:"127.0.0.1" targetPort:<intVal:50051 > > > entry:"Forwarding container  to local port 50053" 
    dev_test.go:261: Detected service/leeroy-app is forwarded to address 127.0.0.1 port 50053
    dev_test.go:279: Waiting on http://127.0.0.1:50053 to return: leeroooooy app!!
    dev_test.go:279: Waiting on http://127.0.0.1:50053 to return: leeroooooy app!!
    dev_test.go:291: [retriable error]: Get "http://127.0.0.1:50053": EOF
    dev_test.go:291: [retriable error]: Get "http://127.0.0.1:50053": EOF
    dev_test.go:291: [retriable error]: Get "http://127.0.0.1:50053": EOF
    dev_test.go:291: [retriable error]: Get "http://127.0.0.1:50053": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
time="2020-11-30T15:20:03-05:00" level=info msg="Ran in 48.496997396s"

I wonder if we're hitting some kind of CPU or memory issue.

This was referenced Nov 30, 2020
Merged
Merged
@briandealwis
Copy link
Member

So I think the problem here is much simpler: the underlying skaffold instance is being blocked as its stdout buffer (a pipe) is full — we don't have anything reading off the process' output.

@briandealwis briandealwis mentioned this issue Dec 3, 2020
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
meta/testing Issues focused on testing Skaffold itself priority/p1 High impact feature/bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Remove return result from RunBackground briandealwis/skaffold
3 participants
@briandealwis @nkubala @gsquared94