@Logging annotation with logEvent = true does not play nice with @Tracing annotation in RequestStreamHandler

[allenada]

I am using Lambda Powertools Java to capture logs, metrics, and traces for my REST service running in Lambda. I am using RequestStreamHandler to forward ApiGateway request to a JerseyLambdaContainerHandler containing handling for my various endpoints proxied by ApiGateway.

Using @Logging(logEvent = true) and @Tracing together causes the JerseyLambdaContainerHandler to not process the request as the InputStream has been read from already due to the (logEvent = true) specification on the @Logging annotation. I do not see these errors using @Logging and @Tracing together, just @Logging(logEvent = true) alone, or just @Tracing alone.

How has this issue affected you? What are you trying to accomplish?

I attempted to use both @Tracing and @Logging(logEvent = true) on the same handler method implementing RequestStreamHandler

The handler method is unable to process the request due to:

com.fasterxml.jackson.databind.exc.MismatchedInputException: "No content to map due to end-of-input\n at [Source: (ByteArrayInputStream); line: 1, column: 0]"

I am able to work around it by resetting the InputStream on the first line of the handler. My method:

    @Logging(logEvent = true)
    @Tracing
    @Metrics(captureColdStart = true)
    @Override
    public void handleRequest(final InputStream inputStream, final OutputStream outputStream, final Context context) throws IOException {
        inputStream.reset(); // Need to reset as Logging aspect with logEvent=true is exhausting the input stream
        log.info("Started processing request");
        HANDLER.proxyStream(inputStream, outputStream, context);
        traceHttp(inputStream, outputStream);
        log.info("Finished processing request");
    }

What were you trying to accomplish?
To use the powertools annotations on my RequestStreamHandler without needing to reset inputStream

Expected Behavior

The inputStream should not be exhausted after the powertools aspects run before my method

Current Behavior

The inputStream is exhausted by the powertools aspects run before my method

Possible Solution

I believe this post details the issue but I'm not an expert in AspectJ (just consuming it here). That post and answer implies that LambdaLoggingAspect.java#L174 is not actually working so when LambdaTracingAspect runs after the LambdaLoggingAspect, it is not actually getting the updated parameters. However, it does not throw this error if I use the @Logging(logEvent = true) annotation without the @Tracing annotation which I do not understand in the context of the above hypothesis so I'm doubtful of my own hypothesis for that reason.

Steps to Reproduce (for bugs)

1. Annotate handler method of RequestStreamHandler with both @Logging(logEvent=true) and @Tracing
2. Execute a request that reads from InputStream
3. Receive exception because InputStream has been read from already

Environment

• Powertools version used: 1.2
• Packaging format (Layers, Maven/Gradle): Gradle
• AWS Lambda function runtime: Java11
• Debugging logs

 | timestamp | message
| 1613335172594 | {"instant":{"epochSecond":1613335172,"nanoOfSecond":396000000},"thread":"main","level":"INFO","loggerName":"com.amazonaws.serverless.proxy.internal.LambdaContainerHandler","message":"Starting Lambda Container Handler","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:32.396Z[UTC]"}
| 1613335174717 | START RequestId: b74a3b4d-3440-4518-a912-56c8cc53b832 Version: $LATEST
| 1613335175305 | {"_aws":{"Timestamp":1613335174944,"CloudWatchMetrics":[{"Namespace":"my-service-api","Metrics":[{"Name":"ColdStart","Unit":"Count"}],"Dimensions":[["Service","FunctionName"]]}]},"traceId":"Root=1-60298a81-f37154f04fe1c3846c6dec35;Parent=c34f426197c429d1;Sampled=1","FunctionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","ColdStart":1.0,"Service":"authorization-service","logStreamId":"2021/02/14/[$LATEST]e794fcfaf4304e4780df7d5fd99261b1","executionEnvironment":"AWS_Lambda_java11"}
| 1613335175408 | {"instant":{"epochSecond":1613335175,"nanoOfSecond":407000000},"thread":"main","level":"INFO","loggerName":"com.myservice.authorization.RequestHandler","message":"<redacted>","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:35.407Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335175625 | {"instant":{"epochSecond":1613335175,"nanoOfSecond":625000000},"thread":"main","level":"INFO","loggerName":"com.amazonaws.xray.config.DaemonConfiguration","message":"Environment variable AWS_XRAY_DAEMON_ADDRESS is set. Emitting to daemon on address 169.254.79.2:2000.","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.jcl.Log4jLog","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:35.625Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179046 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":45000000},"thread":"main","level":"INFO","loggerName":"com.amazonaws.xray.AWSXRayRecorder","message":"Overriding contextMissingStrategy. Environment variable AWS_XRAY_CONTEXT_MISSING has value: \"LOG_ERROR\".","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.jcl.Log4jLog","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.045Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179103 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":103000000},"thread":"main","level":"INFO","loggerName":"com.amazonaws.xray.config.DaemonConfiguration","message":"Environment variable AWS_XRAY_DAEMON_ADDRESS is set. Emitting to daemon on address 169.254.79.2:2000.","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.jcl.Log4jLog","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.103Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179205 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":204000000},"thread":"main","level":"INFO","loggerName":"com.myservice.authorization.RequestHandler","message":"Started processing request","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.204Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179344 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":205000000},"thread":"main","level":"ERROR","loggerName":"com.amazonaws.serverless.proxy.internal.LambdaContainerHandler","message":"Error while mapping object to RequestType class","thrown":{"commonElementCount":0,"localizedMessage":"No content to map due to end-of-input\n at [Source: (ByteArrayInputStream); line: 1, column: 0]","message":"No content to map due to end-of-input\n at [Source: (ByteArrayInputStream); line: 1, column: 0]","name":"com.fasterxml.jackson.databind.exc.MismatchedInputException","extendedStackTrace":[{"class":"com.fasterxml.jackson.databind.exc.MismatchedInputException","method":"from","file":"MismatchedInputException.java","line":59,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.DeserializationContext","method":"reportInputMismatch","file":"DeserializationContext.java","line":1468,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"_initForReading","file":"ObjectReader.java","line":360,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"_bindAndClose","file":"ObjectReader.java","line":2064,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"readValue","file":"ObjectReader.java","line":1453,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.amazonaws.serverless.proxy.internal.LambdaContainerHandler","method":"proxyStream","file":"LambdaContainerHandler.java","line":253,"exact":true,"location":"aws-serverless-java-container-core-1.5.2.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody0","file":"RequestHandler.java","line":56,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure1","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.tracing.internal.LambdaTracingAspect","method":"around","file":"LambdaTracingAspect.java","line":59,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody2","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure3","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect","method":"around","file":"LambdaLoggingAspect.java","line":98,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody4","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure5","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.metrics.internal.LambdaMetricsAspect","method":"around","file":"LambdaMetricsAspect.java","line":56,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"jdk.internal.reflect.NativeMethodAccessorImpl","method":"invoke0","line":-2,"exact":false,"location":"?","version":"?"},{"class":"jdk.internal.reflect.NativeMethodAccessorImpl","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"jdk.internal.reflect.DelegatingMethodAccessorImpl","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"java.lang.reflect.Method","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"lambdainternal.EventHandlerLoader$StreamMethodRequestHandler","method":"handleRequest","file":"EventHandlerLoader.java","line":375,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.EventHandlerLoader$2","method":"call","file":"EventHandlerLoader.java","line":899,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"startRuntime","file":"AWSLambda.java","line":258,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"startRuntime","file":"AWSLambda.java","line":192,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"main","file":"AWSLambda.java","line":187,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"}]},"endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.205Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}  |
| 1613335179346 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":344000000},"thread":"main","level":"ERROR","loggerName":"com.amazonaws.serverless.proxy.AwsProxyExceptionHandler","message":"Called exception handler for:","thrown":{"commonElementCount":0,"localizedMessage":"No content to map due to end-of-input\n at [Source: (ByteArrayInputStream); line: 1, column: 0]","message":"No content to map due to end-of-input\n at [Source: (ByteArrayInputStream); line: 1, column: 0]","name":"com.fasterxml.jackson.databind.exc.MismatchedInputException","extendedStackTrace":[{"class":"com.fasterxml.jackson.databind.exc.MismatchedInputException","method":"from","file":"MismatchedInputException.java","line":59,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.DeserializationContext","method":"reportInputMismatch","file":"DeserializationContext.java","line":1468,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"_initForReading","file":"ObjectReader.java","line":360,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"_bindAndClose","file":"ObjectReader.java","line":2064,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.fasterxml.jackson.databind.ObjectReader","method":"readValue","file":"ObjectReader.java","line":1453,"exact":false,"location":"jackson-databind-2.11.x.jar","version":"?"},{"class":"com.amazonaws.serverless.proxy.internal.LambdaContainerHandler","method":"proxyStream","file":"LambdaContainerHandler.java","line":253,"exact":true,"location":"aws-serverless-java-container-core-1.5.2.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody0","file":"RequestHandler.java","line":56,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure1","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.tracing.internal.LambdaTracingAspect","method":"around","file":"LambdaTracingAspect.java","line":59,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody2","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure3","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect","method":"around","file":"LambdaLoggingAspect.java","line":98,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest_aroundBody4","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler$AjcClosure5","method":"run","file":"RequestHandler.java","line":1,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"org.aspectj.runtime.reflect.JoinPointImpl","method":"proceed","file":"JoinPointImpl.java","line":257,"exact":true,"location":"aspectjrt-1.9.6.jar","version":"?"},{"class":"software.amazon.lambda.powertools.metrics.internal.LambdaMetricsAspect","method":"around","file":"LambdaMetricsAspect.java","line":56,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"com.myservice.authorization.RequestHandler","method":"handleRequest","file":"RequestHandler.java","line":55,"exact":true,"location":"my-serviceAuthorizationService-1.0.jar","version":"?"},{"class":"jdk.internal.reflect.NativeMethodAccessorImpl","method":"invoke0","line":-2,"exact":false,"location":"?","version":"?"},{"class":"jdk.internal.reflect.NativeMethodAccessorImpl","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"jdk.internal.reflect.DelegatingMethodAccessorImpl","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"java.lang.reflect.Method","method":"invoke","line":-1,"exact":false,"location":"?","version":"?"},{"class":"lambdainternal.EventHandlerLoader$StreamMethodRequestHandler","method":"handleRequest","file":"EventHandlerLoader.java","line":375,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.EventHandlerLoader$2","method":"call","file":"EventHandlerLoader.java","line":899,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"startRuntime","file":"AWSLambda.java","line":258,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"startRuntime","file":"AWSLambda.java","line":192,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"},{"class":"lambdainternal.AWSLambda","method":"main","file":"AWSLambda.java","line":187,"exact":true,"location":"aws-lambda-java-runtime-0.2.0.jar","version":"?"}]},"endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.344Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179363 | com.fasterxml.jackson.databind.exc.MismatchedInputException: No content to map due to end-of-input
| 1613335179363 | at [Source: (ByteArrayInputStream); line: 1, column: 0]
| 1613335179382 | at com.fasterxml.jackson.databind.exc.MismatchedInputException.from(MismatchedInputException.java:59)
| 1613335179383 | at com.fasterxml.jackson.databind.DeserializationContext.reportInputMismatch(DeserializationContext.java:1468)
| 1613335179383 | at com.fasterxml.jackson.databind.ObjectReader._initForReading(ObjectReader.java:360)
| 1613335179383 | at com.fasterxml.jackson.databind.ObjectReader._bindAndClose(ObjectReader.java:2064)
| 1613335179383 | at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1453)
| 1613335179383 | at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxyStream(LambdaContainerHandler.java:253)
| 1613335179383 | at com.myservice.authorization.RequestHandler.handleRequest_aroundBody0(RequestHandler.java:56)
| 1613335179383 | at com.myservice.authorization.RequestHandler$AjcClosure1.run(RequestHandler.java:1)
| 1613335179383 | at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:257)
| 1613335179383 | at software.amazon.lambda.powertools.tracing.internal.LambdaTracingAspect.around(LambdaTracingAspect.java:59)
| 1613335179383 | at com.myservice.authorization.RequestHandler.handleRequest_aroundBody2(RequestHandler.java:55)
| 1613335179383 | at com.myservice.authorization.RequestHandler$AjcClosure3.run(RequestHandler.java:1)
| 1613335179383 | at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:257)
| 1613335179384 | at software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect.around(LambdaLoggingAspect.java:98)
| 1613335179384 | at com.myservice.authorization.RequestHandler.handleRequest_aroundBody4(RequestHandler.java:55)
| 1613335179384 | at com.myservice.authorization.RequestHandler$AjcClosure5.run(RequestHandler.java:1)
| 1613335179384 | at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:257)
| 1613335179384 | at software.amazon.lambda.powertools.metrics.internal.LambdaMetricsAspect.around(LambdaMetricsAspect.java:56)
| 1613335179384 | at com.myservice.authorization.RequestHandler.handleRequest(RequestHandler.java:55)
| 1613335179384 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
| 1613335179384 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
| 1613335179384 | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
| 1613335179384 | at java.base/java.lang.reflect.Method.invoke(Unknown Source)
| 1613335179384 | at lambdainternal.EventHandlerLoader$StreamMethodRequestHandler.handleRequest(EventHandlerLoader.java:375)
| 1613335179384 | at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:899)
| 1613335179384 | at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:258)
| 1613335179384 | at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:192)
| 1613335179384 | at lambdainternal.AWSLambda.main(AWSLambda.java:187)
| 1613335179506 | {"instant":{"epochSecond":1613335179,"nanoOfSecond":506000000},"thread":"main","level":"INFO","loggerName":"com.myservice.authorization.RequestHandler","message":"Finished processing request","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","threadId":1,"threadPriority":5,"timestamp":"2021-02-14T20:39:39.506Z[UTC]","coldStart":"true","functionArn":"arn:aws:lambda:us-east-1:xxxxxxxxxxxx:function:AuthorizationServiceLambda","functionMemorySize":"512","functionName":"AuthorizationServiceLambda","functionVersion":"$LATEST","function_request_id":"b74a3b4d-3440-4518-a912-56c8cc53b832","samplingRate":"0.0","service":"authorization-service","xray_trace_id":"1-60298a81-f37154f04fe1c3846c6dec35"}
| 1613335179704 | {"traceId":"Root=1-60298a81-f37154f04fe1c3846c6dec35;Parent=c34f426197c429d1;Sampled=1","functionVersion":"$LATEST","LogGroup":"AuthorizationServiceLambda","ServiceName":"AuthorizationServiceLambda","ServiceType":"AWS::Lambda::Function","Service":"authorization-service","logStreamId":"2021/02/14/[$LATEST]e794fcfaf4304e4780df7d5fd99261b1","executionEnvironment":"AWS_Lambda_java11"}
| 1613335179705 | END RequestId: b74a3b4d-3440-4518-a912-56c8cc53b832
| 1613335179705 | REPORT RequestId: b74a3b4d-3440-4518-a912-56c8cc53b832 Duration: 4988.02 ms Billed Duration: 4989 ms Memory Size: 512 MB Max Memory Used: 227 MB Init Duration: 4751.94 ms  XRAY TraceId: 1-60298a81-f37154f04fe1c3846c6dec35 SegmentId: 18cccb1901b10289 Sampled: true

[pankajagrawal16]

Hi, @allenada Thanks for opening an issue with detailed information. I will have a look at it sometime this week.

[allenada]

I did have some time to take a deeper look into this myself. Looks like if you change LambdaLoggingAspect.java#L78 to the following then the issue is resolved (at least in my local unit test):

@Around(value = "callAt(logging) && execution(@software.amazon.lambda.powertools.logging.Logging* *.*(InputStream, ..))", argNames = "pjp,logging")

[pankajagrawal16]

I did managed to replicate the issue and also understand the problem, which exists only if you are using input stream version of handler together with tracing and logging together.

I haven't find a proper solution yet, but I will check the solution which you mentioned as well and also dive a bit more deeper this week.

In the meantime(while we fix this) I am sure there must be reasons on using stream handler version, but if it helps, you may also switch the lambda function handler to the request handler implementation.

[pankajagrawal16]

I am planning to revisit this issue sometime this week.

[pankajagrawal16]

@allenada This should be fixed with #567

[pankajagrawal16]

Release as part of https://github.com/awslabs/aws-lambda-powertools-java/releases/tag/v1.8.0 @allenada