Log cache pruning to $TART_HOME/tart.log (#265)

* Log cache pruning to $TART_HOME/tart.log

* Log zero capacities

Package.resolved

@@ -9,6 +9,15 @@
         "revision" : "772883073d044bc754d401cabb6574624eb3778f"
       }
     },
+    {
+      "identity" : "puppy",
+      "kind" : "remoteSourceControl",
+      "location" : "https://github.com/sushichop/Puppy",
+      "state" : {
+        "revision" : "3e8d87f714f14244878752a6bb71ea465119f8a1",
+        "version" : "0.5.1"
+      }
+    },
     {
       "identity" : "swift-algorithms",
       "kind" : "remoteSourceControl",
@@ -54,6 +63,15 @@
         "version" : "1.0.3"
       }
     },
+    {
+      "identity" : "swift-log",
+      "kind" : "remoteSourceControl",
+      "location" : "https://github.com/apple/swift-log.git",
+      "state" : {
+        "revision" : "6fe203dc33195667ce1759bf0182975e4653ba1c",
+        "version" : "1.4.4"
+      }
+    },
     {
       "identity" : "swift-numerics",
       "kind" : "remoteSourceControl",

Package.swift

@@ -15,7 +15,8 @@ let package = Package(
     .package(url: "https://github.com/pointfreeco/swift-parsing", from: "0.9.2"),
     .package(url: "https://github.com/apple/swift-algorithms", from: "1.0.0"),
     .package(url: "https://github.com/apple/swift-async-algorithms", branch: "main"),
-    .package(url: "https://github.com/malcommac/SwiftDate", from: "6.3.1")
+    .package(url: "https://github.com/malcommac/SwiftDate", from: "6.3.1"),
+    .package(url: "https://github.com/sushichop/Puppy", from: "0.5.1")
   ],
   targets: [
     .executableTarget(name: "tart", dependencies: [
@@ -25,8 +26,8 @@ let package = Package(
       .product(name: "Dynamic", package: "Dynamic"),
       .product(name: "Parsing", package: "swift-parsing"),
       .product(name: "SwiftDate", package: "SwiftDate"),
+      .product(name: "Puppy", package: "Puppy"),
     ]),
     .testTarget(name: "TartTests", dependencies: ["tart"])
   ]
 )
-

Sources/tart/Commands/Prune.swift

@@ -103,6 +103,9 @@ struct Prune: AsyncParsableCommand {
 
       cacheReclaimedBytes += try prunable.sizeBytes()
       try prunable.delete()
+      puppy.info("deleting \(prunable.url)...")
     }
+
+    puppy.info("reclaimed \(cacheReclaimedBytes) bytes")
   }
 }

Sources/tart/Prunable.swift

@@ -5,6 +5,7 @@ protocol PrunableStorage {
 }
 
 protocol Prunable {
+  var url: URL { get }
   func delete() throws
   func accessDate() throws -> Date
   func sizeBytes() throws -> Int

Sources/tart/Root.swift

@@ -1,5 +1,14 @@
 import ArgumentParser
 import Foundation
+import Puppy
+
+var puppy = Puppy.default
+
+class LogFormatter: LogFormattable {
+    func formatMessage(_ level: LogLevel, message: String, tag: String, function: String, file: String, line: UInt, swiftLogInfo: [String: String], label: String, date: Date, threadID: UInt64) -> String {
+        "\(date) \(level) \(message)"
+    }
+}
 
 @main
 struct Root: AsyncParsableCommand {
@@ -36,6 +45,12 @@ struct Root: AsyncParsableCommand {
     // Set line-buffered output for stdout
     setlinebuf(stdout)
 
+    // Initialize file logger
+    let logFileURL = try Config().tartHomeDir.appendingPathComponent("tart.log")
+    let fileLogger = try FileLogger("org.cirruslabs.tart", fileURL: logFileURL)
+    fileLogger.format = LogFormatter()
+    puppy.add(fileLogger)
+
     // Parse and run command
     do {
       var command = try parseAsRoot()

Sources/tart/URL+Prunable.swift

@@ -1,6 +1,10 @@
 import Foundation
 
 extension URL: Prunable {
+  var url: URL {
+    self
+  }
+
   func delete() throws {
     try FileManager.default.removeItem(at: self)
   }

Sources/tart/VMDirectory.swift

@@ -28,6 +28,10 @@ struct VMDirectory: Prunable {
     baseURL.lastPathComponent
   }
 
+  var url: URL {
+    baseURL
+  }
+
   static func temporary() throws -> VMDirectory {
     let tmpDir = try Config().tartTmpDir.appendingPathComponent(UUID().uuidString)
     try FileManager.default.createDirectory(at: tmpDir, withIntermediateDirectories: false)

Sources/tart/VMStorageOCI.swift

@@ -159,11 +159,22 @@ class VMStorageOCI: PrunableStorage {
         let requiredCapacityBytes = UInt64(uncompressedDiskSize + 128 * 1024 * 1024)
 
         let attrs = try Config().tartCacheDir.resourceValues(forKeys: [.volumeAvailableCapacityForImportantUsageKey, .volumeAvailableCapacityKey])
-        let availableCapacityBytes = max(UInt64(attrs.volumeAvailableCapacityForImportantUsage!), UInt64(attrs.volumeAvailableCapacity!))
+        let capacityImportant = attrs.volumeAvailableCapacityForImportantUsage!
+        let capacityAvailable = attrs.volumeAvailableCapacity!
+        let availableCapacityBytes = max(UInt64(capacityImportant), UInt64(capacityAvailable))
+
+        if capacityImportant == 0 || capacityAvailable == 0 {
+          puppy.warning("important capacity \(capacityImportant) bytes, "
+                  + "available capacity is \(capacityAvailable) bytes")
+        }
 
         // There is a suspicious that occasionally capacity is returned as zero which can't be true.
         // Let's validate to avoid unnecessary pruning.
         if 0 < availableCapacityBytes && availableCapacityBytes < requiredCapacityBytes {
+          puppy.info("pruning cache to accommodate \(name) with a disk of size \(uncompressedDiskSize) bytes ("
+                  + "available capacity is \(availableCapacityBytes) bytes, required capacity "
+                  + "is \(requiredCapacityBytes) bytes)")
+
           try Prune.pruneReclaim(reclaimBytes: requiredCapacityBytes - availableCapacityBytes)
         }
       }