Add logs and events to reconcilers #108

negz · 2020-01-15T07:11:31Z

Description of your changes

This commit introduces new logging and eventing libraries, and adds debug logs and events to all reconcilers. It's guided by the below thinking:

Specifically the approach is to:

Have each reconciler scaffold handle the bulk (all?) of the logging and eventing.
Avoid plumbing loggers and event recorders down into the pluggable logic the reconciler scaffolds call in order to reconcile stuff (e.g. to CRUD external resources, propagate secrets, etc). Instead have said logic wrap error messages with useful context, and log them from the scaffold.
Log assuming Crossplane will be running in production. i.e.
- 50+ claims and resources under reconciliation.
- Most users don't have access to Crossplane pod logs.
- Logs are being sent to a log aggregation platform (Stackdriver, ELK, etc)
- Timeseries metrics are exposed where appropriate.

It's worth noting that the final point above (assuming production) has thus far meant I haven't yet come across anything that seems worthy of logging at info level, however ~80% of the situations worthy of a debug log (mostly errors or healthy state changes relating to resources) have corresponding Kubernetes events.

Checklist

I have:

Run make reviewable to ensure this PR is ready for review.
Ensured this PR contains a neat, self documenting set of commits.
Updated any relevant documentation, examples, or release notes.
Updated the RBAC permissions in clusterrole.yaml to include any new types.

upbound-bot · 2020-01-16T06:12:50Z

upbound-bot · 2020-01-16T07:30:04Z

upbound-bot · 2020-01-16T07:35:25Z

upbound-bot · 2020-01-16T07:40:03Z

suskin

Awesomeeee 🦑 . I had some questions, but they're probably not blockers. But it'd be good to at least take a look at them before merging.

I haven't yet come across anything that seems worthy of logging at info level.

I agree with this.

pkg/logging/logging.go

pkg/reconciler/claimbinding/reconciler.go

pkg/reconciler/managed/reconciler.go

pkg/util/pod.go

upbound-bot · 2020-01-24T23:28:23Z

upbound-bot · 2020-01-24T23:32:59Z

This commit introduces new logging and eventing libraries, and adds debug logs and events to all reconcilers. Signed-off-by: Nic Cope <negz@rk0n.org>

upbound-bot · 2020-01-27T03:28:58Z

negz · 2020-01-27T03:35:59Z

Here are some example events for a newly created resource claim:

# Per kubectl describe postgresqlinstance
Events:
  Type    Reason                  Age                From                                Message
  ----    ------                  ----               ----                                -------
  Normal  SelectedResourceClass   51m                claimscheduling/postgresqlinstance  Selected matching resource class
  Normal  CreatedManagedResource  51m                claimbinding/postgresqlinstance     Successfully created managed resource
  Normal  WaitingToBind           51m (x8 over 51m)  claimbinding/postgresqlinstance     Managed resource is not yet bindable
  Normal  BoundManagedResource    28m                claimbinding/postgresqlinstance     Successfully bound managed resource

...and the corresponding CloudSQLInstance:

# Per kubectl describe cloudsqlinstance
Events:
  Type     Reason                   Age                From                      Message
  ----     ------                   ----               ----                      -------
  Normal   CreatedExternalResource  52m                managed/cloudsqlinstance  Successfully requested creation of external resource
  Normal   UpdatedExternalResource  1s                 managed/cloudsqlinstance  Successfully requested update of external resource
  Warning  CannotConnectToProvider  15s (x3 over 15s)  managed/cloudsqlinstance  provider could not be retrieved: Provider.gcp.crossplane.io "example" not found

It's also possible to view events for all resources in a particular namespace:

# Per kubectl get events --sort-by=.metadata.creationTimestamp
57m         Normal   SelectedResourceClass     postgresqlinstance/app-postgresql               Selected matching resource class
55m         Normal   CreatedManagedResource    postgresqlinstance/app-postgresql               Successfully created managed resource
55m         Normal   WaitingToBind             postgresqlinstance/app-postgresql               Managed resource is not yet bindable
55m         Normal   CreatedExternalResource   cloudsqlinstance/default-app-postgresql-28rwf   Successfully requested creation of external resource
33m         Normal   BoundManagedResource      postgresqlinstance/app-postgresql               Successfully bound managed resource
2m52s       Normal   UpdatedExternalResource   cloudsqlinstance/default-app-postgresql-28rwf   Successfully requested update of external resource
65s         Normal   UnboundManagedResource    postgresqlinstance/app-postgresql               Successfully unbound managed resource
63s         Normal   DeletedExternalResource   cloudsqlinstance/default-app-postgresql-28rwf   Successfully requested deletion of external resource

negz · 2020-01-27T03:53:19Z

Here are some debug logs of the happy path dynamic provisioning of a resource claim:

2020-01-26T19:41:48.654-0800    DEBUG   stack-gcp       Starting        {"sync-period": "1h0m0s"}                                                             
2020-01-26T19:41:59.183-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimscheduling/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:41:59.695-0800    DEBUG   stack-gcp       Attempting to set resource class        {"controller": "claimscheduling/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7101", "external-name": "", "class-kind": "CloudSQLInstanceClass", "class-name": "cloudsqlinstancepostgresql-standard"}
2020-01-26T19:41:59.708-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}  
2020-01-26T19:41:59.818-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:41:59.827-0800    DEBUG   stack-gcp       Successfully created managed resource   {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7102", "external-name": "", "class-name": "cloudsqlinstancepostgresql-standard", "managed-name": ""}
2020-01-26T19:41:59.827-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7102", "external-name": "", "class-name": "cloudsqlinstancepostgresql-standard", "managed-name": ""}
2020-01-26T19:41:59.835-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:41:59.835-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}                   
2020-01-26T19:41:59.931-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:41:59.931-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}                   
2020-01-26T19:42:00.389-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:42:00.389-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:42:02.772-0800    DEBUG   stack-gcp       Successfully requested creation of external resource    {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7104", "external-name": "", "requeue-after": "2020-01-26T19:42:32.772-0800"}
2020-01-26T19:42:02.780-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:42:02.780-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:42:02.780-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:42:02.961-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:42:02.961-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:42:02.972-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7123", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:43:02.972-0800"}
2020-01-26T19:42:02.979-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:42:02.980-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:42:02.980-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:42:03.098-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7125", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:43:03.098-0800"}
2020-01-26T19:42:04.108-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:42:04.244-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7128", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:43:04.244-0800"}
2020-01-26T19:43:04.254-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:43:04.385-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7128", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:44:04.385-0800"}
2020-01-26T19:43:04.393-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:43:04.394-0800    DEBUG   stack-gcp       Managed resource is not yet bindable    {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:43:04.397-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:43:04.523-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7213", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:44:04.523-0800"}
2020-01-26T19:44:04.397-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:44:04.524-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7213", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:45:04.524-0800"}
2020-01-26T19:45:04.536-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:45:04.668-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7213", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:46:04.668-0800"}
2020-01-26T19:46:04.680-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:46:04.812-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7213", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:47:04.812-0800"}
2020-01-26T19:46:04.826-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:46:04.831-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:46:04.864-0800    DEBUG   stack-gcp       Successfully bound managed resource     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql", "uid": "a0f5328a-715f-4c12-8926-e414f2e9e35f", "version": "7106", "external-name": "", "managed-name": "default-app-postgresql-4wsmn"}
2020-01-26T19:46:04.872-0800    DEBUG   stack-gcp       Reconciling     {"controller": "claimbinding/postgresqlinstance", "request": "default/app-postgresql"}
2020-01-26T19:46:04.950-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7458", "external-name": "default-app-postgresql-4wsmn", "requeue-after": "2020-01-26T19:47:04.950-0800"}
2020-01-26T19:46:05.958-0800    DEBUG   stack-gcp       Reconciling     {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn"}
2020-01-26T19:46:06.086-0800    DEBUG   stack-gcp       External resource is up to date {"controller": "managed/cloudsqlinstance", "request": "/default-app-postgresql-4wsmn", "uid": "61cd6496-753a-4397-940c-192f20a0ade8", "version": "7462", "external-name": "default-apppostgresql-4wsmn", "requeue-after": "2020-01-26T19:47:06.086-0800"}

hasheddan

This is looking really solid to me @negz! Thanks for the examples to demonstrate. Are there any further steps you anticipate needing to implement?

hasheddan · 2020-01-27T03:57:39Z

pkg/reconciler/claimbinding/reconciler.go

+
+// ControllerName returns the recommended name for controllers that use this
+// package to reconcile a particular kind of resource claim.
+func ControllerName(kind string) string {


I like this addition here :)

I noticed there were a bunch of inconsistencies in controller names, and that they were fairly long and verbose in the logs. I figured we could get away with just the kind as there will rarely be more than one controller of a particular flavor for a particular resource kind within a particular binary.

hasheddan · 2020-01-27T04:02:37Z

pkg/reconciler/secret/reconciler.go

+// Both secrets must consent to this process by including propagation
+// annotations. The Reconciler assumes it has a watch on both propagating (from)
+// and propagated (to) secrets.
+type Reconciler struct {


This will be a nice help with the making the Secret reconciler implementation look more like the others

Yeah, it was essentially required now that we want functional arguments.

negz · 2020-01-27T04:44:00Z

Are there any further steps you anticipate needing to implement?

Good question. There's a lot more we could do, namely:

Update all infrastructure stacks to pass in loggers and event records to reconcilers.
Document our required logging practices.
Bring the workload and stack manager loggers into line with this pattern.
Plumb logging and eventing into the various managed.ExternalClient implementations.

I plan to address 1 and 2 before considering crossplane/crossplane#331 and crossplane/crossplane#944 fixed, and will raise a new issue to track 3. I'm not yet sure whether 4 is really necessary/useful.

crossplane/crossplane-runtime#108 This commit updates all stack-gcp controllers to use the logging and event recording functionality added in the above crossplane-runtime PR. Legacy controllers are minimally updated to avoid package scoped loggers. Signed-off-by: Nic Cope <negz@rk0n.org>

crossplane/crossplane-runtime#108 This commit updates all stack-aws controllers to use the logging and event recording functionality added in the above crossplane-runtime PR. Legacy controllers are minimally updated to avoid package scoped loggers. Signed-off-by: Nic Cope <negz@rk0n.org>

crossplane/crossplane-runtime#108 This commit updates all stack-aws controllers to use the logging and event recording functionality added in the above crossplane-runtime PR. Legacy controllers are minimally updated to avoid package scoped loggers.

negz requested review from suskin, jbw976, muvaf and hasheddan January 15, 2020 07:11

negz force-pushed the observe branch from a3ec02b to 1883203 Compare January 16, 2020 06:09

negz mentioned this pull request Jan 16, 2020

Plumb up logging and event recorder implementations crossplane-contrib/provider-gcp#142

Merged

5 tasks

negz force-pushed the observe branch from 1883203 to 73fa77b Compare January 16, 2020 07:26

negz force-pushed the observe branch from 73fa77b to 33977bc Compare January 16, 2020 07:31

negz force-pushed the observe branch from 33977bc to 597f42a Compare January 16, 2020 07:36

suskin approved these changes Jan 18, 2020

View reviewed changes

pkg/logging/logging.go Show resolved Hide resolved

pkg/logging/logging.go Show resolved Hide resolved

pkg/reconciler/claimbinding/reconciler.go Show resolved Hide resolved

pkg/reconciler/managed/reconciler.go Show resolved Hide resolved

pkg/util/pod.go Show resolved Hide resolved

negz mentioned this pull request Jan 24, 2020

TRACE-level logging crossplane/crossplane#611

Closed

negz force-pushed the observe branch from 597f42a to 8391d84 Compare January 24, 2020 23:24

negz changed the title ~~Log all the things!~~ Add logs and events to reconcilers Jan 24, 2020

negz force-pushed the observe branch from 8391d84 to e70d998 Compare January 24, 2020 23:29

Add debug logging and events to all reconcilers

2b04b4d

This commit introduces new logging and eventing libraries, and adds debug logs and events to all reconcilers. Signed-off-by: Nic Cope <negz@rk0n.org>

negz force-pushed the observe branch from e70d998 to 2b04b4d Compare January 27, 2020 03:25

negz marked this pull request as ready for review January 27, 2020 03:27

hasheddan reviewed Jan 27, 2020

View reviewed changes

hasheddan approved these changes Jan 27, 2020

View reviewed changes

negz merged commit 8661974 into crossplane:master Jan 27, 2020

negz deleted the observe branch January 27, 2020 05:29

This was referenced Jan 27, 2020

Add ZapLogger with option to disable stacktraces #47

Closed

Disable full call stacks from reconcile errors in logs crossplane/crossplane#529

Closed

negz mentioned this pull request Jan 30, 2020

Plumb up logging and event recording implementations crossplane-contrib/provider-aws#118

Merged

4 tasks

This was referenced Jan 31, 2020

Plumb up logging and event recording implementations crossplane-contrib/provider-azure#101

Merged

Controller Reconcile Events crossplane/crossplane#25

Closed

Improved logging and eventing #104

Closed

negz mentioned this pull request Feb 3, 2020

Pass loggers down from main.go crossplane/crossplane#1227

Merged

4 tasks

negz mentioned this pull request Feb 12, 2020

Please allow for more verbose logging crossplane-contrib/provider-gcp#165

Open

alecrajeev mentioned this pull request Jul 12, 2021

Added verbose logging option when resource is updated #272

Merged

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logs and events to reconcilers #108

Add logs and events to reconcilers #108

negz commented Jan 15, 2020 •

edited

Loading

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

suskin left a comment

upbound-bot commented Jan 24, 2020

upbound-bot commented Jan 24, 2020

upbound-bot commented Jan 27, 2020

negz commented Jan 27, 2020 •

edited

Loading

negz commented Jan 27, 2020

hasheddan left a comment

hasheddan Jan 27, 2020

negz Jan 27, 2020

hasheddan Jan 27, 2020

negz Jan 27, 2020

negz commented Jan 27, 2020

Add logs and events to reconcilers #108

Add logs and events to reconcilers #108

Conversation

negz commented Jan 15, 2020 • edited Loading

Description of your changes

Checklist

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

upbound-bot commented Jan 16, 2020

suskin left a comment

Choose a reason for hiding this comment

upbound-bot commented Jan 24, 2020

upbound-bot commented Jan 24, 2020

upbound-bot commented Jan 27, 2020

negz commented Jan 27, 2020 • edited Loading

negz commented Jan 27, 2020

hasheddan left a comment

Choose a reason for hiding this comment

hasheddan Jan 27, 2020

Choose a reason for hiding this comment

negz Jan 27, 2020

Choose a reason for hiding this comment

hasheddan Jan 27, 2020

Choose a reason for hiding this comment

negz Jan 27, 2020

Choose a reason for hiding this comment

negz commented Jan 27, 2020

negz commented Jan 15, 2020 •

edited

Loading

negz commented Jan 27, 2020 •

edited

Loading