mirror of
https://github.com/ever-co/ever-gauzy.git
synced 2026-10-02 01:54:50 +08:00
fix(sentry): only errors become Sentry events by default; stop logging health probes
The whole ever-co Sentry organisation (5,000 errors a month on the current plan) has accepted no error after the first hours of each monthly reset: 2026-07-09, 08-09 and 09-09 are the only days with accepted errors in 90 days. About 97% of what was accepted were info-level log lines, not errors. - SentryService (the API's Nest logger) turned every log/warn/debug/verbose call into its own Sentry event and ignored the `logLevels: ['error']` the API passes. It now honours `logLevels`: listed levels become events, the rest become breadcrumbs on the next event. An unset or empty list keeps the old capture-everything behaviour. The API reads the list from SENTRY_LOG_LEVELS (default `error`), so capturing warnings or logs again is a config change. - RequestContextMiddleware logged the start and end of every request, including the Kubernetes readiness probe on /api/health every 10 s on every pod: 2 events per probe, ~2,900 events an hour from the four Ever Teams API pods alone. /api/health and /api/health/* are no longer logged. This is decided by path only, since a client-set User-Agent must not be able to hide other requests. - apps/api/src/sentry.ts printed the DSN at startup and ran the SDK in debug mode in production (`environment.production` is false in the published image), writing several SDK lines per request. Debug is now opt-in with SENTRY_DEBUG=true, and the DSN is no longer printed. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 5.5
parent
1b2278d329
commit
69a293175a
@@ -363,6 +363,9 @@ SENTRY_POSTGRES_TRACKING_ENABLED=
|
||||
SENTRY_PROFILING_ENABLED=
|
||||
SENTRY_TRACES_SAMPLE_RATE=
|
||||
SENTRY_PROFILE_SAMPLE_RATE=
|
||||
# Nest log levels that become Sentry events, comma-separated (default: error). Other levels are
|
||||
# attached to the next event as breadcrumbs. Example: SENTRY_LOG_LEVELS=error,warn
|
||||
SENTRY_LOG_LEVELS=
|
||||
|
||||
# PostHog Configuration
|
||||
POSTHOG_KEY=
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import { environment } from '@gauzy/config';
|
||||
import { SentryPlugin, DefaultSentryIntegrations } from '@gauzy/plugin-sentry';
|
||||
import { SentryPlugin, DefaultSentryIntegrations, parseSentryLogLevels } from '@gauzy/plugin-sentry';
|
||||
import { version } from '../version';
|
||||
|
||||
/**
|
||||
@@ -17,15 +17,19 @@ export function initializeSentry(): typeof SentryPlugin | null {
|
||||
return null;
|
||||
}
|
||||
|
||||
console.log('Initializing Sentry with DSN:', environment.sentry.dsn);
|
||||
// Never print the DSN: it carries the project's ingest key.
|
||||
console.log('Initializing Sentry');
|
||||
|
||||
// Configure Sentry
|
||||
return SentryPlugin.init({
|
||||
dsn: environment.sentry.dsn,
|
||||
debug: process.env.SENTRY_DEBUG === 'true' || !environment.production,
|
||||
// Only on request: `environment.production` is false in the published API image, so tying debug to it
|
||||
// printed several SDK lines per request in every production pod.
|
||||
debug: process.env.SENTRY_DEBUG === 'true',
|
||||
environment: environment.production ? 'production' : 'development',
|
||||
release: `gauzy@${version}`,
|
||||
logLevels: ['error'],
|
||||
// Levels that become Sentry events (SENTRY_LOG_LEVELS, default `error`); the rest are breadcrumbs.
|
||||
logLevels: parseSentryLogLevels(process.env.SENTRY_LOG_LEVELS),
|
||||
integrations: [...DefaultSentryIntegrations],
|
||||
tracesSampleRate: parseFloat(process.env.SENTRY_TRACES_SAMPLE_RATE || '0.01'),
|
||||
profilesSampleRate: parseFloat(process.env.SENTRY_PROFILE_SAMPLE_RATE || '1'),
|
||||
|
||||
@@ -1,5 +1,6 @@
|
||||
import { AsyncLocalStorage } from 'async_hooks';
|
||||
import { RequestContextMiddleware } from './request-context.middleware';
|
||||
import { Logger } from '@nestjs/common';
|
||||
import { isHealthCheckRequest, RequestContextMiddleware } from './request-context.middleware';
|
||||
import { RequestContext } from './request-context';
|
||||
|
||||
/**
|
||||
@@ -172,6 +173,57 @@ describe('RequestContextMiddleware — correlation id propagation', () => {
|
||||
expect(responseHeaders['x-correlation-id']).toHaveLength(36);
|
||||
});
|
||||
|
||||
describe('request lifecycle logging', () => {
|
||||
afterEach(() => jest.restoreAllMocks());
|
||||
|
||||
function runRequest(originalUrl: string, headers: Record<string, string> = {}) {
|
||||
const cls = buildClsService();
|
||||
RequestContext.setClsService(cls);
|
||||
const middleware = new RequestContextMiddleware(cls);
|
||||
const { req, res } = buildReqRes(headers);
|
||||
req.originalUrl = originalUrl;
|
||||
middleware.use(req, res, jest.fn());
|
||||
res.end();
|
||||
}
|
||||
|
||||
it('logs the start and the end of an ordinary request', () => {
|
||||
const log = jest.spyOn(Logger.prototype, 'log').mockImplementation(() => undefined);
|
||||
|
||||
runRequest('/api/employee');
|
||||
|
||||
expect(log).toHaveBeenCalledTimes(2);
|
||||
expect(log.mock.calls[0][0]).toContain('GET request to http://localhost/api/employee started.');
|
||||
expect(log.mock.calls[1][0]).toContain('completed with status 200.');
|
||||
});
|
||||
|
||||
// Kubernetes probes every pod every few seconds; each logged line was also a Sentry event.
|
||||
it.each(['/api/health', '/api/health?full=true', '/api/health/database'])(
|
||||
'does not log the health check %s',
|
||||
(url) => {
|
||||
const log = jest.spyOn(Logger.prototype, 'log').mockImplementation(() => undefined);
|
||||
|
||||
runRequest(url);
|
||||
|
||||
expect(log).not.toHaveBeenCalled();
|
||||
}
|
||||
);
|
||||
|
||||
// The User-Agent is client-controlled: a probe-like one must not hide an ordinary request.
|
||||
it('still logs an ordinary request that claims to be a Kubernetes probe', () => {
|
||||
const log = jest.spyOn(Logger.prototype, 'log').mockImplementation(() => undefined);
|
||||
|
||||
runRequest('/api/auth/login', { 'user-agent': 'kube-probe/1.33' });
|
||||
|
||||
expect(log).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
it('only treats the health endpoint itself as a health check', () => {
|
||||
expect(isHealthCheckRequest({ originalUrl: '/api/healthcare' })).toBe(false);
|
||||
expect(isHealthCheckRequest({ originalUrl: '/api/employee?next=/api/health' })).toBe(false);
|
||||
expect(isHealthCheckRequest({ originalUrl: '/api/health' })).toBe(true);
|
||||
});
|
||||
});
|
||||
|
||||
it("does not leak the correlation id outside the request's own run() scope", () => {
|
||||
const cls = buildClsService();
|
||||
RequestContext.setClsService(cls);
|
||||
|
||||
@@ -18,6 +18,17 @@ import { RequestContext } from './request-context';
|
||||
*/
|
||||
const SAFE_CORRELATION_ID = /^[\x21-\x7E]{1,128}$/;
|
||||
|
||||
/**
|
||||
* Kubernetes probes hit /api/health every few seconds on every pod. Logging their start and end drowned
|
||||
* the real requests, and with the Sentry logger each line was also a Sentry event (the bulk of the
|
||||
* organisation's error quota), so health checks are not logged. Decided by path only: a User-Agent is
|
||||
* set by the client, so trusting `kube-probe/*` would let any caller hide any request from these logs.
|
||||
*/
|
||||
export function isHealthCheckRequest(req: Pick<Request, 'originalUrl'>): boolean {
|
||||
const path = (req.originalUrl ?? '').split('?')[0];
|
||||
return path === '/api/health' || path.startsWith('/api/health/');
|
||||
}
|
||||
|
||||
@Injectable()
|
||||
export class RequestContextMiddleware implements NestMiddleware {
|
||||
private readonly logger = new Logger(RequestContextMiddleware.name);
|
||||
@@ -60,9 +71,10 @@ export class RequestContextMiddleware implements NestMiddleware {
|
||||
|
||||
// Build the full request URL
|
||||
const fullUrl = `${req.protocol}://${req.get('host')}${req.originalUrl}`;
|
||||
const logLifecycle = this.loggingEnabled && !isHealthCheckRequest(req);
|
||||
|
||||
// Log the start of the request if logging is enabled
|
||||
if (this.loggingEnabled) {
|
||||
if (logLifecycle) {
|
||||
const contextId = RequestContext.getContextId();
|
||||
this.logger.log(`Context ${contextId}: ${req.method} request to ${fullUrl} started.`);
|
||||
}
|
||||
@@ -72,7 +84,7 @@ export class RequestContextMiddleware implements NestMiddleware {
|
||||
|
||||
// Override the res.end function to log when the response finishes
|
||||
res.end = (...args: any[]): Response => {
|
||||
if (this.loggingEnabled) {
|
||||
if (logLifecycle) {
|
||||
const contextId = RequestContext.getContextId();
|
||||
this.logger.log(
|
||||
`Context ${contextId}: ${req.method} request to ${fullUrl} completed with status ${res.statusCode}.`
|
||||
|
||||
@@ -3,3 +3,4 @@
|
||||
*/
|
||||
export * from './lib/sentry.plugin';
|
||||
export * from './lib/ntegral/sentry.service';
|
||||
export * from './lib/sentry-log-levels';
|
||||
|
||||
@@ -0,0 +1,96 @@
|
||||
import * as Sentry from '@sentry/node';
|
||||
import { SentryService } from './sentry.service';
|
||||
|
||||
jest.mock('@sentry/node', () => ({
|
||||
init: jest.fn(),
|
||||
onUncaughtExceptionIntegration: jest.fn(() => ({ name: 'OnUncaughtException' })),
|
||||
onUnhandledRejectionIntegration: jest.fn(() => ({ name: 'OnUnhandledRejection' })),
|
||||
captureMessage: jest.fn(),
|
||||
addBreadcrumb: jest.fn()
|
||||
}));
|
||||
|
||||
// SentryService only reads the current request's tenant settings from @gauzy/core; with no request
|
||||
// in flight it falls back to "enabled when a DSN is configured".
|
||||
jest.mock('@gauzy/core', () => ({ RequestContext: { currentRequest: () => undefined } }));
|
||||
|
||||
const DSN = 'https://public@o0.ingest.sentry.io/0';
|
||||
|
||||
describe('SentryService', () => {
|
||||
beforeEach(() => {
|
||||
jest.clearAllMocks();
|
||||
// ConsoleLogger would print every call; the console output itself is not under test.
|
||||
jest.spyOn(process.stdout, 'write').mockImplementation(() => true);
|
||||
jest.spyOn(process.stderr, 'write').mockImplementation(() => true);
|
||||
});
|
||||
|
||||
afterEach(() => jest.restoreAllMocks());
|
||||
|
||||
describe("with logLevels ['error'] (what the API configures by default)", () => {
|
||||
const service = () => new SentryService({ dsn: DSN, logLevels: ['error'] });
|
||||
|
||||
it('turns log, warn, debug and verbose calls into breadcrumbs, never into events', () => {
|
||||
const logger = service();
|
||||
|
||||
logger.log('GET request to /api/employee started.', 'RequestContextMiddleware');
|
||||
logger.warn('slow query', 'Database');
|
||||
logger.debug('cache miss', 'Cache');
|
||||
logger.verbose('details', 'Cache');
|
||||
|
||||
expect(Sentry.captureMessage).not.toHaveBeenCalled();
|
||||
expect(Sentry.addBreadcrumb).toHaveBeenCalledTimes(4);
|
||||
expect((Sentry.addBreadcrumb as jest.Mock).mock.calls.map(([crumb]) => crumb.level)).toEqual([
|
||||
'log',
|
||||
'warning',
|
||||
'debug',
|
||||
'info'
|
||||
]);
|
||||
});
|
||||
|
||||
it('still sends errors to Sentry', () => {
|
||||
service().error('Redis connection lost', undefined, 'RedisModule');
|
||||
|
||||
expect(Sentry.captureMessage).toHaveBeenCalledTimes(1);
|
||||
expect(Sentry.captureMessage).toHaveBeenCalledWith(
|
||||
expect.stringContaining('Redis connection lost'),
|
||||
'error'
|
||||
);
|
||||
});
|
||||
});
|
||||
|
||||
it('captures every level listed, e.g. SENTRY_LOG_LEVELS=error,warn', () => {
|
||||
const logger = new SentryService({ dsn: DSN, logLevels: ['error', 'warn'] });
|
||||
|
||||
logger.warn('slow query', 'Database');
|
||||
logger.log('request started', 'RequestContextMiddleware');
|
||||
|
||||
expect(Sentry.captureMessage).toHaveBeenCalledTimes(1);
|
||||
expect(Sentry.captureMessage).toHaveBeenCalledWith(expect.stringContaining('slow query'), 'warning');
|
||||
expect(Sentry.addBreadcrumb).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
|
||||
it('keeps the previous capture-everything behaviour when no levels are configured', () => {
|
||||
const logger = new SentryService({ dsn: DSN });
|
||||
|
||||
logger.log('request started', 'RequestContextMiddleware');
|
||||
logger.error('boom');
|
||||
|
||||
expect(Sentry.captureMessage).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
it('honours an explicit breadcrumb request even for a captured level', () => {
|
||||
new SentryService({ dsn: DSN, logLevels: ['log'] }).log('noise', 'Ctx', true);
|
||||
|
||||
expect(Sentry.captureMessage).not.toHaveBeenCalled();
|
||||
expect(Sentry.addBreadcrumb).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
|
||||
it('sends nothing at all without a DSN', () => {
|
||||
const logger = new SentryService({ logLevels: ['error'] });
|
||||
|
||||
logger.error('boom');
|
||||
logger.log('request started');
|
||||
|
||||
expect(Sentry.captureMessage).not.toHaveBeenCalled();
|
||||
expect(Sentry.addBreadcrumb).not.toHaveBeenCalled();
|
||||
});
|
||||
});
|
||||
@@ -1,4 +1,4 @@
|
||||
import { Inject, Injectable, ConsoleLogger, OnApplicationShutdown } from '@nestjs/common';
|
||||
import { Inject, Injectable, ConsoleLogger, LogLevel, OnApplicationShutdown } from '@nestjs/common';
|
||||
import * as Sentry from '@sentry/node';
|
||||
import { RequestContext } from '@gauzy/core';
|
||||
import { SENTRY_MODULE_OPTIONS } from './sentry.constants';
|
||||
@@ -63,6 +63,18 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
return !!this.opts?.dsn;
|
||||
}
|
||||
|
||||
/**
|
||||
* Whether a message logged at `level` becomes its own Sentry event. `opts.logLevels` is the allow-list
|
||||
* (the API passes SENTRY_LOG_LEVELS, default `error`); every other level is kept as a breadcrumb, so it
|
||||
* still shows up on the next captured event. Capturing every Logger call made each request two events
|
||||
* (RequestContextMiddleware logs its start and end), which used up the org's monthly error quota within
|
||||
* hours of each reset. An unset or empty list keeps the previous behaviour of capturing every level.
|
||||
*/
|
||||
private captures(level: LogLevel): boolean {
|
||||
const levels = this.opts?.logLevels;
|
||||
return !levels?.length || levels.includes(level);
|
||||
}
|
||||
|
||||
/**
|
||||
*
|
||||
* @returns
|
||||
@@ -85,15 +97,11 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
try {
|
||||
super.log(message, context);
|
||||
if (!this.isEnabled()) return;
|
||||
asBreadcrumb
|
||||
? Sentry.addBreadcrumb({
|
||||
message,
|
||||
level: 'log',
|
||||
data: {
|
||||
context
|
||||
}
|
||||
})
|
||||
: Sentry.captureMessage(message, 'log');
|
||||
if (asBreadcrumb || !this.captures('log')) {
|
||||
Sentry.addBreadcrumb({ message, level: 'log', data: { context } });
|
||||
} else {
|
||||
Sentry.captureMessage(message, 'log');
|
||||
}
|
||||
} catch (err) {
|
||||
// do nothing to avoid blocking the application
|
||||
}
|
||||
@@ -110,7 +118,11 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
try {
|
||||
super.error(message, trace, context);
|
||||
if (!this.isEnabled()) return;
|
||||
Sentry.captureMessage(message, 'error');
|
||||
if (this.captures('error')) {
|
||||
Sentry.captureMessage(message, 'error');
|
||||
} else {
|
||||
Sentry.addBreadcrumb({ message, level: 'error', data: { context } });
|
||||
}
|
||||
} catch (err) {
|
||||
// do nothing to avoid blocking the application
|
||||
}
|
||||
@@ -127,15 +139,11 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
try {
|
||||
super.warn(message, context);
|
||||
if (!this.isEnabled()) return;
|
||||
asBreadcrumb
|
||||
? Sentry.addBreadcrumb({
|
||||
message,
|
||||
level: 'warning',
|
||||
data: {
|
||||
context
|
||||
}
|
||||
})
|
||||
: Sentry.captureMessage(message, 'warning');
|
||||
if (asBreadcrumb || !this.captures('warn')) {
|
||||
Sentry.addBreadcrumb({ message, level: 'warning', data: { context } });
|
||||
} else {
|
||||
Sentry.captureMessage(message, 'warning');
|
||||
}
|
||||
} catch (err) {
|
||||
// do nothing to avoid blocking the application
|
||||
}
|
||||
@@ -152,15 +160,11 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
try {
|
||||
super.debug(message, context);
|
||||
if (!this.isEnabled()) return;
|
||||
asBreadcrumb
|
||||
? Sentry.addBreadcrumb({
|
||||
message,
|
||||
level: 'debug',
|
||||
data: {
|
||||
context
|
||||
}
|
||||
})
|
||||
: Sentry.captureMessage(message, 'debug');
|
||||
if (asBreadcrumb || !this.captures('debug')) {
|
||||
Sentry.addBreadcrumb({ message, level: 'debug', data: { context } });
|
||||
} else {
|
||||
Sentry.captureMessage(message, 'debug');
|
||||
}
|
||||
} catch (err) {
|
||||
// do nothing to avoid blocking the application
|
||||
}
|
||||
@@ -177,15 +181,11 @@ export class SentryService extends ConsoleLogger implements OnApplicationShutdow
|
||||
try {
|
||||
super.verbose(message, context);
|
||||
if (!this.isEnabled()) return;
|
||||
asBreadcrumb
|
||||
? Sentry.addBreadcrumb({
|
||||
message,
|
||||
level: 'info',
|
||||
data: {
|
||||
context
|
||||
}
|
||||
})
|
||||
: Sentry.captureMessage(message, 'info');
|
||||
if (asBreadcrumb || !this.captures('verbose')) {
|
||||
Sentry.addBreadcrumb({ message, level: 'info', data: { context } });
|
||||
} else {
|
||||
Sentry.captureMessage(message, 'info');
|
||||
}
|
||||
} catch (err) {
|
||||
// do nothing to avoid blocking the application
|
||||
}
|
||||
|
||||
@@ -0,0 +1,15 @@
|
||||
import { parseSentryLogLevels } from './sentry-log-levels';
|
||||
|
||||
describe('parseSentryLogLevels', () => {
|
||||
it.each([undefined, '', ' ', 'nonsense', ',,'])('falls back to error only for %p', (value) => {
|
||||
expect(parseSentryLogLevels(value)).toEqual(['error']);
|
||||
});
|
||||
|
||||
it('reads a comma-separated list, case- and space-insensitively', () => {
|
||||
expect(parseSentryLogLevels(' Error , WARN ')).toEqual(['error', 'warn']);
|
||||
});
|
||||
|
||||
it('ignores unknown names and duplicates but keeps the valid ones', () => {
|
||||
expect(parseSentryLogLevels('error,info,error,log')).toEqual(['error', 'log']);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,17 @@
|
||||
import type { LogLevel } from '@nestjs/common';
|
||||
|
||||
const NEST_LOG_LEVELS: readonly LogLevel[] = ['log', 'error', 'warn', 'debug', 'verbose', 'fatal'];
|
||||
|
||||
/**
|
||||
* The Nest log levels that become Sentry events, from a comma-separated list such as `error,warn`
|
||||
* (the API reads SENTRY_LOG_LEVELS). Every other level is kept as a breadcrumb by SentryService.
|
||||
* Unknown names are ignored, and an empty or unusable value falls back to `error`: capturing every
|
||||
* log line spent the whole organisation's monthly error quota within hours of each reset.
|
||||
*/
|
||||
export function parseSentryLogLevels(value: string | undefined): LogLevel[] {
|
||||
const levels = (value ?? '')
|
||||
.split(',')
|
||||
.map((level) => level.trim().toLowerCase())
|
||||
.filter((level): level is LogLevel => NEST_LOG_LEVELS.includes(level as LogLevel));
|
||||
return levels.length ? [...new Set(levels)] : ['error'];
|
||||
}
|
||||
Reference in New Issue
Block a user