Remove some spammy logging from backend (#7039)

* Profile Proofreading Performance

* clean up logging, use alfu caching for data access requests

* WIP: test setup for inserting mapping from file

* log timings

* use jgrapht for connected components

* imports

* WIP: more caching

* WIP: use list versions to get newest version

* add list versions test route to debug fossildb perf

* remove superseded changes

* undo dev-only changes

app/models/user/time/TimeSpanService.scala

@@ -149,14 +149,8 @@ class TimeSpanService @Inject()(annotationDAO: AnnotationDAO,
       flushToDb(timeSpansToInsert, timeSpansToUpdate)(ctx)
     }
 
-  private def isNotInterrupted(current: Instant, last: TimeSpan) = {
-    val duration = current - last.lastUpdate
-    if (duration.toMillis < 0) {
-      logger.info(
-        s"Negative timespan duration $duration ms to previous entry. (user ${last._user}, last timespan id ${last._id}, this=$this)")
-    }
-    duration < conf.WebKnossos.User.timeTrackingPause
-  }
+  private def isNotInterrupted(current: Instant, last: TimeSpan) =
+    current - last.lastUpdate < conf.WebKnossos.User.timeTrackingPause
 
   private def belongsToSameTracing(last: TimeSpan, annotation: Option[Annotation]) =
     last._annotation.map(_.id) == annotation.map(_.id)

util/src/main/scala/com/scalableminds/util/io/PathUtils.scala

@@ -50,8 +50,11 @@ trait PathUtils extends LazyLogging {
     else
       None
 
-  def listDirectoryEntries[A](directory: Path, maxDepth: Int, dropCount: Int, filters: (Path => Boolean)*)(
-      f: Iterator[Path] => Box[A]): Box[A] =
+  def listDirectoryEntries[A](directory: Path,
+                              maxDepth: Int,
+                              dropCount: Int,
+                              silent: Boolean,
+                              filters: (Path => Boolean)*)(f: Iterator[Path] => Box[A]): Box[A] =
     try {
       val directoryStream = Files.walk(directory, maxDepth, FileVisitOption.FOLLOW_LINKS)
       val r = f(directoryStream.iterator().asScala.drop(dropCount).filter(d => filters.forall(_(d))))
@@ -60,36 +63,50 @@ trait PathUtils extends LazyLogging {
     } catch {
       case _: AccessDeniedException =>
         val errorMsg = s"Error access denied. Directory: ${directory.toAbsolutePath}"
-        logger.warn(errorMsg)
+        if (!silent) {
+          logger.warn(errorMsg)
+        }
         Failure(errorMsg)
       case _: NoSuchFileException =>
         val errorMsg = s"No such directory. Directory: ${directory.toAbsolutePath}"
-        logger.warn(errorMsg)
+        if (!silent) {
+          logger.warn(errorMsg)
+        }
         Failure(errorMsg)
       case ex: Exception =>
         val errorMsg =
           s"Error: ${ex.getClass.getCanonicalName} - ${ex.getMessage}. Directory: ${directory.toAbsolutePath}"
-        logger.warn(ex.getClass.getCanonicalName)
+        if (!silent) {
+          logger.warn(ex.getClass.getCanonicalName)
+        }
         Failure(errorMsg)
     }
 
-  def listDirectories(directory: Path, filters: (Path => Boolean)*): Box[List[Path]] =
-    listDirectoryEntries(directory, 1, 1, filters :+ directoryFilter _: _*)(r => Full(r.toList))
+  def listDirectories(directory: Path, silent: Boolean, filters: (Path => Boolean)*): Box[List[Path]] =
+    listDirectoryEntries(directory, 1, 1, silent, filters :+ directoryFilter _: _*)(r => Full(r.toList))
 
-  def listDirectoriesRecursive(directory: Path, maxDepth: Int, filters: (Path => Boolean)*): Box[List[Path]] =
-    listDirectoryEntries(directory, maxDepth, 0, filters :+ directoryFilter _: _*)(r => Full(r.toList))
+  def listDirectoriesRecursive(directory: Path,
+                               silent: Boolean,
+                               maxDepth: Int,
+                               filters: (Path => Boolean)*): Box[List[Path]] =
+    listDirectoryEntries(directory, maxDepth, 0, silent, filters :+ directoryFilter _: _*)(r => Full(r.toList))
 
-  def listFiles(directory: Path, filters: (Path => Boolean)*): Box[List[Path]] =
-    listDirectoryEntries(directory, 1, 1, filters :+ fileFilter _: _*)(r => Full(r.toList))
+  def listFiles(directory: Path, silent: Boolean, filters: (Path => Boolean)*): Box[List[Path]] =
+    listDirectoryEntries(directory, 1, 1, silent, filters :+ fileFilter _: _*)(r => Full(r.toList))
 
-  def listFilesRecursive(directory: Path, maxDepth: Int, filters: (Path => Boolean)*): Box[List[Path]] =
-    listDirectoryEntries(directory, maxDepth, 1, filters :+ fileFilter _: _*)(r => Full(r.toList))
+  def listFilesRecursive(directory: Path,
+                         silent: Boolean,
+                         maxDepth: Int,
+                         filters: (Path => Boolean)*): Box[List[Path]] =
+    listDirectoryEntries(directory, maxDepth, 1, silent, filters :+ fileFilter _: _*)(r => Full(r.toList))
 
-  def lazyFileStream[A](directory: Path, filters: (Path => Boolean)*)(f: Iterator[Path] => Box[A]): Box[A] =
-    listDirectoryEntries(directory, 1, 1, filters :+ fileFilter _: _*)(f)
+  def lazyFileStream[A](directory: Path, silent: Boolean, filters: (Path => Boolean)*)(
+      f: Iterator[Path] => Box[A]): Box[A] =
+    listDirectoryEntries(directory, 1, 1, silent, filters :+ fileFilter _: _*)(f)
 
-  def lazyFileStreamRecursive[A](directory: Path, filters: (Path => Boolean)*)(f: Iterator[Path] => Box[A]): Box[A] =
-    listDirectoryEntries(directory, Int.MaxValue, 1, filters :+ fileFilter _: _*)(f)
+  def lazyFileStreamRecursive[A](directory: Path, silent: Boolean, filters: (Path => Boolean)*)(
+      f: Iterator[Path] => Box[A]): Box[A] =
+    listDirectoryEntries(directory, Int.MaxValue, 1, silent, filters :+ fileFilter _: _*)(f)
 
   def ensureDirectory(path: Path): Path = {
     if (!Files.exists(path) || !Files.isDirectory(path))

webknossos-datastore/app/com/scalableminds/webknossos/datastore/dataformats/MappingProvider.scala

@@ -32,6 +32,7 @@ object MappingProvider {
   def exploreMappings(layerDir: Path): Option[Set[String]] = {
     val mappingSet = PathUtils
       .listFiles(layerDir.resolve(MappingProvider.mappingsDir),
+                 silent = true,
                  PathUtils.fileExtensionFilter(MappingProvider.mappingFileExtension))
       .map { paths =>
         paths.map(path => FilenameUtils.removeExtension(path.getFileName.toString))

webknossos-datastore/app/com/scalableminds/webknossos/datastore/dataformats/wkw/WKWDataFormat.scala

@@ -59,7 +59,7 @@ object WKWDataFormat extends DataSourceImporter with WKWDataFormatHelper {
 
   private def exploreResolutions(baseDir: Path)(
       implicit report: DataSourceImportReport[Path]): Box[List[(WKWHeader, Vec3Int)]] =
-    PathUtils.listDirectories(baseDir, magDirFilter).flatMap { resolutionDirs =>
+    PathUtils.listDirectories(baseDir, silent = false, magDirFilter).flatMap { resolutionDirs =>
       val resolutionHeaders = resolutionDirs.sortBy(magDirSortingKey).map { resolutionDir =>
         val resolution = magFromPath(resolutionDir).get
         WKWHeader(resolutionDir.resolve(FILENAME_HEADER_WKW).toFile).map { header =>
@@ -110,16 +110,16 @@ object WKWDataFormat extends DataSourceImporter with WKWDataFormatHelper {
       multiplierY = resolution.cubeLength * resolution.resolution.y
       multiplierZ = resolution.cubeLength * resolution.resolution.z
 
-      resolutionDirs <- PathUtils.listDirectories(baseDir, filterGen(""))
+      resolutionDirs <- PathUtils.listDirectories(baseDir, silent = false, filterGen(""))
       resolutionDir <- resolveHead(baseDir, resolutionDirs.sortBy(magDirSortingKey))
 
-      zDirs <- PathUtils.listDirectories(resolutionDir, filterGen("z"))
+      zDirs <- PathUtils.listDirectories(resolutionDir, silent = false, filterGen("z"))
       zHeadDir <- resolveHead(resolutionDir, zDirs)
 
-      yDirs <- PathUtils.listDirectories(zHeadDir, filterGen("y"))
+      yDirs <- PathUtils.listDirectories(zHeadDir, silent = false, filterGen("y"))
       yHeadDir <- resolveHead(zHeadDir, yDirs)
 
-      xFiles <- PathUtils.listFiles(yHeadDir, filterGen("x"))
+      xFiles <- PathUtils.listFiles(yHeadDir, silent = false, filterGen("x"))
       xFile <- xFiles.headOption
 
       (zMin, zMax) = zDirs.foldRight((getIntFromFilePath(zHeadDir), 0))(minMaxValue)

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/AgglomerateService.scala

@@ -31,7 +31,9 @@ class AgglomerateService @Inject()(config: DataStoreConfig) extends DataConverte
   def exploreAgglomerates(organizationName: String, dataSetName: String, dataLayerName: String): Set[String] = {
     val layerDir = dataBaseDir.resolve(organizationName).resolve(dataSetName).resolve(dataLayerName)
     PathUtils
-      .listFiles(layerDir.resolve(agglomerateDir), PathUtils.fileExtensionFilter(agglomerateFileExtension))
+      .listFiles(layerDir.resolve(agglomerateDir),
+                 silent = true,
+                 PathUtils.fileExtensionFilter(agglomerateFileExtension))
       .map { paths =>
         paths.map(path => FilenameUtils.removeExtension(path.getFileName.toString))
       }

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/ConnectomeFileService.scala

@@ -93,7 +93,9 @@ class ConnectomeFileService @Inject()(config: DataStoreConfig)(implicit ec: Exec
   def exploreConnectomeFiles(organizationName: String, dataSetName: String, dataLayerName: String): Set[String] = {
     val layerDir = dataBaseDir.resolve(organizationName).resolve(dataSetName).resolve(dataLayerName)
     PathUtils
-      .listFiles(layerDir.resolve(connectomesDir), PathUtils.fileExtensionFilter(connectomeFileExtension))
+      .listFiles(layerDir.resolve(connectomesDir),
+                 silent = true,
+                 PathUtils.fileExtensionFilter(connectomeFileExtension))
       .map { paths =>
         paths.map(path => FilenameUtils.removeExtension(path.getFileName.toString))
       }

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/DSUsedStorageService.scala

@@ -46,14 +46,17 @@ class DSUsedStorageService @Inject()(config: DataStoreConfig)(implicit ec: Execu
     def selectedDatasetFilter(p: Path) = dataSetName.forall(name => p.getFileName.toString == name)
 
     for {
-      datasetDirectories <- PathUtils.listDirectories(organizationDirectory, noSymlinksFilter, selectedDatasetFilter) ?~> "listdir.failed"
+      datasetDirectories <- PathUtils.listDirectories(organizationDirectory,
+                                                      silent = true,
+                                                      noSymlinksFilter,
+                                                      selectedDatasetFilter) ?~> "listdir.failed"
       storageReportsNested <- Fox.serialCombined(datasetDirectories)(d => measureStorageForDataSet(organizationName, d))
     } yield storageReportsNested.flatten
   }
 
   def measureStorageForDataSet(organizationName: String, dataSetDirectory: Path): Fox[List[DirectoryStorageReport]] =
     for {
-      layerDirectory <- PathUtils.listDirectories(dataSetDirectory, noSymlinksFilter) ?~> "listdir.failed"
+      layerDirectory <- PathUtils.listDirectories(dataSetDirectory, silent = true, noSymlinksFilter) ?~> "listdir.failed"
       storageReportsNested <- Fox.serialCombined(layerDirectory)(l =>
         measureStorageForLayerDirectory(organizationName, dataSetDirectory, l))
     } yield storageReportsNested.flatten
@@ -62,7 +65,7 @@ class DSUsedStorageService @Inject()(config: DataStoreConfig)(implicit ec: Execu
                                       dataSetDirectory: Path,
                                       layerDirectory: Path): Fox[List[DirectoryStorageReport]] =
     for {
-      magOrOtherDirectory <- PathUtils.listDirectories(layerDirectory, noSymlinksFilter) ?~> "listdir.failed"
+      magOrOtherDirectory <- PathUtils.listDirectories(layerDirectory, silent = true, noSymlinksFilter) ?~> "listdir.failed"
       storageReportsNested <- Fox.serialCombined(magOrOtherDirectory)(m =>
         measureStorageForMagOrOtherDirectory(organizationName, dataSetDirectory, layerDirectory, m))
     } yield storageReportsNested

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/DataSourceImporter.scala

@@ -32,7 +32,7 @@ trait DataSourceImporter {
                         baseDir: Path,
                         previous: Option[DataSource],
                         report: DataSourceImportReport[Path]): Box[DataSource] =
-    PathUtils.listDirectories(baseDir).map { layerDirs =>
+    PathUtils.listDirectories(baseDir, silent = false).map { layerDirs =>
       val layers = layerDirs.flatMap { layerDir =>
         val layerName = layerDir.getFileName.toString
         val previousLayer = previous.flatMap(_.getDataLayer(layerName))

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/DataSourceService.scala

@@ -59,7 +59,7 @@ class DataSourceService @Inject()(
   def checkInbox(verbose: Boolean): Fox[Unit] = {
     if (verbose) logger.info(s"Scanning inbox ($dataBaseDir)...")
     for {
-      _ <- PathUtils.listDirectories(dataBaseDir) match {
+      _ <- PathUtils.listDirectories(dataBaseDir, silent = false) match {
         case Full(organizationDirs) =>
           for {
             _ <- Fox.successful(())
@@ -100,7 +100,7 @@ class DataSourceService @Inject()(
   private def logEmptyDirs(paths: List[Path]): Unit = {
 
     val emptyDirs = paths.flatMap { path =>
-      PathUtils.listDirectories(path) match {
+      PathUtils.listDirectories(path, silent = true) match {
         case Full(Nil) =>
           Some(path)
         case _ => None
@@ -202,7 +202,7 @@ class DataSourceService @Inject()(
   private def teamAwareInboxSources(path: Path): List[InboxDataSource] = {
     val organization = path.getFileName.toString
 
-    PathUtils.listDirectories(path) match {
+    PathUtils.listDirectories(path, silent = true) match {
       case Full(dataSourceDirs) =>
         val dataSources = dataSourceDirs.map(path => dataSourceFromFolder(path, organization))
         dataSources

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/MeshFileService.scala

@@ -184,7 +184,7 @@ class MeshFileService @Inject()(config: DataStoreConfig)(implicit ec: ExecutionC
   def exploreMeshFiles(organizationName: String, dataSetName: String, dataLayerName: String): Fox[Set[MeshFileInfo]] = {
     val layerDir = dataBaseDir.resolve(organizationName).resolve(dataSetName).resolve(dataLayerName)
     val meshFileNames = PathUtils
-      .listFiles(layerDir.resolve(meshesDir), PathUtils.fileExtensionFilter(meshFileExtension))
+      .listFiles(layerDir.resolve(meshesDir), silent = true, PathUtils.fileExtensionFilter(meshFileExtension))
       .map { paths =>
         paths.map(path => FilenameUtils.removeExtension(path.getFileName.toString))
       }

webknossos-datastore/app/com/scalableminds/webknossos/datastore/services/UploadService.scala

@@ -329,6 +329,7 @@ class UploadService @Inject()(dataSourceRepository: DataSourceRepository,
       for {
         listing: Seq[Path] <- PathUtils.listFilesRecursive(dataSourceDir,
                                                            maxDepth = 2,
+                                                           silent = false,
                                                            filters = p => p.getFileName.toString == FILENAME_HEADER_WKW)
         listingRelative = listing.map(dataSourceDir.normalize().relativize(_))
       } yield {
@@ -358,7 +359,7 @@ class UploadService @Inject()(dataSourceRepository: DataSourceRepository,
 
   private def unpackDataset(uploadDir: Path, unpackToDir: Path): Fox[Unit] =
     for {
-      shallowFileList <- PathUtils.listFiles(uploadDir).toFox
+      shallowFileList <- PathUtils.listFiles(uploadDir, silent = false).toFox
       excludeFromPrefix = Category.values.map(_.toString).toList
       firstFile = shallowFileList.headOption
       _ <- if (shallowFileList.length == 1 && shallowFileList.headOption.exists(
@@ -375,7 +376,7 @@ class UploadService @Inject()(dataSourceRepository: DataSourceRepository,
         }.toFox.map(_ => ())
       } else {
         for {
-          deepFileList: List[Path] <- PathUtils.listFilesRecursive(uploadDir, maxDepth = 10).toFox
+          deepFileList: List[Path] <- PathUtils.listFilesRecursive(uploadDir, silent = false, maxDepth = 10).toFox
           commonPrefixPreliminary = PathUtils.commonPrefix(deepFileList)
           strippedPrefix = PathUtils.cutOffPathAtLastOccurrenceOf(commonPrefixPreliminary, excludeFromPrefix)
           commonPrefix = PathUtils.removeSingleFileNameFromPrefix(strippedPrefix,
@@ -406,7 +407,7 @@ class UploadService @Inject()(dataSourceRepository: DataSourceRepository,
 
   private def cleanUpOrphanUploads(): Fox[Unit] =
     for {
-      organizationDirs <- PathUtils.listDirectories(dataBaseDir).toFox
+      organizationDirs <- PathUtils.listDirectories(dataBaseDir, silent = false).toFox
       _ <- Fox.serialCombined(organizationDirs)(cleanUpOrphanUploadsForOrga)
     } yield ()
 
@@ -416,7 +417,7 @@ class UploadService @Inject()(dataSourceRepository: DataSourceRepository,
       Fox.successful(())
     else {
       for {
-        uploadDirs <- PathUtils.listDirectories(orgaUploadingDir).toFox
+        uploadDirs <- PathUtils.listDirectories(orgaUploadingDir, silent = false).toFox
         _ <- Fox.serialCombined(uploadDirs) { uploadDir =>
           isKnownUpload(uploadDir.getFileName.toString).map {
             case false =>

webknossos-tracingstore/app/com/scalableminds/webknossos/tracingstore/TSRemoteDatastoreClient.scala

@@ -88,7 +88,7 @@ class TSRemoteDatastoreClient @Inject()(
                           userToken: Option[String]): Fox[AgglomerateGraph] =
     for {
       remoteLayerUri <- getRemoteLayerUri(remoteFallbackLayer)
-      result <- rpc(s"$remoteLayerUri/agglomerates/$baseMappingName/agglomerateGraph/$agglomerateId")
+      result <- rpc(s"$remoteLayerUri/agglomerates/$baseMappingName/agglomerateGraph/$agglomerateId").silent
         .addQueryStringOptional("token", userToken)
         .silent
         .getWithProtoResponse[AgglomerateGraph](AgglomerateGraph)
@@ -105,6 +105,7 @@ class TSRemoteDatastoreClient @Inject()(
           remoteLayerUri <- getRemoteLayerUri(k._1)
           result <- rpc(s"$remoteLayerUri/agglomerates/${k._2}/largestAgglomerateId")
             .addQueryStringOptional("token", k._3)
+            .silent
             .getWithJsonResponse[Long]
         } yield result
     )

webknossos-tracingstore/app/com/scalableminds/webknossos/tracingstore/TSRemoteWebKnossosClient.scala

@@ -46,6 +46,7 @@ class TSRemoteWebKnossosClient @Inject()(
   def reportTracingUpdates(tracingUpdatesReport: TracingUpdatesReport): Fox[WSResponse] =
     rpc(s"$webKnossosUri/api/tracingstores/$tracingStoreName/handleTracingUpdateReport")
       .addQueryString("key" -> tracingStoreKey)
+      .silent
       .post(Json.toJson(tracingUpdatesReport))
 
   def getDataSourceForTracing(tracingId: String): Fox[DataSourceLike] =
@@ -58,6 +59,7 @@ class TSRemoteWebKnossosClient @Inject()(
     rpc(s"$webKnossosUri/api/tracingstores/$tracingStoreName/dataStoreUri/$dataSetName")
       .addQueryString("organizationName" -> organizationName)
       .addQueryString("key" -> tracingStoreKey)
+      .silent
       .getWithJsonResponse[String]
 
   def getDataSourceIdForTracing(tracingId: String)(implicit ec: ExecutionContext): Fox[DataSourceId] =