add Logger batching and structured logging (#2270)

Author: tim-smart

.changeset/flat-toys-flash.md

@@ -0,0 +1,13 @@
+---
+"effect": patch
+---
+
+add structured logging apis
+
+- Logger.json / Logger.jsonLogger
+- Logger.structured / Logger.structuredLogger
+
+`Logger.json` logs JSON serialized strings to the console.
+
+`Logger.structured` logs structured objects, which is useful in the browser
+where you can inspect objects logged to the console.

.changeset/sharp-bottles-add.md

@@ -0,0 +1,28 @@
+---
+"effect": patch
+---
+
+add Logger.batched, for batching logger output
+
+It takes a duration window and an effectful function that processes the batched output.
+
+Example:
+
+```ts
+import { Console, Effect, Logger } from "effect";
+
+const LoggerLive = Logger.replaceScoped(
+  Logger.defaultLogger,
+  Logger.logfmtLogger.pipe(
+    Logger.batched("500 millis", (messages) =>
+      Console.log("BATCH", messages.join("\n"))
+    )
+  )
+);
+
+Effect.gen(function* (_) {
+  yield* _(Effect.log("one"));
+  yield* _(Effect.log("two"));
+  yield* _(Effect.log("three"));
+}).pipe(Effect.provide(LoggerLive), Effect.runFork);
+```

packages/effect/src/Logger.ts

@@ -2,6 +2,7 @@
  * @since 2.0.0
  */
 import type * as Cause from "./Cause.js"
+import type { DurationInput } from "./Duration.js"
 import type { Effect } from "./Effect.js"
 import type * as FiberId from "./FiberId.js"
 import type * as FiberRefs from "./FiberRefs.js"
@@ -158,6 +159,39 @@ export const map: {
   ): Logger<Message, Output2>
 } = internal.map
 
+/**
+ * @since 2.0.0
+ * @category mapping
+ * @example
+ * import { Console, Effect, Logger } from "effect";
+ *
+ * const LoggerLive = Logger.replaceScoped(
+ *   Logger.defaultLogger,
+ *   Logger.logfmtLogger.pipe(
+ *     Logger.batched("500 millis", (messages) =>
+ *       Console.log("BATCH", messages.join("\n"))
+ *     )
+ *   )
+ * );
+ *
+ * Effect.gen(function* (_) {
+ *   yield* _(Effect.log("one"));
+ *   yield* _(Effect.log("two"));
+ *   yield* _(Effect.log("three"));
+ * }).pipe(Effect.provide(LoggerLive), Effect.runFork);
+ */
+export const batched: {
+  <Output, R>(
+    window: DurationInput,
+    f: (messages: Array<Types.NoInfer<Output>>) => Effect<void, never, R>
+  ): <Message>(self: Logger<Message, Output>) => Effect<Logger<Message, void>, never, R | Scope>
+  <Message, Output, R>(
+    self: Logger<Message, Output>,
+    window: DurationInput,
+    f: (messages: Array<Types.NoInfer<Output>>) => Effect<void, never, R>
+  ): Effect<Logger<Message, void>, never, Scope | R>
+} = fiberRuntime.batchedLogger
+
 /**
  * A logger that does nothing in response to logging events.
  *
@@ -298,6 +332,12 @@ export const zipRight: {
  */
 export const defaultLogger: Logger<unknown, void> = fiberRuntime.defaultLogger
 
+/**
+ * @since 2.0.0
+ * @category constructors
+ */
+export const jsonLogger: Logger<unknown, string> = internal.jsonLogger
+
 /**
  * @since 2.0.0
  * @category constructors
@@ -310,18 +350,47 @@ export const logfmtLogger: Logger<unknown, string> = internal.logfmtLogger
  */
 export const stringLogger: Logger<unknown, string> = internal.stringLogger
 
+/**
+ * @since 2.0.0
+ * @category constructors
+ */
+export const structuredLogger: Logger<
+  unknown,
+  {
+    readonly logLevel: string
+    readonly fiberId: string
+    readonly timestamp: string
+    readonly message: unknown
+    readonly cause: string | undefined
+    readonly annotations: Record<string, unknown>
+    readonly spans: Record<string, number>
+  }
+> = internal.structuredLogger
+
 /**
  * @since 2.0.0
  * @category constructors
  */
 export const tracerLogger: Logger<unknown, void> = fiberRuntime.tracerLogger
 
+/**
+ * @since 2.0.0
+ * @category constructors
+ */
+export const json: Layer.Layer<never> = replace(fiberRuntime.defaultLogger, fiberRuntime.jsonLogger)
+
 /**
  * @since 2.0.0
  * @category constructors
  */
 export const logFmt: Layer.Layer<never> = replace(fiberRuntime.defaultLogger, fiberRuntime.logFmtLogger)
 
+/**
+ * @since 2.0.0
+ * @category constructors
+ */
+export const structured: Layer.Layer<never> = replace(fiberRuntime.defaultLogger, fiberRuntime.structuredLogger)
+
 /**
  * @since 2.0.0
  * @category context

packages/effect/src/internal/fiberRuntime.ts

@@ -5,6 +5,7 @@ import type * as Clock from "../Clock.js"
 import type { ConfigProvider } from "../ConfigProvider.js"
 import * as Context from "../Context.js"
 import * as Deferred from "../Deferred.js"
+import type * as Duration from "../Duration.js"
 import type * as Effect from "../Effect.js"
 import { EffectTypeId } from "../Effectable.js"
 import type * as Either from "../Either.js"
@@ -1361,6 +1362,16 @@ export const defaultLogger: Logger<unknown, void> = globalValue(
     })
 )
 
+/** @internal */
+export const jsonLogger: Logger<unknown, void> = globalValue(
+  Symbol.for("effect/Logger/jsonLogger"),
+  () =>
+    internalLogger.makeLogger((options) => {
+      const formatted = internalLogger.jsonLogger.log(options)
+      getConsole(options.context).log(formatted)
+    })
+)
+
 /** @internal */
 export const logFmtLogger: Logger<unknown, void> = globalValue(
   Symbol.for("effect/Logger/logFmtLogger"),
@@ -1371,6 +1382,16 @@ export const logFmtLogger: Logger<unknown, void> = globalValue(
     })
 )
 
+/** @internal */
+export const structuredLogger: Logger<unknown, void> = globalValue(
+  Symbol.for("effect/Logger/structuredLogger"),
+  () =>
+    internalLogger.makeLogger((options) => {
+      const formatted = internalLogger.structuredLogger.log(options)
+      getConsole(options.context).log(formatted)
+    })
+)
+
 /** @internal */
 export const tracerLogger = globalValue(
   Symbol.for("effect/Logger/tracerLogger"),
@@ -1434,6 +1455,54 @@ export const currentLoggers: FiberRef.FiberRef<
   () => core.fiberRefUnsafeMakeHashSet(HashSet.make(defaultLogger, tracerLogger))
 )
 
+/** @internal */
+export const batchedLogger = dual<
+  <Output, R>(
+    window: Duration.DurationInput,
+    f: (messages: Array<NoInfer<Output>>) => Effect.Effect<void, never, R>
+  ) => <Message>(
+    self: Logger<Message, Output>
+  ) => Effect.Effect<Logger<Message, void>, never, Scope.Scope | R>,
+  <Message, Output, R>(
+    self: Logger<Message, Output>,
+    window: Duration.DurationInput,
+    f: (messages: Array<NoInfer<Output>>) => Effect.Effect<void, never, R>
+  ) => Effect.Effect<Logger<Message, void>, never, Scope.Scope | R>
+>(3, <Message, Output, R>(
+  self: Logger<Message, Output>,
+  window: Duration.DurationInput,
+  f: (messages: Array<NoInfer<Output>>) => Effect.Effect<void, never, R>
+): Effect.Effect<Logger<Message, void>, never, Scope.Scope | R> =>
+  core.flatMap(scope, (scope) => {
+    let buffer: Array<Output> = []
+    const flush = core.suspend(() => {
+      if (buffer.length === 0) {
+        return core.unit
+      }
+      const arr = buffer
+      buffer = []
+      return f(arr)
+    })
+
+    return core.uninterruptibleMask((restore) =>
+      pipe(
+        internalEffect.sleep(window),
+        core.zipRight(flush),
+        internalEffect.forever,
+        restore,
+        forkDaemon,
+        core.flatMap((fiber) => core.scopeAddFinalizer(scope, core.interruptFiber(fiber))),
+        core.zipRight(addFinalizer(() => flush)),
+        core.as(
+          internalLogger.makeLogger((options) => {
+            buffer.push(self.log(options))
+            console.log(buffer)
+          })
+        )
+      )
+    )
+  }))
+
 // circular with Effect
 
 /* @internal */

packages/effect/src/internal/logger.ts

@@ -215,7 +215,7 @@ export const stringLogger: Logger.Logger<unknown, string> = makeLogger<unknown,
 
 export const serializeUnknown = (u: unknown): string => {
   try {
-    return typeof u === "object" ? JSON.stringify(u) : String(u)
+    return typeof u === "object" ? jsonStringifyCircular(u) : String(u)
   } catch (_) {
     return String(u)
   }
@@ -288,6 +288,76 @@ export const logfmtLogger = makeLogger<unknown, string>(
   }
 )
 
+/** @internal */
+export const structuredLogger = makeLogger<unknown, {
+  readonly logLevel: string
+  readonly fiberId: string
+  readonly timestamp: string
+  readonly message: unknown
+  readonly cause: string | undefined
+  readonly annotations: Record<string, unknown>
+  readonly spans: Record<string, number>
+}>(
+  ({ annotations, cause, date, fiberId, logLevel, message, spans }) => {
+    const now = date.getTime()
+    const annotationsObj: Record<string, unknown> = {}
+    const spansObj: Record<string, number> = {}
+
+    if (HashMap.size(annotations) > 0) {
+      for (const [k, v] of annotations) {
+        annotationsObj[k] = structuredMessage(v)
+      }
+    }
+
+    if (List.isCons(spans)) {
+      for (const span of spans) {
+        spansObj[span.label] = now - span.startTime
+      }
+    }
+
+    return {
+      message: structuredMessage(message),
+      logLevel: logLevel.label,
+      timestamp: date.toISOString(),
+      cause: Cause.isEmpty(cause) ? undefined : Cause.pretty(cause),
+      annotations: annotationsObj,
+      spans: spansObj,
+      fiberId: _fiberId.threadName(fiberId)
+    }
+  }
+)
+
+export const structuredMessage = (u: unknown): unknown => {
+  switch (typeof u) {
+    case "bigint":
+    case "function":
+    case "symbol": {
+      return String(u)
+    }
+    default: {
+      return u
+    }
+  }
+}
+
+const jsonStringifyCircular = (obj: unknown) => {
+  let cache: Array<unknown> = []
+  const retVal = JSON.stringify(
+    obj,
+    (_key, value) =>
+      typeof value === "object" && value !== null
+        ? cache.includes(value)
+          ? undefined // circular reference
+          : cache.push(value) && value
+        : value
+  )
+  ;(cache as any) = undefined
+  return retVal
+}
+
+/** @internal */
+export const jsonLogger = map(structuredLogger, jsonStringifyCircular)
+
 /** @internal */
 const filterKeyName = (key: string) => key.replace(/[\s="]/g, "_")
 

packages/effect/test/Logger.test.ts

@@ -1,5 +1,6 @@
 import * as Cause from "effect/Cause"
 import * as Chunk from "effect/Chunk"
+import * as Effect from "effect/Effect"
 import * as FiberId from "effect/FiberId"
 import * as FiberRefs from "effect/FiberRefs"
 import { identity } from "effect/Function"
@@ -8,7 +9,7 @@ import { logLevelInfo } from "effect/internal/core"
 import * as List from "effect/List"
 import * as Logger from "effect/Logger"
 import * as LogSpan from "effect/LogSpan"
-import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"
+import { afterEach, assert, beforeEach, describe, expect, it, vi } from "vitest"
 
 describe("stringLogger", () => {
   beforeEach(() => {
@@ -183,7 +184,7 @@ describe("logfmtLogger", () => {
     })
 
     expect(result).toEqual(
-      `timestamp=${date.toJSON()} level=INFO fiber= message="[object Object]"`
+      `timestamp=${date.toJSON()} level=INFO fiber= message="{\\"hello\\":\\"world\\"}"`
     )
   })
 
@@ -248,4 +249,202 @@ describe("logfmtLogger", () => {
       `timestamp=${date.toJSON()} level=INFO fiber= message="hello world" hashmap="{\\"_id\\":\\"HashMap\\",\\"values\\":[[\\"key\\",2]]}" chunk="{\\"_id\\":\\"Chunk\\",\\"values\\":[1,2]}"`
     )
   })
+
+  it("batched", () =>
+    Effect.gen(function*(_) {
+      const chunks: Array<Array<string>> = []
+      const date = new Date()
+      vi.setSystemTime(date)
+      const logger = yield* _(
+        Logger.logfmtLogger,
+        Logger.batched("100 millis", (_) =>
+          Effect.sync(() => {
+            chunks.push(_)
+          }))
+      )
+      const log = (message: string) =>
+        logger.log({
+          fiberId: FiberId.none,
+          logLevel: logLevelInfo,
+          message,
+          cause: Cause.empty,
+          context: FiberRefs.unsafeMake(new Map()),
+          spans: List.empty(),
+          annotations: HashMap.empty(),
+          date
+        })
+
+      log("a")
+      log("b")
+      log("c")
+      yield* _(Effect.promise(() => vi.advanceTimersByTimeAsync(100)))
+      log("d")
+      log("e")
+      yield* _(Effect.promise(() => vi.advanceTimersByTimeAsync(100)))
+
+      assert.deepStrictEqual(chunks, [
+        [
+          `timestamp=${date.toISOString()} level=INFO fiber= message=a`,
+          `timestamp=${date.toISOString()} level=INFO fiber= message=b`,
+          `timestamp=${date.toISOString()} level=INFO fiber= message=c`
+        ],
+        [
+          `timestamp=${date.toISOString()} level=INFO fiber= message=d`,
+          `timestamp=${date.toISOString()} level=INFO fiber= message=e`
+        ]
+      ])
+    }).pipe(Effect.scoped, Effect.runPromise))
+})
+
+describe("jsonLogger", () => {
+  beforeEach(() => {
+    vi.useFakeTimers()
+  })
+  afterEach(() => {
+    vi.useRealTimers()
+  })
+
+  it("keys with special chars", () => {
+    const date = new Date()
+    vi.setSystemTime(date)
+    const spans = List.make(LogSpan.make("imma span=\"", date.getTime() - 7))
+    const annotations = HashMap.make(
+      ["just_a_key", "just_a_value"],
+      ["I am bad key name", { coolValue: "cool value" }],
+      ["good_key", "I am a good value"],
+      ["good_bool", true],
+      ["good_number", 123]
+    )
+
+    const result = Logger.jsonLogger.log({
+      fiberId: FiberId.none,
+      logLevel: logLevelInfo,
+      message: "My message",
+      cause: Cause.empty,
+      context: FiberRefs.unsafeMake(new Map()),
+      spans,
+      annotations,
+      date
+    })
+
+    expect(result).toEqual(
+      JSON.stringify({
+        message: "My message",
+        logLevel: "INFO",
+        timestamp: date.toJSON(),
+        annotations: {
+          just_a_key: "just_a_value",
+          good_key: "I am a good value",
+          good_bool: true,
+          "I am bad key name": { coolValue: "cool value" },
+          good_number: 123
+        },
+        spans: { "imma span=\"": 7 },
+        fiberId: ""
+      })
+    )
+  })
+
+  it("objects", () => {
+    const date = new Date()
+    vi.setSystemTime(date)
+
+    const result = Logger.jsonLogger.log({
+      fiberId: FiberId.none,
+      logLevel: logLevelInfo,
+      message: { hello: "world" },
+      cause: Cause.empty,
+      context: FiberRefs.unsafeMake(new Map()),
+      spans: List.empty(),
+      annotations: HashMap.empty(),
+      date
+    })
+
+    expect(result).toEqual(JSON.stringify({
+      message: { hello: "world" },
+      logLevel: "INFO",
+      timestamp: date.toJSON(),
+      annotations: {},
+      spans: {},
+      fiberId: ""
+    }))
+  })
+
+  it("circular objects", () => {
+    const date = new Date()
+    vi.setSystemTime(date)
+
+    const msg: Record<string, any> = { hello: "world" }
+    msg.msg = msg
+
+    const result = Logger.jsonLogger.log({
+      fiberId: FiberId.none,
+      logLevel: logLevelInfo,
+      message: msg,
+      cause: Cause.empty,
+      context: FiberRefs.unsafeMake(new Map()),
+      spans: List.empty(),
+      annotations: HashMap.empty(),
+      date
+    })
+
+    expect(result).toEqual(JSON.stringify({
+      message: { hello: "world" },
+      logLevel: "INFO",
+      timestamp: date.toJSON(),
+      annotations: {},
+      spans: {},
+      fiberId: ""
+    }))
+  })
+
+  it("symbols", () => {
+    const date = new Date()
+    vi.setSystemTime(date)
+
+    const result = Logger.jsonLogger.log({
+      fiberId: FiberId.none,
+      logLevel: logLevelInfo,
+      message: Symbol.for("effect/Logger/test"),
+      cause: Cause.empty,
+      context: FiberRefs.unsafeMake(new Map()),
+      spans: List.empty(),
+      annotations: HashMap.empty(),
+      date
+    })
+
+    expect(result).toEqual(JSON.stringify({
+      message: Symbol.for("effect/Logger/test").toString(),
+      logLevel: "INFO",
+      timestamp: date.toJSON(),
+      annotations: {},
+      spans: {},
+      fiberId: ""
+    }))
+  })
+
+  it("functions", () => {
+    const date = new Date()
+    vi.setSystemTime(date)
+
+    const result = Logger.jsonLogger.log({
+      fiberId: FiberId.none,
+      logLevel: logLevelInfo,
+      message: () => "hello world",
+      cause: Cause.empty,
+      context: FiberRefs.unsafeMake(new Map()),
+      spans: List.empty(),
+      annotations: HashMap.empty(),
+      date
+    })
+
+    expect(result).toEqual(JSON.stringify({
+      message: "() => \"hello world\"",
+      logLevel: "INFO",
+      timestamp: date.toJSON(),
+      annotations: {},
+      spans: {},
+      fiberId: ""
+    }))
+  })
 })