Ensure logs are flushed before crash

src/taskworker.js

@@ -43,12 +43,23 @@ if (process.argv.length !== 4) {
 
 const taskId = process.argv[2];
 const logFile = process.argv[3];
+let logFd = null;
 
-function setupLogging(callback) {
-    const logfileStream = fs.createWriteStream(logFile, { flags:'a' });
-    process.stdout.write = process.stderr.write = logfileStream.write.bind(logfileStream);
+async function setupLogging() {
+    logFd = fs.openSync(logFile, 'a');
+    // we used to write using a stream before but it caches internally and there is no way to flush it when things crash
+    process.stdout.write = process.stderr.write = function (...args) {
+        const callback = typeof args[args.length-1] === 'function' ? args.pop() : function () {}; // callback is required for fs.write
+        fs.write.apply(fs, [logFd, ...args, callback]);
+    };
+}
 
-    callback();
+// this is also used as the 'uncaughtException' handler which can only have synchronous functions
+function exitSync(status) {
+    if (status.error) fs.write(logFd, status.error.stack + '\n', function () {});
+    fs.fsyncSync(logFd);
+    fs.closeSync(logFd);
+    process.exit(status.code);
 }
 
 // Main process starts here
@@ -66,24 +77,19 @@ async.series([
 
     const debug = require('debug')('box:taskworker'); // require this here so that logging handler is already setup
 
-    process.on('SIGTERM', () => process.exit(0)); // sent as timeout notification
+    process.on('SIGTERM', () => exitSync({ code: 0 })); // sent as timeout notification
 
     // ensure we log task crashes with the task logs. neither console.log nor debug are sync for some reason
-    process.on('uncaughtException', function (e) { fs.appendFileSync(logFile, e.stack); process.exit(1); });
+    process.on('uncaughtException', (error) => exitSync({ error, code: 1 }));
 
     debug(`Starting task ${taskId}. Logs are at ${logFile}`);
 
     const [getError, task] = await safe(tasks.get(taskId));
-    if (getError || !task) {
-        debug(getError ? `Error getting task: ${getError.message}` : 'Task not found');
-        return process.exit(50);
-    }
+    if (getError) return exitSync({ error: getError, code: 50 });
+    if (!task) return exitSync({ error: new Error(`Task ${taskId} not found`), code: 50 });
 
     const [updateError] = await safe(tasks.update(taskId, { percent: 2, error: null }));
-    if (updateError) {
-        debug(updateError);
-        return process.exit(50);
-    }
+    if (updateError) return exitSync({ error: updateError, code: 50 });
 
     const progressCallback = async function (progress, callback) {
         await safe(tasks.update(taskId, progress));
@@ -100,7 +106,7 @@ async.series([
         debug(`Task took ${(new Date() - startTime)/1000} seconds`);
 
         await safe(tasks.setCompleted(taskId, progress));
-        process.exit(error ? 50 : 0);
+        exitSync({ error, code: error ? 50 : 0 });
     };
 
     try {
@@ -111,7 +117,6 @@ async.series([
             TASKS[task.type].apply(null, task.args.concat(progressCallback).concat(resultCallback));
         }
     } catch (error) {
-        debug('Uncaught exception in task', error);
-        process.exit(1); // do not call setCompleted() intentionally. the task code must be resilient enough to handle it
+        exitSync({ error, code: 1 }); // do not call setCompleted() intentionally. the task code must be resilient enough to handle it
     }
 });