From 00e355bebb2f90bba885517e2211cc21264e63b6 Mon Sep 17 00:00:00 2001
From: Ludovic Orban <lorban@bitronix.be>
Date: Mon, 21 Nov 2022 15:39:25 +0100
Subject: [PATCH] Add debug logging to `SerializedInvoker` (#8914)

Added debug logging and task naming
---
 .../jetty/util/thread/SerializedInvoker.java  | 73 +++++++++++++++++++
 .../test/resources/jetty-logging.properties   |  1 +
 2 files changed, 74 insertions(+)

diff --git a/jetty-core/jetty-util/src/main/java/org/eclipse/jetty/util/thread/SerializedInvoker.java b/jetty-core/jetty-util/src/main/java/org/eclipse/jetty/util/thread/SerializedInvoker.java
index 3b5d57bf122..08530567d50 100644
--- a/jetty-core/jetty-util/src/main/java/org/eclipse/jetty/util/thread/SerializedInvoker.java
+++ b/jetty-core/jetty-util/src/main/java/org/eclipse/jetty/util/thread/SerializedInvoker.java
@@ -45,8 +45,26 @@ public class SerializedInvoker
     public Runnable offer(Runnable task)
     {
         if (task == null)
+        {
+            if (LOG.isDebugEnabled())
+                LOG.debug("Offering task null, skipping it in {}", this);
             return null;
+        }
+        // The NamedRunnable logger is checked to make it possible to enable the nice task names in a debugger
+        // while not flooding the logs nor stderr with logging statements just by adding
+        // org.eclipse.jetty.util.thread.SerializedInvoker$NamedRunnable.LEVEL=DEBUG to jetty-logging.properties.
+        if (NamedRunnable.LOG.isDebugEnabled())
+        {
+            if (!(task instanceof NamedRunnable))
+            {
+                // Wrap the given task with another one that's going to delegate run() to the wrapped task while the
+                // wrapper's toString() returns a description of the place in code where SerializedInvoker.run() was called.
+                task = new NamedRunnable(task, deriveTaskName(task));
+            }
+        }
         Link link = new Link(task);
+        if (LOG.isDebugEnabled())
+            LOG.debug("Offering link {} of {}", link, this);
         Link penultimate = _tail.getAndSet(link);
         if (penultimate == null)
             return link;
@@ -54,6 +72,18 @@ public class SerializedInvoker
         return null;
     }
 
+    protected String deriveTaskName(Runnable task)
+    {
+        StackTraceElement[] stackTrace = new Exception().getStackTrace();
+        for (StackTraceElement stackTraceElement : stackTrace)
+        {
+            String className = stackTraceElement.getClassName();
+            if (!className.equals(SerializedInvoker.class.getName()) && !className.equals(getClass().getName()))
+                return "Queued at " + stackTraceElement;
+        }
+        return task.toString();
+    }
+
     /**
      * Arrange for tasks to be invoked, mutually excluded from other tasks.
      * @param tasks The tasks to invoke
@@ -62,6 +92,8 @@ public class SerializedInvoker
      */
     public Runnable offer(Runnable... tasks)
     {
+        if (LOG.isDebugEnabled())
+            LOG.debug("Offering {} tasks in {}", tasks.length, this);
         Runnable runnable = null;
         for (Runnable task : tasks)
         {
@@ -83,6 +115,9 @@ public class SerializedInvoker
         Runnable todo = offer(task);
         if (todo != null)
             todo.run();
+        else
+            if (LOG.isDebugEnabled())
+                LOG.debug("Queued link in {}", this);
     }
 
     /**
@@ -95,6 +130,15 @@ public class SerializedInvoker
         Runnable todo = offer(tasks);
         if (todo != null)
             todo.run();
+        else
+            if (LOG.isDebugEnabled())
+                LOG.debug("Queued links in {}", this);
+    }
+
+    @Override
+    public String toString()
+    {
+        return String.format("%s@%x", getClass().getSimpleName(), hashCode());
     }
 
     protected void onError(Runnable task, Throwable t)
@@ -140,16 +184,45 @@ public class SerializedInvoker
             Link link = this;
             while (link != null)
             {
+                if (LOG.isDebugEnabled())
+                    LOG.debug("Running link {} of {}", link, SerializedInvoker.this);
                 try
                 {
                     link._task.run();
                 }
                 catch (Throwable t)
                 {
+                    if (LOG.isDebugEnabled())
+                        LOG.debug("Failed while running link {} of {}", link, SerializedInvoker.this, t);
                     onError(link._task, t);
                 }
                 link = link.next();
+                if (link == null && LOG.isDebugEnabled())
+                    LOG.debug("Next link is null, execution is over in {}", SerializedInvoker.this);
             }
         }
+
+        @Override
+        public String toString()
+        {
+            return String.format("%s@%x[%s] -> %s", getClass().getSimpleName(), hashCode(), _task, _next);
+        }
+    }
+
+    private record NamedRunnable(Runnable delegate, String name) implements Runnable
+    {
+        private static final Logger LOG = LoggerFactory.getLogger(NamedRunnable.class);
+
+        @Override
+        public void run()
+        {
+            delegate.run();
+        }
+
+        @Override
+        public String toString()
+        {
+            return name;
+        }
     }
 }
diff --git a/jetty-core/jetty-util/src/test/resources/jetty-logging.properties b/jetty-core/jetty-util/src/test/resources/jetty-logging.properties
index 3c640749c64..8b5f6259c8e 100644
--- a/jetty-core/jetty-util/src/test/resources/jetty-logging.properties
+++ b/jetty-core/jetty-util/src/test/resources/jetty-logging.properties
@@ -2,3 +2,4 @@
 #org.eclipse.jetty.util.PathWatcher.LEVEL=DEBUG
 #org.eclipse.jetty.util.thread.QueuedThreadPool.LEVEL=DEBUG
 #org.eclipse.jetty.util.thread.ReservedThreadExecutor.LEVEL=DEBUG
+#org.eclipse.jetty.util.thread.SerializedInvoker$NamedRunnable.LEVEL=DEBUG