perf: traces and perf improvements (#3471)

src/backend/controllers/system/SystemController.js

@@ -3,18 +3,19 @@
  *
  * This file is part of Puter.
  *
- * Puter is free software: you can redistribute it and/or modify
- * it under the terms of the GNU Affero General Public License as published
- * by the Free Software Foundation, either version 3 of the License, or
- * (at your option) any later version.
+ * Puter is free software: you can redistribute it and/or modify it under the
+ * terms of the GNU Affero General Public License as published by the Free
+ * Software Foundation, either version 3 of the License, or (at your option) any
+ * later version.
  *
- * This program is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- * GNU Affero General Public License for more details.
+ * This program is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
+ * FOR A PARTICULAR PURPOSE. See the GNU Affero General Public License for more
+ * details.
  *
  * You should have received a copy of the GNU Affero General Public License
- * along with this program.  If not, see <https://www.gnu.org/licenses/>.
+ * along with this program. If not, see
+ * [https://www.gnu.org/licenses/](https://www.gnu.org/licenses/).
  */
 
 import { HttpError } from '../../core/http/HttpError.js';
@@ -75,6 +76,11 @@ export class SystemController extends PuterController {
                 process.env.npm_package_version ??
                 'unknown';
             const parts = String(version).split('.');
+            // Deploy-constant, and callers poll it. Cache per-client only:
+            // a shared cache could pin one region's `location` for everyone,
+            // and the short window still bounds how long a client can miss a
+            // new deploy.
+            res.setHeader('Cache-Control', 'private, max-age=60');
             res.json({
                 version,
                 major: parts[0] ? Number(parts[0]) : null,

src/backend/controllers/system/SystemController.test.ts

@@ -75,6 +75,7 @@ const makeUser = async (): Promise<{ actor: Actor; userId: number }> => {
 interface CapturedResponse {
     statusCode: number;
     body: unknown;
+    headers: Record<string, unknown>;
 }
 
 const makeReq = (init: {
@@ -91,7 +92,11 @@ const makeReq = (init: {
 };
 
 const makeRes = () => {
-    const captured: CapturedResponse = { statusCode: 200, body: undefined };
+    const captured: CapturedResponse = {
+        statusCode: 200,
+        body: undefined,
+        headers: {},
+    };
     const res = {
         json: vi.fn((value: unknown) => {
             captured.body = value;
@@ -105,7 +110,10 @@ const makeRes = () => {
             captured.statusCode = code;
             return res;
         }),
-        setHeader: vi.fn(() => res),
+        setHeader: vi.fn((name: string, value: unknown) => {
+            captured.headers[name] = value;
+            return res;
+        }),
     };
     return { res: res as unknown as Response, captured };
 };
@@ -342,6 +350,12 @@ describe('SystemController GET /version', () => {
         expect(body.environment).toBe('dev');
         expect(typeof body.deploy_timestamp).toBe('number');
     });
+
+    it('is cacheable per-client but never by a shared cache', async () => {
+        const { res, captured } = makeRes();
+        await callRoute('get', '/version', makeReq({}), res);
+        expect(captured.headers['Cache-Control']).toBe('private, max-age=60');
+    });
 });
 
 // ── /contactUs ──────────────────────────────────────────────────────

src/backend/core/http/middleware/authProbe.test.ts

@@ -699,6 +699,71 @@ describe('createAuthProbe — reauth signal', () => {
         }
     });
 
+    it('collapses repeat reauth lines for the same auth_id to one', async () => {
+        const stub = makeStubAuth();
+        const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+        try {
+            const probe = createAuthProbe({ authService: stub.service });
+            for (let i = 0; i < 5; i++) {
+                stub.setNextResult({
+                    reauth: { reason: 'token_v1', auth_id: 'u-noisy' },
+                });
+                await runProbe(
+                    probe,
+                    makeReq({ headers: { authorization: 'Bearer tok' } }),
+                );
+            }
+            const reauthCalls = infoSpy.mock.calls.filter((args) =>
+                String(args[0]).startsWith('[auth-v2] reauth'),
+            );
+            expect(reauthCalls).toHaveLength(1);
+        } finally {
+            infoSpy.mockRestore();
+        }
+    });
+
+    it('still logs separately for a different auth_id', async () => {
+        const stub = makeStubAuth();
+        const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+        try {
+            const probe = createAuthProbe({ authService: stub.service });
+            for (const authId of ['u-a', 'u-b']) {
+                stub.setNextResult({
+                    reauth: { reason: 'token_v1', auth_id: authId },
+                });
+                await runProbe(
+                    probe,
+                    makeReq({ headers: { authorization: 'Bearer tok' } }),
+                );
+            }
+            const reauthCalls = infoSpy.mock.calls.filter((args) =>
+                String(args[0]).startsWith('[auth-v2] reauth'),
+            );
+            expect(reauthCalls).toHaveLength(2);
+        } finally {
+            infoSpy.mockRestore();
+        }
+    });
+
+    it('does not sign a reauth token until something reads it', async () => {
+        const stub = makeStubAuth();
+        stub.setNextResult({
+            reauth: { reason: 'token_v1', auth_id: 'u-lazy' },
+        });
+        const signSpy = vi.spyOn(stub.service, 'signReauthToken');
+        const { req } = await runProbe(
+            createAuthProbe({ authService: stub.service }),
+            makeReq({ headers: { authorization: 'Bearer tok' } }),
+        );
+
+        expect(signSpy).not.toHaveBeenCalled();
+        expect(req.requiresReauth?.reauth_token).toBeTruthy();
+        expect(signSpy).toHaveBeenCalledTimes(1);
+        // Memoized — a second read must not re-sign.
+        void req.requiresReauth?.reauth_token;
+        expect(signSpy).toHaveBeenCalledTimes(1);
+    });
+
     it('does not emit a reauth log line on a healthy v2 verify', async () => {
         const stub = makeStubAuth({ user: { uuid: 'u-1' } });
         const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});

src/backend/core/http/middleware/authProbe.ts

@@ -57,8 +57,35 @@ interface AuthProbeOptions {
  * 5. `?auth_token=...` query param
  * 6. Socket handshake query (for ws upgrades that pass through HTTP first)
  */
+// Reauth is a property of a session, not an event: a client still holding a
+// legacy token repeats the identical line on every request it makes, which
+// buries every other log line without adding information. Keep the forensic
+// signal but emit it at most once per auth_id per window.
+const REAUTH_LOG_WINDOW_MS = 10 * 60 * 1000;
+// Bounds the map so a flood of distinct ids can't grow it without limit.
+const REAUTH_LOG_MAX_KEYS = 1024;
+
 export const createAuthProbe = (opts: AuthProbeOptions): RequestHandler => {
     const { authService, cookieName } = opts;
+
+    const reauthLoggedAt = new Map<string, number>();
+    const shouldLogReauth = (key: string): boolean => {
+        const now = Date.now();
+        const last = reauthLoggedAt.get(key);
+        if (last !== undefined && now - last < REAUTH_LOG_WINDOW_MS) {
+            return false;
+        }
+        if (reauthLoggedAt.size >= REAUTH_LOG_MAX_KEYS) {
+            // Map iterates in insertion order and every log re-inserts, so
+            // the first key is the least recently logged.
+            const oldest = reauthLoggedAt.keys().next().value;
+            if (oldest !== undefined) reauthLoggedAt.delete(oldest);
+        }
+        reauthLoggedAt.delete(key);
+        reauthLoggedAt.set(key, now);
+        return true;
+    };
+
     return async (req, _res, next): Promise<void> => {
         // If something upstream already attached an actor, respect it.
         if (req.actor) {
@@ -83,21 +110,42 @@ export const createAuthProbe = (opts: AuthProbeOptions): RequestHandler => {
             });
 
             if (result.reauth) {
+                const { reason, auth_id } = result.reauth;
                 // Bind a short-lived JWT proving the rejected session
                 // identified this auth_id. The GUI echoes this back on
                 // /login or /signup; the raw auth_id is informational
                 // only and is not accepted as authoritative on its own.
-                const reauth_token = result.reauth.auth_id
-                    ? authService.signReauthToken(result.reauth.auth_id)
-                    : undefined;
+                //
+                // Signed on read, not here: a legacy-but-still-valid token
+                // sets `reauth` on a request that then succeeds, and only
+                // the 401 path ever reads the token, so signing eagerly
+                // burns a JWT per request for a value nobody looks at.
+                let signed = false;
+                let signedToken: string | undefined;
                 req.requiresReauth = {
-                    reason: result.reauth.reason as ReauthReason,
-                    auth_id: result.reauth.auth_id,
-                    ...(reauth_token ? { reauth_token } : {}),
+                    reason: reason as ReauthReason,
+                    auth_id,
+                    get reauth_token() {
+                        if (!signed) {
+                            signed = true;
+                            try {
+                                signedToken = auth_id
+                                    ? authService.signReauthToken(auth_id)
+                                    : undefined;
+                            } catch {
+                                // Losing the hint is survivable; the client
+                                // still gets `reauth_required` and can log in.
+                                signedToken = undefined;
+                            }
+                        }
+                        return signedToken;
+                    },
                 };
-                console.info(
-                    `[auth-v2] reauth reason=${result.reauth.reason} auth_id=${result.reauth.auth_id ?? '-'}`,
-                );
+                if (shouldLogReauth(`${reason}:${auth_id ?? '-'}`)) {
+                    console.info(
+                        `[auth-v2] reauth reason=${reason} auth_id=${auth_id ?? '-'}`,
+                    );
+                }
             }
 
             if (result.blocked) {

src/gui/src/globals.js

@@ -233,15 +233,26 @@ window.PANEL_WIDTH = 400;
 
 // the transaction class
 window.Transaction = class {
-    constructor (name) {
+    constructor (name, attributes = {}) {
         this.name = name;
         this.id = uuidv4();
+        // Reported alongside the timing so a slow transaction can be
+        // attributed to a particular subject rather than only a name.
+        this.attributes = { ...attributes };
     }
 
     start () {
         this.start_ts = Date.now();
     }
 
+    /**
+     * Annotate the transaction with anything learned after it started (the
+     * resolved app name, which entry point triggered it, how it finished).
+     */
+    annotate (attributes) {
+        Object.assign(this.attributes, attributes);
+    }
+
     getDuration () {
         return Date.now() - this.start_ts;
     }

src/gui/src/helpers/launch_app.js

@@ -52,8 +52,9 @@ const getLaunchResult = (launchOutcome) => {
     return null;
 };
 
-const endLaunchTransaction = (transaction) => {
+const endLaunchTransaction = (transaction, outcome) => {
     if ( transaction ) {
+        if ( outcome ) transaction.annotate({ outcome });
         transaction.end();
     }
 };
@@ -119,7 +120,17 @@ const launch_app = async (options) => {
     // for it to be ready.
     // Explorer is a special case, it's not an app per se, so it doesn't need a transaction.
     if ( options?.name !== 'explorer' ) {
-        transaction = new window.Transaction('app-is-ready');
+        // Attribute the timing: the same span covers a tile click on a warm
+        // dashboard and a cold landing on /app/<name>, which are different
+        // enough that a combined percentile describes neither.
+        transaction = new window.Transaction('app-is-ready', {
+            'launch.app': options?.name ?? options?.app_obj?.name ?? 'unknown',
+            'launch.dashboard_mode': !! window.is_dashboard_mode,
+            'launch.from_app_url':
+                typeof window.location?.pathname === 'string'
+                && window.location.pathname.startsWith('/app/'),
+            'launch.has_app_obj': !! options?.app_obj,
+        });
         transaction.start();
     }
 
@@ -154,6 +165,7 @@ const launch_app = async (options) => {
 
     // If no `options.name` is provided, use the app name from the app_info
     options.name = options.name ?? app_info.name;
+    transaction?.annotate({ 'launch.app': options.name ?? 'unknown' });
     const requestedAppName = options.privateLaunchRequestedAppName ?? options.name ?? app_info.name ?? null;
     const privateAccessDecision = normalizePrivateAccessDecision(app_info.privateAccess);
 
@@ -191,7 +203,7 @@ const launch_app = async (options) => {
                 fallbackLaunchOutcome.launchResult = redirectedLaunchResult;
             }
 
-            endLaunchTransaction(transaction);
+            endLaunchTransaction(transaction, 'redirected-to-fallback');
             return fallbackLaunchOutcome ?? { launchResult: redirectedLaunchResult };
         }
 
@@ -217,7 +229,7 @@ const launch_app = async (options) => {
             deniedPrivateAccess: true,
             privateAccess: privateAccessDecision,
         };
-        endLaunchTransaction(transaction);
+        endLaunchTransaction(transaction, 'denied-private-access');
         return { launchResult: deniedLaunchResult };
     }
 
@@ -480,7 +492,7 @@ const launch_app = async (options) => {
                     privateAccess: privateAccessDecision ?? undefined,
                     authTokenAcquired: false,
                 };
-                endLaunchTransaction(transaction);
+                endLaunchTransaction(transaction, 'token-unavailable');
                 return { launchResult: tokenFailureLaunchResult };
             }
         }
@@ -722,7 +734,7 @@ const launch_app = async (options) => {
     };
 
     // end the transaction
-    endLaunchTransaction(transaction);
+    endLaunchTransaction(transaction, 'launched');
 
     return process;
 };

src/gui/src/index.js

@@ -80,8 +80,16 @@ window.gui = async (options) => {
         // await window.loadCSS('/dist/bundle.min.css');
     }
 
-    // Load Cloudflare Turnstile script
-    await window.loadScript('https://challenges.cloudflare.com/turnstile/v0/api.js', { defer: true });
+    // Load the captcha script alongside the GUI rather than ahead of it.
+    // Nothing during boot needs it — the challenge modal polls for the
+    // global and the signup form is opened long after — so awaiting it here
+    // only put a third-party round trip in front of every page load. Skipped
+    // entirely when no site key is configured, since every consumer gates on
+    // one.
+    if ( options.turnstileSiteKey ) {
+        window.loadScript('https://challenges.cloudflare.com/turnstile/v0/api.js', { defer: true })
+            .catch(error => console.debug('Captcha script unavailable:', error));
+    }
 
     // 🚀 Launch the GUI 🚀
     window.initgui(options);