Skip to content
Pedro Belo edited this page Aug 13, 2015 · 16 revisions

Pliny logs basic information from your app automatically, and offers helpers so you get the most out of logging in your app.

You can see what is logged by Pliny by booting your app and making a request to it. The output in your server process should look similar to this:

13:37:43 web.1 | request_id=394dde00-6d0b-48f4-a272-69d403a12d4b instrumentation at=finish method=GET path=/ route_signature=/ status=200 elapsed=0.013

This might read odd for new Pliny developers, but this is just a standard line of log in the logfmt format, which is basically a standard to log data in key/value pairs. And we love logfmt exactly because it's a standard, which means your HTTP request info is going to be logged in the same style as your database performance metrics. You can then use standard tooling and services to parse these logs and build dashboards, alerts and metrics out of them.

It's also worth noticing Pliny apps are configured to log to stdout instead of a file, which we believe provides for a better experience both in development and production.

Usage

You can log from anywhere in your app using Pliny.log:

Pliny.log(action: 'login', user: current_user.email)

Which in logfmt results in:

action=login [email protected]

Default log attributes

To add a key/pair to every log coming from your app, define it under config/initializers/logging.rb:

Pliny.default_context = { app: "my-api-app" }

Alternatively you can set a standard key/pair only for a block:

Pliny.context(action: "create-user") do
  Pliny.log(step: "create-api-key")
end

And finally, if you want to add a key/pair only to logs for the same request, use the context in the RequestStore:

Pliny::RequestStore.store[:log_context] = { user: current_user.email }

Now every time you call Pliny.log on that request, it will have current_user set.

Logging elapsed time

The log helper also takes a block to automatically log its duration, in seconds:

Pliny.log(action: 'login') do
  log_user_in
end

Resulting in:

action=login at=start
action=login at=finish elapsed=0.001

Notice it logs twice so you can easily tell what happened inside a block by looking at the logs alone.

Further reading