Merge pull request #1005 from balena-io/better-sync-debug

Make sync-debug much more reliable with logs

Dockerfile.debug

@@ -57,7 +57,8 @@ RUN mkdir -p dist && echo "require('../build/app.js')" > dist/app.js
 
 COPY entry.sh .
 
-RUN mkdir -p rootfs-overlay && 	([ ! -e rootfs-overlay/lib64 ] && ln -s /lib rootfs-overlay/lib64)
+RUN mkdir -p rootfs-overlay && \
+	(([ ! -d rootfs-overlay/lib64 ] && ln -s /lib rootfs-overlay/lib64) || true)
 
 ENV CONFIG_MOUNT_POINT=/boot/config.json \
 	LED_FILE=/dev/null \

package-lock.json

@@ -6581,9 +6581,9 @@
       }
     },
     "livepush": {
-      "version": "1.2.5",
+      "version": "2.0.1",
-      "resolved": "https://registry.npmjs.org/livepush/-/livepush-1.2.5.tgz",
+      "resolved": "https://registry.npmjs.org/livepush/-/livepush-2.0.1.tgz",
-      "integrity": "sha512-aPeBngn6Fr4dusLcbEcA4hM90zl4jJCqMNrYIeXqUPTNZwyA7D2SmQJp9EEYJ/9/Q8cOxi78CTY7CYdvdOR0ng==",
+      "integrity": "sha512-0UWr6T/AR4NpkcdStfOs1Ii3K2yBoX5Ipo25b56Xfuj/ytyNgByd+UUk2SB0uZEHj/QONwgbhmE64mE3oYFoOw==",
       "dev": true,
       "requires": {
         "bluebird": "^3.5.1",

package.json

@@ -73,7 +73,7 @@
     "json-mask": "^0.3.8",
     "knex": "~0.15.2",
     "lint-staged": "^8.1.0",
-    "livepush": "^1.2.5",
+    "livepush": "^2.0.1",
     "lockfile": "^1.0.1",
     "lodash": "^4.17.5",
     "log-timestamp": "^0.1.2",

sync-debug.js

@@ -20,58 +20,55 @@ const dockerode = require('dockerode');
 const chokidar = require('chokidar');
 const _ = require('lodash');
 
-require('ts-node/register');
+let lastReadTimestamp = null;
-const { ContainerLogs } = require('./src/logging/container');
+const setupLogs = async (containerId, docker) => {
-
+	const container = docker.getContainer(containerId);
-const setupLogs = (containerId, docker) => {
+	const stream = await container.logs({
-	console.log('Setting up logs');
+		stdout: true,
-	const logs = new ContainerLogs(containerId, docker);
+		stderr: true,
-	logs.on('log', ({ message }) => {
+		follow: true,
-		if (message.trim().length !== 0) {
+		timestamps: true,
-			console.log(message);
+		// We start from 0, as we risk not getting any logs to
-		}
+		// properly seed the value if the host and remote times differ
+		since: lastReadTimestamp != null ? lastReadTimestamp : 0,
+	});
+	stream.on('data', chunk => {
+		const { message, timestamp } = extractMessage(chunk);
+		lastReadTimestamp = Math.floor(timestamp.getTime() / 1000);
+		process.stdout.write(message);
+	});
+	stream.on('end', () => {
+		setupLogs(containerId, docker);
 	});
-	logs.attach(Date.now());
 };
 
+function extractMessage(msgBuf) {
+	// Non-tty message format from:
+	// https://docs.docker.com/engine/api/v1.30/#operation/ContainerAttach
+	if (_.includes([0, 1, 2], msgBuf[0])) {
+		// Take the header from this message, and parse it as normal
+		msgBuf = msgBuf.slice(8);
+	}
+	const str = msgBuf.toString();
+	const space = str.indexOf(' ');
+	return {
+		timestamp: new Date(str.slice(0, space)),
+		message: str.slice(space + 1),
+	};
+}
+
 const docker = new dockerode({
 	host: ip,
 	port: 2375,
 });
 
-function extractMessage(msgBuf) {
-	// Non-tty message format from:
-	// https://docs.docker.com/engine/api/v1.30/#operation/ContainerAttach
-	if (
-		_.includes([0, 1, 2], msgBuf[0]) &&
-		_.every(msgBuf.slice(1, 7), c => c === 0)
-	) {
-		// Take the header from this message, and parse it as normal
-		msgBuf = msgBuf.slice(8);
-	}
-	const logLine = msgBuf.toString();
-	const space = logLine.indexOf(' ');
-	if (space > 0) {
-		let timestamp = new Date(logLine.substr(0, space)).getTime();
-		if (_.isNaN(timestamp)) {
-			timestamp = Date.now();
-		}
-		return {
-			timestamp,
-			message: logLine.substr(space + 1),
-		};
-	}
-	return;
-}
-
 let changedFiles = [];
 let deletedFiles = [];
 
-const performLivepush = _.debounce(async (livepush, containerId, docker) => {
+const performLivepush = _.debounce(async livepush => {
 	await livepush.performLivepush(changedFiles, deletedFiles);
 	changedFiles = [];
 	deletedFiles = [];
-	setupLogs(containerId, docker);
 }, 1000);
 
 (async () => {
@@ -82,6 +79,8 @@ const performLivepush = _.debounce(async (livepush, containerId, docker) => {
 	const containerId = container.Id;
 	const image = container.Image;
 
+	setupLogs(containerId, docker);
+
 	const livepush = await Livepush.init(
 		await fs.readFile('Dockerfile.debug'),
 		'.',
@@ -115,7 +114,15 @@ const performLivepush = _.debounce(async (livepush, containerId, docker) => {
 		console.log('SYNC: executing:', command);
 	});
 	livepush.on('commandOutput', ({ output }) => {
-		console.log(`\t${output.data.toString()}`);
+		const message = output.data.toString();
+		if (message.trim().length !== 0) {
+			process.stdout.write(`\t${message}`);
+		}
+	});
+	livepush.on('commandReturn', ({ returnCode }) => {
+		if (returnCode !== 0) {
+			console.log(`\tSYNC: Command return non zero exit status: ${returnCode}`);
+		}
 	});
 	livepush.on('containerRestart', () => {
 		console.log('SYNC: Restarting container...');