Report all logs from a container's runtime

We add a database table, which holds information about the last
timestamp of a log successfully reported to a backend (local or remote).
We then use this value to calculate from which point in time to start
reporting logs from the container. If this is the first time we've seen
a container, we get all logs, and for every log reported we save the
timestamp. If it is not the first time we've seen a container, we
request all logs since the last reported time, ensuring no interruption
of service.

Change-type: minor
Closes: #937
Signed-off-by: Cameron Diver <cameron@balena.io>

src/application-manager.coffee

@@ -75,6 +75,16 @@ module.exports = class ApplicationManager extends EventEmitter
 		@_targetVolatilePerImageId = {}
 		@_containerStarted = {}
 
+		# Rather than relying on removing out of data database entries when we're no
+		# longer using them, set a task that runs periodically to clear out the database
+		# This has the advantage that if for some reason a container is removed while the
+		# supervisor is down, we won't have zombie entries in the db
+		setInterval =>
+			@docker.listContainers(all: true).then (containers) =>
+				@logger.clearOutOfDateDBLogs(_.map(containers, 'Id'))
+		# Once a day
+		, 1000 * 60 * 60 * 24
+
 		@config.on 'change', (changedConfig) =>
 			if changedConfig.appUpdatePollInterval
 				@images.appUpdatePollInterval = changedConfig.appUpdatePollInterval

src/logger.ts

@@ -1,6 +1,7 @@
 import * as Bluebird from 'bluebird';
 import * as _ from 'lodash';
 
+import DB from './db';
 import { EventTracker } from './event-tracker';
 import Docker from './lib/docker-utils';
 import { LogType } from './lib/log-types';
@@ -25,6 +26,7 @@ interface LoggerSetupOptions {
 type LogEventObject = Dictionary<any> | null;
 
 interface LoggerConstructOptions {
+	db: DB;
 	eventTracker: EventTracker;
 }
 
@@ -34,11 +36,13 @@ export class Logger {
 	private localBackend: LocalLogBackend | null = null;
 
 	private eventTracker: EventTracker;
+	private db: DB;
 	private containerLogs: { [containerId: string]: ContainerLogs } = {};
 
-	public constructor({ eventTracker }: LoggerConstructOptions) {
+	public constructor({ db, eventTracker }: LoggerConstructOptions) {
 		this.backend = null;
 		this.eventTracker = eventTracker;
+		this.db = db;
 	}
 
 	public init({
@@ -135,18 +139,41 @@ export class Logger {
 			return Bluebird.resolve();
 		}
 
-		return Bluebird.using(this.lock(containerId), () => {
+		return Bluebird.using(this.lock(containerId), async () => {
 			const logs = new ContainerLogs(containerId, docker);
 			this.containerLogs[containerId] = logs;
 			logs.on('error', err => {
 				console.error(`Container log retrieval error: ${err}`);
 				delete this.containerLogs[containerId];
 			});
-			logs.on('log', logMessage => {
+			logs.on('log', async logMessage => {
 				this.log(_.merge({}, serviceInfo, logMessage));
+
+				// Take the timestamp and set it in the database as the last
+				// log sent for this
+				await this.db
+					.models('containerLogs')
+					.where({ containerId })
+					.update({ lastSentTimestamp: logMessage.timestamp });
 			});
+
 			logs.on('closed', () => delete this.containerLogs[containerId]);
-			return logs.attach();
+
+			// Get the timestamp of the last sent log for this container
+			let [timestampObj] = await this.db
+				.models('containerLogs')
+				.select('lastSentTimestamp')
+				.where({ containerId });
+
+			if (timestampObj == null) {
+				timestampObj = { lastSentTimestamp: 0 };
+				// Create the row so we have something to update
+				await this.db
+					.models('containerLogs')
+					.insert({ containerId, lastSentTimestamp: 0 });
+			}
+			const { lastSentTimestamp } = timestampObj;
+			return logs.attach(lastSentTimestamp);
 		});
 	}
 
@@ -194,6 +221,14 @@ export class Logger {
 		this.logSystemMessage(message, obj, eventName);
 	}
 
+	public async clearOutOfDateDBLogs(containerIds: string[]) {
+		console.log('Performing database cleanup for container log timestamps');
+		await this.db
+			.models('containerLogs')
+			.whereNotIn('containerId', containerIds)
+			.delete();
+	}
+
 	private objectNameForLogs(eventObj: LogEventObject): string | null {
 		if (eventObj == null) {
 			return null;

src/logging/container.ts

@@ -27,11 +27,11 @@ export class ContainerLogs extends (EventEmitter as {
 		super();
 	}
 
-	public async attach() {
+	public async attach(lastSentTimestamp: number) {
 		const logOpts = {
 			follow: true,
 			timestamps: true,
-			since: Math.floor(Date.now() / 1000),
+			since: Math.floor(lastSentTimestamp / 1000),
 		};
 		const stdoutLogOpts = { stdout: true, stderr: false, ...logOpts };
 		const stderrLogOpts = { stderr: true, stdout: false, ...logOpts };

src/migrations/M00004.js

@@ -0,0 +1,10 @@
+exports.up = function(knex) {
+	return knex.schema.createTable('containerLogs', table => {
+		table.string('containerId');
+		table.integer('lastSentTimestamp');
+	});
+};
+
+exports.down = function(knex, Promise) {
+	return Promise.reject(new Error('Not Implemented'));
+};

src/supervisor.coffee

@@ -30,7 +30,7 @@ module.exports = class Supervisor extends EventEmitter
 		@db = new DB()
 		@config = new Config({ @db })
 		@eventTracker = new EventTracker()
-		@logger = new Logger({ @eventTracker })
+		@logger = new Logger({ @db, @eventTracker })
 		@deviceState = new DeviceState({ @config, @db, @eventTracker, @logger })
 		@apiBinder = new APIBinder({ @config, @db, @deviceState, @eventTracker })
 

test/12-logger.spec.coffee

@@ -8,6 +8,7 @@ m = require 'mochainon'
 { stub } = m.sinon
 
 { Logger } = require '../src/logger'
+{ ContainerLogs } = require '../src/logging/container'
 describe 'Logger', ->
 	beforeEach ->
 		@_req = new stream.PassThrough()
@@ -111,7 +112,7 @@ describe 'Logger', ->
 		message = '\u0001\u0000\u0000\u0000\u0000\u0000\u0000?2018-09-21T12:37:09.819134000Z this is the message'
 		buffer = Buffer.from(message)
 
-		expect(Logger.extractContainerMessage(buffer)).to.deep.equal({
+		expect(ContainerLogs.extractMessage(buffer)).to.deep.equal({
 			message: 'this is the message',
 			timestamp: 1537533429819
 		})