From a6164eb79e4589247005067ca90092d6617317d5 Mon Sep 17 00:00:00 2001 From: Brian Donovan <1938+eventualbuddha@users.noreply.github.com> Date: Tue, 9 Jan 2024 09:03:26 -0800 Subject: [PATCH] feat(basics): add `iter::toString` (#4489) & perf(logging): reduce peak memory usage in CDF export (#4490) --- .../01-iteration/06-json.exercise.ts | 4 +- libs/auth/src/cast_vote_record_hashes.test.ts | 4 +- .../src/iterators/async_iterator_plus.test.ts | 21 +- .../src/iterators/async_iterator_plus.ts | 4 + .../src/iterators/iterator_plus.test.ts | 19 +- libs/basics/src/iterators/iterator_plus.ts | 4 + libs/basics/src/iterators/lines.test.ts | 2 +- libs/basics/src/iterators/types.ts | 12 + libs/logging/src/export.test.ts | 325 ++++++++++++++++++ libs/logging/src/export.ts | 122 +++++++ libs/logging/src/index.ts | 7 +- libs/logging/src/logger.test.ts | 311 +---------------- libs/logging/src/logger.ts | 121 +------ libs/utils/src/json_stream.test.ts | 2 +- 14 files changed, 516 insertions(+), 442 deletions(-) create mode 100644 libs/logging/src/export.test.ts create mode 100644 libs/logging/src/export.ts diff --git a/docs/exercises/01-iteration/06-json.exercise.ts b/docs/exercises/01-iteration/06-json.exercise.ts index 3a8868aba..f70a63df0 100644 --- a/docs/exercises/01-iteration/06-json.exercise.ts +++ b/docs/exercises/01-iteration/06-json.exercise.ts @@ -140,7 +140,5 @@ function extractNamesFromContactsSolutionInner(): AsyncGenerator { // in a real application you would want to use the AsyncGenerator directly. Otherwise // you would be building up a huge string in memory. async function extractNamesFromContactsSolution(): Promise { - return (await iter(extractNamesFromContactsSolutionInner()).toArray()).join( - '' - ); + return await iter(extractNamesFromContactsSolutionInner()).toString(); } diff --git a/libs/auth/src/cast_vote_record_hashes.test.ts b/libs/auth/src/cast_vote_record_hashes.test.ts index dde92d767..6d3148d13 100644 --- a/libs/auth/src/cast_vote_record_hashes.test.ts +++ b/libs/auth/src/cast_vote_record_hashes.test.ts @@ -89,7 +89,7 @@ const expectedCastVoteRecordRootHash = test('readableFileFromData', async () => { const readableFile = readableFileFromData('1', 'a'); expect(readableFile.fileName).toEqual('1'); - expect((await iter(readableFile.open()).toArray()).join('')).toEqual('a'); + expect(await iter(readableFile.open()).toString()).toEqual('a'); expect(await readableFile.computeSha256Hash()).toEqual(sha256('a')); }); @@ -97,7 +97,7 @@ test('readableFileFromDisk', async () => { fs.writeFileSync(path.join(tempDirectoryPath, '1'), 'a'); const readableFile = readableFileFromDisk(path.join(tempDirectoryPath, '1')); expect(readableFile.fileName).toEqual('1'); - expect((await iter(readableFile.open()).toArray()).join('')).toEqual('a'); + expect(await iter(readableFile.open()).toString()).toEqual('a'); expect(await readableFile.computeSha256Hash()).toEqual(sha256('a')); }); diff --git a/libs/basics/src/iterators/async_iterator_plus.test.ts b/libs/basics/src/iterators/async_iterator_plus.test.ts index 17f55700c..e9188f322 100644 --- a/libs/basics/src/iterators/async_iterator_plus.test.ts +++ b/libs/basics/src/iterators/async_iterator_plus.test.ts @@ -321,11 +321,6 @@ test('toMap property', async () => { ); }); -test('toSet', async () => { - expect(await iter([]).async().toSet()).toEqual(new Set()); - expect(await iter([1, 2, 3]).async().toSet()).toEqual(new Set([1, 2, 3])); -}); - test('toMap from iterable', async () => { expect( await iter(integers({ from: 1, through: 10 })) @@ -339,6 +334,22 @@ test('toMap from iterable', async () => { ); }); +test('toSet', async () => { + expect(await iter([]).async().toSet()).toEqual(new Set()); + expect(await iter([1, 2, 3]).async().toSet()).toEqual(new Set([1, 2, 3])); +}); + +test('toString', async () => { + expect(await iter([]).async().toString()).toEqual(''); + expect(await iter([1, 2, 3]).async().toString()).toEqual('123'); + expect(await iter([1, 2, 3]).async().toString(' ')).toEqual('1 2 3'); + expect( + await iter([{ toString: (): string => 'hello' }, 'world']) + .async() + .toString(', ') + ).toEqual('hello, world'); +}); + test('first', async () => { expect(await iter([]).async().first()).toEqual(undefined); expect(await iter([1]).async().first()).toEqual(1); diff --git a/libs/basics/src/iterators/async_iterator_plus.ts b/libs/basics/src/iterators/async_iterator_plus.ts index 7eabfe5fc..aa0b67b12 100644 --- a/libs/basics/src/iterators/async_iterator_plus.ts +++ b/libs/basics/src/iterators/async_iterator_plus.ts @@ -391,6 +391,10 @@ export class AsyncIteratorPlusImpl implements AsyncIteratorPlus { return set; } + async toString(separator = ''): Promise { + return (await this.toArray()).join(separator); + } + windows(groupSize: 0): never; windows(groupSize: 1): AsyncIteratorPlus<[T]>; windows(groupSize: 2): AsyncIteratorPlus<[T, T]>; diff --git a/libs/basics/src/iterators/iterator_plus.test.ts b/libs/basics/src/iterators/iterator_plus.test.ts index 187409fc2..70f58a19a 100644 --- a/libs/basics/src/iterators/iterator_plus.test.ts +++ b/libs/basics/src/iterators/iterator_plus.test.ts @@ -240,11 +240,6 @@ test('toMap property', () => { ); }); -test('toSet', () => { - expect(iter([]).toSet()).toEqual(new Set()); - expect(iter([1, 2, 3]).toSet()).toEqual(new Set([1, 2, 3])); -}); - test('toMap from iterable', () => { expect(iter(integers({ from: 1, through: 10 })).toMap((a) => a % 2)).toEqual( new Map([ @@ -254,6 +249,20 @@ test('toMap from iterable', () => { ); }); +test('toSet', () => { + expect(iter([]).toSet()).toEqual(new Set()); + expect(iter([1, 2, 3]).toSet()).toEqual(new Set([1, 2, 3])); +}); + +test('toString', () => { + expect(iter([]).toString()).toEqual(''); + expect(iter([1, 2, 3]).toString()).toEqual('123'); + expect(iter([1, 2, 3]).toString(' ')).toEqual('1 2 3'); + expect( + iter([{ toString: (): string => 'hello' }, 'world']).toString(', ') + ).toEqual('hello, world'); +}); + test('first', () => { expect(iter([]).first()).toEqual(undefined); expect(iter([1]).first()).toEqual(1); diff --git a/libs/basics/src/iterators/iterator_plus.ts b/libs/basics/src/iterators/iterator_plus.ts index 95e1f15a4..9446da1f5 100644 --- a/libs/basics/src/iterators/iterator_plus.ts +++ b/libs/basics/src/iterators/iterator_plus.ts @@ -379,6 +379,10 @@ export class IteratorPlusImpl implements IteratorPlus, AsyncIterable { return new Set(this.iterable); } + toString(separator = ''): string { + return this.toArray().join(separator); + } + windows(groupSize: 0): never; windows(groupSize: 1): IteratorPlus<[T]>; windows(groupSize: 2): IteratorPlus<[T, T]>; diff --git a/libs/basics/src/iterators/lines.test.ts b/libs/basics/src/iterators/lines.test.ts index 3c159eca0..f7c340fe2 100644 --- a/libs/basics/src/iterators/lines.test.ts +++ b/libs/basics/src/iterators/lines.test.ts @@ -112,7 +112,7 @@ test('lines (async)', async () => { ).toEqual(['abc', 'de']); const input = createReadStream(__filename); - expect((await lines(input).toArray()).join('\n')).toEqual( + expect(await lines(input).toString('\n')).toEqual( await readFile(__filename, 'utf8') ); diff --git a/libs/basics/src/iterators/types.ts b/libs/basics/src/iterators/types.ts index 681c8163c..e10fcabd3 100644 --- a/libs/basics/src/iterators/types.ts +++ b/libs/basics/src/iterators/types.ts @@ -496,6 +496,12 @@ export interface IteratorPlus extends Iterable { */ toSet(): Set; + /** + * Returns a string representation of `this` by joining elements with + * `separator`. Consumes the entire contained iterable. + */ + toString(separator?: string): string; + /** * Throws an error because `groupSize` must be greater than 0. */ @@ -1121,6 +1127,12 @@ export interface AsyncIteratorPlus extends AsyncIterable { */ toSet(): Promise>; + /** + * Returns a string representation of `this` by joining elements with + * `separator`. Consumes the entire contained iterable. + */ + toString(separator?: string): Promise; + /** * Throws an error because `groupSize` must be greater than 0. */ diff --git a/libs/logging/src/export.test.ts b/libs/logging/src/export.test.ts new file mode 100644 index 000000000..733a18707 --- /dev/null +++ b/libs/logging/src/export.test.ts @@ -0,0 +1,325 @@ +import { electionTwoPartyPrimaryDefinition } from '@votingworks/fixtures'; +import { assert, iter } from '@votingworks/basics'; +import { EventLogging, safeParseJson } from '@votingworks/types'; +import { createReadStream } from 'fs'; +import { join } from 'path'; +import { LogEventId, LogEventType, LogLine, LogSource, Logger } from '.'; +import { buildCdfLog } from './export'; + +jest.useFakeTimers().setSystemTime(new Date('2020-07-24T00:00:00.000Z')); + +describe('buildCdfLog', () => { + test('builds device and election info properly', async () => { + const logger = new Logger(LogSource.VxAdminFrontend); + const cdfLogContent = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter(['']).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult = safeParseJson( + await iter(cdfLogContent).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device).toHaveLength(1); + expect(cdfLog.ElectionId).toEqual( + electionTwoPartyPrimaryDefinition.electionHash + ); + expect(cdfLog.GeneratedTime).toMatchInlineSnapshot( + `"2020-07-24T00:00:00.000Z"` + ); + const cdfLogDevice = cdfLog.Device?.[0]; + assert(cdfLogDevice); + expect(cdfLogDevice.Id).toEqual('12machine34'); + expect(cdfLogDevice.Version).toEqual('thisisacodeversion'); + expect(cdfLogDevice.Type).toEqual('ems'); + expect(cdfLogDevice.Event).toStrictEqual([]); + }); + + test('converts basic log as expected', async () => { + const logger = new Logger(LogSource.VxAdminFrontend); + const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); + const cdfLogContent = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter([ + '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"i know the deal","disposition":"na"}', + ]).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult = safeParseJson( + await iter(cdfLogContent).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device).toHaveLength(1); + const cdfLogDevice = cdfLog.Device?.[0]; + assert(cdfLogDevice); + expect(cdfLogDevice.Event).toHaveLength(1); + const decodedEvent = cdfLogDevice.Event?.[0]; + assert(decodedEvent); + expect(decodedEvent.Id).toEqual(LogEventId.UsbDriveDetected); + expect(decodedEvent.Disposition).toEqual('na'); + expect(decodedEvent.Sequence).toEqual('0'); + expect(decodedEvent.TimeStamp).toEqual('2021-11-03T16:38:09.384062-07:00'); + expect(decodedEvent.Type).toEqual(LogEventType.ApplicationStatus); + expect(decodedEvent.Description).toEqual('i know the deal'); + expect(decodedEvent.Details).toEqual( + JSON.stringify({ source: 'vx-admin-frontend' }) + ); + expect('otherDisposition' in decodedEvent).toEqual(false); + expect(logSpy).toHaveBeenCalledWith( + LogEventId.LogConversionToCdfComplete, + 'election_manager', + expect.objectContaining({ + message: 'Log file successfully converted to CDF format.', + disposition: 'success', + }) + ); + }); + + test('log with unspecified disposition as expected', async () => { + const logger = new Logger(LogSource.VxAdminFrontend); + const cdfLogContent = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter([ + '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"i know the deal","disposition":""}', + ]).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult = safeParseJson( + await iter(cdfLogContent).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device).toHaveLength(1); + const cdfLogDevice = cdfLog.Device?.[0]; + assert(cdfLogDevice); + expect(cdfLogDevice.Event).toHaveLength(1); + const decodedEvent = cdfLogDevice.Event?.[0]; + assert(decodedEvent); + expect(decodedEvent.Disposition).toEqual('na'); + }); + + test('converts log with custom disposition and extra details as expected', async () => { + const logger = new Logger(LogSource.VxAdminFrontend); + const cdfLogContent = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter([ + '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","host":"ubuntu","timeLogInitiated":"1635982689382","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"glistened as it fell","disposition":"dinosaurs","newStatus":"absent"}', + ]).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult = safeParseJson( + await iter(cdfLogContent).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device).toHaveLength(1); + const cdfLogDevice = cdfLog.Device?.[0]; + assert(cdfLogDevice); + expect(cdfLogDevice.Event).toHaveLength(1); + const decodedEvent = cdfLogDevice.Event?.[0]; + assert(decodedEvent); + expect(decodedEvent.Id).toEqual(LogEventId.UsbDriveDetected); + expect(decodedEvent.Disposition).toEqual('other'); + expect(decodedEvent.OtherDisposition).toEqual('dinosaurs'); + expect(decodedEvent.Sequence).toEqual('0'); + expect(decodedEvent.TimeStamp).toEqual('2021-11-03T16:38:09.384062-07:00'); + expect(decodedEvent.Type).toEqual(LogEventType.ApplicationStatus); + expect(decodedEvent.Description).toEqual('glistened as it fell'); + expect(decodedEvent.Details).toMatchInlineSnapshot( + `"{"host":"ubuntu","newStatus":"absent","source":"vx-admin-frontend"}"` + ); + }); + + test('non frontend apps can not export cdf logs', async () => { + const logger = new Logger(LogSource.System); + const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); + await expect( + iter( + buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter(['']).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ) + ).toString() + ).rejects.toThrowError('Can only export CDF logs from a frontend app.'); + expect(logSpy).toHaveBeenCalledWith( + LogEventId.LogConversionToCdfComplete, + 'election_manager', + expect.objectContaining({ + message: 'The current application is not able to export logs.', + disposition: 'failure', + }) + ); + }); + + test('malformed logs are logged', async () => { + const logger = new Logger(LogSource.VxAdminFrontend); + const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); + const missingTimeLogLine: LogLine = { + source: LogSource.System, + eventId: LogEventId.DeviceAttached, + eventType: LogEventType.ApplicationAction, + user: 'system', + disposition: 'na', + message: 'message', + }; + const missingTimeLog = JSON.stringify(missingTimeLogLine); + const properLog = JSON.stringify({ + ...missingTimeLogLine, + timeLogWritten: '2020-07-24T00:00:00.000Z', + }); + const output = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter([`rawr\n${properLog}\n`]).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult = safeParseJson( + await iter(output).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(logSpy).toHaveBeenCalledWith( + LogEventId.LogConversionToCdfLogLineError, + 'election_manager', + expect.objectContaining({ + message: + 'Malformed log line identified, log line will be ignored: rawr ', + disposition: 'failure', + }) + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device?.[0]!.Event).toHaveLength(1); + + const output2 = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + iter(missingTimeLog).async(), + '12machine34', + 'thisisacodeversion', + 'election_manager' + ); + const cdfLogResult2 = safeParseJson( + await iter(output2).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(logSpy).toHaveBeenCalledWith( + LogEventId.LogConversionToCdfLogLineError, + 'election_manager', + expect.objectContaining({ + message: `Malformed log line identified, log line will be ignored: ${missingTimeLog} `, + disposition: 'failure', + }) + ); + expect(cdfLogResult2.isOk()).toBeTruthy(); + const cdfLog2 = cdfLogResult2.ok(); + assert(cdfLog2); + expect(cdfLog2.Device?.[0]!.Event).toStrictEqual([]); + }); + + test('read and interpret a real log file as expected', async () => { + const logFile = createReadStream( + join(__dirname, '../fixtures/samplelog.log') + ); + const logger = new Logger(LogSource.VxAdminFrontend); + const cdfLogContent = buildCdfLog( + logger, + electionTwoPartyPrimaryDefinition, + logFile, + '1234', + 'codeversion', + 'vx-staff' + ); + const cdfLogResult = safeParseJson( + await iter(cdfLogContent).toString(), + EventLogging.ElectionEventLogSchema + ); + expect(cdfLogResult.isOk()).toBeTruthy(); + const cdfLog = cdfLogResult.ok(); + assert(cdfLog); + expect(cdfLog.Device).toHaveLength(1); + expect(cdfLog.ElectionId).toEqual( + electionTwoPartyPrimaryDefinition.electionHash + ); + expect(cdfLog.GeneratedTime).toMatchInlineSnapshot( + `"2020-07-24T00:00:00.000Z"` + ); + const cdfLogDevice = cdfLog.Device?.[0]; + assert(cdfLogDevice); + expect(cdfLogDevice.Id).toEqual('1234'); + expect(cdfLogDevice.Version).toEqual('codeversion'); + expect(cdfLogDevice.Type).toEqual('ems'); + const events = cdfLogDevice.Event!; + // There are 35 log lines in the sample file. + expect(events).toHaveLength(35); + // There should be one auth-login log from the application logging. + expect(events.filter((e) => e.Id === LogEventId.AuthLogin)).toHaveLength(1); + // There should be 11 device-attached logs from the application logging. + expect( + events.filter((e) => e.Id === LogEventId.DeviceAttached) + ).toHaveLength(11); + // There should be 4 usb-device-change-detected logs from the system logging. + expect( + events.filter((e) => e.Id === LogEventId.UsbDeviceChangeDetected) + ).toHaveLength(4); + // An application log should match the snapshot expected. + expect(events.filter((e) => e.Id === LogEventId.AuthLogout)[0]) + .toMatchInlineSnapshot(` + { + "@type": "EventLogging.Event", + "Description": "User logged out.", + "Details": "{"host":"ubuntu","source":"vx-admin-frontend"}", + "Disposition": "success", + "Id": "auth-logout", + "Sequence": "31", + "TimeStamp": "2021-12-12T15:22:14.250052-08:00", + "Type": "user-action", + "UserId": "election_manager", + } + `); + + // A system log should match the snapshot expected. + expect(events.filter((e) => e.Id === LogEventId.UsbDeviceChangeDetected)[0]) + .toMatchInlineSnapshot(` + { + "@type": "EventLogging.Event", + "Description": "usblp1: removed", + "Details": "{"host":"ubuntu","source":"system"}", + "Disposition": "na", + "Id": "usb-device-change-detected", + "Sequence": "25", + "TimeStamp": "2021-12-12T15:22:07.667632-08:00", + "Type": "system-status", + "UserId": "system", + } + `); + }); +}); diff --git a/libs/logging/src/export.ts b/libs/logging/src/export.ts new file mode 100644 index 000000000..75460f9e7 --- /dev/null +++ b/libs/logging/src/export.ts @@ -0,0 +1,122 @@ +import { assert, lines } from '@votingworks/basics'; +import { + Dictionary, + ElectionDefinition, + EventLogging, + safeParse, + safeParseJson, +} from '@votingworks/types'; +import { JsonStreamInput, jsonStream } from '@votingworks/utils'; +import { z } from 'zod'; +import { LogEventId } from './log_event_ids'; +import { CLIENT_SIDE_LOG_SOURCES } from './log_source'; +import { type Logger } from './logger'; +import { DEVICE_TYPES_FOR_APP, LogLineSchema, LoggingUserRole } from './types'; + +function extractAdditionalKeysFromObj( + innerObj: Dictionary, + outerObj: Dictionary +): Dictionary { + const baseDict: Dictionary = {}; + return Object.keys(outerObj) + .filter((key) => !(key in innerObj)) + .reduce((res, nextKey) => { + res[nextKey] = outerObj[nextKey]; + return res; + }, baseDict); +} + +async function* generateCdfEventsForExport( + logger: Logger, + currentUser: LoggingUserRole, + logFileReader: AsyncIterable +): AsyncGenerator { + const logs = lines(logFileReader).filter((l) => l !== ''); + for await (const [idx, log] of logs.enumerate()) { + const decodedLogResult = safeParseJson(log, LogLineSchema); + if (decodedLogResult.isErr()) { + await logger.log(LogEventId.LogConversionToCdfLogLineError, currentUser, { + message: `Malformed log line identified, log line will be ignored: ${log} `, + result: 'Log line will not be included in CDF output', + disposition: 'failure', + }); + continue; + } + const decodedLog = decodedLogResult.ok(); + assert(typeof decodedLog['timeLogWritten'] === 'string'); // While this is not enforced in the LogLine type the zod schema will enforce it is always present so we know this to be true. + + const rawDecodedObject = JSON.parse(log); + const customInformation = extractAdditionalKeysFromObj( + decodedLog, + rawDecodedObject + ); + + const standardDispositionResult = safeParse( + z.nativeEnum(EventLogging.EventDispositionType), + decodedLog.disposition + ); + const disposition = standardDispositionResult.isOk() + ? standardDispositionResult.ok() + : decodedLog.disposition === '' + ? EventLogging.EventDispositionType.Na + : EventLogging.EventDispositionType.Other; + const cdfEvent: EventLogging.Event = { + '@type': 'EventLogging.Event', + Id: decodedLog.eventId, + Disposition: disposition, + OtherDisposition: + disposition === 'other' ? decodedLog.disposition : undefined, + Sequence: idx.toString(), + TimeStamp: decodedLog['timeLogWritten'], + Type: decodedLog.eventType, + Description: decodedLog.message, + Details: JSON.stringify({ + ...customInformation, + source: decodedLog.source, + }), + UserId: decodedLog.user, + }; + yield cdfEvent; + } +} + +export async function* buildCdfLog( + logger: Logger, + electionDefinition: ElectionDefinition, + logFileReader: AsyncIterable, + machineId: string, + codeVersion: string, + currentUser: LoggingUserRole +): AsyncIterable { + const source = logger.getSource(); + + if (!CLIENT_SIDE_LOG_SOURCES.includes(source)) { + await logger.log(LogEventId.LogConversionToCdfComplete, currentUser, { + message: 'The current application is not able to export logs.', + result: 'Log file not converted to CDF format.', + disposition: 'failure', + }); + throw new Error('Can only export CDF logs from a frontend app.'); + } + + const currentDevice: JsonStreamInput = { + '@type': 'EventLogging.Device', + Type: DEVICE_TYPES_FOR_APP[source], + Id: machineId, + Version: codeVersion, + Event: generateCdfEventsForExport(logger, currentUser, logFileReader), + }; + const eventElectionLog: JsonStreamInput = { + '@type': 'EventLogging.ElectionEventLog', + Device: [currentDevice], + ElectionId: electionDefinition.electionHash, + GeneratedTime: new Date().toISOString(), + }; + + await logger.log(LogEventId.LogConversionToCdfComplete, currentUser, { + message: 'Log file successfully converted to CDF format.', + disposition: 'success', + }); + + return yield* jsonStream(eventElectionLog); +} diff --git a/libs/logging/src/index.ts b/libs/logging/src/index.ts index 8c232d794..e0d6e7070 100644 --- a/libs/logging/src/index.ts +++ b/libs/logging/src/index.ts @@ -1,8 +1,9 @@ /* istanbul ignore file */ -export * from './logger'; -export * from './types'; +export * from './export'; +export * from './helpers'; export * from './log_event_ids'; export * from './log_event_types'; export * from './log_source'; +export * from './logger'; export * from './test_utils'; -export * from './helpers'; +export * from './types'; diff --git a/libs/logging/src/logger.test.ts b/libs/logging/src/logger.test.ts index 7f2db252f..ff0e72633 100644 --- a/libs/logging/src/logger.test.ts +++ b/libs/logging/src/logger.test.ts @@ -1,19 +1,10 @@ /* eslint-disable no-console */ import { fakeKiosk } from '@votingworks/test-utils'; -import { readFileSync } from 'fs-extra'; -import { electionTwoPartyPrimaryDefinition } from '@votingworks/fixtures'; -import { join } from 'path'; -import { safeParseJson, EventLogging } from '@votingworks/types'; -import { assert } from '@votingworks/basics'; import { LogEventId } from './log_event_ids'; -import { Logger } from './logger'; import { LogEventType } from './log_event_types'; -import { - DEVICE_TYPES_FOR_APP, - LogDispositionStandardTypes, - LogLine, -} from './types'; import { CLIENT_SIDE_LOG_SOURCES, LogSource } from './log_source'; +import { Logger } from './logger'; +import { DEVICE_TYPES_FOR_APP, LogDispositionStandardTypes } from './types'; jest.useFakeTimers().setSystemTime(new Date('2020-07-24T00:00:00.000Z')); @@ -120,301 +111,3 @@ test('verify that client side apps are configured properly', () => { expect(source in DEVICE_TYPES_FOR_APP).toBeTruthy(); } }); - -describe('test cdf conversion', () => { - test('builds device and election info properly', () => { - const logger = new Logger(LogSource.VxAdminFrontend); - const cdfLogContent = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - '', - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - const cdfLogResult = safeParseJson( - cdfLogContent, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device).toHaveLength(1); - expect(cdfLog.ElectionId).toEqual( - electionTwoPartyPrimaryDefinition.electionHash - ); - expect(cdfLog.GeneratedTime).toMatchInlineSnapshot( - `"2020-07-24T00:00:00.000Z"` - ); - const cdfLogDevice = cdfLog.Device?.[0]; - assert(cdfLogDevice); - expect(cdfLogDevice.Id).toEqual('12machine34'); - expect(cdfLogDevice.Version).toEqual('thisisacodeversion'); - expect(cdfLogDevice.Type).toEqual('ems'); - expect(cdfLogDevice.Event).toStrictEqual([]); - }); - - test('converts basic log as expected', () => { - const logger = new Logger(LogSource.VxAdminFrontend); - const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); - const cdfLogContent = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"i know the deal","disposition":"na"}', - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - const cdfLogResult = safeParseJson( - cdfLogContent, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device).toHaveLength(1); - const cdfLogDevice = cdfLog.Device?.[0]; - assert(cdfLogDevice); - expect(cdfLogDevice.Event).toHaveLength(1); - const decodedEvent = cdfLogDevice.Event?.[0]; - assert(decodedEvent); - expect(decodedEvent.Id).toEqual(LogEventId.UsbDriveDetected); - expect(decodedEvent.Disposition).toEqual('na'); - expect(decodedEvent.Sequence).toEqual('0'); - expect(decodedEvent.TimeStamp).toEqual('2021-11-03T16:38:09.384062-07:00'); - expect(decodedEvent.Type).toEqual(LogEventType.ApplicationStatus); - expect(decodedEvent.Description).toEqual('i know the deal'); - expect(decodedEvent.Details).toEqual( - JSON.stringify({ source: 'vx-admin-frontend' }) - ); - expect('otherDisposition' in decodedEvent).toEqual(false); - expect(logSpy).toHaveBeenCalledWith( - LogEventId.LogConversionToCdfComplete, - 'election_manager', - expect.objectContaining({ - message: 'Log file successfully converted to CDF format.', - disposition: 'success', - }) - ); - }); - - test('log with unspecified disposition as expected', () => { - const logger = new Logger(LogSource.VxAdminFrontend); - const cdfLogContent = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"i know the deal","disposition":""}', - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - const cdfLogResult = safeParseJson( - cdfLogContent, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device).toHaveLength(1); - const cdfLogDevice = cdfLog.Device?.[0]; - assert(cdfLogDevice); - expect(cdfLogDevice.Event).toHaveLength(1); - const decodedEvent = cdfLogDevice.Event?.[0]; - assert(decodedEvent); - expect(decodedEvent.Disposition).toEqual('na'); - }); - - test('converts log with custom disposition and extra details as expected', () => { - const logger = new Logger(LogSource.VxAdminFrontend); - const cdfLogContent = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - '{"timeLogWritten":"2021-11-03T16:38:09.384062-07:00","host":"ubuntu","timeLogInitiated":"1635982689382","source":"vx-admin-frontend","eventId":"usb-drive-detected","eventType":"application-status","user":"system","message":"glistened as it fell","disposition":"dinosaurs","newStatus":"absent"}', - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - const cdfLogResult = safeParseJson( - cdfLogContent, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device).toHaveLength(1); - const cdfLogDevice = cdfLog.Device?.[0]; - assert(cdfLogDevice); - expect(cdfLogDevice.Event).toHaveLength(1); - const decodedEvent = cdfLogDevice.Event?.[0]; - assert(decodedEvent); - expect(decodedEvent.Id).toEqual(LogEventId.UsbDriveDetected); - expect(decodedEvent.Disposition).toEqual('other'); - expect(decodedEvent.OtherDisposition).toEqual('dinosaurs'); - expect(decodedEvent.Sequence).toEqual('0'); - expect(decodedEvent.TimeStamp).toEqual('2021-11-03T16:38:09.384062-07:00'); - expect(decodedEvent.Type).toEqual(LogEventType.ApplicationStatus); - expect(decodedEvent.Description).toEqual('glistened as it fell'); - expect(decodedEvent.Details).toMatchInlineSnapshot( - `"{"host":"ubuntu","newStatus":"absent","source":"vx-admin-frontend"}"` - ); - }); - - test('non frontend apps can not export cdf logs', () => { - const logger = new Logger(LogSource.System); - const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); - expect(() => - logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - '', - '12machine34', - 'thisisacodeversion', - 'election_manager' - ) - ).toThrowError('Can only export CDF logs from a frontend app.'); - expect(logSpy).toHaveBeenCalledWith( - LogEventId.LogConversionToCdfComplete, - 'election_manager', - expect.objectContaining({ - message: 'The current application is not able to export logs.', - disposition: 'failure', - }) - ); - }); - - test('malformed logs are logged', () => { - const logger = new Logger(LogSource.VxAdminFrontend); - const logSpy = jest.spyOn(logger, 'log').mockResolvedValue(); - const missingTimeLogLine: LogLine = { - source: LogSource.System, - eventId: LogEventId.DeviceAttached, - eventType: LogEventType.ApplicationAction, - user: 'system', - disposition: 'na', - message: 'message', - }; - const missingTimeLog = JSON.stringify(missingTimeLogLine); - const properLog = JSON.stringify({ - ...missingTimeLogLine, - timeLogWritten: '2020-07-24T00:00:00.000Z', - }); - const output = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - `rawr\n${properLog}\n`, - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - expect(logSpy).toHaveBeenCalledWith( - LogEventId.LogConversionToCdfLogLineError, - 'election_manager', - expect.objectContaining({ - message: - 'Malformed log line identified, log line will be ignored: rawr ', - disposition: 'failure', - }) - ); - const cdfLogResult = safeParseJson( - output, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device?.[0]!.Event).toHaveLength(1); - - const output2 = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - missingTimeLog, - '12machine34', - 'thisisacodeversion', - 'election_manager' - ); - expect(logSpy).toHaveBeenCalledWith( - LogEventId.LogConversionToCdfLogLineError, - 'election_manager', - expect.objectContaining({ - message: `Malformed log line identified, log line will be ignored: ${missingTimeLog} `, - disposition: 'failure', - }) - ); - const cdfLogResult2 = safeParseJson( - output2, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult2.isOk()).toBeTruthy(); - const cdfLog2 = cdfLogResult2.ok(); - assert(cdfLog2); - expect(cdfLog2.Device?.[0]!.Event).toStrictEqual([]); - }); - - test('read and interpret a real log file as expected', () => { - const logFile = readFileSync(join(__dirname, '../fixtures/samplelog.log')); - const logger = new Logger(LogSource.VxAdminFrontend); - const cdfLogContent = logger.buildCDFLog( - electionTwoPartyPrimaryDefinition, - logFile.toString(), - '1234', - 'codeversion', - 'vx-staff' - ); - const cdfLogResult = safeParseJson( - cdfLogContent, - EventLogging.ElectionEventLogSchema - ); - expect(cdfLogResult.isOk()).toBeTruthy(); - const cdfLog = cdfLogResult.ok(); - assert(cdfLog); - expect(cdfLog.Device).toHaveLength(1); - expect(cdfLog.ElectionId).toEqual( - electionTwoPartyPrimaryDefinition.electionHash - ); - expect(cdfLog.GeneratedTime).toMatchInlineSnapshot( - `"2020-07-24T00:00:00.000Z"` - ); - const cdfLogDevice = cdfLog.Device?.[0]; - assert(cdfLogDevice); - expect(cdfLogDevice.Id).toEqual('1234'); - expect(cdfLogDevice.Version).toEqual('codeversion'); - expect(cdfLogDevice.Type).toEqual('ems'); - const events = cdfLogDevice.Event!; - // There are 35 log lines in the sample file. - expect(events).toHaveLength(35); - // There should be one auth-login log from the application logging. - expect(events.filter((e) => e.Id === LogEventId.AuthLogin)).toHaveLength(1); - // There should be 11 device-attached logs from the application logging. - expect( - events.filter((e) => e.Id === LogEventId.DeviceAttached) - ).toHaveLength(11); - // There should be 4 usb-device-change-detected logs from the system logging. - expect( - events.filter((e) => e.Id === LogEventId.UsbDeviceChangeDetected) - ).toHaveLength(4); - // An application log should match the snapshot expected. - expect(events.filter((e) => e.Id === LogEventId.AuthLogout)[0]) - .toMatchInlineSnapshot(` - { - "@type": "EventLogging.Event", - "Description": "User logged out.", - "Details": "{"host":"ubuntu","source":"vx-admin-frontend"}", - "Disposition": "success", - "Id": "auth-logout", - "Sequence": "31", - "TimeStamp": "2021-12-12T15:22:14.250052-08:00", - "Type": "user-action", - "UserId": "election_manager", - } - `); - - // A system log should match the snapshot expected. - expect(events.filter((e) => e.Id === LogEventId.UsbDeviceChangeDetected)[0]) - .toMatchInlineSnapshot(` - { - "@type": "EventLogging.Event", - "Description": "usblp1: removed", - "Details": "{"host":"ubuntu","source":"system"}", - "Disposition": "na", - "Id": "usb-device-change-detected", - "Sequence": "25", - "TimeStamp": "2021-12-12T15:22:07.667632-08:00", - "Type": "system-status", - "UserId": "system", - } - `); - }); -}); diff --git a/libs/logging/src/logger.ts b/libs/logging/src/logger.ts index 20f3836d4..33d6ab96e 100644 --- a/libs/logging/src/logger.ts +++ b/libs/logging/src/logger.ts @@ -1,23 +1,13 @@ +import { Dictionary } from '@votingworks/types'; import makeDebug from 'debug'; +import { LogEventId, getDetailsForEventId } from './log_event_ids'; +import { CLIENT_SIDE_LOG_SOURCES, LogSource } from './log_source'; import { - Dictionary, - ElectionDefinition, - EventLogging, - safeParse, - safeParseJson, -} from '@votingworks/types'; -import { z } from 'zod'; -import { assert } from '@votingworks/basics'; -import { - LogLine, LogDisposition, LogDispositionStandardTypes, + LogLine, LoggingUserRole, - DEVICE_TYPES_FOR_APP, - LogLineSchema, } from './types'; -import { CLIENT_SIDE_LOG_SOURCES, LogSource } from './log_source'; -import { LogEventId, getDetailsForEventId } from './log_event_ids'; export const LOGS_ROOT_LOCATION = '/var/log'; export const LOG_NAME = 'vx-logs'; @@ -30,25 +20,16 @@ interface LogData extends Dictionary { disposition?: LogDisposition; } -export function extractAdditionalKeysFromObj( - innerObj: Dictionary, - outerObj: Dictionary -): Dictionary { - const baseDict: Dictionary = {}; - return Object.keys(outerObj) - .filter((key) => !(key in innerObj)) - .reduce((res, nextKey) => { - res[nextKey] = outerObj[nextKey]; - return res; - }, baseDict); -} - export class Logger { constructor( private readonly source: LogSource, private readonly kiosk?: KioskBrowser.Kiosk ) {} + getSource(): LogSource { + return this.source; + } + async log( eventId: LogEventId, user: LoggingUserRole, @@ -93,90 +74,4 @@ export class Logger { console.log(JSON.stringify(logLine)); } } - - buildCDFLog( - electionDefinition: ElectionDefinition, - rawLogFileContents: string, - machineId: string, - codeVersion: string, - currentUser: LoggingUserRole - ): string { - if (!CLIENT_SIDE_LOG_SOURCES.includes(this.source)) { - void this.log(LogEventId.LogConversionToCdfComplete, currentUser, { - message: 'The current application is not able to export logs.', - result: 'Log file not converted to CDF format.', - disposition: 'failure', - }); - throw new Error('Can only export CDF logs from a frontend app.'); - } - - const allEvents: EventLogging.Event[] = []; - const logs = rawLogFileContents.split('\n').filter((l) => l !== ''); - for (const [idx, log] of logs.entries()) { - const decodedLogResult = safeParseJson(log, LogLineSchema); - if (decodedLogResult.isErr()) { - void this.log(LogEventId.LogConversionToCdfLogLineError, currentUser, { - message: `Malformed log line identified, log line will be ignored: ${log} `, - result: 'Log line will not be included in CDF output', - disposition: 'failure', - }); - continue; - } - const decodedLog = decodedLogResult.ok(); - assert(typeof decodedLog['timeLogWritten'] === 'string'); // While this is not enforced in the LogLine type the zod schema will enforce it is always present so we know this to be true. - - const rawDecodedObject = JSON.parse(log); - const customInformation = extractAdditionalKeysFromObj( - decodedLog, - rawDecodedObject - ); - - const standardDispositionResult = safeParse( - z.nativeEnum(EventLogging.EventDispositionType), - decodedLog.disposition - ); - const disposition = standardDispositionResult.isOk() - ? standardDispositionResult.ok() - : decodedLog.disposition === '' - ? EventLogging.EventDispositionType.Na - : EventLogging.EventDispositionType.Other; - const cdfEvent: EventLogging.Event = { - '@type': 'EventLogging.Event', - Id: decodedLog.eventId, - Disposition: disposition, - OtherDisposition: - disposition === 'other' ? decodedLog.disposition : undefined, - Sequence: idx.toString(), - TimeStamp: decodedLog['timeLogWritten'], - Type: decodedLog.eventType, - Description: decodedLog.message, - Details: JSON.stringify({ - ...customInformation, - source: decodedLog.source, - }), - UserId: decodedLog.user, - }; - allEvents.push(cdfEvent); - } - - const currentDevice: EventLogging.Device = { - '@type': 'EventLogging.Device', - Type: DEVICE_TYPES_FOR_APP[this.source], - Id: machineId, - Version: codeVersion, - Event: allEvents, - }; - const eventElectionLog: EventLogging.ElectionEventLog = { - '@type': 'EventLogging.ElectionEventLog', - Device: [currentDevice], - ElectionId: electionDefinition.electionHash, - GeneratedTime: new Date().toISOString(), - }; - - void this.log(LogEventId.LogConversionToCdfComplete, currentUser, { - message: 'Log file successfully converted to CDF format.', - disposition: 'success', - }); - return JSON.stringify(eventElectionLog); - } } diff --git a/libs/utils/src/json_stream.test.ts b/libs/utils/src/json_stream.test.ts index 5d13da9e8..fbe02de98 100644 --- a/libs/utils/src/json_stream.test.ts +++ b/libs/utils/src/json_stream.test.ts @@ -6,7 +6,7 @@ async function asString( input: JsonStreamInput, options?: JsonStreamOptions ) { - return (await iter(jsonStream(input, options)).toArray()).join(''); + return await iter(jsonStream(input, options)).toString(); } test('number', async () => {