Skip to content

Commit 60542c0

Browse files
committed
fix: resolve logger test race conditions in CI
- Remove CI environment-specific test behavior (LOG_TEST_FILE_TIMEOUT) - Implement polling mechanism for file creation checks - Use unique directories per test run to avoid conflicts - Add proper error handling in test cleanup - Disable file rotation in tests for predictability The tests were failing on main branch CI due to race conditions between pino-roll worker threads and test cleanup. The fix makes tests deterministic and environment-independent.
1 parent 834f02b commit 60542c0

File tree

3 files changed

+69
-95
lines changed

3 files changed

+69
-95
lines changed

src/logger-validation.ts

Lines changed: 0 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -161,31 +161,3 @@ export function validateFileMode(mode: number | string | undefined): number {
161161

162162
return numericMode;
163163
}
164-
165-
/**
166-
* Parses and validates LOG_TEST_FILE_TIMEOUT environment variable
167-
* @returns Timeout in milliseconds
168-
*/
169-
export function getTestFileTimeout(): number {
170-
const defaultTimeout = 300;
171-
const envTimeout = process.env.LOG_TEST_FILE_TIMEOUT;
172-
173-
if (!envTimeout) {
174-
return defaultTimeout;
175-
}
176-
177-
const parsed = parseInt(envTimeout, 10);
178-
179-
if (isNaN(parsed) || parsed < 0) {
180-
// eslint-disable-next-line no-console
181-
console.warn(`Invalid LOG_TEST_FILE_TIMEOUT: ${envTimeout}, using default ${defaultTimeout}ms`);
182-
return defaultTimeout;
183-
}
184-
185-
if (parsed > 10000) {
186-
// eslint-disable-next-line no-console
187-
console.warn(`LOG_TEST_FILE_TIMEOUT is very high: ${parsed}ms`);
188-
}
189-
190-
return parsed;
191-
}

tests/logger-output.spec.ts

Lines changed: 68 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,6 @@ import { mkdirSync, rmSync, existsSync, readFileSync } from 'fs';
88
import { join } from 'path';
99
import { randomUUID } from 'crypto';
1010
import type { Logger } from '../src/logger.js';
11-
import { getTestFileTimeout } from '../src/logger-validation.js';
1211

1312
// Store original env
1413
const originalEnv = process.env;
@@ -19,7 +18,9 @@ describe('Logger Output Configuration', () => {
1918
let getLoggerOutputMode: () => string;
2019
let createChildLogger: (name: string, context?: Record<string, unknown>) => Logger;
2120

22-
const testLogDir = join(process.cwd(), 'test-logs');
21+
// Use a unique directory for this test suite run to avoid conflicts
22+
const testRunId = randomUUID();
23+
const testLogDir = join(process.cwd(), 'test-logs', testRunId);
2324
const testLogFile = join(testLogDir, 'test.log');
2425

2526
beforeEach(() => {
@@ -32,13 +33,37 @@ describe('Logger Output Configuration', () => {
3233
}
3334
});
3435

35-
afterEach(() => {
36+
afterEach(async () => {
3637
process.env = originalEnv;
3738
vi.clearAllMocks();
3839

39-
// Clean up test log directory
40+
// Add a small delay to let any async file operations complete
41+
await new Promise((resolve) => setTimeout(resolve, 10));
42+
43+
// Clean up test log directory with error handling
4044
if (existsSync(testLogDir)) {
41-
rmSync(testLogDir, { recursive: true, force: true });
45+
try {
46+
rmSync(testLogDir, { recursive: true, force: true });
47+
} catch (error) {
48+
// Ignore ENOENT errors as they're expected if the directory was already removed
49+
// Also ignore EBUSY errors from async operations still in progress
50+
if (error && typeof error === 'object' && 'code' in error) {
51+
const code = (error as { code?: string }).code;
52+
if (code !== 'ENOENT' && code !== 'EBUSY') {
53+
throw error;
54+
}
55+
}
56+
}
57+
}
58+
59+
// Clean up the parent test-logs directory if it's empty
60+
const parentTestLogDir = join(process.cwd(), 'test-logs');
61+
if (existsSync(parentTestLogDir)) {
62+
try {
63+
rmSync(parentTestLogDir, { recursive: true, force: true });
64+
} catch {
65+
// Ignore errors - directory may still have async operations
66+
}
4267
}
4368
});
4469

@@ -121,17 +146,29 @@ describe('Logger Output Configuration', () => {
121146
process.env.LOG_OUTPUT = 'file';
122147
process.env.LOG_FILE_PATH = testLogFile;
123148
process.env.NODE_ENV = 'development';
149+
// Disable file rotation for this test to make it more predictable
150+
delete process.env.LOG_FILE_MAX_SIZE;
151+
delete process.env.LOG_FILE_MAX_FILES;
124152

125153
const loggerModule = await import('../src/logger.js');
126154
logger = loggerModule.logger;
127155

128-
// Log multiple messages to ensure file is written
129-
logger.info('Test message for file output 1');
130-
logger.info('Test message for file output 2');
131-
logger.info('Test message for file output 3');
156+
// Log a message
157+
logger.info('Test message for file output');
132158

133-
// Give more time for async file write in CI
134-
await new Promise((resolve) => setTimeout(resolve, getTestFileTimeout()));
159+
// Wait for file to be created with a simple retry mechanism
160+
// This is more reliable than a fixed timeout
161+
let attempts = 0;
162+
const maxAttempts = 20;
163+
const retryDelay = 50;
164+
165+
while (attempts < maxAttempts) {
166+
if (existsSync(testLogFile)) {
167+
break;
168+
}
169+
await new Promise((resolve) => setTimeout(resolve, retryDelay));
170+
attempts++;
171+
}
135172

136173
// Check if log file was created
137174
expect(existsSync(testLogFile)).toBe(true);
@@ -173,20 +210,30 @@ describe('Logger Output Configuration', () => {
173210
process.env.LOG_OUTPUT = 'file';
174211
process.env.LOG_FILE_PATH = nestedLogPath;
175212
process.env.NODE_ENV = 'development';
213+
// Disable file rotation for predictability
214+
delete process.env.LOG_FILE_MAX_SIZE;
215+
delete process.env.LOG_FILE_MAX_FILES;
176216

177217
const loggerModule = await import('../src/logger.js');
178218
logger = loggerModule.logger;
179219

180-
// Log multiple messages to ensure file is created
181-
logger.info('Test nested directory creation 1');
182-
logger.info('Test nested directory creation 2');
183-
logger.info('Test nested directory creation 3');
220+
// Log a message
221+
logger.info('Test nested directory creation');
184222

185-
// Give more time for async file operations in CI
186-
await new Promise((resolve) => setTimeout(resolve, getTestFileTimeout()));
223+
// Wait for directory to be created with retry mechanism
224+
let attempts = 0;
225+
const maxAttempts = 20;
226+
const retryDelay = 50;
227+
228+
while (attempts < maxAttempts) {
229+
if (existsSync(nestedLogDir)) {
230+
break;
231+
}
232+
await new Promise((resolve) => setTimeout(resolve, retryDelay));
233+
attempts++;
234+
}
187235

188-
// Check if nested directories were created (check directory, not file)
189-
// File creation may be delayed, but directory should exist
236+
// Check if nested directories were created
190237
expect(existsSync(nestedLogDir)).toBe(true);
191238
});
192239
});
@@ -377,11 +424,8 @@ describe('Logger Output Configuration', () => {
377424
expect(logger).toBeDefined();
378425

379426
// Give pino-roll a moment to finish any async operations
380-
// Use configurable timeout for CI environments
381-
const timeout = process.env.LOG_TEST_FILE_TIMEOUT
382-
? parseInt(process.env.LOG_TEST_FILE_TIMEOUT, 10)
383-
: 50;
384-
await new Promise((resolve) => setTimeout(resolve, timeout));
427+
// Using a small fixed delay since we're just checking config parsing
428+
await new Promise((resolve) => setTimeout(resolve, 50));
385429
} finally {
386430
// Clean up the unique directory after each test
387431
// Use a try-catch to handle any cleanup errors gracefully

tests/logger-validation.spec.ts

Lines changed: 1 addition & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -2,13 +2,12 @@
22
* Tests for logger validation utilities
33
*/
44

5-
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
5+
import { describe, it, expect, beforeEach, vi } from 'vitest';
66
import {
77
validateLogPath,
88
validateSyslogHost,
99
validateSyslogPort,
1010
validateFileMode,
11-
getTestFileTimeout,
1211
} from '../src/logger-validation.js';
1312

1413
describe('Logger Validation', () => {
@@ -195,47 +194,6 @@ describe('Logger Validation', () => {
195194
});
196195
});
197196

198-
describe('getTestFileTimeout', () => {
199-
const originalEnv = process.env.LOG_TEST_FILE_TIMEOUT;
200-
201-
beforeEach(() => {
202-
delete process.env.LOG_TEST_FILE_TIMEOUT;
203-
});
204-
205-
afterEach(() => {
206-
if (originalEnv !== undefined) {
207-
process.env.LOG_TEST_FILE_TIMEOUT = originalEnv;
208-
}
209-
});
210-
211-
it('should return default when not set', () => {
212-
expect(getTestFileTimeout()).toBe(300);
213-
});
214-
215-
it('should parse valid timeout values', () => {
216-
process.env.LOG_TEST_FILE_TIMEOUT = '500';
217-
expect(getTestFileTimeout()).toBe(500);
218-
219-
process.env.LOG_TEST_FILE_TIMEOUT = '1000';
220-
expect(getTestFileTimeout()).toBe(1000);
221-
});
222-
223-
it('should warn about very high timeouts', () => {
224-
process.env.LOG_TEST_FILE_TIMEOUT = '15000';
225-
getTestFileTimeout();
226-
// eslint-disable-next-line no-console
227-
expect(console.warn).toHaveBeenCalledWith(expect.stringContaining('very high'));
228-
});
229-
230-
it('should return default for invalid values', () => {
231-
process.env.LOG_TEST_FILE_TIMEOUT = 'invalid';
232-
expect(getTestFileTimeout()).toBe(300);
233-
234-
process.env.LOG_TEST_FILE_TIMEOUT = '-100';
235-
expect(getTestFileTimeout()).toBe(300);
236-
});
237-
});
238-
239197
describe('Edge Cases and Security', () => {
240198
it('should handle unicode characters in file paths', () => {
241199
expect(() => validateLogPath('./logs/测试.log')).not.toThrow();

0 commit comments

Comments
 (0)