WIP adding additional logging

api/src/main/java/ca/bc/gov/educ/penreg/api/orchestrator/PenReqBatchStudentOrchestrator.java

@@ -160,6 +160,7 @@ protected void validateStudentDemographics(final Event event, final Saga saga, f
   protected void processPenMatchResults(final Event event, final Saga saga, final PenRequestBatchStudentSagaData penRequestBatchStudentSagaData) throws IOException, InterruptedException, TimeoutException {
     UUID sagaId = saga.getSagaId();
     Stopwatch processPenMatchResults = new Stopwatch("processPenMatchResults", sagaId);
+    Stopwatch processPenMatchInner = new Stopwatch("processPenMatchInner", sagaId);
     Stopwatch updateAttachedSaga = new Stopwatch("updateAttachedSagaWithEvents", sagaId);
     Stopwatch updateAttachedEntityDuringSaga = new Stopwatch("updateAttachedEntityDuringSagaProcess", sagaId);
     processPenMatchResults.start();
@@ -177,7 +178,9 @@ protected void processPenMatchResults(final Event event, final Saga saga, final
       this.getSagaService().updateAttachedSagaWithEvents(saga, eventStates);
       updateAttachedSaga.stop();
 
+      processPenMatchInner.start();
       eventOptional = this.getPenRequestBatchStudentOrchestratorService().processPenMatchResult(saga, penRequestBatchStudentSagaData, penMatchResult);
+      processPenMatchInner.stop();
 
       penRequestBatchStudentSagaData.setIsPENMatchResultsProcessed(true);
       saga.setPayload(JsonUtil.getJsonStringFromObject(penRequestBatchStudentSagaData)); // save the updated payload to DB...

api/src/main/java/ca/bc/gov/educ/penreg/api/orchestrator/base/BaseOrchestrator.java

@@ -18,6 +18,7 @@
 import ca.bc.gov.educ.penreg.api.struct.Event;
 import ca.bc.gov.educ.penreg.api.struct.NotificationEvent;
 import ca.bc.gov.educ.penreg.api.util.JsonUtil;
+import ca.bc.gov.educ.penreg.api.util.Stopwatch;
 import jakarta.validation.constraints.NotNull;
 import java.io.IOException;
 import java.time.LocalDateTime;
@@ -441,6 +442,10 @@ private void replayFromBeginning(final Saga saga, final T t) throws InterruptedE
   @Async("subscriberExecutor")
   @Transactional
   public void handleEvent(@NotNull final Event event) throws InterruptedException, IOException, TimeoutException {
+    UUID sagaId = event.getSagaId();
+    Stopwatch handleEvent = new Stopwatch("handleEvent", sagaId);
+    Stopwatch processEvent = new Stopwatch("processEvent", sagaId);
+    handleEvent.start();
     log.info("executing saga event {}", event.getEventType());
     log.trace("Full event :: {}", event);
     if (this.sagaEventExecutionNotRequired(event)) {
@@ -457,7 +462,9 @@ public void handleEvent(@NotNull final Event event) throws InterruptedException,
         final var sagaEventState = this.findNextSagaEventState(event.getEventType(), event.getEventOutcome(), sagaData);
         log.trace("found next event as {}", sagaEventState);
         if (sagaEventState.isPresent()) {
+          processEvent.start();
           this.process(event, saga, sagaData, sagaEventState.get());
+          processEvent.stop();
         } else {
           log.error("This should not have happened, please check that both the saga api and all the participating apis are in sync in terms of events and their outcomes. {}", event.toString()); // more explicit error message,
         }
@@ -467,6 +474,8 @@ public void handleEvent(@NotNull final Event event) throws InterruptedException,
     } else {
       log.error("Saga process without DB record is not expected. {}", event);
     }
+
+    handleEvent.stop();
   }
 
   /**
@@ -576,14 +585,22 @@ protected Optional<SagaEventState<T>> findNextSagaEventState(final EventType cur
    * @throws IOException          if there is connectivity problem
    */
   protected void process(@NotNull final Event event, final Saga saga, final T sagaData, final SagaEventState<T> sagaEventState) throws InterruptedException, TimeoutException, IOException {
+    UUID sagaId = saga.getSagaId();
+    Stopwatch process = new Stopwatch("process", sagaId);
+    Stopwatch invokeNextEvent = new Stopwatch("invokeNextEvent", sagaId);
+    process.start();
     if (!saga.getSagaState().equalsIgnoreCase(COMPLETED.toString())
         && this.isNotProcessedEvent(event.getEventType(), saga, this.nextStepsToExecute.keySet())) {
       log.info(SYSTEM_IS_GOING_TO_EXECUTE_NEXT_EVENT_FOR_CURRENT_EVENT, sagaEventState.getNextEventType(), event.getEventType(), saga.getSagaId());
       log.trace("Full event for SAGA_ID :: {} is :: {}", saga.getSagaId(), event.toString());
+
+      invokeNextEvent.start();
       this.invokeNextEvent(event, saga, sagaData, sagaEventState);
+      invokeNextEvent.stop();
     } else {
       log.info("ignoring this message as we have already processed it or it is completed. {}", event.toString()); // it is expected to receive duplicate message in saga pattern, system should be designed to handle duplicates.
     }
+    process.stop();
   }
 
   /**

api/src/main/java/ca/bc/gov/educ/penreg/api/service/PenRequestBatchStudentService.java

@@ -397,7 +397,7 @@ public boolean isPenAlreadyAssigned(final PenRequestBatchEntity penRequestBatch,
       }
       semaphore.tryRelease(id);
     } catch (final Exception e) {
-      log.error("PenMatchRecord in priority queue is empty for matched status, this should not have happened.");
+      log.error("PenMatchRecord in priority queue is empty for matched status, this should not have happened. {}", e);
       throw new PenRegAPIRuntimeException("PenMatchRecord in priority queue is empty for matched status, this should not have happened.");
     }
     return penAlreadyAssigned;