diff --git a/docs/core/logging.md b/docs/core/logging.md index 2df9a4529..617ee4da1 100644 --- a/docs/core/logging.md +++ b/docs/core/logging.md @@ -265,7 +265,7 @@ to customise what is logged. } ``` -### Customising fields in logs +### Customising fields in logs - Utility by default emits `timestamp` field in the logs in format `yyyy-MM-dd'T'HH:mm:ss.SSSZz` and in system default timezone. If you need to customize format and timezone, you can do so by configuring `log4j2.component.properties` and configuring properties as shown in example below: @@ -598,6 +598,48 @@ via `samplingRate` attribute on annotation. POWERTOOLS_LOGGER_SAMPLE_RATE: 0.5 ``` +## AWS Lambda Advanced Logging Controls +With AWS [Lambda Advanced Logging Controls (ALC)](https://docs.aws.amazon.com/lambda/latest/dg/monitoring-cloudwatchlogs.html#monitoring-cloudwatchlogs-advanced), you can control the output format of your logs as either `TEXT` or `JSON` and specify the minimum accepted log level for your application. +Regardless of the output format setting in Lambda, Powertools for AWS Lambda will always output JSON formatted logging messages. + +When you have this feature enabled, log messages that don’t meet the configured log level are discarded by Lambda. +For example, if you set the minimum log level to `WARN`, you will only receive `WARN` and `ERROR` messages in your AWS CloudWatch Logs, all other log levels will be discarded by Lambda. + +```mermaid +sequenceDiagram + participant Lambda service + participant Lambda function + participant Application Logger + + Note over Lambda service: AWS_LAMBDA_LOG_LEVEL="WARN" + Lambda service->>Lambda function: Invoke (event) + Lambda function->>Lambda function: Calls handler + Lambda function->>Application Logger: logger.warn("Something happened") + Lambda function-->>Application Logger: logger.debug("Something happened") + Lambda function-->>Application Logger: logger.info("Something happened") + + Lambda service->>Lambda service: DROP INFO and DEBUG logs + + Lambda service->>CloudWatch Logs: Ingest error logs +``` + +Logger will automatically listen for the `AWS_LAMBDA_LOG_FORMAT` and `AWS_LAMBDA_LOG_LEVEL` environment variables, and change behaviour if they’re found to ensure as much compatibility as possible. + +### Priority of log level settings in Powertools for AWS Lambda + +When the Advanced Logging Controls feature is enabled, we are unable to increase the minimum log level below the `AWS_LAMBDA_LOG_LEVEL` environment variable value, see [AWS Lambda service documentation](https://docs.aws.amazon.com/lambda/latest/dg/monitoring-cloudwatchlogs.html#monitoring-cloudwatchlogs-log-level) for more details. + +We prioritise log level settings in this order: + +1. `AWS_LAMBDA_LOG_LEVEL` environment variable +2. `POWERTOOLS_LOG_LEVEL` environment variable + +In the event you have set `POWERTOOLS_LOG_LEVEL` to a level lower than the ACL setting, Powertools for AWS Lambda will output a warning log message informing you that your messages will be discarded by Lambda. + +### Timestamp format + +When the Advanced Logging Controls feature is enabled, Powertools for AWS Lambda must comply with the timestamp format required by AWS Lambda, which is [RFC3339](https://www.rfc-editor.org/rfc/rfc3339). +In this case the format will be `yyyy-MM-dd'T'HH:mm:ss.SSS'Z'`. ## Upgrade to JsonTemplateLayout from deprecated LambdaJsonLayout configuration in log4j2.xml diff --git a/powertools-logging/pom.xml b/powertools-logging/pom.xml index c31448e30..e4767893b 100644 --- a/powertools-logging/pom.xml +++ b/powertools-logging/pom.xml @@ -137,6 +137,16 @@ org.apache.maven.plugins maven-checkstyle-plugin + + org.apache.maven.plugins + maven-surefire-plugin + 3.1.2 + + + JSON + + + \ No newline at end of file diff --git a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java index 4a98735af..51c868fd7 100644 --- a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java +++ b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java @@ -28,6 +28,7 @@ import static software.amazon.lambda.powertools.logging.LoggingUtils.appendKey; import static software.amazon.lambda.powertools.logging.LoggingUtils.appendKeys; import static software.amazon.lambda.powertools.logging.LoggingUtils.objectMapper; +import static software.amazon.lambda.powertools.logging.internal.LoggingConstants.LAMBDA_LOG_LEVEL; import com.amazonaws.services.lambda.runtime.Context; import com.fasterxml.jackson.core.JsonPointer; @@ -61,16 +62,26 @@ @DeclarePrecedence("*, software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect") public final class LambdaLoggingAspect { private static final Logger LOG = LogManager.getLogger(LambdaLoggingAspect.class); - private static final Random SAMPLER = new Random(); + private static final String POWERTOOLS_LOG_LEVEL = System.getenv("POWERTOOLS_LOG_LEVEL"); - private static final String LOG_LEVEL = System.getenv("POWERTOOLS_LOG_LEVEL"); + private static final Random SAMPLER = new Random(); private static final String SAMPLING_RATE = System.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE"); private static Level LEVEL_AT_INITIALISATION; static { - if (null != LOG_LEVEL) { - resetLogLevels(Level.getLevel(LOG_LEVEL)); + if (POWERTOOLS_LOG_LEVEL != null) { + Level powertoolsLevel = Level.getLevel(POWERTOOLS_LOG_LEVEL); + if (LAMBDA_LOG_LEVEL != null) { + Level lambdaLevel = Level.getLevel(LAMBDA_LOG_LEVEL); + if (powertoolsLevel.intLevel() > lambdaLevel.intLevel()) { + LOG.warn("Current log level ({}) does not match AWS Lambda Advanced Logging Controls minimum log level ({}). This can lead to data loss, consider adjusting them.", + POWERTOOLS_LOG_LEVEL, LAMBDA_LOG_LEVEL); + } + } + resetLogLevels(powertoolsLevel); + } else if (LAMBDA_LOG_LEVEL != null) { + resetLogLevels(Level.getLevel(LAMBDA_LOG_LEVEL)); } LEVEL_AT_INITIALISATION = LOG.getLevel(); diff --git a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolver.java b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolver.java new file mode 100644 index 000000000..500b36c95 --- /dev/null +++ b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolver.java @@ -0,0 +1,169 @@ +/* + * Copyright 2023 Amazon.com, Inc. or its affiliates. + * Licensed under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * http://www.apache.org/licenses/LICENSE-2.0 + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package software.amazon.lambda.powertools.logging.internal; + +import static software.amazon.lambda.powertools.logging.internal.LoggingConstants.LAMBDA_LOG_FORMAT; +import static software.amazon.lambda.powertools.logging.internal.LoggingConstants.LOG_DATE_RFC3339_FORMAT; + +import java.util.Locale; +import java.util.TimeZone; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutDefaults; +import org.apache.logging.log4j.layout.template.json.resolver.EventResolver; +import org.apache.logging.log4j.layout.template.json.resolver.TemplateResolverConfig; +import org.apache.logging.log4j.layout.template.json.util.InstantFormatter; +import org.apache.logging.log4j.layout.template.json.util.JsonWriter; + +/** + * Default timestamp used by log4j is not RFC3339, which is used by Lambda internally to filter logs. + * When `AWS_LAMBDA_LOG_FORMAT` is set to JSON (i.e. using Lambda logging configuration), we should use the appropriate pattern, + * otherwise logs with invalid date format are considered as INFO. + * Inspired from org.apache.logging.log4j.layout.template.json.resolver.TimestampResolver + * + * TODO: remove in v2 an replace with the good pattern in LambdaJsonLayout.json + */ +public class LambdaTimestampResolver implements EventResolver { + + private final EventResolver internalResolver; + + public LambdaTimestampResolver(final TemplateResolverConfig config) { + final PatternResolverContext patternResolverContext = + PatternResolverContext.fromConfig(config); + internalResolver = new PatternResolver(patternResolverContext); + } + + @Override + public void resolve(LogEvent value, JsonWriter jsonWriter) { + internalResolver.resolve(value, jsonWriter); + } + + static String getName() { + return "lambda-timestamp"; + } + + private static final class PatternResolverContext { + + public static final String PATTERN = "pattern"; + private final InstantFormatter formatter; + + private final StringBuilder lastFormattedInstantBuffer = new StringBuilder(); + + private final MutableInstant lastFormattedInstant = new MutableInstant(); + + private PatternResolverContext( + final String pattern, + final TimeZone timeZone, + final Locale locale) { + this.formatter = InstantFormatter + .newBuilder() + .setPattern(pattern) + .setTimeZone(timeZone) + .setLocale(locale) + .build(); + lastFormattedInstant.initFromEpochSecond(-1, 0); + } + + private static PatternResolverContext fromConfig( + final TemplateResolverConfig config) { + final String pattern = readPattern(config); + final TimeZone timeZone = readTimeZone(config); + final Locale locale = config.getLocale(new String[]{PATTERN, "locale"}); + return new PatternResolverContext(pattern, timeZone, locale); + } + + private static String readPattern(final TemplateResolverConfig config) { + final String format = config.getString(new String[]{PATTERN, "format"}); + return format != null + ? format + : getLambdaTimestampFormatOrDefault(); + } + + private static String getLambdaTimestampFormatOrDefault() { + return "JSON".equals(LAMBDA_LOG_FORMAT) ? LOG_DATE_RFC3339_FORMAT : + JsonTemplateLayoutDefaults.getTimestampFormatPattern(); + } + + private static TimeZone readTimeZone(final TemplateResolverConfig config) { + final String timeZoneId = config.getString(new String[]{PATTERN, "timeZone"}); + if (timeZoneId == null) { + return JsonTemplateLayoutDefaults.getTimeZone(); + } + boolean found = false; + for (final String availableTimeZone : TimeZone.getAvailableIDs()) { + if (availableTimeZone.equalsIgnoreCase(timeZoneId)) { + found = true; + break; + } + } + if (!found) { + throw new IllegalArgumentException( + "invalid timestamp time zone: " + config); + } + return TimeZone.getTimeZone(timeZoneId); + } + + } + + private static final class PatternResolver implements EventResolver { + + private final PatternResolverContext patternResolverContext; + + private PatternResolver(final PatternResolverContext patternResolverContext) { + this.patternResolverContext = patternResolverContext; + } + + @Override + public synchronized void resolve( + final LogEvent logEvent, + final JsonWriter jsonWriter) { + + // Format timestamp if it doesn't match the last cached one. + final boolean instantMatching = patternResolverContext.formatter.isInstantMatching( + patternResolverContext.lastFormattedInstant, + logEvent.getInstant()); + if (!instantMatching) { + + // Format the timestamp. + patternResolverContext.lastFormattedInstantBuffer.setLength(0); + patternResolverContext.lastFormattedInstant.initFrom(logEvent.getInstant()); + patternResolverContext.formatter.format( + patternResolverContext.lastFormattedInstant, + patternResolverContext.lastFormattedInstantBuffer); + + // Write the formatted timestamp. + final StringBuilder jsonWriterStringBuilder = jsonWriter.getStringBuilder(); + final int startIndex = jsonWriterStringBuilder.length(); + jsonWriter.writeString(patternResolverContext.lastFormattedInstantBuffer); + + // Cache the written value. + patternResolverContext.lastFormattedInstantBuffer.setLength(0); + patternResolverContext.lastFormattedInstantBuffer.append( + jsonWriterStringBuilder, + startIndex, + jsonWriterStringBuilder.length()); + + } + + // Write the cached formatted timestamp. + else { + jsonWriter.writeRawString( + patternResolverContext.lastFormattedInstantBuffer); + } + + } + + } +} diff --git a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolverFactory.java b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolverFactory.java new file mode 100644 index 000000000..2022c6d4a --- /dev/null +++ b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaTimestampResolverFactory.java @@ -0,0 +1,49 @@ +/* + * Copyright 2023 Amazon.com, Inc. or its affiliates. + * Licensed under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * http://www.apache.org/licenses/LICENSE-2.0 + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package software.amazon.lambda.powertools.logging.internal; + +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.config.plugins.PluginFactory; +import org.apache.logging.log4j.layout.template.json.resolver.EventResolverContext; +import org.apache.logging.log4j.layout.template.json.resolver.EventResolverFactory; +import org.apache.logging.log4j.layout.template.json.resolver.TemplateResolver; +import org.apache.logging.log4j.layout.template.json.resolver.TemplateResolverConfig; +import org.apache.logging.log4j.layout.template.json.resolver.TemplateResolverFactory; + +@Plugin(name = "LambdaTimestampResolverFactory", category = TemplateResolverFactory.CATEGORY) +public final class LambdaTimestampResolverFactory implements EventResolverFactory { + + private static final LambdaTimestampResolverFactory INSTANCE = new LambdaTimestampResolverFactory(); + + private LambdaTimestampResolverFactory() { + } + + @PluginFactory + public static LambdaTimestampResolverFactory getInstance() { + return INSTANCE; + } + + @Override + public String getName() { + return LambdaTimestampResolver.getName(); + } + + @Override + public TemplateResolver create(EventResolverContext context, + TemplateResolverConfig config) { + return new LambdaTimestampResolver(config); + } +} diff --git a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LoggingConstants.java b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LoggingConstants.java new file mode 100644 index 000000000..e58ca4109 --- /dev/null +++ b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LoggingConstants.java @@ -0,0 +1,27 @@ +/* + * Copyright 2023 Amazon.com, Inc. or its affiliates. + * Licensed under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * http://www.apache.org/licenses/LICENSE-2.0 + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package software.amazon.lambda.powertools.logging.internal; + +public class LoggingConstants { + public static final String LAMBDA_LOG_LEVEL = System.getenv("AWS_LAMBDA_LOG_LEVEL"); + + public static final String LAMBDA_LOG_FORMAT = System.getenv("AWS_LAMBDA_LOG_FORMAT"); + + public static final String LOG_DATE_RFC3339_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'"; + + private LoggingConstants() { + // constants + } +} diff --git a/powertools-logging/src/main/resources/LambdaJsonLayout.json b/powertools-logging/src/main/resources/LambdaJsonLayout.json index dfc1fc78f..da3385032 100644 --- a/powertools-logging/src/main/resources/LambdaJsonLayout.json +++ b/powertools-logging/src/main/resources/LambdaJsonLayout.json @@ -1,6 +1,6 @@ { "timestamp": { - "$resolver": "timestamp" + "$resolver": "lambda-timestamp" }, "instant": { "epochSecond": { diff --git a/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java b/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java index 9b0c6165a..95fb9c47f 100644 --- a/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java +++ b/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java @@ -16,6 +16,7 @@ import static java.util.Collections.emptyMap; import static org.apache.commons.lang3.reflect.FieldUtils.writeStaticField; +import static org.assertj.core.api.Assertions.as; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.fail; import static org.mockito.Mockito.when; @@ -32,8 +33,12 @@ import java.nio.file.Files; import java.nio.file.Paths; import java.nio.file.StandardOpenOption; +import java.time.format.DateTimeFormatter; +import java.time.format.DateTimeParseException; +import java.time.format.ResolverStyle; import java.util.Map; import org.apache.logging.log4j.Level; +import org.assertj.core.api.InstanceOfAssertFactories; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.mockito.Mock; @@ -42,7 +47,6 @@ import software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect; class LambdaJsonLayoutTest { - private RequestHandler handler = new PowerLogToolEnabled(); @Mock @@ -73,6 +77,31 @@ void shouldLogInStructuredFormat() throws IOException { .containsKey("service")); } + @Test + void shouldLogWithRFC3339TimestampFormat_WhenLambdaLoggingIsJSON() throws Exception { + // Given: AWS_LAMBDA_LOG_FORMAT=JSON defined in pom.xml + + // When + handler.handleRequest("test", context); + + // Then + assertThat(Files.lines(Paths.get("target/logfile.json"))) + .hasSize(1) + .allSatisfy(line -> assertThat(parseToMap(line)) + .extracting("timestamp", as(InstanceOfAssertFactories.STRING)) + .satisfies(s -> assertThat(hasDateFormat(s, "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'")).isTrue())); + } + + private boolean hasDateFormat(String timestamp, String format) { + DateTimeFormatter dtf = DateTimeFormatter.ofPattern(format).withResolverStyle(ResolverStyle.STRICT); + try { + dtf.parse(timestamp); + return true; + } catch (DateTimeParseException e) { + return false; + } + } + @Test void shouldModifyLogLevelBasedOnEnvVariable() throws IllegalAccessException, IOException, NoSuchMethodException, InvocationTargetException {