Added RecipeId and RecipeName to log lines (#1589)

* Added RecipeId and RecipeName on locations where it is possible to better separate logs per user.
ing-bank · Nov 8, 2023 · a8b2971 · a8b2971
1 parent 4f342b5
commit a8b2971
Show file tree

Hide file tree

Showing 7 changed files with 56 additions and 21 deletions.
diff --git a/...kka-runtime/src/main/scala/com/ing/baker/runtime/akka/actor/logging/LogAndSendEvent.scala b/...kka-runtime/src/main/scala/com/ing/baker/runtime/akka/actor/logging/LogAndSendEvent.scala
@@ -46,9 +46,14 @@ object LogAndSendEvent {
     bakerLogging.eventRejected(eventRejected)
   }
 
-  def firingEvent(recipeInstanceId: String, executionId: Long, transition: Transition, timeStarted: Long): Unit = {
+  def firingEvent(recipeInstanceId: String,
+                  recipeId: String,
+                  recipeName: String,
+                  executionId: Long,
+                  transition: Transition,
+                  timeStarted: Long): Unit = {
     //TODO This does not have a corrosponding BakerEvent, this should be created
-    bakerLogging.firingEvent(recipeInstanceId, executionId, transition, timeStarted)
+    bakerLogging.firingEvent(recipeInstanceId, recipeId, recipeName, executionId, transition, timeStarted)
   }
 
 }
diff --git a/...-runtime/src/main/scala/com/ing/baker/runtime/akka/actor/process_index/ProcessIndex.scala b/...-runtime/src/main/scala/com/ing/baker/runtime/akka/actor/process_index/ProcessIndex.scala
@@ -215,7 +215,7 @@ class ProcessIndex(recipeInstanceIdleTimeout: Option[FiniteDuration],
         BackoffOpts.onStop(
           ProcessInstance.props[RecipeInstanceState, EventInstance](
             compiledRecipe.name,
-            compiledRecipe.petriNet,
+            compiledRecipe,
             runtime,
             ProcessInstance.Settings(
               executionContext = bakerExecutionContext,

diff --git a/...me/src/main/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstance.scala b/...me/src/main/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstance.scala
@@ -6,7 +6,7 @@ import akka.event.{DiagnosticLoggingAdapter, Logging}
 import akka.persistence.{DeleteMessagesFailure, DeleteMessagesSuccess}
 import cats.effect.IO
 import com.ing.baker.il.petrinet.{EventTransition, InteractionTransition, Place, Transition}
-import com.ing.baker.il.{EventDescriptor, checkpointEventInteractionPrefix}
+import com.ing.baker.il.{CompiledRecipe, EventDescriptor, checkpointEventInteractionPrefix}
 import com.ing.baker.il.failurestrategy.{BlockInteraction, FireEventAfterFailure, InteractionFailureStrategy, RetryWithIncrementalBackoff}
 import com.ing.baker.petrinet.api._
 import com.ing.baker.runtime.akka.actor.process_index.ProcessIndexProtocol.FireSensoryEventRejection
@@ -53,13 +53,13 @@ object ProcessInstance {
       None
   }
 
-  def props[S, E](processType: String, petriNet: PetriNet,
+  def props[S, E](processType: String, compiledRecipe: CompiledRecipe,
                                                     runtime: ProcessInstanceRuntime[S, E],
                                                     settings: Settings,
                                                     delayedTransitionActor: ActorRef): Props =
     Props(new ProcessInstance[S, E](
       processType,
-      petriNet,
+      compiledRecipe,
       settings,
       runtime,
       delayedTransitionActor)
@@ -126,10 +126,10 @@ object ProcessInstance {
   */
 class ProcessInstance[S, E](
                                                                processType: String,
-                                                               petriNet: PetriNet,
+                                                               compiledRecipe: CompiledRecipe,
                                                                settings: Settings,
                                                                runtime: ProcessInstanceRuntime[S, E],
-                                                               delayedTransitionActor: ActorRef) extends ProcessInstanceEventSourcing[S, E](petriNet, settings.encryption, runtime.eventSource) {
+                                                               delayedTransitionActor: ActorRef) extends ProcessInstanceEventSourcing[S, E](compiledRecipe.petriNet, settings.encryption, runtime.eventSource) {
 
   import context.dispatcher
 
@@ -301,7 +301,7 @@ class ProcessInstance[S, E](
     case event@TransitionFiredEvent(jobId, transitionId, correlationId, timeStarted, timeCompleted, consumed, produced, output) =>
 
       val transition = instance.petriNet.transitions.getById(transitionId)
-      log.transitionFired(recipeInstanceId, transition.asInstanceOf[Transition], jobId, timeStarted, timeCompleted)
+      log.transitionFired(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, transition, jobId, timeStarted, timeCompleted)
       // persist the success event
       persistEvent(instance, event)(
         eventSource.apply(instance)
@@ -340,7 +340,7 @@ class ProcessInstance[S, E](
         ).marshall
         val internalEvent = ProcessInstanceEventSourcing.DelayedTransitionFired(jobId, transitionId, produced, out)
 
-        log.transitionFired(recipeInstanceId, transition.asInstanceOf[Transition], jobId, System.currentTimeMillis(), System.currentTimeMillis())
+        log.transitionFired(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, transition.asInstanceOf[Transition], jobId, System.currentTimeMillis(), System.currentTimeMillis())
 
         persistEvent(instance, internalEvent)(
           eventSource.apply(instance)
@@ -369,7 +369,7 @@ class ProcessInstance[S, E](
 
       val transition = instance.petriNet.transitions.getById(transitionId)
 
-      log.transitionFailed(recipeInstanceId, transition.asInstanceOf[Transition], jobId, timeStarted, timeFailed, reason)
+      log.transitionFailed(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, transition.asInstanceOf[Transition], jobId, timeStarted, timeFailed, reason)
 
       strategy match {
         case RetryWithDelay(delay) =>
@@ -437,7 +437,7 @@ class ProcessInstance[S, E](
               context become running(updatedInstance, scheduledRetries)
             case (_, Left(reason)) =>
 
-              log.fireTransitionRejected(recipeInstanceId, transition.asInstanceOf[Transition], reason)
+              log.fireTransitionRejected(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, transition.asInstanceOf[Transition], reason)
 
               sender() ! FireSensoryEventRejection.FiringLimitMet(recipeInstanceId)
           }
@@ -552,10 +552,10 @@ class ProcessInstance[S, E](
   }
 
   def executeJob(job: Job[S], originalSender: ActorRef): Unit = {
-    log.fireTransition(recipeInstanceId, job.id, job.transition.asInstanceOf[Transition], System.currentTimeMillis())
+    log.fireTransition(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, job.id, job.transition.asInstanceOf[Transition], System.currentTimeMillis())
     job.transition match {
       case _: EventTransition =>
-        BakerLogging.default.firingEvent(recipeInstanceId, job.id, job.transition.asInstanceOf[Transition], System.currentTimeMillis())
+        BakerLogging.default.firingEvent(recipeInstanceId, compiledRecipe.recipeId, compiledRecipe.name, job.id, job.transition.asInstanceOf[Transition], System.currentTimeMillis())
         executeJobViaExecutor(job, originalSender)
       case i: InteractionTransition if isDelayedInteraction(i) =>
         startDelayedTransition(i, job, originalSender)

diff --git a/.../main/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstanceLogger.scala b/.../main/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstanceLogger.scala
@@ -51,11 +51,18 @@ object ProcessInstanceLogger {
       log.errorWithMDC(msg, mdc, cause)
     }
 
-    def fireTransition(recipeInstanceId: String, jobId: Long, transition: Transition, timeStarted: Long): Unit = {
+    def fireTransition(recipeInstanceId: String,
+                       recipeId: String,
+                       recipeName: String,
+                       jobId: Long,
+                       transition: Transition,
+                       timeStarted: Long): Unit = {
       val mdc = Map(
         "processEvent" -> "FiringTransition",
         "processId" -> recipeInstanceId,
         "recipeInstanceId" -> recipeInstanceId,
+        "recipeName" -> recipeName,
+        "recipeId" -> recipeId,
         "jobId" -> jobId,
         "transitionId" -> transition.label,
         "timeStarted" -> timeStarted
@@ -65,6 +72,8 @@ object ProcessInstanceLogger {
     }
 
     def transitionFired(recipeInstanceId: String,
+                        recipeId: String,
+                        recipeName: String,
                         transition: Transition,
                         jobId: Long,
                         timeStarted: Long,
@@ -73,6 +82,8 @@ object ProcessInstanceLogger {
       val mdc = Map(
         "processEvent" -> "TransitionFired",
         "processId" -> recipeInstanceId,
+        "recipeName" -> recipeName,
+        "recipeId" -> recipeId,
         "recipeInstanceId" -> recipeInstanceId,
         "jobId" -> jobId,
         "transitionId" -> transition.label,
@@ -86,6 +97,8 @@ object ProcessInstanceLogger {
     }
 
     def transitionFailed(recipeInstanceId: String,
+                         recipeId: String,
+                         recipeName: String,
                          transition: Transition,
                          jobId: Long,
                          timeStarted: Long,
@@ -95,6 +108,8 @@ object ProcessInstanceLogger {
         "processEvent" -> "TransitionFailed",
         "processId" -> recipeInstanceId,
         "recipeInstanceId" -> recipeInstanceId,
+        "recipeName" -> recipeName,
+        "recipeId" -> recipeId,
         "jobId" -> jobId,
         "timeStarted" -> timeStarted,
         "timeFailed" -> timeFailed,
@@ -107,10 +122,16 @@ object ProcessInstanceLogger {
       log.logWithMDC(Logging.ErrorLevel, msg, mdc)
     }
 
-    def fireTransitionRejected(recipeInstanceId: String, transition: Transition, rejectReason: String): Unit = {
+    def fireTransitionRejected(recipeInstanceId: String,
+                               recipeId: String,
+                               recipeName: String,
+                               transition: Transition,
+                               rejectReason: String): Unit = {
       val mdc = Map(
         "processEvent" -> "FireTransitionRejected",
         "recipeInstanceEvent" -> "FireInteractionRejected",
+        "recipeName" -> recipeName,
+        "recipeId" -> recipeId,
         "processId" -> recipeInstanceId,
         "recipeInstanceId" -> recipeInstanceId,
         "transitionId" -> transition.label,

diff --git a/...rc/test/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstanceSpec.scala b/...rc/test/scala/com/ing/baker/runtime/akka/actor/process_instance/ProcessInstanceSpec.scala
@@ -4,7 +4,7 @@ import akka.actor.{ActorRef, ActorSystem, PoisonPill, Props, Terminated}
 import akka.event.DiagnosticLoggingAdapter
 import akka.testkit.{TestDuration, TestProbe}
 import akka.util.Timeout
-import com.ing.baker.il.{EventDescriptor, IngredientDescriptor}
+import com.ing.baker.il.{CompiledRecipe, EventDescriptor, IngredientDescriptor}
 import com.ing.baker.il.failurestrategy.{BlockInteraction, FireEventAfterFailure, InteractionFailureStrategy, RetryWithIncrementalBackoff}
 import com.ing.baker.il.petrinet.{InteractionTransition, Place}
 import com.ing.baker.petrinet.api._
@@ -78,7 +78,7 @@ object ProcessInstanceSpec {
                                   delayedTransitionActor: ActorRef): Props = {
     Props(new ProcessInstance[S, E](
       "test",
-      topology,
+      CompiledRecipe("name", UUID.randomUUID().toString, topology, Marking.empty, Seq.empty, Option.empty, Option.empty),
       settings,
       runtime,
       delayedTransitionActor)

diff --git a/core/baker-interface/src/main/scala/com/ing/baker/runtime/model/BakerLogging.scala b/core/baker-interface/src/main/scala/com/ing/baker/runtime/model/BakerLogging.scala
@@ -75,7 +75,9 @@ case class BakerLogging(logger: Logger = BakerLogging.defaultLogger) {
       "recipeInstanceId" -> interactionCompleted.recipeInstanceId,
       "interactionName" -> interactionCompleted.interactionName,
       "duration" -> interactionCompleted.duration.toString,
-      "timeFinished" -> interactionCompleted.timeStamp.toString
+      "timeFinished" -> interactionCompleted.timeStamp.toString,
+      "recipeId" -> interactionCompleted.recipeId,
+      "recipeName" -> interactionCompleted.recipeName
     )
     withMDC(mdc, _.info(msg))
   }
@@ -94,10 +96,17 @@ case class BakerLogging(logger: Logger = BakerLogging.defaultLogger) {
     withMDC(mdc, _.error(msg, interactionFailed.throwable))
   }
 
-  def firingEvent(recipeInstanceId: String, executionId: Long, transition: Transition, timeStarted: Long): Unit = {
+  def firingEvent(recipeInstanceId: String,
+                  recipeId: String,
+                  recipeName: String,
+                  executionId: Long,
+                  transition: Transition,
+                  timeStarted: Long): Unit = {
     val msg = s"Firing event '${transition.label}'"
     val mdc = Map(
       "recipeInstanceId" -> recipeInstanceId,
+      "recipeId" -> recipeId,
+      "recipeName" -> recipeName,
       "eventName" -> transition.label,
       "runtimeTimestamp" -> timeStarted.toString,
       "executionId" -> executionId.toString

diff --git a/...rface/src/main/scala/com/ing/baker/runtime/model/recipeinstance/TransitionExecution.scala b/...rface/src/main/scala/com/ing/baker/runtime/model/recipeinstance/TransitionExecution.scala
@@ -101,7 +101,7 @@ private[recipeinstance] case class TransitionExecution(
           case _: EventTransition =>
               for {
                 timerstamp <- timer.clock.realTime(MILLISECONDS)
-                _ <- effect.delay(components.logging.firingEvent(recipeInstanceId, id, transition, timerstamp))
+                _ <- effect.delay(components.logging.firingEvent(recipeInstanceId, "UNKNOWN", "UNKNOWN", id, transition, timerstamp))
               } yield input
           case _ =>
             effect.pure(None)