AN-522 Add temporary logging around token distribution (#7741)

Author: jgainerdewar

engine/src/main/scala/cromwell/engine/workflow/lifecycle/execution/job/EngineJobExecutionActor.scala

@@ -515,7 +515,7 @@ class EngineJobExecutionActor(replyTo: ActorRef,
   }
 
   onTransition { case fromState -> toState =>
-    jobLogger.info("Transitioning from {}({}) to {}({})", fromState, stateData, toState, nextStateData)
+    jobLogger.debug("Transitioning from {}({}) to {}({})", fromState, stateData, toState, nextStateData)
 
     EngineJobExecutionActorState.transitionEventString(fromState, toState) foreach {
       eventList :+= ExecutionEvent(_)
@@ -548,11 +548,8 @@ class EngineJobExecutionActor(replyTo: ActorRef,
       // due to timeouts). That's ok, we just ignore this message in any other situation:
       stay()
     case Event(msg, _) =>
-      log.error("Bad message from {} to EngineJobExecutionActor in state {}(with data {}): {}",
-                sender(),
-                stateName,
-                stateData,
-                msg
+      jobLogger.error(
+        s"Bad message from ${sender()} to EngineJobExecutionActor in state ${stateName}(with data ${stateData}): ${msg}"
       )
       stay()
   }
@@ -623,15 +620,23 @@ class EngineJobExecutionActor(replyTo: ActorRef,
     runJob(updatedData)
   }
 
-  private def requestRestartCheckToken(): Unit =
+  private def requestRestartCheckToken(): Unit = {
+    jobLogger.info(
+      s"EJEA ${self.toString().split('#').lastOption.getOrElse("ERR").stripSuffix("]")} is requesting restart token of type ${backendLifecycleActorFactory.jobExecutionTokenType} for ${workflowDescriptor.backendDescriptor.hogGroup}"
+    )
     jobRestartCheckTokenDispenserActor ! JobTokenRequest(workflowDescriptor.backendDescriptor.hogGroup,
                                                          backendLifecycleActorFactory.jobRestartCheckTokenType
     )
+  }
 
-  private def requestExecutionToken(): Unit =
+  private def requestExecutionToken(): Unit = {
+    jobLogger.info(
+      s"EJEA ${self.toString().split('#').lastOption.getOrElse("ERR").stripSuffix("]")} is requesting execution token of type ${backendLifecycleActorFactory.jobExecutionTokenType} for ${workflowDescriptor.backendDescriptor.hogGroup}"
+    )
     jobExecutionTokenDispenserActor ! JobTokenRequest(workflowDescriptor.backendDescriptor.hogGroup,
                                                       backendLifecycleActorFactory.jobExecutionTokenType
     )
+  }
 
   // Return any currently held job restart check or execution token.
   private def returnCurrentToken(): Unit = if (

engine/src/main/scala/cromwell/engine/workflow/tokens/JobTokenDispenserActor.scala

@@ -127,8 +127,13 @@ class JobTokenDispenserActor(override val serviceRegistryActor: ActorRef,
     count(tokensReturnedMetricPath, 0L, ServicesPrefix)
   }
 
-  private def enqueue(sndr: ActorRef, hogGroup: String, tokenType: JobTokenType): Unit =
+  private def enqueue(sndr: ActorRef, hogGroup: String, tokenType: JobTokenType): Unit = {
+    val senderId = sndr.toString().split('#').lastOption.getOrElse("ERR").stripSuffix("]")
+    log.info(
+      s"Enqueing request from ${senderId} for $dispenserType token of type $tokenType for $hogGroup"
+    )
     if (tokenAssignments.contains(sndr)) {
+      log.info(s"$senderId already assigned a token")
       sndr ! JobTokenDispensed
     } else {
       val queue = tokenQueues.getOrElse(tokenType, TokenQueue(tokenType, tokenEventLogger))
@@ -137,6 +142,7 @@ class JobTokenDispenserActor(override val serviceRegistryActor: ActorRef,
       increment(requestsEnqueuedMetricPath, ServicesPrefix)
       ()
     }
+  }
 
   private def checkAndDispenseTokens(n: Int): Unit =
     if (tokenQueues.nonEmpty) {
@@ -179,7 +185,9 @@ class JobTokenDispenserActor(override val serviceRegistryActor: ActorRef,
 
     if (nextTokens.nonEmpty) {
       val hogGroupCounts =
-        nextTokens.groupBy(t => t.queuePlaceholder.hogGroup).map { case (hogGroup, list) => s"$hogGroup: ${list.size}" }
+        nextTokens.groupBy(t => t.queuePlaceholder.hogGroup).map { case (hogGroup, list) =>
+          s"$hogGroup: ${list.size} (${list.map(_.actor.toString().split('#').lastOption.getOrElse("ERR").stripSuffix("]")).mkString(", ")})"
+        }
       log.info(s"Assigned new job $dispenserType tokens to the following groups: ${hogGroupCounts.mkString(", ")}")
     }