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

contextual logging #2121

Merged
merged 16 commits into from
Dec 14, 2021
Merged

contextual logging #2121

merged 16 commits into from
Dec 14, 2021

Conversation

darkdarkdragon
Copy link
Contributor

What does this pull request do? Explain your changes. (required)
Passes request specific information (manifestId, seqNo, etc) around and logs everywhere.

Specific updates (required)
Adds requests specific info (manfiestId, etc) to Context object, passes this context around.
Adds 'clog' module that must be used for logging instead of glog. This module takes provided context and logs info from the context along the message.

How did you test each of these updates (required)
Manual

Does this pull request close any open issues?
Fixes #2102

Checklist:

@darkdarkdragon
Copy link
Contributor Author

@iameli @leszko made draft PR for quick review. If this conceptually ok I'll fix tests.

Copy link
Contributor

@leszko leszko left a comment

Choose a reason for hiding this comment

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

Thanks for the PR @darkdarkdragon . I skimmed through the code, I think it solves the problem. Added 2 comments.

My main concern is that we overuse the context object, meaning that we pass it now everywhere just for the logging purpose, but not every place actually respects what context is designed for.

That's why I'd recommend creating a separate struct like clog like this.

struct clog {
  manifestID string,
  sessionID string,
  ...
} 

And then store this struct in the context. In that case, we could pass context only to the functions that respect the context contract (cancellation, timeouts, etc.) and to the others, pass just clog struct. Wdyt?

cmd/livepeer/livepeer.go Show resolved Hide resolved
core/lb.go Outdated
@@ -147,8 +146,9 @@ func (lb *LoadBalancingTranscoder) leastLoaded() string {
}

type transcoderParams struct {
md *SegTranscodingMetadata
res chan struct {
logCtx context.Context
Copy link
Contributor

Choose a reason for hiding this comment

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

This looks fishy. In general Go doc does not recommend storing context in any structs.

Do not store Contexts inside a struct type; instead, pass a Context explicitly to each function that needs it. The Context should be the first parameter, typically named ctx

I understand that transcoderParams are actually for us the request params, but still...

It makes me think that we should maybe have an abstraction like clog struct which we store inside the context. Then, pass only this struct into transcoderParams (and to all other places that do not respect the context (i.e. does not stop working when the context is canceled) ).

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, it is looks not ideal, but I think it's better than the other option. Introducing separate structure for logging data will lead to a lot of wrapping/unwrapping code, and for what? To satisfy one sentence in context package's documentation?
Context is useful because it is a black box, and functions can pass it around without knowing what's inside.

Copy link
Member

@victorges victorges Dec 2, 2021

Choose a reason for hiding this comment

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

In general Go doc does not recommend storing context in any structs.

@leszko I think that's a rule that needs to be interpreted with a grain of salt as well. At least I interpret it as not storing ctxs in a long-living struct that will be shared among multiple short-lived operations, each of these operations (naturally) with their own respective ctxs.

I think in the case of a struct only used to pass parameters around it is very much an exception of that, as it is mostly a syntax sugar for not repeating the parameters multiple times in several places, but all of those within one of those short-live operations with the same ctx. (I am assuming that this is the use case for this params struct, since it is also so short with only 3 fields). An example of that is go's own http.Request object which can hold a ctx for that specific request to be made: https://pkg.go.dev/net/http#NewRequestWithContext

Another exception for that rule I think are "background jobs" which should be cancellable with a context passed on creation of the job. In that case, you could in theory pass the context around in every internal struct that needs access to it, but I think it's also valid to store the job context in the struct that represents the job itself, and access it anywhere you need it. One example of those is the RabbitMQ Streams consumer here (it has an internal done channel instead, but could just as well be an external context.Context for the same result).

Also an example for storing "application" (contextual) data in a context is julienschmidt/httprouter. It is an HTTP router which you can defined path routes with params, and it stores those params in the ctx in case you wanna use it with a raw http.Handler and not their specialized interface.

Copy link
Contributor

Choose a reason for hiding this comment

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

That's ok. Maybe we should just call it ctx or context then? If we pass it a context for the request. logCtx looks misleading, you receive this struct and you're not sure if you can depend on this context timeout/cancellation...

Copy link
Member

Choose a reason for hiding this comment

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

Yeah makes sense! I agree that having a separate context that is used for nothing but logging would be an anti-patttern. IMO, there should be only one ctx passed around [1], which in some places is used only for cancellation in case no logging is done, in others is used only for logging in case cancellation is not supported, and in the ideal cases are used for both. With that in mind, this should be renamed to just ctx and if it's built out of thin air just for logging it should be from a context.TODO() to be fixed later with a real context, not a context.Background() (not sure if that's happening anywhere right now).

[1] The only exception case I've found for this rule is when you do actually have multiple hierarchical cancellation contexts for the current code. For example if you have a server, which has it's own ctx for shutting down, while each request also has it's own ctx. You might use both, or better yet "merge" them into a single ctx that you pass around further down, using the same example as before, like this: https://github.com/livepeer/livepeer-data/blob/ed2b74fc9a2124032c05b11addfa4ebb6c013aab/pkg/event/stream_consumer.go#L199

Copy link
Contributor

Choose a reason for hiding this comment

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

Yeah, agree 🤝

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@leszko @victorges
I've renamed logCtx to ctx in most places, now it's ready for review.

@darkdarkdragon
Copy link
Contributor Author

Thanks for the PR @darkdarkdragon . I skimmed through the code, I think it solves the problem. Added 2 comments.

My main concern is that we overuse the context object, meaning that we pass it now everywhere just for the logging purpose, but not every place actually respects what context is designed for.

That's why I'd recommend creating a separate struct like clog like this.

struct clog {
  manifestID string,
  sessionID string,
  ...
} 

And then store this struct in the context. In that case, we could pass context only to the functions that respect the context contract (cancellation, timeouts, etc.) and to the others, pass just clog struct. Wdyt?

I think context was designed for passing around data, not just for timeouts/cancellation (Value function is part of the Context interface, and documentation has example of passing around data using it).

clog/clog.go Outdated Show resolved Hide resolved
clog/clog.go Outdated Show resolved Hide resolved
core/lb.go Outdated
@@ -147,8 +146,9 @@ func (lb *LoadBalancingTranscoder) leastLoaded() string {
}

type transcoderParams struct {
md *SegTranscodingMetadata
res chan struct {
logCtx context.Context
Copy link
Member

@victorges victorges Dec 2, 2021

Choose a reason for hiding this comment

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

In general Go doc does not recommend storing context in any structs.

@leszko I think that's a rule that needs to be interpreted with a grain of salt as well. At least I interpret it as not storing ctxs in a long-living struct that will be shared among multiple short-lived operations, each of these operations (naturally) with their own respective ctxs.

I think in the case of a struct only used to pass parameters around it is very much an exception of that, as it is mostly a syntax sugar for not repeating the parameters multiple times in several places, but all of those within one of those short-live operations with the same ctx. (I am assuming that this is the use case for this params struct, since it is also so short with only 3 fields). An example of that is go's own http.Request object which can hold a ctx for that specific request to be made: https://pkg.go.dev/net/http#NewRequestWithContext

Another exception for that rule I think are "background jobs" which should be cancellable with a context passed on creation of the job. In that case, you could in theory pass the context around in every internal struct that needs access to it, but I think it's also valid to store the job context in the struct that represents the job itself, and access it anywhere you need it. One example of those is the RabbitMQ Streams consumer here (it has an internal done channel instead, but could just as well be an external context.Context for the same result).

Also an example for storing "application" (contextual) data in a context is julienschmidt/httprouter. It is an HTTP router which you can defined path routes with params, and it stores those params in the ctx in case you wanna use it with a raw http.Handler and not their specialized interface.

@darkdarkdragon darkdarkdragon marked this pull request as ready for review December 3, 2021 21:52
Copy link
Contributor

@leszko leszko left a comment

Choose a reason for hiding this comment

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

I added my comments.

In general, it looks good and I really like the improvement. Most of the comments are minor and some of them might be just because of my lack of the livepeer domain and codebase.

clog/clog.go Outdated Show resolved Hide resolved
clog/clog.go Outdated Show resolved Hide resolved
var clogContextKey = clogContextKeyT{}

const (
// standard keys
Copy link
Contributor

Choose a reason for hiding this comment

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

What is the meaning of a standard key? Why orchSessionID is not a standard key?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

What is the meaning of a standard key?

These constants exists only for one reason - to be able to print them in sorted order.

Why orchSessionID is not a standard key?

It is. I just forgot to add it to the stdKeysOrder array.

Copy link
Contributor

Choose a reason for hiding this comment

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

ahh, I see, then I think you can remove this comment // standard keys and maybe rename stdKeys, because this std has apparently no meaning, which can be confusing.

You can just call them clogKeys or keys.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

They are 'standard' because we define them in the package, and have separate AddXXX methods for them - as opposed to general AddVal method which allows user to add any key.

clog/clog.go Outdated
}

func V(level glog.Level) Verbose {
return Verbose(bool(glog.V(level)))
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
return Verbose(bool(glog.V(level)))
return Verbose(glog.V(level))

Nit: You don't need bool() type conversion here.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

thanks, fixed

clog/clog.go Show resolved Hide resolved
clog/clog.go Outdated
}

func infof(ctx context.Context, lastErr bool, format string, args ...interface{}) {
glog.InfoDepth(2, formatMessage(ctx, lastErr, format, args...))
Copy link
Contributor

Choose a reason for hiding this comment

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

Why is the depth 2 here (while everywhere else it's 1)?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Where it is 1?

clog/clog.go Outdated
}

// Infofe if last argument is not nil it will be printed as " err=%q"
func Infofe(ctx context.Context, format string, args ...interface{}) {
Copy link
Contributor

Choose a reason for hiding this comment

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

Is there any known convention with this e at the end logging functions? If not, then maybe we don't need this Infofe() and (v Verbose) Infofe() at all? I see they are not used in many places and maybe we can add err=%v there in the string message. What do you think? To me, this looks confusing.

Copy link
Contributor Author

@darkdarkdragon darkdarkdragon Dec 6, 2021

Choose a reason for hiding this comment

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

It is convention that I've just invented 😄
This exists to avoid having err=<nil> in the logs. We will get it if we're doing Infof("err=%v", err) in case err could be nil.
So to avoid this I need to write

if err != nil {
  glog.Infof("message var1=%s err=%v", var1, err)
} else {
  glog.Infof("message var1=%s", var1)
}`

Infofe helps to avoid this duplication.

Copy link
Contributor

Choose a reason for hiding this comment

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

ok, I see. I'd probably prefer having err=<nil> since it's kind-of magic behavior of the library you create. In other words, as a user of clog you can be confused that suddenly err= is automatically added at the end. Anyway, it's minor and probably opinion-based, so I leave it up to you (and @victorges) to decide.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

You would prefer not to have err=<nil> in the logs once you will start digging through actual logs 😄
When searching through logs using err= as a query it's much better to see lines with actual errors 😄

Copy link
Member

Choose a reason for hiding this comment

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

When searching through logs using err= as a query it's much better to see lines with actual errors 😄

This will be so much less insane now that we have an actual tool for querying logs by their actual fields and not just text search 😄
But I think it's nice to avoid the err=<nil> lines anyway :)

It is convention that I've just invented 😄

Since it is a new convetion and thus not something that is self-explanatory, WDYT of using a more explicit name for the function? I like Infoferr for example.

And another approach is providing an AddErr function that only adds the error to the log if it is not nil. On your example, it could be:

ctx = clog.AddErr(ctx, err)
clog.Infof(ctx, "message var1=%s", var1)

or with the chaining idea in the other comment:

clog.Fields(ctx).AddErr(err)
    .Infof("message var1=%s", var1)

}
for key, val := range cmap.vals {
if _, ok := stdKeys[key]; !ok {
sb.WriteString(key)
Copy link
Contributor

Choose a reason for hiding this comment

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

Nit: Consider extracting to a function, these 4 lines are the same as in line 166.

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 could, but I don't see much value in it.

}
cmap.mu.RLock()
for _, key := range stdKeysOrder {
if val, ok := cmap.vals[key]; ok {
Copy link
Contributor

Choose a reason for hiding this comment

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

I see you print the standard keys in some predefined order. However, not standard keys are printed in random order. Is that intended?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Is that intended?

It is consequence of go's map being random. I could overcome it by different ways, but I've decided that it's not worth it. And anyway, right now only standard keys are used.

Copy link
Contributor

Choose a reason for hiding this comment

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

If we prepare the clog only for standard keys now, then let's maybe print only them? And skip printing the random keys? I think we should make it clear if the user of clog is allowed to create custom keys or not. If yes, then be consistent and print them in some order (i.e. alphabetic) if not, then just do not log the custom keys.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

  1. It is allowed to create custom keys.
  2. I don't think it's worth it. To do that we will need to write more code and suffer runtime efficiency. We can change it later if we will decide that this is a problem.

Copy link
Contributor

Choose a reason for hiding this comment

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

  1. It is allowed to create custom keys.

Do we use it anywhere? Why do we need it?

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 it will be quite annoying to go through logs where the keys have a random order on every line. Especially when for example going through a stream of the same log type, I normally get used to find the data I want on the same position on the line (cause fields generally have have the same length) and just move around.

Totally something that we can change in implementation later without breaking compatibility, so not necessary now, but giving my +1 here that we probably want to do some deterministic key order here soon. We could create an auxiliary keys slice, sort that, and then print the fields the same way we do for the stdKeysOrder above. That's exactly how logrus does it (src) and I'd guess how json package does it too for serialization.

core/streamdata.go Show resolved Hide resolved
Copy link
Contributor

@leszko leszko left a comment

Choose a reason for hiding this comment

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

Added comments.

I also played with it and everything seems to work fine :)

One more thing came to my mind, I see that in the GH issue #2102, @iameli mentioned that two fields should be printed in the logs manifestId and sessionId. I see a lot of other fields printed, but sessionId was not printed (at least in my case).

Could you maybe confirm with @iameli that what we print is ok?

/*
Package clog provides Conext with logging information.
*/
package clog
Copy link
Contributor

Choose a reason for hiding this comment

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

I think it should at least:

  1. Create this context
  2. Use your functions to update it (AddManifestID(), AddOrchSessionID())
  3. Execute messageFromContext() and assert the result

You can think if something else can be tested.

var clogContextKey = clogContextKeyT{}

const (
// standard keys
Copy link
Contributor

Choose a reason for hiding this comment

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

ahh, I see, then I think you can remove this comment // standard keys and maybe rename stdKeys, because this std has apparently no meaning, which can be confusing.

You can just call them clogKeys or keys.

return AddVal(ctx, orchSessionID, val)
}

func AddSessionID(ctx context.Context, val string) context.Context {
Copy link
Contributor

Choose a reason for hiding this comment

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

👍

clog/clog.go Show resolved Hide resolved
clog/clog.go Outdated
}

// Infofe if last argument is not nil it will be printed as " err=%q"
func Infofe(ctx context.Context, format string, args ...interface{}) {
Copy link
Contributor

Choose a reason for hiding this comment

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

ok, I see. I'd probably prefer having err=<nil> since it's kind-of magic behavior of the library you create. In other words, as a user of clog you can be confused that suddenly err= is automatically added at the end. Anyway, it's minor and probably opinion-based, so I leave it up to you (and @victorges) to decide.

}
cmap.mu.RLock()
for _, key := range stdKeysOrder {
if val, ok := cmap.vals[key]; ok {
Copy link
Contributor

Choose a reason for hiding this comment

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

If we prepare the clog only for standard keys now, then let's maybe print only them? And skip printing the random keys? I think we should make it clear if the user of clog is allowed to create custom keys or not. If yes, then be consistent and print them in some order (i.e. alphabetic) if not, then just do not log the custom keys.

clog/clog.go Show resolved Hide resolved
clog/clog.go Outdated
}

func infof(ctx context.Context, lastErr bool, format string, args ...interface{}) {
glog.InfoDepth(2, formatMessage(ctx, lastErr, format, args...))
Copy link
Contributor

Choose a reason for hiding this comment

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

I already asked about it, but it gets lost somewhere during the refactor ;) Why is the depth here 2 while in Warningf, Fatalf and Infof you use 1?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

For Warningf call stack looks like this: calling code->clog.Warningf->glog.WarningDepth
For Infof: calling code->clog.Infof->infof->glog.InfoDepth
As you can see there is one more function in the chain, so call stack is deeper by one.

Copy link
Contributor

Choose a reason for hiding this comment

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

Ahh, I see. Consider adding a comment to the code to explain it.

@darkdarkdragon
Copy link
Contributor Author

@victorges could you give it another review?

Copy link
Contributor

@leszko leszko left a comment

Choose a reason for hiding this comment

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

@darkdarkdragon , the PR looks good from my end. Last two things are:

  1. Non-standard keys, I still don't get why we have them if we don't use them at all. I think we should not "just have them in case" but rather either remove them for now (if we don't need them), make their printing deterministic (if we need them).

  2. Confirm if the format we print is ok with @iameli , because GH Issue mentioned something slightly different.

/*
Package clog provides Conext with logging information.
*/
package clog
Copy link
Contributor

Choose a reason for hiding this comment

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

Great, thanks!

@iameli
Copy link
Member

iameli commented Dec 8, 2021

  1. Confirm if the format we print is ok with @iameli , because GH Issue mentioned something slightly different.

@leszko Yep, sounds fine to me - just looking for something that we can ingest into Loki and I think this works

Copy link
Member

@victorges victorges left a comment

Choose a reason for hiding this comment

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

LGTM with a few suggestions, but feel free to merge as is! Also thanks for migrating so much of the codebase to the new lib already!

At some point I started mostly skimming on the changes to use the new lib tho, since it looked mostly straightforward/automatic. Let me know if there are any files that need a more thorough review.

Comment on lines +89 to +94
func AddVal(ctx context.Context, key, val string) context.Context {
cmap, _ := ctx.Value(clogContextKey).(*values)
if cmap == nil {
cmap = newValues()
ctx = context.WithValue(ctx, clogContextKey, cmap)
}
Copy link
Member

Choose a reason for hiding this comment

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

One thing that bothers me about the "lazy init" approach is that every interface we give needs to receive & return a context.Context instance. I'm not 100% which is my preference, but have you considered/WDYT of a separate function to initialize the context like

ctx = clog.InitFields(ctx)

and then it can just be used to add fields without worrying about re-setting the ctx value like

clog.AddVal(ctx, "a", "b")

or

clog.Fields(ctx).Add("a", "b")

or even ⛓️

clog.Fields(ctx)
    .Add("a", "b")
    .Add("c", "d")

In which clog.Fields would panic if the fields have not been initialized. Also maybe InitFields could even be the same function as "clone": if there are already fields there, it would create new ones and clone the values, for a "sub-log-context".

Note that we could also allow both interfaces to be used, with the disclaimer that, if you use Fields you must know that your ctx has already been initalized.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Right now, after context is initialised, you can just do clog.AddVal(ctx, "a", "b") - this will work just fine because anyway it will return same context. I didn't want explicit initialisation because I didn't want to have accidental panic in production.

Comment on lines +95 to +97
cmap.mu.Lock()
cmap.vals[key] = val
cmap.mu.Unlock()
Copy link
Member

Choose a reason for hiding this comment

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

Would be great if we could avoid this lock somehow, as logging ideally shouldn't be something you need to be too cautious about performance issues. I wonder if no lock at all wouldn't be sufficient here, since that also considering the current interface which returns a context.Context on every added field, doesn't look like something that we would/should be calling concurrently.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

doesn't look like something that we would/should be calling concurrently.

I thought so, but was forced to add lock after panics 😄 Turned out we do use same context from different go-routines.
Anyway, when I've first created this package, I didn't know how much information will end up in the logging context.
Turned out not much - right now I'm using only one non-standard key, and probably we will not add many more.
So I think we can get rid of map completely and just use pre-allocated array containing key/value pairs.
Or keep map and locks, but pre-format message on every AddXXX call. Or something else - but it is discussion for the next issue/PR 😄

clog/clog.go Outdated
}

// Infofe if last argument is not nil it will be printed as " err=%q"
func Infofe(ctx context.Context, format string, args ...interface{}) {
Copy link
Member

Choose a reason for hiding this comment

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

When searching through logs using err= as a query it's much better to see lines with actual errors 😄

This will be so much less insane now that we have an actual tool for querying logs by their actual fields and not just text search 😄
But I think it's nice to avoid the err=<nil> lines anyway :)

It is convention that I've just invented 😄

Since it is a new convetion and thus not something that is self-explanatory, WDYT of using a more explicit name for the function? I like Infoferr for example.

And another approach is providing an AddErr function that only adds the error to the log if it is not nil. On your example, it could be:

ctx = clog.AddErr(ctx, err)
clog.Infof(ctx, "message var1=%s", var1)

or with the chaining idea in the other comment:

clog.Fields(ctx).AddErr(err)
    .Infof("message var1=%s", var1)

clog/clog.go Show resolved Hide resolved
}
cmap.mu.RLock()
for _, key := range stdKeysOrder {
if val, ok := cmap.vals[key]; ok {
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 it will be quite annoying to go through logs where the keys have a random order on every line. Especially when for example going through a stream of the same log type, I normally get used to find the data I want on the same position on the line (cause fields generally have have the same length) and just move around.

Totally something that we can change in implementation later without breaking compatibility, so not necessary now, but giving my +1 here that we probably want to do some deterministic key order here soon. We could create an auxiliary keys slice, sort that, and then print the fields the same way we do for the stdKeysOrder above. That's exactly how logrus does it (src) and I'd guess how json package does it too for serialization.

return
case params := <-sess.sender:
cancel()
res, err :=
sess.transcoder.Transcode(params.md)
sess.transcoder.Transcode(params.ctx, params.md)
Copy link
Member

Choose a reason for hiding this comment

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

Hum, I think I understood the need but it's quite confusing to have 2 (3?) contexts here. Seems like this context passed here should be logCtx instead? Since it's a function that did not receive a ctx before so it's likely only used for logging.

Is there any way of getting rid of the duplication or maybe sticking to only 1 context in the implementation here? Havent read the whole logic so not sure if I follow it, but if we need params.ctx for cancellation and logCtx for logging, shouldn't clog.Clone(params.ctx, logCtx) or sth like that be the only ctx we need here?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Infofe made for the cases when we don't know if err is nil or not. But here we already checked, so no point of using Infofe

Either way came to my mind that Infofe will be logging errors as info, not as errors, right? Sth we'd like to change somehow?

Fixed in 4d312d6

Also, while at it, mind adding any text here to say something about what is this error?

This concrete error already has verbose description added (like errors.Wrapf(err, "Could not get orchestrator orch=%v", orchestratorServer))

@@ -114,7 +115,7 @@ func (o *orchestratorPool) GetOrchestrators(numOrchestrators int, suspender comm
return
}
if err != nil && !errors.Is(err, context.Canceled) {
glog.Error(err)
clog.Errorf(ctx, "err=%q", err)
Copy link
Member

Choose a reason for hiding this comment

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

Hmm, isn't Infof(err) a good candidate here? Either way came to my mind that Infofe will be logging errors as info, not as errors, right? Sth we'd like to change somehow?

Also, while at it, mind adding any text here to say something about what is this error?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

because ctx is captured in the closure, and will be the same for subsequent calls to function that is returned from createRTMPStreamIDHandler

@@ -238,21 +239,27 @@ func createRTMPStreamIDHandler(s *LivepeerServer) func(url *url.URL) (strmID str
profiles := []ffmpeg.VideoProfile{}
detectionConfig := core.DetectionConfig{}
var VerificationFreq uint
nonce := rand.Uint64()

ctx := clog.AddNonce(_ctx, nonce)
Copy link
Member

Choose a reason for hiding this comment

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

What's the reason for declaring a new variable here instead of replacing?

@@ -1424,26 +1440,26 @@ func (s *LivepeerServer) HandleRecordings(w http.ResponseWriter, r *http.Request
return
default:
}
glog.V(common.VERBOSE).Infof("Playlist generation for manifestID=%s took=%s", manifestID, time.Since(now1))
clog.V(common.VERBOSE).Infof(ctx, "Playlist generation for took=%s", time.Since(now1))
Copy link
Member

Choose a reason for hiding this comment

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

Suggested change
clog.V(common.VERBOSE).Infof(ctx, "Playlist generation for took=%s", time.Since(now1))
clog.V(common.VERBOSE).Infof(ctx, "Playlist generation took=%q", time.Since(now1))

return errSecret
}
if req.Capacity <= 0 {
glog.Info(errZeroCapacity.Error())
glog.Errorf("err=%q", errZeroCapacity.Error())
Copy link
Member

Choose a reason for hiding this comment

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

Same for some info on the logs about what this means / where it comes from.

@darkdarkdragon
Copy link
Contributor Author

@victorges

That's exactly how logrus does it (src)

And it has option to disable sorting 😄 I would prefer not to call sort for every log line.
But we can think of implementation that fixes this later.
And anyway, right now there is only one non-standard key used, so you'll not see keys in random order 😄

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.

improve contextual logging
4 participants