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.

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

Fixes #193 by adding key tracing logs for internal eventing and reconciliation logic #194

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

davoustp
Copy link
Contributor

@davoustp davoustp commented Sep 15, 2023

This commit adds several debug logs for better troubleshooting:

  • each received Kubernetes event monitored by the manager is now logged (using an additional always-true Predicate that logs appropriate details, including a diff between old and new Kubernetes object on Update)
  • each read, write and delete operation to Vault is now logged
  • drift condition is now logged (Vault resource is in sync or not, with diff details in this case)

Log examples

These examples use a DatabaseSecretEngineRole named test-evtlogging

Logs below are redacted to remove details so that the log flow is more obvious.

Creation

debug "CreateEvent received" "namespace":"xyz" "name":"test-evtlogging" "event":{...}
debug "Returning cached client" "controller":"databasesecretenginerole" ...
info  "starting reconcile cycle" "controller":"databasesecretenginerole" ...
debug "reconcile" "controller":"databasesecretenginerole" ...
debug "reading resource from Vault" ... "namespace":"xyz" "name":"test-evtlogging"
            ... "op":"VaultEndpoint.CreateOrUpdate"
debug "resource does not exist, creating it in Vault" ... "name":"test-evtlogging" 
            ... "op":"VaultEndpoint.CreateOrUpdate"
debug "updating k8s resource status" ... "name":"test-evtlogging" ...
debug "adding k8s resource finalizer" ... "name":"test-evtlogging" ...
info  "validate update" "name":"test-evtlogging"

Update

This updates changes the defaultTTL field value from 0s to 60s:

info  "validate update" "name":"test-evtlogging"
debug "UpdateEvent received" "namespace":"xyz" "name":"test-evtlogging" "diff":"<event diff>"
debug "Returning cached client" ... "name":"test-evtlogging" ...
info  "starting reconcile cycle" ... "name":"test-evtlogging" ...
debug "reconcile" ... "name":"test-evtlogging" ...
debug "reading resource from Vault" ... "name":"test-evtlogging" ... "op":"VaultEndpoint.CreateOrUpdate"
debug "resource is not in sync, writing to Vault" ... "name":"test-evtlogging"
       ... "op":"VaultEndpoint.CreateOrUpdate" "diff":"<resource diff>"
debug "updating k8s resource status ... "name":"test-evtlogging" ...

<event diff> is a JSON-like string, which, once unescaped, shows the changes that happened to the Kubernetes resource which triggered the event.
Example:

  &v1alpha1.DatabaseSecretEngineRole{
    TypeMeta: {},
    ObjectMeta: v1.ObjectMeta{
      ... // 3 identical fields
      SelfLink:          "",
      UID:               "887c67ce-5c09-449a-bcda-db560b641933",
-     ResourceVersion:   "2001996",
+     ResourceVersion:   "2002033",
-     Generation:        1,
+     Generation:        2,
      CreationTimestamp: {Time: s"2023-09-15 07:32:39 +0000 UTC"},
      ...
      ManagedFields: []v1.ManagedFieldsEntry{
        {Manager: "Go-http-client", Operation: "Update", ...},
        ...
+       {
+         Manager:    "kubectl-edit",
+         Operation:  "Update",
+         APIVersion: "redhatcop.redhat.io/v1alpha1",
+         Time:       s"2023-09-15 07:32:57 +0000 UTC",
+         FieldsType: "FieldsV1",
+         FieldsV1:   s`{"f:spec":{"f:defaultTTL":{}}}`,
+       },
      },
    },
    Spec: v1alpha1.DatabaseSecretEngineRoleSpec{
        ...
-       DefaultTTL:         v1.Duration{},
+       DefaultTTL:         v1.Duration{Duration: s"1m0s"},
        MaxTTL:             {},
        ...
      },
    },
    Status: {...},
  }

<resource diff> is a JSON-like string, which, once unescaped, shows the difference between the object existing in Vault and what is expected from the Kubernetes resource.
Example:

<resource diff> is a JSON-like string, which, once unescaped, shows something like:

map[string]any{
-   "creation_statements": []any{
-     string(`CREATE ROLE "{{name}}" WITH LOGIN ...`...),
-   },
+   "creation_statements": []string{
+     `CREATE ROLE "{{name}}" WITH LOGIN IN ROLE ...`...,
+   },
-   "credential_type":       string("password"),
    "db_name":               string("the-db-name"),
-   "default_ttl":           s"0",
+   "default_ttl":           v1.Duration{Duration: s"1m0s"},
-   "max_ttl":               s"0",
+   "max_ttl":               v1.Duration{},
-   "renew_statements":      []any{},
+   "renew_statements":      []string(nil),
-   "revocation_statements": []any{string(`DROP ROLE "{{name}}";`)},
+   "revocation_statements": []string{`DROP ROLE "{{name}}";`},
-   "rollback_statements":   []any{},
+   "rollback_statements":   []string(nil),
  }

Note: an unexpected finding with these logs is that there are Go type differences when comparing the payload returned by Vault and the payload we expect, sometimes leading to unnecessary writes to Vault (for instance, when resync'ing all resources on operator restart or on schedule).

Deletion

debug "UpdateEvent received" "namespace":"xyz" "name":"test-evtlogging" "diff":"<event diff>"
debug "Returning cached client" ... "name":"test-evtlogging" ...
info  "starting reconcile cycle" ... "name":"test-evtlogging" ...
debug "reconcile" ... "name":"test-evtlogging" ...
debug "deleting resource from Vault" ... "name":"test-evtlogging" ... "op":"VaultEndpoint.DeleteIfExists"
debug "removing k8s resource finalizer" ... "name":"test-evtlogging" ...
info  "validate update" "name":"test-evtlogging"
debug "DeleteEvent received" "namespace":"xyz" "name":"test-evtlogging" "event":{...}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant