Structured, bounded diagnostics for daemon IPC (#289)

.github/workflows/linux.yml

@@ -20,3 +20,6 @@ jobs:
       - uses: actions/checkout@v4
       - run: swift build
       - run: .build/debug/graphcode
+      # The built CLI against a throwaway daemon — exit 0 on the verbs that dial it.
+      # A runtime fault in the CLI passes every scheme build; this is what catches it.
+      - run: scripts/cli-smoke.sh

GraphcodeKit/Sources/CLI/GraphcodeCommand.swift

@@ -992,6 +992,21 @@ extension GraphcodeCommand {
     return "posted #\(latest)\(suffix)"
   }
 
+  /// The timeout the CLI prints: which phase it was in, for how long, and the two
+  /// numbers that find this run in `graphcoded.log` — its pid (the daemon logs each
+  /// connection's `peer=`) and how many frames it had sent (the daemon's `seq=`).
+  public static func renderTimeout(
+    phase: String, elapsed: TimeInterval, pid: Int32, framesSent: Int
+  ) -> String {
+    let seconds = String(format: "%.1f", elapsed)
+    return """
+      timed out after \(seconds)s \(phase) (pid \(pid), \(framesSent) frame\(framesSent == 1 ? "" : "s") \
+      sent). The command may still have been applied — check with `graphcode status`. \
+      graphcoded.log lines with peer=\(pid) are this run's; seq=\(framesSent) is the frame it \
+      was waiting on.
+      """
+  }
+
   public static func describe(_ error: ParseError) -> String {
     switch error {
     case .unknownCommand(let name): return "unknown command: \(name)"

GraphcodeKit/Sources/DaemonIdentity.swift

@@ -0,0 +1,19 @@
+import Foundation
+
+/// What version of itself a daemon is, for the `startup` line in its log — so version
+/// skew between a client and the daemon answering it can be read off the two logs
+/// rather than guessed (issue #289).
+///
+/// `graphcoded` is a bare executable: Tuist embeds its Info.plist in the binary, where
+/// `Bundle.main` still finds it; a SwiftPM build carries none and says so. The
+/// executable's inode identity is what `graphcoded` already watches to notice an
+/// upgrade underneath itself, so it is logged beside the version as the tie-breaker.
+public enum DaemonIdentity {
+  public static var version: String {
+    (Bundle.main.infoDictionary?["CFBundleShortVersionString"] as? String) ?? "unversioned"
+  }
+
+  public static var build: String {
+    (Bundle.main.infoDictionary?["CFBundleVersion"] as? String) ?? "unversioned"
+  }
+}

GraphcodeKit/Sources/GraphStore.swift

@@ -515,7 +515,7 @@ public actor GraphStore {
     // the same way the registry does. Without this a store could bind to a channel left
     // dead on a recycled descriptor number and drop the client as disconnected on the
     // snapshot it was joining for.
-    OutboundChannels.open(fileDescriptor)
+    OutboundChannels.open(fileDescriptor, tag: id.tag)
     connections[id] = fileDescriptor
     send(.graphChanged(graph.wireSnapshot(revision: revision)), to: id)
   }
@@ -3268,7 +3268,14 @@ public actor GraphStore {
   // MARK: - Broadcast
 
   private func broadcast() {
+    let started = Date()
     onGraphChanged?(graph)
+    DaemonLog.shared.record(
+      "persist",
+      DaemonRequestContext.fields + [
+        ("nodes", String(graph.nodes.count)),
+        ("ms", DaemonLog.milliseconds(Date().timeIntervalSince(started))),
+      ])
     notifyClients()
   }
 
@@ -3284,11 +3291,27 @@ public actor GraphStore {
     // clients attached it was C encodes of the same snapshot on every change, presence
     // tick included (issue #288's CPU amplifier).
     revision += 1
+    let started = Date()
     guard let frame = Self.encode(.graphChanged(graph.wireSnapshot(revision: revision)))
     else { return }
-    for id in connections.keys {
-      deliver(frame, to: id)
-    }
+    let encoded = Date()
+    let intended = connections.count
+    var accepted = 0
+    for id in connections.keys where deliver(frame, to: id) {
+      accepted += 1
+    }
+    // Sizes and counts only. `ms` is the actor's own time — encode plus handing every
+    // frame to its channel — and never includes a client's read: that is `write`'s
+    // `blocked_ms`, per client, which is the field #288 was missing.
+    DaemonLog.shared.record(
+      "broadcast",
+      DaemonRequestContext.fields + [
+        ("kind", "graphChanged"), ("revision", String(revision)),
+        ("bytes", String(frame.data.count)),
+        ("encode_ms", DaemonLog.milliseconds(encoded.timeIntervalSince(started))),
+        ("recipients", String(intended)), ("accepted", String(accepted)),
+        ("ms", DaemonLog.milliseconds(Date().timeIntervalSince(started))),
+      ])
   }
 
   /// The presence poll's broadcast — see `DaemonEvent.nodesChanged`. Not superseded:
@@ -3301,19 +3324,38 @@ public actor GraphStore {
   /// never meets a frame it cannot read. Both frames are encoded at most once.
   private func notifyClients(nodesChanged nodes: [LoopNode]) {
     revision += 1
+    let started = Date()
     let delta = Self.encode(
       .nodesChanged(projectPath: graph.project.path, revision: revision, nodes: nodes))
     var snapshot: EncodedEvent?
+    let intended = connections.count
+    var accepted = 0
+    var snapshots = 0
     for (id, capabilities) in connectionCapabilities where connections[id] != nil {
       if capabilities.contains(ClientCapability.nodesChanged.rawValue) {
-        if let delta { deliver(delta, to: id) }
+        if let delta, deliver(delta, to: id) { accepted += 1 }
       } else {
+        // `deliver` would refuse the delta here on its own; the snapshot is what keeps
+        // this connection current.
         if snapshot == nil {
           snapshot = Self.encode(.graphChanged(graph.wireSnapshot(revision: revision)))
         }
-        if let snapshot { deliver(snapshot, to: id) }
+        if let snapshot, deliver(snapshot, to: id) {
+          accepted += 1
+          snapshots += 1
+        }
       }
     }
+    DaemonLog.shared.record(
+      "broadcast",
+      [
+        ("kind", "nodesChanged"), ("revision", String(revision)),
+        ("nodes", String(nodes.count)), ("bytes", String(delta?.data.count ?? 0)),
+        ("snapshot_bytes", String(snapshot?.data.count ?? 0)),
+        ("recipients", String(intended)), ("accepted", String(accepted)),
+        ("as_snapshot", String(snapshots)),
+        ("ms", DaemonLog.milliseconds(Date().timeIntervalSince(started))),
+      ])
   }
 
   /// An event as the bytes and the superseding key it goes out with — everything about
@@ -3349,16 +3391,20 @@ public actor GraphStore {
     deliver(frame, to: connectionID)
   }
 
-  private func deliver(_ frame: EncodedEvent, to connectionID: UUID) {
-    guard let fileDescriptor = connections[connectionID] else { return }
+  /// Whether the frame was handed to a live channel; `false` also drops the connection
+  /// — or, for an event the connection never announced it could read, sends nothing
+  /// and keeps it.
+  @discardableResult
+  private func deliver(_ frame: EncodedEvent, to connectionID: UUID) -> Bool {
+    guard let fileDescriptor = connections[connectionID] else { return false }
     // The one place the daemon's default is enforced: an event a connection never
     // announced it could read is not sent to it, whatever call site asked. A caller
     // that wants such a connection kept current sends it the legacy shape instead
     // (`notifyClients(nodesChanged:)` sends the snapshot).
     if let required = frame.requiredCapability,
       connectionCapabilities[connectionID]?.contains(required.rawValue) != true
     {
-      return
+      return false
     }
     // Queued, never written here: this runs on the `GraphStore` actor, and a
     // `graphChanged` frame is far larger than a socket's send buffer, so writing it
@@ -3372,8 +3418,9 @@ public actor GraphStore {
       // waiting for the read loop to notice, so a dead connection can't accumulate
       // failed broadcast attempts.
       connections.removeValue(forKey: connectionID)
-      return
+      return false
     }
+    return true
   }
 
   /// Predicate-evaluation state shared between a project store and every sub-graph