Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1693100 - Cluster storage operator logs two log format
Summary: Cluster storage operator logs two log format
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Storage
Version: 4.1
Hardware: Unspecified
OS: Unspecified
low
medium
Target Milestone: ---
: 4.1.0
Assignee: Matthew Wong
QA Contact: Liang Xia
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-03-27 07:56 UTC by Liang Xia
Modified: 2019-04-01 16:10 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-04-01 16:10:30 UTC
Target Upstream Version:


Attachments (Terms of Use)

Description Liang Xia 2019-03-27 07:56:57 UTC
Description of problem:
In the cluster storage operator pod, there are two log formats.


Version-Release number of selected component (if applicable):
4.0.0-0.nightly-2019-03-26-072833

How reproducible:
Always

Steps to Reproduce:
1. oc -n openshift-cluster-storage-operator logs cluster-storage-operator-7877886fc6-cf4zv


Actual results:
$ oc -n openshift-cluster-storage-operator logs cluster-storage-operator-7877886fc6-cf4zv
{"level":"info","ts":1553661967.3551528,"logger":"cmd","msg":"Go Version: go1.10.8"}
{"level":"info","ts":1553661967.3552134,"logger":"cmd","msg":"Go OS/Arch: linux/amd64"}
{"level":"info","ts":1553661967.355229,"logger":"cmd","msg":"Version of operator-sdk: v0.4.0"}
{"level":"info","ts":1553661967.357901,"logger":"leader","msg":"Trying to become the leader."}
{"level":"info","ts":1553661967.5117447,"logger":"leader","msg":"Found existing lock","LockOwner":"cluster-storage-operator-586c5ddc94-jf82m"}
{"level":"info","ts":1553661967.516928,"logger":"leader","msg":"Not the leader. Waiting."}
{"level":"info","ts":1553661968.6436677,"logger":"leader","msg":"Not the leader. Waiting."}
{"level":"info","ts":1553661971.0254984,"logger":"leader","msg":"Not the leader. Waiting."}
{"level":"info","ts":1553661975.5624785,"logger":"leader","msg":"Not the leader. Waiting."}
{"level":"info","ts":1553661984.2828875,"logger":"leader","msg":"Became the leader."}
{"level":"info","ts":1553661984.4230099,"logger":"cmd","msg":"Registering Components."}
{"level":"info","ts":1553661984.4234562,"logger":"kubebuilder.controller","msg":"Starting EventSource","controller":"clusterstorage-controller","source":"kind source: /, Kind="}
{"level":"info","ts":1553661984.423648,"logger":"kubebuilder.controller","msg":"Starting EventSource","controller":"clusterstorage-controller","source":"kind source: /, Kind="}
{"level":"info","ts":1553661984.4238057,"logger":"cmd","msg":"Starting the Cmd."}
{"level":"info","ts":1553661984.5240183,"logger":"kubebuilder.controller","msg":"Starting Controller","controller":"clusterstorage-controller"}
{"level":"info","ts":1553661984.6245205,"logger":"kubebuilder.controller","msg":"Starting workers","controller":"clusterstorage-controller","worker count":1}
{"level":"info","ts":1553661984.6247125,"logger":"controller_clusterstorage","msg":"Reconciling ConfigMap","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1"}
{"level":"info","ts":1553661984.7379026,"logger":"controller_clusterstorage","msg":"Skip reconcile: StorageClass already exists","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1","StorageClass.Name":"gp2"}
E0327 05:04:56.213940       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=289, ErrCode=NO_ERROR, debug=""
E0327 05:04:56.215013       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=289, ErrCode=NO_ERROR, debug=""
E0327 05:04:56.215038       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=289, ErrCode=NO_ERROR, debug=""
{"level":"info","ts":1553663097.4157138,"logger":"controller_clusterstorage","msg":"Reconciling ConfigMap","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1"}
{"level":"info","ts":1553663097.41652,"logger":"controller_clusterstorage","msg":"Skip reconcile: StorageClass already exists","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1","StorageClass.Name":"gp2"}
E0327 05:07:29.534617       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=11, ErrCode=NO_ERROR, debug=""
E0327 05:07:29.535225       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=11, ErrCode=NO_ERROR, debug=""
E0327 05:07:29.535449       1 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=11, ErrCode=NO_ERROR, debug=""
{"level":"info","ts":1553663250.9369354,"logger":"controller_clusterstorage","msg":"Reconciling ConfigMap","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1"}
{"level":"info","ts":1553663250.9461532,"logger":"controller_clusterstorage","msg":"Skip reconcile: StorageClass already exists","Request.Namespace":"kube-system","Request.Name":"cluster-config-v1","StorageClass.Name":"gp2"}


Expected results:
The log should be in a unified format.

Comment 1 Matthew Wong 2019-04-01 16:10:30 UTC
The streamwatcher.go logs are by apimachinery logging via klog and everything else is us logging via controller-runtime's logging. Why controller-runtime decided to write their own logging library when everyone else uses klog, I have no idea, but controller-runtime is what operator-sdk uses so I think we should follow the convention even if it is a bit ugly. In general, these klog messages by underlying libraries can be ignored because anything that is meaningful will be deliberately logged by us.


Note You need to log in before you can comment on or make changes to this bug.