Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging (JSON) formatting; span export #1364

Merged
merged 3 commits into from
Mar 15, 2023
Merged

Conversation

helsaawy
Copy link
Contributor

@helsaawy helsaawy commented Apr 21, 2022

Updated logrus hook to marshal structs and other type (eg, time.Time, time.Duration, []byte) as JSON
strings.

Updated span export to:

  • include span kind
  • include status code
  • log if span attributes were dropped

Additionally, added conversion that checks from common error types
(including those in containerd/containerd/errdefs) to the trace status
code (which, via convention, is a GRPC error code).

Added helper log.Format* functions to format Time and other structs
to JSON. This is already done by the logging hook, but allows spans
format their attributes consistently, since they must be converted to
strings before being exported.

Signed-off-by: Hamza El-Saawy hamzaelsaawy@microsoft.com

@helsaawy helsaawy force-pushed the he/trace-base branch 3 times, most recently from e5c4b57 to e45945c Compare April 21, 2022 20:49
@helsaawy helsaawy marked this pull request as ready for review April 21, 2022 20:58
@helsaawy helsaawy requested a review from a team as a code owner April 21, 2022 20:58
@helsaawy helsaawy force-pushed the he/trace-base branch 7 times, most recently from cb678f6 to 20b711e Compare April 27, 2022 20:18
@helsaawy helsaawy marked this pull request as draft April 27, 2022 21:57
@helsaawy helsaawy marked this pull request as ready for review May 9, 2022 17:06
@helsaawy helsaawy changed the title Log/span ctx changes; JSON formatting Logging (JSON) formatting; span export May 9, 2022
@helsaawy
Copy link
Contributor Author

rebase to remove test vendor

@helsaawy
Copy link
Contributor Author

rebased to include new CI file

internal/log/hook.go Outdated Show resolved Hide resolved
internal/log/hook.go Outdated Show resolved Hide resolved
internal/log/hook.go Outdated Show resolved Hide resolved
Added formatting for logrus export hook to marshal structs as JSON
strings, as well as format other known types (eg, time.Time).

Updated span export to:
* include span kind
* include status code
* log if span attributes were dropped

Added helper `log.Format*` functions to format Time and other structs
to JSON. This is already done by the logging hook, but allows spans
format their attributes consistently, since they must be converted to
strings before being exported.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>
@helsaawy
Copy link
Contributor Author

rebase to resolve merge conflicts with dependent PR, #1379

internal/oc/exporter.go Outdated Show resolved Hide resolved
internal/oc/exporter.go Outdated Show resolved Hide resolved
Remove unused commented out code and left-over function.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>
// (OC) Span attributes are guaranteed to be strings, bools, or int64s, so we can
// can skip overhead in entry.WithFields() and add them directly to entry.Data.
// Preallocate ahead of time, since we should add, at most, 10 additional entries
data := make(logrus.Fields, len(entry.Data)+len(s.Attributes)+10)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't necessarily need this changed, but it does seem like we're effectively copying any data items on log.L twice, once when we call Dup, and once below. Would it be better to just call Dup and then directly add any span attributes and other fields onto that entry directly? Assuming map resizes when they run out of space add a reasonable amount of extra space, I imagine we're not getting much value out of pre-creating an empty map with the final size.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Every call to .WithFields() duplicates the Data map and does additional overhead (src), but making a dedicated map and sizing it felt cleaner than modifying entry.Data directly.

I can switch if if you feel strongly about it though

@kevpar
Copy link
Member

kevpar commented Mar 14, 2023

Given how old this PR is, I'm not going to ask you to do this now, but in the future I want our team to try to split up PRs more into smaller chunks. For instance, it looks like this one would really easily split between log and oc changes, and perhaps even further.

Smaller PRs should hopefully reduce the cognitive overhead with review, which will help get them in faster. It also makes it easier if we need to revert an old change, or bisect to determine what change caused an issue.

internal/log/format.go Outdated Show resolved Hide resolved
@kevpar
Copy link
Member

kevpar commented Mar 14, 2023

Have we thought through the implications of JSON-encoding event data by default in a bunch of cases? For instance, do we or others (Howard?) have log processing that depends on the current format?

internal/log/hook.go Outdated Show resolved Hide resolved
internal/log/hook.go Outdated Show resolved Hide resolved

var _ logrus.Hook = &Hook{}

func NewHook() *Hook {
return &Hook{}
return &Hook{
EncodeAsJSON: true,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this would be a good place to consider splitting PRs in general: Adding new functionality vs turning on that functionality by default.

It's a lot easier to get in changes to add new JSON-encoding support, and keep it off by default, and then make a single, small, obvious change to turn it on by default, rather than mixing that in with the mechanism implementation.

In this case, I'm not too worried about the time or duration formatting, but especially turning on JSON encoding by default seems riskier to me.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can split that part out in a new PR

I discussed with Howard a while back and am re-discussing with him now, but we make no guarantees about log format stability, and we change logs and their fields all the time.
Plus, currently relying on fmt.Sprintf("%v",...) is also not stable, since go makes no guarantees about what the verbose format for structs will be, and any field or struct update will impact that as well

Clarified documentation.

Disable JSON encoding by default.

Bug: `AddSpanContext` wasn't checked when adding span information.
Bug: `EncodeError` was unneeded.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>
Copy link
Member

@kevpar kevpar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@helsaawy helsaawy merged commit 178111d into microsoft:main Mar 15, 2023
princepereira pushed a commit to princepereira/hcsshim that referenced this pull request Aug 29, 2024
* Log (JSON) formatting hook; span export

Added formatting for logrus export hook to marshal structs as JSON
strings, as well as format other known types (eg, time.Time).

Updated span export to:
* include span kind
* include status code
* log if span attributes were dropped

Added helper `log.Format*` functions to format Time and other structs
to JSON. This is already done by the logging hook, but allows spans
format their attributes consistently, since they must be converted to
strings before being exported.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>

* PR: docs, un-exported func, vestigial code

Remove unused commented out code and left-over function.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>

* PR: docs, defaults, AddSpanContext/EncodeError bug

Clarified documentation.

Disable JSON encoding by default.

Bug: `AddSpanContext` wasn't checked when adding span information.
Bug: `EncodeError` was unneeded.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>

---------

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants