fix: improve logging (#67)

Author: Frnd-me

src/main/java/at/ac/uibk/dps/cirrina/cirrina/Cirrina.kt

@@ -11,6 +11,9 @@ import com.google.common.flogger.FluentLogger
 import io.opentelemetry.api.OpenTelemetry
 import io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk
 import java.net.URI
+import java.util.logging.LogManager
+import org.apache.commons.lang3.builder.ToStringBuilder
+import org.apache.commons.lang3.builder.ToStringStyle.SIMPLE_STYLE
 
 private val logger: FluentLogger = FluentLogger.forEnclosingClass()
 
@@ -20,6 +23,17 @@ class Cirrina {
     const val NATS_CONNECTION_TIMEOUT = 60000L
 
     init {
+      ToStringBuilder.setDefaultStyle(SIMPLE_STYLE)
+
+      runCatching {
+          Cirrina::class.java.getResourceAsStream("/logging.properties")?.use { inputStream ->
+            LogManager.getLogManager().readConfiguration(inputStream)
+          } ?: logger.atWarning().log("Logging properties file not found")
+        }
+        .onFailure { ex ->
+          logger.atSevere().withCause(ex).log("Could not load logging properties")
+        }
+
       logger.atFine().log("Starting health service")
       runCatching { HealthService(EnvironmentVariables.healthPort.get()) }
         .getOrElse { e -> logger.atSevere().withCause(e).log("Could not start the health service") }

src/main/java/at/ac/uibk/dps/cirrina/execution/command/ActionAssignCommand.java

@@ -64,7 +64,7 @@ public List<ActionCommand> execute() throws UnsupportedOperationException {
           )
         );
     } catch (IOException e) {
-      logger.atWarning().withCause(e).log("Data assignment failed");
+      logger.atWarning().log("Data assignment failed");
     }
 
     return commands;

src/main/java/at/ac/uibk/dps/cirrina/execution/command/ActionCreateCommand.java

@@ -68,7 +68,7 @@ public List<ActionCommand> execute() throws UnsupportedOperationException {
           gauges.attributesForData("create", !isPersistent ? "local" : "persistent", size)
         );
     } catch (Exception e) {
-      logger.atWarning().withCause(e).log("Data creation failed");
+      logger.atWarning().log("Data creation failed");
     }
 
     return commands;

src/main/java/at/ac/uibk/dps/cirrina/execution/command/ActionInvokeCommand.java

@@ -61,20 +61,19 @@ public List<ActionCommand> execute() throws UnsupportedOperationException {
       // Invoke (asynchronously)
       serviceImplementation
         .invoke(input, executionContext.scope().getId())
-        .exceptionally(e -> {
-          logger
-            .atWarning()
-            .withCause(e)
-            .log(
-              "Service invocation failed for service '%s'",
-              serviceImplementation.getInformationString()
-            );
-          return null;
-        })
-        .thenAccept(output -> {
-          assignServiceOutput(output, extent);
-          raiseEvents(output, eventListener, eventHandler);
-          measurePerformance(start, serviceImplementation);
+        .whenComplete((output, e) -> {
+          if (e != null) {
+            logger
+              .atWarning()
+              .log(
+                "Service invocation failed for service '%s'",
+                serviceImplementation.getInformationString()
+              );
+          } else {
+            assignServiceOutput(output, extent);
+            raiseEvents(output, eventListener, eventHandler);
+            measurePerformance(start, serviceImplementation);
+          }
         });
 
       return commands;

src/main/java/at/ac/uibk/dps/cirrina/execution/command/ActionMatchCommand.java

@@ -39,7 +39,7 @@ public List<ActionCommand> execute() throws UnsupportedOperationException {
         }
       }
     } catch (UnsupportedOperationException e) {
-      logger.atWarning().withCause(e).log("Could not execute match action");
+      logger.atWarning().log("Could not execute match action");
     }
 
     return commands;

src/main/java/at/ac/uibk/dps/cirrina/execution/object/context/NatsContext.kt

@@ -61,7 +61,7 @@ class NatsContext(
                       connection = conn
                     } catch (e: Exception) {
                       logger
-                        .atWarning()
+                        .atSevere()
                         .withCause(e)
                         .log("Failed to setup the persistent context bucket")
                     } finally {
@@ -234,7 +234,7 @@ class NatsContext(
             conn.close()
           }
         }
-        .onFailure { e -> logger.atWarning().withCause(e).log("Failed to close the NATS") }
+        .onFailure { _ -> logger.atWarning().log("Failed to close the NATS") }
     }
   }
 

src/main/java/at/ac/uibk/dps/cirrina/execution/object/event/NatsEventHandler.kt

@@ -54,7 +54,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
                         }
                       connection = conn
                     } catch (e: Exception) {
-                      logger.atWarning().withCause(e).log("Failed to setup the NATS event handler")
+                      logger.atSevere().withCause(e).log("Failed to setup the NATS event handler")
                     } finally {
                       connectedLatch.countDown()
                     }
@@ -97,8 +97,8 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
       .onFailure { e ->
         when (e) {
           is UnsupportedOperationException ->
-            logger.atFiner().withCause(e).log("A message could not be read as an event")
-          else -> logger.atWarning().withCause(e).log("Unexpected error while handling a message")
+            logger.atFiner().log("A message could not be read as an event")
+          else -> logger.atWarning().log("Unexpected error while handling a message")
         }
       }
   }
@@ -133,9 +133,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
     synchronized(lock) {
       connection?.let { conn ->
         runCatching { conn.publish(subject, EventExchange(event).toBytes()) }
-          .onFailure { e ->
-            logger.atWarning().withCause(e).log("Failed to publish event '$subject'", e)
-          }
+          .onFailure { _ -> logger.atWarning().log("Failed to publish event '$subject'") }
       } ?: logger.atWarning().log("Not sending event, not connected to the NATS server")
     }
   }
@@ -153,7 +151,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
           dispatcher?.subscribe(subject)
             ?: logger.atFiner().log("Dispatcher unavailable; queued subscription: $subject")
         }
-        .onFailure { e -> logger.atWarning().withCause(e).log("Could not subscribe to $eventName") }
+        .onFailure { _ -> logger.atWarning().log("Could not subscribe to $eventName") }
     }
   }
 
@@ -167,9 +165,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
     synchronized(lock) {
       subscriptions.remove(subject)
       runCatching { dispatcher?.unsubscribe(subject) }
-        .onFailure { e ->
-          logger.atWarning().withCause(e).log("Could not unsubscribe from $eventName", e)
-        }
+        .onFailure { _ -> logger.atWarning().log("Could not unsubscribe from $eventName") }
     }
   }
 
@@ -187,9 +183,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
           dispatcher?.subscribe(subject)
             ?: logger.atFiner().log("Dispatcher unavailable; queued subscription: $subject")
         }
-        .onFailure { e ->
-          logger.atWarning().withCause(e).log("Could not subscribe to $subject", e)
-        }
+        .onFailure { _ -> logger.atWarning().log("Could not subscribe to $subject") }
     }
   }
 
@@ -204,9 +198,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
     synchronized(lock) {
       subscriptions.remove(subject)
       runCatching { dispatcher?.unsubscribe(subject) }
-        .onFailure { e ->
-          logger.atWarning().withCause(e).log("Could not unsubscribe from $subject", e)
-        }
+        .onFailure { _ -> logger.atWarning().log("Could not unsubscribe from $subject") }
     }
   }
 
@@ -221,7 +213,7 @@ class NatsEventHandler(natsUrl: String) : EventHandler() {
           dispatcher?.let { connection?.closeDispatcher(it) }
           connection?.close()
         }
-        .onFailure { e -> logger.atWarning().withCause(e).log("Failed to close the NATS") }
+        .onFailure { _ -> logger.atWarning().log("Failed to close the NATS") }
     }
   }
 

src/main/java/at/ac/uibk/dps/cirrina/execution/object/statemachine/StateMachine.java

@@ -487,7 +487,7 @@ private void switchActiveState(State state) throws IllegalArgumentException {
     }
 
     logger
-      .atFine()
+      .atFiner()
       .log("State machine '%s': Switching state '%s' to '%s'", this, activeState, state);
 
     // Update the active state
@@ -620,7 +620,7 @@ private void handleInternalTransition(
     @NotNull Transition transition,
     @Nullable Event raisingEvent
   ) throws UnsupportedOperationException {
-    logger.atFine().log("State machine '%s': Handling internal transition '%s'", this, transition);
+    logger.atFiner().log("State machine '%s': Handling internal transition '%s'", this, transition);
 
     // Only perform the transition
     doTransition(transition, raisingEvent);
@@ -637,7 +637,7 @@ private void handleExternalTransition(
     @NotNull Transition transition,
     @Nullable Event raisingEvent
   ) throws UnsupportedOperationException {
-    logger.atFine().log("State machine '%s': Handling external transition '%s'", this, transition);
+    logger.atFiner().log("State machine '%s': Handling external transition '%s'", this, transition);
 
     final var targetStateName = transition.getTargetStateName().get();
 
@@ -723,7 +723,7 @@ private Optional<Transition> handleEvent(Event event)
               );
             }
           } catch (IOException e) {
-            logger.atWarning().withCause(e).log("Failed to set event data");
+            logger.atWarning().log("Failed to set event data");
           }
         },
         () -> logger.atFiner().log("State machine '%s': No on transition selected", this)
@@ -822,7 +822,10 @@ public String getId() {
 
   @Override
   public String toString() {
-    return new ToStringBuilder(this).append("id", stateMachineId).toString();
+    return new ToStringBuilder(this)
+      .append("id", stateMachineId)
+      .append("name", stateMachineClass.getName())
+      .toString();
   }
 
   /**

src/main/resources/logging.properties

@@ -0,0 +1,7 @@
+handlers = java.util.logging.ConsoleHandler
+
+java.util.logging.ConsoleHandler.level = FINE
+java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
+
+.level = INFO
+at.ac.uibk.dps.cirrina.level = FINE