feat(workflow): Logger improvements (#1159)

- [Make log attributes optional for defaultWorkerLogger
sink](8d3a3f1)
- [Attach log attributes to every workflow log
message](5938b70)

The approach taken in this PR (compared to the alternative #1158)
attaches the log attributes in workflow context where the user has more
control.

Author: bergundy

packages/worker/src/index.ts

@@ -50,7 +50,11 @@ export {
   WorkflowBundlePathWithSourceMap, // eslint-disable-line deprecation/deprecation
 } from './worker-options';
 export { ReplayError, ReplayHistoriesIterable, ReplayResult } from './replay';
-export { WorkflowInboundLogInterceptor, workflowLogAttributes } from './workflow-log-interceptor';
+export {
+  WorkflowInboundLogInterceptor, // eslint-disable-line deprecation/deprecation
+  WorkflowLogInterceptor,
+  workflowLogAttributes,
+} from './workflow-log-interceptor';
 export {
   BundleOptions,
   bundleWorkflowCode,

packages/worker/src/workflow-log-interceptor.ts

@@ -3,11 +3,13 @@ import {
   Next,
   WorkflowExecuteInput,
   WorkflowInboundCallsInterceptor,
+  WorkflowOutboundCallsInterceptor,
   workflowInfo,
   WorkflowInfo,
   WorkflowInterceptorsFactory,
   log,
   ContinueAsNew,
+  GetLogAttributesInput,
 } from '@temporalio/workflow';
 import { untrackPromise } from '@temporalio/workflow/lib/stack-helpers';
 
@@ -24,32 +26,35 @@ export function workflowLogAttributes(info: WorkflowInfo): Record<string, unknow
   };
 }
 
-/** Logs Workflow execution starts and completions */
-export class WorkflowInboundLogInterceptor implements WorkflowInboundCallsInterceptor {
-  protected logAttributes(): Record<string, unknown> {
-    return workflowLogAttributes(workflowInfo());
+/** Logs workflow execution starts and completions, attaches log attributes to `workflow.log` calls  */
+export class WorkflowLogInterceptor implements WorkflowInboundCallsInterceptor, WorkflowOutboundCallsInterceptor {
+  getLogAttributes(
+    input: GetLogAttributesInput,
+    next: Next<WorkflowOutboundCallsInterceptor, 'getLogAttributes'>
+  ): Record<string, unknown> {
+    return next({ ...input, ...workflowLogAttributes(workflowInfo()) });
   }
 
   execute(input: WorkflowExecuteInput, next: Next<WorkflowInboundCallsInterceptor, 'execute'>): Promise<unknown> {
-    log.debug('Workflow started', this.logAttributes());
+    log.debug('Workflow started');
     const p = next(input).then(
       (res) => {
-        log.debug('Workflow completed', this.logAttributes());
+        log.debug('Workflow completed');
         return res;
       },
       (error) => {
         // Avoid using instanceof checks in case the modules they're defined in loaded more than once,
         // e.g. by jest or when multiple versions are installed.
         if (typeof error === 'object' && error != null) {
           if (isCancellation(error)) {
-            log.debug('Workflow completed as cancelled', this.logAttributes());
+            log.debug('Workflow completed as cancelled');
             throw error;
           } else if (ContinueAsNew.is(error)) {
-            log.debug('Workflow continued as new', this.logAttributes());
+            log.debug('Workflow continued as new');
             throw error;
           }
         }
-        log.warn('Workflow failed', { error, ...this.logAttributes() });
+        log.warn('Workflow failed', { error });
         throw error;
       }
     );
@@ -59,5 +64,11 @@ export class WorkflowInboundLogInterceptor implements WorkflowInboundCallsInterc
   }
 }
 
+/** @deprecated use {@link WorkflowLogInterceptor} instead */
+export const WorkflowInboundLogInterceptor = WorkflowLogInterceptor;
+
 // ts-prune-ignore-next
-export const interceptors: WorkflowInterceptorsFactory = () => ({ inbound: [new WorkflowInboundLogInterceptor()] });
+export const interceptors: WorkflowInterceptorsFactory = () => {
+  const interceptor = new WorkflowLogInterceptor();
+  return { inbound: [interceptor], outbound: [interceptor] };
+};

packages/workflow/src/interceptors.ts

@@ -118,6 +118,9 @@ export interface SignalWorkflowInput {
       };
 }
 
+/** Input for WorkflowOutboundCallsInterceptor.getLogAttributes */
+export type GetLogAttributesInput = Record<string, unknown>;
+
 /**
  * Implement any of these methods to intercept Workflow code calls to the Temporal APIs, like scheduling an activity and starting a timer
  */
@@ -161,6 +164,13 @@ export interface WorkflowOutboundCallsInterceptor {
     input: StartChildWorkflowExecutionInput,
     next: Next<this, 'startChildWorkflowExecution'>
   ) => Promise<[Promise<string>, Promise<unknown>]>;
+
+  /**
+   * Called on each invocation of the `workflow.log` methods.
+   *
+   * The attributes returned in this call are attached to every log message.
+   */
+  getLogAttributes?: (input: GetLogAttributesInput, next: Next<this, 'getLogAttributes'>) => Record<string, unknown>;
 }
 
 /** Input for WorkflowInternalsInterceptor.concludeActivation */

packages/workflow/src/sinks.ts

@@ -45,10 +45,10 @@ export interface SinkCall {
  */
 export interface LoggerSinks extends Sinks {
   defaultWorkerLogger: {
-    trace(message: string, attrs: Record<string, unknown>): void;
-    debug(message: string, attrs: Record<string, unknown>): void;
-    info(message: string, attrs: Record<string, unknown>): void;
-    warn(message: string, attrs: Record<string, unknown>): void;
-    error(message: string, attrs: Record<string, unknown>): void;
+    trace(message: string, attrs?: Record<string, unknown>): void;
+    debug(message: string, attrs?: Record<string, unknown>): void;
+    info(message: string, attrs?: Record<string, unknown>): void;
+    warn(message: string, attrs?: Record<string, unknown>): void;
+    error(message: string, attrs?: Record<string, unknown>): void;
   };
 }

packages/workflow/src/workflow.ts

@@ -1308,11 +1308,13 @@ export const log: LoggerSinks['defaultWorkerLogger'] = Object.fromEntries(
   (['trace', 'debug', 'info', 'warn', 'error'] as Array<keyof LoggerSinks['defaultWorkerLogger']>).map((level) => {
     return [
       level,
-      (message: string, attrs: Record<string, unknown>) => {
-        assertInWorkflowContext('Workflow.log(...) may only be used from a Workflow Execution.)');
+      (message: string, attrs?: Record<string, unknown>) => {
+        const activator = assertInWorkflowContext('Workflow.log(...) may only be used from a Workflow Execution.');
+        const getLogAttributes = composeInterceptors(activator.interceptors.outbound, 'getLogAttributes', (a) => a);
         return loggerSinks.defaultWorkerLogger[level](message, {
           // Inject the call time in nanosecond resolution as expected by the worker logger.
-          [LogTimestamp]: getActivator().getTimeOfDay(),
+          [LogTimestamp]: activator.getTimeOfDay(),
+          ...getLogAttributes({}),
           ...attrs,
         });
       },