oxen-io/session-desktop
1
0
Fork 0
mirror of https://github.com/oxen-io/session-desktop.git synced 2023-12-14 02:12:57 +01:00
Code Issues Projects Releases Wiki Activity

Move logging to disk via bunyan

Browse source 
- 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
This commit is contained in:
Scott Nonnenberg 2017-09-25 15:00:19 -07:00
parent 33f5a804fe
commit 6b11f67dc6
No known key found for this signature in database
GPG key ID: A4931C09644C654B
12 changed files with 315 additions and 108 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
app/locale.js
View file

@ -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;

89
app/logging.js Normal file
View file

@ -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,
};

2
app/user_config.js
View file

@ -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();

1
background.html
View file

@ -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>

10
js/database.js
View file

@ -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();
}
}
];
}());

90
js/debugLog.js
View file

@ -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);
};
}
})();

137
js/logging.js Normal file
View file

@ -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);
};

8
js/views/debug_log_view.js
View file

@ -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')

23
main.js
View file

@ -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();

5
package.json
View file

@ -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"

3
preload.js
View file

@ -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');

49
yarn.lock
View file

@ -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"