Monitoring with telemetry

Copy Markdown View Source

Log ImagePipe's requests, and send them to your own metrics or logging handlers. This guide assumes ImagePipe runs in your app, as a Plug or through ImagePipe.run/4. image_pipe_server logs its requests by default (see its telemetry settings).

ImagePipe emits :telemetry events and attaches no handlers itself. The event reference lists every event.

Logging with the default logger

Attach the bundled Logger handler once, when your application starts:

# lib/my_app/application.ex
def start(_type, _args) do
  ImagePipe.Telemetry.attach_default_logger()
  # ...
end

Each request then logs one line: the method, path, status, duration, and bytes sent, then what the request did as key=value fields:

[info] GET /w=200/src/REDACTED 200 79ms 4.7kB source_url=beach.jpg cache=miss source=images source_fetch=ok fetch_ms=1 input=jpeg input_size=4000x2667 decode_ms=4 ops=resize output=jpeg output_size=200x133 encode_ms=6 admission=admitted queue_ms=0
[warning] GET /w=200/src/REDACTED 404 1ms source_url=missing.jpg error=source reason="source not found" source=images source_fetch=source_error fetch_ms=0

A 5xx, or a response that failed partway through sending, logs at :error. A 4xx logs at :warning, and so does a result that didn't come out as requested, such as a crop that used attention because detection failed or no detector is configured, or an image scaled down to the limits. A request whose cache read failed logs at :warning too. A low-priority request that the processing pool turned away logs at the base level, since its client retries. A cache write that fails or is dropped logs its own :warning line, because the write can finish after the request's line. The [:request, :summary] event lists the fields. The fields are also in the line's Logger metadata, as a map under :image_pipe, so a JSON formatter such as logger_json writes them as an image_pipe object. One key keeps them clear of the fields a log collector reserves, such as Datadog's status.

The path ends at the source, as in /w=200/src/REDACTED, and the source follows as a source_url= field, without its credentials.

To debug a request, pass stages: true to also log one line for each of its stages, such as each cache lookup, the decode, and the encode. If you set a custom telemetry_prefix, pass the same list as :prefix. ImagePipe.Telemetry.attach_default_logger/1 lists the options.

Attaching handlers

Attach your own handler to the events you need. This one logs each request's result and duration:

# lib/my_app/image_pipe_telemetry.ex
defmodule MyApp.ImagePipeTelemetry do
  require Logger

  def attach do
    :telemetry.attach(
      "my-app-image-pipe",
      [:image_pipe, :request, :stop],
      &__MODULE__.handle_event/4,
      nil
    )
  end

  def handle_event(_event, measurements, metadata, _config) do
    duration_ms = System.convert_time_unit(measurements.duration, :native, :millisecond)
    Logger.info("image_pipe result=#{metadata.result} duration_ms=#{duration_ms}")
  end
end

Call MyApp.ImagePipeTelemetry.attach() at startup. To subscribe to several events, use :telemetry.attach_many/4. Event names start with telemetry_prefix, [:image_pipe] by default (see ImagePipe.config/1). If you set another prefix, use it in the event names here.

For metrics, give the same event names to Telemetry.Metrics and choose which metadata keys become tags.

Request IDs

ImagePipe uses your app's request ID. Run Plug.RequestId before the ImagePipe mount (Phoenix endpoints do by default). It sets the x-request-id response header and Logger.metadata[:request_id].

Every process that serves the request, including the processing pool and the cache writer, keeps the caller's Logger metadata. Log lines and handlers therefore see the same :request_id as the connection process:

def handle_event(_event, _measurements, _metadata, _config) do
  request_id = Logger.metadata()[:request_id]
  # ...
end

Event metadata has no request ID field of its own. Background cache refreshes run outside any request, so they have no request ID. Traces correlate by trace ID instead (see request tracing).

What events contain

Event metadata leaves out origin credentials and the signing and encryption keys. The path on [:request] and the summary ends at the source, as in /w=200/src/REDACTED, and each wm-src64= value is REDACTED. It keeps the URL signature, which authorizes only that URL.

Once a request parses, :source_url and :watermark_source_urls show its sources as ImagePipe parsed them: decoded from src64, or decrypted from enc, so an encrypted source is visible to anyone who reads your telemetry. Each query value, such as a presigned URL's X-Amz-Signature, is replaced with REDACTED. So is each query part without a value, such as &token, and a user name and password. A request that fails before it parses, such as one with a bad signature, has only the path.

Metadata does include values that can have many distinct values, such as paths, preset names, operation parameters, and image sizes. Choose which ones become metrics tags.

If your handler adds a source URL itself, for example from conn, strip any credentials it carries before logging it or sending it to a third party.

Next steps