TestEventsRPC can be flakey

[briandealwis]

@tejal29 and I have had a number of failures in TestEventsRPC as it's receiving 1 deploy event, not the 2 expected.

=== RUN   TestEventsRPC
time="2020-04-27T22:37:19Z" level=info msg="[skaffold build --default-repo gcr.io/k8s-skaffold]"
time="2020-04-27T22:37:19Z" level=info msg="Ran in 121.863354ms"
time="2020-04-27T22:37:19Z" level=debug msg="getting client config for kubeContext: ``"
time="2020-04-27T22:37:19Z" level=info msg="Namespace: skaffoldqfdcw"
time="2020-04-27T22:37:19Z" level=info msg="[skaffold dev --namespace skaffoldqfdcw --default-repo gcr.io/k8s-skaffold --rpc-port 35358]"
    TestEventsRPC: rpc_test.go:88: waiting for connection...
    TestEventsRPC: rpc_test.go:88: waiting for connection...
    TestEventsRPC: rpc_test.go:128: int differ (-got, +want):   int(
        - 	1,
        + 	2,
          )
time="2020-04-27T22:37:21Z" level=info msg="Ran in 2.163203741s"

I added some logging at there are normally two deploy events:

1. deployEvent:<status:"In Progress" > 
2: deployEvent:<status:"Complete" > 

We don't see the second Complete event.

TestEventsRPC failure

``` time="2020-04-28T18:36:30Z" level=info msg="[skaffold dev --namespace skaffoldpbr82 --default-repo gcr.io/k8s-skaffold --rpc-port 29619]" TestEventsRPC: rpc_test.go:88: waiting for connection... TestEventsRPC: rpc_test.go:88: waiting for connection... TestEventsRPC: rpc_test.go:119: meta event 1: metaEvent: type:LOCAL > deploy: cluster:OTHER > > > TestEventsRPC: rpc_test.go:122: build event 1: buildEvent: TestEventsRPC: rpc_test.go:122: build event 2: buildEvent: TestEventsRPC: rpc_test.go:125: deploy event 1: deployEvent: TestEventsRPC: rpc_test.go:131: int differ (-got, +want): int( - 1, + 2, ) time="2020-04-28T18:36:32Z" level=info msg="Ran in 2.143460403s" ```

successful run — notice completion in 1.5s

=== RUN   TestEventsRPC
time="2020-04-28T19:03:11Z" level=info msg="[skaffold build --default-repo gcr.io/k8s-skaffold]"
time="2020-04-28T19:03:11Z" level=info msg="Ran in 110.678287ms"
time="2020-04-28T19:03:11Z" level=debug msg="getting client config for kubeContext: ``"
time="2020-04-28T19:03:11Z" level=info msg="Namespace: skaffoldsbdk5"
time="2020-04-28T19:03:11Z" level=info msg="[skaffold dev --namespace skaffoldsbdk5 --default-repo gcr.io/k8s-skaffold --rpc-port 23499]"
    TestEventsRPC: rpc_test.go:88: waiting for connection...
    TestEventsRPC: rpc_test.go:119: meta event 1: metaEvent:<entry:"Starting Skaffold: &{Version:v1.8.0-84-gf89624e ConfigVersion:skaffold/v2beta3 GitVersion: GitCommit:f89624e16f474d67daee787a3d4dbfb2ed782ca9 GitTreeState:clean BuildDate:2020-04-28T18:55:58Z GoVersion:go1.14.2 Compiler:gc Platform:linux/amd64}" metadata:<build:<numberOfArtifacts:1 builders:<type:DOCKER count:1 > type:LOCAL > deploy:<deployers:<type:KUBECTL count:1 > cluster:OTHER > > > 
    TestEventsRPC: rpc_test.go:122: build event 1: buildEvent:<artifact:"test-dev" status:"In Progress" > 
    TestEventsRPC: rpc_test.go:122: build event 2: buildEvent:<artifact:"test-dev" status:"Complete" > 
    TestEventsRPC: rpc_test.go:125: deploy event 1: deployEvent:<status:"In Progress" > 
    TestEventsRPC: rpc_test.go:125: deploy event 2: deployEvent:<status:"Complete" > 
--- PASS: TestEventsRPC (1.57s)

[briandealwis]

Oh! I just realized that the test failure wasn't using my revised logging code to log the default case: it may be that we're receiving some other event.

skaffold/integration/rpc_test.go

Lines 114 to 128 in 67b405e

	metaEntries, buildEntries, deployEntries := 0, 0, 0
	for _, entry := range logEntries {
	switch entry.Event.GetEventType().(type) {
	case *proto.Event_MetaEvent:
	metaEntries++
	t.Logf("meta event %d: %v", metaEntries, entry.Event)
	case *proto.Event_BuildEvent:
	buildEntries++
	t.Logf("build event %d: %v", buildEntries, entry.Event)
	case *proto.Event_DeployEvent:
	deployEntries++
	t.Logf("deploy event %d: %v", deployEntries, entry.Event)
	default:
	t.Logf("unknown event: %v", entry.Event)
	}

[briandealwis]

Aha! Here's the culprit: statusCheckEvent:<status:"Started" >

time="2020-04-28T20:15:10Z" level=info msg="[skaffold dev --namespace skaffoldbrtb7 --default-repo gcr.io/k8s-skaffold --rpc-port 13338]"
    TestEventsRPC: rpc_test.go:88: waiting for connection...
    TestEventsRPC: rpc_test.go:88: waiting for connection...
    TestEventsRPC: rpc_test.go:119: meta event 1: metaEvent:<entry:"Starting Skaffold: &{Version:v1.8.0-84-gf89624e ConfigVersion:skaffold/v2beta3 GitVersion: GitCommit:f89624e16f474d67daee787a3d4dbfb2ed782ca9 GitTreeState:clean BuildDate:2020-04-28T20:07:14Z GoVersion:go1.14.2 Compiler:gc Platform:linux/amd64}" metadata:<build:<numberOfArtifacts:1 builders:<type:DOCKER count:1 > type:LOCAL > deploy:<deployers:<type:KUBECTL count:1 > cluster:OTHER > > > 
    TestEventsRPC: rpc_test.go:122: build event 1: buildEvent:<artifact:"test-dev" status:"In Progress" > 
    TestEventsRPC: rpc_test.go:122: build event 2: buildEvent:<artifact:"test-dev" status:"Complete" > 
    TestEventsRPC: rpc_test.go:125: deploy event 1: deployEvent:<status:"In Progress" > 
    TestEventsRPC: rpc_test.go:127: unknown event: statusCheckEvent:<status:"Started" > 
    TestEventsRPC: rpc_test.go:132: int differ (-got, +want):   int(
        - 	1,
        + 	2,
          )

[tejal29]

My branch is also failing due to same issue. This could be due to status check being turned on by default.