Do not log in log library by bobcatfish · Pull Request #1364 · knative/serving

bobcatfish · 2018-06-26T23:44:03Z

Okay this is a lot repeated code, but hear me out! When you log in
a library, it means the caller has no control over whether those
logs are emitted or not - case in point, the e2e tests are using this
library, and now they dump the json config and log level at the
beginning of every test, which we don't want and can't control.

This commit changes the logging lib such that it's the caller's
responsibility to decide whether to log or not.

Also open to ideas that involve less code duplication, e.g. a(nother) wrapper that logs, such that the interface includes functions which log and functions which do not log.)
Another option is to have the e2e tests use zap directly instead of using the knative logging lib.)

This is what the test output looks like before this change, in verbose mode:

In the default mode:

Proposed Changes

Remove code that actual logs from the log library
Update users of the log library to log info about initializing the logger

NONE

google-prow-robot · 2018-06-26T23:44:07Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: bobcatfish
To fully approve this pull request, please assign additional approvers.
We suggest the following additional approver: mattmoor

Assign the PR to them by writing /assign @mattmoor in a comment when ready.

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

The pull request process is described here

Details

Needs approval from an approver in each of these files:

OWNERS

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

bobcatfish · 2018-06-27T00:29:10Z

pkg/logging/config.go | 77.8% | 76.0% | -1.8

squinty eyes

dprotaso · 2018-06-27T04:17:48Z

 	proxy.ServeHTTP(w, r)
 }

+func _initializeLogging() *zap.SugaredLogger {


I'd suggest dropping the underscore since it's not really a style I see in go

face palm my bad!

dprotaso · 2018-06-27T04:18:47Z

-	logger.Error("Failed to parse the logging config. Falling back to default logger.", zap.Error(err), zap.String(logkey.JSONConfig, configJSON))
-	return logger.Sugar()
+	errStr := fmt.Sprintf("Failed to parse the logging config. Falling back to default logger. Error: %s. Config: %s", err, configJSON)
+	return logger.Sugar(), errors.New(errStr)


fmt.Errorf will combine your fmt.Sprintf and errors.New

dprotaso · 2018-06-27T04:25:39Z


+func _initializeLogging() *zap.SugaredLogger {
+	configJSON, levelOverride := logging.LoggerDefaultConfigMap("loglevel.activator")
+	genericLogger, err := logging.NewLogger(configJSON, levelOverride)


Maybe we could simplify the interface a bit more so we only make one call to the logging pkg to instantiate a configured logger.

ie.

logger, err := logging.NewLoggerFromConfig("loglevel.activator")

then maybe _initializeLogging is small enough to inline it into main() ?

I'd like to change the assumption this package makes about the config being mounted at /etc/config-logging as well. @mdemirhan thoughts?

Context: #1351

I am all for removing the dependency on the etc/config-logging. It was meant as a helper to reduce the copy/paste between all main.go files.

@bobcatfish The changes look good to me. The duplication hurts the eyes, but if it is going to make things better for tests, I am all for it. Can the new "initializeLogging" not be generalized enough so that we avoid duplication? Alternatively, passing a "do not log" flag to the existing NewLoggerFromXXX method could achieve the same thing and tests can use that flag when initializing its loggers.

evankanderson · 2018-06-27T17:14:53Z

/assign @dprotaso
/assign @mattmoor

bobcatfish · 2018-06-27T22:56:38Z

+	}
+	defer logger.Sync()
+	return logger
+>>>>>>> Do not log in log library


ho boy 😅

bobcatfish · 2018-06-27T23:01:27Z

YUUUUSSSSSS

bobcatfish · 2018-06-27T23:02:04Z

+	}
+}
+
+func writeConfig(dir, key, value string) {


copied @josephburnett 's unit tests for k8sflag here ;)

bobcatfish · 2018-06-27T23:03:21Z

Okay so:

Used @dprotaso 's suggestion to make a slightly more sophisticated function in logging.go, reducing the duplicate code
I dropped the Debug line that logs the logging config b/c it messes up the interface BUT if you all feel strongly I will put it back

@mdemirhan @mattmoor @dprotaso PTAL

bobcatfish · 2018-06-27T23:04:21Z


+// DefaultLoggingConfigPath is the path where the zap logging
+// config will be written in a default Knative deployment.
+const DefaultLoggingConfigPath = "/etc/config-logging"


@mattmoor let me know if you wanted me to do something more specific re 'not relying on /etc/config-logging'

dprotaso · 2018-06-28T01:54:47Z

 	// No good way to test if all the config is applied,
 	// but at the minimum, we can check and see if level is getting applied.
-	logger = NewLogger("{\"level\": \"error\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "")
+	logger, err := NewLogger("{\"level\": \"error\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "")


since you're changing a few NewLogger calls in these tests can you clean up all the escaping by using raw strings

dprotaso · 2018-06-28T01:58:45Z

+
+	logger, err := NewDefaultConfigMapLogger(dir, "myfoo")
+	if err == nil {
+		t.Error("expecte error when creating logger from invalid config file")


dprotaso · 2018-06-28T02:01:45Z

+func TestNewDefaultConfigMapLogger(t *testing.T) {
+	dir, err := ioutil.TempDir("", "")
+	if err != nil {
+		panic(err)


using t.Fatal in these tests instead of panic will cause this to log to the test output buffer

oh yeah, way better thanks!

dprotaso · 2018-06-28T02:05:12Z

 	}`
 	configJSON := fmt.Sprintf(configJSONTemplate, logLevel)
-	return logging.NewLogger(string(configJSON), logLevel)
+	logger, err := logging.NewLogger(string(configJSON), logLevel)


with the line change can you remove the unnecessary cast string(configJSON)

nice catch, thanks!

dprotaso · 2018-06-28T02:17:29Z

+// NewDefaultConfigMapLogger creates a logging object for the
+// for the logLevelKey within configPath corresponding
+// to the provided componentKey.
+func NewDefaultConfigMapLogger(configPath string, componentKey string) (*zap.SugaredLogger, error) {


Given there is a default config path we can simplify the usability of this function a bit more by making configPath optional. Maybe it makes sense to name this function NewComponentLogger now?

ie.

func NewComponentLogger(componentKey string, configPath ...string) (*zap.SugaredLogger, error) { conf := DefaultLoggingConfigPath if len(configPath) > 0 { conf = configPath[0] } ... }

then the usage would simplified to

if logger, err := logging.NewComponentLogger("webhook"); err != nil { logger.Errorf("Error initializing logger: %s", err) }

thanks for letting me know about this! i didn't know about variadic functions in Go!

however after looking into it a bit, I'm not sure I like the idea of using them for this optional params and here is an example of why. The TL;DidntRun is the fact that using a variadic args means callers can start passing you incorrect arguments have you have to either check and make sure they're not doing that explicitly or allow the weird extra arguments to silently not do anything, and neither option seems great

Yup it's dirty - would you settle on having two New* functions

ie.

func NewComponentLogger(componentKey string) (*zap.SugaredLogger, error) { return NewComponentLoggerFromConfig(componentKey, DefaultLoggingConfigPath) } func NewComponentLoggerFromConfig(componentKey, configPath string) (*zap.SugaredLogger, error) { ... }

Okay this is slightly more repeated code, but hear me out! When you log in a library, it means the caller has no control over whether those logs are emitted or not - case in point, the e2e tests are using this library, and now they dump the json config and log level at the beginning of every test, which we don't want and can't control. This commit changes the `logging` lib such that it's the caller's responsibility to decide whether to log or not. This also changes the logic such that the logging configuration is no longer logged at debug.

bobcatfish · 2018-06-28T18:33:06Z

Ready for another round! PTAL @dprotaso @mattmoor @mdemirhan

knative-metrics-robot · 2018-06-28T18:37:48Z

The following is the coverage report on pkg/. Say /test pull-knative-serving-go-coverage to run the coverage report again

File	Old Coverage	New Coverage	Delta
pkg/logging/config.go	77.8%	92.9%	15.1

*TestCoverage feature is being tested, do not rely on any info here yet

bobcatfish · 2018-06-28T18:58:53Z

/test pull-knative-serving-integration-tests

google-prow-robot · 2018-06-28T19:20:21Z

@bobcatfish: The following test failed, say /retest to rerun them all:

Test name	Commit	Details	Rerun command
pull-knative-serving-integration-tests	`274973a`	link	`/test pull-knative-serving-integration-tests`

Full PR test history. Your PR dashboard.

Details

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.

bobcatfish · 2018-06-28T22:37:01Z

Oh neat I think I actually broke something :D AND THE TESTS CAUGHT IIIIIT

mattmoor · 2018-06-29T15:08:45Z

@bobcatfish FYI, my change to refactor the way we load things (to not be in the library!) landed. LMK when this is RFAL.

mattmoor · 2018-07-12T19:42:05Z

/hold

Wait until after we cut first release.

@bobcatfish Are you going to come back to this PR?

mattmoor · 2018-07-19T03:58:51Z

I'm going to close this out. Feel free to reopen, if it's still relevant.

bobcatfish · 2018-07-19T23:41:05Z

Yeah looks like I'm not going to be able to get back to this, esp. since the logging libs have changed significantly since I've last looked, thanks for closing it @mattmoor

I HAVE FAILED YOU @jonjohnsonjr :'(

I've created #1630 so hopefully someone can look into this in the future.

bobcatfish requested review from jessiezcc, jonjohnsonjr and mdemirhan June 26, 2018 23:44

google-prow-robot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Jun 26, 2018

dprotaso reviewed Jun 27, 2018

View reviewed changes

google-prow-robot assigned dprotaso and mattmoor Jun 27, 2018

bobcatfish force-pushed the logging_in_log_lib branch 3 times, most recently from e7f10da to 4cd6bc4 Compare June 27, 2018 22:56

bobcatfish commented Jun 27, 2018

View reviewed changes

bobcatfish force-pushed the logging_in_log_lib branch from 4cd6bc4 to 441ef04 Compare June 27, 2018 23:00

bobcatfish commented Jun 27, 2018

View reviewed changes

dprotaso reviewed Jun 28, 2018

View reviewed changes

bobcatfish force-pushed the logging_in_log_lib branch from 441ef04 to 3dd0776 Compare June 28, 2018 18:28

bobcatfish force-pushed the logging_in_log_lib branch from 3dd0776 to 274973a Compare June 28, 2018 18:32

google-prow-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jul 12, 2018

mattmoor closed this Jul 19, 2018

dprotaso mentioned this pull request Jun 19, 2019

Add @dprotaso as a serving approver #4426

Merged

Conversation

bobcatfish commented Jun 26, 2018

Proposed Changes

Uh oh!

google-prow-robot commented Jun 26, 2018

Uh oh!

bobcatfish commented Jun 27, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

evankanderson commented Jun 27, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bobcatfish commented Jun 27, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bobcatfish commented Jun 27, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dprotaso Jun 28, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dprotaso Jun 28, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bobcatfish commented Jun 28, 2018

Uh oh!

knative-metrics-robot commented Jun 28, 2018

Uh oh!

bobcatfish commented Jun 28, 2018

Uh oh!

google-prow-robot commented Jun 28, 2018

Uh oh!

bobcatfish commented Jun 28, 2018

Uh oh!

mattmoor commented Jun 29, 2018

Uh oh!

mattmoor commented Jul 12, 2018

Uh oh!

mattmoor commented Jul 19, 2018

Uh oh!

dprotaso Jun 28, 2018 •

edited

Loading

dprotaso Jun 28, 2018 •

edited

Loading