feat(logging-p0): complete Wave 2 - Auth/Extractor/Cleaner services transformed
This commit is contained in:
Misaka
381
tests/integration/logger-performance.test.ts
Normal file
381
tests/integration/logger-performance.test.ts
Normal file
@@ -0,0 +1,381 @@
|
||||
/**
|
||||
* Performance Monitor Unit Tests
|
||||
*
|
||||
* Tests for trackDuration helper and PerformanceTracker class
|
||||
*/
|
||||
|
||||
import { describe, it, expect, vi, beforeEach, afterEach, type Mock } from 'vitest'
|
||||
import {
|
||||
trackDuration,
|
||||
PerformanceTracker,
|
||||
createPerformanceTracker,
|
||||
DEFAULT_SLOW_THRESHOLD_MS,
|
||||
type TrackDurationOptions
|
||||
} from '../../src/main/services/logger/performance-monitor'
|
||||
import logger from '../../src/main/services/logger/index'
|
||||
|
||||
// Mock the logger to avoid noisy output during tests
|
||||
vi.mock('../../src/main/services/logger/index', () => ({
|
||||
default: {
|
||||
debug: vi.fn(),
|
||||
info: vi.fn(),
|
||||
warn: vi.fn(),
|
||||
error: vi.fn(),
|
||||
child: vi.fn().mockReturnThis()
|
||||
}
|
||||
}))
|
||||
|
||||
describe('Performance Monitor', () => {
|
||||
beforeEach(() => {
|
||||
vi.clearAllMocks()
|
||||
})
|
||||
|
||||
afterEach(() => {
|
||||
vi.clearAllMocks()
|
||||
})
|
||||
|
||||
describe('trackDuration', () => {
|
||||
it('should track duration of successful async operation', async () => {
|
||||
const mockFn = vi.fn().mockResolvedValue('test result')
|
||||
|
||||
const result = await trackDuration(mockFn, {
|
||||
operationName: 'TestOperation'
|
||||
})
|
||||
|
||||
expect(result.result).toBe('test result')
|
||||
expect(result.durationMs).toBeGreaterThanOrEqual(0)
|
||||
expect(result.isSlow).toBe(false)
|
||||
expect(mockFn).toHaveBeenCalledTimes(1)
|
||||
})
|
||||
|
||||
it('should mark operation as slow when exceeding threshold', async () => {
|
||||
const slowFn = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50)))
|
||||
|
||||
const result = await trackDuration(slowFn, {
|
||||
operationName: 'SlowOperation',
|
||||
slowThresholdMs: 10
|
||||
})
|
||||
|
||||
expect(result.result).toBe('slow')
|
||||
expect(result.durationMs).toBeGreaterThan(10)
|
||||
expect(result.isSlow).toBe(true)
|
||||
})
|
||||
|
||||
it('should log with custom log level', async () => {
|
||||
const mockFn = vi.fn().mockResolvedValue('result')
|
||||
|
||||
await trackDuration(mockFn, {
|
||||
operationName: 'CustomLevelOp',
|
||||
logLevel: 'info'
|
||||
})
|
||||
|
||||
expect(logger.info).toHaveBeenCalled()
|
||||
expect(logger.warn).not.toHaveBeenCalled()
|
||||
})
|
||||
|
||||
it('should log warning for slow operations', async () => {
|
||||
const slowFn = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100)))
|
||||
|
||||
await trackDuration(slowFn, {
|
||||
operationName: 'SlowOp',
|
||||
slowThresholdMs: 50
|
||||
})
|
||||
|
||||
expect(logger.warn).toHaveBeenCalled()
|
||||
const warnCall = (logger.warn as Mock).mock.calls[0][0]
|
||||
expect(warnCall).toContain('SLOW')
|
||||
expect(warnCall).toContain('50ms threshold')
|
||||
})
|
||||
|
||||
it('should include context in logs', async () => {
|
||||
const mockFn = vi.fn().mockResolvedValue('result')
|
||||
|
||||
await trackDuration(mockFn, {
|
||||
operationName: 'ContextOp',
|
||||
context: { userId: 123, customField: 'test' }
|
||||
})
|
||||
|
||||
expect(logger.debug).toHaveBeenCalled()
|
||||
const contextCall = (logger.debug as Mock).mock.calls[0][1]
|
||||
expect(contextCall).toMatchObject({
|
||||
operation: 'ContextOp',
|
||||
userId: 123
|
||||
})
|
||||
// Also check the custom field is included
|
||||
expect(contextCall.customField).toBe('test')
|
||||
})
|
||||
|
||||
it('should log error and duration when operation fails', async () => {
|
||||
const errorFn = vi.fn().mockRejectedValue(new Error('Test error'))
|
||||
|
||||
await expect(
|
||||
trackDuration(errorFn, {
|
||||
operationName: 'ErrorOp'
|
||||
})
|
||||
).rejects.toThrow('Test error')
|
||||
|
||||
expect(logger.error).toHaveBeenCalled()
|
||||
const errorCall = (logger.error as Mock).mock.calls[0][0]
|
||||
expect(errorCall).toContain('failed after')
|
||||
expect(errorCall).toContain('ErrorOp')
|
||||
})
|
||||
|
||||
it('should use custom message in logs', async () => {
|
||||
const mockFn = vi.fn().mockResolvedValue('result')
|
||||
|
||||
await trackDuration(mockFn, {
|
||||
operationName: 'TestOp',
|
||||
message: 'Custom message for this operation'
|
||||
})
|
||||
|
||||
expect(logger.debug).toHaveBeenCalled()
|
||||
const messageCall = (logger.debug as Mock).mock.calls[0][0]
|
||||
expect(messageCall).toContain('Custom message for this operation')
|
||||
})
|
||||
|
||||
it('should have default threshold of 1000ms', async () => {
|
||||
const slowFn = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100)))
|
||||
|
||||
const result = await trackDuration(slowFn, {
|
||||
operationName: 'DefaultThresholdOp'
|
||||
})
|
||||
|
||||
// 100ms should NOT be slow with default 1000ms threshold
|
||||
expect(result.isSlow).toBe(false)
|
||||
expect(result.durationMs).toBeLessThan(1000)
|
||||
})
|
||||
})
|
||||
|
||||
describe('PerformanceTracker', () => {
|
||||
it('should track multiple operations', async () => {
|
||||
const tracker = new PerformanceTracker('TestService', 1000)
|
||||
|
||||
const mockFn1 = vi.fn().mockResolvedValue('result1')
|
||||
const mockFn2 = vi.fn().mockResolvedValue('result2')
|
||||
|
||||
const result1 = await tracker.track('Operation1', mockFn1)
|
||||
const result2 = await tracker.track('Operation2', mockFn2)
|
||||
|
||||
expect(result1).toBe('result1')
|
||||
expect(result2).toBe('result2')
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.count).toBe(2)
|
||||
expect(metrics.minDurationMs).toBeGreaterThanOrEqual(0)
|
||||
expect(metrics.maxDurationMs).toBeGreaterThanOrEqual(0)
|
||||
})
|
||||
|
||||
it('should calculate correct metrics', async () => {
|
||||
const tracker = new PerformanceTracker('TestService', 1000)
|
||||
|
||||
// Track operations with known durations
|
||||
tracker.recordDuration(100)
|
||||
tracker.recordDuration(200)
|
||||
tracker.recordDuration(300)
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
|
||||
expect(metrics.count).toBe(3)
|
||||
expect(metrics.totalDurationMs).toBe(600)
|
||||
expect(metrics.minDurationMs).toBe(100)
|
||||
expect(metrics.maxDurationMs).toBe(300)
|
||||
expect(metrics.avgDurationMs).toBe(200)
|
||||
})
|
||||
|
||||
it('should track slow operations count', async () => {
|
||||
const tracker = new PerformanceTracker('TestService', 50)
|
||||
|
||||
tracker.recordDuration(30) // Normal
|
||||
tracker.recordDuration(100) // Slow
|
||||
tracker.recordDuration(40) // Normal
|
||||
tracker.recordDuration(150) // Slow
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.slowOperationCount).toBe(2)
|
||||
})
|
||||
|
||||
it('should log warnings for slow operations', async () => {
|
||||
const tracker = new PerformanceTracker('TestService', 10)
|
||||
|
||||
const slowFn = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50)))
|
||||
|
||||
await tracker.track('SlowOp', slowFn)
|
||||
|
||||
expect(logger.warn).toHaveBeenCalled()
|
||||
const warnCall = (logger.warn as Mock).mock.calls[0][0]
|
||||
expect(warnCall).toContain('[TestService]')
|
||||
expect(warnCall).toContain('SLOW')
|
||||
})
|
||||
|
||||
it('should include context in operation logs', async () => {
|
||||
const tracker = new PerformanceTracker('DatabaseService', 1000)
|
||||
|
||||
const mockFn = vi.fn().mockResolvedValue('data')
|
||||
|
||||
await tracker.track('getUser', mockFn, { userId: 456, table: 'users' })
|
||||
|
||||
expect(logger.debug).toHaveBeenCalled()
|
||||
const contextCall = (logger.debug as Mock).mock.calls[0][1]
|
||||
expect(contextCall).toMatchObject({
|
||||
operation: 'getUser',
|
||||
userId: 456
|
||||
})
|
||||
})
|
||||
|
||||
it('should log summary with aggregated metrics', () => {
|
||||
const tracker = new PerformanceTracker('TestService', 1000)
|
||||
|
||||
tracker.recordDuration(100)
|
||||
tracker.recordDuration(200)
|
||||
tracker.recordDuration(300)
|
||||
|
||||
tracker.logSummary('info', 'Test Summary')
|
||||
|
||||
expect(logger.info).toHaveBeenCalled()
|
||||
const summaryCall = (logger.info as Mock).mock.calls[0]
|
||||
expect(summaryCall[0]).toContain('Test Summary')
|
||||
expect(summaryCall[1]).toMatchObject({
|
||||
totalOperations: 3,
|
||||
slowOperations: 0
|
||||
})
|
||||
})
|
||||
|
||||
it('should include slow percentage in summary', () => {
|
||||
const tracker = new PerformanceTracker('TestService', 50)
|
||||
|
||||
tracker.recordDuration(30) // Normal
|
||||
tracker.recordDuration(100) // Slow
|
||||
|
||||
tracker.logSummary()
|
||||
|
||||
expect(logger.info).toHaveBeenCalled()
|
||||
const summaryCall = (logger.info as Mock).mock.calls[0][1]
|
||||
expect(summaryCall.slowPercentage).toContain('%')
|
||||
})
|
||||
|
||||
it('should reset metrics when reset() is called', () => {
|
||||
const tracker = new PerformanceTracker('TestService', 1000)
|
||||
|
||||
tracker.recordDuration(100)
|
||||
tracker.recordDuration(200)
|
||||
|
||||
tracker.reset()
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.count).toBe(0)
|
||||
expect(metrics.totalDurationMs).toBe(0)
|
||||
expect(metrics.slowOperationCount).toBe(0)
|
||||
})
|
||||
|
||||
it('should return zero metrics when no operations tracked', () => {
|
||||
const tracker = new PerformanceTracker('EmptyService')
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
|
||||
expect(metrics.count).toBe(0)
|
||||
expect(metrics.totalDurationMs).toBe(0)
|
||||
expect(metrics.minDurationMs).toBe(0)
|
||||
expect(metrics.maxDurationMs).toBe(0)
|
||||
expect(metrics.avgDurationMs).toBe(0)
|
||||
expect(metrics.slowOperationCount).toBe(0)
|
||||
})
|
||||
|
||||
it('should use custom logger if provided', () => {
|
||||
const customLogger = {
|
||||
debug: vi.fn(),
|
||||
info: vi.fn(),
|
||||
warn: vi.fn(),
|
||||
error: vi.fn()
|
||||
} as unknown as typeof logger
|
||||
|
||||
const tracker = new PerformanceTracker('TestService', 1000, customLogger)
|
||||
tracker.recordDuration(100)
|
||||
|
||||
// Should use custom logger
|
||||
expect(customLogger.debug).not.toHaveBeenCalled() // We called recordDuration directly
|
||||
tracker.logSummary()
|
||||
expect(customLogger.info).toHaveBeenCalled()
|
||||
})
|
||||
})
|
||||
|
||||
describe('createPerformanceTracker', () => {
|
||||
it('should create a tracker with default threshold', () => {
|
||||
const tracker = createPerformanceTracker('MyService')
|
||||
|
||||
expect(tracker).toBeInstanceOf(PerformanceTracker)
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.count).toBe(0)
|
||||
})
|
||||
|
||||
it('should create a tracker with custom threshold', () => {
|
||||
const tracker = createPerformanceTracker('FastService', 100)
|
||||
|
||||
tracker.recordDuration(150)
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.slowOperationCount).toBe(1) // 150 > 100
|
||||
})
|
||||
|
||||
it('should use operation name in logs', async () => {
|
||||
const tracker = createPerformanceTracker('MyCustomService', 1000)
|
||||
|
||||
const mockFn = vi.fn().mockResolvedValue('result')
|
||||
await tracker.track('TestOperation', mockFn)
|
||||
|
||||
expect(logger.debug).toHaveBeenCalled()
|
||||
const call = (logger.debug as Mock).mock.calls[0][0]
|
||||
expect(call).toContain('[MyCustomService]')
|
||||
expect(call).toContain('TestOperation')
|
||||
})
|
||||
})
|
||||
|
||||
describe('Integration scenarios', () => {
|
||||
it('should track a sequence of operations with varying speeds', async () => {
|
||||
const tracker = new PerformanceTracker('DataPipeline', 100)
|
||||
|
||||
const fastOp = vi.fn().mockResolvedValue('fast')
|
||||
const mediumOp = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('medium'), 50)))
|
||||
const slowOp = vi
|
||||
.fn()
|
||||
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 200)))
|
||||
|
||||
await tracker.track('FastExtract', fastOp)
|
||||
await tracker.track('MediumTransform', mediumOp)
|
||||
await tracker.track('SlowLoad', slowOp)
|
||||
|
||||
const metrics = tracker.getMetrics()
|
||||
expect(metrics.count).toBe(3)
|
||||
expect(metrics.slowOperationCount).toBe(1) // Only SlowLoad > 100ms
|
||||
expect(metrics.maxDurationMs).toBeGreaterThan(150)
|
||||
})
|
||||
|
||||
it('should handle errors gracefully in tracker', async () => {
|
||||
const tracker = new PerformanceTracker('ErrorProneService', 1000)
|
||||
|
||||
const errorFn = vi.fn().mockRejectedValue(new Error('Expected error'))
|
||||
|
||||
await expect(tracker.track('FailingOp', errorFn)).rejects.toThrow('Expected error')
|
||||
|
||||
expect(logger.error).toHaveBeenCalled()
|
||||
const errorCall = (logger.error as Mock).mock.calls[0][0]
|
||||
expect(errorCall).toContain('[ErrorProneService]')
|
||||
expect(errorCall).toContain('failed after')
|
||||
})
|
||||
})
|
||||
|
||||
describe('Constants', () => {
|
||||
it('should export DEFAULT_SLOW_THRESHOLD_MS as 1000', () => {
|
||||
expect(DEFAULT_SLOW_THRESHOLD_MS).toBe(1000)
|
||||
})
|
||||
})
|
||||
})
|
||||
Reference in New Issue
Block a user