Migrate to zap logger #223

prydie · 2018-07-31T10:54:52Z

Migrates logging from to go.uber.org/zap from github.com/golang/glog and adds the following flags:

--log-level=debug  # control log level
--log-json  # output log as json
--logfile-path  # if provided reload

❯ dist/oci-cloud-controller-manager         \
    --kubeconfig=${KUBECONFIG}              \
    --cloud-config=${CLOUD_PROVIDER_CFG}    \
    --cluster-cidr=10.244.0.0/16            \
    --leader-elect-resource-lock=configmaps \
    --cloud-provider=oci                    \
    --log-json                              \
    --logfile-path="test.log" &
❯ head -n 1 test.log
{"level":"info","ts":"2018-07-31T09:54:33.504+0100","caller":"oci/ccm.go:220","msg":"Using raw configuration provider"}

prydie · 2018-07-31T11:45:34Z

@templecloud do you have any insight into why the e2e tests are failing (I've merged your branch and rebased on top)?

jhorwit2 · 2018-08-07T14:13:53Z

pkg/log/log.go

+)
+
+func init() {
+	flag.StringVar(&lvlString, "log-level", lvlString, "Adjusts the level of the logs that will be omitted.")


This can be cleaned up.

var ( lvl = zapcore.InfoLevel logJSON = true config *zap.Config mu sync.Mutex ) func init() { flag.Var(&lvl, "log-level", "Adjusts the level of the logs that will be omitted.") flag.BoolVar(&logJSON, "log-json", logJSON, "Log in json format.") } .... config.Level.SetLevel(lvl)

zapcore.Level is a int8 though. Doesn't that required --log-level=0 vs --log-level=info?

That's why it's a Var. You'd pass strings. The level implements the flag interface https://github.com/uber-go/zap/blob/master/zapcore/level.go

TIL there's a flag interface. Cheers 👍

jhorwit2 · 2018-08-07T14:15:41Z

pkg/log/log.go

+		cfg = zap.NewProductionConfig()
+	}
+
+	if len(logfilePath) > 0 {


how does rotation work?

I mistakenly presumed filebeat would handle that for us. I guess I should add support for log rotation via https://github.com/natefinch/lumberjack?

potentially? I was more so just curious how it works. If OKE is handling it with filebeat then that's fine.

As far as I understand it Filebeat doesn't actually support log rotation though hence my suggestion we do it at the application level.

jhorwit2 · 2018-08-07T14:18:08Z

pkg/oci/client/compute.go

@@ -106,14 +105,19 @@ func (c *client) GetPrimaryVNICForInstance(ctx context.Context, compartmentID, i

 		for _, attachment := range resp.Items {
 			if attachment.LifecycleState != core.VnicAttachmentLifecycleStateAttached {
-				glog.Infof("VNIC attachment %q for instance %q has a state of %q (not %q)",
-					*attachment.Id, instanceID, attachment.LifecycleState, core.VnicAttachmentLifecycleStateAttached)
+				c.logger.With(


You should create a context logger at the beginning of this method call with instance (and maybe compartment id) as fields.

jhorwit2 · 2018-08-07T14:19:06Z

pkg/oci/client/compute.go

+					"vnicAttachmentID", *attachment.Id,
+					"expectedLifecycleState", core.VnicAttachmentLifecycleStateAttached,
+					"actualLifecycleState", attachment.LifecycleState,
+				).Info("VNIC attachment in unexpected lifecycle state")


personally i'd just have the log msg as "VNIC attachment is not in attached state" and remove the expected msg.

jhorwit2 · 2018-08-07T14:21:11Z

pkg/oci/instances.go

@@ -96,7 +96,7 @@ func (cp *CloudProvider) NodeAddresses(ctx context.Context, name types.NodeName)
 // nodeaddresses are being queried. i.e. local metadata services cannot be used
 // in this method to obtain nodeaddresses.
 func (cp *CloudProvider) NodeAddressesByProviderID(ctx context.Context, providerID string) ([]api.NodeAddress, error) {
-	glog.V(4).Infof("NodeAddressesByProviderID(%q) called", providerID)
+	cp.logger.Debugf("NodeAddressesByProviderID(%q) called", providerID)


These types of log messages are largely useless imo. It'd be more useful to say

cp.logger.With("providerID", providerID).Debug("fetching node addresses by provider id")

jhorwit2 · 2018-08-07T14:22:04Z

pkg/oci/load_balancer.go

@@ -201,9 +202,10 @@ func (cp *CloudProvider) readSSLSecret(svc *v1.Service) (string, string, error)
 // balancer, if it doesn't already exist.
 func (cp *CloudProvider) ensureSSLCertificate(ctx context.Context, lb *loadbalancer.LoadBalancer, spec *LBSpec) error {
 	name := spec.SSLConfig.Name
+	logger := cp.logger.With("certificateName", name, "loadbalancerName", *lb.DisplayName)


I feel we should change this to always use ocid and not display names.

I believe we always add the ocid as soon as we have it; just including display name as we often have that prior to getting an ocid. Thoughts?

jhorwit2 · 2018-08-07T14:23:41Z

pkg/oci/load_balancer.go

@@ -267,7 +270,7 @@ func (cp *CloudProvider) createLoadBalancer(ctx context.Context, spec *LBSpec) (
 		Certificates:  certs,
 	}

-	glog.V(4).Infof("CreateLoadBalancerDetails: %#v", details.String())
+	logger.With("details", details).Debug("CreateLoadBalancerDetails")


This is gonna be a HUGE log message.... What if the cluster has 500+ nodes? Heck even 20 nodes would be a lot for this haha.

jhorwit2 · 2018-08-07T14:23:54Z

pkg/oci/load_balancer.go

@@ -283,16 +286,16 @@ func (cp *CloudProvider) createLoadBalancer(ctx context.Context, spec *LBSpec) (
 		return nil, errors.Wrapf(err, "get load balancer %q", *wr.LoadBalancerId)
 	}

-	glog.Infof("Created load balancer %q with OCID %q", *lb.DisplayName, *lb.Id)
+	logger.With("loadbalancerID", *lb.Id).Info("Loadbalancer created")


load balancer

jhorwit2 · 2018-08-07T14:24:46Z

pkg/oci/load_balancer.go

@@ -364,7 +367,7 @@ func (cp *CloudProvider) updateLoadBalancer(ctx context.Context, lb *loadbalance
 		return errors.Wrap(err, "get subnets for nodes")
 	}

-	actions := sortAndCombineActions(backendSetActions, listenerActions)
+	actions := sortAndCombineActions(cp.logger, backendSetActions, listenerActions)


This and the one above should be context loggers I think w/ at a very minimum the lb id / service name/namespace / something.

jhorwit2 · 2018-08-07T14:24:57Z

pkg/oci/load_balancer.go

@@ -403,7 +406,7 @@ func (cp *CloudProvider) updateBackendSet(ctx context.Context, lbID string, acti
 		ports         = action.Ports
 	)

-	glog.V(2).Infof("Applying %q action on backend set %q for lb %q (ports=%+v)", action.Type(), action.Name(), lbID, ports)
+	cp.logger.Infof("Applying %q action on backend set %q for lb %q (ports=%+v)", action.Type(), action.Name(), lbID, ports)


action stuff should be fields.

lb id should be on the logger already. it gets to be super complex/annoying if we need to add the same fields every where down the call stack.

jhorwit2 · 2018-08-07T14:27:12Z

what happens to the existing glog flags around files that never worked?

prydie · 2018-08-07T18:04:09Z

@jhorwit2 Do you think it's worth adding no-op flags for the old glog flags for compat. or given they never worked can we just drop them (with a note in the CHANGELOG)?

jhorwit2 · 2018-08-07T19:29:12Z

pkg/oci/ccm.go

-	cp, err := buildConfigurationProvider(config)
+	logger := logutil.Logger()
+	defer logger.Sync()
+	zap.ReplaceGlobals(logger)


Replacing it here means there will be logs emitted not following this logger since the CCM itself logs plus other various global things.

Would you suggest swapping out the logger in func main() then?

prydie · 2018-08-08T16:04:06Z

@jhorwit2 My attempt at moving the logger override func main() resulted in the glog logs going to stderr and rather than respecting logger config and writing to file.

owainlewis · 2018-08-09T13:40:34Z

Awaiting a +1 review from @jhorwit2

jhorwit2 · 2018-08-10T14:03:45Z

@prydie do you know why? that seems odd.

prydie · 2018-08-13T09:24:26Z

@jhorwit2 I was previously creating a new logger in both main.go and ccm.go rather than grabbing a reference.

I'm not overly keen on how I'm getting that reference now but it's working:

2018-08-13T10:16:58.389+0100    INFO    oci-cloud-controller-manager/main.go:59 oci-cloud-controller-manager    {“version”: “0.1.2-94-g91c5b388-dirty”, “build”: “0.1.2-94-g91c5b388-dirty”}
2018-08-13T10:16:58.389+0100    INFO    flag/flags.go:27        FLAG: --address=“0.0.0.0”
2018-08-13T10:16:58.389+0100    INFO    flag/flags.go:27        FLAG: --allocate-node-cidrs=“false”
2018-08-13T10:16:58.389+0100    INFO    flag/flags.go:27        FLAG: --allow-untagged-cloud=“false”

Setting env vars in the form LOG_VAR_field_name=value now adds fields fields to the logger (e.g. zap.String("field_name", "value") in this example).

jhorwit2 · 2018-08-14T12:58:56Z

pkg/logging/logging.go

@@ -61,7 +63,15 @@ func Logger() *zap.Logger {
 		cfg = zap.NewProductionConfig()
 	}

-	options := []zap.Option{zap.AddStacktrace(zapcore.FatalLevel)}
+	// Extract log fields from environment variables.


What's the need for this? Won't filebeat/fluentd/< insert log shipper > do that for you?

jhorwit2 · 2018-08-14T15:03:11Z

lgtm

jhorwit2 · 2018-08-14T15:03:44Z

Actually @prydie could you please update the README for docs on this?

prydie · 2018-08-15T12:03:42Z

@jhorwit2 I'm going to merge and create an issue for a broader effort to improve documentation.

prydie requested review from owainlewis and jhorwit2 July 31, 2018 10:54

prydie added the enhancement label Jul 31, 2018

prydie force-pushed the ap/zap branch 3 times, most recently from 895c1fb to ee4cba7 Compare July 31, 2018 11:20

owainlewis added the needs-approval label Jul 31, 2018

prydie force-pushed the ap/zap branch from 5676c64 to 9d6b379 Compare August 2, 2018 13:23

owainlewis removed the needs-approval label Aug 2, 2018

prydie force-pushed the ap/zap branch from 912fd6a to 5e71b61 Compare August 2, 2018 15:27

owainlewis self-assigned this Aug 3, 2018

owainlewis approved these changes Aug 3, 2018

View reviewed changes

prydie force-pushed the ap/zap branch from 5e71b61 to 437af3a Compare August 7, 2018 14:06

prydie added 2 commits August 7, 2018 15:11

Update dependencies

83306fc

Replace glog with zap

17c1e34

prydie force-pushed the ap/zap branch from 437af3a to 17c1e34 Compare August 7, 2018 14:11

jhorwit2 suggested changes Aug 7, 2018

View reviewed changes

Code review comments

d328d6b

jhorwit2 reviewed Aug 7, 2018

View reviewed changes

Tidy up log log lvl flag

525765d

prydie force-pushed the ap/zap branch from ec99f4a to c94030e Compare August 8, 2018 11:51

Debug logs in e2e tests

18243d8

prydie force-pushed the ap/zap branch from c94030e to 18243d8 Compare August 8, 2018 13:06

prydie added 3 commits August 8, 2018 14:52

Override logger in func main()

bed0080

Use lumberjack to implement log rotation

50fc260

Revert moving logger replacement to func main()

1b307e0

prydie added 2 commits August 9, 2018 11:47

Replace vendored glog

02e6b01

Remove -v flag as glog replacement declares flag

91c5b38

prydie added the needs-approval label Aug 9, 2018

owainlewis removed the needs-approval label Aug 9, 2018

Move logger back to main

ebc75f5

prydie added 2 commits August 13, 2018 10:27

Fix e2e tests

9347ab1

Add support for setting log fields from env vars

a78362b

Setting env vars in the form LOG_VAR_field_name=value now adds fields fields to the logger (e.g. zap.String("field_name", "value") in this example).

prydie force-pushed the ap/zap branch from 1029bd8 to a78362b Compare August 13, 2018 12:02

prydie added this to the 0.6.0 milestone Aug 14, 2018

jhorwit2 reviewed Aug 14, 2018

View reviewed changes

jhorwit2 approved these changes Aug 14, 2018

View reviewed changes

prydie merged commit 2040fd6 into master Aug 15, 2018

prydie deleted the ap/zap branch August 15, 2018 12:04

ayushverma14 pushed a commit to ayushverma14/oci-cloud-controller-manager that referenced this pull request Jul 18, 2022

Migrate to zap logger (oracle#223)

f8df023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Migrate to zap logger #223

Migrate to zap logger #223

prydie commented Jul 31, 2018

prydie commented Jul 31, 2018

jhorwit2 Aug 7, 2018

prydie Aug 7, 2018

jhorwit2 Aug 7, 2018

prydie Aug 8, 2018

jhorwit2 Aug 7, 2018

prydie Aug 7, 2018

jhorwit2 Aug 7, 2018

prydie Aug 8, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

prydie Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 Aug 7, 2018

jhorwit2 commented Aug 7, 2018

prydie commented Aug 7, 2018

jhorwit2 Aug 7, 2018

prydie Aug 8, 2018

jhorwit2 Aug 8, 2018

prydie commented Aug 8, 2018

owainlewis commented Aug 9, 2018

jhorwit2 commented Aug 10, 2018

prydie commented Aug 13, 2018

jhorwit2 Aug 14, 2018 •

edited

Loading

jhorwit2 commented Aug 14, 2018

jhorwit2 commented Aug 14, 2018

prydie commented Aug 15, 2018

Migrate to zap logger #223

Migrate to zap logger #223

Conversation

prydie commented Jul 31, 2018

prydie commented Jul 31, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jhorwit2 commented Aug 7, 2018

prydie commented Aug 7, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prydie commented Aug 8, 2018

owainlewis commented Aug 9, 2018

jhorwit2 commented Aug 10, 2018

prydie commented Aug 13, 2018

jhorwit2 Aug 14, 2018 • edited Loading

Choose a reason for hiding this comment

jhorwit2 commented Aug 14, 2018

jhorwit2 commented Aug 14, 2018

prydie commented Aug 15, 2018

jhorwit2 Aug 14, 2018 •

edited

Loading