Add a ZapMapLogger for logging without duplicate entries #94
Conversation
…the remarshalled log entry effectively catching duplicte fields
Generate changelog in
|
|
The PR states that this provider is added as a demonstration. Can you expand a bit on the goal of getting this merged? If this is for doing some experimentation/benchmarking, then would prefer for that to be done on a fork if possible. If this is going to be merged, then would like to understand how it's being thought of as a first-class implementation (and to get context on why this is being implemented on |
|
@nmiyake I have an RFC going into detail on why we should make this change. I initially started this as a demonstration and wanted to use the PR to easily demonstrate the changes required. I already tagged Brad but I will also tag you in the RFC so you can take a look. I would like to get comments from you and other maintainers here and we can decide whether this is the right approach and whether this fork can be modified to accommodate any comments from the maintainers. |
There was a problem hiding this comment.
Reviewed 93 of 96 files at r1, 2 of 2 files at r3, 1 of 1 files at r4.
Reviewable status: all files reviewed, 5 unresolved discussions (waiting on @smoorpal)
go.mod, line 1 at r4 (raw file):
module github.com/smoorpal/witchcraft-go-logging
revert changes to this file before merging
wlog/svclog/svc1log/svc1logtests/tests.go, line 403 at r4 (raw file):
benchmarkCases := make([]TestCase,0,len(testCases)) for _, testCase := range testCases { if testCase.Name!="duplicate origin" && testCase.Name!="parameter that is set manually overrides base value" {
why can't we benchmark these?
wlog/svclog/svc1log/svc1logtests/tests.go, line 460 at r4 (raw file):
require.NoError(t, err, "Case %d: %s\nService log line is not a valid map: %v", i, tc.Name, string(logEntry)) logEntryRewrite, err := safejson.Marshal(gotServiceLog) assert.Equal(t, len(strings.TrimRight(string(logEntry),"\n")), len(string(logEntryRewrite)), "log line is not stable. Differing length on remarshal")
some of these are failing, do we know why?
wlog/svclog/svc1log/svc1logtests/tests.go, line 557 at r4 (raw file):
b.ResetTimer() for i := 0; i<b.N; i++ { buf.Truncate(0)
use buf.Reset()
wlog-zap/internal/logger.go, line 29 at r4 (raw file):
) type zapMapLogEntry struct {
We'll probably (also) want a zerolog implemenation - did you look into ways to implement this in wlog so it can be used by all logger implementations?
There was a problem hiding this comment.
Reviewable status: all files reviewed, 5 unresolved discussions (waiting on @bmoylan and @smoorpal)
wlog/svclog/svc1log/svc1logtests/tests.go, line 403 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
why can't we benchmark these?
These tests currently produce errors for the new implementation of the logger and I don't believe the benchmarks will register if there is a failed test. We need to fix these tests in the course of submitting this PR now that we know the issue with parsing duplicate fields.
wlog/svclog/svc1log/svc1logtests/tests.go, line 460 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
some of these are failing, do we know why?
I use this to check if the logger will print duplicate lines. This fails when the existing logger is used and the log entry has duplicate parameters.
wlog/svclog/svc1log/svc1logtests/tests.go, line 557 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
use
buf.Reset()
Done.
|
@bmoylan I only see zerolog used in one application the logproxy owned by devtools. We could request them to switch to wlog-zap and deprecate wlog-zerlog. https://github.palantir.build/search?q=wlog-zerolog&type=Code |
…ntation of parameters the only logger provider
|
I looked at this more. Its going to be difficult to deduplicate zerolog at the moment without losing the performance and memory improvements associated with it. I think we should consider releasing the change to wlog-zap which a great majority of applications are using and either deprecate or remove zerolog until we have a solution which will allow us to keep the improvements in caelumd and rubixbeat. |
|
One option I can explore for deduplicating zero-log would be to reverse the array of params before they are applied to the zeroLogEntry. Then on each application of a |
…to avoid printing zerolog info level. All levels for zerolog are printed at the beginning of the message and use a lowercase enum. This lowercase is inconsistent with sls defined uppercase enums. Each field key should only appear once so we must print the correctly capitalized level names at the time that we apply params
…ammer error and should be resolved there
wlog/context_default_test.go
Outdated
| regexp.QuoteMeta(`[WARNING] github.com/palantir/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/palantir/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `)) | ||
| firstPortionRegexp, err := regexp.Compile( | ||
| regexp.QuoteMeta(`[WARNING]`) + ".*" + regexp.QuoteMeta(`github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `)) | ||
| require.NoError(t, err, "Unexpected error compiling regex") |
There was a problem hiding this comment.
This was modified so that people testing on a fork do not look for the specific path that depends on not being a fork. i.e. github.com/[^/]+/witchcraft-go-logging is valid.
| @@ -310,7 +311,61 @@ something/something:123`, | |||
| }), | |||
| }), | |||
| }, | |||
| { | |||
There was a problem hiding this comment.
I removed the duplicate safe param test because we are considering this a user error. This is the policy decided for Java. If a user adds duplicate safe params then their line will eventually not be parsed or result in a performance hit when falling back. Zerolog is difficult to enforce this and probably not worth it since you have to reverse all parameters being applied to it to catch the few bad actors.
| @@ -362,6 +417,9 @@ func jsonOutputTests(t *testing.T, loggerProvider func(w io.Writer, level wlog.L | |||
| logEntry := buf.Bytes() | |||
| err := safejson.Unmarshal(logEntry, &gotServiceLog) | |||
| require.NoError(t, err, "Case %d: %s\nService log line is not a valid map: %v", i, tc.Name, string(logEntry)) | |||
| logEntryRewrite, err := safejson.Marshal(gotServiceLog) | |||
There was a problem hiding this comment.
This set of assertions parses the printed service log and rewrites it. If the bytes are not the same length then duplicate fields must have been printed.
There was a problem hiding this comment.
Reviewable status: 0 of 7 files reviewed, 8 unresolved discussions (waiting on @bmoylan)
go.mod, line 1 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
revert changes to this file before merging
Done.
wlog-zap/internal/logger.go, line 29 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
We'll probably (also) want a zerolog implemenation - did you look into ways to implement this in wlog so it can be used by all logger implementations?
Done.
|
|
There was a problem hiding this comment.
Reviewed 4 of 97 files at r6, 1 of 2 files at r7, 3 of 5 files at r8, 1 of 1 files at r9, 1 of 1 files at r10.
Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @smoorpal)
wlog/context_default_test.go, line 177 at r8 (raw file):
Previously, smoorpal wrote…
This was modified so that people testing on a fork do not look for the specific path that depends on not being a fork. i.e.
github.com/[^/]+/witchcraft-go-loggingis valid.
In general we'd recommend using git remotes for working on forks instead of a different module name/location. If we have to go this route I'd replace .* with [^/]+ just to be a little more specific.
wlog/svclog/svc1log/svc1logtests/tests.go, line 403 at r4 (raw file):
Previously, smoorpal wrote…
These tests currently produce errors for the new implementation of the logger and I don't believe the benchmarks will register if there is a failed test. We need to fix these tests in the course of submitting this PR now that we know the issue with parsing duplicate fields.
do these still need to be ignored?
wlog/svclog/svc1log/svc1logtests/tests.go, line 314 at r8 (raw file):
Previously, smoorpal wrote…
I removed the duplicate safe param test because we are considering this a user error. This is the policy decided for Java. If a user adds duplicate safe params then their line will eventually not be parsed or result in a performance hit when falling back. Zerolog is difficult to enforce this and probably not worth it since you have to reverse all parameters being applied to it to catch the few bad actors.
Doesn't this happen in practice if I have a param set on a context and then override that param at the log site? E.g.
ctx := wparams.ContextWithSafeParam(ctx, "key", "value1")
svc1log.FromContext(ctx).Info("msg", svc1log.SafeParam("key", "value2")I think this is common enough that we should handle it, but because params are stored in a map we should get it for free, no?
wlog/svclog/svc1log/svc1logtests/tests.go, line 420 at r8 (raw file):
Previously, smoorpal wrote…
This set of assertions parses the printed service log and rewrites it. If the bytes are not the same length then duplicate fields must have been printed.
Could you add this context to the assert message below? Something like Differing length on remarshal, possibly due to duplicate keys in the original payload
wlog/svclog/svc1log/svc1logtests/tests.go, line 508 at r10 (raw file):
} func JSONBenchmarkSuite(b *testing.B, loggerProvider func(w io.Writer, level wlog.LogLevel, origin string) svc1log.Logger) {
How are these different than https://github.com/palantir/witchcraft-go-logging/blob/develop/benchmarks/benchmark_test.go?
wlog-zerolog/internal/logger.go, line 35 at r10 (raw file):
func (e *zeroLogEntry) keyExists(key string) bool { if i, exists := e.keys[key]; exists { e.keys[key] = i + 1
Are these int values used anywhere? I see us counting the occurrences but never using those counts. Could this map be replaced by a simpler map[string]struct{}?
wlog-zerolog/internal/logger.go, line 163 at r10 (raw file):
} func reverseParams(params []wlog.Param) []wlog.Param {
nit: maybe better to not have a return value to make it clearer that this is happening in-place
…context for each type of logger
…e passed in and reversed. We would like the last paramater to stay so if the params are reversed we should avoid overriding a key that already exists.
There was a problem hiding this comment.
Reviewable status: 3 of 7 files reviewed, 5 unresolved discussions (waiting on @bmoylan)
wlog/context_default_test.go, line 177 at r8 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
In general we'd recommend using git remotes for working on forks instead of a different module name/location. If we have to go this route I'd replace
.*with[^/]+just to be a little more specific.
Added more specific regex.
wlog/svclog/svc1log/svc1logtests/tests.go, line 403 at r4 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
do these still need to be ignored?
I removed the benchmarks I have added to this file. Everything I was trying to do is encapsulated in the top level benchmarks directory. This directory benchmarks all test suites and includes the referenced tests without problem.
wlog/svclog/svc1log/svc1logtests/tests.go, line 314 at r8 (raw file):
ContextWithSafeParam
Interesting. I wasn't aware that params were stored when the logger was created like this. I expanded wlog/svc1log/context_test.go in order to test each type of logger when parameters are added to the context and when they overwrite the context params. In order to do this I had to take out the AnyMap implementation in zerolog and replace it with something specific. Now that parameters are passed in reverse we want to avoid setting a safe/unsafe param if it is already set.
wlog/svclog/svc1log/svc1logtests/tests.go, line 508 at r10 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
How are these different than https://github.com/palantir/witchcraft-go-logging/blob/develop/benchmarks/benchmark_test.go?
They are not. I wrote something special to compare the map implementation and have now removed it.
wlog-zerolog/internal/logger.go, line 35 at r10 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
Are these int values used anywhere? I see us counting the occurrences but never using those counts. Could this map be replaced by a simpler
map[string]struct{}?
Yep makes sense. Done.
There was a problem hiding this comment.
Reviewable status: 3 of 7 files reviewed, 3 unresolved discussions (waiting on @bmoylan)
wlog/svclog/svc1log/svc1logtests/tests.go, line 403 at r4 (raw file):
Previously, smoorpal wrote…
I removed the benchmarks I have added to this file. Everything I was trying to do is encapsulated in the top level benchmarks directory. This directory benchmarks all test suites and includes the referenced tests without problem.
Done.
wlog/svclog/svc1log/svc1logtests/tests.go, line 508 at r10 (raw file):
Previously, smoorpal wrote…
They are not. I wrote something special to compare the map implementation and have now removed it.
Done.
wlog-zerolog/internal/logger.go, line 35 at r10 (raw file):
Previously, smoorpal wrote…
Yep makes sense. Done.
Done.
There was a problem hiding this comment.
Reviewed 4 of 5 files at r11.
Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @smoorpal)
wlog/svclog/svc1log/svc1logtests/tests.go, line 360 at r11 (raw file):
} func BenchmarkCases() []TestCase {
looks like this is no longer used
wlog-zerolog/internal/logger.go, line 107 at r11 (raw file):
} func (e *zeroLogEntry) AnyMapValue(key string, values map[string]interface{}) {
Can you add a comment to these explaining how they differ from the wlog implementation?
wlog-zerolog/internal/logger.go, line 111 at r11 (raw file):
return } if len(values) == 0 {
isn't this exactly the same as the block above?
…tringMapValues in zerolog. Remove erroneous.
There was a problem hiding this comment.
Reviewable status: 5 of 7 files reviewed, 3 unresolved discussions (waiting on @bmoylan)
wlog/svclog/svc1log/svc1logtests/tests.go, line 360 at r11 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
looks like this is no longer used
Indeed. I missed removing this when I cleared out my custom benchmarks.
wlog-zerolog/internal/logger.go, line 107 at r11 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
Can you add a comment to these explaining how they differ from the wlog implementation?
Sure thing. Added. Let me know if you think its a satisfactory explanation.
wlog-zerolog/internal/logger.go, line 111 at r11 (raw file):
Previously, bmoylan (Brad Moylan) wrote…
isn't this exactly the same as the block above?
Yes. Good catch. I must have messed something up when copying the code.
There was a problem hiding this comment.
Reviewable status: 5 of 7 files reviewed, 3 unresolved discussions (waiting on @bmoylan)
wlog/svclog/svc1log/svc1logtests/tests.go, line 360 at r11 (raw file):
Previously, smoorpal wrote…
Indeed. I missed removing this when I cleared out my custom benchmarks.
Done.
wlog-zerolog/internal/logger.go, line 107 at r11 (raw file):
Previously, smoorpal wrote…
Sure thing. Added. Let me know if you think its a satisfactory explanation.
Done.
wlog-zerolog/internal/logger.go, line 111 at r11 (raw file):
Previously, smoorpal wrote…
Yes. Good catch. I must have messed something up when copying the code.
Done.
There was a problem hiding this comment.
Reviewed 2 of 2 files at r12.
Reviewable status:complete! all files reviewed, all discussions resolved
|
// holding off on merge until we've finalized the rollout plan 👎 |
|
👍 |
Before this PR
The default ZapLogger was capable of printing duplicate fields which would break certain json decoders downstream.
After this PR
==COMMIT_MSG==
wlog-zap and wlog-zerolog updated to prevent printing duplicate Params.
==COMMIT_MSG==
Possible downsides?
The expense of storing in a map may result in slightly difference performance since allocation is not as straight forward.
This change is