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,117 @@
+// The route's guard order (rate limit, auth, adminAuth) is pinned by the route
+// guard test. These cases send real requests through the router with the real
+// auth and adminAuth middleware, so the status codes an operator sees are the
+// ones the real guards produce. Only the data they read is faked.
+jest.mock('../../../services/sessionAccountService', () => ({
+  loadSessionAccount: jest.fn(async (id) => ({
+    'admin-1': {
+      _id: 'admin-1', username: 'admin', email: 'a@x.test', role: 'admin', 
+    },
+    'user-1': {
+      _id: 'user-1', username: 'user', email: 'u@x.test', role: 'user', 
+    },
+  }[id] || null)),
+  sessionRefusal: jest.fn((account) => (account ? null : 'missing')),
+  isAccountInstanceRestricted: jest.fn(async () => false),
+}));
+jest.mock('../../../models/User', () => ({
+  findById: jest.fn(async (id) => ({ _id: id, role: id === 'admin-1' ? 'admin' : 'user' })),
+  findOne: jest.fn(async () => null),
+  updateOne: jest.fn(async () => ({})),
+}));
+jest.mock('../../../middleware/ipRateLimit', () => ({
+  cloudflareIpRateLimitKeyGenerator: () => 'test-ip',
+}));
+
+const express = require('express');
+const request = require('supertest');
+const jwt = require('jsonwebtoken');
+const adminAgentAuthRoutes = require('../../../routes/admin/agentAuthRefusals');
+const {
+  AGENT_AUTH_REFUSAL_REASONS,
+  recordAgentAuthRefusal,
+  resetAgentAuthRefusalsForTest,
+} = require('../../../services/agentAuthRefusals');
+
+const SECRET = 'test-jwt-secret';
+const sessionFor = (id) => jwt.sign({ id }, SECRET, { expiresIn: '1h' });
+
+const buildApp = () => {
+  const app = express();
+  app.use('/api/admin/agent-auth', adminAgentAuthRoutes);
+  return app;
+};
+
+describe('GET /api/admin/agent-auth/refusals (TASK-712)', () => {
+  let savedSecret;
+  let savedNodeEnv;
+
+  beforeAll(() => {
+    savedSecret = process.env.JWT_SECRET;
+    process.env.JWT_SECRET = SECRET;
+  });
+  afterAll(() => {
+    process.env.JWT_SECRET = savedSecret;
+  });
+  beforeEach(() => {
+    resetAgentAuthRefusalsForTest();
+    savedNodeEnv = process.env.NODE_ENV;
+  });
+  afterEach(() => {
+    process.env.NODE_ENV = savedNodeEnv;
+  });
+
+  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('a session for an account that no longer exists is refused with 401', async () => {
+    const res = await request(buildApp())
+      .get('/api/admin/agent-auth/refusals')
+      .set('Authorization', `Bearer ${sessionFor('deleted-1')}`);
+    expect(res.status).toBe(401);
+    expect(res.body.msg).toBe('Account no longer exists');
+  });
+
+  test('an authenticated non-admin is refused with 403', async () => {
+    const res = await request(buildApp())
+      .get('/api/admin/agent-auth/refusals')
+      .set('Authorization', `Bearer ${sessionFor('user-1')}`);
+    expect(res.status).toBe(403);
+    expect(res.body.message).toBe('Admin access required');
+  });
+
+  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('Authorization', `Bearer ${sessionFor('admin-1')}`);
+
+    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);
+  });
+
+  // Keep this last: the limiter's store lives for the whole file, and the
+  // other cases run with the limiter skipped under NODE_ENV=test.
+  test('the limiter answers 429 after 60 requests in a window', async () => {
+    process.env.NODE_ENV = 'production';
+    const app = buildApp();
+    let last;
+    for (let i = 0; i < 61; i += 1) {
+      // eslint-disable-next-line no-await-in-loop
+      last = await request(app).get('/api/admin/agent-auth/refusals');
+    }
+    expect(last.status).toBe(429);
+    expect(last.body).toEqual({ error: 'rate_limited' });
+  });
+});

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);
+  });
+});