log

Overview ¶

Package log is Pachyderm's logger.

As a developer in the Pachyderm codebase, logging should be very easy. All context.Contexts available throughout Pachyderm are capable of logging a message associated with that request or subsystem.

HOW TO LOG ¶

The API surface that we provide is simply:

Debug(ctx, message, [fields...])
Info(ctx, message, [fields...])
Error(ctx, message, [fields...])

The fields are zap.Field objects; 99% of the time the field you're looking for is in the zap package, but we have a few in this package as well. "go doc zap.Field" and "go doc log.Field" will list them all; there are about 100 of them.

LEVELS ¶

Debug messages are interesting to you, the developer. Info messages are interesting to the team running Pachyderm day-to-day. If you want an operator or support to see a message, choose the Info level. Error messages are for actionable errors; if you can't handle a request and there is no way for an end user to see an error message, choose Error. (It's assumed that the operator or Pachyderm support will have to jump in whenever these show up. Misleading errors, especially errors that resolve themselves after a retry, are a big waste of customer time.)

Error messages that end users should see must be in the API response or UI, not in log messages, of course. End users should never have to read the logs.

STRUCTURED LOGGING ¶

All logs are structured; prefer:

Debug(ctx, "did a thing", zap.String("thing", thing), zap.String("reason", "because"))

over a non-structured:

Debugf(ctx, "did a thing (%v) because %v", thing, "because")

Structured logging is nice because you don't have to think about how to nicely phrase the message to make the fields make sense; just stick as much data in there as you like. And, automation or people debugging can filter for relevant messages with tools like jlog <https://github.com/jrockway/json-logs> or jq.

It is conventional to name your fields with camelCase, not snake_case or whatever-this-is-case. When unpacking a compound object into individual fields, object.key1, object.key2 are acceptable. (Example: grpc.code, grpc.message in gRPC responses.)

SPANS ¶

A common pattern is logging how long a certain operation ran for, and whether or not it succeeded. Most uses are covered by:

func doSomething(ctx context.Context, to *Object) (retErr error) {
    defer log.Span(ctx, "doSomething", zap.Object("to", to))(log.Errorp(&retErr))
    do()
    things()
    and()
    return them()
}

This will log:

DEBUG doSomething; span starting {to: {my: object}}
DEBUG doSomething; span finished ok {span_duration: 100ms, to: {my: object}}

or

DEBUG doSomething; span starting {to: {my: object}}
DEBUG doSomething; span failed {span_duration: 100ms, error: "them failed", errorVerbose: "<stack trace>", to: {my: object}}

There is `SpanL` if you want to set a log level other than DEBUG. log.Span takes fields as well, if you want to annotate the span with an ID or other information to help you assocaite the "end" log with the "start" log. The fields will be logged for both the start and end events.

There are the fields `Errorp` (for failing if a pointer to an error is non-nil, useful with retErr as above), `ErrorpL` (to change the log level on failure), zap.Error (for an error that is ready when you call the callback), and `ErrorL` (to change the log level if the error is non-nil). (As an aside, `zap.Error` won't log anything if its argument is nil, so you can always include an error without checking for nil-ness first. Our wrappers also conform to that convention.)

There is also SpanContext, where the operation itself wants to add details to the span:

func doSomething(ctx context.Context) (retErr error) {
    ctx, end := log.SpanContext(ctx, "doSomething", zap.String("theThing", "coolThing"))
    defer end(log.ErrorpL(&retErr, log.LevelError))
    do(ctx)
    things(ctx)
    and(ctx)
    return them(ctx)
}

This will log:

DEBUG doSomething doSomething; span starting {theThing: coolThing}
DEBUG doSomething inside do {theThing: coolThing}
DEBUG doSomething inside things {theThing: coolThing}
INFO  doSomething them is having trouble {theThing: coolThing, howMuchTrouble: a lot}
ERROR doSomething doSomething; span failed {span_duration: 1ms, theThing: coolThing, error: "them failed"}

There is `SpanContextL` for controlling the level of the starting message.

Finally, there is `LogStep`, which used to be called middleware.LogStep. It takes a callback instead of requiring you to defer things with pointers.

That is all you need to know to start logging things! The rest of the functionality is more advanced.

SAMPLING ¶

Some subsystems can be pretty noisy. The loggers we provide are configured to rate-limit messages over a short period of time (on the order of 2 messages every 3 seconds). This lets you see the first few log messages of a noisy routine, without filling up all storage space with one log message.

Rate limiting is keyed on message and severity; one noisy message won't rate limit other less frequent messages. Design your messages and log levels accordingly. For example, in the GRPC logging interceptor, we include the service name and method in the log message (in addition to fields), simply to ensure that one frequent GRPC call doesn't prevent other calls from being logged. Severity counts as well, so if you're writing a backoff routine, the first attempts might log at level DEBUG, but the last attempt can log at INFO. This ensures that even after a bunch of retries in a short period of time, the final outcome will still appear in the logs. (The backoff package does not yet do this.)

At the end of the day, it's about 100ns per message to log to a rate-limited logger (including some non-rate-limited messages; see BenchmarkFieldsSampled), so don't worry about logging too much. (Normal messages take about 2µs to process and render; most of this time is spent providing the "caller" field.)

You should feel perfectly free to log things like:

for i := 0; i < 10000; i++ {
    DoThing(items, i)
    Debug(ctx, "did a thing to items", zap.Int("i", i), zap.Int("max", 10000))
}

If it proceeds quickly, there will only be a few log lines. If DoThing is unexpectedly slow sometimes, then those logs will magically appear. Just don't change the message or level every iteration.

GETTING A LOGGER ¶

By the time you read this, all code should have been converted to transmit loggers through the context. If you run into some code that can't accept contexts, use `pctx.TODO()` if you can't fix the API today. TODO uses the global logger, but doesn't warn about the logger not being initialized, as Child() would do on an empty context. (For saftey, there is no circumstance where a log function will ever panic, or not log, but we do warn if the provided context doesn't have a logger inside of it. It's probably a bug, and the stack trace attached to the warning should let you track it down easily.)

Top-level applications need to initialize the global logger, from which background services and pctx.TODO() derive the global logger from. We have three ways of doing this, InitPachdLogger, InitWorkerLogger, and InitPachctlLogger. The Pachd Logger is designed for compatability with third-party logging systems, like Stackdriver, and should be the default for any server-side applications. The Worker logger is designed to only emit messages that can be parsed by `pachctl logs`, and is used only by the worker (user code container, not the storage container). The Pachctl logger is for command-line apps, and pretty-prints messages similar to those in this documentation. (It also adds color if the terminal is capable and it's not disabled by pachctl flags.) If you're writing a new CLI utility, you probably want the Pachctl logger.

The root context in applications is `pctx.Background()`. Call it exactly once after Init(Pachd|Worker|Pachctl)Logger.

In tests, use pctx.TestContext(t). In the future we plan to add other accouterments to contexts inside Pachyderm; use of this function will ensure that your tests are ready. The test context contains a logger scoped to that test; it is safe to run tests in parallel that both use different TestContexts. Anything logged to that logger will appear in the test logs (go test -v ...) in a format similar to pachctl's logs. For logging inside tests, rather than in production code called by tests, just use `t.Log`.

Do not use `zap.L()` and `zap.S()` outside of this package. They are set up and work, but prefer the context propagation.

CONFIGURING LOGGING ¶

Logging is configured by the environment, unrelated to service environment initialization.

The knobs you can tweak are:

• PACHYDERM_LOG_LEVEL={debug, info, error}. That controls the minimum serverity log messages that will be printed. We default to info, but it's configurable in the helm chart.

• PACHYDERM_DEVELOPMENT_LOGGER=1. If set to "1" or "true", then any warnings generated by the logging system will panic. It can't be turned on in the helm chart; these warnings should never reach production releases, but if they do, we just want to carry on and not crash.

• PACHYDERM_DISABLE_LOG_SAMPLING=1. If set to "1" or "true", no log sampling will occur. This might be helpful if there are a lot of duplicate messages that you really need to see in order to debug. It can't be turned on in the helm chart.

If you mess up the syntax of any of these environment variables, a warning will be the first message printed to the logger after it starts up. These will also panic in development mode.

At startup, the values of these configuration items will be stored and propagated to all workers. That's why they have the PACHYDERM_ prefix, so as not to conflict with user code.

You can change the log level across the entire fleet of services at runtime with `pachctl debug log-level ...`.

MISCELLANEOUS ¶

Some third-party packages expect a certain type of logger. We typically add adaptors to this package to convert a context into a logger for that subsystem.

See:

NewAmazonLogger(ctx)         # For the S3 client
NewLogrus(ctx)               # For logrus users, like dex and snowflake.
NewStdLogAt(ctx, level)      # For "log" users, like the net/http server.
AddLoggerToEtcdServer(ctx, server)        # To add a logger to an in-memory etcd.
AddLoggerToHttpServer(ctx, name, server)  # To add a logger to incoming requests in a net/http server.

Do not use a NewLogrus or a NewStdLogAt as the primary logger in any code you're writing. They are only for adapting to the needs of third-party packages.

EXTENDING THE LOGGING PACKAGE ¶

Sometimes the loggers available might not be quite what you need. Add the utility function you need to this package. To test it, there are private methods in testing.go that create a logger for testing the logging system. They create a pachd-style logger, that logs to an object you can iterate over to extract the parsed messages.

Because logging is widespread throughout the codebase, this package should not have any dependencies inside Pachyderm. For example, there is a function in here that generates UUIDs, but it can't depend on internal/uuid, because internal/uuid depends on internal/backoff, which depends on this package. It should always be safe to add logging no matter where you are in the codebase.