From efaa402dcad373744bf66545b7e2c22e172da061 Mon Sep 17 00:00:00 2001
From: Dexter Chua <dec41@srcf.net>
Date: Fri, 3 Jul 2020 17:42:14 +0800
Subject: [PATCH] Fix dmpWorker logging

dmpWorker is run as a childProcess, which is a completely separate
nodejs instance. As such, the `logger` it obtains is a separate instance
than the one in the parent. The parent reads the config file to
determine the log level, but the childProcess does not. So the log level
used in dmpWorker is always `debug`, regardless of the configuration
options.

In addition to polluting the logs, this is potentially a privacy issue,
because `dmpWorker` logs the diffs of notes at the `debug` level, which
will then enter the system logs.

This commit fixes this by making `dmpWorker` send any messages back to
the parent, who is responsible for logging. This also avoids any
potential race conditions between the two loggers writing to the same
output.

Fixes #433

Signed-off-by: Dexter Chua <dec41@srcf.net>
---
 src/lib/models/revision.ts   |  5 +++++
 src/lib/workers/dmpWorker.ts | 34 ++++++++++++++++++++++------------
 2 files changed, 27 insertions(+), 12 deletions(-)

diff --git a/src/lib/models/revision.ts b/src/lib/models/revision.ts
index 074d5c241..9bc12c8da 100644
--- a/src/lib/models/revision.ts
+++ b/src/lib/models/revision.ts
@@ -21,6 +21,7 @@ class Data {
   cacheKey
   error
   result
+  level
 }
 
 function createDmpWorker (): ChildProcess {
@@ -33,6 +34,10 @@ function createDmpWorker (): ChildProcess {
     }
     const cacheKey = data.cacheKey
     switch (data.msg) {
+      case 'log':
+        logger.log(data.level, data.result[0], ...data.result[1])
+        // The cacheKey is a dummy value and we want to skip the delete line.
+        return
       case 'error':
         dmpCallbackCache[cacheKey](data.error, null)
         break
diff --git a/src/lib/workers/dmpWorker.ts b/src/lib/workers/dmpWorker.ts
index cfbdf3b84..14449aa89 100644
--- a/src/lib/workers/dmpWorker.ts
+++ b/src/lib/workers/dmpWorker.ts
@@ -1,7 +1,6 @@
 // external modules
 // eslint-disable-next-line @typescript-eslint/camelcase
 import { DIFF_DELETE, DIFF_INSERT, diff_match_patch, patch_obj } from 'diff-match-patch'
-import { logger } from '../logger'
 import { Revision } from '../models'
 
 // Function for suppressing TS2722
@@ -13,6 +12,17 @@ function processSend (options): boolean {
   return false
 }
 
+// We can't use the logger directly, because we are in a distinct nodejs
+// process and the global instance of logger is not the one of the parent. In
+// particular, it does not have the log level set correctly.
+function log (level: string, msg, ...splat): boolean {
+  return processSend({
+    msg: 'log',
+    level: level,
+    result: [msg, splat],
+    cacheKey: 1 // dummy value
+  })
+}
 // eslint-disable-next-line @typescript-eslint/camelcase,new-cap
 const dmp: diff_match_patch = new diff_match_patch()
 
@@ -80,7 +90,7 @@ function getRevision (revisions: Revision[], count: number): { content: string;
     authorship: authorship
   }
   const msEnd = (new Date()).getTime()
-  logger.debug((msEnd - msStart) + 'ms')
+  log('debug', (msEnd - msStart) + 'ms')
   return data
 }
 
@@ -91,8 +101,8 @@ function createPatch (lastDoc: string, currDoc: string): string {
   const patch: patch_obj[] = dmp.patch_make(lastDoc, diff)
   const strPatch: string = dmp.patch_toText(patch)
   const msEnd = (new Date()).getTime()
-  logger.debug(strPatch)
-  logger.debug((msEnd - msStart) + 'ms')
+  log('debug', strPatch)
+  log('debug', (msEnd - msStart) + 'ms')
   return strPatch
 }
 
@@ -107,12 +117,12 @@ class Data {
 
 process.on('message', function (data: Data) {
   if (!data || !data.msg || !data.cacheKey) {
-    return logger.error('dmp worker error: not enough data')
+    return log('error', 'dmp worker error: not enough data')
   }
   switch (data.msg) {
     case 'create patch':
       if (data.lastDoc === undefined || data.currDoc === undefined) {
-        return logger.error('dmp worker error: not enough data on create patch')
+        return log('error', 'dmp worker error: not enough data on create patch')
       }
       try {
         const patch: string = createPatch(data.lastDoc, data.currDoc)
@@ -122,7 +132,7 @@ process.on('message', function (data: Data) {
           cacheKey: data.cacheKey
         })
       } catch (err) {
-        logger.error('create patch: dmp worker error', err)
+        log('error', 'create patch: dmp worker error', err)
         processSend({
           msg: 'error',
           error: err,
@@ -132,7 +142,7 @@ process.on('message', function (data: Data) {
       break
     case 'get revision':
       if (data.revisions === undefined || data.count === undefined) {
-        return logger.error('dmp worker error: not enough data on get revision')
+        return log('error', 'dmp worker error: not enough data on get revision')
       }
       try {
       // eslint-disable-next-line @typescript-eslint/camelcase
@@ -143,7 +153,7 @@ process.on('message', function (data: Data) {
           cacheKey: data.cacheKey
         })
       } catch (err) {
-        logger.error('get revision: dmp worker error', err)
+        log('error', 'get revision: dmp worker error', err)
         processSend({
           msg: 'error',
           error: err,
@@ -156,8 +166,8 @@ process.on('message', function (data: Data) {
 
 // log uncaught exception
 process.on('uncaughtException', function (err: Error) {
-  logger.error('An uncaught exception has occured.')
-  logger.error(err)
-  logger.error('Process will exit now.')
+  log('error', 'An uncaught exception has occured.')
+  log('error', err)
+  log('error', 'Process will exit now.')
   process.exit(1)
 })