tech: Reduce amount of logs written to disk

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 { logger, LOG_BASENAME } = require('./utils/logger')
+const { defaultTransport, logger, LOG_BASENAME } = require('./utils/logger')
 const { sendToTrash } = require('./utils/fs')
 const notes = require('./utils/notes')
 const web = require('./utils/web')
@@ -428,11 +428,13 @@ class App {
     }
 
     const allFlags = await flags.all(this.config)
-    const measurePerfFlag = allFlags[flags.MEASURE_PERF_FLAG]
 
+    const measurePerfFlag = allFlags[flags.MEASURE_PERF_FLAG]
     process.env.MEASURE_PERF = process.env.MEASURE_PERF || measurePerfFlag
-
     if (measurePerfFlag) process.env.PRINT_PERF_MEASURES = '1'
+
+    const debugFlag = allFlags[flags.DEBUG_FLAG]
+    if (debugFlag) defaultTransport.level = 'trace'
   }
 
   clientInfo() /*: ClientInfo */ {

core/local/channel_watcher/add_checksum.js

@@ -67,14 +67,21 @@ function loop(
         if (isFileWithContent(event) && !event.md5sum) {
           const absPath = path.join(syncPath, event.path)
           event.md5sum = await opts.checksumer.push(absPath)
-          log.debug('computed checksum', { path: event.path, event })
+          log.trace('Checksum complete', { path: event.path, event })
         }
       } catch (err) {
         // Even if the file is no longer at the expected path, we want to
         // keep the event. Maybe it was one if its parents directory that was
         // moved, and then we can refine the event later (in incompleteFixer).
         _.set(event, ['incomplete', STEP_NAME], err.message)
-        log.debug('Cannot compute checksum', { err, event })
+        if (err.code.match(/ENOENT/)) {
+          log.debug('Checksum failed: file does not exist anymore', {
+            path: event.path,
+            event
+          })
+        } else {
+          log.error('Cannot compute checksum', { err, event, sentry: true })
+        }
       }
     }
 

core/local/channel_watcher/add_infos.js

@@ -92,7 +92,7 @@ function loop(
           }
         }
       } catch (err) {
-        log.debug('Cannot get infos', { err, event })
+        log.error('Cannot get infos', { err, event })
         _.set(event, ['incomplete', STEP_NAME], err.message)
       }
       batch.push(event)

core/local/channel_watcher/await_write_finish.js

@@ -270,7 +270,7 @@ async function awaitWriteFinish(channel /*: Channel */, out /*: Channel */) {
 function loop(channel /*: Channel */, opts /*: {} */) /*: Channel */ {
   const out = new Channel()
   awaitWriteFinish(channel, out).catch(err => {
-    log.warn({ err })
+    log.error({ err })
   })
   return out
 }

core/local/channel_watcher/dispatch.js

@@ -91,7 +91,7 @@ function step(opts /*: DispatchOptions */) {
       try {
         await dispatchEvent(event, opts)
       } catch (err) {
-        log.warn('could not dispatch local event', { err, event })
+        log.error('could not dispatch local event', { err, event })
       }
     }
 
@@ -127,7 +127,7 @@ async function dispatchEvent(
         ).last_seq
         opts.events.emit('sync-target', target)
       } catch (err) {
-        log.warn({ err })
+        log.error({ err })
         /* ignore err */
       }
     } finally {
@@ -156,25 +156,25 @@ actions = {
     actions.createddirectory(event, opts, 'Dir found'),
 
   createdfile: async (event, { prep }, description = 'File added') => {
-    log.info(description, { event })
+    log.debug(description, { event })
     const doc = buildFile(event.path, event.stats, event.md5sum)
     await prep.addFileAsync(SIDE, doc)
   },
 
   createddirectory: async (event, { prep }, description = 'Dir added') => {
-    log.info(description, { event })
+    log.debug(description, { event })
     const doc = buildDir(event.path, event.stats)
     await prep.putFolderAsync(SIDE, doc)
   },
 
   modifiedfile: async (event, { prep }) => {
-    log.info('File modified', { event })
+    log.debug('File modified', { event })
     const doc = buildFile(event.path, event.stats, event.md5sum)
     await prep.updateFileAsync(SIDE, doc)
   },
 
   modifieddirectory: async (event, { prep }) => {
-    log.info('Dir modified', { event })
+    log.debug('Dir modified', { event })
     const doc = buildDir(event.path, event.stats)
     await prep.putFolderAsync(SIDE, doc)
   },
@@ -200,7 +200,7 @@ actions = {
       log.warn('File move source has been replaced in Pouch', { event })
       return
     }
-    log.info('File moved', { event })
+    log.debug('File moved', { event })
 
     const doc = buildFile(event.path, event.stats, event.md5sum)
     if (event.overwrite) {
@@ -236,7 +236,7 @@ actions = {
       log.warn('Dir move source has been replaced in Pouch', { event })
       return
     }
-    log.info('Dir moved', { event })
+    log.debug('Dir moved', { event })
 
     const doc = buildDir(event.path, event.stats)
     if (event.overwrite) {
@@ -255,7 +255,7 @@ actions = {
       // => we can ignore safely this event
       return
     }
-    log.info('File removed', { event })
+    log.debug('File removed', { event })
     await prep.trashFileAsync(SIDE, was)
   },
 
@@ -267,7 +267,7 @@ actions = {
       // => we can ignore safely this event
       return
     }
-    log.info('Dir removed', { event })
+    log.debug('Dir removed', { event })
     await prep.trashFolderAsync(SIDE, was)
   }
 }

core/local/channel_watcher/incomplete_fixer.js

@@ -310,7 +310,7 @@ function step(
             state.incompletes.splice(i, 1)
           }
         } catch (err) {
-          log.warn('Error while rebuilding incomplete event', {
+          log.error('Error while rebuilding incomplete event', {
             err,
             event,
             item

core/local/channel_watcher/index.js

@@ -156,7 +156,7 @@ class ChannelWatcher {
   }
 
   async start() {
-    log.debug('starting...')
+    log.info('Starting watcher...')
 
     await stepsInitialState(this.state, this)
     const scanDone = new Promise(resolve => {
@@ -167,7 +167,7 @@ class ChannelWatcher {
   }
 
   async stop() /*: Promise<*> */ {
-    log.debug('stopping...')
+    log.info('Stopping watcher...')
 
     await this.producer.stop()
   }
@@ -177,7 +177,7 @@ class ChannelWatcher {
   }
 
   fatal(err /*: Error */) /*: void */ {
-    log.error(`Local watcher fatal: ${err.message}`, { err, sentry: true })
+    log.fatal(`Local watcher fatal: ${err.message}`, { err, sentry: true })
     this.events.emit(LOCAL_WATCHER_FATAL_EVENT, err)
     this.events.removeAllListeners(LOCAL_WATCHER_FATAL_EVENT)
     this.stop()

core/local/channel_watcher/initial_diff.js

@@ -75,7 +75,7 @@ function loop(
 ) /*: Channel */ {
   const out = new Channel()
   initialDiff(channel, out, opts).catch(err => {
-    log.warn({ err })
+    log.error({ err })
   })
   return out
 }

core/local/channel_watcher/overwrite.js

@@ -179,7 +179,7 @@ const loop = (channel /*: Channel */, opts /*: OverwriteOptions */) => {
   const out = new Channel()
 
   _loop(channel, out, opts).catch(err => {
-    log.warn({ err })
+    log.error({ err })
   })
 
   return out

core/local/channel_watcher/parcel_producer.js

@@ -99,6 +99,8 @@ class Producer {
    *   events for its content in that case).
    */
   async start() {
+    log.info('Starting producer...')
+
     this.watcher = await parcel.subscribe(
       this.config.syncPath,
       async (err, events) => {
@@ -115,7 +117,7 @@ class Producer {
 
     this.channel.push([INITIAL_SCAN_DONE])
     this.initialScanDone = true
-    log.trace('Scan done')
+    log.info('Folder scan done')
 
     this.events.emit('buffering-end')
   }
@@ -186,7 +188,8 @@ class Producer {
   }
 
   async stop() {
-    log.trace('Stop')
+    log.info('Stopping producer...')
+
     if (this.watcher) {
       await this.watcher.unsubscribe()
       // XXX: unsubscribe() resolves before it was actually finished

core/local/channel_watcher/scan_folder.js

@@ -40,7 +40,7 @@ function loop(
       }
       if (event.action === 'created' && event.kind === 'directory') {
         opts.scan(event.path).catch(err => {
-          log.warn('Error on folder scan', { err, event })
+          log.error('Error on folder scan', { err, event })
         })
       }
     }

core/local/channel_watcher/win_identical_renaming.js

@@ -178,7 +178,7 @@ const loop = (
   const out = new Channel()
 
   _loop(channel, out, opts).catch(err => {
-    log.warn({ err })
+    log.error({ err })
   })
 
   return out

core/local/chokidar/analysis.js

@@ -146,7 +146,7 @@ function analyseEvents(
   const changesFound = new LocalChangeMap()
 
   if (pendingChanges.length > 0) {
-    log.warn(`Prepend ${pendingChanges.length} pending change(s)`, {
+    log.debug(`Prepend ${pendingChanges.length} pending change(s)`, {
       changes: pendingChanges
     })
     for (const a of pendingChanges) {

core/local/chokidar/normalize_paths.js

@@ -45,7 +45,7 @@ const step = async (
         normalizedPaths.push(normalized)
 
         if (c.path !== normalized) {
-          log.info(
+          log.debug(
             'normalizing local path to match existing doc and parent norms',
             { path: c.path, normalized }
           )

core/local/chokidar/send_to_prep.js

@@ -45,7 +45,7 @@ const onAddFile = (
   prep /*: Prep */
 ) => {
   const doc = metadata.buildFile(filePath, stats, md5sum)
-  log.info('FileAddition', { path: filePath })
+  log.debug('FileAddition', { path: filePath })
   return prep.addFileAsync(SIDE, doc)
 }
 
@@ -55,7 +55,7 @@ const onMoveFile = async (
 ) => {
   const doc = metadata.buildFile(filePath, stats, md5sum, old.remote)
   if (overwrite) doc.overwrite = overwrite
-  log.info('FileMove', { path: filePath, oldpath: old.path })
+  log.debug('FileMove', { path: filePath, oldpath: old.path })
   return prep.moveFileAsync(SIDE, doc, old)
 }
 
@@ -66,7 +66,7 @@ const onMoveFolder = (
   const doc = metadata.buildDir(folderPath, stats, old.remote)
   // $FlowFixMe we set doc.overwrite to true, it will be replaced by metadata in merge
   if (overwrite) doc.overwrite = overwrite
-  log.info('DirMove', { path: folderPath, oldpath: old.path })
+  log.debug('DirMove', { path: folderPath, oldpath: old.path })
   return prep.moveFolderAsync(SIDE, doc, old)
 }
 
@@ -76,7 +76,7 @@ const onAddDir = (
   prep /*: Prep */
 ) => {
   const doc = metadata.buildDir(folderPath, stats)
-  log.info('DirAddition', { path: folderPath })
+  log.debug('DirAddition', { path: folderPath })
   return prep.putFolderAsync(SIDE, doc)
 }
 
@@ -89,7 +89,7 @@ const onUnlinkFile = (
   { path: filePath, old } /*: LocalFileDeletion */,
   prep /*: Prep */
 ) => {
-  log.info('FileDeletion', { path: filePath })
+  log.debug('FileDeletion', { path: filePath })
   if (!old) {
     log.debug('Assuming file already removed', { path: filePath })
     return
@@ -106,7 +106,7 @@ const onUnlinkDir = (
   { path: folderPath, old } /*: LocalDirDeletion */,
   prep /*: Prep */
 ) => {
-  log.info('DirDeletion', { path: folderPath })
+  log.debug('DirDeletion', { path: folderPath })
   if (!old) {
     log.debug('Assuming dir already removed', { path: folderPath })
     return
@@ -123,7 +123,7 @@ const onChange = (
   } /*: LocalFileUpdate|LocalFileAdded|LocalFileUpdated */,
   prep /*: Prep */
 ) => {
-  log.info('FileUpdate', { path: filePath })
+  log.debug('FileUpdate', { path: filePath })
   const doc = metadata.buildFile(filePath, stats, md5sum)
   return prep.updateFileAsync(SIDE, doc)
 }

core/local/chokidar/watcher.js

@@ -124,7 +124,7 @@ class LocalWatcher {
    * @see https://github.com/paulmillr/chokidar
    */
   start() {
-    log.debug('Starting...')
+    log.info('Starting watcher...')
 
     this.resetInitialScanParams()
 
@@ -175,7 +175,7 @@ class LocalWatcher {
             log.chokidar.debug(eventType, { path, stats, isInitialScan })
             const newEvent = chokidarEvent.build(eventType, path, stats)
             if (newEvent.type !== eventType) {
-              log.info('fixed wrong fsevents event type', {
+              log.debug('fixed wrong fsevents event type', {
                 eventType,
                 event: newEvent
               })
@@ -189,10 +189,11 @@ class LocalWatcher {
       this.watcher
         .on('ready', () => {
           stopChokidarScanMeasure()
+          log.info('Folder scan done')
           this.buffer.switchMode('timeout')
         })
         .on('raw', async (event, path, details) => {
-          log.chokidar.debug('raw', { event, path, details })
+          log.chokidar.trace('raw', { event, path, details })
 
           if (isRescanFlag(details.flags)) {
             try {
@@ -225,7 +226,7 @@ class LocalWatcher {
   // TODO: Start checksuming as soon as an add/change event is buffered
   // TODO: Put flushed event batches in a queue
   async onFlush(rawEvents /*: ChokidarEvent[] */) {
-    log.debug(`Flushed ${rawEvents.length} events`)
+    log.info(`Flushed ${rawEvents.length} events`)
 
     this.events.emit('buffering-end')
     syncDir.ensureExistsSync(this)
@@ -283,7 +284,7 @@ class LocalWatcher {
   }
 
   async stop(force /*: ?bool */ = false) {
-    log.debug('Stopping watcher...')
+    log.info('Stopping watcher...')
 
     if (!this.watcher) return
 
@@ -345,7 +346,7 @@ class LocalWatcher {
   }
 
   fatal(err /*: Error */) /*: void */ {
-    log.error(`Local watcher fatal: ${err.message}`, { err, sentry: true })
+    log.fatal(`Local watcher fatal: ${err.message}`, { err, sentry: true })
     this.events.emit(LOCAL_WATCHER_FATAL_EVENT, err)
     this.events.removeAllListeners(LOCAL_WATCHER_FATAL_EVENT)
     this.stop()

core/local/index.js

@@ -504,7 +504,7 @@ class Local /*:: implements Reader, Writer */ {
   ) /*: Promise<T> */ {
     const conflict = metadata.createConflictingDoc(newMetadata)
 
-    log.warn('Resolving local conflict', {
+    log.info('Resolving local conflict', {
       path: conflict.path,
       oldpath: newMetadata.path
     })