Merge pull request #447 from jluhrs/feature/SEQNG-451

SEQNG-451 Log error messages from failed actions.

modules/edu.gemini.seqexec.engine/src/main/scala/edu/gemini/seqexec/engine/Event.scala

@@ -38,7 +38,10 @@ object Event {
   def getSeqState(id: Sequence.Id, f: (Sequence.State) => Option[Process[Task, Event]]): Event = EventUser(GetSeqState(id, f))
   def actionStop(id: Sequence.Id, f: (Sequence.State) => Option[Process[Task, Event]]): Event = EventUser(ActionStop(id, f))
   def actionResume(id: Sequence.Id, i: Int, c: Task[Result]): Event = EventUser(ActionResume(id, i, c))
-  def logMsg(msg: String): Event = EventUser(Log(msg))
+  def logDebugMsg(msg: String): Event = EventUser(LogDebug(msg))
+  def logInfoMsg(msg: String): Event = EventUser(LogInfo(msg))
+  def logWarningMsg(msg: String): Event = EventUser(LogWarning(msg))
+  def logErrorMsg(msg: String): Event = EventUser(LogError(msg))
 
   def failed(id: Sequence.Id, i: Int, e: Result.Error): Event = EventSystem(Failed(id, i, e))
   def completed[R<:Result.RetVal](id: Sequence.Id, i: Int, r: Result.OK[R]): Event = EventSystem(Completed(id, i, r))

modules/edu.gemini.seqexec.engine/src/main/scala/edu/gemini/seqexec/engine/UserEvent.scala

@@ -64,6 +64,19 @@ final case class ActionResume(id: Sequence.Id, i: Int, cont: Task[Result]) exten
   val user: Option[UserDetails] = None
 }
 
-final case class Log(msg: String) extends UserEvent {
+final case class LogDebug(msg: String) extends UserEvent {
   val user: Option[UserDetails] = None
 }
+
+final case class LogInfo(msg: String) extends UserEvent {
+  val user: Option[UserDetails] = None
+}
+
+final case class LogWarning(msg: String) extends UserEvent {
+  val user: Option[UserDetails] = None
+}
+
+final case class LogError(msg: String) extends UserEvent {
+  val user: Option[UserDetails] = None
+}
+

modules/edu.gemini.seqexec.engine/src/main/scala/edu/gemini/seqexec/engine/package.scala

@@ -333,6 +333,8 @@ package object engine {
     modifyS(id)(_.mark(i)(e)) *>
       switch(id)(SequenceState.Failed(e.msg))
 
+  def logError(e: Result.Error): HandleP[Unit] = Logger.error(e.errMsg.getOrElse(e.msg))
+
   /**
     * Ask for the current Handle `Status`.
     */
@@ -358,6 +360,12 @@ package object engine {
       * Log debug lifted into Handle.
       */
     def debug(msg: => String): HandleP[Unit] = pure((logger.debug(msg), None)).void
+
+    /**
+      *  Log error lifted into Handle
+      */
+    def error(msg: => String): HandleP[Unit] = pure((logger.error(msg), None)).void
+
   }
 
   /**
@@ -389,15 +397,18 @@ package object engine {
       case GetSeqState(id, f)          => getSeqState(id, f)
       case ActionStop(id, f)           => Logger.debug("Engine: Action stop requested") *> actionStop(id, f)
       case ActionResume(id, i, cont)   => Logger.debug("Engine: Action resume requested") *> actionResume(id, i, cont)
-      case Log(msg)                    => Logger.debug(msg)
+      case LogDebug(msg)               => Logger.debug(msg)
+      case LogInfo(msg)                => Logger.info(msg)
+      case LogWarning(msg)             => Logger.warning(msg)
+      case LogError(msg)               => Logger.error(msg)
     }
 
     def handleSystemEvent(se: SystemEvent): HandleP[Unit] = se match {
       case Completed(id, i, r)     => Logger.debug("Engine: Action completed") *> complete(id, i, r)
       case PartialResult(id, i, r) => Logger.debug("Engine: Partial result") *> partialResult(id, i, r)
       case Paused(id, i, r)        => Logger.debug("Engine: Action paused")  *> actionPause(id, i, r)
-      case Failed(id, i, e)        => Logger.debug("Engine: Action failed") *> fail(id)(i, e)
-      case Busy(id)                => Logger.debug("Engine: Resources needed for this sequence are in use")
+      case Failed(id, i, e)        => logError(e) *> fail(id)(i, e)
+      case Busy(id)                => Logger.warning("Cannot run sequence %id because required systems are in use.")
       case BreakpointReached(id)   => Logger.debug("Engine: Breakpoint reached")
       case Executed(id)            => Logger.debug("Engine: Execution completed") *> next(id)
       case Executing(id)           => Logger.debug("Engine: Executing") *> execute(id)

modules/edu.gemini.seqexec.model/src/main/scala/edu/gemini/seqexec/model/ModelBooPicklers.scala

@@ -123,7 +123,6 @@ object ModelBooPicklers {
     .addConcreteType[SequencePaused]
     .addConcreteType[ExposurePaused]
     .addConcreteType[ResourcesBusy]
-    .addConcreteType[NewLogMessage]
     .addConcreteType[ServerLogMessage]
     .addConcreteType[NullEvent.type]
 

modules/edu.gemini.seqexec.model/src/test/scala/edu/gemini/seqexec/model/BoopicklingSpec.scala

@@ -90,10 +90,6 @@ class BoopicklingSpec extends FlatSpec with Matchers with PropertyChecks {
       // events
       testPickleUnpickle[ExposurePaused]
     }
-    it should "pickle/depickle NewLogMessage" in {
-      // events
-      testPickleUnpickle[NewLogMessage]
-    }
     it should "pickle/depickle SequencesQueue[SequenceId]" in {
       // events
       testPickleUnpickle[SequencesQueue[SequenceId]]

modules/edu.gemini.seqexec.model/src/test/scala/edu/gemini/seqexec/model/SharedModelArbitraries.scala

@@ -49,7 +49,6 @@ object SharedModelArbitraries {
   implicit val speArb = implicitly[Arbitrary[SequencePauseRequested]]
   implicit val spcArb = implicitly[Arbitrary[SequencePauseCanceled]]
   implicit val asrArb = implicitly[Arbitrary[ActionStopRequested]]
-  implicit val lmArb  = implicitly[Arbitrary[NewLogMessage]]
   implicit val slmArb = implicitly[Arbitrary[ServerLogMessage]]
   implicit val neArb  = implicitly[Arbitrary[NullEvent.type]]
   implicit val opArb  = implicitly[Arbitrary[OperatorUpdated]]

modules/edu.gemini.seqexec.server/src/main/scala/edu/gemini/seqexec/server/SeqTranslate.scala

@@ -238,7 +238,7 @@ class SeqTranslate(site: Site, systems: Systems, settings: Settings) {
     seqState,
     toInstrumentSys(seqState.toSequence.metadata.instrument).toOption.flatMap(_.observeControl match {
       case Controllable(StopObserveCmd(stop), _, _, _, _, _) => Some(Process.eval(stop.run.map{
-        case -\/(e) => Event.logMsg(SeqexecFailure.explain(e))
+        case -\/(e) => Event.logErrorMsg(SeqexecFailure.explain(e))
         case _      => Event.nullEvent
       }))
       case _                                                 => none
@@ -249,7 +249,7 @@ class SeqTranslate(site: Site, systems: Systems, settings: Settings) {
     seqState,
     toInstrumentSys(seqState.toSequence.metadata.instrument).toOption.flatMap(_.observeControl match {
       case Controllable(_, AbortObserveCmd(abort), _, _, _, _) => Some(Process.eval(abort.run.map{
-        case -\/(e) => Event.logMsg(SeqexecFailure.explain(e))
+        case -\/(e) => Event.logErrorMsg(SeqexecFailure.explain(e))
         case _      => Event.nullEvent
       }))
       case _                                                   => none
@@ -259,7 +259,7 @@ class SeqTranslate(site: Site, systems: Systems, settings: Settings) {
   def pauseObserve(seqState: Sequence.State): Option[Process[Task, Event]] = deliverObserveCmd( seqState,
     toInstrumentSys(seqState.toSequence.metadata.instrument).toOption.flatMap(_.observeControl match {
       case Controllable(_, _, PauseObserveCmd(pause), _, _, _) => Some(Process.eval(pause.run.map{
-        case -\/(e) => Event.logMsg(SeqexecFailure.explain(e))
+        case -\/(e) => Event.logErrorMsg(SeqexecFailure.explain(e))
         case _      => Event.nullEvent
       }))
       case _                                                   => none

modules/edu.gemini.seqexec.server/src/main/scala/edu/gemini/seqexec/server/SeqexecEngine.scala

@@ -179,8 +179,8 @@ class SeqexecEngine(settings: SeqexecEngine.Settings) {
     } yield translator.sequence(seqId, odbSeq)
 
     t.map {
-      case (err :: _, None)  => List(Event.logMsg(SeqexecFailure.explain(err)))
-      case (errs, Some(seq)) => Event.load(seqId.stringValue, seq) :: errs.map(e => Event.logMsg(SeqexecFailure.explain(e)))
+      case (err :: _, None)  => List(Event.logDebugMsg(SeqexecFailure.explain(err)))
+      case (errs, Some(seq)) => Event.load(seqId.stringValue, seq) :: errs.map(e => Event.logDebugMsg(SeqexecFailure.explain(e)))
       case _                 => Nil
     }
   }
@@ -207,7 +207,10 @@ class SeqexecEngine(settings: SeqexecEngine.Settings) {
       case engine.GetState(_)            => NullEvent
       case engine.GetSeqState(_, _)      => NullEvent
       case engine.ActionStop(_, _)       => ActionStopRequested(svs)
-      case engine.Log(msg)               => NewLogMessage(msg)
+      case engine.LogDebug(msg)          => NullEvent
+      case engine.LogInfo(msg)           => NullEvent
+      case engine.LogWarning(msg)        => NullEvent
+      case engine.LogError(msg)          => NullEvent
       case engine.ActionResume(_, _, _)  => SequenceUpdated(svs)
     }
     case engine.EventSystem(se) => se match {
@@ -255,13 +258,13 @@ class SeqexecEngine(settings: SeqexecEngine.Settings) {
     val seqexecList = st.sequences.keys.toSeq.map(v => new SPObservationID(v))
 
     def loads(odbList: Seq[SPObservationID]): Task[List[Event]] =
-      odbList.diff(seqexecList).toList.map(id => loadEvents(id)).sequenceU.map(_.flatten).run.map(_.valueOr( r => List(Event.logMsg(SeqexecFailure.explain(r)))))
+      odbList.diff(seqexecList).toList.map(id => loadEvents(id)).sequenceU.map(_.flatten).run.map(_.valueOr( r => List(Event.logDebugMsg(SeqexecFailure.explain(r)))))
 
     def unloads(odbList: Seq[SPObservationID]): Seq[Event] =
       seqexecList.diff(odbList).map(id => unloadEvent(id))
 
     val x = odbProxy.queuedSequences.flatMapF(seqs => loads(seqs).map(ee => (ee ++ unloads(seqs)).right)).run
-    val y = x.map(_.valueOr(r => List(Event.logMsg(SeqexecFailure.explain(r)))))
+    val y = x.map(_.valueOr(r => List(Event.logWarningMsg(SeqexecFailure.explain(r)))))
     y.map { ee => ee.nonEmpty option Process.emitAll(ee).evalMap(Task.delay(_)) }
   }