Switch to structured logging #360

pinikomarov · 2023-06-24T00:05:16Z

This automatically adds additional Log fields like reconcile_id etc.. from the controller context.

Follow up from: openstack-k8s-operators/keystone-operator#220
Epic : OSP-22582 Switch Operators to structured logging

before :

{"level":"info","ts":"2023-07-04T10:11:14.655+0300","logger":"controllers.OpenStackControlPlane","msg":"Reconciling Glance","Glance.Namespace":"openstack","Glance.Name":"glance"}

after:

2023-10-15T02:37:10.941+0300    INFO    Controllers.OpenStackClient     OpenStackClient CR values       {"controller": "openstackclient", "controllerGroup": "client.openstack.org", "controllerKind": "OpenStackClient", "OpenStackClient": {"name":"openstackclient","namespace":"openstack"}, "namespace": "openstack", "name": "openstackclient", "reconcileID": "21a5c4af-ea9a-4c5c-aae2-78c77b76b01c", "Name": "openstackclient", "Namespace": "openstack", "Secret": "openstack-config-secret", "Image": "quay.io/podified-antelope-centos9/openstack-openstackclient@sha256:66a098b20c2a26ffc43b7d21f76b17bba386c3eebcc33ed48fb31208896d9761"}

set log dev true for console output

openshift-ci · 2023-06-24T00:05:28Z

Hi @pinikomarov. Thanks for your PR.

I'm waiting for a openstack-k8s-operators member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

softwarefactory-project-zuul · 2023-06-24T00:24:58Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/ce7e0b7e00054ef4ad9ebf6dea35a88f

❌ openstack-operator-content-provider FAILURE in 12m 22s
⚠️ openstack-operator-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-operator-content-provider
⚠️ openstack-operator-crc-podified-edpm-deployment SKIPPED Skipped due to failed job openstack-operator-content-provider

softwarefactory-project-zuul · 2023-06-24T23:52:59Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/61cf3b954f6f49a2b3f1445103c62749

❌ openstack-operator-content-provider FAILURE in 5m 38s
⚠️ openstack-operator-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-operator-content-provider
⚠️ openstack-operator-crc-podified-edpm-deployment SKIPPED Skipped due to failed job openstack-operator-content-provider

softwarefactory-project-zuul · 2023-06-25T00:05:53Z

Merge Failed.

This change or one of its cross-repo dependencies was unable to be automatically merged with the current state of its repository. Please rebase the change and upload a new patchset.
Warning:
Error merging github.com/openstack-k8s-operators/openstack-operator for 360,524e7a7715692721b65e3e26d33d6c1bc6705ba4

softwarefactory-project-zuul · 2023-06-28T22:44:29Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/1a8775bb9d5d487b91c2cb956c376f6a

❌ openstack-operator-content-provider RETRY_LIMIT in 2m 47s
⚠️ openstack-operator-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-operator-content-provider
⚠️ openstack-operator-crc-podified-edpm-deployment SKIPPED Skipped due to failed job openstack-operator-content-provider

pinikomarov · 2023-06-29T00:51:59Z

Hi @gibizer, can you take a look ?

I'm running this on titan88 using install yamls with the patch I'm getting :

/root/openstack-operator/controllers/core/openstackcontrolplane_controller.go:38:2: no such package located
Error: not all generators ran successfully

and on line 38th line we have : 
import (
github.com/openstack-k8s-operators/openstack-operator/pkg/openstack](http://github.com/openstack-k8s-operators/openstack-operator/pkg/openstack)

any ideas why this would break ?
tnx

pinikomarov · 2023-06-29T08:46:17Z

OH nevermind , K I got it

-: import cycle not allowed: import stack: [github.com/openstack-k8s-operators/openstack-operator github.com/openstack-k8s-operators/openstack-operator/controllers/core github.com/openstack-k8s-operators/openstack-operator/pkg/openstack github.com/openstack-k8s-operators/openstack-operator/controllers/core]

so it's denying import of the for the owned resources I guessing ..
< 1 minute ago
so openstackcontrolplane_controller.go which is importing "github.com/openstack-k8s-operators/openstack-operator/pkg/openstack"
is calling pkg/openstack/ovn.go which is importing openstackcontrolplane_controller.go for the GetLog func.
and that in turn causes re-import of the "openstack-operator/pkg/openstack" module. that's the import cycle go was talking about

softwarefactory-project-zuul · 2023-07-04T07:09:20Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/b157b69d3d6340ef9dc46ea6ac659d00

❌ openstack-operator-content-provider FAILURE in 6m 18s
⚠️ openstack-operator-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-operator-content-provider
⚠️ openstack-operator-crc-podified-edpm-deployment SKIPPED Skipped due to failed job openstack-operator-content-provider

softwarefactory-project-zuul · 2023-07-04T08:36:24Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/e95938ec99334f7893d329c4fd026f6d

✔️ openstack-operator-content-provider SUCCESS in 1h 09m 33s
❌ openstack-operator-crc-podified-edpm-baremetal FAILURE in 43m 01s
✔️ openstack-operator-crc-podified-edpm-deployment SUCCESS in 57m 36s

gibizer · 2023-07-04T11:04:50Z

It seems openstack-operator uses a different log format compared to keystone-operator.
keystone-operator:

2023-07-04T10:58:40Z	INFO	Controllers.KeystoneAPI	Reconciling Service	{"controller": "keystoneapi", "controllerGroup": "keystone.openstack.org", "controllerKind": "KeystoneAPI", "KeystoneAPI": {"name":"keystone","namespace":"openstack"}, "namespace": "openstack", "name": "keystone", "reconcileID": "ecd75bab-0441-4d17-9342-91416beb6d15"}

openstack-operator:

{"level":"info","ts":"2023-07-04T10:17:44.052+0300","logger":"Controllers.OpenstackControlPlane","msg":"Setting StatefulSet","controller":"openstackcontrolplane","controllerGroup":"core.openstack.org","controllerKind":"OpenStackControlPlane","OpenStackControlPlane":{"name":"openstack-network-isolation","namespace":"openstack"},"namespace":"openstack","name":"openstack-network-isolation","reconcileID":"9c199ee4-2e92-46ad-943c-fc977b70b9f5"}

I guess the difference is in the logger setup:

openstack-operator/main.go

Lines 111 to 122 in 5066704

    
           devMode, err := strconv.ParseBool(os.Getenv("DEV_MODE")) 
        
           if err != nil { 
        
           	devMode = false 
        
           } 
        
           opts := zap.Options{ 
        
           	Development: devMode, 
        
           	TimeEncoder: zapcore.ISO8601TimeEncoder, 
        
           } 
        
           opts.BindFlags(flag.CommandLine) 
        
           flag.Parse() 
        
           ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))

https://github.com/openstack-k8s-operators/keystone-operator/blob/4371f9602724378ac0c39eff7e635035afc761a3/main.go#L69-L75

The dev mode difference is added in 6435a06 But that commit does not have much reasoning why we are disabled dev mode by default. Maybe @fao89 or @abays knows more.

fao89 · 2023-07-04T11:11:10Z

I didn't have a special reason for setting it to false as default, I just wanted to make the development configurable, no objections for making true the default

pinikomarov · 2023-07-04T13:48:40Z

thanks @fao89 I changed it in the patch
@gibizer I updated the zap logging option to dev true so it's console output mode.
I also updated the commit message at the top to reflect that

fao89 · 2023-07-04T13:51:53Z

/ok-to-test

softwarefactory-project-zuul · 2023-07-04T14:00:45Z

Build failed (check pipeline). For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

https://review.rdoproject.org/zuul/buildset/fbb087b896f348a1b40c9c894fa3a4e5

✔️ openstack-operator-content-provider SUCCESS in 15m 34s
❌ openstack-operator-crc-podified-edpm-baremetal RETRY_LIMIT in 3s
❌ openstack-operator-crc-podified-edpm-deployment RETRY_LIMIT in 3s

gibizer

I have two small requests inline.

controllers/core/openstackcontrolplane_controller.go

gibizer · 2023-07-04T14:12:49Z

I didn't have a special reason for setting it to false as default, I just wanted to make the development configurable, no objections for making true the default

OK. So this is something we might want to decided together and sync in each operator. I don't know the actual implication of the devMode logger versus the non devMode one. Other then that actually log line format it emits. The devMode one is easier for humans to parse, but maybe the devMode:false one is better from machine processing?

softwarefactory-project-zuul · 2023-10-05T21:31:50Z

Merge Failed.

This change or one of its cross-repo dependencies was unable to be automatically merged with the current state of its repository. Please rebase the change and upload a new patchset.
Warning:
Error merging github.com/openstack-k8s-operators/openstack-operator for 360,bdbc9a517cfdd9ea685ce530ac0f3d4bc852c3c5

softwarefactory-project-zuul · 2023-10-08T12:15:37Z

Merge Failed.

This change or one of its cross-repo dependencies was unable to be automatically merged with the current state of its repository. Please rebase the change and upload a new patchset.
Warning:
Error merging github.com/openstack-k8s-operators/openstack-operator for 360,dd6d771929ca9714b3e14ae8d571e749390317da

softwarefactory-project-zuul · 2023-10-16T23:20:22Z

Merge Failed.

This change or one of its cross-repo dependencies was unable to be automatically merged with the current state of its repository. Please rebase the change and upload a new patchset.
Warning:
Error merging github.com/openstack-k8s-operators/openstack-operator for 360,9956edb4ca12c7f73060b5570adb76ee53cfd405

pinikomarov · 2023-10-19T09:49:31Z

/retest

softwarefactory-project-zuul · 2023-10-28T01:57:34Z

Build failed (check pipeline). Post recheck (without leading slash)
to rerun all jobs. Make sure the failure cause has been resolved before
you rerun jobs.

https://review.rdoproject.org/zuul/buildset/5de099c338a84439a2f84a968d2688c7

❌ openstack-k8s-operators-content-provider FAILURE in 6m 45s
⚠️ podified-multinode-edpm-deployment-crc SKIPPED Skipped due to failed job openstack-k8s-operators-content-provider
⚠️ cifmw-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-k8s-operators-content-provider

softwarefactory-project-zuul · 2023-10-28T02:27:43Z

Build failed (check pipeline). Post recheck (without leading slash)
to rerun all jobs. Make sure the failure cause has been resolved before
you rerun jobs.

https://review.rdoproject.org/zuul/buildset/650e8097373440eaa70edf973e4b8b16

❌ openstack-k8s-operators-content-provider FAILURE in 6m 44s
⚠️ podified-multinode-edpm-deployment-crc SKIPPED Skipped due to failed job openstack-k8s-operators-content-provider
⚠️ cifmw-crc-podified-edpm-baremetal SKIPPED Skipped due to failed job openstack-k8s-operators-content-provider

pinikomarov · 2023-10-28T02:28:29Z

/retest

pinikomarov · 2023-11-04T02:20:59Z

/retest

softwarefactory-project-zuul · 2023-11-04T03:55:26Z

Build failed (check pipeline). Post recheck (without leading slash)
to rerun all jobs. Make sure the failure cause has been resolved before
you rerun jobs.

https://review.rdoproject.org/zuul/buildset/d8327199bdde4d67b09eaaf22762ea31

✔️ openstack-k8s-operators-content-provider SUCCESS in 1h 33m 29s
✔️ podified-multinode-edpm-deployment-crc SUCCESS in 1h 02m 52s
❌ cifmw-crc-podified-edpm-baremetal FAILURE in 1h 01m 02s
✔️ openstack-operator-tempest-multinode SUCCESS in 1h 17m 03s

pinikomarov · 2023-11-07T10:06:37Z

recheck

pinikomarov · 2023-11-07T13:19:50Z

recheck

softwarefactory-project-zuul · 2023-11-07T15:23:25Z

Build failed (check pipeline). Post recheck (without leading slash)
to rerun all jobs. Make sure the failure cause has been resolved before
you rerun jobs.

https://review.rdoproject.org/zuul/buildset/382d78a88bfa463bb78e9080196f6753

✔️ openstack-k8s-operators-content-provider SUCCESS in 2h 00m 04s
✔️ podified-multinode-edpm-deployment-crc SUCCESS in 1h 09m 32s
❌ cifmw-crc-podified-edpm-baremetal FAILURE in 41m 46s
✔️ openstack-operator-tempest-multinode SUCCESS in 1h 34m 15s

This automatically adds additional Log fields like reconcile_id etc.. from the controller context. Follow up from: openstack-k8s-operators/keystone-operator#220 Epic : [OSP-22582](https://issues.redhat.com/browse/OSP-22582) Switch Operators to structured logging before : ```bash {"level":"info","ts":"2023-07-04T10:11:14.655+0300","logger":"controllers.OpenStackControlPlane","msg":"Reconciling Glance","Glance.Namespace":"openstack","Glance.Name":"glance"} ``` after: ```bash 2023-07-04T16:37:17.388+0300 INFO Controllers.OpenstackControlPlane Reconciling Cinder {"controller": "openstackcontrolplane", "controllerGroup": "core.openstack.org", "controllerKind": "OpenStackControlPlane", "OpenStackControlPlane": {"name":"openstack-network-isolation","namespace":"openstack"}, "namespace": "openstack", "name": "openstack-network-isolation", "reconcileID": "4801c762-5a50-4773-849c-c8b19f59841d", "Cinder.Namespace": "openstack", "Cinder.Name": "cinder"} ``` Full logs with before and after log messages for the multiple resources called by this operator: Full Before : http://pastebin.test.redhat.com/1104088 Full After: http://pastebin.test.redhat.com/1104132 set log dev true for console output fix non needed fmt import update logging usage update logging naming update main.go logging update logging fixup

pinikomarov · 2023-11-22T06:21:15Z

@dprince @stuggi hi can you review please ?

abays · 2023-11-30T14:46:02Z

@gibizer Have your requested changes been satisfied here?

gibizer · 2023-11-30T15:24:53Z

@gibizer Have your requested changes been satisfied here?

Yes, this looks OK to me.

stuggi

/lgtm

openshift-ci · 2023-12-04T10:52:07Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: pinikomarov, stuggi

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [stuggi]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

openshift-ci · 2023-12-04T13:05:54Z

@pinikomarov: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
ci/prow/unit	`dd6d771`	link	true	`/test unit`

Full PR test history. Your PR dashboard.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

pinikomarov · 2023-12-04T22:49:42Z

/retest-required

openshift-ci bot added the do-not-merge/work-in-progress label Jun 24, 2023

openshift-ci bot added the needs-ok-to-test label Jun 24, 2023

openshift-merge-robot added the needs-rebase label Jun 25, 2023

pinikomarov force-pushed the structured_logging branch from 524e7a7 to 95a9728 Compare June 28, 2023 22:27

openshift-merge-robot removed the needs-rebase label Jun 28, 2023

pinikomarov force-pushed the structured_logging branch from 8a9a6e7 to 97f7532 Compare July 4, 2023 07:25

pinikomarov marked this pull request as ready for review July 4, 2023 07:36

openshift-ci bot removed the do-not-merge/work-in-progress label Jul 4, 2023

openshift-ci bot requested review from abays and stuggi July 4, 2023 07:36

pinikomarov force-pushed the structured_logging branch from 97f7532 to 54e05d1 Compare July 4, 2023 13:43

openshift-ci bot added ok-to-test and removed needs-ok-to-test labels Jul 4, 2023

gibizer requested changes Jul 4, 2023

View reviewed changes

controllers/core/openstackcontrolplane_controller.go Outdated Show resolved Hide resolved

controllers/core/openstackcontrolplane_controller.go Show resolved Hide resolved

openshift-ci bot assigned gibizer Jul 4, 2023

pinikomarov force-pushed the structured_logging branch from dd6d771 to 9956edb Compare October 16, 2023 23:20

pinikomarov force-pushed the structured_logging branch from 9956edb to 4ba5c0d Compare October 17, 2023 00:49

openshift-merge-robot removed the needs-rebase label Oct 17, 2023

pinikomarov force-pushed the structured_logging branch from be582bf to d7055b4 Compare October 28, 2023 02:17

pinikomarov force-pushed the structured_logging branch from d7055b4 to 46df8c0 Compare November 4, 2023 02:20

pinikomarov force-pushed the structured_logging branch from 46df8c0 to 2eec08d Compare November 8, 2023 23:43

stuggi approved these changes Dec 4, 2023

View reviewed changes

openshift-ci bot assigned stuggi Dec 4, 2023

openshift-ci bot added the lgtm label Dec 4, 2023

openshift-ci bot added the approved label Dec 4, 2023

openshift-merge-bot bot merged commit 96a56b8 into openstack-k8s-operators:main Dec 5, 2023
6 checks passed

Switch to structured logging #360

Switch to structured logging #360

Conversation

pinikomarov commented Jun 24, 2023 • edited Loading

openshift-ci bot commented Jun 24, 2023

softwarefactory-project-zuul bot commented Jun 24, 2023

softwarefactory-project-zuul bot commented Jun 24, 2023

softwarefactory-project-zuul bot commented Jun 25, 2023

softwarefactory-project-zuul bot commented Jun 28, 2023

pinikomarov commented Jun 29, 2023 • edited Loading

pinikomarov commented Jun 29, 2023 • edited Loading

softwarefactory-project-zuul bot commented Jul 4, 2023

softwarefactory-project-zuul bot commented Jul 4, 2023

gibizer commented Jul 4, 2023

fao89 commented Jul 4, 2023 • edited Loading

pinikomarov commented Jul 4, 2023

fao89 commented Jul 4, 2023

softwarefactory-project-zuul bot commented Jul 4, 2023

gibizer left a comment

Choose a reason for hiding this comment

gibizer commented Jul 4, 2023

softwarefactory-project-zuul bot commented Oct 5, 2023

softwarefactory-project-zuul bot commented Oct 8, 2023

softwarefactory-project-zuul bot commented Oct 16, 2023

pinikomarov commented Oct 19, 2023

softwarefactory-project-zuul bot commented Oct 28, 2023

softwarefactory-project-zuul bot commented Oct 28, 2023

pinikomarov commented Oct 28, 2023

pinikomarov commented Nov 4, 2023

softwarefactory-project-zuul bot commented Nov 4, 2023

pinikomarov commented Nov 7, 2023

pinikomarov commented Nov 7, 2023

softwarefactory-project-zuul bot commented Nov 7, 2023

pinikomarov commented Nov 22, 2023

abays commented Nov 30, 2023

gibizer commented Nov 30, 2023

stuggi left a comment

Choose a reason for hiding this comment

openshift-ci bot commented Dec 4, 2023

openshift-ci bot commented Dec 4, 2023 • edited Loading

pinikomarov commented Dec 4, 2023

pinikomarov commented Jun 24, 2023 •

edited

Loading

pinikomarov commented Jun 29, 2023 •

edited

Loading

pinikomarov commented Jun 29, 2023 •

edited

Loading

fao89 commented Jul 4, 2023 •

edited

Loading

openshift-ci bot commented Dec 4, 2023 •

edited

Loading