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

allenada · 2021-02-14T22:15:26Z

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)

Annotate handler method of RequestStreamHandler with both @Logging(logEvent=true) and @Tracing
Execute a request that reads from InputStream
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

The text was updated successfully, but these errors were encountered:

pankajagrawal16 · 2021-02-15T06:00:37Z

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

allenada · 2021-02-16T04:59:29Z

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 · 2021-02-16T05:10:52Z

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 · 2021-03-02T06:02:48Z

I am planning to revisit this issue sometime this week.

pankajagrawal16 · 2021-10-04T12:10:41Z

@allenada This should be fixed with #567

pankajagrawal16 · 2021-11-05T15:20:03Z

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

allenada added the bug Something isn't working label Feb 14, 2021

pankajagrawal16 mentioned this issue Feb 20, 2021

feat: Override object mapper #287

Closed

6 tasks

pankajagrawal16 added the help wanted label May 14, 2021

pankajagrawal16 mentioned this issue Oct 4, 2021

fix: LoggingAspect precedence to be last for accepting mutated args #567

Merged

6 tasks

pankajagrawal16 removed the help wanted label Oct 4, 2021

pankajagrawal16 added the status/staged-next-release label Oct 22, 2021

pankajagrawal16 closed this as completed Nov 5, 2021

jeromevdl removed the status/staged-next-release label Aug 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

allenada commented Feb 14, 2021 •

edited

Loading

pankajagrawal16 commented Feb 15, 2021 •

edited

Loading

allenada commented Feb 16, 2021 •

edited

Loading

pankajagrawal16 commented Feb 16, 2021 •

edited

Loading

pankajagrawal16 commented Mar 2, 2021

pankajagrawal16 commented Oct 4, 2021

pankajagrawal16 commented Nov 5, 2021

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

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

Comments

allenada commented Feb 14, 2021 • edited Loading

Expected Behavior

Current Behavior

Possible Solution

Steps to Reproduce (for bugs)

Environment

pankajagrawal16 commented Feb 15, 2021 • edited Loading

allenada commented Feb 16, 2021 • edited Loading

pankajagrawal16 commented Feb 16, 2021 • edited Loading

pankajagrawal16 commented Mar 2, 2021

pankajagrawal16 commented Oct 4, 2021

pankajagrawal16 commented Nov 5, 2021

allenada commented Feb 14, 2021 •

edited

Loading

pankajagrawal16 commented Feb 15, 2021 •

edited

Loading

allenada commented Feb 16, 2021 •

edited

Loading

pankajagrawal16 commented Feb 16, 2021 •

edited

Loading