From 6b11f67dc6e09b19e3182ae50bc3e4c9249ca667 Mon Sep 17 00:00:00 2001
From: Scott Nonnenberg <scott@nonnenberg.com>
Date: Mon, 25 Sep 2017 15:00:19 -0700
Subject: [PATCH] Move logging to disk via bunyan

- Logging is available in main process as well as renderer process, and
  entries all go to one set of rotating files. Log entries in the
  renderer process go to DevTools as well as the console. Entries from
  the main process only show up in the console.
- We save three days of logs, one day per file in %userData%/logs
- The 'debug' object store is deleted in a new database migration
- Timestamps and level included in the new log we generate for publish
  as well as the devtools
- The bunyan API is exposed via windows.log (providing the ability to
  log at different levels, and save objects instead of just text), so we
  can move our code to it over time.

FREEBIE
---
 app/locale.js              |   6 +-
 app/logging.js             |  89 ++++++++++++++++++++++++
 app/user_config.js         |   2 +-
 background.html            |   1 -
 js/database.js             |  10 +++
 js/debugLog.js             |  90 ------------------------
 js/logging.js              | 137 +++++++++++++++++++++++++++++++++++++
 js/views/debug_log_view.js |   8 +--
 main.js                    |  23 +++++--
 package.json               |   5 +-
 preload.js                 |   3 +-
 yarn.lock                  |  49 ++++++++++++-
 12 files changed, 315 insertions(+), 108 deletions(-)
 create mode 100644 app/logging.js
 delete mode 100644 js/debugLog.js
 create mode 100644 js/logging.js

diff --git a/app/locale.js b/app/locale.js
index 93d14d808f..7b0de1d1c6 100644
--- a/app/locale.js
+++ b/app/locale.js
@@ -3,6 +3,8 @@ const fs = require('fs');
 const app = require('electron').app;
 const _ = require('lodash');
 
+const logger = require('./logging').getLogger();
+
 function normalizeLocaleName(locale) {
   if (/^en-/.test(locale)) {
     return 'en';
@@ -42,8 +44,8 @@ function load() {
     // We start with english, then overwrite that with anything present in locale
     messages = _.merge(english, messages);
   } catch (e) {
-    console.log('Problem loading messages for locale ', localeName, e.stack);
-    console.log('Falling back to en locale');
+    logger.error('Problem loading messages for locale ' + localeName + ' ' + e.stack);
+    logger.error('Falling back to en locale');
 
     localeName = 'en';
     messages = english;
diff --git a/app/logging.js b/app/logging.js
new file mode 100644
index 0000000000..34a0ad9f1a
--- /dev/null
+++ b/app/logging.js
@@ -0,0 +1,89 @@
+const path = require('path');
+const fs = require('fs');
+
+const electron = require('electron')
+const bunyan = require('bunyan');
+const mkdirp = require('mkdirp');
+const _ = require('lodash');
+
+
+const app = electron.app;
+const ipc = electron.ipcMain;
+const LEVELS = ['fatal', 'error', 'warn', 'info', 'debug', 'trace'];
+
+let logger;
+
+
+function dropFirst(args) {
+  return Array.prototype.slice.call(args, 1);
+}
+
+function initialize() {
+  if (logger) {
+    throw new Error('Already called initialize!');
+  }
+
+  const basePath = app.getPath('userData');
+  const logPath = path.join(basePath, 'logs');
+  mkdirp.sync(logPath);
+
+  const logFile = path.join(logPath, 'log.log');
+
+  logger = bunyan.createLogger({
+    name: 'log',
+    streams: [{
+      level: 'debug',
+      stream: process.stdout
+    }, {
+      type: 'rotating-file',
+      path: logFile,
+      period: '1d',
+      count: 3
+    }]
+  });
+
+  LEVELS.forEach(function(level) {
+    ipc.on('log-' + level, function() {
+      // first parameter is the event, rest are provided arguments
+      var args = dropFirst(arguments);
+      logger[level].apply(logger, args);
+    });
+  });
+
+  ipc.on('fetch-log', function(event) {
+    event.returnValue = fetch(logPath);
+  });
+}
+
+function getLogger() {
+  if (!logger) {
+    throw new Error('Logger hasn\'t been initialized yet!');
+  }
+
+  return logger;
+}
+
+function fetch(logPath) {
+  const files = fs.readdirSync(logPath);
+  let contents = '';
+
+  files.forEach(function(file) {
+    contents += fs.readFileSync(path.join(logPath, file), { encoding: 'utf8' });
+  });
+
+  const lines = _.compact(contents.split('\n'));
+  const data = _.compact(lines.map(function(line) {
+    try {
+      return JSON.parse(line);
+    }
+    catch (e) {}
+  }));
+
+  return _.sortBy(data, 'time');
+}
+
+
+module.exports = {
+  initialize,
+  getLogger,
+};
diff --git a/app/user_config.js b/app/user_config.js
index 2855a62f9e..164ffe24e0 100644
--- a/app/user_config.js
+++ b/app/user_config.js
@@ -14,7 +14,7 @@ if (config.has('storageProfile')) {
   app.setPath('userData', userData);
 }
 
-console.log('userData ' + app.getPath('userData'));
+console.log('userData: ' + app.getPath('userData'));
 
 // this needs to be below our update to the appData path
 const userConfig = new ElectronConfig();
diff --git a/background.html b/background.html
index 58f4a295f8..8d021db408 100644
--- a/background.html
+++ b/background.html
@@ -784,7 +784,6 @@
   <script type='text/javascript' src='js/components.js'></script>
   <script type='text/javascript' src='js/reliable_trigger.js'></script>
   <script type='text/javascript' src='js/database.js'></script>
-  <script type='text/javascript' src='js/debugLog.js'></script>
   <script type='text/javascript' src='js/storage.js'></script>
   <script type='text/javascript' src='js/signal_protocol_store.js'></script>
   <script type='text/javascript' src='js/libtextsecure.js'></script>
diff --git a/js/database.js b/js/database.js
index 9675cd0f9e..e3698ab722 100644
--- a/js/database.js
+++ b/js/database.js
@@ -97,6 +97,16 @@
                 messages.createIndex('unique', ['source', 'sourceDevice', 'sent_at'], { unique: true });
                 next();
             }
+        },
+        {
+            version: "16.0",
+            migrate: function(transaction, next) {
+                console.log('migration 16.0');
+                console.log('Dropping log table, since we now log to disk');
+                var messages = transaction.db.deleteObjectStore('debug');
+                next();
+            }
         }
+
     ];
 }());
diff --git a/js/debugLog.js b/js/debugLog.js
deleted file mode 100644
index 63e56079b1..0000000000
--- a/js/debugLog.js
+++ /dev/null
@@ -1,90 +0,0 @@
-/*
- * vim: ts=4:sw=4:expandtab
- */
-(function () {
-    'use strict';
-
-    var LogEntry = Backbone.Model.extend({
-        database: Whisper.Database,
-        storeName: 'debug',
-        printTime: function() {
-            try {
-                return new Date(this.get('time')).toISOString();
-            } catch(e) {
-                return '';
-            }
-        },
-        printValue: function() {
-            return this.get('value') || '';
-        }
-    });
-
-    var DebugLog = Backbone.Collection.extend({
-        database: Whisper.Database,
-        storeName: 'debug',
-        model: LogEntry,
-        comparator: 'time',
-        initialize: function() {
-            this.fetch({remove: false}).then(function() {
-                console.log('Debug log: after fetch have', this.length, 'entries');
-            }.bind(this));
-        },
-        log: function(str) {
-            var entry = this.add({time: Date.now(), value: str});
-            if (window.Whisper.Database.nolog) {
-                entry.save();
-            }
-
-            // Two separate iterations to deal with removal eventing wonkiness
-            var toDrop = this.length - MAX_MESSAGES;
-            var entries = [];
-            for (var i = 0; i < toDrop; i += 1) {
-                entries.push(this.at(i));
-            }
-            this.remove(entries);
-            for (var j = 0, max = entries.length; j < max; j += 1) {
-                entries[j].destroy();
-            }
-        },
-        print: function() {
-            return this.map(function(entry) {
-                return entry.printTime() + ' ' + entry.printValue();
-            }).join('\n');
-        }
-    });
-
-    var MAX_MESSAGES = 2000;
-    var PHONE_REGEX = /\+\d{7,12}(\d{3})/g;
-    var log = new DebugLog();
-    if (window.console) {
-        console._log = console.log;
-        console.log = function() {
-            console._log.apply(this, arguments);
-            var args = Array.prototype.slice.call(arguments);
-            var str = args.join(' ').replace(PHONE_REGEX, "+[REDACTED]$1");
-            log.log(str);
-        };
-        console.get = function() {
-            return window.navigator.userAgent +
-                ' node/' + window.config.node_version +
-                '\n' + log.print();
-        };
-        console.post = function(log) {
-            if (log === undefined) {
-                log = console.get();
-            }
-            return new Promise(function(resolve) {
-                $.post('https://api.github.com/gists', textsecure.utils.jsonThing({
-                    "files": { "debugLog.txt": { "content": log } }
-                })).then(function(response) {
-                    console._log('Posted debug log to ', response.html_url);
-                    resolve(response.html_url);
-                }).fail(resolve);
-            });
-        };
-
-        window.onerror = function(message, script, line, col, error) {
-            console.log(error.stack);
-        };
-    }
-})();
diff --git a/js/logging.js b/js/logging.js
new file mode 100644
index 0000000000..b9520d6a47
--- /dev/null
+++ b/js/logging.js
@@ -0,0 +1,137 @@
+'use strict';
+
+const electron = require('electron');
+const bunyan = require('bunyan');
+const _ = require('lodash');
+
+
+const ipc = electron.ipcRenderer;
+const PHONE_REGEX = /\+\d{7,12}(\d{3})/g;
+
+// Default Bunyan levels: https://github.com/trentm/node-bunyan#levels
+// To make it easier to visually scan logs, we make all levels the same length
+const BLANK_LEVEL = '     ';
+const LEVELS = {
+  60: 'fatal',
+  50: 'error',
+  40: 'warn ',
+  30: 'info ',
+  20: 'debug',
+  10: 'trace',
+};
+
+
+// Backwards-compatible logging, simple strings and no level (defaulted to INFO)
+
+function now() {
+  const date = new Date();
+  return date.toJSON();
+}
+
+function log() {
+  const args = Array.prototype.slice.call(arguments, 0);
+
+  const consoleArgs = ['INFO ', now()].concat(args);
+  console._log.apply(console, consoleArgs);
+
+  const str = args.join(' ').replace(PHONE_REGEX, "+[REDACTED]$1");
+  ipc.send('log-info', str)
+}
+
+if (window.console) {
+  console._log = console.log;
+  console.log = log;
+};
+
+
+// The mechanics of preparing a log for publish
+
+function getHeader() {
+  return window.navigator.userAgent + ' node/' + window.config.node_version;
+}
+
+function getLevel(level) {
+  var text = LEVELS[level];
+  if (!text) {
+    return BLANK_LEVEL;
+  }
+
+  return text.toUpperCase();
+}
+
+function formatLine(entry) {
+  return getLevel(entry.level) + ' ' + entry.time + ' ' + entry.msg;
+}
+
+function format(entries) {
+  return entries.map(formatLine).join('\n');
+}
+
+function fetch() {
+  return getHeader() + '\n' + format(ipc.sendSync('fetch-log'));
+};
+
+function publish(log) {
+  log = log || fetch();
+
+  return new Promise(function(resolve) {
+    const payload = textsecure.utils.jsonThing({
+      files: {
+        'debugLog.txt': {
+          content: log
+        }
+      }
+    });
+
+    $.post('https://api.github.com/gists', payload)
+      .then(function(response) {
+        console._log('Posted debug log to ', response.html_url);
+        resolve(response.html_url);
+      })
+      .fail(resolve);
+  });
+};
+
+
+// A modern logging interface for the browser
+
+// We create our own stream because we don't want to output JSON to the devtools console.
+//   Anyway, the default process.stdout stream goes to the command-line, not the devtools.
+const logger = bunyan.createLogger({
+  name: 'log',
+  streams: [{
+    level: 'debug',
+    stream: {
+      write: function(entry) {
+        console._log(formatLine(JSON.parse(entry)));
+      }
+    }
+  }]
+});
+
+// The Bunyan API: https://github.com/trentm/node-bunyan#log-method-api
+function logAtLevel() {
+  const level = arguments[0];
+  const args = Array.prototype.slice.call(arguments, 1);
+
+  const ipcArgs = ['log-' + level].concat(args);
+  ipc.send.apply(ipc, ipcArgs);
+
+  logger[level].apply(logger, args);
+}
+
+window.log = {
+  fatal: _.partial(logAtLevel, 'fatal'),
+  error: _.partial(logAtLevel, 'error'),
+  warn: _.partial(logAtLevel, 'warn'),
+  info: _.partial(logAtLevel, 'info'),
+  debug: _.partial(logAtLevel, 'debug'),
+  trace: _.partial(logAtLevel, 'trace'),
+  fetch,
+  publish,
+}
+
+window.onerror = function(message, script, line, col, error) {
+  log.error(error.stack);
+};
+
diff --git a/js/views/debug_log_view.js b/js/views/debug_log_view.js
index 0ed21b9bea..628ddc96cc 100644
--- a/js/views/debug_log_view.js
+++ b/js/views/debug_log_view.js
@@ -22,7 +22,7 @@
         className: 'debug-log modal',
         initialize: function() {
             this.render();
-            this.$('textarea').val(console.get());
+            this.$('textarea').val(log.fetch());
         },
         events: {
             'click .submit': 'submit',
@@ -41,11 +41,11 @@
         },
         submit: function(e) {
             e.preventDefault();
-            var log = this.$('textarea').val();
-            if (log.length === 0) {
+            var text = this.$('textarea').val();
+            if (text.length === 0) {
                 return;
             }
-            console.post(log).then(function(url) {
+            log.publish(text).then(function(url) {
                 var view = new Whisper.DebugLogLinkView({
                     url: url,
                     el: this.$('.result')
diff --git a/main.js b/main.js
index aba7284000..55d2f86d08 100644
--- a/main.js
+++ b/main.js
@@ -1,8 +1,10 @@
+const path = require('path');
+const url = require('url');
+
 const electron = require('electron')
-const app = electron.app
-const BrowserWindow = electron.BrowserWindow
-const path = require('path')
-const url = require('url')
+
+const BrowserWindow = electron.BrowserWindow;
+const app = electron.app;
 const ipc = electron.ipcMain;
 const Menu = electron.Menu;
 const shell = electron.shell;
@@ -10,6 +12,7 @@ const shell = electron.shell;
 const autoUpdate = require('./app/auto_update');
 const windowState = require('./app/window_state');
 
+
 console.log('setting AUMID');
 app.setAppUserModelId('org.whispersystems.signal-desktop')
 
@@ -38,9 +41,15 @@ if (config.environment === 'production' && !process.mas) {
 }
 
 const userConfig = require('./app/user_config');
-let windowConfig = userConfig.get('window');
+const logging = require('./app/logging');
 
+// this must be after we set up appPath in user_config.js
+logging.initialize();
+const logger = logging.getLogger();
+
+let windowConfig = userConfig.get('window');
 const loadLocale = require('./app/locale').load;
+
 let locale;
 
 function createWindow () {
@@ -126,7 +135,7 @@ function createWindow () {
   });
 
   mainWindow.webContents.on('will-navigate', function(e) {
-    console.log('will-navigate');
+    logger.info('will-navigate');
     e.preventDefault();
   });
 
@@ -169,7 +178,7 @@ function showDebugLog() {
 // initialization and is ready to create browser windows.
 // Some APIs can only be used after this event occurs.
 app.on('ready', function() {
-  console.log('app ready');
+  logger.info('app ready');
 
   if (!locale) {
     locale = loadLocale();
diff --git a/package.json b/package.json
index bb64a7d7ec..d9f1bd9eb8 100644
--- a/package.json
+++ b/package.json
@@ -33,7 +33,7 @@
     "spectron": "^3.6.2"
   },
   "scripts": {
-    "postinstall": "electron-builder install-app-deps",
+    "postinstall": "electron-builder install-app-deps && rimraf node_modules/dtrace-provider",
     "test": "grunt test",
     "lint": "grunt jshint",
     "start": "electron .",
@@ -132,6 +132,7 @@
     ]
   },
   "dependencies": {
+    "bunyan": "^1.8.12",
     "config": "^1.26.2",
     "electron-config": "^1.0.0",
     "electron-editor-context-menu": "^1.1.1",
@@ -139,7 +140,9 @@
     "emoji-datasource-apple": "^3.0.0",
     "emoji-js": "^3.2.2",
     "lodash": "^4.17.4",
+    "mkdirp": "^0.5.1",
     "os-locale": "^2.1.0",
+    "rimraf": "^2.6.2",
     "semver": "^5.4.1",
     "spellchecker": "^3.4.3",
     "websocket": "^1.0.24"
diff --git a/preload.js b/preload.js
index 1659635906..d43f021ae4 100644
--- a/preload.js
+++ b/preload.js
@@ -7,7 +7,7 @@
   window.PROTO_ROOT = 'protos';
   window.config = require('url').parse(window.location.toString(), true).query;
 
-  const ipc = electron.ipcRenderer
+  const ipc = electron.ipcRenderer;
   window.config.localeMessages = ipc.sendSync('locale-data');
 
   window.setBadgeCount = function(count) {
@@ -31,6 +31,7 @@
 
   // We pull these dependencies in now, from here, because they have Node.js dependencies
 
+  require('./js/logging');
   require('./js/spell_check');
   require('./js/backup');
 
diff --git a/yarn.lock b/yarn.lock
index f7e2bb8f94..a7b3371bed 100644
--- a/yarn.lock
+++ b/yarn.lock
@@ -448,6 +448,15 @@ builtin-modules@^1.0.0:
   version "1.1.1"
   resolved "https://registry.yarnpkg.com/builtin-modules/-/builtin-modules-1.1.1.tgz#270f076c5a72c02f5b65a47df94c5fe3a278892f"
 
+bunyan@^1.8.12:
+  version "1.8.12"
+  resolved "https://registry.yarnpkg.com/bunyan/-/bunyan-1.8.12.tgz#f150f0f6748abdd72aeae84f04403be2ef113797"
+  optionalDependencies:
+    dtrace-provider "~0.8"
+    moment "^2.10.6"
+    mv "~2"
+    safe-json-stringify "~1"
+
 bytes@2.2.0:
   version "2.2.0"
   resolved "https://registry.yarnpkg.com/bytes/-/bytes-2.2.0.tgz#fd35464a403f6f9117c2de3609ecff9cae000588"
@@ -965,6 +974,12 @@ dotenv@^4.0.0:
   version "4.0.0"
   resolved "https://registry.yarnpkg.com/dotenv/-/dotenv-4.0.0.tgz#864ef1379aced55ce6f95debecdce179f7a0cd1d"
 
+dtrace-provider@~0.8:
+  version "0.8.5"
+  resolved "https://registry.yarnpkg.com/dtrace-provider/-/dtrace-provider-0.8.5.tgz#98ebba221afac46e1c39fd36858d8f9367524b92"
+  dependencies:
+    nan "^2.3.3"
+
 duplexer3@^0.1.4:
   version "0.1.4"
   resolved "https://registry.yarnpkg.com/duplexer3/-/duplexer3-0.1.4.tgz#ee01dd1cac0ed3cbc7fdbea37dc0a8f1ce002ce2"
@@ -1573,7 +1588,7 @@ glob@^5.0.1, glob@~5.0.0:
     once "^1.3.0"
     path-is-absolute "^1.0.0"
 
-glob@^6.0.4:
+glob@^6.0.1, glob@^6.0.4:
   version "6.0.4"
   resolved "https://registry.yarnpkg.com/glob/-/glob-6.0.4.tgz#0f08860f6a155127b2fadd4f9ce24b1aab6e4d22"
   dependencies:
@@ -2604,6 +2619,10 @@ mksnapshot@^0.3.0:
     fs-extra "0.26.7"
     request "^2.79.0"
 
+moment@^2.10.6:
+  version "2.18.1"
+  resolved "https://registry.yarnpkg.com/moment/-/moment-2.18.1.tgz#c36193dd3ce1c2eed2adb7c802dbbc77a81b1c0f"
+
 morgan@^1.6.1:
   version "1.8.1"
   resolved "https://registry.yarnpkg.com/morgan/-/morgan-1.8.1.tgz#f93023d3887bd27b78dfd6023cea7892ee27a4b1"
@@ -2630,6 +2649,14 @@ mute-stream@0.0.7, mute-stream@~0.0.4:
   version "0.0.7"
   resolved "https://registry.yarnpkg.com/mute-stream/-/mute-stream-0.0.7.tgz#3075ce93bc21b8fab43e1bc4da7e8115ed1e7bab"
 
+mv@~2:
+  version "2.1.1"
+  resolved "https://registry.yarnpkg.com/mv/-/mv-2.1.1.tgz#ae6ce0d6f6d5e0a4f7d893798d03c1ea9559b6a2"
+  dependencies:
+    mkdirp "~0.5.1"
+    ncp "~2.0.0"
+    rimraf "~2.4.0"
+
 nan@^2.0.0, nan@^2.3.2, nan@^2.3.3:
   version "2.6.2"
   resolved "https://registry.yarnpkg.com/nan/-/nan-2.6.2.tgz#e4ff34e6c95fdfb5aecc08de6596f43605a7db45"
@@ -2642,6 +2669,10 @@ ncp@0.4.x:
   version "0.4.2"
   resolved "https://registry.yarnpkg.com/ncp/-/ncp-0.4.2.tgz#abcc6cbd3ec2ed2a729ff6e7c1fa8f01784a8574"
 
+ncp@~2.0.0:
+  version "2.0.0"
+  resolved "https://registry.yarnpkg.com/ncp/-/ncp-2.0.0.tgz#195a21d6c46e361d2fb1281ba38b91e9df7bdbb3"
+
 negotiator@0.6.1:
   version "0.6.1"
   resolved "https://registry.yarnpkg.com/negotiator/-/negotiator-0.6.1.tgz#2b327184e8992101177b28563fb5e7102acd0ca9"
@@ -3350,6 +3381,18 @@ rimraf@2, rimraf@2.x.x, rimraf@^2.2.8, rimraf@~2.2.8:
   version "2.2.8"
   resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.2.8.tgz#e439be2aaee327321952730f99a8929e4fc50582"
 
+rimraf@^2.6.2:
+  version "2.6.2"
+  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.6.2.tgz#2ed8150d24a16ea8651e6d6ef0f47c4158ce7a36"
+  dependencies:
+    glob "^7.0.5"
+
+rimraf@~2.4.0:
+  version "2.4.5"
+  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.4.5.tgz#ee710ce5d93a8fdb856fb5ea8ff0e2d75934b2da"
+  dependencies:
+    glob "^6.0.1"
+
 run-async@^2.2.0:
   version "2.3.0"
   resolved "https://registry.yarnpkg.com/run-async/-/run-async-2.3.0.tgz#0371ab4ae0bdd720d4166d7dfda64ff7a445a6c0"
@@ -3364,6 +3407,10 @@ safe-buffer@^5.0.1, safe-buffer@~5.0.1:
   version "5.0.1"
   resolved "https://registry.yarnpkg.com/safe-buffer/-/safe-buffer-5.0.1.tgz#d263ca54696cd8a306b5ca6551e92de57918fbe7"
 
+safe-json-stringify@~1:
+  version "1.0.4"
+  resolved "https://registry.yarnpkg.com/safe-json-stringify/-/safe-json-stringify-1.0.4.tgz#81a098f447e4bbc3ff3312a243521bc060ef5911"
+
 sanitize-filename@^1.6.1:
   version "1.6.1"
   resolved "https://registry.yarnpkg.com/sanitize-filename/-/sanitize-filename-1.6.1.tgz#612da1c96473fa02dccda92dcd5b4ab164a6772a"