Runtime issues

[DAddYE]

Runtime issues

[ascandella]

Related to the other issue, that's actually zap behavior that's been
vendored due to the outstanding PR. I'm not sure we want to re introduce
the map version, but surely this is something that should be caught by
tests? It's programmer error.
On Fri, Nov 18, 2016 at 5:52 PM DAddYE [email protected] wrote:

With the current implementation
https://github.com/uber-go/fx/blob/master/core/ulog/log.go#L141-L144 we
can get runtime errors ... for logging. Even if more verbose I'd follow the
withFields thing we used before.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
#75, or mute the thread
https://github.com/notifications/unsubscribe-auth/AAF7PweT7H4uF6OyUzz5ej3ecQqz-XgZks5q_lZHgaJpZM4K3H7Y
.

[DAddYE]

Yup that's right but better avoid surprises at runtime

[ascandella]

I think this is something that's better suited to a linter than changing
the behavior of the logger. Having multiple ways to accomplish the same
thing is a non-goal of UberFx and we need it to be fast enough to support
our highest QPS services. Believe it or not logrus was a huge perf
bottleneck and i'd like to avoid making the same mistakes here.
On Fri, Nov 18, 2016 at 6:06 PM DAddYE [email protected] wrote:

Yup that's right but better avoid surprise at runtime

—
You are receiving this because you commented.

Reply to this email directly, view it on GitHub
#75 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAF7P8oSnIEbGp0Pl0VCJ3l7F6G1nYwyks5q_ll-gaJpZM4K3H7Y
.

[DAddYE]

why don't make an api like:

log.Info("Account created").With("accountID", a.ID).With("date", a.createdAT)

a little bit more verbose but not that bad.

[ascandella]

That seems reasonable. Does zap not already provide that @anuptalwalkar ?

[DAddYE]

If we want to avoid type checks we can make it even faster:

log.Info("Account created").WithInt("accountID", a.ID).WithString("date", a.createdAT)

[anuptalwalkar]

@DAddYE Tagging is supported with ulog interface. You can currently use the API the way you mentionedlog.With("accountID", a.ID).With("date", a.createdAT).Info("Account created")

For performance logging, zap already support WithFields(), method and zap.Field(key, value) methods. ulog provides an access to zap.Logger with ulog.RawLogger() method.

[glibsm]

The .With() method has a different purpose - it actually returns a new instance of the logger with additional fields baked in.

I.e. foo_logger := my_logger.With("foo", "bar"); foo_logger.Info("baz") will print foo, bar and baz.

Back to the issue at hand. One of the main ideas of taking in a ...interface{}as opposed with zap-like WithInt is developer friendlyness. Writing a zap log is not all that appealing:

logger.Info("Failed to fetch URL.",
  zap.String("url", url),
  zap.Int("attempt", tryNum),
  zap.Duration("backoff", sleepFor),
)

Now, I'm not suggesting that it's the best interface we can come up with, but I want us to try and shoot for something easier to use than log.Info("message").WithInt("my_int", 42)

It may be that taking a string and map is easier in the long run.

[ascandella]

I really, really don't think we should take a map. It creates a ton of allocations even if the message is never emitted. Additionally, having multiple ways to accomplish the same thing is both confusing and non-idiomatic.

cc @akshayjshah

[akshayjshah]

@DAddYE, you've proposed something that's nearly identical to the core zap API. Instead of your proposed

log.Info("Account created").WithInt("accountID", a.ID).WithString("date", a.createdAT)

you'd have

log.Info("Account created", Int("accountID", a.ID), String("date", a.createdAt))

or, if you'd like to re-use the same context on multiple log messages,

log.With(Int("accountID", a.ID), String("date", a.createdAt)).Info("Account created")

The basic idea is the same - express key-value pairs in a type-safe, performant way, even if it's a bit verbose. Compared to the core logger, zap's SugaredLogger tries reduce API verbosity so logging isn't so intrusive. Applications that need the best possible performance & compile-time safety should zap.Desugar their logger, which immediately exposes the core API (preserving any context already accumulated).

This discussion appears to largely concern what, exactly, the less-verbose API should look like. The short version is that I prefer this alternating key-value approach, but I don't have huge objections to a map-based approach instead. They can be equally performant. If it changes your opinion, the zap sugaring implementation handles the error you've identified a bit differently, so it's fatal in development but just an error log in prod.

Summary:

• If you want a super-fast, type-safe logger, desugar the uberfx-provided logger and use the core zap.Logger API. Many infra services will do this.
• The current proposal for sugaring is logger.With("k", "v", "k2", "v2").Info("things", "k3", "v3").
• We could just as easily sugar with logger.With(map[string]interface{}{"k": "v", "k2", "v2"}).Info("things").

I'm open to either sugaring option, but don't think we should support both.

[DAddYE]

I really, really don't think we should take a map. It creates a ton of allocations even if the message is never emitted. Additionally, having multiple ways to accomplish the same thing is both confusing and non-idiomatic.

Totally agree. Let's keep what we have now. No?

[ascandella]

@peter-edge @akshayjshah has any of this changed with the recent zap changes?

[ascandella]

Also, FWIW we have it on our action items to move to a typed logger internally, exposing sugared purely for our users.

[akshayjshah]

Nope, this discussion is still pretty accurate. As part of updating ulog, I'm migrating most internal logging to the type-safe logger.

Here's the shape of things in zap 1.0. For the best performance and type-safety, you use a *zap.Logger:

logger.With(
  zap.Int("count", 42),
  zap.String("url", "http://www.google.com"),
).Info("Something happened.", zap.Error(someErr))

If you don't care about ~10-20 allocations and a slight performance hit, you can use *zap.SugaredLogger:

logger.With(
  "count", 42,
  "url", "http://www.google.com",
).Infow("Something happened.", "error", someErr)

The SugaredLogger also include println- and printf-style logging methods. It also lets you mix loosely-typed key-value pairs with structured fields:

logger.With(
  "count", 42,
  "url", "http://www.google.com",
  zap.Stack("stacktrace"), //does a bunch of work to capture a stacktrace
).Infow("Something happened.", "error", someErr) // "infow" == "info with structured context"

The loosely-typed logger never panics in production; at worst, it logs an error that you've passed invalid params. In local development, those errors turn into panics, which should help you catch them quickly.

It's dirt cheap to convert between the sugared and unsugared loggers, so application owners don't need to make a single choice for the whole application.

sugared := baseLogger.Sugar()
base := sugared.Desugar()

[bufdev]

Is this still an issue?

[akshayjshah]

Shouldn't be an issue anymore.