feat(logs): timestamped sync log + menubar Show logs… opens log dir

README.md

@@ -31,7 +31,7 @@ make list
   - sing-box native VLESS for TCP+vision fallback
 - **Tailscale (corporate access)**: by default the Mac is a thin VLESS client and the **VPN exit** runs Tailscale. IP-level corporate traffic (`10.x`, `100.64.x`) tunnels through VLESS → exit server's xray → kernel routes via the exit's Tailscale interface → tailnet *by default*. **Hostname resolution** for `*.<COMPANY_DOMAIN>` requires `--with-corp-dns` at render time — without it, corp domains resolve via `1.1.1.1` (which has no internal records). The exit must run `tailscale up --accept-routes` (**required**, not optional — without it the kernel won't have the corp routes that xray's `freedom` outbound depends on) and be tagged with whatever ACL grants corp access. Opt into per-Mac embedded tsnet with `--with-tailscale` if you need per-laptop tailnet identity instead.
 - **Auto-failover**: urltest probes both transports every 30s, instant switchover on failure
-- **BBVPN.app (menu-bar)**: installed by the .pkg flow to `/Applications/BBVPN.app`. Registers the `bb-vpn://enroll?uuid=…` URL scheme so the operator-shared enrollment link works on first click, and shows a colored dot in the menu bar (green/yellow/grey) with status details + a "Show log…" action. Polls `/Library/Application Support/bb-dpi/status.json` every 5s and shells out to `bb-vpn enroll` on URI receipt, which writes one `inbox/enroll-*.json` request file for the root daemon to ingest — no other writes to `/Library/`. Daemon lifecycle (start / stop / sync) lives in the `bb-vpn` CLI (`sudo bb-vpn start|stop|sync`); the menubar is status + URI enroll only.
+- **BBVPN.app (menu-bar)**: installed by the .pkg flow to `/Applications/BBVPN.app`. Registers the `bb-vpn://enroll?uuid=…` URL scheme so the operator-shared enrollment link works on first click, and shows a colored dot in the menu bar (green/yellow/grey) with status details + a "Show logs…" action that opens `/Library/Logs/bb-dpi/` in Finder. Polls `/Library/Application Support/bb-dpi/status.json` every 5s and shells out to `bb-vpn enroll` on URI receipt, which writes one `inbox/enroll-*.json` request file for the root daemon to ingest — no other writes to `/Library/`. Daemon lifecycle (start / stop / sync) lives in the `bb-vpn` CLI (`sudo bb-vpn start|stop|sync`); the menubar is status + URI enroll only.
 
 ## Server Hardening
 

client/bb-vpn/cmd/bb-vpn/sync.go

@@ -2,7 +2,10 @@ package main
 
 import (
 	"fmt"
+	"io"
 	"os"
+	"strings"
+	"time"
 
 	"bb-dpi/client/bb-vpn/pkg/launchctl"
 	"bb-dpi/client/bb-vpn/pkg/state"
@@ -15,11 +18,25 @@ import (
 // Honors BB_VPN_BIN_DIR (override the binary lookup dir; production
 // is state.Path("bin")) and BB_VPN_DEV (skip kickstart calls for
 // dev-mode use on macold or similar).
+//
+// Log lines: every physical line written to stderr begins with a UTC
+// RFC3339 timestamp (millisecond precision) so
+// /Library/Logs/bb-dpi/bb-vpn-sync.log answers "when did this tick
+// happen" directly. The OK line also carries duration_ms (so a slow
+// control-plane fetch / kickstart is visible at a glance) and
+// surfaces inbox_drain_err when that non-fatal failure occurs —
+// previously inbox-drain errors only appeared on status.json.
 func syncCmd(args []string) int {
 	_ = args // sync takes no flags today
+	// time.Now() preserves Go's monotonic clock reading; .UTC()
+	// would strip it and make time.Since() wall-clock-based, which
+	// could produce wrong (or negative) duration_ms if NTP stepped
+	// the clock during the tick. logSync stamps its own UTC emit
+	// time, so we don't need a UTC `start` here anyway.
+	start := time.Now()
 
 	if os.Geteuid() != 0 {
-		fmt.Fprintln(os.Stderr, "bb-vpn sync: requires root (run via launchd or sudo)")
+		logSync("requires root (run via launchd or sudo)")
 		return exitUsage
 	}
 
@@ -32,15 +49,52 @@ func syncCmd(args []string) int {
 		DevMode: os.Getenv("BB_VPN_DEV") == "1",
 	}
 	res := launchctl.Tick(opts)
+	durMS := time.Since(start).Milliseconds()
 	if res.Err != nil {
-		fmt.Fprintf(os.Stderr, "bb-vpn sync: %v\n", res.Err)
+		logSync(fmt.Sprintf("error duration_ms=%d: %v", durMS, res.Err))
 		if res.BlackholeEntered {
-			fmt.Fprintln(os.Stderr, "bb-vpn sync: entered runtime_blackhole — run `sudo bb-vpn recover` to recover")
+			logSync("entered runtime_blackhole — run `sudo bb-vpn recover` to recover")
 			return exitSoftware
 		}
 		return exitSoftware
 	}
-	fmt.Fprintf(os.Stderr, "bb-vpn sync: ok (issued_at=%s servers=%d xray=%v rendered=%v promoted=%v kickstarted=%v)\n",
-		res.BundleIssuedAt, res.ServerCount, res.XrayNeeded, res.Rendered, res.Promoted, res.Kickstarted)
+	// Build the OK line. inbox_drain_err is non-fatal but worth
+	// surfacing alongside the OK so a perms accident on inbox/ is
+	// visible without reading status.json separately.
+	msg := fmt.Sprintf("ok (duration_ms=%d issued_at=%s servers=%d xray=%v rendered=%v promoted=%v kickstarted=%v",
+		durMS, res.BundleIssuedAt, res.ServerCount, res.XrayNeeded, res.Rendered, res.Promoted, res.Kickstarted)
+	if res.InboxDrainErr != nil {
+		msg += fmt.Sprintf(" inbox_drain_err=%q", res.InboxDrainErr.Error())
+	}
+	msg += ")"
+	logSync(msg)
 	return 0
 }
+
+// logSyncOut is the destination logSync writes to. Defaults to
+// os.Stderr (which the launchd plist redirects to
+// /Library/Logs/bb-dpi/bb-vpn-sync.log). Tests rewire it to a buffer.
+var logSyncOut io.Writer = os.Stderr
+
+// logSync writes one or more physical lines to logSyncOut, each
+// prefixed with the current UTC timestamp (millisecond precision) and
+// the "bb-vpn sync:" component tag.
+//
+// The timestamp is stamped at emit time (not call time captured by the
+// caller) so it can't lag behind: a slow tick that captured start at
+// T0 and only reaches logSync at T0+10s will stamp T0+10s on its OK
+// line, matching when the line actually hit the log.
+//
+// msg may contain embedded newlines (e.g., sing-box check / xray -test
+// dumps multi-line stderr into res.Err). Splitting+prefixing per
+// physical line keeps the log grep-friendly: every line that lands in
+// bb-vpn-sync.log is timestamped, not just the first.
+func logSync(msg string) {
+	t := time.Now().UTC().Format("2006-01-02T15:04:05.000Z")
+	// Drop the trailing newline so we don't emit a spurious empty
+	// prefixed line at the end; the per-line loop adds its own \n.
+	msg = strings.TrimRight(msg, "\n")
+	for _, line := range strings.Split(msg, "\n") {
+		fmt.Fprintf(logSyncOut, "%s bb-vpn sync: %s\n", t, line)
+	}
+}

client/bb-vpn/cmd/bb-vpn/sync_test.go

@@ -0,0 +1,80 @@
+package main
+
+import (
+	"bytes"
+	"regexp"
+	"strings"
+	"testing"
+)
+
+// TestLogSync_MultilineMessage covers the regression Codex caught in
+// the round-1 review: sing-box check / xray -test failures get folded
+// into res.Err and contain embedded \n. The previous version of
+// logSync prefixed only the FIRST physical line, leaving continuation
+// lines un-timestamped in /Library/Logs/bb-dpi/bb-vpn-sync.log and
+// breaking grep-by-timestamp diagnosis.
+func TestLogSync_MultilineMessage(t *testing.T) {
+	var buf bytes.Buffer
+	orig := logSyncOut
+	logSyncOut = &buf
+	defer func() { logSyncOut = orig }()
+
+	logSync("error duration_ms=42: first line\nsecond line\nthird line")
+
+	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
+	if len(lines) != 3 {
+		t.Fatalf("expected 3 physical lines, got %d: %q", len(lines), buf.String())
+	}
+	// Every line must start with a millisecond-precision RFC3339 UTC
+	// timestamp followed by " bb-vpn sync: ".
+	pattern := regexp.MustCompile(`^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z bb-vpn sync: `)
+	expectedTails := []string{
+		"error duration_ms=42: first line",
+		"second line",
+		"third line",
+	}
+	for i, line := range lines {
+		if !pattern.MatchString(line) {
+			t.Errorf("line %d missing timestamp prefix: %q", i, line)
+		}
+		if !strings.HasSuffix(line, expectedTails[i]) {
+			t.Errorf("line %d wrong tail: got %q, want suffix %q", i, line, expectedTails[i])
+		}
+	}
+}
+
+// TestLogSync_SingleLineMessage is the happy path: a one-line message
+// produces one prefixed line, no spurious empty trailing line.
+func TestLogSync_SingleLineMessage(t *testing.T) {
+	var buf bytes.Buffer
+	orig := logSyncOut
+	logSyncOut = &buf
+	defer func() { logSyncOut = orig }()
+
+	logSync("ok (duration_ms=123)")
+
+	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
+	if len(lines) != 1 {
+		t.Fatalf("expected 1 physical line, got %d: %q", len(lines), buf.String())
+	}
+	if !strings.HasSuffix(lines[0], "bb-vpn sync: ok (duration_ms=123)") {
+		t.Errorf("unexpected output: %q", lines[0])
+	}
+}
+
+// TestLogSync_TrailingNewlineDoesNotEmitEmptyLine guards against the
+// strings.Split foot-gun where "msg\n" → ["msg", ""] would otherwise
+// produce a spurious empty timestamped line.
+func TestLogSync_TrailingNewlineDoesNotEmitEmptyLine(t *testing.T) {
+	var buf bytes.Buffer
+	orig := logSyncOut
+	logSyncOut = &buf
+	defer func() { logSyncOut = orig }()
+
+	logSync("trailing newline\n")
+
+	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
+	if len(lines) != 1 {
+		t.Fatalf("expected 1 physical line, got %d: %q", len(lines), buf.String())
+	}
+}

client/menubar/BBVPN/BBVPNApp.swift

@@ -6,7 +6,9 @@
 //   grey    — not enrolled (status.json absent or missing identity)
 //
 // Menu items (see `menuContent` below):
-//   "Show log…"    — opens status.json in the user's default JSON viewer.
+//   "Show logs…"   — opens /Library/Logs/bb-dpi/ in Finder so the user
+//                    can pick sing-box.log / xray.log / bb-vpn-sync.log
+//                    (etc.) directly without `sudo cat` from a terminal.
 //   "Quit"
 //
 // Daemon lifecycle (start / stop / sync) deliberately lives in the
@@ -85,8 +87,13 @@ struct BBVPNApp: App {
 
         Divider()
 
-        Button("Show log…") {
-            NSWorkspace.shared.open(EnrollHandler.statusFileURL)
+        Button("Show logs…") {
+            // Opens /Library/Logs/bb-dpi/ in Finder. Console.app
+            // can read these too, but Finder lets the user pick a
+            // file by name (sing-box.log, xray.log, bb-vpn-sync.log,
+            // bb-vpn-menubar.log) and open it with their preferred
+            // viewer.
+            NSWorkspace.shared.open(EnrollHandler.logDirURL)
         }
         // Daemon lifecycle (start / stop / sync) lives in the
         // `bb-vpn` CLI — run from a terminal with sudo. Menubar is

client/menubar/BBVPN/EnrollHandler.swift

@@ -13,6 +13,10 @@ import Foundation
 enum EnrollHandler {
     static let appSupportURL = URL(fileURLWithPath: "/Library/Application Support/bb-dpi")
     static let statusFileURL = appSupportURL.appendingPathComponent("status.json")
+    // Directory the daemon logs land in (sing-box, xray, bb-vpn sync,
+    // bb-vpn menubar). The "Show logs…" menu item opens this in
+    // Finder so the user can pick the file they want.
+    static let logDirURL = URL(fileURLWithPath: "/Library/Logs/bb-dpi", isDirectory: true)
     // Absolute path to the bb-vpn binary the .pkg installs. Using the
     // private-path binary directly (not ~/.local/bin/bb-vpn) so the
     // menubar works even if the user's PATH or symlink is broken.

client/menubar/README.md

@@ -12,7 +12,8 @@ Tiny SwiftUI menu-bar app. Two responsibilities:
    `/Library/Application Support/bb-dpi/inbox/` for the root daemon
    to ingest.
 
-Menu items: just **Show log…** + **Quit**. Daemon lifecycle (`start`,
+Menu items: just **Show logs…** (opens `/Library/Logs/bb-dpi/` in Finder)
++ **Quit**. Daemon lifecycle (`start`,
 `stop`, `sync`) lives in the `bb-vpn` CLI and requires `sudo`. This
 avoids the macOS privilege-escalation gymnastics that an in-menubar
 Start/Stop would need (osascript admin prompts on every click, or an