Separate routes & actions, add tests for POST /v2/journal-logs

Signed-off-by: Christina Ying Wang <[email protected]>

src/device-api/actions.ts

@@ -27,6 +27,7 @@ import {
 	NotFoundError,
 	BadRequestError,
 } from '../lib/errors';
+import { JournalctlOpts, spawnJournalctl } from '../lib/journald';
 
 /**
  * Run an array of healthchecks, outputting whether all passed or not
@@ -464,3 +465,12 @@ export const cleanupVolumes = async (
 		withScope({ apps: [id] }),
 	);
 };
+
+/**
+ * Spawn a journalctl process with the given options
+ * Used by:
+ * - POST /v2/journal-logs
+ */
+export const getLogStream = (opts: JournalctlOpts) => {
+	return spawnJournalctl(opts);
+};

src/device-api/v2.ts

@@ -12,7 +12,6 @@ import * as db from '../db';
 import * as logger from '../logger';
 import * as images from '../compose/images';
 import * as serviceManager from '../compose/service-manager';
-import { spawnJournalctl } from '../lib/journald';
 import log from '../lib/supervisor-console';
 import supervisorVersion = require('../lib/supervisor-version');
 import { checkInt, checkString, checkTruthy } from '../lib/validation';
@@ -533,34 +532,31 @@ router.get('/v2/cleanup-volumes', async (req: AuthorizedRequest, res, next) => {
 	}
 });
 
-router.post('/v2/journal-logs', (req, res) => {
-	const all = checkTruthy(req.body.all);
-	const follow = checkTruthy(req.body.follow);
-	const count = checkInt(req.body.count, { positive: true }) || undefined;
-	const unit = req.body.unit;
-	const format = req.body.format || 'short';
-	const containerId = req.body.containerId;
-	const since = req.body.since;
-	const until = req.body.until;
-
-	const journald = spawnJournalctl({
-		all,
-		follow,
-		count,
-		unit,
-		format,
-		containerId,
-		since,
-		until,
-	});
-	res.status(200);
-	// We know stdout will be present
-	journald.stdout!.pipe(res);
-	res.on('close', () => {
-		journald.kill('SIGKILL');
-	});
-	journald.on('exit', () => {
-		journald.stdout!.unpipe();
-		res.end();
-	});
+router.post('/v2/journal-logs', (req, res, next) => {
+	try {
+		const opts = {
+			all: checkTruthy(req.body.all),
+			follow: checkTruthy(req.body.follow),
+			count: checkInt(req.body.count, { positive: true }),
+			unit: req.body.unit,
+			format: req.body.format,
+			containerId: req.body.containerId,
+			since: req.body.since,
+			until: req.body.until,
+		};
+
+		const journalProcess = actions.getLogStream(opts);
+		res.status(200);
+
+		journalProcess.stdout.pipe(res);
+		res.on('close', () => {
+			journalProcess.kill('SIGKILL');
+		});
+		journalProcess.on('exit', () => {
+			journalProcess.stdout.unpipe();
+			res.end();
+		});
+	} catch (e: unknown) {
+		next(e);
+	}
 });

src/lib/journald.ts

@@ -1,6 +1,7 @@
 import { ChildProcess, spawn } from 'child_process';
 
 import log from './supervisor-console';
+import { Readable } from 'stream';
 
 /**
  * Given a date integer in ms, return in a format acceptable by journalctl.
@@ -13,17 +14,24 @@ import log from './supervisor-console';
 export const toJournalDate = (timestamp: number): string =>
 	new Date(timestamp).toISOString().replace(/T/, ' ').replace(/\..+$/, '');
 
-export function spawnJournalctl(opts: {
+export interface JournalctlOpts {
 	all: boolean;
 	follow: boolean;
-	count?: number | 'all';
 	unit?: string;
 	containerId?: string;
-	format: string;
-	filterString?: string;
+	count?: number;
 	since?: string;
 	until?: string;
-}): ChildProcess {
+	format?: string;
+	matches?: string;
+}
+
+// A journalctl process has a non-null stdout
+export interface JournalctlProcess extends ChildProcess {
+	stdout: Readable;
+}
+
+export function spawnJournalctl(opts: JournalctlOpts): JournalctlProcess {
 	const args: string[] = [];
 	if (opts.all) {
 		args.push('-a');
@@ -52,10 +60,15 @@ export function spawnJournalctl(opts: {
 		args.push(opts.until);
 	}
 	args.push('-o');
-	args.push(opts.format);
-
-	if (opts.filterString) {
-		args.push(opts.filterString);
+	if (opts.format != null) {
+		args.push(opts.format);
+	} else {
+		args.push('short');
+	}
+	// Filter logs by space-seperated matches per
+	// journalctl interface of `journalctl [OPTIONS..] [MATCHES..]`
+	if (opts.matches) {
+		args.push(opts.matches);
 	}
 
 	log.debug('Spawning journalctl', args.join(' '));

src/logging/monitor.ts

@@ -65,7 +65,7 @@ class LogMonitor {
 				all: true,
 				follow: true,
 				format: 'json',
-				filterString: '_SYSTEMD_UNIT=balena.service',
+				matches: '_SYSTEMD_UNIT=balena.service',
 			},
 			(row) => {
 				if (row.CONTAINER_ID_FULL && this.containers[row.CONTAINER_ID_FULL]) {
@@ -148,7 +148,7 @@ class LogMonitor {
 				all: true,
 				follow: false,
 				format: 'json',
-				filterString: `CONTAINER_ID_FULL=${containerId}`,
+				matches: `CONTAINER_ID_FULL=${containerId}`,
 				since: toJournalDate(lastSentTimestamp + 1), // increment to exclude last sent log
 			},
 			(row) => this.handleRow(row),

test/integration/device-api/actions.spec.ts

@@ -15,7 +15,8 @@ import * as TargetState from '~/src/device-state/target-state';
 import * as applicationManager from '~/src/compose/application-manager';
 import { cleanupDocker } from '~/test-lib/docker-helper';
 
-import { exec } from '~/src/lib/fs-utils';
+import { exec } from '~/lib/fs-utils';
+import * as journald from '~/lib/journald';
 
 export async function dbusSend(
 	dest: string,
@@ -913,3 +914,31 @@ describe('cleans up orphaned volumes', () => {
 		expect(getAndRemoveOrphanedVolumesStub).to.have.been.calledOnce;
 	});
 });
+
+describe('spawns a journal process', () => {
+	// This action simply calls spawnJournalctl which we test in
+	// journald.spec.ts, so we can just stub it here
+	let spawnJournalctlStub: SinonStub;
+	before(() => {
+		spawnJournalctlStub = stub(journald, 'spawnJournalctl');
+	});
+	after(() => {
+		spawnJournalctlStub.restore();
+	});
+
+	it('spawns a journal process through journald', async () => {
+		const opts = {
+			all: true,
+			follow: true,
+			unit: 'test-unit',
+			containerId: 'test-container-id',
+			count: 10,
+			since: '2019-01-01 00:00:00',
+			until: '2019-01-01 01:00:00',
+			format: 'json',
+			matches: '_SYSTEMD_UNIT=test-unit',
+		};
+		await actions.getLogStream(opts);
+		expect(spawnJournalctlStub).to.have.been.calledOnceWith(opts);
+	});
+});

test/integration/device-api/v2.spec.ts

@@ -772,4 +772,37 @@ describe('device-api/v2', () => {
 				.expect(503);
 		});
 	});
+
+	describe('POST /v2/journal-logs', () => {
+		// Actions are tested elsewhere so we can stub the dependency here
+		let getLogStreamStub: SinonStub;
+		before(() => {
+			getLogStreamStub = stub(actions, 'getLogStream');
+		});
+		after(() => {
+			getLogStreamStub.restore();
+		});
+
+		it('responds with 200 and pipes journal stdout to response', async () => {
+			getLogStreamStub.callThrough();
+
+			await request(api)
+				.post('/v2/journal-logs')
+				.set('Authorization', `Bearer ${await deviceApi.getGlobalApiKey()}`)
+				.expect(200)
+				.then(({ text }) => {
+					// journalctl in the sut service should be empty
+					// as we don't log to it during testing
+					expect(text).to.equal('-- No entries --\n');
+				});
+		});
+
+		it('responds with 503 if an error occurred', async () => {
+			getLogStreamStub.throws(new Error());
+			await request(api)
+				.post('/v2/journal-logs')
+				.set('Authorization', `Bearer ${await deviceApi.getGlobalApiKey()}`)
+				.expect(503);
+		});
+	});
 });

test/integration/lib/journald.spec.ts

@@ -0,0 +1,71 @@
+import { expect } from 'chai';
+import { ChildProcess } from 'child_process';
+
+import { toJournalDate, spawnJournalctl } from '~/src/lib/journald';
+
+describe('lib/journald', () => {
+	describe('toJournalDate', () => {
+		it('should convert a timestamp in ms to a journalctl date', () => {
+			const journalDate = toJournalDate(
+				new Date('2019-01-01T00:00:00.000Z').getTime(),
+			);
+			expect(journalDate).to.equal('2019-01-01 00:00:00');
+		});
+	});
+
+	describe('spawnJournalctl', () => {
+		it('should spawn a journalctl process with defaults', () => {
+			const journalProcess = spawnJournalctl({
+				all: false,
+				follow: false,
+			});
+
+			expect(journalProcess).to.have.property('stdout');
+			expect(journalProcess).to.be.instanceOf(ChildProcess);
+			expect(journalProcess)
+				.to.have.property('spawnargs')
+				.that.deep.equals(['journalctl', '-o', 'short']);
+
+			journalProcess.kill('SIGKILL');
+		});
+
+		it('should spawn a journalctl process with valid options', () => {
+			const journalProcess = spawnJournalctl({
+				all: true,
+				follow: true,
+				unit: 'test-unit',
+				containerId: 'test-container',
+				count: 10,
+				since: '2019-01-01 00:00:00',
+				until: '2019-01-02 00:00:00',
+				format: 'json',
+				matches: '_SYSTEMD_UNIT=test-unit',
+			});
+
+			expect(journalProcess).to.have.property('stdout');
+			expect(journalProcess).to.be.instanceOf(ChildProcess);
+			expect(journalProcess)
+				.to.have.property('spawnargs')
+				.that.deep.equals([
+					'journalctl',
+					'-a',
+					'--follow',
+					'-u',
+					'test-unit',
+					'-t',
+					'test-container',
+					'-n',
+					'10',
+					'-S',
+					'2019-01-01 00:00:00',
+					'-U',
+					'2019-01-02 00:00:00',
+					'-o',
+					'json',
+					'_SYSTEMD_UNIT=test-unit',
+				]);
+
+			journalProcess.kill('SIGKILL');
+		});
+	});
+});