Observability #

Logs, spans, and metrics are effects. They carry their context with them.

The problem. After an incident, you must find out what happened. In plain TypeScript, the answer is console.log in every function. Each line builds its own context by hand:

async function chargeCard(order: Order) {
  console.log(`[${new Date().toISOString()}] [INFO] charge order ${order.id} for user ${order.userId}`)
  const result = await gateway.charge(order)
  console.log(`[${new Date().toISOString()}] [INFO] charged order ${order.id} for user ${order.userId} in ${Date.now() - start}ms`)
}

Every line repeats the order id and the user id. If you forget one, that line is useless when you search for the order. You measure time with Date.now() by hand. Later, the team adds a global APM agent. The agent does not know which request a function call belongs to. That context is in local variables, and the agent cannot see it.

The shift

Today you think of a log line as text that a function prints. In Effect, a log line, a span, and a metric update are effects. They run inside a fiber. A fiber is the unit that runs an effect, and it carries context with it. When you write Effect.annotateLogs(handler, { requestId }), every log line inside handler gets requestId. This includes log lines in functions that handler calls. You do not pass the id around. When you put an effect inside Effect.withSpan("charge"), every span inside it becomes a child span. The trace tree is the same as the call tree.

The logger, the tracer, and the metric registry are services. This is the benefit: you can change the logger to a JSON logger in production, to a silent logger in tests, or to a plain logger in this playground. You do not change one Effect.log call. To export spans to OpenTelemetry, you provide one layer at the edge of the app.

Task Plain TypeScript Effect
Write a log line console.log("...") with manual format Effect.logInfo("..."), the Logger service sets the format
Add context Pass ids into every function Effect.annotateLogs one time, all inner code gets it
Measure an operation Date.now() before and after Effect.withSpan("name"), child spans are automatic
Count events A module-level let count = 0 Metric.counter("name"), read it with Metric.value
Change the backend Change every call site Provide a different layer

Note: the default logger prints a timestamp and a fiber id on every line. This output changes on every run. Lesson 1 builds a small logger with stable output, and all other lessons use it. That is also the first lesson: the logger is a service that you own.

Learn #

Lesson 1. Replace the logger #

Effect.log and the related functions do not print. They send a log event to the Logger services that are installed. The default logger prints a line like this:

[13:42:07.118] INFO (#12): starting v1

The timestamp and the fiber number change on every run. You cannot compare this output in a test or in this playground. The first thing to learn is that you can replace the logger.

Logger.make takes a function. The function gets the log event. The event has a message (an array, because Effect.log("a", 1) accepts more than 1 value), a logLevel, the fiber, a cause, and a date. Our logger builds a short string and prints it with console.log.

Logger.layer([plain]) is a layer. It replaces the current set of loggers with the loggers in the list. Provide it around the program. Every Effect.log inside the program now goes to plain only. The program did not change.

import { Effect, Logger } from "effect"

// A Logger is a service. This one prints only the level and the message,
// so the output is stable from run to run.
const plain = Logger.make<unknown, void>(({ logLevel, message }) => {
  const text = Array.isArray(message) ? message.join(" ") : String(message)
  console.log("[" + logLevel + "] " + text)
})

const program = Effect.gen(function* () {
  yield* Effect.log("starting", "v1")       // Effect.log uses the Info level
  yield* Effect.logInfo("loaded 3 users")
  yield* Effect.logWarning("cache miss")
  yield* Effect.logError("payment declined")
})

// Logger.layer([...]) REPLACES the default loggers with the ones listed
Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

Remove the line Effect.provide(Logger.layer([plain])) and run again. The same 4 lines appear, but the default logger prints them with timestamps. Add { mergeWithExisting: true } as the second argument of Logger.layer. Now both loggers print. The program did not change. Only the service changed.

Lesson 2. Log levels and the minimum level #

Every log call has a level. This table lists the levels from the most severe to the least severe:

Function Level Shown by default?
Effect.logFatal Fatal yes
Effect.logError Error yes
Effect.logWarning Warn yes
Effect.logInfo / Effect.log Info yes
Effect.logDebug Debug no
Effect.logTrace Trace no

The limit is a fiber-local value with the name References.MinimumLogLevel. The default is "Info". This is why debug lines do not appear. In Effect v4, a value of this type is a Context.Reference. A reference is a service with a default value. You change it for one part of the program with Effect.provideService. In a layer, you use Layer.succeed.

The filter runs before the logger. A filtered line has almost no cost. You can keep logDebug calls in the code and turn them on only when you need them.

import { Effect, Logger, References } from "effect"

const plain = Logger.make<unknown, void>(({ logLevel, message }) => {
  console.log("[" + logLevel + "] " + (Array.isArray(message) ? message.join(" ") : String(message)))
})

const work = Effect.gen(function* () {
  yield* Effect.logDebug("query plan: index scan")
  yield* Effect.logInfo("found 2 rows")
  yield* Effect.logWarning("slow query")
})

const runAt = (level: "Debug" | "Info" | "Warn") => {
  console.log("-- minimum " + level)
  Effect.runSync(
    work.pipe(
      Effect.provideService(References.MinimumLogLevel, level),  // override the reference for this region
      Effect.provide(Logger.layer([plain]))
    )
  )
}

runAt("Info")   // the default: Debug is hidden
runAt("Debug")  // everything
runAt("Warn")   // only Warn and above
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

In v3, the name of this function was Logger.withMinimumLogLevel. In v4, the minimum level is a reference. You can also read it: const level = yield* References.MinimumLogLevel. Add this line to work and print the level.

Lesson 3. Annotations travel with the fiber #

In plain TypeScript, you pass a request id into every function to get it into every log line. In Effect, you use Effect.annotateLogs. It attaches key/value pairs to one part of the program. Every log event inside that part gets the pairs. The depth of the call does not matter.

The annotations are in a reference with the name References.CurrentLogAnnotations. Our logger reads the annotations from the fiber that sent the event, with fiber.getRef(...). A production logger, for example the JSON logger, prints the annotations as fields. This is what makes structured logs searchable.

Nested annotateLogs calls merge. The inner part sees the outer keys and its own keys. When the part ends, the annotations are removed. Nothing goes to the next request.

import { Effect, Logger, References } from "effect"

const plain = Logger.make<unknown, void>(({ logLevel, message, fiber }) => {
  const text = Array.isArray(message) ? message.join(" ") : String(message)
  // Read the annotations of the fiber that logged
  const annotations = fiber.getRef(References.CurrentLogAnnotations)
  const extra = Object.entries(annotations).map(([k, v]) => " " + k + "=" + String(v)).join("")
  console.log("[" + logLevel + "] " + text + extra)
})

// loadCart knows nothing about request ids, yet its log lines will carry one
const loadCart = (userId: string) =>
  Effect.gen(function* () {
    yield* Effect.logInfo("loading cart")
    return ["book", "pen"]
  }).pipe(Effect.annotateLogs("userId", userId))   // inner region adds userId

const handle = (requestId: string, userId: string) =>
  Effect.gen(function* () {
    yield* Effect.logInfo("request received")
    const items = yield* loadCart(userId)
    yield* Effect.logInfo("done with " + items.length + " items")
  }).pipe(Effect.annotateLogs({ requestId }))      // outer region adds requestId

const program = Effect.gen(function* () {
  yield* handle("r-1", "ada")
  yield* handle("r-2", "lin")
})

Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

Note: the line "done with 2 items" does not have userId. That annotation belonged to the loadCart part, and that part has ended. If an annotation must stay until the end of the current scope, use Effect.annotateLogsScoped.

Lesson 4. Log spans: how long has this part run? #

Effect.withLogSpan(effect, "label") marks a part of the program with a label and a start time. Every log line inside that part shows how long the part has run. This is a cheap way to find slow steps without a full trace setup. A production logger prints it as label=12ms.

We cannot show real milliseconds here. Our logger prints only the labels. The labels are in References.CurrentLogSpans as [label, startTime] pairs, newest first. We reverse the list to read from outer to inner.

Compare this with lesson 3. Annotations are values that you attach. Log spans are timers that you start. Both travel with the fiber, and both are removed when their part ends. Lesson 5 covers trace spans. A trace span is the same idea, but for a tracer instead of a logger.

import { Effect, Logger, References } from "effect"

const plain = Logger.make<unknown, void>(({ message, fiber }) => {
  const text = Array.isArray(message) ? message.join(" ") : String(message)
  // Each entry is [label, startTimestamp]; a real logger would print the elapsed ms
  const labels = fiber.getRef(References.CurrentLogSpans).map(([label]) => label).reverse()
  console.log(text + (labels.length ? "  spans: " + labels.join(" > ") : ""))
})

const query = Effect.logInfo("running query").pipe(Effect.withLogSpan("db"))

const handler = Effect.gen(function* () {
  yield* Effect.logInfo("start")
  yield* query
  yield* Effect.logInfo("respond")
}).pipe(Effect.withLogSpan("request"))

const program = Effect.gen(function* () {
  yield* Effect.logInfo("boot")   // no span active here
  yield* handler
})

Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

Replace plain with Logger.consoleLogFmt, one of the built-in loggers, and look at the output. You see fields like request=3ms db=1ms with real durations, and a timestamp. This is why the expected output does not use it.

Lesson 5. Trace spans nest like your calls #

A span is a unit of work in a trace. It has a name, a start time, and an end time. Effect.withSpan(effect, "name") makes a span around an effect. The span ends when the effect ends. This is true when the effect succeeds, fails, or is interrupted. Every span made inside becomes a child of it, because the fiber carries the current span. A trace viewer can show checkout > charge > gateway as a tree, and you do not connect parent ids by hand.

A span has attributes. You can set them when you make the span, with { attributes: { ... } }. You can also set them later from inside the span, with Effect.annotateCurrentSpan.

Effect.currentSpan gives the active span. We use it to print the name of the span, the name of its parent, and its attributes. This output is stable. In a real app you do not read spans yourself. You provide a tracer layer, for example the OTLP tracer from effect/unstable/observability, and every span is exported. Note: currentSpan fails with NoSuchElementError when no span is active. Its error type is not never.

import { Effect, Option } from "effect"

// Print where we are in the trace tree
const whereAmI = Effect.gen(function* () {
  const span = yield* Effect.currentSpan
  const parent = Option.match(span.parent, {
    onNone: () => "none",
    onSome: (p) => (p._tag === "Span" ? p.name : "external")
  })
  const attrs = JSON.stringify(Object.fromEntries(span.attributes))
  console.log(span.name + "  parent=" + parent + "  attrs=" + attrs)
})

const charge = Effect.gen(function* () {
  yield* Effect.annotateCurrentSpan("amount", 42)   // add an attribute from inside
  yield* whereAmI
}).pipe(Effect.withSpan("charge", { attributes: { gateway: "acme" } }))

const checkout = Effect.gen(function* () {
  yield* whereAmI
  yield* charge          // becomes a child of "checkout" automatically
  yield* whereAmI        // back in "checkout"
}).pipe(Effect.withSpan("checkout", { attributes: { orderId: "o-1" } }))

Effect.runSync(checkout)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

Effect.fn("name") is a short form. It puts the body of a function inside a span with the name of the function. This is the usual way to trace service methods. Replace the checkout definition with Effect.fn("checkout")(function* () { ... }) and call checkout().

Lesson 6. Metrics: counter, gauge, histogram #

A log tells you what happened one time. A metric tells you how often and how much, at low cost, over time. Effect has a small set of metric types:

Metric Records update does Use it for
Metric.counter A total Adds the input Requests served, errors seen
Metric.gauge 1 current value Replaces the value (modify adds) Queue length, memory in use
Metric.histogram A distribution in buckets Records 1 observation Latency, payload size
Metric.frequency A count for each string Adds 1 to that string Status codes, error tags

You make a metric with a name. A description and attributes are optional. Metric.update(metric, value) records a value. Metric.value(metric) reads the current state, and we print that state. Metrics are registered in the Metric.MetricRegistry reference. An exporter layer can find all of them by name.

The state of a histogram has count, min, max, sum, and buckets. For each upper limit that you gave, a bucket holds the number of observations that are equal to or below that limit.

import { Effect, Metric } from "effect"

const requests = Metric.counter("requests_total", { description: "requests served" })
const queueSize = Metric.gauge("queue_size")
const latency = Metric.histogram("latency_ms", { boundaries: [10, 50, 100] })

const program = Effect.gen(function* () {
  yield* Metric.update(requests, 1)
  yield* Metric.update(requests, 4)      // counter: add

  yield* Metric.update(queueSize, 7)     // gauge: set to 7
  yield* Metric.modify(queueSize, -2)    // gauge: add -2, now 5

  for (const ms of [5, 30, 75, 300]) {
    yield* Metric.update(latency, ms)    // histogram: one observation each
  }

  const r = yield* Metric.value(requests)
  const q = yield* Metric.value(queueSize)
  const h = yield* Metric.value(latency)
  console.log("requests:", r.count)
  console.log("queue:", q.value)
  console.log("latency count", h.count, "min", h.min, "max", h.max, "sum", h.sum)
  console.log("buckets", JSON.stringify(h.buckets))   // [upperBound, observationsAtOrBelow]
})

Effect.runSync(program)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).
Notice

The bucket counts are cumulative. The value 30 ms is at or below 50, and also at or below 100. The value 300 ms is above every limit, so it appears only in count and sum. Add yield* Metric.dump and print the result. It shows every registered metric as a table.

Do and don't #

DoDon'tWhy
Provide Logger.layer([...]) 1 time, at the edge of the app.Do not format log lines by hand with console.log inside effects.A hand-made line has no level, no annotations, and no span, and you cannot change its destination without a change to the code.
Write yield* Effect.logInfo(...) for every log call.Do not write Effect.logInfo(...) on its own line without yield*.A log call is an effect; without yield* the effect is made and dropped, and nothing prints.
Change the minimum level with Effect.provideService(References.MinimumLogLevel, "Debug") for the part that you debug.Do not remove logDebug calls when you do not see them.The default minimum level is "Info"; the debug lines are filtered, not lost, and a filtered line has almost no cost.
Put Effect.annotateLogs({ requestId }) on the full handler.Do not add the request id to each message string.An annotation on the handler reaches every log line inside, and also the lines from the functions that the handler calls.
Catch the NoSuchElementError of Effect.currentSpan, for example with Effect.orElseSucceed.Do not give Effect.currentSpan the type Effect<Span>.When no span is active, currentSpan fails, and an annotation with never as the error type does not compile.
Use Metric.modify to add to a gauge.Do not use Metric.update when you want to add to a gauge.On a gauge, update replaces the current value, so update(queue, -2) sets the queue size to -2.
Give Effect.track a metric that accepts an Exit, for example Metric.withConstantInput(1).Do not pass a plain Counter<number> to Effect.track.Effect.track records the Exit of the effect, and a counter of numbers does not accept an Exit, so the program does not compile.

Fix it #

Each program below is broken or incomplete. Make it print the expected output with zero type errors. Use hints before the solution.

1. The silent log #

Only the first 2 lines appear. The warning is absent. Change the program so that all 3 log lines print, in this order.

expected output: [Info] connecting [Info] connected [Warn] using fallback region
import { Effect, Logger } from "effect"

const plain = Logger.make<unknown, void>(({ logLevel, message }) => {
  console.log("[" + logLevel + "] " + (Array.isArray(message) ? message.join(" ") : String(message)))
})

const program = Effect.gen(function* () {
  yield* Effect.logInfo("connecting")
  yield* Effect.logInfo("connected")
  Effect.logWarning("using fallback region")
})

Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

2. The absent debug line #

The program must print the debug line, but the line is filtered out. Change the configuration of the program, not the log call, so that all 3 lines print.

expected output: [Info] importing 3 files [Debug] file a.csv: 120 rows [Info] import finished
import { Effect, Logger } from "effect"

const plain = Logger.make<unknown, void>(({ logLevel, message }) => {
  console.log("[" + logLevel + "] " + (Array.isArray(message) ? message.join(" ") : String(message)))
})

const program = Effect.gen(function* () {
  yield* Effect.logInfo("importing 3 files")
  yield* Effect.logDebug("file a.csv: 120 rows")
  yield* Effect.logInfo("import finished")
})

Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

3. The annotation in the wrong place #

Both log lines must have requestId=r-9, but only the second line has it. Move the annotation so that the full request is annotated.

expected output: [Info] validating requestId=r-9 [Info] saving requestId=r-9
import { Effect, Logger, References } from "effect"

const plain = Logger.make<unknown, void>(({ logLevel, message, fiber }) => {
  const text = Array.isArray(message) ? message.join(" ") : String(message)
  const annotations = fiber.getRef(References.CurrentLogAnnotations)
  const extra = Object.entries(annotations).map(([k, v]) => " " + k + "=" + String(v)).join("")
  console.log("[" + logLevel + "] " + text + extra)
})

const handle = (requestId: string) =>
  Effect.gen(function* () {
    yield* Effect.logInfo("validating")
    yield* Effect.logInfo("saving").pipe(Effect.annotateLogs({ requestId }))
  })

Effect.runSync(handle("r-9").pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

4. currentSpan can fail #

spanName must be an Effect<string> that gives the name of the current span, or "no span" when there is no span. The program does not compile. Change spanName only. Do not change its type annotation or the program below it.

expected output: outside: no span inside: checkout
import { Effect } from "effect"

const spanName: Effect.Effect<string> = Effect.currentSpan.pipe(
  Effect.map((span) => span.name)
)

const program = Effect.gen(function* () {
  console.log("outside:", yield* spanName)
  console.log("inside:", yield* spanName.pipe(Effect.withSpan("checkout")))
})

Effect.runSync(program)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

5. Set or add? #

The gauge must end at 5 (7 items arrived, 2 items were processed), but it prints -2. Change the second metric call.

expected output: queue: 5
import { Effect, Metric } from "effect"

const queue = Metric.gauge("queue_size")

const program = Effect.gen(function* () {
  yield* Metric.update(queue, 7)
  yield* Metric.update(queue, -2)
  const state = yield* Metric.value(queue)
  console.log("queue:", state.value)
})

Effect.runSync(program)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

6. Track an effect with a counter #

Effect.track must add 1 to runs each time job runs, but the program does not compile. Change the counter definition so that the program prints runs: 3.

expected output: runs: 3
import { Effect, Metric } from "effect"

const runs = Metric.counter("job_runs")

const job = Effect.succeed("ok").pipe(Effect.track(runs))

const program = Effect.gen(function* () {
  yield* job
  yield* job
  yield* job
  const state = yield* Metric.value(runs)
  console.log("runs:", state.count)
})

Effect.runSync(program)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

Build it #

Write the program from the spec. The output must match exactly.

1. Structured request log #

Build a small request pipeline with structured logs and a counter.

  1. Write a logger plain with Logger.make. It must print <LEVEL> <message> <key>=<value>.... LEVEL is the log level in upper case. The message parts are joined with spaces. The annotations (from References.CurrentLogAnnotations) follow in insertion order, each as key=value.
  2. Write handle(requestId, path) as an Effect.gen. It must log "handling" at Info, add 1 to the counter served, and log "unknown path" at Warn when path is not "/" and not "/health". Annotate the full handler with { requestId, path }.
  3. program must call handle for ("r-1", "/"), ("r-2", "/admin"), ("r-3", "/health") in this order. Then it must print served: <count> with console.log.

Run the program with the plain logger provided. Exact output:

INFO handling requestId=r-1 path=/
INFO handling requestId=r-2 path=/admin
WARN unknown path requestId=r-2 path=/admin
INFO handling requestId=r-3 path=/health
served: 3
expected output: INFO handling requestId=r-1 path=/ INFO handling requestId=r-2 path=/admin WARN unknown path requestId=r-2 path=/admin INFO handling requestId=r-3 path=/health served: 3
import { Effect, Logger, Metric, References } from "effect"

const served = Metric.counter("served")

// TODO: plain logger printing "<LEVEL> <message> key=value..."
const plain = Logger.make<unknown, void>((options) => {
  throw new Error("TODO")
})

// TODO: handle(requestId, path)

const program = Effect.gen(function* () {
  // TODO: handle the three requests, then print "served: <count>"
})

Effect.runSync(program.pipe(Effect.provide(Logger.layer([plain]))))
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

2. Traced checkout with a price histogram #

Trace a checkout and measure the item prices.

  1. Write enter, an effect that reads Effect.currentSpan and prints enter <name> (parent: <parentName or none>). If the parent is an external span, print external.
  2. Write priceItem(name, price). It must record price into the histogram prices (boundaries [10, 50]), then run enter. Wrap it in a span with the name price:<name>.
  3. Write checkout. It must run enter, then priceItem for ("book", 12), ("pen", 3), ("desk", 180), then print items: <count> total: <sum> from Metric.value(prices). Wrap it in a span with the name checkout.

Exact output:

enter checkout (parent: none)
enter price:book (parent: checkout)
enter price:pen (parent: checkout)
enter price:desk (parent: checkout)
items: 3 total: 195
buckets: [[10,1],[50,2]]

The last line is JSON.stringify of the buckets of the histogram.

expected output: enter checkout (parent: none) enter price:book (parent: checkout) enter price:pen (parent: checkout) enter price:desk (parent: checkout) items: 3 total: 195 buckets: [[10,1],[50,2]]
import { Effect, Metric, Option } from "effect"

const prices = Metric.histogram("item_price", { boundaries: [10, 50] })

// TODO: enter prints "enter <span> (parent: <parent or none>)"

// TODO: priceItem(name, price) records the price, runs enter, in span "price:<name>"

const checkout = Effect.gen(function* () {
  // TODO
}).pipe(Effect.withSpan("checkout"))

Effect.runSync(checkout)
⌘/Ctrl + Enter
Press Run (or ⌘/Ctrl+Enter in the editor).

Recall #

Answer in your head first, then reveal. Come back to these tomorrow.

Why does `Effect.log` print nothing by itself, and what decides the format? #

Effect.log sends a log event to the current set of Logger services. The loggers decide the format and the destination. Logger.layer([...]) replaces that set. The option { mergeWithExisting: true } adds to it.

What is the type of `Effect.currentSpan`, and why is it not `Effect<Span>`? #

Effect<Span, NoSuchElementError>. There can be no active span. Effect shows that failure in the error channel. It does not return undefined.

How do you show `Effect.logDebug` lines in v4? #

Change the References.MinimumLogLevel reference for the part of the program: Effect.provideService(References.MinimumLogLevel, "Debug"). In a layer, use Layer.succeed(References.MinimumLogLevel, "Debug"). The default is "Info".

Which function do you use to attach a `requestId` to every log line in a handler, and also to the lines from the functions that the handler calls? #

Effect.annotateLogs(handler, { requestId }). The annotations travel with the fiber. The inner calls get them, and you do not pass the id as an argument.

What is the difference between `Metric.update` and `Metric.modify` on a gauge? #

update sets the gauge to the given value. modify adds the value to the current value. On a counter, both functions add.

How does a span know its parent? #

The fiber carries the current span. Effect.withSpan reads it, makes a child span, and makes the child the current span for the wrapped effect. When the effect ends, the span is closed and the parent is the current span again.