Skip to content

Commit 2d42729

Browse files
authored
fix: catch unhandled promise rejections in logging middleware (#291)
* fix: catch unhandled promise rejections in logging middleware * test(api_usage): assert exact Redis key pattern and TTL in incrWithTtlAtomic assertion
1 parent 38c4d80 commit 2d42729

2 files changed

Lines changed: 145 additions & 1 deletion

File tree

Lines changed: 142 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,142 @@
1+
'use strict';
2+
3+
const mockLogCreate = jest.fn();
4+
const mockApiAnalyticsCreate = jest.fn();
5+
const mockIncrWithTtlAtomic = jest.fn();
6+
7+
jest.mock('@urbackend/common', () => ({
8+
Log: {
9+
create: (...args) => mockLogCreate(...args),
10+
},
11+
ApiAnalytics: {
12+
create: (...args) => mockApiAnalyticsCreate(...args),
13+
},
14+
redis: {
15+
set: jest.fn().mockResolvedValue(null),
16+
},
17+
getDayKey: () => '2026-06-08',
18+
DEFAULT_DAILY_TTL_SECONDS: 86400,
19+
incrWithTtlAtomic: (...args) => mockIncrWithTtlAtomic(...args),
20+
}));
21+
22+
const { logger } = require('../middlewares/api_usage');
23+
24+
describe('api_usage middleware', () => {
25+
let req, res, next;
26+
let finishCallback;
27+
28+
beforeEach(() => {
29+
jest.clearAllMocks();
30+
req = {
31+
project: { _id: 'test_project_id' },
32+
method: 'GET',
33+
originalUrl: '/api/data/test-endpoint',
34+
ip: '127.0.0.1',
35+
_dailyCountIncremented: false,
36+
};
37+
res = {
38+
statusCode: 200,
39+
on: jest.fn((event, cb) => {
40+
if (event === 'finish') {
41+
finishCallback = cb;
42+
}
43+
}),
44+
};
45+
next = jest.fn();
46+
});
47+
48+
test('registers finish listener and calls next()', () => {
49+
logger(req, res, next);
50+
expect(next).toHaveBeenCalled();
51+
expect(res.on).toHaveBeenCalledWith('finish', expect.any(Function));
52+
});
53+
54+
test('does not register finish listener for non-analytics routes', () => {
55+
req.originalUrl = '/other/route';
56+
logger(req, res, next);
57+
expect(next).toHaveBeenCalled();
58+
expect(res.on).not.toHaveBeenCalled();
59+
});
60+
61+
test('handles successful Log.create and ApiAnalytics.create', async () => {
62+
mockLogCreate.mockResolvedValue({ _id: 'log_id' });
63+
mockApiAnalyticsCreate.mockResolvedValue({ _id: 'analytics_id' });
64+
mockIncrWithTtlAtomic.mockResolvedValue(1);
65+
66+
const consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {});
67+
68+
logger(req, res, next);
69+
expect(finishCallback).toBeDefined();
70+
71+
// Trigger finish callback
72+
await finishCallback();
73+
74+
expect(mockLogCreate).toHaveBeenCalledWith({
75+
projectId: 'test_project_id',
76+
method: 'GET',
77+
path: '/api/data/test-endpoint',
78+
status: 200,
79+
ip: '127.0.0.1',
80+
});
81+
// Assert the exact Redis key pattern and TTL value, not just invocation
82+
expect(mockIncrWithTtlAtomic).toHaveBeenCalledWith(
83+
expect.anything(), // redis instance
84+
'project:usage:req:count:test_project_id:2026-06-08',
85+
86400
86+
);
87+
88+
// Wait for setImmediate callbacks to execute
89+
await new Promise((resolve) => setImmediate(resolve));
90+
91+
expect(mockApiAnalyticsCreate).toHaveBeenCalledWith({
92+
projectId: 'test_project_id',
93+
endpoint: '/api/data/test-endpoint',
94+
method: 'GET',
95+
statusCode: 200,
96+
responseTimeMs: expect.any(Number),
97+
});
98+
99+
expect(consoleLogSpy).toHaveBeenCalledWith(expect.stringContaining('Logged: GET /api/data/test-endpoint'));
100+
consoleLogSpy.mockRestore();
101+
});
102+
103+
test('handles Log.create database failure gracefully without crashing', async () => {
104+
const dbError = new Error('Database connection failed');
105+
mockLogCreate.mockRejectedValue(dbError);
106+
mockApiAnalyticsCreate.mockResolvedValue({ _id: 'analytics_id' });
107+
mockIncrWithTtlAtomic.mockResolvedValue(1);
108+
109+
const consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
110+
111+
logger(req, res, next);
112+
await finishCallback();
113+
114+
// Log.create is fire-and-forget, so it will resolve/reject asynchronously.
115+
// We wait a tiny bit to make sure its catch block runs.
116+
await new Promise((resolve) => setTimeout(resolve, 10));
117+
118+
expect(mockLogCreate).toHaveBeenCalled();
119+
expect(consoleErrorSpy).toHaveBeenCalledWith('Logging failed:', dbError.message);
120+
121+
consoleErrorSpy.mockRestore();
122+
});
123+
124+
test('handles ApiAnalytics.create database failure gracefully without crashing', async () => {
125+
mockLogCreate.mockResolvedValue({ _id: 'log_id' });
126+
const analyticsError = new Error('Analytics write failed');
127+
mockApiAnalyticsCreate.mockRejectedValue(analyticsError);
128+
129+
const consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
130+
131+
logger(req, res, next);
132+
await finishCallback();
133+
134+
// Wait for setImmediate to trigger the analytics write and catch block
135+
await new Promise((resolve) => setImmediate(resolve));
136+
137+
expect(mockApiAnalyticsCreate).toHaveBeenCalled();
138+
expect(consoleErrorSpy).toHaveBeenCalledWith('Failed to save API analytics:', analyticsError.message);
139+
140+
consoleErrorSpy.mockRestore();
141+
});
142+
});

apps/public-api/src/middlewares/api_usage.js

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,8 @@ const logger = (req, res, next) => {
3838
path: req.originalUrl,
3939
status: res.statusCode,
4040
ip: req.ip
41+
}).catch((e) => {
42+
console.error("Logging failed:", e.message);
4143
});
4244

4345
// Usage counter (Redis): daily API requests per project
@@ -68,7 +70,7 @@ const logger = (req, res, next) => {
6870
responseTimeMs: parseFloat(responseTimeMs),
6971
});
7072
} catch (err) {
71-
console.error('Failed to save API analytics:', err);
73+
console.error('Failed to save API analytics:', err.message || err);
7274
}
7375
});
7476
}

0 commit comments

Comments
 (0)