diff --git a/server/account/src/__tests__/operations.test.ts b/server/account/src/__tests__/operations.test.ts index a5a5676b2b2..67ea04e5544 100644 --- a/server/account/src/__tests__/operations.test.ts +++ b/server/account/src/__tests__/operations.test.ts @@ -25,7 +25,8 @@ import { systemAccountUuid } from '@hcengineering/core' import platform, { PlatformError, Status, Severity, getMetadata } from '@hcengineering/platform' -import { decodeToken, decodeTokenVerbose } from '@hcengineering/server-token' +import serverToken, { decodeToken, decodeTokenVerbose, TokenError } from '@hcengineering/server-token' +import { Analytics } from '@hcengineering/analytics' import * as utils from '../utils' import { type AccountDB, type SocialId } from '../types' @@ -35,6 +36,9 @@ import { sendInvite, resendInvite, getLoginInfoByToken, + getLoginWithWorkspaceInfo, + getWorkspacesInfo, + updateLastVisit, releaseSocialId, loginAsGuest, getLoginCapabilities, @@ -74,6 +78,9 @@ jest.mock('@hcengineering/platform', () => { // Mock server-token jest.mock('@hcengineering/server-token', () => ({ + __esModule: true, + default: jest.requireActual('@hcengineering/server-token').default, + TokenError: jest.requireActual('@hcengineering/server-token').TokenError, decodeTokenVerbose: jest.fn(), decodeToken: jest.fn(), generateToken: jest.fn().mockImplementation((account, workspace, extra, _, options) => { @@ -91,7 +98,18 @@ jest.mock('@hcengineering/server-token', () => ({ }) })) +// Mock analytics +jest.mock('@hcengineering/analytics', () => ({ + Analytics: { + handleError: jest.fn() + } +})) + describe('account operations', () => { + // The mocked function is a plain jest.fn(), so referencing it unbound is safe. + // eslint-disable-next-line @typescript-eslint/unbound-method + const handleError = Analytics.handleError as jest.Mock + const mockCtx = { error: jest.fn(), info: jest.fn(), @@ -1010,7 +1028,7 @@ describe('account operations', () => { ;(decodeToken as jest.Mock).mockReturnValue({ nbf: futureTime }) ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { - throw new Error('Token not yet active') + throw new TokenError('Token not yet active') }) await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, mockToken)).rejects.toThrow( @@ -1020,13 +1038,187 @@ describe('account operations', () => { test('should throw error when token has expired', async () => { ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { - throw new Error('Token expired') + throw new TokenError('Token expired') }) await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, mockToken)).rejects.toThrow( new PlatformError(new Status(Severity.ERROR, platform.status.TokenExpired, {})) ) }) + + describe('invalid token logging', () => { + const allLogged = (): string => + JSON.stringify([ + (mockCtx.warn as jest.Mock).mock.calls, + (mockCtx.error as jest.Mock).mock.calls, + (mockCtx.info as jest.Mock).mock.calls, + handleError.mock.calls.map((c) => [ + String(c[0]), + c[0]?.name, + c[0]?.message, + c[0]?.stack, + String(c[0]?.cause), + { ...c[0] } + ]) + ]) + + beforeEach(() => { + ;(getMetadata as jest.Mock).mockImplementation((key) => + key === serverToken.metadata.Secret ? 'test-secret' : undefined + ) + }) + + test('logs an expired token with a fingerprint and a reason only and does not report it', async () => { + ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { + throw new TokenError('Token expired') + }) + + await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, mockToken)).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.TokenExpired, {})) + ) + + expect(handleError).not.toHaveBeenCalled() + expect(mockCtx.error).not.toHaveBeenCalled() + expect(mockCtx.warn).toHaveBeenCalledWith('Invalid token', { + token: utils.tokenFingerprint(mockToken), + error: 'TokenError', + reason: 'Token expired' + }) + expect(utils.tokenFingerprint(mockToken)).toMatch(/^[0-9a-f]{16}$/) + expect(allLogged()).not.toContain(mockToken) + }) + + test('does not log a decoder message that quotes the token', async () => { + ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { + throw new TokenError(`Unexpected token ${mockToken} in JSON at position 0`) + }) + + await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, mockToken)).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.Unauthorized, {})) + ) + + expect(mockCtx.warn).toHaveBeenCalledWith('Invalid token', { + token: utils.tokenFingerprint(mockToken), + error: 'TokenError', + reason: 'other' + }) + expect(handleError).not.toHaveBeenCalled() + expect(allLogged()).not.toContain(mockToken) + }) + + test('still reports a non-token failure without leaking the token', async () => { + // Grant token without `sub`: the only other await inside the try block. + ;(decodeTokenVerbose as jest.Mock).mockReturnValue({ + account: 'test-account', + grant: { workspace: 'test-workspace', role: AccountRole.User } + }) + const dbErr = Object.assign(new Error(`connection reset while handling ${mockToken}`), { token: mockToken }) + ;(mockDb.generatePersonUuid as jest.Mock).mockRejectedValueOnce(dbErr) + + await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, mockToken)).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.Unauthorized, {})) + ) + + expect(handleError).toHaveBeenCalledTimes(1) + expect(handleError.mock.calls[0][0]).not.toBe(dbErr) + expect(mockCtx.error).toHaveBeenCalledWith('Invalid token', { + token: utils.tokenFingerprint(mockToken), + error: 'Error', + reason: 'unexpected' + }) + expect(mockCtx.warn).not.toHaveBeenCalled() + expect(allLogged()).not.toContain(mockToken) + }) + + test('does not log anything when no token was supplied', async () => { + ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { + throw new TokenError('Not enough or too many segments') + }) + + await expect(getLoginInfoByToken(mockCtx, mockDb, mockBranding, undefined as any)).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.Unauthorized, {})) + ) + + expect(mockCtx.warn).not.toHaveBeenCalled() + expect(mockCtx.error).not.toHaveBeenCalled() + expect(handleError).not.toHaveBeenCalled() + }) + }) + }) + + describe('getLoginWithWorkspaceInfo', () => { + const mockCtx = { + error: jest.fn(), + info: jest.fn(), + warn: jest.fn() + } as unknown as MeasureContext + const mockDb = {} as unknown as AccountDB + const mockToken = 'test-token' + + beforeEach(() => { + jest.clearAllMocks() + ;(getMetadata as jest.Mock).mockImplementation((key) => + key === serverToken.metadata.Secret ? 'test-secret' : undefined + ) + }) + + test.each([ + ['Signature verification failed', 'Signature verification failed'], + [`Signature verification failed ${mockToken}`, 'other'] + ])( + 'rejects an invalid token (%s) with Unauthorized, logs a fingerprint and reason only and skips Analytics', + async (message, reason) => { + ;(decodeTokenVerbose as jest.Mock).mockImplementation(() => { + throw new TokenError(message) + }) + + await expect(getLoginWithWorkspaceInfo(mockCtx, mockDb, null, mockToken)).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.Unauthorized, {})) + ) + + expect(handleError).not.toHaveBeenCalled() + expect(mockCtx.error).not.toHaveBeenCalled() + expect(mockCtx.warn).toHaveBeenCalledWith('Invalid token', { + token: utils.tokenFingerprint(mockToken), + error: 'TokenError', + reason + }) + expect(JSON.stringify((mockCtx.warn as jest.Mock).mock.calls)).not.toContain(mockToken) + } + ) + }) + + describe('getWorkspacesInfo / updateLastVisit caller check', () => { + const mockCtx = { + error: jest.fn(), + info: jest.fn(), + warn: jest.fn() + } as unknown as MeasureContext + const mockDb = {} as unknown as AccountDB + const mockToken = 'test-token' + + beforeEach(() => { + jest.clearAllMocks() + ;(getMetadata as jest.Mock).mockImplementation((key) => + key === serverToken.metadata.Secret ? 'test-secret' : undefined + ) + ;(decodeTokenVerbose as jest.Mock).mockReturnValue({ account: 'not-system' }) + }) + + test.each([ + ['getWorkspacesInfo', getWorkspacesInfo], + ['updateLastVisit', updateLastVisit] + ])('%s rejects a non-system caller without logging the token', async (_, method) => { + await expect(method(mockCtx, mockDb, null, mockToken, { ids: ['ws' as WorkspaceUuid] })).rejects.toThrow( + new PlatformError(new Status(Severity.ERROR, platform.status.Forbidden, {})) + ) + + expect(mockCtx.error).toHaveBeenCalledWith(expect.any(String), { + account: 'not-system', + token: utils.tokenFingerprint(mockToken) + }) + expect(JSON.stringify((mockCtx.error as jest.Mock).mock.calls)).not.toContain(mockToken) + }) }) describe('releaseSocialId', () => { diff --git a/server/account/src/__tests__/utils.test.ts b/server/account/src/__tests__/utils.test.ts index 6a86da07997..ea1130854a0 100644 --- a/server/account/src/__tests__/utils.test.ts +++ b/server/account/src/__tests__/utils.test.ts @@ -67,11 +67,15 @@ import { addSocialIdBase, doReleaseSocialId, getLastPasswordChangeEvent, - isPasswordChangedSince + isPasswordChangedSince, + reportInvalidToken, + tokenErrorReason, + tokenFingerprint } from '../utils' // eslint-disable-next-line import/no-named-default import platform, { getMetadata, PlatformError, Severity, Status } from '@hcengineering/platform' -import { decodeTokenVerbose, generateToken, TokenError } from '@hcengineering/server-token' +import serverToken, { decodeTokenVerbose, generateToken, TokenError } from '@hcengineering/server-token' +import { Analytics } from '@hcengineering/analytics' import { randomBytes } from 'crypto' import { type AccountDB, type AccountEvent, AccountEventType, type Workspace } from '../types' @@ -92,6 +96,8 @@ jest.mock('@hcengineering/platform', () => { // Mock server-token jest.mock('@hcengineering/server-token', () => ({ + __esModule: true, + default: jest.requireActual('@hcengineering/server-token').default, TokenError: jest.requireActual('@hcengineering/server-token').TokenError, decodeTokenVerbose: jest.fn(), generateToken: jest.fn() @@ -2435,3 +2441,193 @@ describe('account utils', () => { }) }) }) + +describe('token log redaction', () => { + const token = 'eyJ.secret.token' + + const useSecret = (secret: string | undefined): void => { + ;(getMetadata as jest.Mock).mockImplementation((id) => (id === serverToken.metadata.Secret ? secret : undefined)) + } + + beforeEach(() => { + jest.clearAllMocks() + useSecret('test-secret') + }) + + afterEach(() => { + ;(getMetadata as jest.Mock).mockReset() + }) + + describe('tokenFingerprint', () => { + test('returns a 16-character hex digest that is not part of the token', () => { + const fp = tokenFingerprint('header.payload.signature') + expect(fp).toMatch(/^[0-9a-f]{16}$/) + expect('header.payload.signature').not.toContain(fp as string) + }) + + test('is deterministic and distinguishes tokens', () => { + expect(tokenFingerprint('a.b.c')).toBe(tokenFingerprint('a.b.c')) + expect(tokenFingerprint('a.b.c')).not.toBe(tokenFingerprint('a.b.d')) + }) + + test('depends on the server secret', () => { + useSecret('s1') + const one = tokenFingerprint('a.b.c') + useSecret('s2') + expect(tokenFingerprint('a.b.c')).not.toBe(one) + }) + + test('is omitted when the server secret is not configured', () => { + useSecret(undefined) + expect(tokenFingerprint('a.b.c')).toBeUndefined() + useSecret('') + expect(tokenFingerprint('a.b.c')).toBeUndefined() + }) + + test('returns undefined for a missing or empty token', () => { + expect(tokenFingerprint(undefined)).toBeUndefined() + expect(tokenFingerprint(null)).toBeUndefined() + expect(tokenFingerprint('')).toBeUndefined() + }) + }) + + describe('tokenErrorReason', () => { + test('classifies known TokenError messages and falls back to other', () => { + expect(tokenErrorReason(new TokenError('Token expired'))).toBe('Token expired') + expect(tokenErrorReason(new TokenError('Signature verification failed'))).toBe('Signature verification failed') + expect(tokenErrorReason(new TokenError('Unexpected token x in JSON at position 3'))).toBe('other') + expect(tokenErrorReason(new Error('Token expired'))).toBe('unexpected') + expect(tokenErrorReason('Token expired')).toBe('unexpected') + }) + }) + + describe('reportInvalidToken', () => { + // The mocked function is a plain jest.fn(), so referencing it unbound is safe. + // eslint-disable-next-line @typescript-eslint/unbound-method + const handleError = Analytics.handleError as jest.Mock + + let ctx: MeasureContext + + const reportedErrors = (): any[] => handleError.mock.calls.map((c) => c[0]) + + const allLogged = (): string => + JSON.stringify([ + (ctx.warn as jest.Mock).mock.calls, + (ctx.error as jest.Mock).mock.calls, + (ctx.info as jest.Mock).mock.calls, + reportedErrors().map((e) => [ + typeof e, + String(e), + e?.name, + e?.message, + e?.stack, + String(e?.cause), + e != null && typeof e === 'object' ? { ...e } : e + ]) + ]) + + beforeEach(() => { + ctx = { error: jest.fn(), warn: jest.fn(), info: jest.fn() } as unknown as MeasureContext + }) + + test('logs a TokenError at warn level with fingerprint and reason only and skips Analytics', () => { + reportInvalidToken(ctx, token, new TokenError('Token expired')) + expect(ctx.warn).toHaveBeenCalledWith('Invalid token', { + token: tokenFingerprint(token), + error: 'TokenError', + reason: 'Token expired' + }) + expect(ctx.error).not.toHaveBeenCalled() + expect(handleError).not.toHaveBeenCalled() + expect(allLogged()).not.toContain(token) + }) + + test('never logs a TokenError message that contains the raw token', () => { + reportInvalidToken(ctx, token, new TokenError(`Unexpected token ${token} in JSON at position 0`)) + expect(ctx.warn).toHaveBeenCalledWith('Invalid token', { + token: tokenFingerprint(token), + error: 'TokenError', + reason: 'other' + }) + expect(handleError).not.toHaveBeenCalled() + expect(allLogged()).not.toContain(token) + }) + + test('omits the fingerprint when the server secret is not configured', () => { + useSecret(undefined) + reportInvalidToken(ctx, token, new TokenError('Token expired')) + expect(ctx.warn).toHaveBeenCalledWith('Invalid token', { + token: undefined, + error: 'TokenError', + reason: 'Token expired' + }) + expect(allLogged()).not.toContain(token) + }) + + test('reports any other error to Analytics as a fresh error and logs it at error level', () => { + const err = new Error('connection reset') + reportInvalidToken(ctx, token, err) + expect(handleError).toHaveBeenCalledTimes(1) + const reported = reportedErrors()[0] + expect(reported).toBeInstanceOf(Error) + expect(reported).not.toBe(err) + expect(reported.name).toBe('Error') + expect(reported.message).toBe('Unexpected error while validating a token') + expect(reported.cause).toBeUndefined() + // only the allowlisted name may be set on the fresh error + expect(Object.keys(reported).filter((k) => k !== 'name')).toEqual([]) + expect(ctx.error).toHaveBeenCalledWith('Invalid token', { + token: tokenFingerprint(token), + error: 'Error', + reason: 'unexpected' + }) + expect(ctx.warn).not.toHaveBeenCalled() + expect(allLogged()).not.toContain(token) + }) + + test('does not leak a token contained in the message of an unexpected error', () => { + reportInvalidToken(ctx, token, new Error(`connection reset while handling ${token}`)) + expect(handleError).toHaveBeenCalledTimes(1) + expect(allLogged()).not.toContain(token) + }) + + test('does not leak a token contained in the cause of an unexpected error', () => { + const err = new Error('connection reset') + Object.defineProperty(err, 'cause', { value: new Error(`while handling ${token}`), enumerable: false }) + reportInvalidToken(ctx, token, err) + expect(handleError).toHaveBeenCalledTimes(1) + expect(reportedErrors()[0].cause).toBeUndefined() + expect(allLogged()).not.toContain(token) + }) + + test('does not leak a token contained in a custom field of an unexpected error', () => { + const err = Object.assign(new Error('connection reset'), { request: { token }, detail: token }) + reportInvalidToken(ctx, token, err) + expect(handleError).toHaveBeenCalledTimes(1) + expect(Object.keys(reportedErrors()[0]).filter((k) => k !== 'name')).toEqual([]) + expect(allLogged()).not.toContain(token) + }) + + test('does not leak a token from an error whose name contains it', () => { + const err = new Error('connection reset') + err.name = `Error_${token}` + reportInvalidToken(ctx, token, err) + expect(reportedErrors()[0].name).toBe('Error') + expect(allLogged()).not.toContain(token) + }) + + test('does not leak a token from a thrown string', () => { + reportInvalidToken(ctx, token, `failed to handle ${token}`) + expect(handleError).toHaveBeenCalledTimes(1) + const reported = reportedErrors()[0] + expect(reported).toBeInstanceOf(Error) + expect(reported.name).toBe('Error') + expect(ctx.error).toHaveBeenCalledWith('Invalid token', { + token: tokenFingerprint(token), + error: 'string', + reason: 'unexpected' + }) + expect(allLogged()).not.toContain(token) + }) + }) +}) diff --git a/server/account/src/operations.ts b/server/account/src/operations.ts index 453b74aebe0..0e8953515d0 100644 --- a/server/account/src/operations.ts +++ b/server/account/src/operations.ts @@ -134,7 +134,9 @@ import { checkPasswordAging, generateTotpSecret, verifyTotpCode, - getTotpUrl + getTotpUrl, + reportInvalidToken, + tokenFingerprint } from './utils' const NIL_UUID = '00000000-0000-0000-0000-000000000000' as AccountUuid @@ -2014,7 +2016,7 @@ export async function getWorkspacesInfo ( const { account } = decodeTokenVerbose(ctx, token) if (account !== systemAccountUuid) { - ctx.error('getWorkspaceInfos with wrong user', { account, token }) + ctx.error('getWorkspaceInfos with wrong user', { account, token: tokenFingerprint(token) }) throw new PlatformError(new Status(Severity.ERROR, platform.status.Forbidden, {})) } @@ -2043,7 +2045,7 @@ export async function updateLastVisit ( const { account } = decodeTokenVerbose(ctx, token) if (account !== systemAccountUuid) { - ctx.error('updateLastVisit with wrong user', { account, token }) + ctx.error('updateLastVisit with wrong user', { account, token: tokenFingerprint(token) }) throw new PlatformError(new Status(Severity.ERROR, platform.status.Forbidden, {})) } @@ -2125,8 +2127,7 @@ export async function getLoginInfoByToken ( } catch (err: any) { if (token !== undefined) { // do not spam errors as this is expected when we issue request with no token - Analytics.handleError(err) - ctx.error('Invalid token', { token, errMsg: err.message }) + reportInvalidToken(ctx, token, err) } switch (err.message) { case 'Token not yet active': { @@ -2310,8 +2311,7 @@ export async function getLoginWithWorkspaceInfo ( try { ;({ account: accountUuid, extra, workspace } = decodeTokenVerbose(ctx, token)) } catch (err: any) { - Analytics.handleError(err) - ctx.error('Invalid token', { token }) + reportInvalidToken(ctx, token, err) throw new PlatformError(new Status(Severity.ERROR, platform.status.Unauthorized, {})) } diff --git a/server/account/src/utils.ts b/server/account/src/utils.ts index bf36af312c1..5c5115c1c94 100644 --- a/server/account/src/utils.ts +++ b/server/account/src/utils.ts @@ -38,12 +38,12 @@ import { import { getMongoClient } from '@hcengineering/mongo' // TODO: get rid of this import later import platform, { getMetadata, PlatformError, Severity, Status, translate } from '@hcengineering/platform' import { getDBClient, setDBExtraOptions } from '@hcengineering/postgres' -import { pbkdf2Sync, randomBytes } from 'crypto' +import { createHmac, pbkdf2Sync, randomBytes } from 'crypto' import otpGenerator from 'otp-generator' import { authenticator } from 'otplib' import { Analytics } from '@hcengineering/analytics' -import { +import serverToken, { decodeToken, decodeTokenVerbose, generateToken, @@ -178,6 +178,79 @@ export function isGuest (account: AccountUuid, extra: Record | unde return account === GUEST_ACCOUNT && extra?.guest === 'true' } +/** + * Exact messages a `TokenError` can carry today (jwt-simple plus the checks in + * `@hcengineering/server-token`). Anything else is logged as `other`: decoder + * messages may quote the malformed input, so they are never logged verbatim. + */ +const KNOWN_TOKEN_ERROR_MESSAGES: ReadonlySet = new Set([ + 'No token supplied', + 'Not enough or too many segments', + 'Algorithm not supported', + 'Algorithm type not recognized', + 'Require key', + 'Signature verification failed', + 'Token not yet active', + 'Token expired', + 'Token revoked', + 'Token revocation could not be verified' +]) + +/** + * Fixed category for a failed token: a known `TokenError` message, `other` for + * any other `TokenError`, and `unexpected` for everything else. + */ +export function tokenErrorReason (err: unknown): string { + if (!(err instanceof TokenError)) return 'unexpected' + return KNOWN_TOKEN_ERROR_MESSAGES.has(err.message) ? err.message : 'other' +} + +/** + * Short identifier of a raw token for log correlation. Tokens are bearer + * credentials and must never be written to logs or to the error reporter. The + * fingerprint is an HMAC-SHA256 keyed with a key derived from the server secret, + * so it cannot be recomputed without that secret; it lets operators correlate + * repeated failures of one token. Without a configured secret no fingerprint is + * produced. + */ +export function tokenFingerprint (token: string | undefined | null): string | undefined { + if (token == null || token === '') return undefined + const secret = getMetadata(serverToken.metadata.Secret) + if (secret == null || secret === '') return undefined + const key = createHmac('sha256', secret).update('account:token-fingerprint').digest() + return createHmac('sha256', key).update(token).digest('hex').slice(0, 16) +} + +function safeErrorName (err: unknown, token: string): string { + if (!(err instanceof Error)) return typeof err + const name = err.name + if (typeof name !== 'string' || !/^[A-Za-z][A-Za-z0-9_]{0,63}$/.test(name) || name.includes(token)) { + return 'Error' + } + return name +} + +/** + * Logs a token that failed validation without exposing it. A `TokenError` (bad + * signature, expired, not yet active, revoked) is an expected authentication + * failure: it is logged at warn level with a fixed reason and is not reported to + * Analytics. Anything else is unexpected: it is logged at error level and a fresh + * error carrying only the error class name is reported to Analytics. The original + * error, its message, stack, cause and custom fields are never passed on. + */ +export function reportInvalidToken (ctx: MeasureContext, token: string, err: unknown): void { + const fingerprint = tokenFingerprint(token) + if (err instanceof TokenError) { + ctx.warn('Invalid token', { token: fingerprint, error: 'TokenError', reason: tokenErrorReason(err) }) + return + } + const name = safeErrorName(err, token) + const reported = new Error('Unexpected error while validating a token') + if (err instanceof Error) reported.name = name + Analytics.handleError(reported) + ctx.error('Invalid token', { token: fingerprint, error: name, reason: 'unexpected' }) +} + export function wrap ( accountMethod: (ctx: MeasureContext, db: AccountDB, branding: Branding | null, ...args: any[]) => Promise ): AccountMethodHandler {