UNDERTOW-1794 DefaultAccessLogReceiver violates Closeable contract #1041

baranowb · 2021-02-16T09:11:53Z

ISSUE: https://issues.redhat.com/browse/UNDERTOW-1794
related to: https://issues.redhat.com/browse/EAP7-1642

baranowb · 2021-02-16T09:29:35Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-                if (stateUpdater.compareAndSet(this, 3, 1)) {
-                    logWriteExecutor.execute(this);
+            for (int i = 0; i < 1000 && !this.closed && !pendingMessages.isEmpty(); ++i) {
+                final String msg = pendingMessages.poll();


It might be better to use peek()+remove() here. Though Id assume follow up might be better than to alter PRs ad hoc.

@baranowb because this class has concurrent access, poll is better than peek() + remove(). Between the moment we invoke peek() and the moment we invoke remove, we risk having another thread executing flushAndTerminate. This is why we need to run poll() here.

There is trade off. It is possible that XNIO thread will be terminated between poll() and write(), leaking one message.
If its peek()+remove(), it might double entry, but not loose it. Its a trade off.

You're right about it. My question is now is hot to prevent both scenarios. Is there some way we can synchronize just a little bit to prevent a duplicate entry in the log? I think we must prevent an output that will be considered buggy by users if someone finds a duplicate entry after shutting down the server.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2021-02-16T10:01:58Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-        closed = true;
-        if (stateUpdater.compareAndSet(this, 0, 1)) {
-            logWriteExecutor.execute(this);
+        this.closed = true;


method must take into account that the state could change between one if and the other. So, there is a possibility that all stateUpdater checks return false.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2021-02-16T10:08:05Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

+        try {
+            while (!this.pendingMessages.isEmpty()) {
+                final String msg = this.pendingMessages.poll();
+                // TODO: clarify this, how is this possible?


It might not be possible. Lets wait for the final version of the code of run() and close() to decide this

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2021-02-16T10:10:15Z

as this is a new feature, merging of this PR will require synchronization with the RFE process. I'll assist in having all the process followed as fast as we can to have this merged the soonest.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2023-03-21T20:31:22Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-            doRotate();
+    private void writeMessage(final String message) {
+        //NOTE: is there a need to rotate on write?
+        //if (System.currentTimeMillis() > changeOverPoint) {


Yes, but only once per run. Now that this method is called per message it is no longer the adequate place for that.

Probably we should add the limit to 1000 here? I think it would perform a bit better.

I still stand my ground, I think the granularity of checking 1000 here performs better.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

baranowb · 2023-04-26T08:33:02Z

core/src/main/java/io/undertow/UndertowLogger.java

+    void accessLogWorkerFailureOnTransition();
+
+    @LogMessage(level = DEBUG)
+    @Message(id = 6000, value = "Access Log Worker failed to reschedule.")


Big brain math....

On the other hand - no one noticed :)

I cant find this one to mark it as outdated, lets reset.

fl4via

There are some pending issues here to consider.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2024-04-30T06:55:03Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

+            //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();
+        }


just a thought, has this been tested? Is it better to silently not log the message or to throw an exception?
My first idea is throwing an exception, but still I need to know if the consequences of this exception have been explored and double-checked as harmless.

Well. Its a tricky scenario. When this happens, every connection/exchange should/will be purged.
When exception is thrown, it potentially wont allow to close connection.

Also, note that its expected behavior from closed resource.

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2024-04-30T08:02:07Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-                    logWriteExecutor.execute(this);
+            for (int i = 0; i < 1000 && !this.closed && !pendingMessages.isEmpty(); ++i) {
+                final String msg = pendingMessages.peek();
+                if (msg == null) {


it is not supposed to be null, because you are checking it is not empty

fl4via · 2024-04-30T08:08:19Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-                if (stateUpdater.compareAndSet(this, 3, 1)) {
-                    logWriteExecutor.execute(this);
+            for (int i = 0; i < 1000 && !this.closed && !pendingMessages.isEmpty(); ++i) {
+                final String msg = pendingMessages.peek();


I might be looking too much into details here, but why peeking and removing instead of just polling?

in case there is some intermitent IO failure, it should not purge entries without writing them first. Though, in such case, some overflow mechanism should be in place as well?

Also "i < 1000 && !this.closed &&" checking this in loop might not be best, should be enough to loop through and check at the end IMHO

fl4via · 2024-04-30T08:09:22Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

+                }
+            }
+        }finally {
+            // flush what we might have


this is a very good point

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

fl4via · 2024-04-30T08:32:01Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

+                }
+                return;
+            } else {
+                if (!pendingMessages.isEmpty() || forceLogRotation) {


I have been thinking... we still need a state for being at the finally block, as it prevents us from having more than one thread scheduling a new execution of run at the same time

how? if there is nothing in pendingMessages, it does not need scheduling, if someone writes, it will be able to schedule. In reality, pendingMessages are filled before state change, so its just a race between logMessage thread and run() to schedule new execution.

fl4via · 2024-04-30T08:35:39Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

@@ -59,7 +58,7 @@ public class DefaultAccessLogReceiver implements AccessLogReceiver, Runnable, Cl
    //0 = not running
    //1 = queued
    //2 = running
-    //3 = final state of running (inside finally of run())


I added a comment down below that we will still need state 3 to be used to keep tracking of being at finally of run)
That being said what are we trying to achieve with the new state 3? (It will have to be moved to 4 if we decide to keep it)> Are we trying to prevent run from doing anything after closed is invoked? Is that its purpose?

okay, it is clearly stated in the Jira: we want to make sure that close returns only after it is fully closed. The question that remains is if we need a new state for it, I think we need so we can fully skip the rest of the execution of run() in case it is closing, without having to resort to verifying the value of close.

I dont think so. Its a bit different FSM/CAS that was present before. It relied only on worker threads to dump messages even when handler has been closed and once its done close. This cant be done now since those worker threads may be disabled( upstream issue)

fl4via · 2024-04-30T08:57:45Z

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java

-            doRotate();
+    private void writeMessage(final String message) {
+        //NOTE: is there a need to rotate on write?
+        //if (System.currentTimeMillis() > changeOverPoint) {


I still stand my ground, I think the granularity of checking 1000 here performs better.

baranowb commented Feb 16, 2021

View reviewed changes

fl4via reviewed Feb 16, 2021

View reviewed changes

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java Outdated Show resolved Hide resolved

fl4via reviewed Feb 16, 2021

View reviewed changes

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java Show resolved Hide resolved

fl4via reviewed Feb 16, 2021

View reviewed changes

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java Outdated Show resolved Hide resolved

fl4via reviewed Feb 16, 2021

View reviewed changes

fl4via requested changes Feb 16, 2021

View reviewed changes

core/src/main/java/io/undertow/server/handlers/accesslog/DefaultAccessLogReceiver.java Show resolved Hide resolved

fl4via added the new feature/API change New feature to be introduced or a change to the API (non suitable to minor releases) label Feb 16, 2021

baranowb force-pushed the UNDERTOW-1794 branch from febb374 to 7beb8be Compare February 17, 2021 08:45

baranowb force-pushed the UNDERTOW-1794 branch 2 times, most recently from bb266f8 to 8407e8d Compare March 8, 2021 09:58

baranowb force-pushed the UNDERTOW-1794 branch from 8407e8d to 00a68be Compare April 27, 2021 11:14

fl4via previously requested changes Mar 21, 2023

View reviewed changes

fl4via added the waiting PR update Awaiting PR update(s) from contributor before merging label Mar 21, 2023

baranowb force-pushed the UNDERTOW-1794 branch from 00a68be to d782713 Compare April 14, 2023 11:26

baranowb requested a review from fl4via April 14, 2023 11:31

baranowb commented Apr 26, 2023

View reviewed changes

baranowb force-pushed the UNDERTOW-1794 branch from d782713 to 8ff8540 Compare April 26, 2023 08:51

baranowb force-pushed the UNDERTOW-1794 branch from 8ff8540 to 77cb16d Compare March 12, 2024 08:47

fl4via requested changes Apr 30, 2024

View reviewed changes

baranowb force-pushed the UNDERTOW-1794 branch 2 times, most recently from 4e48ee9 to 566c11f Compare May 8, 2024 15:49

[UNDERTOW-1794] improve DefaultAccessLogReceiver to obey contract!

3b217e9

baranowb force-pushed the UNDERTOW-1794 branch from 566c11f to 3b217e9 Compare May 9, 2024 07:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

UNDERTOW-1794 DefaultAccessLogReceiver violates Closeable contract #1041

UNDERTOW-1794 DefaultAccessLogReceiver violates Closeable contract #1041

baranowb commented Feb 16, 2021 •

edited by fl4via

baranowb Feb 16, 2021 •

edited

fl4via Feb 16, 2021

baranowb Feb 16, 2021

fl4via Mar 8, 2021

fl4via Feb 16, 2021

fl4via Feb 16, 2021

fl4via commented Feb 16, 2021

fl4via Mar 21, 2023

fl4via Mar 21, 2023

fl4via Apr 30, 2024

baranowb Apr 26, 2023

baranowb Apr 26, 2023

fl4via left a comment

fl4via Apr 30, 2024

baranowb May 7, 2024

baranowb May 8, 2024

fl4via Apr 30, 2024

fl4via Apr 30, 2024

baranowb May 7, 2024

baranowb May 8, 2024

fl4via Apr 30, 2024

fl4via Apr 30, 2024

baranowb May 7, 2024

fl4via Apr 30, 2024

fl4via Apr 30, 2024

baranowb May 9, 2024

fl4via Apr 30, 2024

UNDERTOW-1794 DefaultAccessLogReceiver violates Closeable contract #1041

Are you sure you want to change the base?

UNDERTOW-1794 DefaultAccessLogReceiver violates Closeable contract #1041

Conversation

baranowb commented Feb 16, 2021 • edited by fl4via

baranowb Feb 16, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fl4via commented Feb 16, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fl4via left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

baranowb commented Feb 16, 2021 •

edited by fl4via

baranowb Feb 16, 2021 •

edited