[Feature Request] Support Pino as a logging framework with Runtime.install

[paymog]

Is your feature request related to a problem? Please describe.

Support Pino as a logging framework with Runtime.install

Describe the solution you'd like

Currently, the Logger interface is Winston-like. This makes it difficult for teams that use Pino to have a familiar interface when doing workflow AND activity logging. Right now we're forced to either

1. use LoggerSinks (which seem to be deprecated) for Pino workflow logging
2. use winston-style logging in workflows and pino style logging in activities

Additional context

I've done quite a bit of hacking to get Pino logging for workflows working. Here's what I've done (reduced a bit to make it more legible)

export interface PinoLoggerSink extends Sinks {
  logger: {
    fatal(objOrMessage: object | string, msg?: string): void;
    error(objOrMessage: object | string, msg?: string): void;
    warn(objOrMessage: object | string, msg?: string): void;
    info(objOrMessage: object | string, msg?: string): void;
    debug(objOrMessage: object | string, msg?: string): void;
    trace(objOrMessage: object | string, msg?: string): void;
  };
}

export type LoggerSinks = PinoLoggerSink;

  const loggerOptions: LoggerOptions = {
    base: { pid: process.pid },
    formatters: {
      level: (label) => {
        return { level: label };
      },
    },
  };

  if (!IS_PRODUCTION) {
    loggerOptions.transport = {
      target: "pino-pretty",
      options: {
        translateTime: "HH:MM:ss Z",
        ignore: "pid,hostname",
      },
    };
  }

  const baseLogger = pino(loggerOptions);
  const activityLogger = baseLogger.child({ name: "activity" });
  const workflowPinoLogger = baseLogger.child({ name: "workflow" });

  const injectedWorkflowLoggerSink: InjectedSinks<LoggerSinks> = {
    logger: {
      fatal: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.fatal({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.fatal(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
      error: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.error({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.error(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
      warn: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.warn({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.warn(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
      info: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.info({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.info(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
      debug: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.debug({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.debug(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
      trace: {
        fn(workflowInfo, objOrMessage, message) {
          if (typeof objOrMessage === "string") {
            workflowPinoLogger.trace({ ...workflowInfo }, objOrMessage);
          } else {
            workflowPinoLogger.trace(
              { ...workflowInfo, ...objOrMessage },
              message
            );
          }
        },
        callDuringReplay: false,
      },
    },
  };

  const runtimeOptions: RuntimeOptions = {
    logger: {
      log<Level extends string = LogLevel>(
        level: Level,
        message: string,
        meta?: LogMetadata
      ) {
        switch (level) {
          case "TRACE":
            baseLogger.trace(meta, message);
            break;
          case "DEBUG":
            baseLogger.debug(meta, message);
            break;
          case "INFO":
            baseLogger.info(meta, message);
            break;
          case "WARN":
            baseLogger.warn(meta, message);
            break;
          case "ERROR":
            baseLogger.error(meta, message);
            break;
          default:
            throw new Error(`Unknown log level: ${level}`);
        }
      },
      trace(message: string, meta?: LogMetadata) {
        baseLogger.trace(meta, message);
      },
      debug(message: string, meta?: LogMetadata) {
        baseLogger.debug(meta, message);
      },
      info(message: string, meta?: LogMetadata) {
        baseLogger.info(meta, message);
      },
      warn(message: string, meta?: LogMetadata) {
        baseLogger.warn(meta, message);
      },
      error(message: string, meta?: LogMetadata) {
        baseLogger.error(meta, message);
      },
    },
    telemetryOptions: {
      logging: {
        forward: {},
      },
    },
  };

  if (IS_PRODUCTION) {
    runtimeOptions.telemetryOptions = {
      ...runtimeOptions.telemetryOptions,
      metrics: {
        prometheus: {
          bindAddress: `0.0.0.0:${PROMETHEUS_PORT}`,
        },
      },
    };
  }

  Runtime.install(runtimeOptions);

  const worker = await Worker.create({
    interceptors: appendDefaultInterceptors({
      activityInbound: [
        (ctx) => new ActivityInboundLogInterceptor(ctx, activityLogger),
      ],
    }),
    sinks: injectedWorkflowLoggerSink,
    shutdownGraceTime: SHUTDOWN_GRACE_TIME,
  });

[mjameswh]

IIUC, there's four distinct requests here:

1. Allow for Pino-style logging API in Workflow context;
2. Allow for Pino-style logging API in Activity context;
3. Make it easy to pass a Pino-style logger to Runtime.install;
4. Add annotations on log messages to determine where they come from (e.g. name: activity or name: workflow).

@paymog Anything missing?

[paymog]

I guess so? I'm still wrapping my head around how logging works in temporal. My understanding is that if Runtime.install supported Pino style logging (item 3) then items 1, 2, and 4 would naturally fall into place because of how the Runtime logger is accessed in workflows and activities.

If Runtime.install doesn't work for both Workflows and Activities then yes, items 1, 2, and 3 are all separate. Item 4 is super low priority in my opinion because Pino supports child loggers and because the "location" of the log (workflow vs activity) can be inferred from the other metadata/context on the log that gets injected by the worker.

[mjameswh]

Let me first respond to the feature request.

We discussed this with the team, and we strongly feel that the SDK itself must remain logger-framework agnostic. I can see how the SDK's Logger interface seems to adhere to Winston's style (same way of naming log levels functions, same order of arguments), but this is pretty much coincidental and only true at a shallow level (e.g. there is no actual import or dependency on Winston; only the simplest call signature is supported; no support for many winston-specific log levels; etc).

The SDK already provides a way to funnel all log messages emitted from Workflow code, Activity code, by the SDK itself and by the underlying Core SDK, through a single upstream logger (i.e. Runtime.logger). Relaying log messages emitted by any of these subsystems through a specific logging library simply require registration of a log adaptor on Runtime.logger. Note that even connecting to a Winston upstream logger requires such an adaptor. There's little we can do in the SDK itself to make this part easier while remaining log-framework agnostic.

Regarding the logger interface exposed to activities and workflows, again, there's not that much we can do within the SDK itself to simplify usage of alternate logging APIs. It is simply not possible to expose the logger object directly to workflow code, due to the fact that workflows executes in a sandboxed environment and on a different worker thread. As for exposing your custom logger object directly to activity code, this would technically be possible (actually, it is, already), but then it would be impossible for the SDK to automatically inject contextual metadata on log messages and to automatically emit lifecycle tracing messages. I can't see how that would be an improvement.

[mjameswh]

Regarding the code you shared on how you connected to Pino, it could have been much simpler.

Here are a few specific things you could have done differently:

• There was no need to register a custom logger sink; instead, you could simply create an adaptor class that exposes Pino-style log methods, but internally transmit these using the existing Logger's signature.
• This very same adaptor could be used to provide Pino-style logger API in activity code, obliterating the need to register an ActivityInboundLogInterceptor (by the way, both ActivityInboundLogInterceptor and appendDefaultInterceptors are deprecated since 1.9.0).
• To support the fatal log level, or any other custom level, the ingress adaptor could copy the log level name to a metadata field; then, the outgress adaptor could look for that field, and if present, call the corresponding log functions on your upstream Pino logger.
• To implement your egress adaptor on Runtime.logger, you could have used the SDK provided DefaultLogger class, and then, only provide the generic log function.

I will try to come up with a sample for this.

[paymog]

must remain logger-framework agnostic

Totally agree!

but this is pretty much coincidental and only true at a shallow level

Gotcha

there's not that much we can do within the SDK itself to simplify usage of alternate logging APIs

hmm, can you make two interfaces and use a type union for the base logger?

I will try to come up with a sample for this.

I would love that, thank you!