Log timings of FS operations (#9908)

I'm seeing occasional IO timeouts, especially on startup operations, for cloud projects. Adding some logging to make an informed decision if there are some problems there.

Related to #9789

# Important Notes
Also added retries when closing the file as I saw a number of times:
```
Session release failed.
LsRpcError: Language server request 'text/closeFile' failed.
at LanguageServer.request (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:58291:15)
at async Promise.all (index 0)
at async _LanguageServerSession.release (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:59165:5)
at async /tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:59670:7 {
cause: JSONRPCError2: Request timeout request took longer than 15000 ms to resolve
at new JSONRPCError2 (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:26822:30)
at Timeout._onTimeout (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:26985:20)
at listOnTimeout (node:internal/timers:569:17)
at process.processTimers (node:internal/timers:512:7) {
code: 7777,
data: undefined
},
request: 'text/closeFile',
params: {
path: {
rootId: '00000000-0000-0000-0000-000000000001',
segments: [Array]
}
}
}
```

engine/language-server/src/main/scala/org/enso/languageserver/boot/MainModule.scala

@@ -123,7 +123,7 @@ class MainModule(serverConfig: LanguageServerConfig, logLevel: Level) {
   private val zioExec = effect.ZioExec(zioRuntime)
   log.trace("Created ZIO executor [{}].", zioExec)
 
-  private val fileSystem: FileSystem = new FileSystem
+  private val fileSystem: FileSystem = new FileSystem(log)
   log.trace("Created file system [{}].", fileSystem)
 
   val git = Git.withEmptyUserConfig(

engine/language-server/src/main/scala/org/enso/languageserver/filemanager/FileSystem.scala

@@ -2,6 +2,7 @@ package org.enso.languageserver.filemanager
 
 import org.apache.commons.io.{FileExistsException, FileUtils}
 import org.enso.languageserver.effect.BlockingIO
+import org.slf4j.Logger
 import zio._
 
 import java.io.{File, FileNotFoundException, RandomAccessFile}
@@ -15,7 +16,7 @@ import zio.ZIO.attemptBlocking
 
 /** File manipulation facility.
   */
-class FileSystem extends FileSystemApi[BlockingIO] {
+class FileSystem(logger: Logger) extends FileSystemApi[BlockingIO] {
 
   private val tenMb: Int = 1 * 1024 * 1024 * 10
 
@@ -34,15 +35,19 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     file: File,
     content: String
   ): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking(FileUtils.write(file, content, "UTF-8"))
+    timedBlockingOp("writeTextToFile", logger) {
+      FileUtils.write(file, content, "UTF-8")
+    }
       .mapError(errorHandling)
 
   /** @inheritdoc */
   override def writeBinary(
     file: File,
     contents: Array[Byte]
   ): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking(FileUtils.writeByteArrayToFile(file, contents))
+    timedBlockingOp("writeBytesToFile", logger) {
+      FileUtils.writeByteArrayToFile(file, contents)
+    }
       .mapError(errorHandling)
 
   /** Reads the contents of a textual file.
@@ -51,14 +56,16 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     * @return either [[FileSystemFailure]] or the content of a file as a String
     */
   override def read(file: File): BlockingIO[FileSystemFailure, String] =
-    attemptBlocking(FileUtils.readFileToString(file, "UTF-8"))
+    timedBlockingOp("readFile", logger) {
+      FileUtils.readFileToString(file, "UTF-8")
+    }
       .mapError(errorHandling)
 
   /** @inheritdoc */
   override def readBinary(
     file: File
   ): BlockingIO[FileSystemFailure, Array[Byte]] =
-    attemptBlocking(FileUtils.readFileToByteArray(file))
+    timedBlockingOp("readBytes", logger) { FileUtils.readFileToByteArray(file) }
       .mapError(errorHandling)
 
   /** Deletes the specified file or directory recursively.
@@ -67,7 +74,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     * @return either [[FileSystemFailure]] or Unit
     */
   def delete(file: File): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking {
+    timedBlockingOp("deletePath", logger) {
       if (file.isDirectory) {
         FileUtils.deleteDirectory(file)
       } else {
@@ -87,7 +94,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     } yield ()
 
   private def createEmptyFile(file: File): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking(file.createNewFile(): Unit)
+    timedBlockingOp("createEmptyFile", logger) { file.createNewFile(): Unit }
       .mapError(errorHandling)
 
   /** Creates a directory, including any necessary but nonexistent parent
@@ -99,7 +106,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
   override def createDirectory(
     file: File
   ): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking(FileUtils.forceMkdir(file))
+    timedBlockingOp("digestBytes", logger) { FileUtils.forceMkdir(file) }
       .mapError(errorHandling)
 
   /** Copy a file or directory recursively.
@@ -114,7 +121,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     if (from.isDirectory && to.isFile) {
       ZIO.fail(FileExists)
     } else {
-      attemptBlocking {
+      timedBlockingOp("copyFile", logger) {
         if (from.isFile && to.isDirectory) {
           FileUtils.copyFileToDirectory(from, to)
         } else if (from.isDirectory) {
@@ -132,7 +139,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     * @return either [[FileSystemFailure]] or Unit
     */
   override def move(from: File, to: File): BlockingIO[FileSystemFailure, Unit] =
-    attemptBlocking {
+    timedBlockingOp("moveFile", logger) {
       if (to.isDirectory) {
         val createDestDir = false
         FileUtils.moveToDirectory(from, to, createDestDir)
@@ -149,7 +156,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     * @return either [[FileSystemFailure]] or file existence flag
     */
   override def exists(file: File): BlockingIO[FileSystemFailure, Boolean] =
-    attemptBlocking(Files.exists(file.toPath))
+    timedBlockingOp("fileExists", logger) { Files.exists(file.toPath) }
       .mapError(errorHandling)
 
   /** List contents of a given path.
@@ -160,7 +167,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
   override def list(path: File): BlockingIO[FileSystemFailure, Vector[Entry]] =
     if (path.exists) {
       if (path.isDirectory) {
-        attemptBlocking {
+        timedBlockingOp("listPath", logger) {
           FileSystem
             .list(path.toPath)
             .map {
@@ -189,7 +196,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     val limit = FileSystem.Depth(depth)
     if (path.exists && limit.canGoDeeper) {
       if (path.isDirectory) {
-        attemptBlocking {
+        timedBlockingOp("tree", logger) {
           val directory = DirectoryEntry.empty(path.toPath)
           FileSystem.readDirectoryEntry(
             directory,
@@ -217,7 +224,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     path: File
   ): BlockingIO[FileSystemFailure, Attributes] =
     if (path.exists) {
-      attemptBlocking {
+      timedBlockingOp("fileInfo", logger) {
         val attrs =
           Files.readAttributes(path.toPath, classOf[BasicFileAttributes])
         Attributes.fromBasicAttributes(path.toPath, attrs)
@@ -233,7 +240,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     */
   override def digest(path: File): BlockingIO[FileSystemFailure, SHA3_224] = {
     if (path.isFile) {
-      attemptBlocking {
+      timedBlockingOp("digestFile", logger) {
         val messageDigest = MessageDigest.getInstance("SHA3-224")
         Using.resource(
           Files.newInputStream(path.toPath, StandardOpenOption.READ)
@@ -267,7 +274,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
   ): BlockingIO[FileSystemFailure, SHA3_224] = {
     val path = segment.path
     if (path.isFile) {
-      attemptBlocking {
+      timedBlockingOp("digestBytes", logger) {
         val messageDigest = MessageDigest.getInstance("SHA3-224")
         Using.resource(
           Files.newInputStream(path.toPath, StandardOpenOption.READ)
@@ -316,7 +323,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     if (path.isDirectory) {
       ZIO.fail(NotFile)
     } else {
-      attemptBlocking {
+      timedBlockingOp("writeBytes", logger) {
         Using.resource(new RandomAccessFile(path, "rw")) { file =>
           Using.resource(file.getChannel) { chan =>
             val lock = chan.lock()
@@ -366,7 +373,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
   ): BlockingIO[FileSystemFailure, ReadBytesResult] = {
     val path = segment.path
     if (path.isFile) {
-      attemptBlocking {
+      timedBlockingOp("readBytes", logger) {
         Using.resource(
           Files.newInputStream(path.toPath, StandardOpenOption.READ)
         ) { stream =>
@@ -404,6 +411,22 @@ class FileSystem extends FileSystemApi[BlockingIO] {
     case FileSystem.CannotOverwrite    => CannotOverwrite
     case ex                            => GenericFileSystemFailure(ex.getMessage)
   }
+
+  private def timedBlockingOp[T](opName: String, logger: Logger)(
+    op: => T
+  )(implicit trace: Trace): Task[T] = {
+    attemptBlocking {
+      val start = java.lang.System.currentTimeMillis()
+      try {
+        op
+      } finally {
+        if (logger.isTraceEnabled()) {
+          val now = java.lang.System.currentTimeMillis();
+          logger.trace(s"$opName took ${now - start} milliseconds")
+        }
+      }
+    }
+  }
 }
 
 object FileSystem {

engine/language-server/src/main/scala/org/enso/languageserver/requesthandler/text/CloseFileHandler.scala

@@ -1,15 +1,18 @@
 package org.enso.languageserver.requesthandler.text
 
-import akka.actor.{Actor, ActorRef, Cancellable, Props}
+import akka.actor.{Actor, ActorRef, Props}
 import com.typesafe.scalalogging.LazyLogging
 import org.enso.jsonrpc._
-import org.enso.languageserver.requesthandler.RequestTimeout
 import org.enso.languageserver.session.JsonSession
 import org.enso.languageserver.text.TextApi.{CloseFile, FileNotOpenedError}
-import org.enso.languageserver.text.TextProtocol
+import org.enso.languageserver.text.{TextApi, TextProtocol}
 import org.enso.languageserver.text.TextProtocol.{FileClosed, FileNotOpened}
-import org.enso.languageserver.util.UnhandledLogging
+import org.enso.languageserver.util.{
+  RequestHandlerWithRetries,
+  UnhandledLogging
+}
 
+import scala.concurrent.ExecutionContext
 import scala.concurrent.duration.FiniteDuration
 
 /** A request handler for `text/closeFile` commands.
@@ -22,45 +25,36 @@ class CloseFileHandler(
   bufferRegistry: ActorRef,
   timeout: FiniteDuration,
   rpcSession: JsonSession
-) extends Actor
+) extends RequestHandlerWithRetries[
+      Request[CloseFile.type, CloseFile.Params],
+      FileClosed.type,
+      FileNotOpened.type,
+      TextProtocol.CloseFile
+    ](bufferRegistry, timeout, 5)
+    with Actor
     with LazyLogging
     with UnhandledLogging {
 
-  import context.dispatcher
-
-  override def receive: Receive = requestStage
-
-  private def requestStage: Receive = {
-    case Request(CloseFile, id, params: CloseFile.Params) =>
-      bufferRegistry ! TextProtocol.CloseFile(rpcSession.clientId, params.path)
-      val cancellable =
-        context.system.scheduler.scheduleOnce(timeout, self, RequestTimeout)
-      context.become(responseStage(id, sender(), cancellable))
+  override protected def request(
+    msg: Request[TextApi.CloseFile.type, CloseFile.Params]
+  ): TextProtocol.CloseFile = {
+    TextProtocol.CloseFile(rpcSession.clientId, msg.params.path)
   }
 
-  private def responseStage(
-    id: Id,
+  override protected def positiveResponse(
     replyTo: ActorRef,
-    cancellable: Cancellable
-  ): Receive = {
-    case RequestTimeout =>
-      logger.error(
-        "Closing file request [{}] for [{}] timed out.",
-        id,
-        rpcSession.clientId
-      )
-      replyTo ! ResponseError(Some(id), Errors.RequestTimeout)
-      context.stop(self)
-
-    case FileClosed =>
-      replyTo ! ResponseResult(CloseFile, id, Unused)
-      cancellable.cancel()
-      context.stop(self)
+    initialMsg: Request[TextApi.CloseFile.type, CloseFile.Params],
+    msg: TextProtocol.FileClosed.type
+  ): Unit = {
+    replyTo ! ResponseResult(CloseFile, initialMsg.id, Unused)
+  }
 
-    case FileNotOpened =>
-      replyTo ! ResponseError(Some(id), FileNotOpenedError)
-      cancellable.cancel()
-      context.stop(self)
+  override protected def negativeResponse(
+    replyTo: ActorRef,
+    initialMsg: Request[TextApi.CloseFile.type, CloseFile.Params],
+    error: TextProtocol.FileNotOpened.type
+  )(implicit ec: ExecutionContext): Unit = {
+    replyTo ! ResponseError(Some(initialMsg.id), FileNotOpenedError)
   }
 }
 

engine/language-server/src/test/scala/org/enso/languageserver/filemanager/FileSystemSpec.scala

@@ -13,6 +13,7 @@ import java.security.MessageDigest
 import scala.collection.mutable.ArrayBuffer
 import scala.io.Source
 import scala.jdk.CollectionConverters._
+import org.slf4j.LoggerFactory
 
 class FileSystemSpec
     extends AnyWordSpecLike
@@ -1020,7 +1021,9 @@ class FileSystemSpec
     val testDirPath = Files.createTempDirectory(null)
     sys.addShutdownHook(FileUtils.deleteQuietly(testDirPath.toFile))
 
-    val objectUnderTest = new FileSystem
+    val objectUnderTest = new FileSystem(
+      LoggerFactory.getLogger(classOf[FileSystemSpec])
+    )
 
   }
 

engine/language-server/src/test/scala/org/enso/languageserver/websocket/binary/BaseBinaryServerTest.scala

@@ -36,6 +36,7 @@ import org.enso.languageserver.websocket.binary.factory.{
 import java.util.concurrent.{ExecutorService, Executors}
 import scala.concurrent.ExecutionContext
 import scala.concurrent.duration._
+import org.slf4j.LoggerFactory
 
 abstract class BaseBinaryServerTest extends BinaryServerTestKit {
 
@@ -89,7 +90,9 @@ abstract class BaseBinaryServerTest extends BinaryServerTestKit {
           FileManager.props(
             config.fileManager,
             contentRootManagerWrapper,
-            new FileSystem,
+            new FileSystem(
+              LoggerFactory.getLogger(classOf[BaseBinaryServerTest])
+            ),
             zioExec
           )
         )

engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/BaseServerTest.scala

@@ -73,6 +73,7 @@ import java.util.concurrent.{Executors, ThreadFactory}
 import java.util.concurrent.atomic.AtomicInteger
 import scala.concurrent.ExecutionContext
 import scala.concurrent.duration._
+import org.slf4j.LoggerFactory
 
 abstract class BaseServerTest
     extends JsonRpcServerTestKit
@@ -235,7 +236,7 @@ abstract class BaseServerTest
       FileManager.props(
         config.fileManager,
         contentRootManagerWrapper,
-        new FileSystem,
+        new FileSystem(LoggerFactory.getLogger(classOf[BaseServerTest])),
         zioExec
       ),
       s"file-manager-${UUID.randomUUID()}"
@@ -273,7 +274,7 @@ abstract class BaseServerTest
         config,
         contentRootManagerWrapper,
         watcherFactory,
-        new FileSystem,
+        new FileSystem(LoggerFactory.getLogger(classOf[BaseServerTest])),
         zioExec
       ),
       s"fileevent-registry-${UUID.randomUUID()}"