From 73509542773f1d0f66cba0379a3d5b9abf0d77dc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Renaudeau?= Date: Tue, 10 Jul 2018 13:36:26 +0200 Subject: [PATCH] Fix and improve logs - bugfix that if your log file reach 20Mb the exported log is not the correct one - make the log files rotate to a gzip - include APDU in logs - blacklist some commands that was producing way too intensive logs - don't log the redux action anymore. it's not that useful and way too verbose to log --- src/commands/libcoreSignAndBroadcast.js | 4 +- src/commands/libcoreSyncAccount.js | 2 +- src/components/ExportLogsBtn.js | 40 +++++++++++++++++--- src/helpers/deviceAccess.js | 6 +-- src/helpers/resolveLogsDirectory.js | 29 +++++++------- src/logger/logger.js | 50 +++++++++++++++++++------ yarn.lock | 30 +++++++-------- 7 files changed, 108 insertions(+), 53 deletions(-) diff --git a/src/commands/libcoreSignAndBroadcast.js b/src/commands/libcoreSignAndBroadcast.js index 409e809c..8b8e6bb2 100644 --- a/src/commands/libcoreSignAndBroadcast.js +++ b/src/commands/libcoreSignAndBroadcast.js @@ -19,13 +19,15 @@ type BitcoinLikeTransaction = { } type Input = { - account: AccountRaw, + account: AccountRaw, // FIXME there is no reason we send the whole AccountRaw transaction: BitcoinLikeTransaction, deviceId: string, } type Result = { type: 'signed' } | { type: 'broadcasted', operation: OperationRaw } +// FIXME this command should be unified with 'signTransaction' command + const cmd: Command = createCommand( 'libcoreSignAndBroadcast', ({ account, transaction, deviceId }) => diff --git a/src/commands/libcoreSyncAccount.js b/src/commands/libcoreSyncAccount.js index d2677b9e..380e8151 100644 --- a/src/commands/libcoreSyncAccount.js +++ b/src/commands/libcoreSyncAccount.js @@ -8,7 +8,7 @@ import { syncAccount } from 'helpers/libcore' import withLibcore from 'helpers/withLibcore' type Input = { - rawAccount: AccountRaw, + rawAccount: AccountRaw, // FIXME there is no reason we send the whole AccountRaw } type Result = AccountRaw diff --git a/src/components/ExportLogsBtn.js b/src/components/ExportLogsBtn.js index e69dcb0d..c63d5089 100644 --- a/src/components/ExportLogsBtn.js +++ b/src/components/ExportLogsBtn.js @@ -9,13 +9,30 @@ import KeyHandler from 'react-key-handler' import { getCurrentLogFile } from 'helpers/resolveLogsDirectory' import Button from './base/Button' +function copyFile(source, target) { + const rd = fs.createReadStream(source) + const wr = fs.createWriteStream(target) + return new Promise((resolve, reject) => { + rd.on('error', reject) + wr.on('error', reject) + wr.on('finish', resolve) + rd.pipe(wr) + }).catch(error => { + // $FlowFixMe + rd.destroy() + wr.end() + throw error + }) +} + class ExportLogsBtn extends Component<{ t: *, hookToShortcut?: boolean, }> { - handleExportLogs = () => { - const srcLogFile = getCurrentLogFile() + export = async () => { + const srcLogFile = await getCurrentLogFile() const resourceUsage = webFrame.getResourceUsage() + const ext = srcLogFile.match(/[.]log[.]gz$/) ? 'log.gz' : 'log' logger.log('exportLogsMeta', { resourceUsage, release: __APP_VERSION__, @@ -27,19 +44,32 @@ class ExportLogsBtn extends Component<{ title: 'Export logs', defaultPath: `ledgerlive-export-${moment().format( 'YYYY.MM.DD-HH.mm.ss', - )}-${__GIT_REVISION__ || 'unversionned'}.log`, + )}-${__GIT_REVISION__ || 'unversionned'}.${ext}`, filters: [ { name: 'All Files', - extensions: ['log'], + extensions: [ext], }, ], }) if (path) { - fs.createReadStream(srcLogFile).pipe(fs.createWriteStream(path)) + await copyFile(srcLogFile, path) } } + exporting = false + handleExportLogs = () => { + if (this.exporting) return + this.exporting = true + this.export() + .catch(e => { + logger.critical(e) + }) + .then(() => { + this.exporting = false + }) + } + onKeyHandle = e => { if (e.ctrlKey) { this.handleExportLogs() diff --git a/src/helpers/deviceAccess.js b/src/helpers/deviceAccess.js index fe9b95e1..0aa85738 100644 --- a/src/helpers/deviceAccess.js +++ b/src/helpers/deviceAccess.js @@ -1,7 +1,7 @@ // @flow +import logger from 'logger' import type Transport from '@ledgerhq/hw-transport' import TransportNodeHid from '@ledgerhq/hw-transport-node-hid' -import { DEBUG_DEVICE } from 'config/constants' import { retry } from './promise' import { createCustomErrorClass } from './errors' @@ -31,9 +31,7 @@ export const withDevice: WithDevice = devicePath => job => { busy = true try { const t = await retry(() => TransportNodeHid.open(devicePath), { maxRetry: 1 }) - if (DEBUG_DEVICE) { - t.setDebugMode(true) - } + t.setDebugMode(logger.apdu) try { const res = await job(t).catch(mapError) return res diff --git a/src/helpers/resolveLogsDirectory.js b/src/helpers/resolveLogsDirectory.js index 3cd1ae0e..e6fedb00 100644 --- a/src/helpers/resolveLogsDirectory.js +++ b/src/helpers/resolveLogsDirectory.js @@ -1,7 +1,7 @@ // @flow +import fs from 'fs' import path from 'path' -import moment from 'moment' const resolveLogsDirectory = () => { const { LEDGER_LOGS_DIRECTORY } = process.env @@ -12,18 +12,17 @@ const resolveLogsDirectory = () => { export default resolveLogsDirectory -export const RotatingLogFileParameters = { - filename: 'application-%DATE%.log', - datePattern: 'YYYY-MM-DD', - maxSize: '20m', - maxFiles: '14d', -} - export const getCurrentLogFile = () => - path.resolve( - resolveLogsDirectory(), - RotatingLogFileParameters.filename.replace( - '%DATE%', - moment().format(RotatingLogFileParameters.datePattern), - ), - ) + new Promise((resolve, reject) => { + const dir = resolveLogsDirectory() + fs.readdir(dir, (err, files) => { + if (err) { + reject(err) + } else { + // last file is always the most up to date log. file will rotate. + const last = files[files.length - 1] + if (!last) reject(new Error('no logs')) + else resolve(path.resolve(dir, last)) + } + }) + }) diff --git a/src/logger/logger.js b/src/logger/logger.js index 755c4bf9..a26119c5 100644 --- a/src/logger/logger.js +++ b/src/logger/logger.js @@ -2,10 +2,11 @@ import winston from 'winston' import Transport from 'winston-transport' -import resolveLogsDirectory, { RotatingLogFileParameters } from 'helpers/resolveLogsDirectory' +import resolveLogsDirectory from 'helpers/resolveLogsDirectory' import anonymizer from 'helpers/anonymizer' import { + DEBUG_DEVICE, DEBUG_NETWORK, DEBUG_COMMANDS, DEBUG_DB, @@ -31,7 +32,11 @@ const pinfo = format(info => { const transports = [ new winston.transports.DailyRotateFile({ dirname: resolveLogsDirectory(), - ...RotatingLogFileParameters, + zippedArchive: true, + filename: 'application-%DATE%.log', + datePattern: 'YYYY-MM-DD', + maxSize: '20m', + maxFiles: '14d', }), ] @@ -108,6 +113,16 @@ const logLibcore = !__DEV__ || DEBUG_LIBCORE const logWS = !__DEV__ || DEBUG_WS const logNetwork = !__DEV__ || DEBUG_NETWORK const logAnalytics = !__DEV__ || DEBUG_ANALYTICS +const logApdu = !__DEV__ || DEBUG_DEVICE + +const blacklistTooVerboseCommandInput = ['libcoreSyncAccount', 'libcoreSignAndBroadcast'] +const blacklistTooVerboseCommandResponse = [ + 'libcoreSyncAccount', + 'libcoreScanAccounts', + 'listApps', + 'listAppVersions', + 'listCategories', +] export default { setProcessShortName: (processShortName: string) => { @@ -120,10 +135,19 @@ export default { if (logCmds) { switch (type) { case 'cmd.START': - logger.log('info', 'info', `CMD ${id}.send()`, { type, data }) + logger.log( + 'info', + 'info', + `CMD ${id}.send()`, + blacklistTooVerboseCommandInput.includes(id) ? { type } : { type, data }, + ) break case 'cmd.NEXT': - logger.log('info', `● CMD ${id}`, { type, data }) + logger.log( + 'info', + `● CMD ${id}`, + blacklistTooVerboseCommandResponse.includes(id) ? { type } : { type, data }, + ) break case 'cmd.COMPLETE': logger.log('info', `✔ CMD ${id} finished in ${spentTime.toFixed(0)}ms`, { type }) @@ -155,7 +179,7 @@ export default { onReduxAction: (action: Object) => { if (logRedux) { - logger.log('info', `⚛️ ${action.type}`, { type: 'action', action }) + logger.log('info', `⚛️ ${action.type}`, { type: 'action' }) } }, @@ -170,6 +194,12 @@ export default { } }, + apdu: (log: string) => { + if (logApdu) { + logger.log('info', log, { type: 'apdu' }) + } + }, + websocket: (type: string, msg: *) => { if (logWS) { logger.log('info', `~ ${type}:`, msg, { type: 'ws' }) @@ -202,9 +232,7 @@ export default { }) => { const anonymURL = anonymizer.url(url) - const log = `✔📡 HTTP ${status} ${method} ${anonymURL} – finished in ${responseTime.toFixed( - 0, - )}ms` + const log = `✔📡 HTTP ${status} ${method} ${url} – finished in ${responseTime.toFixed(0)}ms` if (logNetwork) { logger.log('info', log, { type: 'network-response' }) } @@ -229,7 +257,7 @@ export default { responseTime: number, }) => { const anonymURL = anonymizer.url(url) - const log = `✖📡 HTTP ${status} ${method} ${anonymURL} – ${error} – failed after ${responseTime.toFixed( + const log = `✖📡 HTTP ${status} ${method} ${url} – ${error} – failed after ${responseTime.toFixed( 0, )}ms` if (logNetwork) { @@ -251,9 +279,7 @@ export default { url: string, responseTime: number, }) => { - const log = `✖📡 NETWORK DOWN – ${method} ${anonymizer.url( - url, - )} – after ${responseTime.toFixed(0)}ms` + const log = `✖📡 NETWORK DOWN – ${method} ${url} – after ${responseTime.toFixed(0)}ms` if (logNetwork) { logger.log('info', log, { type: 'network-down' }) } diff --git a/yarn.lock b/yarn.lock index 7c6fa13a..83233bc9 100644 --- a/yarn.lock +++ b/yarn.lock @@ -1475,10 +1475,10 @@ resolved "https://registry.yarnpkg.com/@emotion/utils/-/utils-0.7.1.tgz#e44e596d03c9f16ba3b127ad333a8a072bcb5a0a" "@ledgerhq/hw-app-btc@^4.13.0": - version "4.17.0" - resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-btc/-/hw-app-btc-4.17.0.tgz#8f9e138446ea4b4c19c1584160f0333bbdfd48ae" + version "4.19.0" + resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-btc/-/hw-app-btc-4.19.0.tgz#0fdce47ad71df7783c6bf881e6a9bc8b4c84de52" dependencies: - "@ledgerhq/hw-transport" "^4.15.0" + "@ledgerhq/hw-transport" "^4.19.0" create-hash "^1.1.3" "@ledgerhq/hw-app-btc@^4.7.3": @@ -1489,23 +1489,23 @@ create-hash "^1.1.3" "@ledgerhq/hw-app-eth@^4.14.0": - version "4.15.0" - resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-eth/-/hw-app-eth-4.15.0.tgz#16e520793d27d6daf9edfb6f08138aad14f2ce4f" + version "4.19.0" + resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-eth/-/hw-app-eth-4.19.0.tgz#2a76556172b4e9522a9b92357a48b39e10e003a6" dependencies: - "@ledgerhq/hw-transport" "^4.15.0" + "@ledgerhq/hw-transport" "^4.19.0" "@ledgerhq/hw-app-xrp@^4.13.0": - version "4.15.0" - resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-xrp/-/hw-app-xrp-4.15.0.tgz#a6d553ad89559465d7bcce3b34d56a131722166d" + version "4.19.0" + resolved "https://registry.yarnpkg.com/@ledgerhq/hw-app-xrp/-/hw-app-xrp-4.19.0.tgz#67fc53e5ab7791f28481ed5406adcf7d92c7ca9b" dependencies: - "@ledgerhq/hw-transport" "^4.15.0" + "@ledgerhq/hw-transport" "^4.19.0" bip32-path "0.4.2" "@ledgerhq/hw-transport-node-hid@^4.13.0": - version "4.18.0" - resolved "https://registry.yarnpkg.com/@ledgerhq/hw-transport-node-hid/-/hw-transport-node-hid-4.18.0.tgz#39ab0f9300c755f6b33f28dda22e30677882b6be" + version "4.19.1" + resolved "https://registry.yarnpkg.com/@ledgerhq/hw-transport-node-hid/-/hw-transport-node-hid-4.19.1.tgz#bc2cda4db0b4e8a3e26682bf5b81011f8eb53d82" dependencies: - "@ledgerhq/hw-transport" "^4.15.0" + "@ledgerhq/hw-transport" "^4.19.0" node-hid "^0.7.2" "@ledgerhq/hw-transport-node-hid@^4.7.6": @@ -1515,9 +1515,9 @@ "@ledgerhq/hw-transport" "^4.15.0" node-hid "^0.7.2" -"@ledgerhq/hw-transport@^4.13.0", "@ledgerhq/hw-transport@^4.15.0": - version "4.15.0" - resolved "https://registry.yarnpkg.com/@ledgerhq/hw-transport/-/hw-transport-4.15.0.tgz#ec99436c2662e70fb6f9c72f7bb5d1f3a051c4e3" +"@ledgerhq/hw-transport@^4.13.0", "@ledgerhq/hw-transport@^4.15.0", "@ledgerhq/hw-transport@^4.19.0": + version "4.19.0" + resolved "https://registry.yarnpkg.com/@ledgerhq/hw-transport/-/hw-transport-4.19.0.tgz#19a804aee1bfc4abac1dc9a2a7a582e79273f991" dependencies: events "^2.0.0"