feat(backend): log and count agentRuntimeAuth refusals by reason (TASK-712)

backend/__tests__/unit/middleware/agentRuntimeAuth.test.js

@@ -64,6 +64,8 @@ jest.mock('../../../models/Pod', () => ({
 }));
 
 const agentRuntimeAuth = require('../../../middleware/agentRuntimeAuth').default;
+const { agentAuthRefusalCounts, resetAgentAuthRefusalsForTest } = require('../../../services/agentAuthRefusals');
+const { findOne: mockCredentialFindOne } = require('../../../models/AgentCredential');
 
 const buildReq = (token) => {
   const headers = { authorization: `Bearer ${token}` };
@@ -256,3 +258,126 @@ describe('agentRuntimeAuth path 1 (User-row token) — first-use starter hook (#
     expect(next).not.toHaveBeenCalled();
   });
 });
+
+// TASK-712: every refusal branch logs one reason line and counts it, and the
+// token never appears in what is logged.
+describe('agentRuntimeAuth refusals are logged and counted (TASK-712)', () => {
+  const TOKEN = 'cm_agent_secret-token-value-do-not-log';
+  const FINGERPRINT_HASH = 'a1b2c3d4e5f60718293a4b5c6d7e8f90a1b2c3d4e5f60718293a4b5c6d7e8f90';
+  let warn;
+
+  const refusalLines = () => warn.mock.calls
+    .filter(([tag]) => tag === '[agent-auth-refused]')
+    .map(([, json]) => JSON.parse(json));
+  const allLoggedText = () => warn.mock.calls.map((args) => args.map(String).join(' ')).join('\n');
+
+  beforeEach(() => {
+    resetAgentAuthRefusalsForTest();
+    mockSecret.hash.mockReturnValue(FINGERPRINT_HASH);
+    warn = jest.spyOn(console, 'warn').mockImplementation(() => {});
+    mockCredentialFindOne.mockResolvedValue(null);
+  });
+  afterEach(() => warn.mockRestore());
+
+  const agentUser = (overrides = {}) => ({
+    _id: 'bot-user-1',
+    username: 'my-byo-agent',
+    isBot: true,
+    botMetadata: { agentName: 'my-byo-agent', instanceId: 'default', displayName: 'My BYO Agent' },
+    agentRuntimeTokens: [{ tokenHash: FINGERPRINT_HASH }],
+    ...overrides,
+  });
+
+  test('a missing token is refused, logged as missing_token with no fingerprint, and counted', async () => {
+    const res = buildRes();
+    const req = {
+      headers: {}, header: () => undefined, method: 'GET', baseUrl: '/api/agents/runtime',
+    };
+    await agentRuntimeAuth(req, res, jest.fn());
+    expect(res.status).toHaveBeenCalledWith(401);
+    expect(res.json).toHaveBeenCalledWith({ message: 'Missing agent token' });
+    expect(refusalLines()).toEqual([expect.objectContaining({
+      reason: 'missing_token', route: '/api/agents/runtime', method: 'GET', fingerprint: 'none',
+    })]);
+    expect(agentAuthRefusalCounts().counts.missing_token).toBe(1);
+  });
+
+  test('an unknown token is refused as invalid_token, with the first 8 hex of its hash as fingerprint', async () => {
+    mockUserFindOne.mockResolvedValue(null);
+    mockInstallationFindOne.mockResolvedValue(null);
+    const res = buildRes();
+    await agentRuntimeAuth(buildReq(TOKEN), res, jest.fn());
+    expect(res.json).toHaveBeenCalledWith({ message: 'Invalid agent token' });
+    expect(refusalLines()).toEqual([expect.objectContaining({ reason: 'invalid_token', fingerprint: 'a1b2c3d4' })]);
+    expect(agentAuthRefusalCounts().counts.invalid_token).toBe(1);
+  });
+
+  test('a User-row token with no active installation is refused as agent_not_installed', async () => {
+    mockUserFindOne.mockResolvedValue(agentUser());
+    mockInstallationFind.mockReturnValue({ lean: async () => [] });
+    const res = buildRes();
+    await agentRuntimeAuth(buildReq(TOKEN), res, jest.fn());
+    expect(res.json).toHaveBeenCalledWith({ message: 'Agent not installed' });
+    expect(refusalLines()).toEqual([
+      expect.objectContaining({ reason: 'agent_not_installed', fingerprint: 'a1b2c3d4' }),
+    ]);
+  });
+
+  test('a User-row token past its own expiry is refused as session_expired', async () => {
+    mockUserFindOne.mockResolvedValue(agentUser({
+      agentRuntimeTokens: [{ tokenHash: FINGERPRINT_HASH, expiresAt: new Date('2020-01-01T00:00:00Z') }],
+    }));
+    const res = buildRes();
+    await agentRuntimeAuth(buildReq(TOKEN), res, jest.fn());
+    expect(res.json).toHaveBeenCalledWith({ message: 'Session token expired' });
+    expect(refusalLines()).toEqual([expect.objectContaining({ reason: 'session_expired' })]);
+  });
+
+  test('a revoked credential is refused with its own reason, token_revoked', async () => {
+    mockCredentialFindOne.mockResolvedValue({ _id: 'cred-1', kind: 'runtime', status: 'revoked' });
+    const res = buildRes();
+    await agentRuntimeAuth(buildReq(TOKEN), res, jest.fn());
+    expect(res.json).toHaveBeenCalledWith({ message: 'Token revoked' });
+    expect(refusalLines()).toEqual([expect.objectContaining({ reason: 'token_revoked', fingerprint: 'a1b2c3d4' })]);
+  });
+
+  test('the token text never appears in any logged output, on any token-bearing refusal branch', async () => {
+    const branches = [
+      ['invalid_token', 'cm_agent_invalid-branch-token', () => {
+        mockUserFindOne.mockResolvedValue(null);
+        mockInstallationFindOne.mockResolvedValue(null);
+      }],
+      ['agent_not_installed', 'cm_agent_not-installed-branch-token', () => {
+        mockUserFindOne.mockResolvedValue(agentUser());
+        mockInstallationFind.mockReturnValue({ lean: async () => [] });
+      }],
+      ['session_expired', 'cm_agent_expired-branch-token', () => {
+        mockUserFindOne.mockResolvedValue(agentUser({
+          agentRuntimeTokens: [{ tokenHash: FINGERPRINT_HASH, expiresAt: new Date('2020-01-01T00:00:00Z') }],
+        }));
+      }],
+      ['token_revoked', 'cm_agent_revoked-branch-token', () => {
+        mockCredentialFindOne.mockResolvedValue({ _id: 'cred-1', kind: 'runtime', status: 'revoked' });
+      }],
+    ];
+    await branches.reduce((previous, [, token, arrange]) => previous.then(() => {
+      arrange();
+      return agentRuntimeAuth(buildReq(token), buildRes(), jest.fn());
+    }), Promise.resolve());
+    expect(refusalLines().map((line) => line.reason)).toEqual(branches.map(([reason]) => reason));
+    branches.forEach(([, token]) => {
+      expect(allLoggedText()).not.toContain(token);
+      expect(allLoggedText()).not.toContain(token.slice('cm_agent_'.length));
+    });
+  });
+
+  test('a repeated refusal from the same client is logged once and counted every time', async () => {
+    mockUserFindOne.mockResolvedValue(null);
+    mockInstallationFindOne.mockResolvedValue(null);
+    await [1, 2, 3, 4, 5].reduce((previous) => previous.then(
+      () => agentRuntimeAuth(buildReq(TOKEN), buildRes(), jest.fn()),
+    ), Promise.resolve());
+    expect(refusalLines()).toHaveLength(1);
+    expect(agentAuthRefusalCounts().counts.invalid_token).toBe(5);
+  });
+});

backend/__tests__/unit/routes/admin.agentAuthRefusals.test.js

@@ -0,0 +1,68 @@
+// The route's guard order (rate limit, auth, adminAuth) is pinned by the route
+// guard test. These cases send real requests through the router so the status
+// codes an operator sees are checked, not just the handler's return value.
+jest.mock('../../../middleware/auth', () => (req, res, next) => {
+  if (!req.headers['x-test-user']) return res.status(401).json({ message: 'No token' });
+  req.user = { id: req.headers['x-test-user'] };
+  return next();
+});
+jest.mock('../../../middleware/adminAuth', () => (req, res, next) => {
+  if (req.headers['x-test-role'] !== 'admin') return res.status(403).json({ message: 'Admin only' });
+  return next();
+});
+jest.mock('../../../middleware/ipRateLimit', () => ({
+  cloudflareIpRateLimitKeyGenerator: () => 'test-ip',
+}));
+
+const express = require('express');
+const request = require('supertest');
+const adminAgentAuthRoutes = require('../../../routes/admin/agentAuthRefusals');
+const {
+  AGENT_AUTH_REFUSAL_REASONS,
+  recordAgentAuthRefusal,
+  resetAgentAuthRefusalsForTest,
+} = require('../../../services/agentAuthRefusals');
+
+const buildApp = () => {
+  const app = express();
+  app.use('/api/admin/agent-auth', adminAgentAuthRoutes);
+  return app;
+};
+
+describe('GET /api/admin/agent-auth/refusals (TASK-712)', () => {
+  beforeEach(() => {
+    resetAgentAuthRefusalsForTest();
+  });
+
+  test('an unauthenticated request is refused with 401', async () => {
+    const res = await request(buildApp()).get('/api/admin/agent-auth/refusals');
+    expect(res.status).toBe(401);
+  });
+
+  test('an authenticated non-admin is refused with 403', async () => {
+    const res = await request(buildApp())
+      .get('/api/admin/agent-auth/refusals')
+      .set('x-test-user', 'user-1');
+    expect(res.status).toBe(403);
+  });
+
+  test('an admin gets the per-reason counts since process start', async () => {
+    recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/api/agents/runtime/context', method: 'GET', tokenHash: 'token-hash-fixture',
+    });
+    recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/api/agents/runtime/context', method: 'GET', tokenHash: 'token-hash-fixture',
+    });
+
+    const res = await request(buildApp())
+      .get('/api/admin/agent-auth/refusals')
+      .set('x-test-user', 'admin-1')
+      .set('x-test-role', 'admin');
+
+    expect(res.status).toBe(200);
+    expect(res.body.since).toEqual(expect.any(String));
+    expect(Object.keys(res.body.counts).sort()).toEqual([...AGENT_AUTH_REFUSAL_REASONS].sort());
+    expect(res.body.counts.invalid_token).toBe(2);
+    expect(res.body.counts.missing_token).toBe(0);
+  });
+});

backend/__tests__/unit/services/agentAuthRefusals.test.js

@@ -0,0 +1,92 @@
+const {
+  AGENT_AUTH_REFUSAL_REASONS, agentAuthRefusalCounts, credentialRefusalReason, recordAgentAuthRefusal,
+  refusalFingerprint, refusalRoute, resetAgentAuthRefusalsForTest,
+} = require('../../../services/agentAuthRefusals');
+
+const HASH = 'deadbeef00112233445566778899aabbccddeeff00112233445566778899aabb';
+
+describe('agentAuthRefusals (TASK-712)', () => {
+  let warn;
+  beforeEach(() => {
+    resetAgentAuthRefusalsForTest();
+    warn = jest.spyOn(console, 'warn').mockImplementation(() => {});
+  });
+  afterEach(() => warn.mockRestore());
+
+  const lines = () => warn.mock.calls.map(([, json]) => JSON.parse(json));
+
+  test('maps every fixed credential-gate message to a bounded reason', () => {
+    expect(credentialRefusalReason('Token revoked')).toBe('token_revoked');
+    expect(credentialRefusalReason('Credential owner is being deleted')).toBe('credential_owner_deleting');
+    expect(credentialRefusalReason('Session token expired')).toBe('session_expired');
+    expect(credentialRefusalReason('Issuing credential revoked')).toBe('issuing_credential_revoked');
+    expect(credentialRefusalReason('Machine access revoked')).toBe('machine_access_revoked');
+    expect(credentialRefusalReason('Invalid agent credential')).toBe('credential_invalid');
+    expect(credentialRefusalReason('something unexpected')).toBe('credential_invalid');
+  });
+
+  test('fingerprint is the first 8 hex of the hash, and none without a token', () => {
+    expect(refusalFingerprint(HASH)).toBe('deadbeef');
+    expect(refusalFingerprint(undefined)).toBe('none');
+    expect(refusalFingerprint(null)).toBe('none');
+  });
+
+  test('route is the mount prefix plus the route pattern, never a concrete url', () => {
+    expect(refusalRoute({ baseUrl: '/api/agents/runtime', route: { path: '/pods/:podId/messages' } }))
+      .toBe('/api/agents/runtime/pods/:podId/messages');
+    expect(refusalRoute({ baseUrl: '/api/agents/runtime' })).toBe('/api/agents/runtime');
+    expect(refusalRoute({})).toBe('unknown');
+  });
+
+  test('logs one line with the reason, route, method and fingerprint, and no token', () => {
+    recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/r', method: 'POST', tokenHash: HASH, now: 1000, 
+    });
+    expect(lines()).toEqual([{
+      reason: 'invalid_token', route: '/r', method: 'POST', fingerprint: 'deadbeef', repeatsSinceLastLog: 0,
+    }]);
+  });
+
+  test('rate-limits per reason and fingerprint, and reports the repeats on the next line', () => {
+    const at = (ms) => recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/r', tokenHash: HASH, now: ms, 
+    });
+    at(0); at(1000); at(59000);
+    expect(lines()).toHaveLength(1);
+    at(61000);
+    expect(lines()).toHaveLength(2);
+    expect(lines()[1].repeatsSinceLastLog).toBe(2);
+  });
+
+  test('a different fingerprint or reason is its own line', () => {
+    recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/r', tokenHash: HASH, now: 0, 
+    });
+    recordAgentAuthRefusal({
+      reason: 'invalid_token', route: '/r', tokenHash: `ffffffff${HASH.slice(8)}`, now: 0, 
+    });
+    recordAgentAuthRefusal({
+      reason: 'agent_not_installed', route: '/r', tokenHash: HASH, now: 0, 
+    });
+    expect(lines()).toHaveLength(3);
+  });
+
+  test('a spray of distinct tokens is capped by a global line budget, and counts keep counting', () => {
+    for (let i = 0; i < 150; i += 1) {
+      recordAgentAuthRefusal({
+        reason: 'invalid_token', route: '/r', tokenHash: i.toString(16).padStart(8, '0') + HASH.slice(8), now: 0,
+      });
+    }
+    expect(lines()).toHaveLength(100);
+    expect(agentAuthRefusalCounts().counts.invalid_token).toBe(150);
+  });
+
+  test('counts are readable per reason, with every reason present and zeroed', () => {
+    recordAgentAuthRefusal({ reason: 'missing_token', route: '/r', now: 0 });
+    const { since, counts } = agentAuthRefusalCounts();
+    expect(new Date(since).toString()).not.toBe('Invalid Date');
+    expect(Object.keys(counts).sort()).toEqual([...AGENT_AUTH_REFUSAL_REASONS].sort());
+    expect(counts.missing_token).toBe(1);
+    expect(counts.token_revoked).toBe(0);
+  });
+});

backend/middleware/agentRuntimeAuth.ts

@@ -12,6 +12,9 @@ import { markByoConnectionAttempt } from '../services/onboardingMarks';
 import { recordByoEvent, seatRegisteredKey } from '../services/byoTelemetry';
 import { isSpawnCredential } from '../services/spawnCredentialService';
 import { embeddedRuntimeTokenExpired, runtimeCredentialRefusalReason } from '../services/runtimeCredentialGate';
+import {
+  credentialRefusalReason, recordAgentAuthRefusal, refusalRoute, type AgentAuthRefusalReason,
+} from '../services/agentAuthRefusals';
 
 // eslint-disable-next-line global-require
 const { hash } = require('../utils/secret') as { hash: (value: string) => string };
@@ -46,11 +49,24 @@ const extractToken = (req: Request): string | undefined => {
   return req.header('x-commonly-agent-token');
 };
 
+// Every 401 goes through here, so each refusal is logged and counted with its
+// reason (TASK-712). The response is unchanged: same status, same message.
+const refuse = (
+  req: Request,
+  res: Response,
+  reason: AgentAuthRefusalReason,
+  message: string,
+  tokenHash?: string,
+): Response => {
+  recordAgentAuthRefusal({ reason, route: refusalRoute(req), method: req.method, tokenHash });
+  return res.status(401).json({ message });
+};
+
 export default async function agentRuntimeAuth(req: Request, res: Response, next: NextFunction): Promise<void | Response> {
   try {
     const token = extractToken(req);
     if (!token || !token.startsWith('cm_agent_')) {
-      return res.status(401).json({ message: 'Missing agent token' });
+      return refuse(req, res, 'missing_token', 'Missing agent token');
     }
 
     const tokenHash = hash(token);
@@ -72,7 +88,9 @@ export default async function agentRuntimeAuth(req: Request, res: Response, next
     const credential = await AgentCredential.findOne({ tokenHash });
     if (credential) {
       const refusal = await runtimeCredentialRefusalReason(credential);
-      if (refusal) return res.status(401).json({ message: refusal });
+      if (refusal) {
+        return refuse(req, res, credentialRefusalReason(refusal), refusal, tokenHash);
+      }
       try {
         // Settings reads this ledger row. A successful authenticated request
         // must be visible to the next credential read, including first use.
@@ -95,7 +113,7 @@ export default async function agentRuntimeAuth(req: Request, res: Response, next
 
     if (agentUser) {
       if (embeddedRuntimeTokenExpired(agentUser, tokenHash)) {
-        return res.status(401).json({ message: 'Session token expired' });
+        return refuse(req, res, 'session_expired', 'Session token expired', tokenHash);
       }
       const tokenRecord = agentUser.agentRuntimeTokens.find((t) => t.tokenHash === tokenHash);
       // Pre-update value: a token with no lastUsedAt is authenticating for
@@ -127,7 +145,7 @@ export default async function agentRuntimeAuth(req: Request, res: Response, next
       // Old uninstall paths left User-row tokens behind. Even before a data
       // cleanup, a token with no active installation must not authenticate.
       if (installations.length === 0) {
-        return res.status(401).json({ message: 'Agent not installed' });
+        return refuse(req, res, 'agent_not_installed', 'Agent not installed', tokenHash);
       }
       const installationPodIds = installations
         .map((inst) => inst?.podId?.toString())
@@ -167,7 +185,7 @@ export default async function agentRuntimeAuth(req: Request, res: Response, next
     });
 
     if (!installation) {
-      return res.status(401).json({ message: 'Invalid agent token' });
+      return refuse(req, res, 'invalid_token', 'Invalid agent token', tokenHash);
     }
 
     // Same first-use observation as the User-token path above (#916).