Merge pull request #3 from tmfg/feature/DPO-2313-road

.gitignore

@@ -1 +1,15 @@
-target/
+*
+
+!/.gitignore
+!/pom.xml
+!/LICENSE
+!/README.md
+
+!src/
+!src/**/
+!src/**/*.java
+
+!.github/
+!.github/**/
+!.github/workflows/**/**.yml
+!.github/CODEOWNERS

pom.xml

@@ -30,6 +30,11 @@
             <artifactId>spring-boot-starter-web</artifactId>
             <version>${spring.version}</version>
         </dependency>
+        <dependency>
+            <groupId>org.springframework.boot</groupId>
+            <artifactId>spring-boot-starter-actuator</artifactId>
+            <version>${spring.version}</version>
+        </dependency>
         <dependency>
             <groupId>org.apache.commons</groupId>
             <artifactId>commons-lang3</artifactId>

src/main/java/fi/livi/digitraffic/common/annotation/NoJobLogging.java

@@ -0,0 +1,15 @@
+package fi.livi.digitraffic.common.annotation;
+
+import java.lang.annotation.ElementType;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+import java.lang.annotation.Target;
+
+/**
+ * Methods annotated with @NoJobLogging will not be monitored for execution time
+ * by ScheduledJobLogger.monitorScheduledJob()
+ */
+@Retention(RetentionPolicy.RUNTIME)
+@Target({ElementType.METHOD})
+public @interface NoJobLogging {
+}

src/main/java/fi/livi/digitraffic/common/aop/PerformanceMonitorAspect.java

@@ -21,38 +21,11 @@
 public class PerformanceMonitorAspect {
 
     private static final Logger log = LoggerFactory.getLogger("PerformanceMonitor");
-    private static final Logger logScheduledJob = LoggerFactory.getLogger("ScheduledJobMonitor");
     public static final int DEFAULT_ERROR_LIMIT = 60000;
     public static final int DEFAULT_WARNING_LIMIT = 5000;
     public static final int DEFAULT_INFO_LIMIT = 1000;
 
-    /**
-     * By default every method with @Scheduled annotation is monitored for
-     * logging execution start and end.
-     */
-    @Around("@annotation(org.springframework.scheduling.annotation.Scheduled)")
-    public Object monitorScheduledJob(final ProceedingJoinPoint pjp) throws Throwable {
-
-        final MethodSignature methodSignature = (MethodSignature) pjp.getSignature();
-
-        final StopWatch stopWatch = StopWatch.createStarted();
-        final String jobName = methodSignature.getDeclaringType().getSimpleName();
-        logScheduledJob.info("jobType=Scheduled jobName={} start", jobName);
-
-        try {
-            return pjp.proceed();
-        } catch (final Exception e) {
-            logScheduledJob.info("jobType=Scheduled jobName={} end jobEndStatus={} jobTimeMs={} lastError: {} {}",
-                jobName, "FAIL", stopWatch.getTime(), e.getClass(), e.getMessage());
-            throw e;
-        } finally {
-            stopWatch.stop();
-            logScheduledJob.info("jobType=Scheduled jobName={} end jobEndStatus={} jobTimeMs={}",
-                jobName, "SUCCESS", stopWatch.getTime());
-        }
-    }
-
-    /**
+     /**
      * By default every method in class with @Service annotation is monitored.
      * In addition any method can be monitored with @PerformanceMonitor annotation.
      * @PerformanceMonitor annotation also has properties to adjust monitoring settings.

src/main/java/fi/livi/digitraffic/common/aop/ScheduledJobLogger.java

@@ -0,0 +1,57 @@
+package fi.livi.digitraffic.common.aop;
+
+import static fi.livi.digitraffic.common.scheduler.JobLogger.JobType.Scheduled;
+
+import org.apache.commons.lang3.StringUtils;
+import org.apache.commons.lang3.time.StopWatch;
+import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.annotation.Around;
+import org.aspectj.lang.annotation.Aspect;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.core.Ordered;
+import org.springframework.core.annotation.Order;
+
+import fi.livi.digitraffic.common.scheduler.JobLogger;
+import fi.livi.digitraffic.common.scheduler.JobLogger.JobType;
+
+@Aspect
+@Order(Ordered.HIGHEST_PRECEDENCE)
+public class ScheduledJobLogger {
+
+    private static final Logger log = LoggerFactory.getLogger(ScheduledJobLogger.class);
+    private static final JobType jobType = Scheduled;
+
+    /**
+     * Execution start (debug level) and end (info or error level) times will be
+     * logged for each method annotated with @Scheduled.
+     *
+     * Methods annotated with @NoJobLogging will not be monitored.
+     */
+    @Around("@annotation(org.springframework.scheduling.annotation.Scheduled) && !@annotation(fi.livi.digitraffic.common.annotation.NoJobLogging)")
+    public Object monitorScheduledJob(final ProceedingJoinPoint pjp) throws Throwable {
+        final String method = pjp.getSignature().getName();
+        // Strip away Configuration suffix and Spring proxy classes
+        final String jobClass = StringUtils.substringBefore(StringUtils.substringBefore(pjp.getTarget().getClass().getSimpleName(),"Configuration"), "$");
+
+        final StopWatch stopWatch = StopWatch.createStarted();
+        final String jobName = jobClass + "." + method;
+
+        JobLogger.logJobStart(log, jobType, jobName);
+
+        Exception error = null;
+        try {
+            return pjp.proceed();
+        } catch (final Exception e) {
+            error = e;
+            throw e;
+        } finally {
+            stopWatch.stop();
+            if (error == null) {
+                JobLogger.logJobEndStatusSuccess(log, jobType, jobName, stopWatch.getTime());
+            } else {
+                JobLogger.logJobEndStatusFail(log, jobType, jobName, stopWatch.getTime(), error);
+            }
+        }
+    }
+}

src/main/java/fi/livi/digitraffic/common/aop/TransactionLoggerAspect.java

@@ -1,5 +1,9 @@
 package fi.livi.digitraffic.common.aop;
 
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.atomic.AtomicLong;
+
 import org.apache.commons.lang3.time.StopWatch;
 import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Around;
@@ -16,6 +20,10 @@ public class TransactionLoggerAspect {
 
     private final int limit;
 
+    private final AtomicLong idCounter = new AtomicLong();
+
+    private static Map<Long, TransactionDetails> activeTransactions = new ConcurrentHashMap();
+
     public TransactionLoggerAspect(final int limit) {
         this.limit = limit;
     }
@@ -26,19 +34,43 @@ public Object monitor(final ProceedingJoinPoint pjp) throws Throwable {
         final MethodSignature methodSignature = (MethodSignature) pjp.getSignature();
         final String className = methodSignature.getDeclaringType().getSimpleName();
         final String methodName = methodSignature.getName();
+        final String methodKey = className + "." + methodName;
         final Object[] args = pjp.getArgs();
+        final Long transactionId = idCounter.incrementAndGet();
 
         try {
+            activeTransactions.put(transactionId, new TransactionDetails(methodKey, args, System.currentTimeMillis()));
+
             return pjp.proceed();
         } finally {
             final long tookMs = stopWatch.getTime();
 
+            activeTransactions.remove(transactionId);
+
             if(tookMs > limit) {
-                final StringBuilder arguments = new StringBuilder(100);
-                fi.livi.digitraffic.common.aop.PerformanceMonitorAspect.buildValueToString(arguments, args);
-                log.info("Transaction method={}.{} arguments={} tookMs={}", className, methodName, arguments, tookMs);
+                final String arguments = argumentsToString(args);
+                log.info("Transaction method={} arguments={} tookMs={}", methodKey, arguments, tookMs);
             }
         }
     }
+
+    public static void logActiveTransactions(final Logger logger) {
+        Map.copyOf(activeTransactions)
+                .entrySet()
+                .forEach(e -> logger.info("Active transaction {}", e.getValue().getLogString()));
+    }
+
+    private static String argumentsToString(final Object[] args) {
+        final StringBuilder arguments = new StringBuilder(100);
+        PerformanceMonitorAspect.buildValueToString(arguments, args);
+
+        return arguments.toString();
+    }
+
+    private record TransactionDetails(String method, Object[] args, Long starttime) {
+        String getLogString() {
+            return String.format("%s age %d ms arguments %s", method, System.currentTimeMillis() - starttime, argumentsToString(args));
+        };
+    }
 }
 

src/main/java/fi/livi/digitraffic/common/config/metrics/HikariCPMetrics.java

@@ -0,0 +1,10 @@
+package fi.livi.digitraffic.common.config.metrics;
+
+public final class HikariCPMetrics {
+    public static final String CONNECTIONS_MAX = "hikaricp.connections.max";
+    public static final String CONNECTIONS_PENDING = "hikaricp.connections.pending";
+    public static final String CONNECTIONS_TIMEOUT = "hikaricp.connections.timeout";
+    public static final String CONNECTIONS_ACTIVE = "hikaricp.connections.active";
+
+    public static final String TAG_POOL = "pool";
+}

src/main/java/fi/livi/digitraffic/common/config/metrics/PendingConnectionDebugger.java

@@ -0,0 +1,41 @@
+package fi.livi.digitraffic.common.config.metrics;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.scheduling.annotation.Scheduled;
+import org.springframework.stereotype.Service;
+
+import fi.livi.digitraffic.common.annotation.NoJobLogging;
+import fi.livi.digitraffic.common.aop.TransactionLoggerAspect;
+import io.micrometer.core.instrument.Measurement;
+import io.micrometer.core.instrument.Meter;
+import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.search.RequiredSearch;
+
+@Service
+public class PendingConnectionDebugger {
+    private final MeterRegistry meterRegistry;
+
+    private static final int PENDING_CONNECTIONS_LOG_LIMIT = 5;
+
+    private static final Logger log = LoggerFactory.getLogger("PendingConnectionDebugger");
+
+    public PendingConnectionDebugger(final MeterRegistry meterRegistry) {
+        this.meterRegistry = meterRegistry;
+    }
+
+    @Scheduled(fixedRate = 500)
+    @NoJobLogging
+    void debugPendingConnections() {
+        final RequiredSearch requiredSearch = meterRegistry.get(HikariCPMetrics.CONNECTIONS_PENDING);
+        final Meter meter = requiredSearch.meter(); // should only have one meter
+        final Measurement measurement = meter.measure().iterator().next(); // should only have one measurement
+
+        // when too many connections are pending, print all active transactions
+        if(measurement.getValue() > PENDING_CONNECTIONS_LOG_LIMIT) {
+            log.error("Connections pending! count={}", measurement.getValue());
+
+            TransactionLoggerAspect.logActiveTransactions(log);
+        }
+    }
+}

src/main/java/fi/livi/digitraffic/common/scheduler/JobLogger.java

@@ -0,0 +1,34 @@
+package fi.livi.digitraffic.common.scheduler;
+
+import org.slf4j.Logger;
+
+public class JobLogger {
+
+    public enum JobType {
+        Scheduled,
+        Quartz;
+    }
+
+    public enum JobEndStatus {
+        SUCCESS,
+        FAIL;
+    }
+
+    public static void logJobStart(final Logger log, final JobType jobType, final String jobName) {
+        log.debug("jobType={} jobName={} start", jobType.name(), jobName);
+    }
+
+    public static void logJobEndStatusFail(final Logger log, final JobType jobType, final String jobName, long timeMs, final Exception lastError) {
+        log.error(formatMessage(jobType, jobName, JobEndStatus.FAIL, timeMs), lastError);
+    }
+
+    public static void logJobEndStatusSuccess(final Logger log, final JobType jobType, final String jobName, long timeMs) {
+        log.info(formatMessage(jobType, jobName, JobEndStatus.SUCCESS, timeMs));
+    }
+
+    private static final String messageFormat = "jobType=%s jobName=%s jobEndStatus=%s jobTimeMs=%d";
+
+    private static String formatMessage(final JobType jobType, final String jobName, final JobEndStatus status, final long timeMs) {
+        return String.format(messageFormat, jobType, jobName, status, timeMs);
+    }
+}