From 9ab551578807027bc56541389a746e1656204ae7 Mon Sep 17 00:00:00 2001 From: baranowb Date: Tue, 6 Oct 2020 15:21:48 +0200 Subject: [PATCH 1/2] [UNDERTOW-1794] improve DefaultAccessLogReceiver to obey contract! --- .../main/java/io/undertow/UndertowLogger.java | 18 +- .../java/io/undertow/UndertowMessages.java | 4 + .../accesslog/DefaultAccessLogReceiver.java | 275 ++++++++++++------ .../accesslog/AccessLogFileTestCase.java | 6 +- 4 files changed, 206 insertions(+), 97 deletions(-) diff --git a/core/src/main/java/io/undertow/UndertowLogger.java b/core/src/main/java/io/undertow/UndertowLogger.java index aed93fea64..bb783ffd60 100644 --- a/core/src/main/java/io/undertow/UndertowLogger.java +++ b/core/src/main/java/io/undertow/UndertowLogger.java @@ -474,4 +474,20 @@ void nodeConfigCreated(URI connectionURI, String balancer, String domain, String @LogMessage(level = WARN) @Message(id = 5106, value = "Content mismatch for '%s'. Expected length '%s', but was '%s'.") void contentEntryMismatch(Object key, long indicatedSize, long written); -} + + @LogMessage(level = DEBUG) + @Message(id = 5107, value = "Access Log Worker failed to transition gracefuly.") + void accessLogWorkerFailureOnTransition(); + + @LogMessage(level = DEBUG) + @Message(id = 5108, value = "Access Log Worker failed to reschedule.") + void accessLogWorkerFailureOnReschedule(); + + @LogMessage(level = DEBUG) + @Message(id = 5109, value = "Access Log Worker did not terminate cleanly.") + void accessLogWorkerNoTermination(); + + @LogMessage(level = DEBUG) + @Message(id = 5110, value = "Interruption in close()") + void closeInterrupted(@Cause InterruptedException ie); +} \ No newline at end of file diff --git a/core/src/main/java/io/undertow/UndertowMessages.java b/core/src/main/java/io/undertow/UndertowMessages.java index 4edcc69af0..7581263954 100644 --- a/core/src/main/java/io/undertow/UndertowMessages.java +++ b/core/src/main/java/io/undertow/UndertowMessages.java @@ -643,4 +643,8 @@ public interface UndertowMessages { @Message(id = 207, value = "Invalid SNI hostname '%s'") IllegalArgumentException invalidSniHostname(String hostNameValue, @Cause Throwable t); + + @Message(id = 209, value = "Failed to schedule access message. Access logger is closing.") + IllegalStateException failedToLogAccessOnClose(); + } diff --git a/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java b/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java index d6f093c645..123b1914bd 100644 --- a/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java +++ b/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java @@ -27,17 +27,16 @@ import java.nio.file.Path; import java.nio.file.StandardOpenOption; import java.text.SimpleDateFormat; -import java.util.ArrayList; import java.util.Calendar; import java.util.Date; import java.util.Deque; -import java.util.List; import java.util.Locale; import java.util.concurrent.ConcurrentLinkedDeque; import java.util.concurrent.Executor; import java.util.concurrent.atomic.AtomicIntegerFieldUpdater; import io.undertow.UndertowLogger; +import io.undertow.UndertowMessages; /** * Log Receiver that stores logs in a directory under the specified file name, and rotates them after @@ -51,15 +50,17 @@ */ public class DefaultAccessLogReceiver implements AccessLogReceiver, Runnable, Closeable { private static final String DEFAULT_LOG_SUFFIX = "log"; + private static final int DEFAULT_RETRY_COUNT = 150; + private static final int DEFAULT_RETRY_DELAY = 200; private final Executor logWriteExecutor; private final Deque pendingMessages; - //0 = not running - //1 = queued - //2 = running - //3 = final state of running (inside finally of run()) + //0 = not running - access log handler is not running, nor scheduled + //1 = queued - log handler has been scheduled to run + //2 = running - log handler is in run() method and performs I/O + //3 = closing/closed - run() method as triggered by close() to terminate @SuppressWarnings("unused") private volatile int state = 0; @@ -81,6 +82,8 @@ public class DefaultAccessLogReceiver implements AccessLogReceiver, Runnable, Cl private boolean initialRun = true; private final boolean rotate; private final LogFileHeaderGenerator fileHeaderGenerator; + private final int closeRetryCount = DEFAULT_RETRY_COUNT; + private final int closeRetryDelay = DEFAULT_RETRY_DELAY; public DefaultAccessLogReceiver(final Executor logWriteExecutor, final File outputDirectory, final String logBaseName) { this(logWriteExecutor, outputDirectory.toPath(), logBaseName, null); @@ -106,7 +109,7 @@ public DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outp this(logWriteExecutor, outputDirectory, logBaseName, logNameSuffix, rotate, null); } - private DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outputDirectory, final String logBaseName, final String logNameSuffix, boolean rotate, LogFileHeaderGenerator fileHeader) { + public DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outputDirectory, final String logBaseName, final String logNameSuffix, boolean rotate, LogFileHeaderGenerator fileHeader) { this.logWriteExecutor = logWriteExecutor; this.outputDirectory = outputDirectory; this.logBaseName = logBaseName; @@ -139,12 +142,14 @@ private void calculateChangeOverPoint() { @Override public void logMessage(final String message) { + if(closed) { + //Log handler is closing, other resources should as well, there shouldn't + //be resources served that required this to log stuff into AL file. + throw UndertowMessages.MESSAGES.failedToLogAccessOnClose(); + } this.pendingMessages.add(message); - int state = stateUpdater.get(this); - if (state == 0) { - if (stateUpdater.compareAndSet(this, 0, 1)) { - logWriteExecutor.execute(this); - } + if (this.state == 0 && stateUpdater.compareAndSet(this, 0, 1)) { + logWriteExecutor.execute(this); } } @@ -153,75 +158,71 @@ public void logMessage(final String message) { */ @Override public void run() { + //check if we can transition to 2. If so, perform tasks in small chunks and check this.closed. + //move into 3 if(this.closed) and terminate run() if (!stateUpdater.compareAndSet(this, 1, 2)) { return; } - if (forceLogRotation) { - doRotate(); + //NOTE: once we are here, run() control state transition, unless it is too slow + //and close takes over after grace period. + + if (forceLogRotation || System.currentTimeMillis() > changeOverPoint) { + performFileRotation(); } else if (initialRun && Files.exists(defaultLogFile)) { - //if there is an existing log file check if it should be rotated - long lm = 0; - try { - lm = Files.getLastModifiedTime(defaultLogFile).toMillis(); - } catch (IOException e) { - UndertowLogger.ROOT_LOGGER.errorRotatingAccessLog(e); - } - Calendar c = Calendar.getInstance(); - c.setTimeInMillis(changeOverPoint); - c.add(Calendar.DATE, -1); - if (lm <= c.getTimeInMillis()) { - doRotate(); - } + checkAndRotateOnInitialRun(); } - initialRun = false; - List messages = new ArrayList<>(); - String msg; - //only grab at most 1000 messages at a time - for (int i = 0; i < 1000; ++i) { - msg = pendingMessages.poll(); - if (msg == null) { - break; + + if(closed) { + //better to check initially, rather than in loop, reach out to RAM all the time + if (!stateUpdater.compareAndSet(this, 2, 3)) { + UndertowLogger.ROOT_LOGGER.accessLogWorkerFailureOnTransition(); } - messages.add(msg); + return; } + //only grab at most 1000 messages at a time try { - if (!messages.isEmpty()) { - writeMessage(messages); - } - } finally { - // change this state to final state - stateUpdater.set(this, 3); - //check to see if there is still more messages - //if so then run this again - if (!pendingMessages.isEmpty() || forceLogRotation) { - if (stateUpdater.compareAndSet(this, 3, 1)) { - logWriteExecutor.execute(this); + if(initOutput()) { + for (int i = 0; i < 1000 && !pendingMessages.isEmpty(); ++i) { + final String msg = pendingMessages.peek(); + if (msg == null) { + break; + } + if (!writeMessage(msg)) { + break; + } + + // NOTE:this is very similar to remove(), but without screenNull + // at best, it will work like poll/remove, at worst, will do nothing + if (!pendingMessages.remove(msg)) { + break; + } } } - // Check the state before resetting the state to 0 (not running) and checking if a writer needs to be closed: - // - If state != 3 here, another thread is executing this. - // The other thread will visit here and will check if a writer needs to be closed. - // We can leave state and skip closing a writer. - // - If state == 3 here, there is no another thread executing this. - // So, update the state to 0 (not running) and check if a writer needs be closed. - if (stateUpdater.compareAndSet(this, 3, 0) && closed) { - // As close() can be invoked from another thread in parallel, - // it will dispatch a new thread to close writer if state == 0 (not running) at that moment. - // So, just in case, check the state again: - // - if state != 0, another thread has already dispatched from close() and it will visit here. So, closing writer can be skipped here. - // - if state == 0, writer can be closed here. Let's change state to 3 again in order to prevent close() from dispatching a new thread. - if (stateUpdater.compareAndSet(this, 0, 3)) { - try { - if(writer != null) { - writer.flush(); - writer.close(); - writer = null; - } - } catch (IOException e) { - UndertowLogger.ROOT_LOGGER.errorWritingAccessLog(e); - } finally { - // reset the state to 0 again finally - stateUpdater.set(this, 0); + }finally { + // flush what we might have + try { + //this can happen when log has been rotated and there were no write + final BufferedWriter bw = this.writer; + if(bw != null) + bw.flush(); + } catch (IOException e) { + UndertowLogger.ROOT_LOGGER.errorWritingAccessLog(e); + } + if(this.closed) { + if (!stateUpdater.compareAndSet(this, 2, 3)) { + UndertowLogger.ROOT_LOGGER.accessLogWorkerFailureOnTransition(); + } + return; + } else { + if (!pendingMessages.isEmpty() || forceLogRotation) { + if (stateUpdater.compareAndSet(this, 2, 1)) { + logWriteExecutor.execute(this); + } else { + UndertowLogger.ROOT_LOGGER.accessLogWorkerFailureOnReschedule(); + } + } else { + if (!stateUpdater.compareAndSet(this, 2, 0)) { + UndertowLogger.ROOT_LOGGER.accessLogWorkerFailureOnTransition(); } } } @@ -243,42 +244,72 @@ void awaitWrittenForTest() throws InterruptedException { } } - private void writeMessage(final List messages) { - if (System.currentTimeMillis() > changeOverPoint) { - doRotate(); + private boolean writeMessage(final String message) { + //NOTE: is there a need to rotate on write? + //if (System.currentTimeMillis() > changeOverPoint) { + // performFileRotation(); + //} + try { + final BufferedWriter bw = this.writer; + if(bw != null){ + bw.write(message); + bw.newLine(); + return true; + } + return false; + } catch (IOException e) { + UndertowLogger.ROOT_LOGGER.errorWritingAccessLog(e); + return false; } + } + + private boolean initOutput() { try { - if (writer == null) { - writer = Files.newBufferedWriter(defaultLogFile, StandardCharsets.UTF_8, StandardOpenOption.APPEND, StandardOpenOption.CREATE); - if(Files.size(defaultLogFile) == 0 && fileHeaderGenerator != null) { + if (this.writer == null) { + //TODO: does this ^^ need a isOpen check? + this.writer = Files.newBufferedWriter(defaultLogFile, StandardCharsets.UTF_8, StandardOpenOption.APPEND, StandardOpenOption.CREATE); + if (Files.size(defaultLogFile) == 0 && fileHeaderGenerator != null) { String header = fileHeaderGenerator.generateHeader(); - if(header != null) { - writer.write(header); - writer.newLine(); - writer.flush(); + if (header != null) { + this.writer.write(header); + this.writer.newLine(); + this.writer.flush(); } } } - for (String message : messages) { - writer.write(message); - writer.newLine(); - } - writer.flush(); + return true; } catch (IOException e) { UndertowLogger.ROOT_LOGGER.errorWritingAccessLog(e); + return false; + } + } + private void checkAndRotateOnInitialRun() { + //if there is an existing log file check if it should be rotated + long lm = 0; + try { + lm = Files.getLastModifiedTime(defaultLogFile).toMillis(); + } catch (IOException e) { + UndertowLogger.ROOT_LOGGER.errorRotatingAccessLog(e); } + Calendar c = Calendar.getInstance(); + c.setTimeInMillis(changeOverPoint); + c.add(Calendar.DATE, -1); + if (lm <= c.getTimeInMillis()) { + performFileRotation(); + } + initialRun = false; } - private void doRotate() { + private void performFileRotation() { forceLogRotation = false; if (!rotate) { return; } try { - if (writer != null) { - writer.flush(); - writer.close(); - writer = null; + if (this.writer != null) { + this.writer.flush(); + this.writer.close(); + this.writer = null; } if (!Files.exists(defaultLogFile)) { return; @@ -308,11 +339,67 @@ public void rotate() { } } + @SuppressWarnings("static-access") @Override public void close() throws IOException { - closed = true; - if (stateUpdater.compareAndSet(this, 0, 1)) { - logWriteExecutor.execute(this); + synchronized (this) { + if(this.closed) { + return; + } + this.closed = true; + } + if (this.stateUpdater.compareAndSet(this, 0, 3)) { + flushAndTerminate(); + return; + } else { + // state[1,2] - scheduled or running, attempt schedule hijack + if (this.stateUpdater.compareAndSet(this, 1, 3)) { + //this means this thread raced against scheduled run(). run() will exit ASAP + //as 1->2 wont be possible, we are at 3 and this.closed == true + flushAndTerminate(); + return; + } + // either failed race to 1->3 or we were in 2. We have to wait here sometime. + // wait ~30s(by default), if situation does not clear up, try dumping stuff + for(int i=0; i Date: Tue, 14 May 2024 10:52:41 +0200 Subject: [PATCH 2/2] [UNDERTOW-1794] Add properties to allow set retry count/delay --- .../accesslog/DefaultAccessLogReceiver.java | 27 +++++++++++++++++-- 1 file changed, 25 insertions(+), 2 deletions(-) diff --git a/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java b/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java index 123b1914bd..ab695e7155 100644 --- a/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java +++ b/core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java @@ -26,6 +26,8 @@ import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.StandardOpenOption; +import java.security.AccessController; +import java.security.PrivilegedAction; import java.text.SimpleDateFormat; import java.util.Calendar; import java.util.Date; @@ -52,6 +54,8 @@ public class DefaultAccessLogReceiver implements AccessLogReceiver, Runnable, Cl private static final String DEFAULT_LOG_SUFFIX = "log"; private static final int DEFAULT_RETRY_COUNT = 150; private static final int DEFAULT_RETRY_DELAY = 200; + public static final String DEFAULT_RETRY_COUNT_PROPERTY = "io.undertow.accesslog.logreceiver.retryCount"; + public static final String DEFAULT_RETRY_DELAY_PROPERTY = "io.undertow.accesslog.logreceiver.retryDelay"; private final Executor logWriteExecutor; @@ -82,8 +86,8 @@ public class DefaultAccessLogReceiver implements AccessLogReceiver, Runnable, Cl private boolean initialRun = true; private final boolean rotate; private final LogFileHeaderGenerator fileHeaderGenerator; - private final int closeRetryCount = DEFAULT_RETRY_COUNT; - private final int closeRetryDelay = DEFAULT_RETRY_DELAY; + private final int closeRetryCount; + private final int closeRetryDelay; public DefaultAccessLogReceiver(final Executor logWriteExecutor, final File outputDirectory, final String logBaseName) { this(logWriteExecutor, outputDirectory.toPath(), logBaseName, null); @@ -109,6 +113,7 @@ public DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outp this(logWriteExecutor, outputDirectory, logBaseName, logNameSuffix, rotate, null); } + @SuppressWarnings({ "removal", "deprecation" }) public DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outputDirectory, final String logBaseName, final String logNameSuffix, boolean rotate, LogFileHeaderGenerator fileHeader) { this.logWriteExecutor = logWriteExecutor; this.outputDirectory = outputDirectory; @@ -119,6 +124,24 @@ public DefaultAccessLogReceiver(final Executor logWriteExecutor, final Path outp this.pendingMessages = new ConcurrentLinkedDeque<>(); this.defaultLogFile = outputDirectory.resolve(logBaseName + this.logNameSuffix); calculateChangeOverPoint(); + + String property = System.getSecurityManager() == null ? System.getProperty(DEFAULT_RETRY_COUNT_PROPERTY) + : AccessController.doPrivileged(new PrivilegedAction() { + @Override + public String run() { + return System.getProperty(DEFAULT_RETRY_COUNT_PROPERTY); + } + }); + this.closeRetryCount = property == null ? DEFAULT_RETRY_COUNT : Integer.parseInt(property); + + property = System.getSecurityManager() == null ? System.getProperty(DEFAULT_RETRY_DELAY_PROPERTY) + : AccessController.doPrivileged(new PrivilegedAction() { + @Override + public String run() { + return System.getProperty(DEFAULT_RETRY_DELAY_PROPERTY); + } + }); + this.closeRetryDelay = property == null ? DEFAULT_RETRY_DELAY : Integer.parseInt(property); } private void calculateChangeOverPoint() {