Apply blocked task logging to scheduled executor service (#4969)

* log dead tasks
* do log when tasks are scheduled and/or run

Signed-off-by: Andrew Fiddian-Green <software@whitebear.ch>

bundles/org.openhab.core/src/main/java/org/openhab/core/internal/common/WrappedScheduledExecutorService.java

@@ -15,8 +15,10 @@ package org.openhab.core.internal.common;
 import java.time.Duration;
 import java.time.Instant;
 import java.util.Objects;
+import java.util.Set;
 import java.util.concurrent.Callable;
 import java.util.concurrent.CancellationException;
+import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
 import java.util.concurrent.ScheduledFuture;
@@ -38,6 +40,7 @@ import org.slf4j.LoggerFactory;
  * user doesn't catch the error in the runnable itself.
  *
  * @author Hilbrand Bouwkamp - Initial contribution
+ * @author Andrew Fiddian-Green - Added task duration logging
  */
 @NonNullByDefault
 public class WrappedScheduledExecutorService extends ScheduledThreadPoolExecutor {
@@ -46,8 +49,11 @@ public class WrappedScheduledExecutorService extends ScheduledThreadPoolExecutor
 
     private static final Duration DEFAULT_TIMEOUT = Duration.ofMillis(5000);
 
+    private final Set<TimedAbstractTask> runningTasks;
+
     public WrappedScheduledExecutorService(int corePoolSize, ThreadFactory threadFactory) {
         super(corePoolSize, threadFactory);
+        runningTasks = ConcurrentHashMap.newKeySet(corePoolSize);
     }
 
     /**
@@ -61,10 +67,13 @@ public class WrappedScheduledExecutorService extends ScheduledThreadPoolExecutor
         protected TimedAbstractTask() {
             this.stackTraceHolder = new Exception();
             this.timeout = Instant.MAX;
+            logLongRunningTasks();
         }
 
         protected void clockStart() {
-            timeout = Instant.now().plus(DEFAULT_TIMEOUT);
+            extendTimeout();
+            logLongRunningTasks();
+            runningTasks.add(this);
         }
 
         protected void clockStop() {
@@ -72,6 +81,11 @@ public class WrappedScheduledExecutorService extends ScheduledThreadPoolExecutor
                 logger.debug("Scheduled task took more than {}; it was created here: ", DEFAULT_TIMEOUT,
                         stackTraceHolder);
             }
+            runningTasks.remove(this);
+        }
+
+        protected void extendTimeout() {
+            timeout = Instant.now().plus(DEFAULT_TIMEOUT);
         }
     }
 
@@ -169,4 +183,31 @@ public class WrappedScheduledExecutorService extends ScheduledThreadPoolExecutor
         Callable<V> c = logger.isDebugEnabled() ? new TimedCallable<>(callable) : callable;
         return super.schedule(c, delay, unit);
     }
+
+    /**
+     * On close, log all currently running tasks that have not yet finished.
+     */
+    @Override
+    public void close() {
+        runningTasks.forEach(t -> {
+            logger.debug("Scheduled task is still running during shutdown; it was created here: ", t.stackTraceHolder);
+        });
+        runningTasks.clear();
+        super.close();
+    }
+
+    /**
+     * Logs all currently running tasks that have exceeded the timeout. This method is called when either
+     * a new {@link TimedAbstractTask} is created or when its respective task gets called. e.g. the task
+     * is scheduled via 'scheduleWithFixedDelay()' (say) and its runnable is called repeatedly thereafter.
+     * Using this approach provides more opportunities to log long running tasks. This method extends the
+     * timeout of each logged task to reduce the frequency of messages in the log.
+     */
+    private synchronized void logLongRunningTasks() {
+        runningTasks.stream().filter(t -> Instant.now().isAfter(t.timeout)).forEach(t -> {
+            logger.debug("Scheduled task is taking more than {}; it was created here: ", DEFAULT_TIMEOUT,
+                    t.stackTraceHolder);
+            t.extendTimeout();
+        });
+    }
 }