Refactor logging configuration #1699

charith-elastic · 2019-09-09T15:21:07Z

This change does the following:

Allow logging verbosity levels to be configured from the command-line (log.V(2) etc. should actually work as intended now)
Output the timestamp in ISO8601 format (Operator logs in unix epoch timestamps but would prefer iso8601/rfc3339 #1587)
Change log message key to message (StackDriver logging can render logs nicely if this key exists)
Change timestamp key to @timestamp
Add the ver key to report operator version in log lines
Propagate log verbosity to E2E tests

As we are currently on controller-runtime v0.1, log.InitLogger is much more complicated than it needs to be. When we migrate to controller-runtime v0.2 it can be simplified.

The suggestion in #1587 to be compatible with ECS logging format by renaming logger to log.level and level to log.level didn't seem to add much benefit at this point so I have left the shorter keys in place to aid readability.

Fixes #1587

anyasabo · 2019-09-09T23:10:53Z

pkg/utils/log/log.go

+	}
+}
+
+func getVersionString() string {


I think the pkg/controller/common/version package might be what you want here

IIRC the version package only contains functions for parsing a version string into constituent parts. I am just trying to concatenate the version string with the build hash here.

Ah yeah my bad I was translating hash to label in my head

anyasabo · 2019-09-09T23:16:12Z

Allow logging verbosity levels to be configured from the command-line (log.V(2) etc. should actually work as intended now)

Do we want to do this? I thought in #305 we had decided that we only wanted two levels of logging (debug/info), so wonder if I missed a discussion somewhere.

Change log message key to message (StackDriver logging can render logs nicely if this key exists)

👍

Change timestamp key to @timestamp

Can you clarify the reasoning for this one? Is it just so it's rather than ts?

When we migrate to controller-runtime v0.2 it can be simplified.

This might be worth waiting a week to make the change on the kubebuilder v2 feature branch IMO.

charith-elastic · 2019-09-10T07:26:15Z

Allow logging verbosity levels to be configured from the command-line (log.V(2) etc. should actually work as intended now)

Do we want to do this? I thought in #305 we had decided that we only wanted two levels of logging (debug/info), so wonder if I missed a discussion somewhere.

I wasn't aware of the that discussion, thanks for pointing it out. On several occasions I found myself wanting to output things that didn't quite fit the V(1) debug category because they were only useful for development purposes. Having a V(2) would help because then even if those log statements were left in the code accidentally, they wouldn't pollute the log output and it would be obvious to the code readers that those lines can be removed at any time.

Whether the team wants to use levels above 1 or not, I don't think there's any harm in being able to configure the output level from a flag though. WDYT?

Change timestamp key to @timestamp

Can you clarify the reasoning for this one? Is it just so it's rather than ts?

Yes, because @timestamp is a fairly well-known timestamp key than ts and some log processing systems can probably make use of it automatically without user intervention.

When we migrate to controller-runtime v0.2 it can be simplified.

This might be worth waiting a week to make the change on the kubebuilder v2 feature branch IMO.

This will continue to work on v2 it's just that it will have more configuration functions that we can use. Happy to wait if you feel this would add additional complexity to the migration.

pkg/utils/log/log.go

thbkrkr · 2019-09-10T09:42:48Z

pkg/utils/log/log.go

+	var opts []zap.Option
+	if dev.Enabled {
+		encoderConf := zap.NewDevelopmentEncoderConfig()
+		encoderConf.EncodeLevel = zapcore.CapitalColorLevelEncoder


Nice to have colors :)

pkg/utils/log/log.go

charith-elastic · 2019-09-10T10:28:21Z

Docs build is failing due to this change: elastic/docs#1172
I'll raise a separate issue to fix it.

sebgl · 2019-09-10T12:33:12Z

On several occasions I found myself wanting to output things that didn't quite fit the V(1) debug category because they were only useful for development purposes. Having a V(2) would help because then even if those log statements were left in the code accidentally, they wouldn't pollute the log output and it would be obvious to the code readers that those lines can be removed at any time.
Whether the team wants to use levels above 1 or not, I don't think there's any harm in being able to configure the output level from a flag though. WDYT?

+1 with that, I also find myself wanting a V(2) in some situations. Mostly for logs that are pure debugging (sometimes JSON dumps), which I consider different from V(1) that reports what's going on.
Also agree on how having V(2) available does not prevent us from using V(1) in most situations.

sebgl

LGTM 👍
Looking forward to the reconciliation with controller-runtime v0.2.

david-kow

One question, LGTM otherwise.

david-kow · 2019-09-10T12:58:33Z

pkg/utils/log/log.go

+
+var (
+	verbosity       = flag.Int("log-verbosity", 0, "Verbosity level of logs (-2=Error, -1=Warn, 0=Info, >0=Debug)")
+	enableDebugLogs = flag.Bool("enable-debug-logs", false, "Enable debug logs")


Is this still needed? It seems to only be used to enable the same behavior as verbosity flag does.

I mainly kept it for backward compatibility as we have documented it in the troubleshooting docs and it's much more obvious to a casual user what enable-debug-logs would do compared to log-verbosity=1

Agreed, we probably don't want multiple ways to do the same thing. But I could definitely be missing a use case

david-kow · 2019-09-10T13:47:09Z

pkg/utils/log/log.go

+		encoderConf := zap.NewProductionEncoderConfig()
+		encoderConf.MessageKey = "message"
+		encoderConf.TimeKey = "@timestamp"
+		encoderConf.EncodeTime = zapcore.ISO8601TimeEncoder


anyasabo · 2019-09-10T14:09:06Z

Makefile

@@ -76,7 +79,7 @@ dep:

 dep-vendor-only:
 	# don't attempt to upgrade Gopkg.lock
-	dep ensure --vendor-only 
+	dep ensure --vendor-only


anyasabo · 2019-09-10T14:13:57Z

Having a V(2) would help because then even if those log statements were left in the code accidentally, they wouldn't pollute the log output and it would be obvious to the code readers that those lines can be removed at any time.

I don't really run into this much personally. I think if we do want this we will probably want to update the troubleshooting or development docs to make it clear what the difference is between log levels and how to use them.

anyasabo · 2019-09-10T14:16:54Z

This will continue to work on v2 it's just that it will have more configuration functions that we can use. Happy to wait if you feel this would add additional complexity to the migration.

Ah cool, the initialization code is getting heavily reworked atm but it looks like it should just be adding a flag so I think we're good from that perspective

charith-elastic added >enhancement Enhancement of existing functionality v1.0.0-beta1 >refactoring labels Sep 9, 2019

anyasabo reviewed Sep 9, 2019

View reviewed changes

thbkrkr reviewed Sep 10, 2019

View reviewed changes

charith-elastic added 3 commits September 10, 2019 13:29

Refactor logging configuration

557f882

Address CR comments

8b29994

Set stacktrace level to error

2b4ab2a

charith-elastic force-pushed the logging branch from 635961c to 2b4ab2a Compare September 10, 2019 12:30

sebgl approved these changes Sep 10, 2019

View reviewed changes

david-kow reviewed Sep 10, 2019

View reviewed changes

anyasabo reviewed Sep 10, 2019

View reviewed changes

charith-elastic merged commit 7846324 into elastic:master Sep 11, 2019

charith-elastic deleted the logging branch September 11, 2019 07:35

charith-elastic mentioned this pull request Sep 11, 2019

Switch to controller-runtime v0.2 logging package #1708

Closed

anyasabo mentioned this pull request Sep 26, 2019

Add operator config reference #1798

Merged

sebgl mentioned this pull request Jan 28, 2020

Add the --cert-dir flag to change the directory for Webhook certificate. #2463

Closed

nvjmayo mentioned this pull request Jul 17, 2020

Use ISO 8601 format for datetime stamps in logs NVIDIA/gpu-operator#66

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor logging configuration #1699

Refactor logging configuration #1699

charith-elastic commented Sep 9, 2019

anyasabo Sep 9, 2019

charith-elastic Sep 10, 2019

anyasabo Sep 10, 2019

anyasabo commented Sep 9, 2019

charith-elastic commented Sep 10, 2019

thbkrkr Sep 10, 2019

charith-elastic commented Sep 10, 2019

sebgl commented Sep 10, 2019

sebgl left a comment

david-kow left a comment

david-kow Sep 10, 2019

charith-elastic Sep 10, 2019

anyasabo Sep 10, 2019 •

edited

Loading

david-kow Sep 10, 2019

anyasabo Sep 10, 2019

anyasabo commented Sep 10, 2019

anyasabo commented Sep 10, 2019

Refactor logging configuration #1699

Refactor logging configuration #1699

Conversation

charith-elastic commented Sep 9, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

anyasabo commented Sep 9, 2019

charith-elastic commented Sep 10, 2019

Choose a reason for hiding this comment

charith-elastic commented Sep 10, 2019

sebgl commented Sep 10, 2019

sebgl left a comment

Choose a reason for hiding this comment

david-kow left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

anyasabo Sep 10, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

anyasabo commented Sep 10, 2019

anyasabo commented Sep 10, 2019

anyasabo Sep 10, 2019 •

edited

Loading