JSON annotation in CR doesn't create JSON logs

[pit1sIBM]

Describe the bug

I've got the following annotations on my CR but I don't see JSON logs in the operator either locally or in the pod. Anything obvious that I'm missing here?

    oper8.org/log-default-level: debug3
    oper8.org/log-json: "true"

Platform

Please provide details about the environment you are using, including the following:

❯ pip show oper8
Name: oper8
Version: 0.1.15
Summary: Python-native Kubernetes operator framework for managing trees of components
Home-page:
Author:
Author-email:
License: Apache-2.0
Requires: alchemy-config, alchemy-logging, deepdiff, jsonpatch, kubernetes, openshift, pygit2, python-dateutil, semver
Required-by: document_processing

Sample Code

Logs with the CR annotated while running our operator locally

docker run --rm -it \
                 \
                -v ~/.kube/config:/kube/config \
                -e KUBECONFIG=/kube/config \
                document-processing-operator:latest
2024-03-29T17:19:51.747983 [MAIN :INFO:140488196974400] Running Python Operator
2024-03-29T17:19:51.753122 [MAIN :INFO:140488196974400] Starting Watches
2024-03-29T17:19:51.753346 [PYTHW:INFO:140488196974400] Starting PythonWatchManager: Watch[<class 'document_processing.controller.DocumentProcessingController'>]
2024-03-29T17:19:51.753749 [TRDUT:INFO:140488196974400] Starting TimerThread: timer_thread
2024-03-29T17:19:51.756878 [TRDUT:INFO:140488196974400] Starting ReconcileThread: reconcile_thread
2024-03-29T17:19:51.758716 [TRDUT:INFO:140488196974400] Starting WatchThread: watch_thread_watsonx.ibm.com/v1_DocumentProcessing
2024-03-29T17:19:52.521238 [RCLTH:INFO:140488036312640] Pushing request 'ReconcileRequest(controller_type=<class 'document_processing.controller.DocumentProcessingController'>, type=<KubeEventType.ADDED: 'ADDED'>, resource=watsonx.ibm.com/v1/DocumentProcessing/wdp-dr, timestamp=datetime.datetime(2024, 3, 29, 17, 19, 51, 700232))' to reconcile queue
2024-03-29T17:19:52.532115 [RCLTH:INFO:140488044705344] Starting reconcile for request ReconcileRequest(controller_type=<class 'document_processing.controller.DocumentProcessingController'>, type=<KubeEventType.ADDED: 'ADDED'>, resource=watsonx.ibm.com/v1/DocumentProcessing/wdp-dr, timestamp=datetime.datetime(2024, 3, 29, 17, 19, 51, 700232))
2024-03-29T17:19:52.542252 [ENTRY:INFO:140488125838912] ReconcileProcessEntrypoint for <class 'document_processing.controller.DocumentProcessingController'> and with type: KubeEventType.ADDED
2024-03-29T17:19:52.545162 [RECON:INFO:140488125838912] BEGIN: reconcile()
2024-03-29T17:19:53.225879 [RECON:INFO:140488125838912] Reconciling resource DocumentProcessing/docproc/wdp-dr
2024-03-29T17:19:58.814419 [CLSTR:INFO:140488125838912] Fetching Secret/wdp-dr-wdu-runtime-etcd-cxn from cluster
2024-03-29T17:19:58.828015 [CLSTR:INFO:140488125838912] Fetching Secret/wdp-dr-enrich-etcd-cxn from cluster
2024-03-29T17:19:58.838508 [CLSTR:INFO:140488125838912] Fetching Secret/wdp-dr-etcd-auth from cluster
2024-03-29T17:19:58.841430 [CLSTR:INFO:140488125838912] Fetching Secret/wdp-dr-teh-msk from cluster

Logs with LOG_JSON set in the container's env

docker run --rm -it \
                 \
                -v ~/.kube/config:/kube/config \
                -e KUBECONFIG=/kube/config \
                -e LOG_JSON=true \
                document-processing-operator:latest
{"channel": "MAIN", "exception": null, "level": "info", "message": "Running Python Operator", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.116860"}
{"channel": "MAIN", "exception": null, "level": "info", "message": "Starting Watches", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.125099"}
{"channel": "PYTHW", "exception": null, "level": "info", "message": "Starting PythonWatchManager: Watch[<class 'document_processing.controller.DocumentProcessingController'>]", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.125320"}
{"channel": "TRDUTLS", "exception": null, "level": "info", "message": "Starting TimerThread: timer_thread", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.125966"}
{"channel": "TRDUTLS", "exception": null, "level": "info", "message": "Starting ReconcileThread: reconcile_thread", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.129462"}
{"channel": "TRDUTLS", "exception": null, "level": "info", "message": "Starting WatchThread: watch_thread_watsonx.ibm.com/v1_DocumentProcessing", "num_indent": 0, "process": 7, "thread": 139932219877184, "threadName": "MainThread", "thread_id": 139932219877184, "timestamp": "2024-03-29T17:25:08.131324"}

Expected behavior

JSON logs when the CR is annotated correctly

Observed behavior

Logs not in JSON when the CR is annotated correctly

Additional context

JSON logging works with env var, issue is specific to CR annotations

[pit1sIBM]

Spoke to @HonakerM about this previously but forgot to create an issue at the time