-
Notifications
You must be signed in to change notification settings - Fork 291
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
Upgrade to zap 1.0 release candidate #290
Conversation
@akshayjshah, thanks for your PR! By analyzing the history of the files in this pull request, we identified @anuptalwalkar, @glibsm and @alsamylkin to be potential reviewers. |
Argh, there's already a massive conflict with Anup's latest logging refactoring. I'll resolve all the conflicts later this weekend. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Notes, mostly for myself:
- This removes IsDevelopmentEnvironment()
- Will require internal documentation changes
- Need to discuss our story around exposing tally directly versus a duck-typed interface and whether or not we want to do the same (and the associated overhead)
- Timelines
Generally I'm +2 on this change and willing to merge/manually test myself tomorrow if we can iron out the major issues today/tomorrow.
I still have this lingering feeling we want a facade interface though, having seen how many times users have been bitten by library upgrades. Not saying that your team will do that, but whether my team should take a hard stance and do our best to never expose types we don't control directly as part of our APIs.
auth/uauth.go
Outdated
@@ -48,7 +48,7 @@ var ( | |||
// CreateAuthInfo interface provides necessary data | |||
type CreateAuthInfo interface { | |||
Config() config.Provider | |||
Logger() ulog.Log | |||
Logger() *zap.Logger |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think this is going to be the most contentious part cc @shawnburke who deals with the same issue in Catalyst. I'm sure your 1.x series will maintain API compatibility but we've been trying to introduce as many shim layers as possible (caveat: you'll see nearby we're exposing tally directly, which we may decide not to) to provide you the flexibility to change your APIs without worrying about breaking UberFx consumers.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Let's discuss this in person. I Have a lot of reservations about top-level frameworks own interfaces for logging and metrics; it forces components far down the stack to depend on the framework, instead of the reverse.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Meant to post to this comment, but replied to the email instead so it's at the bottom. Copy-paste:
Ya, this is definitely not black-and-white, definitely should hammer out in
person. My primary concern is stability, not ownership. If we can keep
pushing new versions of Fx without ever breaking people using our logging
mechanism, then my vote is for whatever mechanism makes that easiest.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Agreed.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I started email thread before this PR, and Im curious too. I have been asked this question multiple times that why fx is so tightly integrated with zap.Logger, and can it be used with different logger implementation.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ack ya I am starting to really like zap, and am super impressed with it, but...I have to agree, I hate when frameworks/libraries tightly link a logging library. I wish we could even document the Typed()
function to return nil if zap is not being used, or something a little less unsafe.
examples/keyvalue/server/observer.go
Outdated
@@ -32,7 +32,7 @@ type Observer struct { | |||
|
|||
// OnInit is called during service init process. Returning an error halts the init? | |||
func (o *Observer) OnInit(svc service.Host) error { | |||
svc.Logger().Info( | |||
svc.Logger().Sugar().Infow( |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sugar()
is low enough overhead/memoized that we don't need a svc.SugaredLogger()
? Cool!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep, its one allocation. Not free, but not a big deal if you're using the sugared API. If UberFx gets to a point where it's counting single allocations, memorizing this may make sense.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
How do you feel about svc.TypedLogger()
and svc.Logger()
being sugared? I'm on the fence as to how we want to expose this, but my gut (and my discussions outside of uber) is that most people find the verbosity of zap.String()
etc too high, and will opt for typed only when perf is a concern.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Let's defer pending the interface discussion. If we end up not putting a facade in front of logging, we can do away with this API altogether - it's just a roundabout way of giving people access to zap.L
and zap.S
, which FX startup configures.
glide.yaml
Outdated
# Pinned temporarily while zap reaches 1.0 (https://github.com/uber-go/fx/pull/243) | ||
version: c064b5c44b285a7e2fd5c9b26e8c38228ce2bccb | ||
- package: go.uber.org/zap | ||
version: v1.0.0-rc.1 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Any release timeline on 1.0? We had an incredibly painful amount of churn with yarpc 1.0 RC candidates, both for my team and our consumers.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Typical for an RC - depends on how many things I got wrong :)
I'm hoping to update some other internal projects this week and cut a 1.0 final before the end of the month. The APIs for the loggers themselves are very, very unlikely to change; more likely that some portion of the constructors changes.
I misspelled a JSON key, so there's and RC.2 coming Monday. Shouldn't affect you guys.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Cool. Again though, this makes me think we should keep a ulog.Logger even if it's currently just the exact same interface as a zap.Logger so that we can upgrade to v1 without breaking users.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Any breaking change in the RC will also break your interface, so I'm not sure what this buys you.
I've had this discussion about interfaces with Peter and Josh before, and it's nuanced enough that we should take it out of PR comments. I'll send you a short proposal, and we can discuss in person. I'm certainly not blocking you from shipping what you want in FX, but I don't think that this interface will be helpful.
modules/rpc/handler.go
Outdated
@@ -85,7 +89,7 @@ func (a authOnewayInboundMiddleware) HandleOneway(ctx context.Context, req *tran | |||
func authorize(ctx context.Context, host service.Host) (context.Context, error) { | |||
if err := host.AuthClient().Authorize(ctx); err != nil { | |||
stats.RPCAuthFailCounter.Inc(1) | |||
ulog.Logger(ctx).Error(auth.ErrAuthorization, "error", err) | |||
ulog.Logger(ctx).Error(auth.ErrAuthorization, zap.Error(err)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh man, @akshayjshah, you really went above and beyond here. We have an action item to convert to unsugared usage internally. Really appreciate this!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
👍
modules/rpc/handler.go
Outdated
@@ -110,7 +114,7 @@ func (p panicOnewayInboundMiddleware) HandleOneway(ctx context.Context, req *tra | |||
func panicRecovery(ctx context.Context) { | |||
if err := recover(); err != nil { | |||
stats.RPCPanicCounter.Inc(1) | |||
ulog.Logger(ctx).Error("Panic recovered serving request", "error", errors.Errorf("panic in handler: %+v", err)) | |||
ulog.Logger(ctx).Error("Panic recovered serving request.", zap.Any("error", err)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is this a thing? Periods after messages? If so, we should document somewhere and communicate with my team.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sorry, broke with your convention out of habit. My strong preference is for comments and log messages to be complete sentences - initial capitals, proper spelling and grammar, and terminal punctuation. I think I'm out of the mainstream on this though.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Golang comments expect a period in the end: https://github.com/golang/go/wiki/CodeReviewComments#comment-sentences
I have seen we missed period in a few places.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Comments !== log messages
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think I'm agreeing with Aiden 2-0 so far in the Aiden/Akshay "Battle of the PR" here. I actually don't even like sentences, I like "Events", and wish they were somehow documented. Think request_panic_recovered
.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure. Don't think that this is a place we need consensus.
service/host.go
Outdated
} | ||
} | ||
|
||
// Flush tracing buffers | ||
if s.tracerCloser != nil { | ||
s.Logger().Debug("Closing tracer") | ||
if err = s.tracerCloser.Close(); err != nil { | ||
s.Logger().Error("Failure to close tracer", "error", err) | ||
s.Logger().Error("Failure to close tracer", zap.Error(err)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
TODO add period here?
service/host.go
Outdated
@@ -199,7 +206,7 @@ func (s *host) AddModules(modules ...ModuleCreateFunc) error { | |||
if !s.supportsRole(mi.Roles...) { | |||
s.Logger().Info( | |||
"module will not be added due to selected roles", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
TODO(my team) capitalize "Module"
service/host.go
Outdated
@@ -278,9 +285,12 @@ func (s *host) start() Control { | |||
|
|||
s.shutdownMu.Unlock() | |||
if _, err := s.shutdown(e, "", nil); err != nil { | |||
s.Logger().Error("Unable to shut down modules", "initialError", e, "shutdownError", err) | |||
s.Logger().Error("Unable to shut down modules", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
No period? Perhaps I'm misunderstanding the guideline here.
service/host.go
Outdated
s.Logger().Error("Unable to shut down modules", "initialError", e, "shutdownError", err) | ||
s.Logger().Error("Unable to shut down modules", | ||
zap.String("initialError", e.Error()), | ||
zap.String("shutdownError", err.Error()), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We're going to lose the cause/stacktrace of these errors by turning them into Strings, right?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Possibly. I'll take another pass to make sure we don't lose any info.
I'm not going to take a dependency on Daves error package in zap (it's pre-1.0), but I should still be able to support these errors with Error
.
service/host.go
Outdated
@@ -400,7 +413,11 @@ func (s *host) transitionState(to State) { | |||
|
|||
// TODO(ai) this isn't used yet | |||
if to < s.state { | |||
s.Logger().Fatal("Can't down from state", "from", s.state, "to", to, "service", s.Name()) | |||
s.Logger().Fatal("Can't down from state", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Again, same question about periods. Seems like maybe we should just leave them out and back out the changes towards the top to remain consistent
With regards to your comment:
It's always seemed weird to me that the logger object was stored as a value on the context. If we can just extract the tracing when we need it, it seems much cleaner to not add additional metadata. I tried to work this out with @anuptalwalkar and @alsamylkin, but they had some technical reasons why it was necessary to store on the context. |
I'm out on Monday, but will try to get the remaining nits ironed out by Tuesday. Mind scheduling something for us to chat Tuesday morning? |
Sure. What's the scope? Fascade interfaces in general, review of this PR,
scheduling/timing/ownership?
…On Sat, Feb 18, 2017 at 4:21 PM Akshay Shah ***@***.***> wrote:
I'm out on Monday, but will try to get the remaining nits ironed out by
Tuesday. Mind scheduling something for us to chat Tuesday morning?
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#290 (comment)>, or mute
the thread
<https://github.com/notifications/unsubscribe-auth/AAF7P-ipBYpbe0GYIxIPJ4ED5D3G84DFks5rd4sKgaJpZM4MFDXz>
.
|
cc @shawnburke we should (maybe?) take a consistent stance on fascade interfaces between UberFx and Catalyst, otherwise we could end up with some painful conversion functions. Would you like to join the meeting, or have a separate discussion w.r.t. UberFx+Catalyst once we've figured out our strategy on zap/tally/etc? |
@@ -74,7 +74,7 @@ func TestExecutionChainFiltersError(t *testing.T) { | |||
} | |||
|
|||
func withOpentracingSetup(t *testing.T, registerFunc auth.RegisterFunc, fn func(tracer opentracing.Tracer)) { | |||
tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", ulog.NopLogger, metrics.NopCachedStatsReporter) | |||
tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", zap.New(nil), metrics.NopCachedStatsReporter) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Consider zap.Nop()
instead of zap.New(nil)
for NopCore.
I actually had to pull up zap to see what it meant to pass in nil
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep, fair point. New
supports nil purely for safety (since I can't stop people from passing nil interfaces, this seemed like the best way to not add an error return). uber-go/zap#326 adds an explicit NewNop
.
I'd definitely like to get through this PR, and ideally also figure out the facades & interface ownership aspects. |
modules/uhttp/filters.go
Outdated
@@ -55,8 +55,7 @@ type contextFilter struct { | |||
} | |||
|
|||
func (f contextFilter) Apply(w http.ResponseWriter, r *http.Request, next http.Handler) { | |||
ctx := ulog.NewLogContext(r.Context()) | |||
next.ServeHTTP(w, r.WithContext(ctx)) | |||
next.ServeHTTP(w, r) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I want to keep this. We had this filter to keep the logger inside context and making it available for users. Primary reason is to keep adding fields that are not provided by zap. Logger(ctx) provides default fields from zap configuration (host, time, etc), but some of the fields come from fx. Right now, you have module: "http"
, service name, traceID, spanID with the logger available in the user handler.
To answer the other question on why Logger is on the context and not fields. I see that you have added Logger(ctx) to pull all fields from context instead of returning configured logger. This seems efficient right now, but it will be O(n) operation n being number of fields in the context to make the logger rich enough for our needs. There is this slight performance benefit of having Logger in the context since most of the codebase is literally doing 'ulog.Logger(ctx)' on every logging step. What do you think? We can comeback to perf later since either way will not break any APIs.
// hijack output from the standard library's "log" package. It returns a | ||
// function to undo these changes. | ||
func SetLogger(log *zap.Logger) func() { | ||
undoGlobals := zap.ReplaceGlobals(log) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is sweet!
auth/uauth.go
Outdated
@@ -48,7 +48,7 @@ var ( | |||
// CreateAuthInfo interface provides necessary data | |||
type CreateAuthInfo interface { | |||
Config() config.Provider | |||
Logger() ulog.Log | |||
Logger() *zap.Logger |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I started email thread before this PR, and Im curious too. I have been asked this question multiple times that why fx is so tightly integrated with zap.Logger, and can it be used with different logger implementation.
I really really really like this PR. This is going to break like, everything, ever, but I don't mind at all. Totally worth it. |
I suspect that, at the end of the day, a bunch of the migration pain can be fixed with |
Rebased on master, addressed some nits. This go-round leaves all log messages exactly as-is :) Travis will fail until I can get some eyes on uber-go/zap#333 and uber-go/zap#329. Once those land, I can cut a second RC and update FX's Glide manifest and lock files. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Like the ratio: 1980 lines removed, 469 added
} | ||
j, ok := span.Context().(jaeger.SpanContext) | ||
if !ok { | ||
return nil |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks weird..
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Can you elaborate a bit? If there's no Jaeger span available, there's nothing to do; it's not an error, it's an expected case.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I am confused, why is it an expected case?
// To register it with a zap.Logger, use zap.Hooks. | ||
func Metrics(s tally.Scope) func(zapcore.Entry) error { | ||
// Avoid allocating strings and maps in the request path. | ||
debugC := s.Tagged(map[string]string{"level": "debug"}).Counter("logs") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
can we simplify it even further and put counters in a map, so returning function will probably have only one if?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is faster - why take on a hash map lookup when we can use a short switch
instead? For straightforward, well-encapsulated, often-executed code, I don't think that the brevity gains are worth it.
Of course, y'all own this code - I'll change if you really want me to.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Well, this is because Zap has weird constants :) otherwise we can use arrays and be on par.
I did a simple benchmark and maps are 3 times slower, so it is good to keep switch.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Cool - thanks for the stamp! The add/delete ratio is unfortunately misleading, since this diff drops Sentry support :/
We'll need to get that filebeat extension shipped pronto.
} | ||
j, ok := span.Context().(jaeger.SpanContext) | ||
if !ok { | ||
return nil |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Can you elaborate a bit? If there's no Jaeger span available, there's nothing to do; it's not an error, it's an expected case.
// To register it with a zap.Logger, use zap.Hooks. | ||
func Metrics(s tally.Scope) func(zapcore.Entry) error { | ||
// Avoid allocating strings and maps in the request path. | ||
debugC := s.Tagged(map[string]string{"level": "debug"}).Counter("logs") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is faster - why take on a hash map lookup when we can use a short switch
instead? For straightforward, well-encapsulated, often-executed code, I don't think that the brevity gains are worth it.
Of course, y'all own this code - I'll change if you really want me to.
My stamp is not binding to merge, I agree with the changes, but we need to figure out sentry(and fix lint errors) to merge. |
This necessarily updates all the other dependencies, too.
Remove most of ulog, since it's either unnecessary or subsumed by zap. The only lost functionality here is Sentry integration, which we can bring back next week (either as an UberFX-specific encoder wrapper, or as a Filebeat plugin).
There's no need for this; we don't need to put loggers into the context in order to add tracing information to the context.
Again, this necessarily upgrades all other dependencies.
assert.NotNil(t, jConfig) | ||
assert.Equal(t, jaeger.NullLogger, jConfig.Logger) | ||
} | ||
|
||
func TestLoadAppConfig_NilJaegerConfig(t *testing.T) { | ||
jConfig := loadAppConfig(nil, getLogger()) | ||
jConfig := loadAppConfig(nil, zap.L()) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
zap.L and zap.S are a bit confusing. Not blocking this PR, but we may need some verbose method here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep, these are extremely short by design. Many logging packages have top-level Error
, Infof
, etc. functions; I really, really don't want these in zap, which means that we need a minimally noisy way to get the global logger. zap.GlobalLogger().Info("something")
seems like a lot; zap.L().Info("something")
is much less intrusive.
This is definitely a matter of taste, though - file an issue and we can discuss pros and cons there.
Merging the PR, since conflicts are resolved here and offline. |
❤️ |
leerooooooooooyyyyyyyyy |
This PR upgrades UberFX to use the release candidate of zap 1.0. Along the way, it migrates FX to use the base zap logger (what you were calling the typed logger). It includes a few potentially controversial changes, which I'll address head-on here. I'm happy to chat about any of this in person on Monday.
(Clearly, this can't get merged until after your code freeze. That's cool, I'd just like to get review done before I'm constantly rebasing.)
No ulog.Log interface
Interfaces are good for a few things:
However, the former
ulog.Log
interface doesn't accomplish any of these goals. It would have included the fullzap.SugaredLogger
API, and it doesn't prevent UberFX (and ulog) from taking a concrete dependency on zap. Most importantly, because we need users to be able to recover the strongly-typed*zap.Logger
, it references tons of concrete zap types (*zap.Logger
, which then referencesField
and*CheckedEntry
). It's hard for me to imagine a reimplementation of that API outside zap.That might still be okay, but interfaces are also harder to extend - adding even a single method is a breaking change. Given all that, it seems wiser to me to use
*zap.Logger
directly and eliminate a bunch of copypasta. Since we own both libraries, I don't see this as a significant problem. - users can and should declare narrow interfaces for just the portions of the logger that they're using.No Sentry integration
This is purely a time issue. If you can't wait for the Filebeat plugin we've discussed, I'm happy to resurrect direct Sentry integration in a follow-on PR. The latest zap should allow us to do that without so many map copies and with zero impact on non-error log performance.
No loggers in contexts
I was a little confused by the existing code. It looks to me like we're largely working with a single global logger, which starts off with some default configuration and is reconfigured on service startup. We're supplying that logger to users by putting it into the request context and providing
ulog.Logger(ctx context.Context) ulog.Logger
as a getter. Where possible, we add tracing information to the logger before putting it into the context.In all that, I'm not sure whether the logger needs to be in the context at all. We can keep
ulog.Logger
, and add just add the context's tracing information to the logger when it's retrieved. This is quite inexpensive, and it's much simpler.No log builder
I don't think that this is required any more either; we can just use zap's config shapes instead. They already come with sensible default values, and we can modify the service scaffold to comply with our internal logging schemas.
Documentation
I didn't touch the ulog README much - I'll leave that for someone on your team.