Unexpected logging behaviour

[dmeehan1968]

I'm relatively new to effect, and hoping to use it in my AWS projects. In attempting to write a lambda to handle incoming IoT Core Lorawan events, I seem to be struggling with logging.

There are two issues:

1. The default effect-aws services use a configuration that installs a logger in the client instance, and when trying to use Logger.withMinimumLogLevel I don't seem to be able to control whether its output. As a result I've had to use the service baseLayer to create a client omitting the logger. Should I be able to control the log level, and ideally how can I do this with the Powertools service?
2. When I attempt to replace the default logger with either the logfmtLogger or structuredLogger, I get no log output at all. I've tried replacing it with a custom logger that just logs everything using console.log and that works ok, so not sure what I'm doing wrong.

I have a feeling that I'm not setting up the environment correctly, possible related to the runtime that gets used. Any input gratefully received!

Context: we receive Lorawan data from IoT Core devices and external network services, and so the purpose of the code is to transform the events to a common event format and then publish them to EventBridge so that downstream microservices can handle them. In this case, this is receiving events from Loriot via its AWS IoT Core integration, so triggered by a Topic Rule.

const ingestServiceHandler = (event: unknown, _context: Context) => pipe(
  Schema.decodeUnknown(LoriotUplink)(event),
  Effect.andThen(transformLoriotUplinkToCommonUplink),
  Effect.andThen(transformCommonUplinkToEventBridgeEntry({
    Source: 'loriot',
  })),
  Effect.andThen(entry => EventBridge.putEvents({ Entries: [entry] })),
  Effect.andThen(Effect.log),
)

const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.baseLayer(({ logger: _, ...params }) => new EventBridgeClient(params)),
  // Logger.replace(Logger.defaultLogger, Logger.structuredLogger),
)

export const handler = makeLambda(ingestServiceHandler, lambdaLayer)

[floydspace]

Hi @dmeehan1968 thanks for your question,

1. yes you should be able to contol it but with Logger.minimumLogLevel for example

// ...
const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
).pipe(Layer.provideMerge(Logger.minimumLogLevel(LogLevel.Info)))
// ...

it is bc it should be applyed on Layer, not on Effect
2. to enable different logging format you do the same

// ...
const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
).pipe(Layer.provideMerge(Logger.logFmt)) // or `Logger.structured`
// ...

the ultimate example would be

// ...
const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
).pipe(
  Layer.provideMerge(Logger.logFmt),
  Layer.provideMerge(Logger.minimumLogLevel(LogLevel.Info))
)
// ...

[dmeehan1968]

@floydspace Thank you, that was helpful in clarifying the order.

I hadn't realised that the Logger.logFmt alias was there. I'm not clear on why that works and the following doesn't, given both provide a Layer instance!

  Layer.provideMerge(Logger.replace(Logger.defaultLogger, Logger.logfmtLogger)),

Specifying the log level as indicated does fix the issue of filtering out the EventBridge client logs if I set the minimum log level to LogLevel.Warning, for example.

Please could you provide an example of using the effect-aws Powertools logger, there is no example in the docs.

A mystery, but at least I now seem to have some working output as desired. Thanks!

[floydspace]

@dmeehan1968

Please could you provide an example of using the effect-aws Powertools logger

actually it is the same like with effect built-in loggers

import { DefaultPowerToolsLoggerLayer } from "@effect-aws/powertools-logger";

// ...
const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
).pipe(Layer.provideMerge(DefaultPowerToolsLoggerLayer))
// ...

I'm not clear on why that works and the following doesn't

that is indeed mystery, bc logFmt actually the same, I would suggest try again, maybe initially you did not use provideMerge, but provide which only applies to the downstream layer but not to the actual program.

[dmeehan1968]

@floydspace Unfortunately this doesn't work, I get no output at all (same as my previous problem).

const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
).pipe(
  Layer.provideMerge(DefaultPowerToolsLoggerLayer),
)

export const handler = makeLambda(ingestServiceHandler, lambdaLayer)

Regards the longer format using Logger.replace, I have reconfirmed that this doesn't work when using Layer.provideMerge.

[dmeehan1968]

I realised that one reason why I wasn't getting log output with the power tools logger is that my lambda environment is setup with the powertools environment variables to control the log level, and it defaults to errors only.

This allowed me to refine the creation of the layer, but confusingly there is a difference.

Here, this creates the power tools logger and uses the environment log level to determine output. This works as expected when log level is info, and I see both the client log and my application log, both formatted as for powertools.

const lambdaLayer = Layer.empty.pipe(
  Layer.provideMerge(IngestServiceParams.Default),
  Layer.provideMerge(EventBridge.defaultLayer),
  Layer.provideMerge(DefaultPowerToolsLoggerLayer),
)

However, this seems like it should be functionally equivalent to the following, which is less verbose, but leads to the client log being with the Effect defaultLogger, and the application log being in the powertools format.

const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer,
  DefaultPowerToolsLoggerLayer,
)

I then realised that when using mergeAll, perhaps the order of evaluation is important, but this also leads to the event bridge log using the default logger.

const lambdaLayer = Layer.mergeAll(
  IngestServiceParams.Default,
  DefaultPowerToolsLoggerLayer,
  EventBridge.defaultLayer,
)

mergeAll is documented to create a single layer with all layers merged, whereas provideMerge suggests it creates a chain of layers, one feeding into the other.

Looking again at the provideMerge example, setting the power tools logger first then causes the event bridge service logs to be in the default logger format. I think this means I should read the other of evaluation as right to left.

const lambdaLayer = Layer.empty.pipe(
  Layer.provideMerge(IngestServiceParams.Default),
  Layer.provideMerge(DefaultPowerToolsLoggerLayer),
  Layer.provideMerge(EventBridge.defaultLayer),
)

Clearly my understanding of Layer merging is inadequate, and I can't figure out why the outcome is different. The best I rationalise from it is that merged layers (flat) don't effect each other, but that the chain of layers created by provideMerge does, but should be specified in reverse order (right most layers affecting prior).

Perhaps this could be documented more clearly in the examples, perhaps in the @effect-aws/powertools-logger examples.

[floydspace]

However, this seems like it should be functionally equivalent to the following

it is not functionally equivalent, bc Layer.mergeAll will merge only merge layers , but layers would not be applyed with each other, it is why you see default logger, and order does not matter in this case, for your better understanding to make it work you need to do smth like this:

Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer.pipe(Layer.provide(DefaultPowerToolsLoggerLayer)), // you need to provide for this layer separatly, bc the next line is just a sibling
  DefaultPowerToolsLoggerLayer,
)

so the correct way is using provideMerge which does 2 things: it will provide for the layer and merge with it

[dmeehan1968]

Ok, thanks. It's still not particularly clear to me and the examples in the effect.website don't really make it any clearer.

A practical example in the docs for effect-aws (perhaps in the powertools logger service at least) would make this more apparent.

At least for now I have a working example and can move on. Thank you very much for your advice.

[florianbepunkt]

Related question: Is it possible to set a log level per layer?

During development I would like to set the log level for AWS to warnings, but keep my business code info logs.

[floydspace]

Is it possible to set a log level per layer?

does it work if you provide Logger.minimumLogLevel per aws client layer as in this example

Layer.mergeAll(
  IngestServiceParams.Default,
  EventBridge.defaultLayer.pipe(Layer.provide(Logger.minimumLogLevel(LogLevel.Debug))),
  DefaultPowerToolsLoggerLayer,
)

[dmeehan1968]

I'm still struggling with dependency order when listed in the dependencies of an Effect.Service.

DeviceRepository has an internal dependency (and is implemented with Effect.Service) on the DynamoDBDocumentService, and when log level is INFO it will output a line that details the input and output to the client command.

PayloadPublishingService uses EventBridgeService to send messages, structured the same and would behave the same, outputting the input and output of the command at INFO level.

This DecoverService has a simple Effect.log whenever its called. So the hierarchy is like this:

DecoderService
  |---- DeviceRepository
    |---- DynamoDbDocumentService
  |---- PayloadPublisherService
    |---- EventBridgeService

The sub-services don't specify the PowerTools logger.

In the DecoderService, when I specify the following for dependencies, I get the default logger output, with the expected content. But it should be outputting in PowerTools format.

  dependencies: [
    DeviceRepository.Default,
    PayloadPublishingService.Default,
    DefaultPowerToolsLoggerLayer,
  ]

When I do this, I get the the default logger for the DecoderService, and PowerTools for the Dynamo and EventBridge services:

  dependencies: [
    DeviceRepository.Default.pipe(Layer.provide(DefaultPowerToolsLoggerLayer)),
    PayloadPublishingService.Default.pipe(Layer.provide(DefaultPowerToolsLoggerLayer)),
    DefaultPowerToolsLoggerLayer,
  ]

And when I do this, I get the same:

  dependencies: [
    Layer.empty.pipe(
      Layer.provideMerge(DeviceRepository.Default),
      Layer.provideMerge(PayloadPublishingService.Default),
      Layer.provideMerge(DefaultPowerToolsLoggerLayer),
    ),
  ]

And when I do the following and apply the PowerTools layer to the DecoderService layer (outside of the Service, where its passed to the makeLambda call, I still don't get PowerTools output for the DecoderService.

  dependencies: [
    DeviceRepository.Default,
    PayloadPublishingService.Default,
  ]

Within a unit test, I setup a layer as follows, and this gives PowerTools output for the DecoderService, and if I put log calls in the repository or publisher (the Dynamo and EventBridge clients are mocked, so there will be no output for those.

    const layer = DecoderService.DefaultWithoutDependencies.pipe(
      Layer.provide(DeviceRepository.Default),
      Layer.provide(PayloadPublishingService.Default),
      Layer.provide(Layer.setConfigProvider(configProvider)),
      Layer.provide(DefaultPowerToolsLoggerLayer),
    )

    const sut = () => DecoderService.handler.pipe(
      Effect.andThen(handler => handler(event, {} as Context)),
      Effect.provide(layer),
      Effect.runPromise,
    )

Constructing the test layer like this also gives PowerTools log output from the DecoderService:

    const layer = DecoderService.Default.pipe(
      Layer.provide(Layer.setConfigProvider(configProvider)),
      Layer.provide(DefaultPowerToolsLoggerLayer),
    )

The difference in how layers are apparently constructed when using Effect.Service, at least when there is some nesting of the dependencies, seems to be different to constructing the layer by hand (no merging needed). It's very frustrating and I can't see any logic to it.

I can't figure out if this is my failing, Effect.Service or the way the PowerToolsLoggerService is implemented. But I sure would like too!

[dmeehan1968]

Aaah, the benefit of writing things out.

In my DecoderService I had created a makeHandler static so I could make the Lambda handler construction as simple as:

export const handler = DecoderService.makeHandler()

And the definition of that function was:

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

Note that I was not passing the layer as the makeLambda global layer, and hence the PowerTools layer was not being applied throughout. So the simple solution was:

return makeLambda(service.handler, serviceLayer)

I think this could be further refined as technically the globalLayer only needs the PowerTools layer, and not the other dependencies. The makeLambda overloaded declaration make this a little trickier, but it seems there is no double initialisation of the dependencies due to Layer memoisation.

This also has the benefit of moving the PowerTools logger provision outside of the service, useful for services that might have different runtime contexts so the logger can be provided when needed. This makes the lambda handler initialisation this:

export const handler = DecoderService.makeHandler(
  DecoderService.Default.pipe(
    Layer.provideMerge(DefaultPowerToolsLoggerLayer),
  )
)

I can then use the same interface to create the handler for testing purposes.

For completeness, here is the outline of the DecoderService

export class DecoderService extends Effect.Service<DecoderService>()('DecoderService', {
  effect: Effect.gen(function* () {
    const devices = yield* DeviceRepository
    const events = yield* PayloadPublishingService

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

        // Do event handling here

      }),
    }
  }),
  dependencies: [
    DeviceRepository.Default,
    PayloadPublishingService.Default,
  ],
}) {

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

}

I think I got myself totally confused around layers and completely overlooked the relevance of providing the global layer. Of course, if this still isn't the right approach, I'm all ears!