From 7c91e09e10e23dbe3b872ac9e655486bc42d6b52 Mon Sep 17 00:00:00 2001 From: fitz123 <10243861+fitz123@users.noreply.github.com> Date: Thu, 21 May 2026 20:49:47 +0400 Subject: [PATCH 1/3] =?UTF-8?q?feat:=20timestamped=20sync=20log=20+=20menu?= =?UTF-8?q?bar=20Show=20logs=E2=80=A6=20opens=20log=20dir?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cmd/bb-vpn/sync.go: - every sync line is now prefixed with a UTC RFC3339.000Z timestamp, so /Library/Logs/bb-dpi/bb-vpn-sync.log answers 'when did this tick happen' directly. Before, the only timestamp was the bundle's publish-time issued_at, which is the operator-side publish moment, not the client-side sync moment. - ok line now carries duration_ms (HTTPS fetch + render + kickstart wall-time) so a slow control-plane endpoint is visible at a glance. - ok line now surfaces inbox_drain_err=… when InboxDrainErr was set. Previously this non-fatal error was only readable via status.json; now it's in the log alongside the OK so an inbox-perm accident doesn't hide behind 'everything is fine'. - centralized through a small logSync() helper so all sync stderr goes through one timestamp formatter. client/menubar: - 'Show log…' menu item is now 'Show logs…' and opens /Library/Logs/bb-dpi/ in Finder. Previously it opened status.json, which is just one of the things you might want to look at — and daemon logs (sing-box.log, xray.log, bb-vpn-sync.log, bb-vpn-menubar.log) are what an operator usually reaches for when the menubar goes yellow. Finder lets the user pick a file by name without needing 'sudo cat' from a terminal. --- README.md | 2 +- client/bb-vpn/cmd/bb-vpn/sync.go | 39 +++++++++++++++++++++--- client/menubar/BBVPN/BBVPNApp.swift | 13 ++++++-- client/menubar/BBVPN/EnrollHandler.swift | 4 +++ client/menubar/README.md | 3 +- 5 files changed, 51 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index dd19d9f..418aabd 100644 --- a/README.md +++ b/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 `*.` 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 diff --git a/client/bb-vpn/cmd/bb-vpn/sync.go b/client/bb-vpn/cmd/bb-vpn/sync.go index 52b3d13..f9cce9c 100644 --- a/client/bb-vpn/cmd/bb-vpn/sync.go +++ b/client/bb-vpn/cmd/bb-vpn/sync.go @@ -3,6 +3,7 @@ package main import ( "fmt" "os" + "time" "bb-dpi/client/bb-vpn/pkg/launchctl" "bb-dpi/client/bb-vpn/pkg/state" @@ -15,11 +16,19 @@ 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 line written to stderr begins with a UTC RFC3339 +// timestamp 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 + start := time.Now().UTC() if os.Geteuid() != 0 { - fmt.Fprintln(os.Stderr, "bb-vpn sync: requires root (run via launchd or sudo)") + logSync(start, "requires root (run via launchd or sudo)") return exitUsage } @@ -32,15 +41,35 @@ 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(start, 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(start, "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(start, msg) return 0 } + +// logSync writes " bb-vpn sync: \n" to stderr. +// The launchd plist redirects stderr to /Library/Logs/bb-dpi/bb-vpn-sync.log, +// so this is the canonical log entrypoint for the sync daemon. The +// timestamp uses RFC3339 with millisecond precision — enough to +// distinguish back-to-back ticks (e.g., an enroll-triggered WatchPaths +// sync immediately followed by a forced sync) without the noise of +// nanoseconds. +func logSync(t time.Time, msg string) { + fmt.Fprintf(os.Stderr, "%s bb-vpn sync: %s\n", t.Format("2006-01-02T15:04:05.000Z"), msg) +} diff --git a/client/menubar/BBVPN/BBVPNApp.swift b/client/menubar/BBVPN/BBVPNApp.swift index 47602f9..6aa865e 100644 --- a/client/menubar/BBVPN/BBVPNApp.swift +++ b/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 diff --git a/client/menubar/BBVPN/EnrollHandler.swift b/client/menubar/BBVPN/EnrollHandler.swift index c2394ef..d77f9a6 100644 --- a/client/menubar/BBVPN/EnrollHandler.swift +++ b/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. diff --git a/client/menubar/README.md b/client/menubar/README.md index 1f5c497..9181714 100644 --- a/client/menubar/README.md +++ b/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 From 8c2dd9cd3ec346bc59b1eff8bcc83a050e958853 Mon Sep 17 00:00:00 2001 From: fitz123 <10243861+fitz123@users.noreply.github.com> Date: Thu, 21 May 2026 20:54:44 +0400 Subject: [PATCH 2/3] fix(sync-log): emit-time stamp + per-line prefix for multi-line errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Round 1 multi-review findings: - Codex (medium 0.86): logSync prefixed only the first physical line. sing-box check / xray -test failures dump multi-line stderr into res.Err — continuation lines landed in bb-vpn-sync.log un-timestamped, breaking grep-by-timestamp diagnosis on the exact paths operators need most. Fix: logSync now strings.TrimRight's trailing \n and splits on \n, emitting one timestamped 'bb-vpn sync:' line per physical line. - Opus (low 0.85): the entry-time start := time.Now().UTC() was reused as BOTH the duration_ms base AND the log-line prefix. On a slow tick (perEndpointTimeout=5s × failover + 5s reboot-recovery sleep + kickstart cost) the prefix could lag emit-time by 10s+, misordering a casual grep-and-sort. Fix: logSync stamps time.Now().UTC() at emit time. start is now used only for duration_ms. Side benefit: removes the foot-gun where a future caller could pass a non-UTC time.Time and the literal 'Z' in the format would silently lie. - Opus (low 0.95): doc-comment said 'RFC3339Nano' but format is millisecond. Rewritten to match. Also wired logSyncOut io.Writer (defaults to os.Stderr) so sync_test.go can capture output in a bytes.Buffer. New tests cover: - multi-line: every physical line carries the timestamp prefix - single-line: no spurious empty trailing line - trailing \n: strings.Split foot-gun doesn't produce empty entry --- client/bb-vpn/cmd/bb-vpn/sync.go | 56 +++++++++++++------ client/bb-vpn/cmd/bb-vpn/sync_test.go | 80 +++++++++++++++++++++++++++ 2 files changed, 118 insertions(+), 18 deletions(-) create mode 100644 client/bb-vpn/cmd/bb-vpn/sync_test.go diff --git a/client/bb-vpn/cmd/bb-vpn/sync.go b/client/bb-vpn/cmd/bb-vpn/sync.go index f9cce9c..2b0a97c 100644 --- a/client/bb-vpn/cmd/bb-vpn/sync.go +++ b/client/bb-vpn/cmd/bb-vpn/sync.go @@ -2,7 +2,9 @@ package main import ( "fmt" + "io" "os" + "strings" "time" "bb-dpi/client/bb-vpn/pkg/launchctl" @@ -17,18 +19,19 @@ import ( // is state.Path("bin")) and BB_VPN_DEV (skip kickstart calls for // dev-mode use on macold or similar). // -// Log lines: every line written to stderr begins with a UTC RFC3339 -// timestamp 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 — +// 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 start := time.Now().UTC() if os.Geteuid() != 0 { - logSync(start, "requires root (run via launchd or sudo)") + logSync("requires root (run via launchd or sudo)") return exitUsage } @@ -43,9 +46,9 @@ func syncCmd(args []string) int { res := launchctl.Tick(opts) durMS := time.Since(start).Milliseconds() if res.Err != nil { - logSync(start, fmt.Sprintf("error duration_ms=%d: %v", durMS, res.Err)) + logSync(fmt.Sprintf("error duration_ms=%d: %v", durMS, res.Err)) if res.BlackholeEntered { - logSync(start, "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 @@ -59,17 +62,34 @@ func syncCmd(args []string) int { msg += fmt.Sprintf(" inbox_drain_err=%q", res.InboxDrainErr.Error()) } msg += ")" - logSync(start, msg) + logSync(msg) return 0 } -// logSync writes " bb-vpn sync: \n" to stderr. -// The launchd plist redirects stderr to /Library/Logs/bb-dpi/bb-vpn-sync.log, -// so this is the canonical log entrypoint for the sync daemon. The -// timestamp uses RFC3339 with millisecond precision — enough to -// distinguish back-to-back ticks (e.g., an enroll-triggered WatchPaths -// sync immediately followed by a forced sync) without the noise of -// nanoseconds. -func logSync(t time.Time, msg string) { - fmt.Fprintf(os.Stderr, "%s bb-vpn sync: %s\n", t.Format("2006-01-02T15:04:05.000Z"), msg) +// 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) + } } diff --git a/client/bb-vpn/cmd/bb-vpn/sync_test.go b/client/bb-vpn/cmd/bb-vpn/sync_test.go new file mode 100644 index 0000000..39138dd --- /dev/null +++ b/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()) + } +} From 0c88ec5a683da93c9274488d09444887ea2a5f5a Mon Sep 17 00:00:00 2001 From: fitz123 <10243861+fitz123@users.noreply.github.com> Date: Thu, 21 May 2026 21:04:13 +0400 Subject: [PATCH 3/3] fix(sync): preserve monotonic clock for duration_ms MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Copilot review on PR #30 caught a Go gotcha: `time.Now().UTC()` strips the monotonic clock reading (per Go's time package docs — any `In`/`Local`/`UTC` operation drops it). `time.Since(start)` then becomes wall-clock-based and can produce wrong or even negative duration_ms if NTP or a manual clock change steps the system clock during the sync tick. After the round-1 refactor that moved emit-time stamping into logSync, the `start` var is only used for duration math — `time.Now()` is sufficient and preserves monotonic. One-line fix. --- client/bb-vpn/cmd/bb-vpn/sync.go | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/client/bb-vpn/cmd/bb-vpn/sync.go b/client/bb-vpn/cmd/bb-vpn/sync.go index 2b0a97c..a0ccdee 100644 --- a/client/bb-vpn/cmd/bb-vpn/sync.go +++ b/client/bb-vpn/cmd/bb-vpn/sync.go @@ -28,7 +28,12 @@ import ( // previously inbox-drain errors only appeared on status.json. func syncCmd(args []string) int { _ = args // sync takes no flags today - start := time.Now().UTC() + // 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 { logSync("requires root (run via launchd or sudo)")