From 16ad20d440e3b2cc11d94a2c9fb3187f30324397 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Tue, 10 Sep 2024 19:46:11 +0200 Subject: [PATCH] Fix reloading of the configuration from HTTP(S) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The `HttpWatcher` didn't propagate the observed last modification time back to the configuration. As a result, each new configuration was already deprecated when it started and the reconfiguration process looped. Closes #2937 Rewrite Jetty tests using WireMock Closes #2813 Co-authored-by: Volkan Yazıcı --- log4j-core-test/pom.xml | 46 +++- .../core/config/ConfigurationSourceTest.java | 62 +++-- .../HttpThreadContextMapFilterTest.java | 113 -------- .../MutableThreadContextMapFilterTest.java | 254 +++++++++++++----- .../core/net/UrlConnectionFactoryTest.java | 232 ++++++++-------- .../logging/log4j/core/net/WireMockUtil.java | 84 ++++++ .../log4j/core/util/HttpWatcherTest.java | 158 +++++++++++ .../log4j/core/util/WatchHttpTest.java | 159 ----------- .../log4j/core/util/WatchManagerTest.java | 179 ++++++------ .../ConfigurationSourceTest.xml} | 18 +- .../src/test/resources/emptyConfig.json | 4 - .../MutableThreadContextMapFilterTest.xml | 23 +- .../src/test/resources/filterConfig.json | 6 - .../logging/log4j/core/LoggerContext.java | 11 +- .../core/config/AbstractConfiguration.java | 28 +- .../core/config/ConfigurationSource.java | 133 ++++----- .../log4j/core/config/HttpWatcher.java | 41 ++- .../core/config/xml/XmlConfiguration.java | 10 +- .../filter/MutableThreadContextMapFilter.java | 62 +++-- .../logging/log4j/core/util/Loader.java | 5 +- .../logging/log4j/core/util/Source.java | 40 +-- .../logging/log4j/core/util/WatchManager.java | 20 +- .../util/internal/HttpInputStreamUtil.java | 98 +++++-- log4j-parent/pom.xml | 34 +-- log4j-perf-test/pom.xml | 33 ++- log4j-plugins/pom.xml | 3 + log4j-slf4j2-impl/pom.xml | 22 +- log4j-to-slf4j/pom.xml | 13 + pom.xml | 4 + src/changelog/.3.x.x/2937-http-watcher.xml | 8 + 30 files changed, 1075 insertions(+), 828 deletions(-) delete mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/HttpThreadContextMapFilterTest.java create mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/WireMockUtil.java create mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/HttpWatcherTest.java delete mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchHttpTest.java rename log4j-core-test/src/test/resources/{log4j-sync-to-list.xml => config/ConfigurationSourceTest.xml} (71%) delete mode 100644 log4j-core-test/src/test/resources/emptyConfig.json rename log4j-core-test/src/test/resources/{ => filter}/MutableThreadContextMapFilterTest.xml (68%) delete mode 100644 log4j-core-test/src/test/resources/filterConfig.json create mode 100644 src/changelog/.3.x.x/2937-http-watcher.xml diff --git a/log4j-core-test/pom.xml b/log4j-core-test/pom.xml index 47ca1a22d8c..b96526c7f7f 100644 --- a/log4j-core-test/pom.xml +++ b/log4j-core-test/pom.xml @@ -61,8 +61,34 @@ java.allocation.instrumenter;substitute="java-allocation-instrumenter", spring.test;substitute="spring-test" + + + 2.0.16 + 3.9.1 + + + + + + org.slf4j + slf4j-api + ${slf4j2.version} + + + + + + + com.google.code.gson + gson + 2.11.0 + + + + + @@ -235,13 +261,6 @@ test - - - log4j - log4j - test - - com.github.ivandzf log4j2-custom-layout @@ -282,11 +301,11 @@ test - + org.slf4j - slf4j-api - test + slf4j-nop + ${slf4j2.version} @@ -297,8 +316,9 @@ - com.github.tomakehurst - wiremock-jre8 + org.wiremock + wiremock + ${wiremock.version} test @@ -339,6 +359,8 @@ random false + + DEBUG false diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSourceTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSourceTest.java index f17b3b2a55a..5001ad2d449 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSourceTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSourceTest.java @@ -16,6 +16,7 @@ */ package org.apache.logging.log4j.core.config; +import static java.util.Objects.requireNonNull; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; @@ -32,21 +33,28 @@ import java.net.URL; import java.nio.file.Files; import java.nio.file.Path; -import java.nio.file.Paths; import java.util.jar.Attributes; import java.util.jar.JarEntry; import java.util.jar.JarOutputStream; import java.util.jar.Manifest; +import org.apache.commons.io.IOUtils; import org.apache.logging.log4j.core.net.UrlConnectionFactory; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; public class ConfigurationSourceTest { - private static final Path JAR_FILE = Paths.get("target", "test-classes", "jarfile.jar"); - private static final Path CONFIG_FILE = Paths.get("target", "test-classes", "log4j2-console.xml"); - private static final byte[] buffer = new byte[1024]; + /** + * The path inside the jar created by {@link #prepareJarConfigURL} containing the configuration. + */ + public static final String PATH_IN_JAR = "/config/console.xml"; + + private static final String CONFIG_FILE = "/config/ConfigurationSourceTest.xml"; + + @TempDir + private Path tempDir; @Test - public void testJira_LOG4J2_2770_byteArray() throws Exception { + void testJira_LOG4J2_2770_byteArray() throws Exception { final ConfigurationSource configurationSource = new ConfigurationSource(new ByteArrayInputStream(new byte[] {'a', 'b'})); assertNotNull(configurationSource.resetInputStream()); @@ -54,20 +62,19 @@ public void testJira_LOG4J2_2770_byteArray() throws Exception { /** * Checks if the usage of 'jar:' URLs does not increase the file descriptor - * count and the jar file can be deleted. - * - * @throws Exception + * count, and the jar file can be deleted. */ @Test - public void testNoJarFileLeak() throws Exception { - final URL jarConfigURL = prepareJarConfigURL(); + void testNoJarFileLeak() throws Exception { + final Path jarFile = prepareJarConfigURL(tempDir); + final URL jarConfigURL = new URL("jar:" + jarFile.toUri().toURL() + "!" + PATH_IN_JAR); final long expected = getOpenFileDescriptorCount(); UrlConnectionFactory.createConnection(jarConfigURL).getInputStream().close(); // This can only fail on UNIX assertEquals(expected, getOpenFileDescriptorCount()); // This can only fail on Windows try { - Files.delete(JAR_FILE); + Files.delete(jarFile); } catch (IOException e) { fail(e); } @@ -75,7 +82,8 @@ public void testNoJarFileLeak() throws Exception { @Test public void testLoadConfigurationSourceFromJarFile() throws Exception { - final URL jarConfigURL = prepareJarConfigURL(); + final Path jarFile = prepareJarConfigURL(tempDir); + final URL jarConfigURL = new URL("jar:" + jarFile.toUri().toURL() + "!" + PATH_IN_JAR); final long expectedFdCount = getOpenFileDescriptorCount(); ConfigurationSource configSource = ConfigurationSource.fromUri(jarConfigURL.toURI()); assertNotNull(configSource); @@ -90,7 +98,7 @@ public void testLoadConfigurationSourceFromJarFile() throws Exception { assertEquals(expectedFdCount, getOpenFileDescriptorCount()); // This can only fail on Windows try { - Files.delete(JAR_FILE); + Files.delete(jarFile); } catch (IOException e) { fail(e); } @@ -104,22 +112,18 @@ private long getOpenFileDescriptorCount() { return 0L; } - public static URL prepareJarConfigURL() throws IOException { - if (!Files.exists(JAR_FILE)) { - final Manifest manifest = new Manifest(); - manifest.getMainAttributes().put(Attributes.Name.MANIFEST_VERSION, "1.0"); - try (final OutputStream os = Files.newOutputStream(JAR_FILE); - final JarOutputStream jar = new JarOutputStream(os, manifest); - final InputStream config = Files.newInputStream(CONFIG_FILE)) { - final JarEntry jarEntry = new JarEntry("config/console.xml"); - jar.putNextEntry(jarEntry); - int len; - while ((len = config.read(buffer)) != -1) { - jar.write(buffer, 0, len); - } - jar.closeEntry(); - } + public static Path prepareJarConfigURL(Path dir) throws IOException { + Path jarFile = dir.resolve("jarFile.jar"); + final Manifest manifest = new Manifest(); + manifest.getMainAttributes().put(Attributes.Name.MANIFEST_VERSION, "1.0"); + try (final OutputStream os = Files.newOutputStream(jarFile); + final JarOutputStream jar = new JarOutputStream(os, manifest); + final InputStream config = + requireNonNull(ConfigurationSourceTest.class.getResourceAsStream(CONFIG_FILE))) { + final JarEntry jarEntry = new JarEntry("config/console.xml"); + jar.putNextEntry(jarEntry); + IOUtils.copy(config, os); } - return new URL("jar:" + JAR_FILE.toUri().toURL() + "!/config/console.xml"); + return jarFile; } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/HttpThreadContextMapFilterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/HttpThreadContextMapFilterTest.java deleted file mode 100644 index d35737b0b02..00000000000 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/HttpThreadContextMapFilterTest.java +++ /dev/null @@ -1,113 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to you 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 org.apache.logging.log4j.core.filter; - -import static com.github.tomakehurst.wiremock.client.WireMock.get; -import static com.github.tomakehurst.wiremock.client.WireMock.ok; -import static org.assertj.core.api.Assertions.assertThat; - -import com.github.tomakehurst.wiremock.WireMockServer; -import com.github.tomakehurst.wiremock.common.FileSource; -import com.github.tomakehurst.wiremock.core.WireMockConfiguration; -import com.github.tomakehurst.wiremock.extension.Parameters; -import com.github.tomakehurst.wiremock.extension.ResponseTransformer; -import com.github.tomakehurst.wiremock.http.Request; -import com.github.tomakehurst.wiremock.http.Response; -import java.net.HttpURLConnection; -import java.net.URL; -import java.util.concurrent.atomic.AtomicInteger; -import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.core.LoggerContext; -import org.apache.logging.log4j.core.test.appender.ListAppender; -import org.apache.logging.log4j.core.test.junit.LoggerContextSource; -import org.apache.logging.log4j.core.test.junit.Named; -import org.apache.logging.log4j.spi.ExtendedLogger; -import org.junit.jupiter.api.Test; - -/** - * Tests {@link ThreadContextMapFilter} using a WireMock stub. - */ -public class HttpThreadContextMapFilterTest { - - @Test - @LoggerContextSource("HttpThreadContextMapFilterTest.xml") - public void wireMock_logs_should_be_filtered_on_MDC( - final LoggerContext loggerContext, @Named("List") final ListAppender appender) throws Exception { - - // Create the logger - final ExtendedLogger logger = loggerContext.getLogger(HttpThreadContextMapFilterTest.class); - - // Create a response transformer; the only way to dynamically construct WireMock responses. - // We need a dynamic response generation, since there we will issue MDC changes and log statements. - final ResponseTransformer wireMockResponseTransformer = new ResponseTransformer() { - - private final AtomicInteger invocationCounter = new AtomicInteger(); - - @Override - public Response transform( - final Request request, - final Response response, - final FileSource files, - final Parameters parameters) { - final int invocationCount = invocationCounter.getAndIncrement(); - ThreadContext.put("invocationCount", "" + invocationCount); - logger.info("transforming request #{}", invocationCount); - return response; - } - - @Override - public String getName() { - return "mdc-writer"; - } - }; - - // Create the WireMock server extended using the response transformer. - final WireMockServer wireMockServer = new WireMockServer( - WireMockConfiguration.wireMockConfig().dynamicPort().extensions(wireMockResponseTransformer)); - wireMockServer.stubFor(get("/").willReturn(ok().withTransformers(wireMockResponseTransformer.getName()))); - - wireMockServer.start(); - try { - - // Perform some HTTP requests. - // `HttpThreadContextMapFilterTest.xml` only allows when `invocationCount={0,2}`. - // Hence, there preferably needs to be more than 2 requests. - final String wireMockStubUrl = wireMockServer.url("/"); - httpGet(wireMockStubUrl); - httpGet(wireMockStubUrl); - httpGet(wireMockStubUrl); - httpGet(wireMockStubUrl); - httpGet(wireMockStubUrl); - - // Verify that `invocationCount={0,2}` filter in `HttpThreadContextMapFilterTest.xml` works - assertThat(appender.getMessages()).containsOnly("transforming request #0", "transforming request #2"); - - } finally { - wireMockServer.stop(); - } - } - - private static void httpGet(String url) throws Exception { - final HttpURLConnection connection = (HttpURLConnection) new URL(url).openConnection(); - connection.connect(); - try { - assertThat(connection.getResponseCode()).isEqualTo(HttpURLConnection.HTTP_OK); - } finally { - connection.disconnect(); - } - } -} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilterTest.java index 1d4addf2873..0afd6dbae83 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilterTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilterTest.java @@ -16,101 +16,233 @@ */ package org.apache.logging.log4j.core.filter; -import static org.junit.jupiter.api.Assertions.assertNotEquals; +import static java.nio.charset.StandardCharsets.UTF_8; +import static org.apache.logging.log4j.core.net.WireMockUtil.createMapping; +import static org.apache.logging.log4j.core.test.TestConstants.AUTH_BASIC_PASSWORD; +import static org.apache.logging.log4j.core.test.TestConstants.AUTH_BASIC_USERNAME; +import static org.apache.logging.log4j.core.test.TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS; +import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertNotNull; -import static org.junit.jupiter.api.Assertions.assertTrue; -import static org.junit.jupiter.api.Assertions.fail; -import java.io.File; -import java.io.IOException; +import com.github.tomakehurst.wiremock.client.BasicCredentials; +import com.github.tomakehurst.wiremock.client.WireMock; +import com.github.tomakehurst.wiremock.junit5.WireMockRuntimeInfo; +import com.github.tomakehurst.wiremock.junit5.WireMockTest; +import java.io.ByteArrayInputStream; +import java.io.InputStream; +import java.net.URI; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.StandardCopyOption; -import java.util.concurrent.CountDownLatch; +import java.nio.file.attribute.FileTime; +import java.time.Instant; +import java.time.LocalDateTime; +import java.time.ZoneOffset; +import java.time.ZonedDateTime; +import java.time.temporal.ChronoUnit; import java.util.concurrent.TimeUnit; +import java.util.concurrent.locks.Condition; +import java.util.concurrent.locks.ReentrantLock; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.core.Appender; import org.apache.logging.log4j.core.LoggerContext; -import org.apache.logging.log4j.core.config.Configurator; +import org.apache.logging.log4j.core.config.Configuration; +import org.apache.logging.log4j.core.config.ConfigurationSource; import org.apache.logging.log4j.core.test.appender.ListAppender; +import org.apache.logging.log4j.plugins.di.ConfigurableInstanceFactory; +import org.apache.logging.log4j.plugins.di.DI; import org.apache.logging.log4j.test.TestProperties; -import org.apache.logging.log4j.test.junit.Log4jStaticResources; +import org.apache.logging.log4j.test.junit.SetTestProperty; import org.apache.logging.log4j.test.junit.UsingTestProperties; import org.junit.jupiter.api.AfterEach; -import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.parallel.ResourceLock; +import org.junit.jupiter.api.io.TempDir; /** * Unit test for simple App. */ +@SetTestProperty(key = CONFIGURATION_ALLOWED_PROTOCOLS, value = "http,https") +@SetTestProperty(key = AUTH_BASIC_PASSWORD, value = "log4j") +@SetTestProperty(key = AUTH_BASIC_USERNAME, value = "log4j") @UsingTestProperties -@ResourceLock(Log4jStaticResources.THREAD_CONTEXT) -@ResourceLock(Log4jStaticResources.LOG_MANAGER) -public class MutableThreadContextMapFilterTest implements MutableThreadContextMapFilter.FilterConfigUpdateListener { +@WireMockTest +class MutableThreadContextMapFilterTest implements MutableThreadContextMapFilter.FilterConfigUpdateListener { - static final String CONFIG = "MutableThreadContextMapFilterTest.xml"; - static LoggerContext loggerContext = null; - static File targetFile = new File("target/test-classes/testConfig.json"); - static Path target = targetFile.toPath(); - CountDownLatch updated = new CountDownLatch(1); + private static final BasicCredentials CREDENTIALS = new BasicCredentials("log4j", "log4j"); + private static final String FILE_NAME = "testConfig.json"; + private static final String URL_PATH = "/" + FILE_NAME; + private static final String JSON = "application/json"; + + private static final byte[] EMPTY_CONFIG = ("{" // + + " \"configs\":{}" // + + "}") + .getBytes(UTF_8); + private static final byte[] FILTER_CONFIG = ("{" // + + " \"configs\": {" // + + " \"loginId\": [\"rgoers\", \"adam\"]," // + + " \"corpAcctNumber\": [\"30510263\"]" // + + " }" // + + "}") + .getBytes(UTF_8); + + private static final String CONFIG = "filter/MutableThreadContextMapFilterTest.xml"; + private static final ConfigurableInstanceFactory instanceFactory = DI.createInitializedFactory(); + private static LoggerContext loggerContext = null; + private final ReentrantLock lock = new ReentrantLock(); + private final Condition filterUpdated = lock.newCondition(); + private final Condition resultVerified = lock.newCondition(); + private Exception exception; @AfterEach - public void after() { - try { - Files.deleteIfExists(target); - } catch (IOException ioe) { - // Ignore this. - } + void cleanup() { + exception = null; ThreadContext.clearMap(); - loggerContext.stop(); - loggerContext = null; + if (loggerContext != null) { + loggerContext.stop(); + loggerContext = null; + } } @Test - public void filterTest(final TestProperties properties) throws Exception { - properties.setProperty("configLocation", "target/test-classes/testConfig.json"); - ThreadContext.put("loginId", "rgoers"); - Path source = new File("target/test-classes/emptyConfig.json").toPath(); - Files.copy(source, target, StandardCopyOption.REPLACE_EXISTING); - final long fileTime = targetFile.lastModified() - 1000; - assertTrue(targetFile.setLastModified(fileTime)); - loggerContext = Configurator.initialize(null, CONFIG); - assertNotNull(loggerContext); - final Appender app = loggerContext.getConfiguration().getAppender("List"); - assertNotNull(app); - assertTrue(app instanceof ListAppender); - final MutableThreadContextMapFilter filter = - (MutableThreadContextMapFilter) loggerContext.getConfiguration().getFilter(); + void file_location_works(TestProperties properties, @TempDir Path dir) throws Exception { + // Set up the test file. + Instant now = Instant.now().truncatedTo(ChronoUnit.SECONDS); + Instant before = now.minus(1, ChronoUnit.MINUTES); + Instant after = now.plus(1, ChronoUnit.MINUTES); + Path testConfig = dir.resolve("testConfig.json"); + properties.setProperty("configLocation", testConfig.toString()); + try (final InputStream inputStream = new ByteArrayInputStream(EMPTY_CONFIG)) { + Files.copy(inputStream, testConfig); + Files.setLastModifiedTime(testConfig, FileTime.from(before)); + } + // Setup Log4j + ConfigurationSource source = + ConfigurationSource.fromResource(CONFIG, getClass().getClassLoader()); + loggerContext = new LoggerContext("file_location_works", null, (URI) null, instanceFactory); + Configuration configuration = loggerContext.getConfiguration(source); + configuration.initialize(); // To create the components + final ListAppender app = configuration.getAppender("LIST"); + assertThat(app).isNotNull(); + final MutableThreadContextMapFilter filter = (MutableThreadContextMapFilter) configuration.getFilter(); assertNotNull(filter); filter.registerListener(this); - final Logger logger = loggerContext.getLogger("Test"); - logger.debug("This is a test"); - Assertions.assertEquals(0, ((ListAppender) app).getEvents().size()); - source = new File("target/test-classes/filterConfig.json").toPath(); - String msg = null; - boolean copied = false; - for (int i = 0; i < 5 && !copied; ++i) { - Thread.sleep(100 + (100 * i)); - try { - Files.copy(source, target, StandardCopyOption.REPLACE_EXISTING); - copied = true; - } catch (Exception ex) { - msg = ex.getMessage(); + + lock.lock(); + try { + // Starts the configuration + loggerContext.start(configuration); + + final Logger logger = loggerContext.getLogger(MutableThreadContextMapFilterTest.class); + + assertThat(filterUpdated.await(20, TimeUnit.SECONDS)) + .as("Initial configuration was loaded") + .isTrue(); + ThreadContext.put("loginId", "rgoers"); + logger.debug("This is a test"); + assertThat(app.getEvents()).isEmpty(); + + // Prepare the second test case: updated config + try (final InputStream inputStream = new ByteArrayInputStream(FILTER_CONFIG)) { + Files.copy(inputStream, testConfig, StandardCopyOption.REPLACE_EXISTING); + Files.setLastModifiedTime(testConfig, FileTime.from(after)); } + resultVerified.signalAll(); + + assertThat(filterUpdated.await(20, TimeUnit.SECONDS)) + .as("Updated configuration was loaded") + .isTrue(); + logger.debug("This is a test"); + assertThat(app.getEvents()).hasSize(1); + + // Prepare the third test case: removed config + Files.delete(testConfig); + resultVerified.signalAll(); + + assertThat(filterUpdated.await(20, TimeUnit.SECONDS)) + .as("Configuration removal was detected") + .isTrue(); + logger.debug("This is a test"); + assertThat(app.getEvents()).hasSize(1); + resultVerified.signalAll(); + } finally { + lock.unlock(); } - assertTrue(copied, "File not copied: " + msg); - assertNotEquals(fileTime, targetFile.lastModified()); - if (!updated.await(5, TimeUnit.SECONDS)) { - fail("File update was not detected"); + assertThat(exception).as("Asynchronous exception").isNull(); + } + + @Test + void http_location_works(TestProperties properties, WireMockRuntimeInfo info) throws Exception { + WireMock wireMock = info.getWireMock(); + // Setup WireMock + // The HTTP Last-Modified header has a precision of 1 second + ZonedDateTime now = LocalDateTime.now().atZone(ZoneOffset.UTC); + ZonedDateTime before = now.minusMinutes(1); + ZonedDateTime after = now.plusMinutes(1); + properties.setProperty("configLocation", info.getHttpBaseUrl() + URL_PATH); + // Setup Log4j + ConfigurationSource source = + ConfigurationSource.fromResource(CONFIG, getClass().getClassLoader()); + loggerContext = new LoggerContext("http_location_works", null, (URI) null, instanceFactory); + Configuration configuration = loggerContext.getConfiguration(source); + configuration.initialize(); // To create the components + final ListAppender app = configuration.getAppender("LIST"); + assertThat(app).isNotNull(); + final MutableThreadContextMapFilter filter = (MutableThreadContextMapFilter) configuration.getFilter(); + assertNotNull(filter); + filter.registerListener(this); + lock.lock(); + try { + // Prepare the first test case: original empty config + wireMock.importStubMappings(createMapping(URL_PATH, CREDENTIALS, EMPTY_CONFIG, JSON, before)); + // Starts the configuration + loggerContext.start(configuration); + + final Logger logger = loggerContext.getLogger(MutableThreadContextMapFilterTest.class); + + assertThat(filterUpdated.await(2, TimeUnit.SECONDS)) + .as("Initial configuration was loaded") + .isTrue(); + ThreadContext.put("loginId", "rgoers"); + logger.debug("This is a test"); + assertThat(app.getEvents()).isEmpty(); + + // Prepare the second test case: updated config + wireMock.removeMappings(); + wireMock.importStubMappings(createMapping(URL_PATH, CREDENTIALS, FILTER_CONFIG, JSON, after)); + resultVerified.signalAll(); + + assertThat(filterUpdated.await(2, TimeUnit.SECONDS)) + .as("Updated configuration was loaded") + .isTrue(); + logger.debug("This is a test"); + assertThat(app.getEvents()).hasSize(1); + + // Prepare the third test case: removed config + wireMock.removeMappings(); + resultVerified.signalAll(); + + assertThat(filterUpdated.await(2, TimeUnit.SECONDS)) + .as("Configuration removal was detected") + .isTrue(); + logger.debug("This is a test"); + assertThat(app.getEvents()).hasSize(1); + resultVerified.signalAll(); + } finally { + lock.unlock(); } - logger.debug("This is a test"); - Assertions.assertEquals(1, ((ListAppender) app).getEvents().size()); + assertThat(exception).as("Asynchronous exception").isNull(); } @Override public void onEvent() { - updated.countDown(); + lock.lock(); + try { + filterUpdated.signalAll(); + resultVerified.await(); + } catch (final InterruptedException e) { + exception = e; + } finally { + lock.unlock(); + } } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/UrlConnectionFactoryTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/UrlConnectionFactoryTest.java index 3a5d8ba5b15..670f24d22ef 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/UrlConnectionFactoryTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/UrlConnectionFactoryTest.java @@ -16,20 +16,27 @@ */ package org.apache.logging.log4j.core.net; -import static javax.servlet.http.HttpServletResponse.SC_BAD_REQUEST; -import static javax.servlet.http.HttpServletResponse.SC_INTERNAL_SERVER_ERROR; -import static javax.servlet.http.HttpServletResponse.SC_NOT_FOUND; -import static javax.servlet.http.HttpServletResponse.SC_NOT_MODIFIED; -import static javax.servlet.http.HttpServletResponse.SC_OK; -import static javax.servlet.http.HttpServletResponse.SC_UNAUTHORIZED; +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static java.util.Objects.requireNonNull; +import static org.apache.hc.core5.http.HttpStatus.SC_INTERNAL_SERVER_ERROR; +import static org.apache.hc.core5.http.HttpStatus.SC_NOT_MODIFIED; +import static org.apache.hc.core5.http.HttpStatus.SC_OK; +import static org.apache.logging.log4j.core.config.ConfigurationSourceTest.PATH_IN_JAR; +import static org.apache.logging.log4j.core.net.WireMockUtil.createMapping; +import static org.apache.logging.log4j.core.test.TestConstants.AUTH_BASIC_PASSWORD; +import static org.apache.logging.log4j.core.test.TestConstants.AUTH_BASIC_USERNAME; +import static org.apache.logging.log4j.core.test.TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS; +import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; -import static org.junit.jupiter.api.Assertions.assertTrue; -import static org.junit.jupiter.api.Assertions.fail; +import com.github.tomakehurst.wiremock.client.BasicCredentials; +import com.github.tomakehurst.wiremock.client.WireMock; +import com.github.tomakehurst.wiremock.junit5.WireMockRuntimeInfo; +import com.github.tomakehurst.wiremock.junit5.WireMockTest; import com.sun.management.UnixOperatingSystemMXBean; -import java.io.File; +import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.InputStream; import java.lang.management.ManagementFactory; @@ -38,105 +45,108 @@ import java.net.URI; import java.net.URL; import java.nio.file.Files; -import java.util.Base64; -import java.util.Enumeration; -import javax.servlet.ServletException; -import javax.servlet.http.HttpServletRequest; -import javax.servlet.http.HttpServletResponse; +import java.nio.file.Path; +import java.nio.file.Paths; +import java.time.ZonedDateTime; +import java.time.temporal.ChronoUnit; +import java.util.List; +import java.util.stream.Collectors; +import java.util.stream.Stream; +import org.apache.commons.io.IOUtils; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.config.ConfigurationSource; import org.apache.logging.log4j.core.config.ConfigurationSourceTest; -import org.apache.logging.log4j.core.test.TestConstants; +import org.apache.logging.log4j.core.impl.CoreProperties.AuthenticationProperties; +import org.apache.logging.log4j.core.net.ssl.SslConfiguration; +import org.apache.logging.log4j.core.net.ssl.SslConfigurationFactory; +import org.apache.logging.log4j.core.util.AuthorizationProvider; import org.apache.logging.log4j.kit.env.PropertyEnvironment; import org.apache.logging.log4j.test.junit.SetTestProperty; -import org.eclipse.jetty.http.HttpHeader; -import org.eclipse.jetty.server.Server; -import org.eclipse.jetty.server.ServerConnector; -import org.eclipse.jetty.servlet.DefaultServlet; -import org.eclipse.jetty.servlet.ServletContextHandler; -import org.eclipse.jetty.servlet.ServletHolder; -import org.junit.jupiter.api.AfterAll; -import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.condition.DisabledOnOs; import org.junit.jupiter.api.condition.OS; -import org.junit.jupiter.api.parallel.Isolated; +import org.junit.jupiter.api.io.TempDir; import org.junitpioneer.jupiter.RetryingTest; /** * Tests the UrlConnectionFactory */ -@Isolated -public class UrlConnectionFactoryTest { +@WireMockTest +@SetTestProperty(key = CONFIGURATION_ALLOWED_PROTOCOLS, value = "jar,http") +class UrlConnectionFactoryTest { private static final Logger LOGGER = LogManager.getLogger(UrlConnectionFactoryTest.class); - private static final String BASIC = "Basic "; - private static final String expectedCreds = "testuser:password"; - private static Server server; - private static final Base64.Decoder decoder = Base64.getDecoder(); - private static int port; - - @BeforeAll - public static void startServer() throws Exception { - try { - server = new Server(0); - final ServletContextHandler context = new ServletContextHandler(); - final ServletHolder defaultServ = new ServletHolder("default", TestServlet.class); - defaultServ.setInitParameter("resourceBase", System.getProperty("user.dir")); - defaultServ.setInitParameter("dirAllowed", "true"); - context.addServlet(defaultServ, "/"); - server.setHandler(context); - - // Start Server - server.start(); - port = ((ServerConnector) server.getConnectors()[0]).getLocalPort(); - } catch (Throwable ex) { - ex.printStackTrace(); - throw ex; + + private static final String URL_PATH = "/log4j2-config.xml"; + private static final BasicCredentials CREDENTIALS = new BasicCredentials("testUser", "password"); + private static final byte[] CONFIG_FILE_BODY; + private static final String CONTENT_TYPE = "application/xml"; + + private final PropertyEnvironment environment = PropertyEnvironment.getGlobal(); + private final SslConfiguration sslConfiguration = SslConfigurationFactory.getSslConfiguration(environment); + + static { + try (InputStream input = requireNonNull( + UrlConnectionFactoryTest.class.getClassLoader().getResourceAsStream("log4j2-config.xml"))) { + ByteArrayOutputStream output = new ByteArrayOutputStream(); + IOUtils.copy(input, output); + CONFIG_FILE_BODY = output.toByteArray(); + } catch (IOException e) { + throw new AssertionError(e); } } - @AfterAll - public static void stopServer() throws Exception { - server.stop(); + @AfterEach + void cleanup(WireMockRuntimeInfo info) { + info.getWireMock().removeMappings(); } @Test - @SetTestProperty(key = TestConstants.AUTH_BASIC_USERNAME, value = "foo") - @SetTestProperty(key = TestConstants.AUTH_BASIC_PASSWORD, value = "bar") - @SetTestProperty(key = TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS, value = "http") - public void testBadCrdentials() throws Exception { - final URI uri = new URI("http://localhost:" + port + "/log4j2-config.xml"); + @SetTestProperty(key = AUTH_BASIC_USERNAME, value = "foo") + @SetTestProperty(key = AUTH_BASIC_PASSWORD, value = "bar") + void testBadCredentials(WireMockRuntimeInfo info) throws Exception { + WireMock wireMock = info.getWireMock(); + // RFC 1123 format rounds to full seconds + ZonedDateTime now = ZonedDateTime.now().truncatedTo(ChronoUnit.SECONDS); + wireMock.importStubMappings(createMapping(URL_PATH, CREDENTIALS, CONFIG_FILE_BODY, CONTENT_TYPE, now)); + final URI uri = new URI(info.getHttpBaseUrl() + URL_PATH); final ConfigurationSource source = ConfigurationSource.fromUri(uri); assertNull(source, "A ConfigurationSource should not have been returned"); } @Test - @SetTestProperty(key = TestConstants.AUTH_BASIC_USERNAME, value = "testuser") - @SetTestProperty(key = TestConstants.AUTH_BASIC_PASSWORD, value = "password") - @SetTestProperty(key = TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS, value = "http") - public void withAuthentication() throws Exception { - final URI uri = new URI("http://localhost:" + port + "/log4j2-config.xml"); + @SetTestProperty(key = AUTH_BASIC_USERNAME, value = "testUser") + @SetTestProperty(key = AUTH_BASIC_PASSWORD, value = "password") + public void withAuthentication(WireMockRuntimeInfo info) throws Exception { + WireMock wireMock = info.getWireMock(); + // RFC 1123 format rounds to full seconds + ZonedDateTime now = ZonedDateTime.now().truncatedTo(ChronoUnit.SECONDS); + wireMock.importStubMappings(createMapping(URL_PATH, CREDENTIALS, CONFIG_FILE_BODY, CONTENT_TYPE, now)); + final URI uri = new URI(info.getHttpBaseUrl() + URL_PATH); final ConfigurationSource source = ConfigurationSource.fromUri(uri); assertNotNull(source, "No ConfigurationSource returned"); final InputStream is = source.getInputStream(); assertNotNull(is, "No data returned"); is.close(); final long lastModified = source.getLastModified(); + assertThat(lastModified).isEqualTo(now.toInstant().toEpochMilli()); int result = verifyNotModified(uri, lastModified); assertEquals(SC_NOT_MODIFIED, result, "File was modified"); - final File file = new File("target/test-classes/log4j2-config.xml"); - if (!file.setLastModified(System.currentTimeMillis())) { - fail("Unable to set last modified time"); - } + + wireMock.removeMappings(); + now = now.plusMinutes(5); + wireMock.importStubMappings(createMapping(URL_PATH, CREDENTIALS, CONFIG_FILE_BODY, CONTENT_TYPE, now)); result = verifyNotModified(uri, lastModified); assertEquals(SC_OK, result, "File was not modified"); } - private int verifyNotModified(final URI uri, final long lastModifiedMillis) throws Exception { - final HttpURLConnection urlConnection = UrlConnectionFactory.createConnection( - uri.toURL(), lastModifiedMillis, null, null, PropertyEnvironment.getGlobal()); + private int verifyNotModified(URI uri, long lastModifiedMillis) throws Exception { + AuthorizationProvider authorizationProvider = + AuthorizationProvider.getAuthorizationProvider(environment.getProperty(AuthenticationProperties.class)); + HttpURLConnection urlConnection = UrlConnectionFactory.createConnection( + uri.toURL(), lastModifiedMillis, sslConfiguration, authorizationProvider, environment); urlConnection.connect(); try { @@ -149,20 +159,39 @@ private int verifyNotModified(final URI uri, final long lastModifiedMillis) thro @RetryingTest(maxAttempts = 5, suspendForMs = 1000) @DisabledOnOs(value = OS.WINDOWS, disabledReason = "Fails frequently on Windows (#2011)") - public void testNoJarFileLeak() throws Exception { - ConfigurationSourceTest.prepareJarConfigURL(); - final URL url = new File("target/test-classes/jarfile.jar").toURI().toURL(); + @SetTestProperty(key = AUTH_BASIC_USERNAME, value = "testUser") + @SetTestProperty(key = AUTH_BASIC_PASSWORD, value = "password") + void testNoJarFileLeak(@TempDir Path dir, WireMockRuntimeInfo info) throws Exception { + Path jarFile = ConfigurationSourceTest.prepareJarConfigURL(dir); // Retrieve using 'file:' - URL jarUrl = new URL("jar:" + url.toString() + "!/config/console.xml"); + URL jarUrl = new URL("jar:" + jarFile.toUri().toURL() + "!" + PATH_IN_JAR); long expected = getOpenFileDescriptorCount(); UrlConnectionFactory.createConnection(jarUrl).getInputStream().close(); assertEquals(expected, getOpenFileDescriptorCount()); + + // Prepare mock + ByteArrayOutputStream body = new ByteArrayOutputStream(); + try (InputStream inputStream = Files.newInputStream(jarFile)) { + IOUtils.copy(inputStream, body); + } + WireMock wireMock = info.getWireMock(); + wireMock.register(WireMock.get("/jarFile.jar") + .willReturn( + aResponse().withStatus(200).withBodyFile("jarFile.jar").withBody(body.toByteArray()))); // Retrieve using 'http:' - jarUrl = new URL("jar:http://localhost:" + port + "/jarfile.jar!/config/console.xml"); - final File tmpDir = new File(System.getProperty("java.io.tmpdir")); - expected = tmpDir.list().length; + jarUrl = new URL("jar:" + info.getHttpBaseUrl() + "/jarFile.jar!" + PATH_IN_JAR); + // URLConnection leaves JAR files in the temporary directory + Path tmpDir = Paths.get(System.getProperty("java.io.tmpdir")); + List expectedFiles; + try (Stream stream = Files.list(tmpDir)) { + expectedFiles = stream.collect(Collectors.toList()); + } UrlConnectionFactory.createConnection(jarUrl).getInputStream().close(); - assertEquals(expected, tmpDir.list().length, "File descriptor leak"); + List actualFiles; + try (Stream stream = Files.list(tmpDir)) { + actualFiles = stream.collect(Collectors.toList()); + } + assertThat(actualFiles).containsExactlyElementsOf(expectedFiles); } private long getOpenFileDescriptorCount() { @@ -172,53 +201,4 @@ private long getOpenFileDescriptorCount() { } return 0L; } - - public static class TestServlet extends DefaultServlet { - - private static final long serialVersionUID = -2885158530511450659L; - - @Override - protected void doGet(final HttpServletRequest request, final HttpServletResponse response) - throws ServletException, IOException { - final Enumeration headers = request.getHeaders(HttpHeader.AUTHORIZATION.toString()); - if (headers == null) { - response.sendError(SC_UNAUTHORIZED, "No Auth header"); - return; - } - while (headers.hasMoreElements()) { - final String authData = headers.nextElement(); - assertTrue(authData.startsWith(BASIC), "Not a Basic auth header"); - final String credentials = new String(decoder.decode(authData.substring(BASIC.length()))); - if (!expectedCreds.equals(credentials)) { - response.sendError(SC_UNAUTHORIZED, "Invalid credentials"); - return; - } - } - final String servletPath = request.getServletPath(); - if (servletPath != null) { - File file = new File("target/classes" + servletPath); - if (!file.exists()) { - file = new File("target/test-classes" + servletPath); - } - if (!file.exists()) { - response.sendError(SC_NOT_FOUND); - return; - } - final long modifiedSince = request.getDateHeader(HttpHeader.IF_MODIFIED_SINCE.toString()); - final long lastModified = (file.lastModified() / 1000) * 1000; - LOGGER.debug("LastModified: {}, modifiedSince: {}", lastModified, modifiedSince); - if (modifiedSince > 0 && lastModified <= modifiedSince) { - response.setStatus(SC_NOT_MODIFIED); - return; - } - response.setDateHeader(HttpHeader.LAST_MODIFIED.toString(), lastModified); - response.setContentLengthLong(file.length()); - Files.copy(file.toPath(), response.getOutputStream()); - response.getOutputStream().flush(); - response.setStatus(SC_OK); - } else { - response.sendError(SC_BAD_REQUEST, "Unsupported request"); - } - } - } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/WireMockUtil.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/WireMockUtil.java new file mode 100644 index 00000000000..f8655742320 --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/WireMockUtil.java @@ -0,0 +1,84 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you 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 org.apache.logging.log4j.core.net; + +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static com.github.tomakehurst.wiremock.client.WireMock.absent; +import static com.github.tomakehurst.wiremock.client.WireMock.after; +import static com.github.tomakehurst.wiremock.client.WireMock.anyUrl; +import static com.github.tomakehurst.wiremock.client.WireMock.before; +import static com.github.tomakehurst.wiremock.client.WireMock.equalToDateTime; +import static com.github.tomakehurst.wiremock.client.WireMock.get; +import static com.github.tomakehurst.wiremock.client.WireMock.notContaining; +import static com.github.tomakehurst.wiremock.stubbing.StubImport.stubImport; +import static com.google.common.net.HttpHeaders.AUTHORIZATION; +import static com.google.common.net.HttpHeaders.CONTENT_TYPE; +import static com.google.common.net.HttpHeaders.IF_MODIFIED_SINCE; +import static com.google.common.net.HttpHeaders.LAST_MODIFIED; + +import com.github.tomakehurst.wiremock.client.BasicCredentials; +import com.github.tomakehurst.wiremock.stubbing.StubImport; +import java.time.ZoneOffset; +import java.time.ZonedDateTime; +import java.time.format.DateTimeFormatter; + +public class WireMockUtil { + + private static final DateTimeFormatter formatter = DateTimeFormatter.RFC_1123_DATE_TIME.withZone(ZoneOffset.UTC); + + /** + * Establishes a set of mapping to serve a file + * + * @param urlPath The URL path of the served file + * @param credentials The credentials to use for authentication + * @param body The body of the file + * @param contentType The MIME content type of the file + * @param lastModified The last modification date of the file + * @return A set of mappings + */ + public static StubImport createMapping( + String urlPath, BasicCredentials credentials, byte[] body, String contentType, ZonedDateTime lastModified) { + int idx = urlPath.lastIndexOf('/'); + String fileName = idx == -1 ? urlPath : urlPath.substring(idx + 1); + return stubImport() + // Lack of authentication data + .stub(get(anyUrl()) + .withHeader(AUTHORIZATION, absent()) + .willReturn(aResponse().withStatus(401).withStatusMessage("Not Authenticated"))) + // Wrong authentication data + .stub(get(anyUrl()) + .withHeader(AUTHORIZATION, notContaining(credentials.asAuthorizationHeaderValue())) + .willReturn(aResponse().withStatus(403).withStatusMessage("Not Authorized"))) + // Serves the file + .stub(get(urlPath) + .withBasicAuth(credentials.username, credentials.password) + .withHeader(IF_MODIFIED_SINCE, before(lastModified).or(absent())) + .willReturn(aResponse() + .withStatus(200) + .withBodyFile(fileName) + .withBody(body) + .withHeader(LAST_MODIFIED, formatter.format(lastModified)) + .withHeader(CONTENT_TYPE, contentType))) + // The file was not updated since lastModified + .stub(get(urlPath) + .withBasicAuth(credentials.username, credentials.password) + .withHeader(IF_MODIFIED_SINCE, after(lastModified).or(equalToDateTime(lastModified))) + .willReturn( + aResponse().withStatus(304).withHeader(LAST_MODIFIED, formatter.format(lastModified)))) + .build(); + } +} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/HttpWatcherTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/HttpWatcherTest.java new file mode 100644 index 00000000000..a7b6eb34dff --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/HttpWatcherTest.java @@ -0,0 +1,158 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you 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 org.apache.logging.log4j.core.util; + +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static com.github.tomakehurst.wiremock.client.WireMock.get; +import static java.util.Collections.singletonList; +import static org.apache.logging.log4j.core.test.TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS; +import static org.assertj.core.api.Assertions.assertThat; + +import com.github.tomakehurst.wiremock.client.WireMock; +import com.github.tomakehurst.wiremock.junit5.WireMockRuntimeInfo; +import com.github.tomakehurst.wiremock.junit5.WireMockTest; +import com.github.tomakehurst.wiremock.stubbing.StubMapping; +import java.net.URL; +import java.time.Instant; +import java.time.ZoneOffset; +import java.time.format.DateTimeFormatter; +import java.time.temporal.ChronoUnit; +import java.util.List; +import java.util.Queue; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.LinkedBlockingQueue; +import java.util.concurrent.TimeUnit; +import java.util.function.Consumer; +import org.apache.logging.log4j.core.config.AbstractConfiguration; +import org.apache.logging.log4j.core.config.Configuration; +import org.apache.logging.log4j.core.config.ConfigurationSource; +import org.apache.logging.log4j.core.config.HttpWatcher; +import org.apache.logging.log4j.core.config.Reconfigurable; +import org.apache.logging.log4j.kit.env.PropertyEnvironment; +import org.apache.logging.log4j.plugins.di.ConfigurableInstanceFactory; +import org.apache.logging.log4j.plugins.di.DI; +import org.apache.logging.log4j.test.junit.SetTestProperty; +import org.junit.jupiter.api.Test; + +/** + * Test the WatchManager + */ +@SetTestProperty(key = CONFIGURATION_ALLOWED_PROTOCOLS, value = "http,https") +@WireMockTest +class HttpWatcherTest { + + private static final DateTimeFormatter formatter = DateTimeFormatter.RFC_1123_DATE_TIME.withZone(ZoneOffset.UTC); + private static final String XML = "application/xml"; + private static final ConfigurableInstanceFactory instanceFactory = DI.createInitializedFactory(); + + @Test + void testModified(final WireMockRuntimeInfo info) throws Exception { + final WireMock wireMock = info.getWireMock(); + + final BlockingQueue queue = new LinkedBlockingQueue<>(); + List> listeners = + singletonList(new TestConfigurationListener(queue, "log4j-test1.xml")); + // HTTP Last-Modified is in seconds + Instant now = Instant.now().truncatedTo(ChronoUnit.SECONDS); + Instant previous = now.minus(5, ChronoUnit.MINUTES); + final URL url = new URL(info.getHttpBaseUrl() + "/log4j-test1.xml"); + final Configuration configuration = createConfiguration(url); + + final StubMapping stubMapping = wireMock.register(get("/log4j-test1.xml") + .willReturn(aResponse() + .withBodyFile("log4j-test1.xml") + .withStatus(200) + .withHeader("Last-Modified", formatter.format(previous)) + .withHeader("Content-Type", XML))); + Watcher watcher = new HttpWatcher(configuration, null, listeners, previous.toEpochMilli()); + watcher.watching(new Source(url)); + try { + assertThat(watcher.isModified()).as("File was modified").isTrue(); + assertThat(watcher.getLastModified()).as("File modification time").isEqualTo(previous.toEpochMilli()); + // Check if listeners are correctly called + // Note: listeners are called asynchronously + watcher.modified(); + String str = queue.poll(1, TimeUnit.SECONDS); + assertThat(str).isEqualTo("log4j-test1.xml"); + ConfigurationSource configurationSource = configuration.getConfigurationSource(); + // Check that the last modified time of the ConfigurationSource was modified as well + // See: https://github.com/apache/logging-log4j2/issues/2937 + assertThat(configurationSource.getLastModified()) + .as("Last modification time of current ConfigurationSource") + .isEqualTo(0L); + configurationSource = configurationSource.resetInputStream(); + assertThat(configurationSource.getLastModified()) + .as("Last modification time of next ConfigurationSource") + .isEqualTo(previous.toEpochMilli()); + } finally { + wireMock.removeStubMapping(stubMapping); + } + } + + @Test + void testNotModified(final WireMockRuntimeInfo info) throws Exception { + final WireMock wireMock = info.getWireMock(); + + final BlockingQueue queue = new LinkedBlockingQueue<>(); + List> listeners = + singletonList(new TestConfigurationListener(queue, "log4j-test2.xml")); + // HTTP Last-Modified is in seconds + Instant now = Instant.now().truncatedTo(ChronoUnit.SECONDS); + Instant previous = now.minus(5, ChronoUnit.MINUTES); + final URL url = new URL(info.getHttpBaseUrl() + "/log4j-test2.xml"); + final Configuration configuration = createConfiguration(url); + + final StubMapping stubMapping = wireMock.register(get("/log4j-test2.xml") + .willReturn(aResponse() + .withStatus(304) + .withHeader("Last-Modified", formatter.format(now) + " GMT") + .withHeader("Content-Type", XML))); + Watcher watcher = new HttpWatcher(configuration, null, listeners, previous.toEpochMilli()); + watcher.watching(new Source(url)); + try { + assertThat(watcher.isModified()).as("File was modified").isFalse(); + // If the file was not modified, neither should be the last modification time + assertThat(watcher.getLastModified()).isEqualTo(previous.toEpochMilli()); + // Check that the last modified time of the ConfigurationSource was not modified either + ConfigurationSource configurationSource = configuration.getConfigurationSource(); + assertThat(configurationSource.getLastModified()) + .as("Last modification time of current ConfigurationSource") + .isEqualTo(0L); + configurationSource = configurationSource.resetInputStream(); + assertThat(configurationSource.getLastModified()) + .as("Last modification time of next ConfigurationSource") + .isEqualTo(0L); + } finally { + wireMock.removeStubMapping(stubMapping); + } + } + + // Creates a configuration with a predefined configuration source + private static Configuration createConfiguration(URL url) { + ConfigurationSource configurationSource = new ConfigurationSource(new Source(url), new byte[0], 0L); + return new AbstractConfiguration( + null, configurationSource, instanceFactory.getInstance(PropertyEnvironment.class), instanceFactory) {}; + } + + private record TestConfigurationListener(Queue queue, String name) implements Consumer { + + @Override + public void accept(Reconfigurable ignored) { + queue.add(name); + } + } +} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchHttpTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchHttpTest.java deleted file mode 100644 index 7e5057a113a..00000000000 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchHttpTest.java +++ /dev/null @@ -1,159 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to you 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 org.apache.logging.log4j.core.util; - -import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; -import static com.github.tomakehurst.wiremock.client.WireMock.get; -import static com.github.tomakehurst.wiremock.client.WireMock.urlPathEqualTo; -import static org.junit.Assert.assertNotNull; -import static org.junit.Assert.assertNull; -import static org.junit.jupiter.api.Assumptions.assumeTrue; - -import com.github.tomakehurst.wiremock.client.WireMock; -import com.github.tomakehurst.wiremock.junit5.WireMockRuntimeInfo; -import com.github.tomakehurst.wiremock.junit5.WireMockTest; -import com.github.tomakehurst.wiremock.stubbing.StubMapping; -import java.net.URL; -import java.util.ArrayList; -import java.util.Calendar; -import java.util.List; -import java.util.Queue; -import java.util.TimeZone; -import java.util.concurrent.BlockingQueue; -import java.util.concurrent.LinkedBlockingQueue; -import java.util.concurrent.TimeUnit; -import java.util.function.Consumer; -import org.apache.logging.log4j.core.config.Configuration; -import org.apache.logging.log4j.core.config.ConfigurationScheduler; -import org.apache.logging.log4j.core.config.DefaultConfiguration; -import org.apache.logging.log4j.core.config.HttpWatcher; -import org.apache.logging.log4j.core.config.Reconfigurable; -import org.apache.logging.log4j.core.test.TestConstants; -import org.apache.logging.log4j.core.util.datetime.FastDateFormat; -import org.apache.logging.log4j.status.StatusLogger; -import org.apache.logging.log4j.test.junit.SetTestProperty; -import org.apache.logging.log4j.util.PropertiesUtil; -import org.junit.jupiter.api.Test; - -/** - * Test the WatchManager - */ -@SetTestProperty(key = TestConstants.CONFIGURATION_ALLOWED_PROTOCOLS, value = "http,https") -@WireMockTest -public class WatchHttpTest { - - private static final String FORCE_RUN_KEY = WatchHttpTest.class.getSimpleName() + ".forceRun"; - private final String file = "log4j-test1.xml"; - private static final TimeZone UTC = TimeZone.getTimeZone("UTC"); - private static FastDateFormat formatter = FastDateFormat.getInstance("EEE, dd MMM yyyy HH:mm:ss", UTC); - private static final String XML = "application/xml"; - - private static final boolean IS_WINDOWS = PropertiesUtil.getProperties().isOsWindows(); - - @Test - public void testWatchManager(final WireMockRuntimeInfo info) throws Exception { - assumeTrue(!IS_WINDOWS || Boolean.getBoolean(FORCE_RUN_KEY)); - final WireMock wireMock = info.getWireMock(); - - final BlockingQueue queue = new LinkedBlockingQueue<>(); - final List> listeners = new ArrayList<>(); - listeners.add(new TestConfigurationListener(queue, "log4j-test1.xml")); - final Calendar now = Calendar.getInstance(UTC); - final Calendar previous = now; - previous.add(Calendar.MINUTE, -5); - final Configuration configuration = new DefaultConfiguration(); - final URL url = new URL(info.getHttpBaseUrl() + "/log4j-test1.xml"); - final StubMapping stubMapping = wireMock.register(get(urlPathEqualTo("/log4j-test1.xml")) - .willReturn(aResponse() - .withBodyFile(file) - .withStatus(200) - .withHeader("Last-Modified", formatter.format(previous) + " GMT") - .withHeader("Content-Type", XML))); - final ConfigurationScheduler scheduler = new ConfigurationScheduler(); - scheduler.incrementScheduledItems(); - final WatchManager watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); - watchManager.setIntervalSeconds(1); - scheduler.start(); - watchManager.start(); - try { - watchManager.watch( - new Source(url.toURI()), - new HttpWatcher(configuration, null, listeners, previous.getTimeInMillis())); - final String str = queue.poll(2, TimeUnit.SECONDS); - assertNotNull("File change not detected", str); - } finally { - watchManager.stop(); - scheduler.stop(); - wireMock.removeStubMapping(stubMapping); - } - } - - @Test - public void testNotModified(final WireMockRuntimeInfo info) throws Exception { - assumeTrue(!IS_WINDOWS || Boolean.getBoolean(FORCE_RUN_KEY)); - final WireMock wireMock = info.getWireMock(); - - final BlockingQueue queue = new LinkedBlockingQueue<>(); - final List> listeners = new ArrayList<>(); - listeners.add(new TestConfigurationListener(queue, "log4j-test2.xml")); - final TimeZone timeZone = TimeZone.getTimeZone("UTC"); - final Calendar now = Calendar.getInstance(timeZone); - final Calendar previous = now; - previous.add(Calendar.MINUTE, -5); - final Configuration configuration = new DefaultConfiguration(); - final URL url = new URL(info.getHttpBaseUrl() + "/log4j-test2.xml"); - final StubMapping stubMapping = wireMock.register(get(urlPathEqualTo("/log4j-test2.xml")) - .willReturn(aResponse() - .withBodyFile(file) - .withStatus(304) - .withHeader("Last-Modified", formatter.format(now) + " GMT") - .withHeader("Content-Type", XML))); - final ConfigurationScheduler scheduler = new ConfigurationScheduler(); - scheduler.incrementScheduledItems(); - final WatchManager watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); - watchManager.setIntervalSeconds(1); - scheduler.start(); - watchManager.start(); - try { - watchManager.watch( - new Source(url.toURI()), - new HttpWatcher(configuration, null, listeners, previous.getTimeInMillis())); - final String str = queue.poll(2, TimeUnit.SECONDS); - assertNull("File changed.", str); - } finally { - watchManager.stop(); - scheduler.stop(); - wireMock.removeStubMapping(stubMapping); - } - } - - private static class TestConfigurationListener implements Consumer { - private final Queue queue; - private final String name; - - public TestConfigurationListener(final Queue queue, final String name) { - this.queue = queue; - this.name = name; - } - - @Override - public void accept(final Reconfigurable reconfigurable) { - // System.out.println("Reconfiguration detected for " + name); - queue.add(name); - } - } -} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchManagerTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchManagerTest.java index 318252f7713..0bfceaf3432 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchManagerTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/WatchManagerTest.java @@ -18,6 +18,12 @@ import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; +import static org.mockito.Mockito.clearInvocations; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.timeout; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; import java.io.File; import java.io.FileOutputStream; @@ -31,7 +37,8 @@ import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.core.config.ConfigurationScheduler; import org.apache.logging.log4j.status.StatusLogger; -import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.condition.DisabledOnOs; import org.junit.jupiter.api.condition.EnabledIfSystemProperty; @@ -42,107 +49,111 @@ */ @DisabledOnOs(OS.WINDOWS) @EnabledIfSystemProperty(named = "WatchManagerTest.forceRun", matches = "true") -@Tag("sleepy") -public class WatchManagerTest { +class WatchManagerTest { private final String testFile = "target/testWatchFile"; private final String originalFile = "target/test-classes/log4j-test1.xml"; private final String newFile = "target/test-classes/log4j-test1.yaml"; - @Test - public void testWatchManager() throws Exception { - final ConfigurationScheduler scheduler = new ConfigurationScheduler(); + private ConfigurationScheduler scheduler; + private WatchManager watchManager; + + @BeforeEach + void setUp() { + scheduler = new ConfigurationScheduler(); scheduler.incrementScheduledItems(); - final WatchManager watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); + watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); watchManager.setIntervalSeconds(1); scheduler.start(); watchManager.start(); - try { - final File sourceFile = new File(originalFile); - Path source = Paths.get(sourceFile.toURI()); - try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { - Files.copy(source, targetStream); - } - final File updateFile = new File(newFile); - final File targetFile = new File(testFile); - final BlockingQueue queue = new LinkedBlockingQueue<>(); - watchManager.watchFile(targetFile, new TestWatcher(queue)); - Thread.sleep(1000); - source = Paths.get(updateFile.toURI()); - Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); - Thread.sleep(1000); - final File f = queue.poll(1, TimeUnit.SECONDS); - assertNotNull(f, "File change not detected"); - } finally { - watchManager.stop(); - scheduler.stop(); - } + } + + @AfterEach + void tearDown() { + watchManager.stop(); + scheduler.stop(); + watchManager = null; + scheduler = null; } @Test - public void testWatchManagerReset() throws Exception { - final ConfigurationScheduler scheduler = new ConfigurationScheduler(); - scheduler.incrementScheduledItems(); - final WatchManager watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); - watchManager.setIntervalSeconds(1); - scheduler.start(); - watchManager.start(); - try { - final File sourceFile = new File(originalFile); - Path source = Paths.get(sourceFile.toURI()); - try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { - Files.copy(source, targetStream); - } - final File updateFile = new File(newFile); - final File targetFile = new File(testFile); - final BlockingQueue queue = new LinkedBlockingQueue<>(); - watchManager.watchFile(targetFile, new TestWatcher(queue)); - watchManager.stop(); - Thread.sleep(1000); - source = Paths.get(updateFile.toURI()); - Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); - watchManager.reset(); - watchManager.start(); - Thread.sleep(1000); - final File f = queue.poll(1, TimeUnit.SECONDS); - assertNull(f, "File change detected"); - } finally { - watchManager.stop(); - scheduler.stop(); + void testWatchManager() throws Exception { + final File sourceFile = new File(originalFile); + Path source = Paths.get(sourceFile.toURI()); + try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { + Files.copy(source, targetStream); } + final File updateFile = new File(newFile); + final File targetFile = new File(testFile); + final BlockingQueue queue = new LinkedBlockingQueue<>(); + watchManager.watchFile(targetFile, new TestWatcher(queue)); + Thread.sleep(1000); + source = Paths.get(updateFile.toURI()); + Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); + Thread.sleep(1000); + final File f = queue.poll(1, TimeUnit.SECONDS); + assertNotNull(f, "File change not detected"); } @Test - public void testWatchManagerResetFile() throws Exception { - final ConfigurationScheduler scheduler = new ConfigurationScheduler(); - scheduler.incrementScheduledItems(); - final WatchManager watchManager = new WatchManager(scheduler, StatusLogger.getLogger()); - watchManager.setIntervalSeconds(1); - scheduler.start(); + void testWatchManagerReset() throws Exception { + final File sourceFile = new File(originalFile); + Path source = Paths.get(sourceFile.toURI()); + try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { + Files.copy(source, targetStream); + } + final File updateFile = new File(newFile); + final File targetFile = new File(testFile); + final BlockingQueue queue = new LinkedBlockingQueue<>(); + watchManager.watchFile(targetFile, new TestWatcher(queue)); + watchManager.stop(); + Thread.sleep(1000); + source = Paths.get(updateFile.toURI()); + Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); + watchManager.reset(); watchManager.start(); - try { - final File sourceFile = new File(originalFile); - Path source = Paths.get(sourceFile.toURI()); - try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { - Files.copy(source, targetStream); - } - final File updateFile = new File(newFile); - final File targetFile = new File(testFile); - final BlockingQueue queue = new LinkedBlockingQueue<>(); - watchManager.watchFile(targetFile, new TestWatcher(queue)); - watchManager.stop(); - Thread.sleep(1000); - source = Paths.get(updateFile.toURI()); - Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); - watchManager.reset(targetFile); - watchManager.start(); - Thread.sleep(1000); - final File f = queue.poll(1, TimeUnit.SECONDS); - assertNull(f, "File change detected"); - } finally { - watchManager.stop(); - scheduler.stop(); + Thread.sleep(1000); + final File f = queue.poll(1, TimeUnit.SECONDS); + assertNull(f, "File change detected"); + } + + @Test + void testWatchManagerResetFile() throws Exception { + final File sourceFile = new File(originalFile); + Path source = Paths.get(sourceFile.toURI()); + try (final FileOutputStream targetStream = new FileOutputStream(testFile)) { + Files.copy(source, targetStream); } + final File updateFile = new File(newFile); + final File targetFile = new File(testFile); + final BlockingQueue queue = new LinkedBlockingQueue<>(); + watchManager.watchFile(targetFile, new TestWatcher(queue)); + watchManager.stop(); + Thread.sleep(1000); + source = Paths.get(updateFile.toURI()); + Files.copy(source, Paths.get(targetFile.toURI()), StandardCopyOption.REPLACE_EXISTING); + watchManager.reset(targetFile); + watchManager.start(); + Thread.sleep(1000); + final File f = queue.poll(1, TimeUnit.SECONDS); + assertNull(f, "File change detected"); + } + + /** + * Verify the + */ + @Test + void testWatchManagerCallsWatcher() { + Source source = mock(Source.class); + Watcher watcher = mock(Watcher.class); + when(watcher.isModified()).thenReturn(false); + watchManager.watch(source, watcher); + verify(watcher, timeout(2000)).isModified(); + verify(watcher, never()).modified(); + when(watcher.isModified()).thenReturn(true); + clearInvocations(watcher); + verify(watcher, timeout(2000)).isModified(); + verify(watcher).modified(); } private static class TestWatcher implements FileWatcher { diff --git a/log4j-core-test/src/test/resources/log4j-sync-to-list.xml b/log4j-core-test/src/test/resources/config/ConfigurationSourceTest.xml similarity index 71% rename from log4j-core-test/src/test/resources/log4j-sync-to-list.xml rename to log4j-core-test/src/test/resources/config/ConfigurationSourceTest.xml index e0e95c2fd0e..df84260a13f 100644 --- a/log4j-core-test/src/test/resources/log4j-sync-to-list.xml +++ b/log4j-core-test/src/test/resources/config/ConfigurationSourceTest.xml @@ -15,20 +15,18 @@ ~ See the License for the specific language governing permissions and ~ limitations under the License. --> - - + - - + + - - - - - - + + diff --git a/log4j-core-test/src/test/resources/emptyConfig.json b/log4j-core-test/src/test/resources/emptyConfig.json deleted file mode 100644 index 37086f2b1f6..00000000000 --- a/log4j-core-test/src/test/resources/emptyConfig.json +++ /dev/null @@ -1,4 +0,0 @@ -{ - "configs": { - } -} \ No newline at end of file diff --git a/log4j-core-test/src/test/resources/MutableThreadContextMapFilterTest.xml b/log4j-core-test/src/test/resources/filter/MutableThreadContextMapFilterTest.xml similarity index 68% rename from log4j-core-test/src/test/resources/MutableThreadContextMapFilterTest.xml rename to log4j-core-test/src/test/resources/filter/MutableThreadContextMapFilterTest.xml index 39a02650daa..34eb059c4e0 100644 --- a/log4j-core-test/src/test/resources/MutableThreadContextMapFilterTest.xml +++ b/log4j-core-test/src/test/resources/filter/MutableThreadContextMapFilterTest.xml @@ -15,22 +15,21 @@ ~ See the License for the specific language governing permissions and ~ limitations under the License. --> - - + - - - - - + - - - - - + + diff --git a/log4j-core-test/src/test/resources/filterConfig.json b/log4j-core-test/src/test/resources/filterConfig.json deleted file mode 100644 index 91c8143ec2b..00000000000 --- a/log4j-core-test/src/test/resources/filterConfig.json +++ /dev/null @@ -1,6 +0,0 @@ -{ - "configs": { - "loginId": ["rgoers", "adam"], - "corpAcctNumber": ["30510263"] - } -} \ No newline at end of file diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java index 2eb829db496..4b5d3dd0ed2 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java @@ -341,7 +341,7 @@ public void start() { * @param config The new Configuration. */ public void start(final Configuration config) { - LOGGER.debug("Starting {} with configuration {}...", this, config); + LOGGER.info("Starting {}[name={}] with configuration {}...", getClass().getSimpleName(), getName(), config); if (configLock.tryLock()) { try { if (this.isInitialized() || this.isStopped()) { @@ -355,7 +355,7 @@ public void start(final Configuration config) { } } setConfiguration(config); - LOGGER.debug("{} started OK with configuration {}.", this, config); + LOGGER.info("{}[name={}] started with configuration {}.", getClass().getSimpleName(), getName(), config); } private void setUpShutdownHook() { @@ -815,7 +815,12 @@ public void setConfigLocation(final URI configLocation) { private void reconfigure(final URI configURI) { final Object externalContext = externalMap.get(EXTERNAL_CONTEXT_KEY); final ClassLoader cl = externalContext instanceof ClassLoader ? (ClassLoader) externalContext : null; - LOGGER.debug("Reconfiguration started for {} at URI {} with optional ClassLoader: {}", this, configURI, cl); + LOGGER.debug( + "Reconfiguration started for context[name={}] at URI {} ({}) with optional ClassLoader: {}", + contextName, + configURI, + this, + cl); final Configuration instance = getConfiguration(contextName, configURI, cl); if (instance == null) { LOGGER.error( diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java index e6c1f4427ca..b62b1f0b807 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java @@ -19,7 +19,9 @@ import aQute.bnd.annotation.Cardinality; import aQute.bnd.annotation.Resolution; import aQute.bnd.annotation.spi.ServiceConsumer; +import java.io.File; import java.lang.ref.WeakReference; +import java.net.URI; import java.util.ArrayList; import java.util.Collections; import java.util.Comparator; @@ -322,9 +324,10 @@ protected void initializeWatchers( if (configSource != null && (configSource.getFile() != null || configSource.getURL() != null)) { if (monitorIntervalSeconds > 0) { watchManager.setIntervalSeconds(monitorIntervalSeconds); - if (configSource.getFile() != null) { - final Source cfgSource = new Source(configSource); - final long lastModified = configSource.getFile().lastModified(); + File file = configSource.getFile(); + if (file != null) { + final Source cfgSource = new Source(file); + final long lastModified = file.lastModified(); final ConfigurationFileWatcher watcher = new ConfigurationFileWatcher(this, reconfigurable, listeners, lastModified); watchManager.watch(cfgSource, watcher); @@ -342,8 +345,10 @@ protected void initializeWatchers( } private void monitorSource(final Reconfigurable reconfigurable, final ConfigurationSource configSource) { - if (configSource.getLastModified() > 0) { - final Source cfgSource = new Source(configSource); + URI uri = configSource.getURI(); + if (uri != null && configSource.getLastModified() > 0) { + File file = configSource.getFile(); + final Source cfgSource = file != null ? new Source(file) : new Source(uri); final Watcher watcher = instanceFactory .getInstance(WatcherFactory.class) .newWatcher(cfgSource, this, reconfigurable, listeners, configSource.getLastModified()); @@ -364,9 +369,13 @@ public void start() { if (getState().equals(State.INITIALIZING)) { initialize(); } - LOGGER.debug("Starting configuration {}", this); + LOGGER.info("Starting configuration {}...", this); this.setStarting(); if (watchManager.getIntervalSeconds() >= 0) { + LOGGER.info( + "Start watching for changes to {} every {} seconds", + getConfigurationSource(), + watchManager.getIntervalSeconds()); watchManager.start(); } for (final ConfigurationExtension extension : extensions) { @@ -386,7 +395,7 @@ public void start() { root.start(); // LOG4J2-336 } super.start(); - LOGGER.debug("Started configuration {} OK.", this); + LOGGER.info("Configuration {} started.", this); } /** @@ -394,9 +403,9 @@ public void start() { */ @Override public boolean stop(final long timeout, final TimeUnit timeUnit) { + LOGGER.info("Stopping configuration {}...", this); this.setStopping(); super.stop(timeout, timeUnit, false); - LOGGER.trace("Stopping {}...", this); // Stop the components that are closest to the application first: // 1. Notify all LoggerConfigs' ReliabilityStrategy that the configuration will be stopped. @@ -485,7 +494,7 @@ public boolean stop(final long timeout, final TimeUnit timeUnit) { advertiser.unadvertise(advertisement); } setStopped(); - LOGGER.debug("Stopped {} OK", this); + LOGGER.info("Configuration {} stopped.", this); return true; } @@ -513,6 +522,7 @@ public void setup() { // default does nothing, subclasses do work. } + @SuppressWarnings("deprecation") protected Level getDefaultStatus() { return instanceFactory.getInstance(Constants.STATUS_LOGGER_LEVEL_KEY); } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationSource.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationSource.java index 48ae11b9bf9..a270e04f7e3 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationSource.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationSource.java @@ -33,6 +33,7 @@ import java.nio.file.Path; import java.util.Objects; import javax.net.ssl.HttpsURLConnection; +import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.impl.CoreProperties.AuthenticationProperties; import org.apache.logging.log4j.core.net.ssl.LaxHostnameVerifier; import org.apache.logging.log4j.core.net.ssl.SslConfiguration; @@ -42,13 +43,19 @@ import org.apache.logging.log4j.core.util.Loader; import org.apache.logging.log4j.core.util.Source; import org.apache.logging.log4j.kit.env.PropertyEnvironment; +import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.LoaderUtil; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; /** * Represents the source for the logging configuration. */ +@NullMarked public class ConfigurationSource { + private static final Logger LOGGER = StatusLogger.getLogger(); + /** * ConfigurationSource to use with Configurations that do not require a "real" configuration source. */ @@ -61,11 +68,12 @@ public class ConfigurationSource { private static final String HTTPS = "https"; private final InputStream stream; - private volatile byte[] data; - private volatile Source source; - private final long lastModified; + private volatile byte @Nullable [] data; + private final @Nullable Source source; + // The initial modification time when the `ConfigurationSource` is created + private final long initialLastModified; // Set when the configuration has been updated so reset can use it for the next lastModified timestamp. - private volatile long modifiedMillis; + private volatile long currentLastModified; /** * Constructs a new {@code ConfigurationSource} with the specified input stream that originated from the specified @@ -84,7 +92,7 @@ public ConfigurationSource(final InputStream stream, final File file) { } catch (final Exception ex) { // There is a problem with the file. It will be handled somewhere else. } - this.lastModified = modified; + this.currentLastModified = this.initialLastModified = modified; } /** @@ -104,7 +112,7 @@ public ConfigurationSource(final InputStream stream, final Path path) { } catch (Exception ex) { // There is a problem with the file. It will be handled somewhere else. } - this.lastModified = modified; + this.currentLastModified = this.initialLastModified = modified; } /** @@ -115,10 +123,7 @@ public ConfigurationSource(final InputStream stream, final Path path) { * @param url the URL where the input stream originated */ public ConfigurationSource(final InputStream stream, final URL url) { - this.stream = Objects.requireNonNull(stream, "stream is null"); - this.data = null; - this.lastModified = 0; - this.source = new Source(url); + this(stream, url, 0L); } /** @@ -132,7 +137,7 @@ public ConfigurationSource(final InputStream stream, final URL url) { public ConfigurationSource(final InputStream stream, final URL url, final long lastModified) { this.stream = Objects.requireNonNull(stream, "stream is null"); this.data = null; - this.lastModified = lastModified; + this.currentLastModified = this.initialLastModified = lastModified; this.source = new Source(url); } @@ -147,23 +152,30 @@ public ConfigurationSource(final InputStream stream) throws IOException { this(stream.readAllBytes(), null, 0); } - public ConfigurationSource(final Source source, final byte[] data, final long lastModified) throws IOException { + public ConfigurationSource(final Source source, final byte[] data, final long lastModified) { Objects.requireNonNull(source, "source is null"); this.data = Objects.requireNonNull(data, "data is null"); this.stream = new ByteArrayInputStream(data); - this.lastModified = lastModified; + this.currentLastModified = this.initialLastModified = lastModified; this.source = source; } - private ConfigurationSource(final byte[] data, final URL url, final long lastModified) { - this.data = Objects.requireNonNull(data, "data is null"); - this.stream = new ByteArrayInputStream(data); - this.lastModified = lastModified; - if (url == null) { - this.data = data; - } else { - this.source = new Source(url); + private ConfigurationSource(byte[] data, @Nullable Source source, long lastModified) { + this(data, source, new ByteArrayInputStream(data), lastModified); + } + + /** + * @throws NullPointerException if both {@code stream} and {@code data} are {@code null}. + */ + private ConfigurationSource( + byte @Nullable [] data, @Nullable Source source, InputStream stream, long lastModified) { + if (data == null && source == null) { + throw new NullPointerException("both `data` and `source` are null"); } + this.stream = stream; + this.data = data; + this.source = source; + this.currentLastModified = this.initialLastModified = lastModified; } /** @@ -172,29 +184,17 @@ private ConfigurationSource(final byte[] data, final URL url, final long lastMod * * @return the configuration source file, or {@code null} */ - public File getFile() { + public @Nullable File getFile() { return source == null ? null : source.getFile(); } - private boolean isFile() { - return source != null && source.getFile() != null; - } - - private boolean isURL() { - return source != null && source.getURI() != null; - } - - private boolean isLocation() { - return source != null && source.getLocation() != null; - } - /** * Returns the configuration source URL, or {@code null} if this configuration source is based on a file or has * neither a file nor an URL. * * @return the configuration source URL, or {@code null} */ - public URL getURL() { + public @Nullable URL getURL() { return source == null ? null : source.getURL(); } @@ -202,24 +202,30 @@ public void setData(final byte[] data) { this.data = data; } - public void setModifiedMillis(final long modifiedMillis) { - this.modifiedMillis = modifiedMillis; + /** + * Updates the last known modification time of the resource. + * + * @param currentLastModified The modification time of the resource in millis. + */ + public void setModifiedMillis(final long currentLastModified) { + this.currentLastModified = currentLastModified; } /** * Returns a URI representing the configuration resource or null if it cannot be determined. * @return The URI. */ - public URI getURI() { + public @Nullable URI getURI() { return source == null ? null : source.getURI(); } /** - * Returns the time the resource was last modified or 0 if it is not available. + * Returns the last modification time known when the {@code ConfigurationSource} was created. + * * @return the last modified time of the resource. */ public long getLastModified() { - return lastModified; + return initialLastModified; } /** @@ -228,7 +234,7 @@ public long getLastModified() { * * @return a string describing the configuration source file or URL, or {@code null} */ - public String getLocation() { + public @Nullable String getLocation() { return source == null ? null : source.getLocation(); } @@ -247,26 +253,31 @@ public InputStream getInputStream() { * @return a new {@code ConfigurationSource} * @throws IOException if a problem occurred while opening the new input stream */ - public ConfigurationSource resetInputStream() throws IOException { + public @Nullable ConfigurationSource resetInputStream() throws IOException { + byte[] data = this.data; if (source != null && data != null) { - return new ConfigurationSource(source, data, this.lastModified); - } else if (isFile()) { - return new ConfigurationSource(new FileInputStream(getFile()), getFile()); - } else if (isURL() && data != null) { + return new ConfigurationSource(source, data, currentLastModified); + } + File file = getFile(); + if (file != null) { + return new ConfigurationSource(Files.newInputStream(file.toPath()), getFile()); + } + URL url = getURL(); + if (url != null && data != null) { // Creates a ConfigurationSource without accessing the URL since the data was provided. - return new ConfigurationSource(data, getURL(), modifiedMillis == 0 ? lastModified : modifiedMillis); - } else if (isURL()) { - return fromUri(getURI()); - } else if (data != null) { - return new ConfigurationSource(data, null, lastModified); + return new ConfigurationSource(data, new Source(url), currentLastModified); } - return null; + URI uri = getURI(); + if (uri != null) { + return fromUri(uri); + } + return data == null ? null : new ConfigurationSource(data, null, currentLastModified); } @Override public String toString() { - if (isLocation()) { - return getLocation(); + if (source != null) { + return source.getLocation(); } if (this == NULL_SOURCE) { return "NULL_SOURCE"; @@ -274,6 +285,7 @@ public String toString() { if (this == COMPOSITE_SOURCE) { return "COMPOSITE_SOURCE"; } + byte[] data = this.data; final int length = data == null ? -1 : data.length; return "stream (" + length + " bytes, unknown location)"; } @@ -281,9 +293,9 @@ public String toString() { /** * Loads the configuration from a URI. * @param configLocation A URI representing the location of the configuration. - * @return The ConfigurationSource for the configuration. + * @return The ConfigurationSource for the configuration or {@code null}. */ - public static ConfigurationSource fromUri(final URI configLocation) { + public static @Nullable ConfigurationSource fromUri(final URI configLocation) { final File configFile = FileUtils.fileFromUri(configLocation); if (configFile != null && configFile.exists() && configFile.canRead()) { try { @@ -316,18 +328,15 @@ public static ConfigurationSource fromUri(final URI configLocation) { * @param loader The default ClassLoader to use. * @return The ConfigurationSource for the configuration. */ - public static ConfigurationSource fromResource(final String resource, final ClassLoader loader) { + public static @Nullable ConfigurationSource fromResource(String resource, @Nullable ClassLoader loader) { final URL url = Loader.getResource(resource, loader); - if (url == null) { - return null; - } - return getConfigurationSource(url); + return url == null ? null : getConfigurationSource(url); } @SuppressFBWarnings( value = "PATH_TRAVERSAL_IN", justification = "The name of the accessed files is based on a configuration value.") - private static ConfigurationSource getConfigurationSource(final URL url) { + private static @Nullable ConfigurationSource getConfigurationSource(final URL url) { try { final URLConnection urlConnection = url.openConnection(); // A "jar:" URL file remains open after the stream is closed, so do not cache it. diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/HttpWatcher.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/HttpWatcher.java index 07e40ca4a77..3201f7d0979 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/HttpWatcher.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/HttpWatcher.java @@ -16,11 +16,14 @@ */ package org.apache.logging.log4j.core.config; +import static java.util.Objects.requireNonNull; +import static org.apache.logging.log4j.util.Strings.toRootUpperCase; + import java.io.IOException; -import java.io.InputStream; import java.net.MalformedURLException; import java.net.URISyntaxException; import java.net.URL; +import java.time.Instant; import java.util.List; import java.util.function.Consumer; import org.apache.logging.log4j.Logger; @@ -112,37 +115,51 @@ private boolean refreshConfiguration() { final LastModifiedSource source = new LastModifiedSource(url.toURI(), lastModifiedMillis); final HttpInputStreamUtil.Result result = HttpInputStreamUtil.getInputStream(source, properties, authorizationProvider, sslConfiguration); + // Update lastModifiedMillis + // https://github.com/apache/logging-log4j2/issues/2937 + lastModifiedMillis = source.getLastModified(); + // The result of the HTTP/HTTPS request is already logged at `DEBUG` by `HttpInputStreamUtil` + // We only log the important events at `INFO` or more. switch (result.getStatus()) { case NOT_MODIFIED: { - LOGGER.debug("Configuration Not Modified"); return false; } case SUCCESS: { final ConfigurationSource configSource = getConfiguration().getConfigurationSource(); try { - final InputStream is = result.getInputStream(); - configSource.setData(is.readAllBytes()); - final long lastModified = source.getLastModified(); - configSource.setModifiedMillis(lastModified); - lastModifiedMillis = lastModified; - LOGGER.debug("Content was modified for {}", url.toString()); + // In this case `result.getInputStream()` is not null. + configSource.setData( + requireNonNull(result.getInputStream()).readAllBytes()); + configSource.setModifiedMillis(source.getLastModified()); + LOGGER.info( + "{} resource at {} was modified on {}", + () -> toRootUpperCase(url.getProtocol()), + () -> url.toExternalForm(), + () -> Instant.ofEpochMilli(source.getLastModified())); return true; } catch (final IOException e) { - LOGGER.error("Error accessing configuration at {}: {}", url, e.getMessage()); + // Dead code since result.getInputStream() is a ByteArrayInputStream + LOGGER.error("Error accessing configuration at {}", url.toExternalForm(), e); return false; } } case NOT_FOUND: { - LOGGER.info("Unable to locate configuration at {}", url.toString()); + LOGGER.warn( + "{} resource at {} was not found", + () -> toRootUpperCase(url.getProtocol()), + () -> url.toExternalForm()); return false; } default: { - LOGGER.warn("Unexpected error accessing configuration at {}", url.toString()); + LOGGER.warn( + "Unexpected error retrieving {} resource at {}", + () -> toRootUpperCase(url.getProtocol()), + () -> url.toExternalForm()); return false; } } } catch (final URISyntaxException ex) { - LOGGER.error("Bad configuration URL: {}, {}", url.toString(), ex.getMessage()); + LOGGER.error("Bad configuration file URL {}", url.toExternalForm(), ex); return false; } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/xml/XmlConfiguration.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/xml/XmlConfiguration.java index 01cb345f394..eb0a97a0b48 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/xml/XmlConfiguration.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/xml/XmlConfiguration.java @@ -20,6 +20,7 @@ import java.io.ByteArrayInputStream; import java.io.IOException; import java.io.InputStream; +import java.time.Instant; import java.util.ArrayList; import java.util.List; import java.util.Map; @@ -175,7 +176,7 @@ public XmlConfiguration(final LoggerContext loggerContext, final ConfigurationSo * * @param xIncludeAware enabled XInclude * @return a new DocumentBuilder - * @throws ParserConfigurationException + * @throws ParserConfigurationException if a DocumentBuilder cannot be created, which satisfies the configuration requested. */ static DocumentBuilder newDocumentBuilder(final boolean xIncludeAware) throws ParserConfigurationException { final DocumentBuilderFactory factory = DocumentBuilderFactory.newInstance(); @@ -241,7 +242,7 @@ public void setup() { return; } constructHierarchy(rootNode, rootElement); - if (status.size() > 0) { + if (!status.isEmpty()) { for (final Status s : status) { LOGGER.error("Error processing element {} ({}): {}", s.name, s.element, s.errorType); } @@ -295,7 +296,7 @@ private void constructHierarchy(final Node node, final Element element) { } final String text = buffer.toString().trim(); - if (text.length() > 0 || (!node.hasChildren() && !node.isRoot())) { + if (!text.isEmpty() || (!node.hasChildren() && !node.isRoot())) { node.setValue(text); } } @@ -337,7 +338,8 @@ private Map processAttributes(final Node node, final Element ele @Override public String toString() { - return getClass().getSimpleName() + "[location=" + getConfigurationSource() + "]"; + return getClass().getSimpleName() + "[location=" + getConfigurationSource() + ", lastModified=" + + Instant.ofEpochMilli(getConfigurationSource().getLastModified()) + "]"; } /** diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilter.java index 396033ed21c..f694a19b6fd 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/filter/MutableThreadContextMapFilter.java @@ -66,6 +66,8 @@ @PerformanceSensitive("allocation") public class MutableThreadContextMapFilter extends AbstractFilter { + private static final String HTTP = "http"; + private static final String HTTPS = "https"; private static final KeyValuePair[] EMPTY_ARRAY = {}; private volatile Filter filter; @@ -376,29 +378,42 @@ public void run() { final PropertyEnvironment properties = configuration.getEnvironment(); final SslConfiguration sslConfiguration = SslConfigurationFactory.getSslConfiguration(properties); final ConfigResult result = getConfig(source, authorizationProvider, properties, sslConfiguration); - if (result.status == Status.SUCCESS) { - filter = ThreadContextMapFilter.newBuilder() - .setPairs(result.pairs) - .setOperator("or") - .setOnMatch(getOnMatch()) - .setOnMismatch(getOnMismatch()) - .setContextDataInjector(configuration.getComponent(ContextDataInjector.KEY)) - .get(); - LOGGER.info("Filter configuration was updated: {}", filter.toString()); - for (FilterConfigUpdateListener listener : listeners) { - listener.onEvent(); - } - } else if (result.status == Status.NOT_FOUND) { - if (!(filter instanceof NoOpFilter)) { - LOGGER.info("Filter configuration was removed"); + switch (result.status) { + case SUCCESS: + filter = ThreadContextMapFilter.newBuilder() + .setPairs(result.pairs) + .setOperator("or") + .setOnMatch(getOnMatch()) + .setOnMismatch(getOnMismatch()) + .setContextDataInjector(configuration.getComponent(ContextDataInjector.KEY)) + .get(); + LOGGER.info("MutableThreadContextMapFilter configuration was updated: {}", filter.toString()); + break; + case NOT_FOUND: + if (!(filter instanceof NoOpFilter)) { + LOGGER.info("MutableThreadContextMapFilter configuration was removed"); + filter = new NoOpFilter(); + } + break; + case EMPTY: + LOGGER.debug("MutableThreadContextMapFilter configuration is empty"); filter = new NoOpFilter(); + break; + } + switch (result.status) { + // These results cause changes in the filter + // We call the listeners + case SUCCESS: + case NOT_FOUND: + case EMPTY: for (FilterConfigUpdateListener listener : listeners) { listener.onEvent(); } - } - } else if (result.status == Status.EMPTY) { - LOGGER.debug("Filter configuration is empty"); - filter = new NoOpFilter(); + break; + // These results do no cause changes in the filter + case ERROR: + case NOT_MODIFIED: + break; } } } @@ -407,7 +422,7 @@ public void run() { value = "PATH_TRAVERSAL_IN", justification = "The location of the file comes from a configuration value.") private static LastModifiedSource getSource(final String configLocation) { - LastModifiedSource source = null; + LastModifiedSource source; try { final URI uri = new URI(configLocation); if (uri.getScheme() != null) { @@ -430,8 +445,9 @@ private static ConfigResult getConfig( final File inputFile = source.getFile(); final ConfigResult configResult = new ConfigResult(); InputStream inputStream = null; - HttpInputStreamUtil.Result result = null; + HttpInputStreamUtil.Result result; final long lastModified = source.getLastModified(); + URI uri = source.getURI(); try { if (inputFile != null && inputFile.exists()) { try { @@ -446,7 +462,7 @@ private static ConfigResult getConfig( } catch (Exception ex) { result = new HttpInputStreamUtil.Result(Status.ERROR); } - } else if (source.getURI() != null) { + } else if (HTTP.equalsIgnoreCase(uri.getScheme()) || HTTPS.equalsIgnoreCase(uri.getScheme())) { try { result = HttpInputStreamUtil.getInputStream(source, props, authorizationProvider, sslConfiguration); inputStream = result.getInputStream(); @@ -508,7 +524,7 @@ private static void parseJsonConfiguration(final InputStream inputStream, final LOGGER.warn("Ignoring the value for {}, which is not an array: {}", key, jsonArray); } } - if (pairs.size() > 0) { + if (!pairs.isEmpty()) { configResult.pairs = pairs.toArray(EMPTY_ARRAY); configResult.status = Status.SUCCESS; } else { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Loader.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Loader.java index ed65209a13c..84667ce9483 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Loader.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Loader.java @@ -24,6 +24,7 @@ import org.apache.logging.log4j.kit.env.PropertyEnvironment; import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.LoaderUtil; +import org.jspecify.annotations.Nullable; /** * Load resources (or images) from various sources. @@ -81,9 +82,9 @@ public static ClassLoader getThreadContextClassLoader() { * * @param resource The resource to load. * @param defaultLoader The default ClassLoader. - * @return A URL to the resource. + * @return A URL to the resource or {@code null}. */ - public static URL getResource(final String resource, final ClassLoader defaultLoader) { + public static @Nullable URL getResource(final String resource, final ClassLoader defaultLoader) { try { ClassLoader classLoader = getThreadContextClassLoader(); if (classLoader != null) { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Source.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Source.java index 327363d233d..b5a5cb6e2b8 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Source.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Source.java @@ -16,6 +16,8 @@ */ package org.apache.logging.log4j.core.util; +import static java.util.Objects.requireNonNull; + import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import java.io.File; import java.io.IOException; @@ -30,10 +32,13 @@ import org.apache.logging.log4j.core.config.ConfigurationSource; import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.Strings; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; /** * Represents the source for the logging configuration as an immutable object. */ +@NullMarked public class Source { private static final Logger LOGGER = StatusLogger.getLogger(); @@ -45,9 +50,9 @@ private static String normalize(final File file) { } } - private static File toFile(final Path path) { + private static @Nullable File toFile(Path path) { try { - return Objects.requireNonNull(path, "path").toFile(); + return requireNonNull(path, "path").toFile(); } catch (final UnsupportedOperationException e) { return null; } @@ -57,9 +62,9 @@ private static File toFile(final Path path) { @SuppressFBWarnings( value = "PATH_TRAVERSAL_IN", justification = "The URI should be specified in a configuration file.") - private static File toFile(final URI uri) { + private static @Nullable File toFile(URI uri) { try { - final String scheme = Objects.requireNonNull(uri, "uri").getScheme(); + final String scheme = requireNonNull(uri, "uri").getScheme(); if (Strings.isBlank(scheme) || scheme.equals("file")) { return new File(uri.getPath()); } else { @@ -67,20 +72,20 @@ private static File toFile(final URI uri) { return null; } } catch (final Exception e) { - LOGGER.debug("uri is malformed: " + uri.toString()); + LOGGER.debug("uri is malformed: " + uri); return null; } } private static URI toURI(final URL url) { try { - return Objects.requireNonNull(url, "url").toURI(); + return requireNonNull(url, "url").toURI(); } catch (final URISyntaxException e) { throw new IllegalArgumentException(e); } } - private final File file; + private final @Nullable File file; private final URI uri; private final String location; @@ -88,21 +93,23 @@ private static URI toURI(final URL url) { * Constructs a Source from a ConfigurationSource. * * @param source The ConfigurationSource. + * @throws NullPointerException if {@code source} is {@code null}. */ public Source(final ConfigurationSource source) { this.file = source.getFile(); - this.uri = source.getURI(); - this.location = source.getLocation(); + this.uri = requireNonNull(source.getURI()); + this.location = requireNonNull(source.getLocation()); } /** * Constructs a new {@code Source} with the specified file. * file. * - * @param file the file where the input stream originated + * @param file the file where the input stream originated. + * @throws NullPointerException if {@code file} is {@code null}. */ public Source(final File file) { - this.file = Objects.requireNonNull(file, "file"); + this.file = requireNonNull(file, "file"); this.location = normalize(file); this.uri = file.toURI(); } @@ -111,9 +118,10 @@ public Source(final File file) { * Constructs a new {@code Source} from the specified Path. * * @param path the Path where the input stream originated + * @throws NullPointerException if {@code path} is {@code null}. */ public Source(final Path path) { - final Path normPath = Objects.requireNonNull(path, "path").normalize(); + final Path normPath = requireNonNull(path, "path").normalize(); this.file = toFile(normPath); this.uri = normPath.toUri(); this.location = normPath.toString(); @@ -123,9 +131,10 @@ public Source(final Path path) { * Constructs a new {@code Source} from the specified URI. * * @param uri the URI where the input stream originated + * @throws NullPointerException if {@code uri} is {@code null}. */ public Source(final URI uri) { - final URI normUri = Objects.requireNonNull(uri, "uri").normalize(); + final URI normUri = requireNonNull(uri, "uri").normalize(); this.uri = normUri; this.location = normUri.toString(); this.file = toFile(normUri); @@ -135,6 +144,7 @@ public Source(final URI uri) { * Constructs a new {@code Source} from the specified URL. * * @param url the URL where the input stream originated + * @throws NullPointerException if this URL is {@code null}. * @throws IllegalArgumentException if this URL is not formatted strictly according to RFC2396 and cannot be * converted to a URI. */ @@ -162,7 +172,7 @@ public boolean equals(final Object obj) { * * @return the configuration source file, or {@code null} */ - public File getFile() { + public @Nullable File getFile() { return file; } @@ -185,7 +195,7 @@ public String getLocation() { value = "PATH_TRAVERSAL_IN", justification = "The `file`, `uri` and `location` fields come from Log4j properties.") public Path getPath() { - return file != null ? file.toPath() : uri != null ? Paths.get(uri) : Paths.get(location); + return file != null ? file.toPath() : Paths.get(uri); } /** diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/WatchManager.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/WatchManager.java index 5118f1cb9c3..a7e242b6220 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/WatchManager.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/WatchManager.java @@ -20,6 +20,7 @@ import aQute.bnd.annotation.Resolution; import aQute.bnd.annotation.spi.ServiceConsumer; import java.io.File; +import java.time.Instant; import java.util.Date; import java.util.HashMap; import java.util.List; @@ -53,8 +54,9 @@ public class WatchManager extends AbstractLifeCycle { private static final class ConfigurationMonitor { - private volatile long lastModifiedMillis; private final Watcher watcher; + // Only used for logging + private volatile long lastModifiedMillis; public ConfigurationMonitor(final long lastModifiedMillis, final Watcher watcher) { this.watcher = watcher; @@ -115,15 +117,11 @@ public void run() { final ConfigurationMonitor monitor = entry.getValue(); if (monitor.getWatcher().isModified()) { final long lastModified = monitor.getWatcher().getLastModified(); - if (logger.isInfoEnabled()) { - logger.info( - "Source '{}' was modified on {} ({}), previous modification was on {} ({})", - source, - millisToString(lastModified), - lastModified, - millisToString(monitor.lastModifiedMillis), - monitor.lastModifiedMillis); - } + logger.info( + "Configuration source at `{}` was modified on `{}`, previous modification was on `{}`", + () -> source, + () -> Instant.ofEpochMilli(lastModified), + () -> Instant.ofEpochMilli(monitor.lastModifiedMillis)); monitor.lastModifiedMillis = lastModified; monitor.getWatcher().modified(); } @@ -188,7 +186,7 @@ public int getIntervalSeconds() { } public boolean hasEventListeners() { - return eventServiceList.size() > 0; + return !eventServiceList.isEmpty(); } private String millisToString(final long millis) { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/HttpInputStreamUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/HttpInputStreamUtil.java index b5961883287..10204e30f3a 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/HttpInputStreamUtil.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/HttpInputStreamUtil.java @@ -16,17 +16,24 @@ */ package org.apache.logging.log4j.core.util.internal; +import static org.apache.logging.log4j.util.Strings.toRootUpperCase; + import java.io.ByteArrayInputStream; import java.io.IOException; import java.io.InputStream; import java.net.HttpURLConnection; +import java.time.Instant; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.config.ConfigurationException; import org.apache.logging.log4j.core.net.UrlConnectionFactory; import org.apache.logging.log4j.core.net.ssl.SslConfiguration; import org.apache.logging.log4j.core.util.AuthorizationProvider; +import org.apache.logging.log4j.core.util.Source; import org.apache.logging.log4j.kit.env.PropertyEnvironment; import org.apache.logging.log4j.status.StatusLogger; +import org.apache.logging.log4j.util.Supplier; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; /** * Utility method for reading data from an HTTP InputStream. @@ -36,9 +43,20 @@ public final class HttpInputStreamUtil { private static final Logger LOGGER = StatusLogger.getLogger(); private static final int NOT_MODIFIED = 304; private static final int NOT_AUTHORIZED = 401; + private static final int FORBIDDEN = 403; private static final int NOT_FOUND = 404; private static final int OK = 200; + /** + * Retrieves an HTTP resource if it has been modified. + *

+ * Side effects: if the request is successful, the last modified time of the {@code source} + * parameter is modified. + *

+ * @param source The location of the HTTP resource + * @param authorizationProvider The authentication data for the HTTP request + * @return A {@link Result} object containing the status code and body of the response + */ public static Result getInputStream( final LastModifiedSource source, final PropertyEnvironment props, @@ -54,12 +72,16 @@ public static Result getInputStream( final int code = connection.getResponseCode(); switch (code) { case NOT_MODIFIED: { - LOGGER.debug("Configuration not modified"); + LOGGER.debug( + "{} resource {}: not modified since {}", + formatProtocol(source), + () -> source, + () -> Instant.ofEpochMilli(lastModified)); result.status = Status.NOT_MODIFIED; return result; } case NOT_FOUND: { - LOGGER.debug("Unable to access {}: Not Found", source.toString()); + LOGGER.debug("{} resource {}: not found", formatProtocol(source), () -> source); result.status = Status.NOT_FOUND; return result; } @@ -67,60 +89,88 @@ public static Result getInputStream( try (final InputStream is = connection.getInputStream()) { source.setLastModified(connection.getLastModified()); LOGGER.debug( - "Content was modified for {}. previous lastModified: {}, new lastModified: {}", - source.toString(), - lastModified, - connection.getLastModified()); + "{} resource {}: last modified on {}", + formatProtocol(source), + () -> source, + () -> Instant.ofEpochMilli(connection.getLastModified())); result.status = Status.SUCCESS; - result.inputStream = new ByteArrayInputStream(is.readAllBytes()); + result.bytes = is.readAllBytes(); return result; } catch (final IOException e) { try (final InputStream es = connection.getErrorStream()) { - LOGGER.info( - "Error accessing configuration at {}: {}", - source.toString(), - es.readAllBytes()); + if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "Error accessing {} resource at {}: {}", + formatProtocol(source).get(), + source, + es.readAllBytes(), + e); + } } catch (final IOException ioe) { - LOGGER.error( - "Error accessing configuration at {}: {}", source.toString(), e.getMessage()); + LOGGER.debug( + "Error accessing {} resource at {}", + formatProtocol(source), + () -> source, + () -> e); } - throw new ConfigurationException("Unable to access " + source.toString(), e); + throw new ConfigurationException("Unable to access " + source, e); } } case NOT_AUTHORIZED: { - throw new ConfigurationException("Authorization failed"); + throw new ConfigurationException("Authentication required for " + source); + } + case FORBIDDEN: { + throw new ConfigurationException("Access denied to " + source); } default: { if (code < 0) { - LOGGER.info("Invalid response code returned"); + LOGGER.debug("{} resource {}: invalid response code", formatProtocol(source), source); } else { - LOGGER.info("Unexpected response code returned {}", code); + LOGGER.debug( + "{} resource {}: unexpected response code {}", + formatProtocol(source), + source, + code); } - throw new ConfigurationException("Unable to access " + source.toString()); + throw new ConfigurationException("Unable to access " + source); } } } finally { connection.disconnect(); } } catch (IOException e) { - LOGGER.warn("Error accessing {}: {}", source.toString(), e.getMessage()); - throw new ConfigurationException("Unable to access " + source.toString(), e); + LOGGER.debug("Error accessing {} resource at {}", formatProtocol(source), source, e); + throw new ConfigurationException("Unable to access " + source, e); } } + private static Supplier formatProtocol(Source source) { + return () -> toRootUpperCase(source.getURI().getScheme()); + } + + @NullMarked public static class Result { - private InputStream inputStream; + private byte @Nullable [] bytes = null; private Status status; - public Result() {} + public Result() { + this(Status.ERROR); + } public Result(final Status status) { this.status = status; } - public InputStream getInputStream() { - return inputStream; + /** + * Returns the data if the status is {@link Status#SUCCESS}. + *

+ * In any other case the result is {@code null}. + *

+ * @return The contents of the HTTP response or null if empty. + */ + public @Nullable InputStream getInputStream() { + return bytes != null ? new ByteArrayInputStream(bytes) : null; } public Status getStatus() { diff --git a/log4j-parent/pom.xml b/log4j-parent/pom.xml index 2cce92c1fbf..e189f1a2de6 100644 --- a/log4j-parent/pom.xml +++ b/log4j-parent/pom.xml @@ -117,7 +117,6 @@ 2.0.1 3.3.4 4.0.5 - 9.4.55.v20240627 3.5.12 1.37 3.4.1 @@ -140,11 +139,8 @@ 1.0.1 4.13.5 3.5.1 - 2.0.15 2.1.7 - 10.1.30 1.7 - 2.35.2 2.10.0 - - com.github.tomakehurst - wiremock-jre8 - ${wiremock.version} - - org.xmlunit xmlunit-core @@ -750,7 +719,8 @@ org.slf4j:jcl-over-slf4j org.springframework:spring-jcl - + + log4j:log4j org.slf4j:log4j-over-slf4j ch.qos.reload4j:reload4j diff --git a/log4j-perf-test/pom.xml b/log4j-perf-test/pom.xml index aadc3c8933d..d6cd2076e14 100644 --- a/log4j-perf-test/pom.xml +++ b/log4j-perf-test/pom.xml @@ -37,8 +37,30 @@ true true org.apache.logging.log4j.perf + + + 1.2.25 + 2.0.16 + + + + + org.slf4j + slf4j-api + ${slf4j2.version} + + + + ch.qos.reload4j + reload4j + ${reload4j.version} + + + + + org.openjdk.jmh @@ -108,10 +130,6 @@ org.openjdk.jmh jmh-core - - log4j - log4j - ch.qos.logback logback-classic @@ -122,6 +140,10 @@ logback-core compile + + ch.qos.reload4j + reload4j + org.slf4j slf4j-api @@ -145,7 +167,7 @@ org.apache.maven.plugins @@ -158,6 +180,7 @@ ch.qos.logback:* + ch.qos.reload4j:reload4j diff --git a/log4j-plugins/pom.xml b/log4j-plugins/pom.xml index ac88ccb6806..379bf796562 100644 --- a/log4j-plugins/pom.xml +++ b/log4j-plugins/pom.xml @@ -44,14 +44,17 @@ + org.apache.logging.log4j log4j-api + org.apache.logging.log4j log4j-kit + diff --git a/log4j-slf4j2-impl/pom.xml b/log4j-slf4j2-impl/pom.xml index 7019645401f..b48e3f50feb 100644 --- a/log4j-slf4j2-impl/pom.xml +++ b/log4j-slf4j2-impl/pom.xml @@ -36,17 +36,19 @@ (Refer to the `log4j-to-slf4j` artifact for forwarding the Log4j API to SLF4J.) - - - false - - - org.slf4j;substitute="slf4j-api" - + 2.0.16 + + + + + org.slf4j + slf4j-api + ${slf4j2.version} + + + + org.osgi diff --git a/log4j-to-slf4j/pom.xml b/log4j-to-slf4j/pom.xml index 413fde7a59d..2240022d4cb 100644 --- a/log4j-to-slf4j/pom.xml +++ b/log4j-to-slf4j/pom.xml @@ -49,7 +49,20 @@ org.jspecify;transitive=false + + 2.0.16 + + + + + org.slf4j + slf4j-api + ${slf4j2.version} + + + + org.osgi diff --git a/pom.xml b/pom.xml index dc412611b06..5b4e43691f2 100644 --- a/pom.xml +++ b/pom.xml @@ -374,6 +374,10 @@ + + org.apache.logging.log4j log4j-api diff --git a/src/changelog/.3.x.x/2937-http-watcher.xml b/src/changelog/.3.x.x/2937-http-watcher.xml new file mode 100644 index 00000000000..ec3e1a14263 --- /dev/null +++ b/src/changelog/.3.x.x/2937-http-watcher.xml @@ -0,0 +1,8 @@ + + + + Fix reloading of the configuration from an HTTP(S) source +