diff --git a/example/HelloWorldFunction/src/main/java/helloworld/App.java b/example/HelloWorldFunction/src/main/java/helloworld/App.java index cf58b9191..c1b7d254d 100644 --- a/example/HelloWorldFunction/src/main/java/helloworld/App.java +++ b/example/HelloWorldFunction/src/main/java/helloworld/App.java @@ -12,10 +12,17 @@ import com.amazonaws.services.lambda.runtime.RequestHandler; import com.amazonaws.services.lambda.runtime.events.APIGatewayProxyRequestEvent; import com.amazonaws.services.lambda.runtime.events.APIGatewayProxyResponseEvent; +import com.amazonaws.xray.AWSXRay; +import com.amazonaws.xray.entities.Entity; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import software.aws.lambda.logging.PowerLogger; import software.aws.lambda.logging.PowerToolsLogging; +import software.aws.lambda.tracing.PowerToolTracing; +import software.aws.lambda.tracing.PowerTracer; + +import static software.aws.lambda.tracing.PowerTracer.putMetadata; +import static software.aws.lambda.tracing.PowerTracer.withEntitySubsegment; /** * Handler for requests to Lambda function. @@ -25,6 +32,7 @@ public class App implements RequestHandler headers = new HashMap<>(); headers.put("Content-Type", "application/json"); @@ -37,21 +45,60 @@ public APIGatewayProxyResponseEvent handleRequest(final APIGatewayProxyRequestEv try { final String pageContents = this.getPageContents("https://checkip.amazonaws.com"); log.info(pageContents); + PowerTracer.putAnnotation("Test", "New"); String output = String.format("{ \"message\": \"hello world\", \"location\": \"%s\" }", pageContents); + PowerTracer.withSubsegment("loggingResponse", subsegment -> { + String sampled = "log something out"; + log.info(sampled); + log.info(output); + }); + + threadOption1(); + + threadOption2(); + log.info("After output"); return response .withStatusCode(200) .withBody(output); - } catch (IOException e) { + } catch (IOException | InterruptedException e) { return response .withBody("{}") .withStatusCode(500); } } + private void threadOption1() throws InterruptedException { + Entity traceEntity = AWSXRay.getTraceEntity(); + Thread thread = new Thread(() -> { + AWSXRay.setTraceEntity(traceEntity); + log(); + }); + thread.start(); + thread.join(); + } + + private void threadOption2() throws InterruptedException { + Entity traceEntity = AWSXRay.getTraceEntity(); + Thread anotherThread = new Thread(() -> withEntitySubsegment("inlineLog", traceEntity, subsegment -> { + String var = "somethingToProcess"; + log.info("inside threaded logging inline {}", var); + })); + anotherThread.start(); + anotherThread.join(); + } + + @PowerToolTracing + private void log() { + log.info("inside threaded logging for function"); + } + + + @PowerToolTracing(namespace = "getPageContents", captureResponse = false, captureError = false) private String getPageContents(String address) throws IOException { URL url = new URL(address); + putMetadata("getPageContents", address); try (BufferedReader br = new BufferedReader(new InputStreamReader(url.openStream()))) { return br.lines().collect(Collectors.joining(System.lineSeparator())); } diff --git a/example/template.yaml b/example/template.yaml index c04d77c44..66b6946c7 100644 --- a/example/template.yaml +++ b/example/template.yaml @@ -20,7 +20,8 @@ Resources: MemorySize: 512 Environment: # More info about Env Vars: https://github.com/awslabs/serverless-application-model/blob/master/versions/2016-10-31.md#environment-object Variables: - PARAM1: VALUE + POWERTOOLS_SERVICE_NAME: SAILING + Tracing: Active Events: HelloWorld: Type: Api # More info about API Event Source: https://github.com/awslabs/serverless-application-model/blob/master/versions/2016-10-31.md#api @@ -35,6 +36,7 @@ Resources: Handler: helloworld.AppStream::handleRequest Runtime: java8 MemorySize: 512 + Tracing: Active Environment: Variables: PARAM1: VALUE diff --git a/pom.xml b/pom.xml index 3f20e8839..7e2ddb544 100644 --- a/pom.xml +++ b/pom.xml @@ -42,6 +42,7 @@ 2.13.3 2.11.0 1.9.6 + 2.4.0 UTF-8 @@ -83,6 +84,31 @@ aspectjrt ${aspectj.version} + + com.amazonaws + aws-xray-recorder-sdk-core + ${aws.xray.recorder.version} + + + com.amazonaws + aws-xray-recorder-sdk-aws-sdk + ${aws.xray.recorder.version} + + + com.amazonaws + aws-xray-recorder-sdk-aws-sdk-instrumentor + ${aws.xray.recorder.version} + + + com.amazonaws + aws-xray-recorder-sdk-aws-sdk-v2 + ${aws.xray.recorder.version} + + + com.amazonaws + aws-xray-recorder-sdk-aws-sdk-v2-instrumentor + ${aws.xray.recorder.version} + diff --git a/src/main/java/software/aws/lambda/internal/LambdaHandlerProcessor.java b/src/main/java/software/aws/lambda/internal/LambdaHandlerProcessor.java new file mode 100644 index 000000000..3e223fb21 --- /dev/null +++ b/src/main/java/software/aws/lambda/internal/LambdaHandlerProcessor.java @@ -0,0 +1,31 @@ +package software.aws.lambda.internal; + +import java.io.InputStream; +import java.io.OutputStream; + +import com.amazonaws.services.lambda.runtime.Context; +import com.amazonaws.services.lambda.runtime.RequestHandler; +import com.amazonaws.services.lambda.runtime.RequestStreamHandler; +import org.aspectj.lang.ProceedingJoinPoint; + +public final class LambdaHandlerProcessor { + public static Boolean IS_COLD_START = null; + + public static boolean isHandlerMethod(ProceedingJoinPoint pjp) { + return "handleRequest".equals(pjp.getSignature().getName()); + } + + public static boolean placedOnRequestHandler(ProceedingJoinPoint pjp) { + return RequestHandler.class.isAssignableFrom(pjp.getSignature().getDeclaringType()) + && pjp.getArgs().length == 2 + && pjp.getArgs()[1] instanceof Context; + } + + public static boolean placedOnStreamHandler(ProceedingJoinPoint pjp) { + return RequestStreamHandler.class.isAssignableFrom(pjp.getSignature().getDeclaringType()) + && pjp.getArgs().length == 3 + && pjp.getArgs()[0] instanceof InputStream + && pjp.getArgs()[1] instanceof OutputStream + && pjp.getArgs()[2] instanceof Context; + } +} diff --git a/src/main/java/software/aws/lambda/logging/internal/LambdaAspect.java b/src/main/java/software/aws/lambda/logging/internal/LambdaLoggingAspect.java similarity index 76% rename from src/main/java/software/aws/lambda/logging/internal/LambdaAspect.java rename to src/main/java/software/aws/lambda/logging/internal/LambdaLoggingAspect.java index 6030d2aa9..f065ca4fd 100644 --- a/src/main/java/software/aws/lambda/logging/internal/LambdaAspect.java +++ b/src/main/java/software/aws/lambda/logging/internal/LambdaLoggingAspect.java @@ -10,8 +10,6 @@ import java.util.Optional; import com.amazonaws.services.lambda.runtime.Context; -import com.amazonaws.services.lambda.runtime.RequestHandler; -import com.amazonaws.services.lambda.runtime.RequestStreamHandler; import com.fasterxml.jackson.databind.ObjectMapper; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; @@ -25,17 +23,20 @@ import static java.util.Optional.empty; import static java.util.Optional.of; +import static software.aws.lambda.internal.LambdaHandlerProcessor.IS_COLD_START; +import static software.aws.lambda.internal.LambdaHandlerProcessor.isHandlerMethod; +import static software.aws.lambda.internal.LambdaHandlerProcessor.placedOnRequestHandler; +import static software.aws.lambda.internal.LambdaHandlerProcessor.placedOnStreamHandler; @Aspect -public final class LambdaAspect { - static Boolean IS_COLD_START = null; +public final class LambdaLoggingAspect { private static final ObjectMapper mapper = new ObjectMapper(); @Pointcut("@annotation(powerToolsLogging)") public void callAt(PowerToolsLogging powerToolsLogging) { } - @Around(value = "callAt(powerToolsLogging)", argNames = "pjp,powerToolsLogging") + @Around(value = "callAt(powerToolsLogging) && execution(@PowerToolsLogging * *.*(..))", argNames = "pjp,powerToolsLogging") public Object around(ProceedingJoinPoint pjp, PowerToolsLogging powerToolsLogging) throws Throwable { Object[] proceedArgs = pjp.getArgs(); @@ -46,13 +47,15 @@ public Object around(ProceedingJoinPoint pjp, ThreadContext.put("coldStart", null == IS_COLD_START ? "true" : "false"); }); - IS_COLD_START = false; if (powerToolsLogging.logEvent()) { proceedArgs = logEvent(pjp); } - return pjp.proceed(proceedArgs); + Object proceed = pjp.proceed(proceedArgs); + + IS_COLD_START = false; + return proceed; } private Optional extractContext(ProceedingJoinPoint pjp) { @@ -113,19 +116,4 @@ private Object[] logFromInputStream(ProceedingJoinPoint pjp) { private Logger logger(ProceedingJoinPoint pjp) { return LogManager.getLogger(pjp.getSignature().getDeclaringType()); } - - private boolean isHandlerMethod(ProceedingJoinPoint pjp) { - return "handleRequest".equals(pjp.getSignature().getName()); - } - - private boolean placedOnRequestHandler(ProceedingJoinPoint pjp) { - return RequestHandler.class.isAssignableFrom(pjp.getSignature().getDeclaringType()) - && pjp.getArgs().length == 2 && pjp.getArgs()[1] instanceof Context; - } - - private boolean placedOnStreamHandler(ProceedingJoinPoint pjp) { - return RequestStreamHandler.class.isAssignableFrom(pjp.getSignature().getDeclaringType()) - && pjp.getArgs().length == 3 && pjp.getArgs()[0] instanceof InputStream - && pjp.getArgs()[2] instanceof Context; - } } diff --git a/src/main/java/software/aws/lambda/tracing/PowerToolTracing.java b/src/main/java/software/aws/lambda/tracing/PowerToolTracing.java new file mode 100644 index 000000000..48a2d4439 --- /dev/null +++ b/src/main/java/software/aws/lambda/tracing/PowerToolTracing.java @@ -0,0 +1,14 @@ +package software.aws.lambda.tracing; + +import java.lang.annotation.ElementType; +import java.lang.annotation.Retention; +import java.lang.annotation.RetentionPolicy; +import java.lang.annotation.Target; + +@Retention(RetentionPolicy.RUNTIME) +@Target(ElementType.METHOD) +public @interface PowerToolTracing { + String namespace() default ""; + boolean captureResponse() default true; + boolean captureError() default true; +} diff --git a/src/main/java/software/aws/lambda/tracing/PowerTracer.java b/src/main/java/software/aws/lambda/tracing/PowerTracer.java new file mode 100644 index 000000000..b0f22e1d5 --- /dev/null +++ b/src/main/java/software/aws/lambda/tracing/PowerTracer.java @@ -0,0 +1,43 @@ +package software.aws.lambda.tracing; + +import java.util.function.Consumer; + +import com.amazonaws.xray.AWSXRay; +import com.amazonaws.xray.entities.Entity; +import com.amazonaws.xray.entities.Subsegment; + +public final class PowerTracer { + public static final String SERVICE_NAME = null != System.getenv("POWERTOOLS_SERVICE_NAME") + ? System.getenv("POWERTOOLS_SERVICE_NAME") : "service_undefined"; + + public static void putAnnotation(String key, String value) { + AWSXRay.getCurrentSubsegmentOptional() + .ifPresent(segment -> segment.putAnnotation(key, value)); + } + + public static void putMetadata(String key, Object value) { + String namespace = AWSXRay.getCurrentSubsegmentOptional() + .map(Subsegment::getNamespace).orElse(SERVICE_NAME); + + putMetadata(namespace, key, value); + } + + public static void putMetadata(String namespace, String key, Object value) { + AWSXRay.getCurrentSubsegmentOptional() + .ifPresent(segment -> segment.putMetadata(namespace, key, value)); + } + + public static void withEntitySubsegment(String name, Entity entity, Consumer subsegment) { + AWSXRay.setTraceEntity(entity); + withSubsegment(name, subsegment); + } + + public static void withSubsegment(String name, Consumer subsegment) { + Subsegment segment = AWSXRay.beginSubsegment("## " + name); + try { + subsegment.accept(segment); + } finally { + AWSXRay.endSubsegment(); + } + } +} diff --git a/src/main/java/software/aws/lambda/tracing/internal/LambdaTracingAspect.java b/src/main/java/software/aws/lambda/tracing/internal/LambdaTracingAspect.java new file mode 100644 index 000000000..ead145fb2 --- /dev/null +++ b/src/main/java/software/aws/lambda/tracing/internal/LambdaTracingAspect.java @@ -0,0 +1,78 @@ +package software.aws.lambda.tracing.internal; + +import com.amazonaws.xray.AWSXRay; +import com.amazonaws.xray.entities.Subsegment; +import com.fasterxml.jackson.databind.ObjectMapper; +import org.aspectj.lang.ProceedingJoinPoint; +import org.aspectj.lang.annotation.Around; +import org.aspectj.lang.annotation.Aspect; +import org.aspectj.lang.annotation.Pointcut; +import software.aws.lambda.tracing.PowerToolTracing; + +import static software.aws.lambda.internal.LambdaHandlerProcessor.IS_COLD_START; +import static software.aws.lambda.internal.LambdaHandlerProcessor.isHandlerMethod; +import static software.aws.lambda.internal.LambdaHandlerProcessor.placedOnRequestHandler; +import static software.aws.lambda.internal.LambdaHandlerProcessor.placedOnStreamHandler; +import static software.aws.lambda.tracing.PowerTracer.SERVICE_NAME; + +@Aspect +public final class LambdaTracingAspect { + private static final ObjectMapper mapper = new ObjectMapper(); + + @Pointcut("@annotation(powerToolsTracing)") + public void callAt(PowerToolTracing powerToolsTracing) { + } + + @Around(value = "callAt(powerToolsTracing) && execution(@PowerToolTracing * *.*(..))", argNames = "pjp,powerToolsTracing") + public Object around(ProceedingJoinPoint pjp, + PowerToolTracing powerToolsTracing) throws Throwable { + Object[] proceedArgs = pjp.getArgs(); + Subsegment segment; + + segment = AWSXRay.beginSubsegment("## " + pjp.getSignature().getName()); + segment.setNamespace(namespace(powerToolsTracing)); + + boolean placedOnHandlerMethod = placedOnHandlerMethod(pjp); + + if (placedOnHandlerMethod) { + segment.putAnnotation("ColdStart", IS_COLD_START == null); + } + + + try { + Object methodReturn = pjp.proceed(proceedArgs); + if (powerToolsTracing.captureResponse()) { + segment.putMetadata(namespace(powerToolsTracing), pjp.getSignature().getName() + " response", response(pjp, methodReturn)); + } + + IS_COLD_START = false; + + return methodReturn; + } catch (Exception e) { + if (powerToolsTracing.captureError()) { + segment.putMetadata(namespace(powerToolsTracing), pjp.getSignature().getName() + " error", e); + } + throw e; + } finally { + AWSXRay.endSubsegment(); + } + } + + private Object response(ProceedingJoinPoint pjp, Object methodReturn) { + // TODO should we try to parse output stream? or just not support it? + if (placedOnStreamHandler(pjp)) { + + } + + return methodReturn; + } + + private String namespace(PowerToolTracing powerToolsTracing) { + return powerToolsTracing.namespace().isEmpty() ? SERVICE_NAME : powerToolsTracing.namespace(); + } + + private boolean placedOnHandlerMethod(ProceedingJoinPoint pjp) { + return isHandlerMethod(pjp) + && (placedOnRequestHandler(pjp) || placedOnStreamHandler(pjp)); + } +} diff --git a/src/test/java/software/aws/lambda/logging/internal/LambdaAspectTest.java b/src/test/java/software/aws/lambda/logging/internal/LambdaLoggingAspectTest.java similarity index 94% rename from src/test/java/software/aws/lambda/logging/internal/LambdaAspectTest.java rename to src/test/java/software/aws/lambda/logging/internal/LambdaLoggingAspectTest.java index 6af0a53bb..3f2ff3669 100644 --- a/src/test/java/software/aws/lambda/logging/internal/LambdaAspectTest.java +++ b/src/test/java/software/aws/lambda/logging/internal/LambdaLoggingAspectTest.java @@ -15,12 +15,13 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.mockito.Mock; +import software.aws.lambda.internal.LambdaHandlerProcessor; import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.Mockito.when; import static org.mockito.MockitoAnnotations.initMocks; -class LambdaAspectTest { +class LambdaLoggingAspectTest { private RequestStreamHandler requestStreamHandler; private RequestHandler requestHandler; @@ -32,7 +33,7 @@ class LambdaAspectTest { void setUp() { initMocks(this); ThreadContext.clearAll(); - LambdaAspect.IS_COLD_START = null; + LambdaHandlerProcessor.IS_COLD_START = null; setupContext(); requestHandler = new PowerLogToolEnabled(); requestStreamHandler = new PowerLogToolEnabledForStream(); @@ -55,7 +56,7 @@ void shouldSetLambdaContextWhenEnabled() { void shouldSetLambdaContextForStreamHandlerWhenEnabled() throws IOException { requestStreamHandler = new PowerLogToolEnabledForStream(); - requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), null, context); + requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), new ByteArrayOutputStream(), context); assertThat(ThreadContext.getImmutableContext()) .hasSize(5) @@ -68,13 +69,13 @@ void shouldSetLambdaContextForStreamHandlerWhenEnabled() throws IOException { @Test void shouldSetColdStartFlag() throws IOException { - requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), null, context); + requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), new ByteArrayOutputStream(), context); assertThat(ThreadContext.getImmutableContext()) .hasSize(5) .containsEntry("coldStart", "true"); - requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), null, context); + requestStreamHandler.handleRequest(new ByteArrayInputStream(new byte[]{}), new ByteArrayOutputStream(), context); assertThat(ThreadContext.getImmutableContext()) .hasSize(5)