From 5749740a841c6b29165f99d7c1c947c911eddeb9 Mon Sep 17 00:00:00 2001 From: Hogan Bobertz Date: Fri, 13 Dec 2024 11:36:16 -0500 Subject: [PATCH] chore: add logging tests (#245) Working on some [shell/CLI logging changes](https://github.com/cdklabs/cdk-assets/pull/221/files) and need to verify that my changes are not breaking the existing functionality. Adding these tests pre-emptively before merging that pr to ensure no breaking changes --- test/logging.test.ts | 258 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 258 insertions(+) create mode 100644 test/logging.test.ts diff --git a/test/logging.test.ts b/test/logging.test.ts new file mode 100644 index 0000000..b126dd8 --- /dev/null +++ b/test/logging.test.ts @@ -0,0 +1,258 @@ +import { spawn } from 'child_process'; +import * as path from 'path'; +import { Manifest } from '@aws-cdk/cloud-assembly-schema'; +import { S3Client, ListObjectsV2Command } from '@aws-sdk/client-s3'; +import { mockClient } from 'aws-sdk-client-mock'; +import mockfs from './mock-fs'; +import { setLogThreshold, log, LogLevel } from '../bin/logging'; + +describe('Logging System', () => { + let consoleErrorSpy: jest.SpyInstance; + const originalConsoleError = console.error; + + beforeEach(() => { + consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); + }); + + afterEach(() => { + consoleErrorSpy.mockRestore(); + console.error = originalConsoleError; + }); + + describe('log threshold behavior', () => { + test('only logs messages at or above the threshold level', () => { + setLogThreshold('info'); + + log('verbose', 'Verbose message'); + log('info', 'Info message'); + log('error', 'Error message'); + + expect(consoleErrorSpy).not.toHaveBeenCalledWith(expect.stringContaining('Verbose message')); + + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Info message')); + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Error message')); + }); + + test('logs all messages when threshold is verbose', () => { + setLogThreshold('verbose'); + + log('verbose', 'Verbose message'); + log('info', 'Info message'); + log('error', 'Error message'); + + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Verbose message')); + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Info message')); + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Error message')); + }); + + test('logs only errors when threshold is error', () => { + setLogThreshold('error'); + + log('verbose', 'Verbose message'); + log('info', 'Info message'); + log('error', 'Error message'); + + expect(consoleErrorSpy).not.toHaveBeenCalledWith(expect.stringContaining('Verbose message')); + expect(consoleErrorSpy).not.toHaveBeenCalledWith(expect.stringContaining('Info message')); + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Error message')); + }); + }); + + describe('log formatting', () => { + test('pads log level names consistently', () => { + setLogThreshold('verbose'); + + log('error', 'Error message'); + log('info', 'Info message'); + log('verbose', 'Verbose message'); + + const calls = consoleErrorSpy.mock.calls; + + calls.forEach((call) => { + const logMessage = call[0] as string; + const levelPart = logMessage.split(':')[0]; + expect(levelPart.length).toBe(7); + }); + }); + }); + + describe('invalid usage', () => { + test('handles invalid log levels gracefully', () => { + setLogThreshold('info'); + + log('invalid' as LogLevel, 'Invalid level message'); + + expect(consoleErrorSpy).not.toHaveBeenCalled(); + }); + }); + describe('log level transitions', () => { + test('handles dynamic threshold changes', () => { + setLogThreshold('verbose'); + log('verbose', 'Initial verbose message'); + + setLogThreshold('info'); + log('verbose', 'Should not appear'); + log('info', 'Should appear'); + + setLogThreshold('error'); + log('info', 'Should not appear'); + log('error', 'Should appear'); + + expect(consoleErrorSpy).toHaveBeenCalledWith( + expect.stringContaining('Initial verbose message') + ); + expect(consoleErrorSpy).not.toHaveBeenCalledWith( + expect.stringContaining('Should not appear') + ); + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('Should appear')); + }); + + test('maintains message integrity across level changes', () => { + const message = 'A'.repeat(1000); + + setLogThreshold('verbose'); + log('verbose', message); + + setLogThreshold('error'); + log('error', message); + + const calls = consoleErrorSpy.mock.calls; + calls.forEach((call) => { + const logMessage = call[0] as string; + expect(logMessage).toContain(message); + }); + }); + }); +}); + +describe('CLI Logging Integration', () => { + const s3Mock = mockClient(S3Client); + + beforeEach(() => { + s3Mock.reset(); + s3Mock.on(ListObjectsV2Command).resolves({ + Contents: [], + }); + + mockfs({ + '/test/assets.json': JSON.stringify({ + version: Manifest.version(), + files: { + asset1: { + source: { + path: 'some_file', + }, + destinations: { + dest1: { + bucketName: 'test-bucket', + objectKey: 'test-key', + region: 'us-east-1', + }, + }, + }, + }, + }), + '/test/some_file': 'test content', + }); + }); + + afterEach(() => { + mockfs.restore(); + }); + + function runCli( + args: string[] + ): Promise<{ stdout: string; stderr: string; combinedOutput: string[] }> { + return new Promise((resolve, reject) => { + const cliPath = path.resolve(__dirname, '../bin/cdk-assets'); + // dummy credentials + const env = { + ...process.env, + AWS_REGION: 'us-east-1', + AWS_ACCESS_KEY_ID: 'AKIAIOSFODNN7EXAMPLE', + AWS_SECRET_ACCESS_KEY: 'wJalrXUtnFEMI/K7MDENG/bPxRfiCYEXAMPLEKEY', + }; + + const child = spawn('node', [cliPath, ...args], { env }); + + let stdout = ''; + let stderr = ''; + const combinedOutput: string[] = []; + + child.stdout.on('data', (data) => { + const str = data.toString(); + stdout += str; + combinedOutput.push(str); + }); + + child.stderr.on('data', (data) => { + const str = data.toString(); + stderr += str; + combinedOutput.push(str); + }); + + child.on('close', (code) => { + resolve({ stdout, stderr, combinedOutput }); + }); + + child.on('error', reject); + }); + } + + test('handles list command with default logging', async () => { + const { combinedOutput } = await runCli(['ls', '-p', mockfs.path('/test')]); + + const output = combinedOutput.join(''); + expect(output).toContain('asset1'); + }); + + test('shows verbose output with single -v flag', async () => { + const { combinedOutput } = await runCli(['publish', '-v', '-p', mockfs.path('/test')]); + + const output = combinedOutput.join(''); + expect(output).toContain('verbose: '); + }); + + test('shows increased verbosity with multiple verbose flags', async () => { + const { combinedOutput } = await runCli(['publish', '-vv', '-p', mockfs.path('/test')]); + + const output = combinedOutput.join(''); + const verboseCount = (output.match(/verbose: /g) || []).length; + expect(verboseCount).toBeGreaterThan(1); + }); + + test('shows help output correctly', async () => { + const { stdout } = await runCli(['--help']); + + expect(stdout).toContain('cdk-assets '); + expect(stdout).toContain('[args]'); + expect(stdout).toContain('Commands:'); + expect(stdout).toContain('Options:'); + }); + + test('shows error for invalid path', async () => { + const { stderr } = await runCli(['ls', '-p', '/invalid/path']); + expect(stderr).toContain('Error'); + }); + + test('handles publish command progress output', async () => { + const { combinedOutput } = await runCli(['publish', '-p', mockfs.path('/test')]); + + const output = combinedOutput.join(''); + expect(output).toMatch(/\[\d+%\]/); + expect(output).toContain('Publishing'); + }); + + test('shows different log levels appropriately', async () => { + const { combinedOutput } = await runCli(['publish', '-v', '-p', mockfs.path('/test')]); + + const output = combinedOutput.join(''); + expect(output).toContain('verbose: '); + expect(output).toContain('info : '); + }); + + test('command version output', async () => { + const { stdout } = await runCli(['--version']); + expect(stdout.trim()).toMatch(/\d+\.\d+\.\d+/); + }); +});