NO-JIRA: add more and better logging (#200)

src/main/scala/nl.knaw.dans.easy.deposit/AgreementGenerator.scala

@@ -35,7 +35,7 @@ case class AgreementGenerator(http: BaseHttp,
                              ) extends DebugEnhancedLogging {
   def generate(agreementData: AgreementData, id: UUID): Try[Array[Byte]] = Try {
     val json = toJson(agreementData)
-    logger.info(s"[$id] calling easy-deposit-agreement-generator with body $json")
+    logger.info(s"[$id] calling easy-deposit-agreement-generator")
 
     http(url.toString)
       .timeout(connectionTimeoutMs, readTimeoutMs)

src/main/scala/nl.knaw.dans.easy.deposit/EasyDepositApiApp.scala

@@ -255,8 +255,8 @@ class EasyDepositApiApp(configuration: Configuration) extends DebugEnhancedLoggi
       stateManager <- deposit.getStateManager(submitBase, easyHome)
       oldStateInfo <- stateManager.getStateInfo
       _ <- stateManager.canChangeState(oldStateInfo, newStateInfo)
-        .doIfSuccess { _ => logger.info(s"[$id] state change from $oldStateInfo to $newStateInfo is allowed") }
-        .doIfFailure { case _ => logger.info(s"[$id] state change from $oldStateInfo to $newStateInfo is not allowed") }
+        .doIfSuccess { _ => logger.info(s"[$id] state change from ${ oldStateInfo.state } to ${ newStateInfo.state } is allowed") }
+        .doIfFailure { case _ => logger.info(s"[$id] state change from ${ oldStateInfo.state } to ${ newStateInfo.state } is not allowed") }
       _ <- if (newStateInfo.state == State.submitted)
              submit(deposit, stateManager) // also changes the state
            else stateManager.changeState(oldStateInfo, newStateInfo)
@@ -438,7 +438,7 @@ class EasyDepositApiApp(configuration: Configuration) extends DebugEnhancedLoggi
       deposit <- DepositDir.get(draftBase, userId, id)
       dataFiles <- deposit.getDataFiles
       disposableStagingDir <- getStagedDir(userId, id)
-    } yield (disposableStagingDir, StagedFilesTarget(dataFiles.bag, destination))
+    } yield (disposableStagingDir, StagedFilesTarget(id, dataFiles.bag, destination))
   }
 
   // the temporary directory is dropped when the disposable resource is released on completion of the request

src/main/scala/nl.knaw.dans.easy.deposit/Errors.scala

@@ -39,7 +39,11 @@ object Errors extends DebugEnhancedLogging {
     extends FileAlreadyExistsException(
       s"Staging area [$dir] should be empty unless a forced shutdown occurred during an upload/submit request." +
         " Directories containing bags are aborted submits, somehow (allow) resubmit if indeed not in fedora." +
-        " Other directories contain files of uploads that are not yet moved into the bag."
+        " Other directories contain files of uploads that are not yet moved into the bag." +
+        " Please consult the logs on what happened in this situation, which steps of the processing of staged" +
+        " deposits has already been completed and which steps still need to be done. These latter steps need to" +
+        " be performed manually before restarting this service. Don't delete data from this staging without careful" +
+        " consideration!"
     )
 
   abstract sealed class ServletResponseException(status: Int, httpResponseBody: String)

src/main/scala/nl.knaw.dans.easy.deposit/PidRequester.scala

@@ -37,7 +37,7 @@ class PidRequester(http: BaseHttp, uri: URI) extends DebugEnhancedLogging {
       .asString
   } flatMap {
     case HttpResponse(body, CREATED_201, _) =>
-      logger.info(s"[$id] agreement generated successfully")
+      logger.info(s"[$id] pid generated successfully: '$body'")
       Success(body)
     case HttpResponse(body, code, _) =>
       logger.info(s"[$id] PID generator failed with code $code and body $body")

src/main/scala/nl.knaw.dans.easy.deposit/StagedFilesTarget.scala

@@ -16,6 +16,7 @@
 package nl.knaw.dans.easy.deposit
 
 import java.nio.file.Path
+import java.util.UUID
 
 import better.files.File
 import nl.knaw.dans.bag.DansBag
@@ -28,7 +29,7 @@ import scala.util.{ Success, Try }
  * @param draftBag    the bag that receives the staged files as payload
  * @param destination relative location in the bag's data directory
  */
-case class StagedFilesTarget(draftBag: DansBag, destination: Path) extends DebugEnhancedLogging {
+case class StagedFilesTarget(id: UUID, draftBag: DansBag, destination: Path) extends DebugEnhancedLogging {
 
   /**
    * Moves files from stagingDir to draftBag, after deleting each file in the bag as soon as it would be overwritten.
@@ -44,10 +45,15 @@ case class StagedFilesTarget(draftBag: DansBag, destination: Path) extends Debug
       )
 
     def cleanUp(bagRelativePath: Path) = {
-      if ((draftBag.data / bagRelativePath.toString).exists)
+      val oldFile = draftBag.data / bagRelativePath.toString
+      if (oldFile.exists) {
+        logger.info(s"[$id] removing payload file $bagRelativePath to be replaced by the newly uploaded file")
         draftBag.removePayloadFile(bagRelativePath)
-      else if (fetchFiles.contains(bagRelativePath))
-             draftBag.removeFetchItem(bagRelativePath)
+      }
+      else if (fetchFiles.contains(bagRelativePath)) {
+        logger.info(s"[$id] removing fetch file $bagRelativePath to be replaced by the newly uploaded file")
+        draftBag.removeFetchItem(bagRelativePath)
+      }
       else Success(())
     }
 
@@ -57,6 +63,7 @@ case class StagedFilesTarget(draftBag: DansBag, destination: Path) extends Debug
         val bagRelativePath = destination.resolve(stagingDir.relativize(stagedFile))
         for {
           _ <- cleanUp(bagRelativePath)
+          _ = logger.info(s"[$id] moving uploaded files in $stagingDir to bag payload ${ draftBag.data }")
           _ <- draftBag.addPayloadFile(stagedFile, bagRelativePath)(ATOMIC_MOVE)
         } yield ()
       }.failFastOr(draftBag.save)

src/main/scala/nl.knaw.dans.easy.deposit/StateManager.scala

@@ -46,7 +46,7 @@ case class StateManager(draftDeposit: DepositDir, submitBase: File, easyHome: UR
   private lazy val submittedProps = getProp(bagIdKey, draftProps)
     .map(submittedId => {
       val submitDepositPropsFile = submitBase / submittedId / "deposit.properties"
-      
+
       // It is not certain that `submitDepositPropsFile` exists at the time of reading this parameter.
       // Given that the submit is done asynchronously, it is possible that the next request
       //   (e.g. deposit listing) is done before the deposit is moved to `submitBase`.
@@ -100,7 +100,7 @@ case class StateManager(draftDeposit: DepositDir, submitBase: File, easyHome: UR
   }
 
   def changeState(oldStateInfo: StateInfo, newStateInfo: StateInfo): Try[Unit] = {
-    logger.info(s"[${ draftDeposit.id }] changing deposit state from $oldStateInfo to $newStateInfo")
+    logger.info(s"[${ draftDeposit.id }] changing deposit state from ${ oldStateInfo.state } to ${ newStateInfo.state } with description ${ newStateInfo.stateDescription }")
 
     // getStateInfo has been called by canChangeState, but it is not an IO action
     // so let's keep it simple without optimisation

src/main/scala/nl.knaw.dans.easy.deposit/SubmitJob.scala

@@ -26,22 +26,20 @@ import better.files.File.{ CopyOptions, VisitOptions }
 import nl.knaw.dans.bag.ChecksumAlgorithm.ChecksumAlgorithm
 import nl.knaw.dans.bag.DansBag
 import nl.knaw.dans.bag.v0.DansV0Bag
-import nl.knaw.dans.easy.deposit.Errors.AlreadySubmittedException
-import nl.knaw.dans.easy.deposit.docs.StateInfo.State
-import nl.knaw.dans.easy.deposit.docs.{ AgreementData, StateInfo }
+import nl.knaw.dans.easy.deposit.docs.AgreementData
 import nl.knaw.dans.lib.error._
 import nl.knaw.dans.lib.logging.DebugEnhancedLogging
 
 import scala.collection.JavaConverters._
 import scala.util.control.NonFatal
 import scala.util.{ Failure, Success, Try }
 
-class SubmitJob(depositId: UUID,
+class SubmitJob(draftDepositId: UUID,
                 depositUiURL: String,
                 groupPrincipal: GroupPrincipal,
                 fileLimit: Int,
                 draftBag: DansBag,
-                stagedDir: File,
+                stagedDepositDir: File,
                 submitDir: File,
                 datasetXml: String,
                 filesXml: String,
@@ -57,66 +55,68 @@ class SubmitJob(depositId: UUID,
   private val depositorInfoDirectoryName = "depositor-info"
 
   override def run(): Unit = {
-    logger.info(s"[$depositId] starting the dispatched submit action")
+    logger.info(s"[$draftDepositId] starting the dispatched submit action")
 
     submitDeposit() match {
       case Failure(e) =>
-        logger.error(s"[$depositId] error in dispatched submit action ${ this.toString }", e)
+        logger.error(s"[$draftDepositId] error in dispatched submit action ${ this.toString }", e)
         draftDepositStateManager.setStateFailed(e.getMessage)
-          .doIfFailure { case e => logger.error(s"[$depositId] could not set state to FAILED after submission failed", e) }
+          .doIfFailure { case e => logger.error(s"[$draftDepositId] could not set state to FAILED after submission failed", e) }
       case Success(()) =>
         sendEmail
-          .doIfSuccess(_ => logger.info(s"[$depositId] finished with dispatched submit action"))
-          .doIfFailure { case e => logger.error(s"[$depositId] deposit submitted but could not send confirmation message", e) }
+          .doIfSuccess(_ => logger.info(s"[$draftDepositId] finished with dispatched submit action"))
+          .doIfFailure { case e => logger.error(s"[$draftDepositId] deposit submitted but could not send confirmation message", e) }
     }
   }
 
   private def submitDeposit(): Try[Unit] = {
     val fullMsg4DataManager = {
-      val secondPart = s"The deposit can be found at $depositUiURL/$depositId"
+      val secondPart = s"The deposit can be found at $depositUiURL/$draftDepositId"
       msg4DataManager.fold(secondPart)(_ + "\n\n" + secondPart)
     }
-    logger.debug(s"Message for the datamanager:\n$fullMsg4DataManager")
+    logger.debug(s"[$draftDepositId] Message for the datamanager:\n$fullMsg4DataManager")
+
+    val stagedBagDir = stagedDepositDir / bagDirName
+    logger.info(s"[$draftDepositId] Created staged bag in ${ stagedBagDir }")
     for {
-      stageBag <- DansV0Bag.empty(stagedDir / bagDirName).map(_.withCreated())
-      _ = (draftBag.baseDir.parent / propsFileName).copyTo(stagedDir / propsFileName)
+      stageBag <- DansV0Bag.empty(stagedBagDir).map(_.withCreated())
+      _ = (draftBag.baseDir.parent / propsFileName).copyTo(stagedDepositDir / propsFileName)
+      _ = logger.info(s"[$draftDepositId] adding metadata to staged bag")
       _ <- stageBag.addMetadataFile(fullMsg4DataManager, s"$depositorInfoDirectoryName/message-from-depositor.txt")
       _ <- stageBag.addMetadataFile(agreementsXml, s"$depositorInfoDirectoryName/agreements.xml")
       _ <- stageBag.addMetadataFile(datasetXml, "dataset.xml")
       _ <- stageBag.addMetadataFile(filesXml, "files.xml")
-      _ = logger.info(s"[$depositId] copy ${ draftBag.data } to ${ stageBag.data }")
+      _ = logger.info(s"[$draftDepositId] copy payload to staged bag: ${ draftBag.data } to ${ stageBag.data }")
       _ <- stageBag.addPayloadFile(draftBag.data, Paths.get("."))
-      _ = logger.info(s"[$depositId] save changes to stageBag ${ stageBag.baseDir }")
+      _ = logger.info(s"[$draftDepositId] save (tag)manifests to staged bag")
       _ <- stageBag.save()
-      _ = logger.info(s"[$depositId] validate stageBag ${ stageBag.baseDir }")
+      _ = logger.info(s"[$draftDepositId] validate staged bag")
       _ <- isValid(stageBag)
-      _ = logger.info(s"[$depositId] compare payload manifests of stageBag and draftBag")
+      _ = logger.info(s"[$draftDepositId] compare payload manifests of draft bag and staged bag")
       _ <- samePayloadManifestEntries(stageBag, draftBag)
-      stageDepositDir = stageBag.baseDir.parent
-      _ = logger.info(s"[$depositId] set unix rights for $stageDepositDir")
-      _ <- setRightsRecursively(stageDepositDir)
-      _ = logger.info(s"[$depositId] move $stageDepositDir to $submitDir")
-      _ = stageDepositDir.moveTo(submitDir)(CopyOptions.atomically)
+      _ = logger.info(s"[$draftDepositId] set unix rights for $stagedDepositDir")
+      _ <- setRightsRecursively(stagedDepositDir)
+      _ = logger.info(s"[$draftDepositId] move $stagedDepositDir to $submitDir")
+      _ = stagedDepositDir.moveTo(submitDir)(CopyOptions.atomically)
     } yield ()
   }
 
   private def sendEmail: Try[Unit] = {
     for {
-      agreement <- agreementGenerator.generate(agreementData, depositId)
+      agreement <- agreementGenerator.generate(agreementData, draftDepositId)
       attachments = Map(
         Mailer.agreementFileName(agreementGenerator.acceptHeader) -> Some(Mailer.dataSource(agreement, agreementGenerator.acceptHeader)),
         Mailer.datasetXmlAttachmentName -> Some(Mailer.xmlDataSource(datasetXml)),
         Mailer.filesAttachmentName -> serializeManifest(draftBag, fileLimit).map(Mailer.txtDataSource),
       ).collect { case (key, Some(value)) => key -> value }
-      email <- mailer.buildMessage(agreementData, attachments, depositId, msg4DataManager)
-      _ = logger.info(s"[$depositId] send email")
+      email <- mailer.buildMessage(agreementData, attachments, draftDepositId, msg4DataManager)
+      _ = logger.info(s"[$draftDepositId] send email")
       messageId <- Try { email.sendMimeMessage }
-      _ = logger.info(s"[$depositId] sent email $messageId")
+      _ = logger.info(s"[$draftDepositId] sent email $messageId")
     } yield ()
   }
 
   private def serializeManifest(draftBag: DansBag, fileLimit: Int): Option[String] = {
-    debug("creating manifest")
     val entries = draftBag.payloadManifests.headOption.map(_._2).getOrElse(Map.empty)
     if (entries.size > fileLimit) None // all files or none avoids confusion
     else Some(entries.map { case (file, sha) => s"$sha ${ draftBag.data.relativize(file) }" }.mkString("\n"))
@@ -174,5 +174,5 @@ class SubmitJob(depositId: UUID,
     case NonFatal(e) => throw new IOException(s"unexpected error occured on $path", e)
   }
 
-  override def toString: String = s"<SubmitWorkerAction[id = $depositId, draftBag = ${ draftBag.baseDir }]>"
+  override def toString: String = s"<SubmitWorkerAction[id = $draftDepositId, draftBag = ${ draftBag.baseDir }, submitDir = $submitDir]>"
 }

src/main/scala/nl.knaw.dans.easy.deposit/Submitter.scala

@@ -72,15 +72,18 @@ class Submitter(submitToBaseDir: File,
       submittedId <- draftDepositStateManager.getSubmittedBagId // created by changeState
       submitDir = submitToBaseDir / submittedId.toString
       _ = if (submitDir.exists) throw AlreadySubmittedException(depositId)
-      _ = logger.info(s"[$depositId] dispatching submit action to threadpool executor")
+      queueSize = jobQueue.getSystemStatus.queueSize
+      queueMsg = if (queueSize > 0) s"; currently ${ queueSize } jobs waiting to be processed"
+                 else ""
+      _ = logger.info(s"[$depositId] dispatching submit action to threadpool executor$queueMsg")
       _ <- jobQueue.scheduleJob {
         new SubmitJob(
-          depositId = draftDeposit.id,
+          draftDepositId = draftDeposit.id,
           depositUiURL = depositUiURL,
           groupPrincipal = groupPrincipal,
           fileLimit = fileLimit,
           draftBag = draftBag,
-          stagedDir = stagedDir,
+          stagedDepositDir = stagedDir,
           submitDir = submitDir,
           datasetXml = datasetXml,
           filesXml = filesXml,

src/main/scala/nl.knaw.dans.easy.deposit/authentication/AuthenticationSupport.scala

@@ -63,7 +63,7 @@ trait AuthenticationSupport extends ScentrySupport[AuthUser] {
       httpOnly = true // JavaScript can't get the cookie
       // version = 0 // obsolete? https://stackoverflow.com/questions/29124177/recommended-set-cookie-version-used-by-web-servers-0-1-or-2#29143128
     )
-    logger.debug(s"authCookieOptions: $cookieConfig")
+    logger.trace(s"authCookieOptions: $cookieConfig")
     scentry.store = new CookieAuthStore(self)(cookieConfig)
   }
 

src/main/scala/nl.knaw.dans.easy.deposit/servlets/DepositServlet.scala

@@ -24,6 +24,7 @@ import nl.knaw.dans.easy.deposit.EasyDepositApiApp
 import nl.knaw.dans.easy.deposit.Errors._
 import nl.knaw.dans.easy.deposit.docs.JsonUtil.toJson
 import nl.knaw.dans.easy.deposit.docs.{ DatasetMetadata, StateInfo }
+import nl.knaw.dans.lib.string._
 import org.scalatra._
 import org.scalatra.servlet.{ FileUploadSupport, SizeConstraintExceededException }
 import org.scalatra.util.RicherString._
@@ -111,7 +112,9 @@ class DepositServlet(app: EasyDepositApiApp)
         _ = logger.info(s"[$uuid] saving metadata")
         managedIS = managed(request.getInputStream)
         datasetMetadata <- managedIS.apply(is => DatasetMetadata(is))
+        _ = logger.debug(s"[$uuid] comparing DOI in deposit.properties and newly uploaded dataset metadata")
         _ <- app.checkDoi(user.id, uuid, datasetMetadata)
+        _ = logger.debug(s"[$uuid] writing newly uploaded dataset metadata to deposit")
         _ <- app.writeDataMetadataToDeposit(datasetMetadata, user.id, uuid)
       } yield NoContent()
     }.getOrRecoverWithActionResult
@@ -131,7 +134,7 @@ class DepositServlet(app: EasyDepositApiApp)
         uuid <- getUUID
         managedIS = managed(request.getInputStream)
         stateInfo <- managedIS.apply(is => StateInfo(is))
-        _ = logger.info(s"[$uuid] changing state to $stateInfo")
+        _ = logger.info(s"[$uuid] changing state to ${ stateInfo.state } with description ${ stateInfo.stateDescription }")
         _ <- app.setDepositState(stateInfo, user.id, uuid)
       } yield NoContent()
     }.getOrRecoverWithActionResult
@@ -150,7 +153,7 @@ class DepositServlet(app: EasyDepositApiApp)
       for {
         uuid <- getUUID
         path <- getPath
-        _ = logger.info(s"[$uuid] retrieve file info for path $path")
+        _ = logger.info(s"[$uuid] retrieve file info for path '${ path.toString.toOption.getOrElse("/") }'")
         contents <- app.getFileInfo(user.id, uuid, path)
       } yield Ok(body = toJson(contents), headers = Map(contentTypeJson))
     }.getOrRecoverWithActionResult
@@ -160,7 +163,7 @@ class DepositServlet(app: EasyDepositApiApp)
       for {
         uuid <- getUUID
         path <- getPath
-        _ = logger.info(s"[$uuid] upload file to path $path")
+        _ = logger.info(s"[$uuid] upload file to path '${ path.toString.toOption.getOrElse("/") }'")
         _ <- isMultipart
         fileItems = fileMultiParams.valuesIterator.flatten.buffered
         maybeManagedArchiveInputStream <- fileItems.nextAsArchiveIfOnlyOne
@@ -180,7 +183,7 @@ class DepositServlet(app: EasyDepositApiApp)
       for {
         uuid <- getUUID
         path <- getPath
-        _ = logger.info(s"[$uuid] upload file to path $path")
+        _ = logger.info(s"[$uuid] upload file to path '${ path.toString.toOption.getOrElse("/") }'")
         managedIS = managed(request.getInputStream)
         newFileWasCreated <- managedIS.apply(app.writeDepositFile(_, user.id, uuid, path, Option(request.getContentType)))
         _ = logger.info(s"[$uuid] ${if (newFileWasCreated) "no " else ""}new file was created")
@@ -194,7 +197,7 @@ class DepositServlet(app: EasyDepositApiApp)
       for {
         uuid <- getUUID
         path <- getPath
-        _ = logger.info(s"[$uuid] deleting file $path")
+        _ = logger.info(s"[$uuid] deleting file ${ path.toString.toOption.getOrElse("/") }")
         _ <- app.deleteDepositFile(user.id, uuid, path)
       } yield NoContent()
     }.getOrRecoverWithActionResult