Connect Retry Swallows Error Messages

[aistein]

If an eventsource fails to connect, it will retry and ultimately fail without actually logging why the connection failed.

For example, we were trying to connect to GCP PubSub using JSON formatted service-account credentials. It turned out that we had somehow messed up the JSON formatting, and so the credentials were not able to be digested. If more fine-grained logging of error messages was enabled in the Connect function, we likely would have seen this error and fixed it much faster. Instead, our logs offered little helpful information (even with DEBUG_LOG:true:

Eventsource Pod Logs

2021-04-07T21:05:13.256Z	INFO	argo-events.eventsource	gcppubsub/start.go:73	started processing the GCP Pub Sub event source...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr"}
2021-04-07T21:05:13.256Z	INFO	argo-events.eventsource	gcppubsub/start.go:90	assuming all events have a json body...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:13.256Z	INFO	argo-events.eventsource	gcppubsub/start.go:93	setting up a client to connect to PubSub...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:13.256Z	DEBUG	argo-events.eventsource	gcppubsub/start.go:206	using default credentials	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:13.256Z	DEBUG	argo-events.eventsource	gcppubsub/start.go:212	set up pubsub client	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:21.040Z	INFO	argo-events.eventsource	gcppubsub/start.go:73	started processing the GCP Pub Sub event source...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr"}
2021-04-07T21:05:21.040Z	INFO	argo-events.eventsource	gcppubsub/start.go:90	assuming all events have a json body...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:21.040Z	INFO	argo-events.eventsource	gcppubsub/start.go:93	setting up a client to connect to PubSub...	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:21.040Z	DEBUG	argo-events.eventsource	gcppubsub/start.go:206	using default credentials	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:05:21.041Z	DEBUG	argo-events.eventsource	gcppubsub/start.go:212	set up pubsub client	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "topic": "gcr", "topicProjectID": "te-engg-dev", "projectID": "te-engg-dev", "subscriptionID": "tiphys-gcr-1"}
2021-04-07T21:10:36.419Z	ERROR	argo-events.eventsource	eventsources/eventing.go:355	failed to start listening eventsource	{"eventSourceName": "gcr-pubsub", "eventSourceType": "pubsub", "eventName": "gcr", "error": "timed out waiting for the condition"}
github.com/argoproj/argo-events/eventsources.(*EventSourceAdaptor).Start.func3
	/home/runner/work/argo-events/argo-events/eventsources/eventing.go:355
2021-04-07T21:10:36.419Z	ERROR	argo-events.eventsource	eventsources/eventing.go:378	Erroring out, no active event server running	{"eventSourceName": "gcr-pubsub"}
github.com/argoproj/argo-events/eventsources.(*EventSourceAdaptor).Start
	/home/runner/work/argo-events/argo-events/eventsources/eventing.go:378
main.main
	/home/runner/work/argo-events/argo-events/eventsources/cmd/main.go:58
runtime.main
	/opt/hostedtoolcache/go/1.14.15/x64/src/runtime/proc.go:203
2021-04-07T21:10:36.419Z	INFO	argo-events.eventsource	eventsources/eventing.go:291	exiting eventbus connection daemon...	{"eventSourceName": "gcr-pubsub"}
2021-04-07T21:10:36.421Z	ERROR	argo-events.eventsource	driver/nats.go:84	NATS connection lost	{"eventSourceName": "gcr-pubsub", "clientID": "gcr-pubsub-eventsource-g4k5b-7bcb559869-4k4r5"}
github.com/argoproj/argo-events/eventbus/driver.(*natsStreaming).Connect.func1
	/home/runner/work/argo-events/argo-events/eventbus/driver/nats.go:84
github.com/nats-io/nats%2ego.(*Conn).close.func1
	/home/runner/go/pkg/mod/github.com/nats-io/[email protected]/nats.go:3722
github.com/nats-io/nats%2ego.(*asyncCallbacksHandler).asyncCBDispatcher
	/home/runner/go/pkg/mod/github.com/nats-io/[email protected]/nats.go:2008
2021-04-07T21:10:36.421Z	FATAL	argo-events.eventsource	cmd/main.go:59	failed to start eventsource server	{"eventSourceName": "gcr-pubsub", "error": "no active event server running", "errorVerbose": "no active event server running\ngithub.com/argoproj/argo-events/eventsources.(*EventSourceAdaptor).Start\n\t/home/runner/work/argo-events/argo-events/eventsources/eventing.go:381\nmain.main\n\t/home/runner/work/argo-events/argo-events/eventsources/cmd/main.go:58\nruntime.main\n\t/opt/hostedtoolcache/go/1.14.15/x64/src/runtime/proc.go:203\nruntime.goexit\n\t/opt/hostedtoolcache/go/1.14.15/x64/src/runtime/asm_amd64.s:1373"}
main.main
	/home/runner/work/argo-events/argo-events/eventsources/cmd/main.go:59
runtime.main
	/opt/hostedtoolcache/go/1.14.15/x64/src/runtime/proc.go:203

Initial discussion in argo-events slack:
https://argoproj.slack.com/archives/CAM37QYMS/p1617829466178400

Code of Interest:

argo-events/common/retry.go

Line 74 in 82068ec

return false, nil