diff --git a/app/locale.js b/app/locale.js index 93d14d808..7b0de1d1c 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 000000000..34a0ad9f1 --- /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 2855a62f9..164ffe24e 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 58f4a295f..8d021db40 100644 --- a/background.html +++ b/background.html @@ -784,7 +784,6 @@ - diff --git a/js/database.js b/js/database.js index 9675cd0f9..e3698ab72 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 63e56079b..000000000 --- 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 000000000..b9520d6a4 --- /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 0ed21b9be..628ddc96c 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 aba728400..55d2f86d0 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 bb64a7d7e..d9f1bd9eb 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 165963590..d43f021ae 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 f7e2bb8f9..a7b3371be 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"