@effect-aws/powertools-logger: Support for log annotations (appendKeys)

[dmeehan1968]

Any plans to add support for log annotations? As far as I can tell, any annotations are not added to the Powertools output. Looking at the source there appears to be a FiberRef for extra keys, but not any way to set them (if this is meant to be used for this purpose).

What I like to do is add metadata to the running process that is only output in the event of any log output. This way if I set the log level to ERROR for the lambda, I won't see output unless there is an error, in which case it can, for example, capture the incoming event.

It might be nice to support temporary and persistent keys, although I've never found a need for the latter.

[floydspace]

hi @dmeehan1968 actoually it supposed to work, could you share your env? like powertools version, effect version etc..
this piece of code exactly intended to add annotations as extra inputs:

      ...HashMap.reduce(options.annotations, {}, (acc, value, key) => ({
        ...acc,
        [key]: value,
      })),

https://github.com/floydspace/effect-aws/blob/9acc922588e89c27071ef076e415a65b40fae2fd/packages/powertools-logger/src/Logger.ts#L109C1-L112C11

[dmeehan1968]

Here is an outline of the service that has the PowerToolsLoggerService, the logs are written in PT format.

export class DecoderService extends Effect.Service<DecoderService>()('DecoderService', {
  effect: Effect.gen(function* () {

    return {
      handler: (unknown: unknown, _context: Context) => Effect.gen(function* () {

        // Do work here

      }).pipe(
        Effect.annotateLogs({ event: unknown }),    // this should add the event to any logs emitted during the 'do work'
      ),
    }
  }),
  dependencies: [
    DeviceRepository.Default,
    PayloadPublishingService.Default,
  ],
  accessors: true,
}) {

  static makeHandler(serviceLayer: Layer.Layer<DecoderService, ConfigError.ConfigError> = DecoderService.Default) {
    const service = DecoderService.pipe(
      Effect.provide(serviceLayer),
      Effect.runSync,
    )
    return makeLambda(service.handler, serviceLayer)
  }

}

Dependencies:

    "@effect-aws/client-eventbridge": "^1.7.0",
    "@effect-aws/lambda": "^1.2.0",
    "@effect-aws/lib-dynamodb": "^1.4.1",
    "@effect-aws/powertools-logger": "^1.4.0",
    "effect": "^3.12.4"

Example of the DynamoDBDocumentService output (INFO level) on which I expect the annotations to appear (in this case, there should be an 'event' key/value at the top level.

{
    "level": "INFO",
    "sampling_rate": 0,
    "service": "--REDACTED--",
    "timestamp": "2025-01-31T18:42:37.646Z",
    "xray_trace_id": "1-679d1998-29ec4d522aee025b56b11198",
    "clientName": "DynamoDBClient",
    "commandName": "GetItemCommand",
    "input": {
        "TableName": "--REDACTED--",
        "Key": {
           // REDACTED
        }
    },
    "output": {
        "$metadata": {
           // REDACTED
        },
        "Item": {
           // REDACTED
        }
    },
    "metadata": {
        "httpStatusCode": 200,
        "requestId": "--REDACTED--",
        "attempts": 1,
        "totalRetryDelay": 0
    },
    "fiber": "#37"
}

[floydspace]

Not sure where do you connect the PowerTools Logger Layer...
But here is how I modified your snippet and it works for me:

diff --git a/main.ts b/main.ts
index 5bbf5e9..56c69df 100644
--- a/main.ts
+++ b/main.ts
@@ -11,7 +11,7 @@ export class DecoderService extends Effect.Service<DecoderService>()(
         handler: (unknown: unknown, _context: Context) =>
           Effect.gen(function* () {
 
-            // Do work here
+            yield* Effect.logInfo("doing work");
 
           }).pipe(
             Effect.annotateLogs({ event: unknown }) // this should add the event to any logs emitted during the 'do work'
@@ -32,7 +32,7 @@ export class DecoderService extends Effect.Service<DecoderService>()(
       Effect.provide(serviceLayer),
       Effect.runSync
     );
-    return makeLambda(service.handler, serviceLayer);
+    return makeLambda(service.handler, serviceLayer.pipe(Layer.provide(DefaultPowerToolsLoggerLayer)));
   }
 }

I get this log

{"level":"INFO","message":"doing work","sampling_rate":0,"service":"service_undefined","timestamp":"2025-01-31T19:47:24.402Z","fiber":"#6","event":{"test":"test"}}

which includes annotations

[dmeehan1968]

I am doing the PowerTools service provision outside of the makeHandler call, but the effect was exactly the same as shown.

If I put an Effect.log in the service as you did, I do get the annotation. 👍

But in my case, the log output is being generated by the DynamoDbDocumentService's client, included via the DeviceRepository dependency. The same goes for the PayloadPublishingService which uses EventBridgeService. 👎

I think this might be something to do with the effect-aws services passing of the logger to the client, or order of creation.

I also query this:

effect-aws/packages/powertools-logger/src/Logger.ts

Line 39 in 9acc922

return Effect.locally(effect(message), logExtraInput, extraInputs);

Whereas in the makeLogger you are doing a getOrDefault on the fiberRef:

effect-aws/packages/powertools-logger/src/Logger.ts

Lines 93 to 95 in 9acc922

	const extraInputs = [
	...FiberRefs.getOrDefault(options.context, logExtraInput),
	];

However, I think if that was the cause it wouldn't work in the case of the non-client output.

[floydspace]

Ok I got it, the problem is that the annotation you are adding is in the different scope (even different fiber) than the logs coming from services,
The logs are actually printed by aws native client and then forwarded to effect, and this forwarding mapping is done on the layer construction level, so there is no access to handler scope.

Not sure if it is event possible to fix, I need to dive deeper

Maybe the only option is implement own logging layer which must be on top of an effectful aws client wrapper, currently, so to say, it is on bottom

[dmeehan1968]

Hmm, I thought the service (DynamoDbDocumentService) was having the current logger injected as the client logger. So if the service has the PT logger, doesn't the client have the same? But I don't understand the layer levels that influence this.

Would using the PowerToolsLogger client instance's appendKeys be an option, even if its repeated on every log call? I think if the key is repeated it replaces, but might merge, so its some overhead to do it on every call.

[dmeehan1968]

I spotted an additional issue, which is when a failure incurs inside an effect that its wrapped by an annotation:

export class DecoderService extends Effect.Service<DecoderService>()('DecoderService', {
  effect: Effect.gen(function* () {

    return {
      handler: (unknown: unknown, _context: Context) => Effect.gen(function* () {

        // FAILURE reported from this effect or an embedded one e.g 
        // yield* Effect.fail(new Error('Oops'))

      }).pipe(
        Effect.annotateLogs({ event: unknown }),    // this should add the event to any logs emitted during the 'do work'
      ),
    }
  }),
  dependencies: [
    DeviceRepository.Default,
    PayloadPublishingService.Default,
  ],
  accessors: true,
}) {

  static makeHandler(serviceLayer: Layer.Layer<DecoderService, ConfigError.ConfigError> = DecoderService.Default) {
    const service = DecoderService.pipe(
      Effect.provide(serviceLayer),
      Effect.runSync,
    )
    return makeLambda(service.handler, serviceLayer)
  }

}

In this case ,the annotation isn't part of the reported error. I think this is because the error output actually comes from run... call within makeLamda. I get it from an effect point of view, but it means I'm not annotating at the point where the failure 'does' occur, so I end up putting annotations before I might need them. Not sure how I think I'd deal with that but want to log it before I forget.

[dmeehan1968]

After sleeping on this, I realised that its actually my responsibility to somewhere decide how to handle errors. As this is an AWS Lambda and a final promise rejection determines lambda retry logic, I do want some (if not all) of the errors to propogate out of the handler.

I was overlooking that the log entry which showed the error was actually being generated by the Lambda service, to indicate the errors that had propagated:

2025-02-02T09:03:40.881Z	1c5dcab9-d294-46a3-bd07-301e3518c508	ERROR	Invoke Error 	
{
    "_id": "FiberFailure",
    "cause": {
        "_id": "Cause",
        "_tag": "Fail",
        "failure": "Something went wrong on purpose"
    }
}

If I want an error log that includes my annotations, then I need to catch the failures, log them (which includes the annotations) and then propagate them.

      }).pipe(
        Effect.catchAll(error =>
          Effect.all([
            Effect.logError({ error }),
            Effect.fail(error),
          ]),                                      // log and propagate
        ),
        Effect.annotateLogs({ event: unknown }),   // original annotation
      ),

This gives an additional ERROR level log, prior to the Lambda reported one:

{
    "level": "ERROR",
    "sampling_rate": 0,
    "service": "--REDACTED--",
    "timestamp": "2025-02-02T09:03:40.880Z",
    "xray_trace_id": "--REDACTED--",
    "error": "Something went wrong on purpose",
    "fiber": "#38",
    "event": {
        "version": "0",
        "id": "61640761-0f50-6094-f23d-b4612e5a5189",
        "detail-type": "lorawan.uplink",
        "source": "loriot",
        "account": "--REDACTED--",
        "time": "2025-02-02T09:03:40Z",
        "region": "--REDACTED--",
        "resources": [],
        "detail": {
        --REDACTED--
        }
    }
}

So that at least tidies up how to ensure the annotations come out for app level logs, leaving why they don't come out for AWS Client logs.