chore: remove source of duplicate properties in JSON log

[JamesPeiris]

Description

The EventSource logs contain noise in the form of duplicate properties

• eventName
• eventSourceName

E.g.

{
   "eventSourceName": "jp-webhook",
   "eventSourceName": "jp-webhook",
   "eventSourceType": "webhook",
   "eventName": "example",
   "eventName": "example"
}

The following are the original contiguous logs:

No Duplicates

{"level":"info","ts":1621930364.5526974,"logger":"argo-events.eventsource","caller":"driver/nats.go:96","msg":"NATS auth strategy: None","eventSourceName":"jp-webhook","clientID":"client-jp-webhook-eventsource-6zw95-6c7794fcf8-6wsqb-507"},
{"level":"info","ts":1621930364.556608,"logger":"argo-events.eventsource","caller":"driver/nats.go:105","msg":"Connected to NATS server.","eventSourceName":"jp-webhook","clientID":"client-jp-webhook-eventsource-6zw95-6c7794fcf8-6wsqb-507"},
{"level":"info","ts":1621930364.5600975,"logger":"argo-events.eventsource","caller":"driver/nats.go:118","msg":"Connected to NATS streaming server.","eventSourceName":"jp-webhook","clientID":"client-jp-webhook-eventsource-6zw95-6c7794fcf8-6wsqb-507"},
{"level":"info","ts":1621930364.5601459,"logger":"argo-events.eventsource","caller":"eventsources/eventing.go:423","msg":"Eventing server started.","eventSourceName":"jp-webhook"},
{"level":"info","ts":1621930364.5601807,"logger":"argo-events.eventsource","caller":"eventsources/eventing.go:332","msg":"starting eventbus connection daemon...","eventSourceName":"jp-webhook"},
{"level":"info","ts":1621930364.560263,"logger":"argo-events.eventsource","caller":"webhook/start.go:149","msg":"started processing the webhook event source...","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example"},

Duplicates

{"level":"info","ts":1621930364.5602934,"logger":"argo-events.eventsource","caller":"webhook/webhook.go:216","msg":"validating the route...","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example","eventSourceName":"jp-webhook","eventName":"example"},
{"level":"info","ts":1621930364.5603027,"logger":"argo-events.eventsource","caller":"webhook/webhook.go:222","msg":"listening to payloads for the route...","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example","eventSourceName":"jp-webhook","eventName":"example"},
{"level":"info","ts":1621930364.5603175,"logger":"argo-events.eventsource","caller":"webhook/webhook.go:229","msg":"activating the route...","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example","eventSourceName":"jp-webhook","eventName":"example"},
{"level":"info","ts":1621930364.560419,"logger":"argo-events.eventsource","caller":"webhook/webhook.go:179","msg":"route is activated","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example","eventSourceName":"jp-webhook","eventName":"example","port":"12000","endpoint":"/example"},
{"level":"info","ts":1621930364.5604398,"logger":"argo-events.eventsource","caller":"webhook/webhook.go:232","msg":"running operations post route activation...","eventSourceName":"jp-webhook","eventSourceType":"webhook","eventName":"example","eventSourceName":"jp-webhook","eventName":"example"}

The Problem

Each type of EventSource decorates the logs with eventName and eventSourceName before logging the specific type of webhook being set up:

argo-events/eventsources/sources/webhook/start.go

Lines 147 to 149 in 0e577da

	log := logging.FromContext(ctx).
	With(logging.LabelEventSourceType, el.GetEventSourceType(), logging.LabelEventName, el.GetEventName())
	log.Info("started processing the webhook event source...")

argo-events/eventsources/sources/github/start.go

Lines 291 to 293 in b0ab8bb

	logger := logging.FromContext(ctx).
	With(logging.LabelEventSourceType, el.GetEventSourceType(), logging.LabelEventName, el.GetEventName())
	logger.Info("started processing the Github event source...")

argo-events/eventsources/sources/slack/start.go

Lines 315 to 318 in b0ab8bb

	log := logging.FromContext(ctx).
	With(logging.LabelEventSourceType, el.GetEventSourceType(), logging.LabelEventName, el.GetEventName())
	log.Info("started processing the Slack event source...")

However, each one of these calls webhook.NewRoute, which again decorates the logs with the eventName and eventSourceName:

argo-events/eventsources/common/webhook/webhook.go

Line 48 in 0e577da

Logger: logger.With(logging.LabelEventSourceName, eventSourceName, logging.LabelEventName, eventName),

The Fix

Ideally this decoration would happen in one common place (i.e. webhook.NewRoute) so developers aren't relied upon to remember to add this decoration with each new EventSource.

However:

• Each EventSource already adds these properties, so the easy fix is to pass the logger in unchanged to webhook.NewRoute() - i.e. no .With() modifications (done in this PR).
• Certain EventSources (e.g. Kafka) don't use this common webhook.NewRoute function, so the decoration would need to happen at the specific EventSource regardless.

Links

Related Zap issue: uber-go/zap#622

Checklist

• My organization is added to USERS.md.
  We are trialing it before adopting, happy to update this once/if we officially use argo-events.

[whynowy]

Thanks for the detailed information! I'm surprised the issue is not fixed by zap.

[whynowy]

Thanks for fixing it!