fix: Manage logging level on logger itself (#2358)

In order to improve performance, we reduced the amount of logs written
to disk by setting the maximum level logged to `info` by default.

However, we left the level of the logger itself to `trace` so we could
increase the amount of logs written to disk via a flag and it turns
out we would not see the expected performance improvements because of
this.

By managing the logging level on the logger itself we make sure
`winston` won't process `debug` and `trace` logging calls unless we've
enabled the debug flag or set the `DEBUG` env variable.

core/app.js

@@ -27,7 +27,7 @@ const { Remote } = require('./remote')
 const { Sync } = require('./sync')
 const SyncState = require('./syncstate')
 const Registration = require('./remote/registration')
-const { defaultTransport, logger, LOG_BASENAME } = require('./utils/logger')
+const { baseLogger, logger, LOG_BASENAME } = require('./utils/logger')
 const { sendToTrash } = require('./utils/fs')
 const notes = require('./utils/notes')
 const web = require('./utils/web')
@@ -431,10 +431,16 @@ class App {
 
     const measurePerfFlag = allFlags[flags.MEASURE_PERF_FLAG]
     process.env.MEASURE_PERF = process.env.MEASURE_PERF || measurePerfFlag
-    if (measurePerfFlag) process.env.PRINT_PERF_MEASURES = '1'
+    if (measurePerfFlag) {
+      log.info('perf measures enabled')
+      process.env.PRINT_PERF_MEASURES = '1'
+    }
 
     const debugFlag = allFlags[flags.DEBUG_FLAG]
-    if (debugFlag) defaultTransport.level = 'trace'
+    if (debugFlag) {
+      log.info('debug enabled')
+      baseLogger.level = 'trace'
+    }
   }
 
   clientInfo() /*: ClientInfo */ {

core/utils/logger.js

@@ -138,7 +138,6 @@ const defaultFormatter = combine(
 )
 
 const defaultTransport = new DailyRotateFile({
-  level: process.env.DEBUG ? 'trace' : 'info',
   dirname: LOG_DIR,
   filename: LOG_BASENAME,
   datePattern: 'YYYY-MM-DD', // XXX: rotate every day
@@ -147,7 +146,7 @@ const defaultTransport = new DailyRotateFile({
   format: combine(defaultFormatter, json())
 })
 
-const defaultLogger = winston.createLogger({
+const baseLogger = winston.createLogger({
   levels: {
     fatal: 0,
     error: 1,
@@ -156,10 +155,10 @@ const defaultLogger = winston.createLogger({
     debug: 4,
     trace: 5
   },
-  level: 'trace',
+  level: process.env.DEBUG ? 'trace' : 'info',
   transports: [defaultTransport]
 })
-defaultLogger.on('error', err => {
+baseLogger.on('error', err => {
   // eslint-disable-next-line no-console
   console.log('failed to log', { err })
 })
@@ -169,7 +168,7 @@ if (process.env.DEBUG) {
   // XXX: Clear log file from previous logs to simplify analysis
   fse.outputFileSync(filename, '')
 
-  defaultLogger.add(
+  baseLogger.add(
     new winston.transports.File({
       filename,
       format: combine(defaultFormatter, json())
@@ -178,7 +177,7 @@ if (process.env.DEBUG) {
 }
 
 if (process.env.TESTDEBUG) {
-  defaultLogger.add(
+  baseLogger.add(
     new winston.transports.Console({
       handleExceptions: true,
       format: combine(
@@ -203,7 +202,7 @@ if (process.env.TESTDEBUG) {
 }
 
 function logger(options) {
-  return defaultLogger.child(options)
+  return baseLogger.child(options)
 }
 
 module.exports = {
@@ -216,7 +215,7 @@ module.exports = {
   LOG_DIR,
   LOG_BASENAME,
   defaultFormatter,
-  defaultLogger,
+  baseLogger,
   defaultTransport,
   dropTimestamp,
   logger,

core/utils/sentry.js

@@ -33,7 +33,7 @@ const {
   INFO_LVL,
   DEBUG_LVL,
   defaultFormatter,
-  defaultLogger,
+  baseLogger,
   logger
 } = require('./logger')
 
@@ -140,7 +140,7 @@ function setup(clientInfos /*: ClientInfo */) {
       scope.setTag('instance', instance)
       scope.setTag('server_name', clientInfos.deviceName)
     })
-    defaultLogger.add(
+    baseLogger.add(
       new SentryTransport({
         format: combine(defaultFormatter, json())
       })

test/property/local_watcher/index.js

@@ -8,9 +8,10 @@ const fse = require('fs-extra')
 const glob = require('glob')
 const path = require('path')
 const Promise = require('bluebird')
+const winston = require('winston')
 
 const { id } = require('../../../core/metadata')
-const { defaultLogger } = require('../../../core/utils/logger')
+const { baseLogger } = require('../../../core/utils/logger')
 
 const { ContextDir } = require('../../support/helpers/context_dir')
 const TmpDir = require('../../support/helpers/TmpDir')
@@ -32,12 +33,13 @@ describe('Local watcher', function () {
 
       let state /*: Object */ = { name: scenario, conflicts: [] }
       state.dir = new ContextDir(await TmpDir.emptyForTestFile(scenario))
-      defaultLogger.streams.length = 0
-      defaultLogger.addStream({
-        type: 'file',
-        path: state.dir.root + '.log',
-        level: 'debug'
-      })
+      baseLogger.clear()
+      baseLogger.add(
+        new winston.transports.File({
+          filename: state.dir.root + '.log',
+          level: 'debug'
+        })
+      )
       await run(state, ops)
 
       // Wait that the dust settles

test/support/hooks/logging.js

@@ -2,13 +2,13 @@
 /* @flow */
 const winston = require('winston')
 
-const { defaultLogger, logger } = require('../../../core/utils/logger')
+const { baseLogger, logger } = require('../../../core/utils/logger')
 
 const log = logger({ component: 'mocha' })
 
 const errors = []
 
-defaultLogger.add(
+baseLogger.add(
   new winston.Transport({
     level: 'error',
     log: ({ err, message }, callback) => {