JavaScript-level logging

README.md

@@ -66,6 +66,7 @@ Tweak package-global settings. This method may be called even after watchers hav
 const watcher = require('@atom/watcher')
 
 await watcher.configure({
+  jsLog: watcher.STDOUT,
   mainLog: watcher.STDERR,
   workerLog: 'worker.log',
   pollingLog: 'polling.log',
@@ -75,15 +76,17 @@ await watcher.configure({
 })
 ```
 
-`mainLog` configures the logging of events from the main thread, in line with libuv's event loop. It may be one of:
+`jsLog` configures the logging of events from the JavaScript layer. It may be one of:
 
 * A `String` specifying a path to log to a file. Be careful that you don't log to a directory that you're watching :innocent:
 * The constants `watcher.STDERR` or `watcher.STDOUT` to log to the `node` process' standard error or output streams.
 * `watcher.DISABLE` to disable main thread logging. This is the default.
 
-`workerLog` configures logging for the worker thread, which is used to interact with native operating system filesystem watching APIs. It accepts the same arguments as `mainLog` and also defaults to `watcher.DISABLE`.
+`mainLog` configures the logging of events from the main thread, in line with libuv's event loop. It accepts the same arguments as `jsLog` and also defaults to `watcher.DISABLE`.
 
-`pollingLog` configures logging for the polling thread, which polls the filesystem when the worker thread is unable to. The polling thread only launches when at least one path needs to be polled. `pollingLog` accepts the same arguments as `mainLog` and also defaults to `watcher.DISABLE`.
+`workerLog` configures logging for the worker thread, which is used to interact with native operating system filesystem watching APIs. It accepts the same arguments as `jsLog` and also defaults to `watcher.DISABLE`.
+
+`pollingLog` configures logging for the polling thread, which polls the filesystem when the worker thread is unable to. The polling thread only launches when at least one path needs to be polled. `pollingLog` accepts the same arguments as `jsLog` and also defaults to `watcher.DISABLE`.
 
 `workerCacheSize` controls the number of recently seen stat results are cached within the worker thread. Increasing the cache size will improve the reliability of rename correlation and the entry kinds of deleted entries, but will consume more RAM. The default is `4096`.
 
@@ -153,6 +156,15 @@ const watcher = await watchPath('/var/log', {}, () => {})
 watcher.dispose()
 ```
 
+### Environment variables
+
+Logging may also be configured by setting environment variables. Each of these may be set to an empty string to disable that log, `"stderr"` to output to stderr, `"stdout"` to output to stdout, or a path to write output to a file at that path.
+
+* `WATCHER_LOG_JS`: JavaScript layer logging
+* `WATCHER_LOG_MAIN`: Main thread logging
+* `WATCHER_LOG_WORKER`: Worker thread logging
+* `WATCHER_LOG_POLLING`: Polling thread logging
+
 ## CLI
 
 It's possible to call `@atom/watcher` from the command-line, like this:

lib/binding.js

@@ -1,5 +1,6 @@
-let watcher = null
+const logger = require('./logger')
 
+let watcher = null
 function getWatcher () {
   if (!watcher) {
     try {
@@ -44,6 +45,32 @@ function logOption (baseName, options, normalized) {
   throw new Error(`option ${baseName} must be DISABLE, STDERR, STDOUT, or a filename`)
 }
 
+function jsLogOption (value) {
+  if (value === undefined) return
+
+  if (value === DISABLE) {
+    logger.disable()
+    return
+  }
+
+  if (value === STDERR) {
+    logger.toStderr()
+    return
+  }
+
+  if (value === STDOUT) {
+    logger.toStdout()
+    return
+  }
+
+  if (typeof value === 'string' || value instanceof String) {
+    logger.toFile(value)
+    return
+  }
+
+  throw new Error('option jsLog must be DISABLE, STDERR, STDOUT, or a filename')
+}
+
 function configure (options) {
   if (!options) {
     return Promise.reject(new Error('configure() requires an option object'))
@@ -54,6 +81,7 @@ function configure (options) {
   logOption('mainLog', options, normalized)
   logOption('workerLog', options, normalized)
   logOption('pollingLog', options, normalized)
+  jsLogOption(options.jsLog)
 
   if (options.workerCacheSize) normalized.workerCacheSize = options.workerCacheSize
   if (options.pollingThrottle) normalized.pollingThrottle = options.pollingThrottle

lib/logger.js

@@ -0,0 +1,63 @@
+const util = require('util')
+const fs = require('fs')
+
+class StreamLogger {
+  constructor (stream) {
+    this.stream = stream
+  }
+
+  log (...args) {
+    this.stream.write(util.format(...args) + '\n')
+  }
+}
+
+const nullLogger = {
+  log () {}
+}
+
+let activeLogger = null
+
+function disable () {
+  activeLogger = nullLogger
+}
+
+function toStdout () {
+  activeLogger = new StreamLogger(process.stdout)
+}
+
+function toStderr () {
+  activeLogger = new StreamLogger(process.stderr)
+}
+
+function toFile (filePath) {
+  const stream = fs.createWriteStream(filePath, { defaultEncoding: 'utf8', flags: 'a' })
+  activeLogger = new StreamLogger(stream)
+}
+
+function fromEnv (value) {
+  if (!value) {
+    return disable()
+  } else if (value === 'stdout') {
+    return toStdout()
+  } else if (value === 'stderr') {
+    return toStderr()
+  } else {
+    return toFile(value)
+  }
+}
+
+function getActiveLogger () {
+  if (activeLogger === null) {
+    fromEnv(process.env.WATCHER_LOG_JS)
+  }
+  return activeLogger
+}
+
+module.exports = {
+  disable,
+  toStdout,
+  toStderr,
+  toFile,
+  fromEnv,
+  log (...args) { return getActiveLogger().log(...args) }
+}

lib/native-watcher-registry.js

@@ -1,4 +1,5 @@
 const path = require('path')
+const { log } = require('./logger')
 const { Tree } = require('./registry/tree')
 
 // Private: Track the directories being monitored by native filesystem watchers. Minimize the number of native watchers
@@ -28,12 +29,15 @@ class NativeWatcherRegistry {
   //
   // * `watcher` an unattached {PathWatcher}.
   async attach (watcher) {
+    log('attaching watcher %s to native registry.', watcher)
     const normalizedDirectory = await watcher.getNormalizedPathPromise()
     const pathSegments = normalizedDirectory.split(path.sep).filter(segment => segment.length > 0)
 
+    log('adding watcher %s to tree.', watcher)
     this.tree.add(pathSegments, watcher.getOptions(), (native, nativePath, options) => {
       watcher.attachToNative(native, nativePath, options)
     })
+    log('watcher %s added. tree state:\n%s', watcher, this.print())
   }
 
   // Private: Generate a visual representation of the currently active watchers managed by this

lib/native-watcher.js

@@ -1,5 +1,6 @@
 const binding = require('./binding')
 const { Emitter, CompositeDisposable, Disposable } = require('event-kit')
+const { log } = require('./logger')
 
 const ACTIONS = new Map([
   [0, 'created'],
@@ -37,21 +38,26 @@ class NativeWatcher {
 
     this.onEvents = this.onEvents.bind(this)
     this.onError = this.onError.bind(this)
+
+    log('create NativeWatcher %s with options %j.', this, this.options)
   }
 
   // Private: Begin watching for filesystem events.
   //
   // Has no effect if the watcher has already been started.
   async start () {
     if (this.state === STARTING) {
+      log('NativeWatcher %s is already starting.', this)
       await new Promise(resolve => this.emitter.once('did-start', resolve))
       return
     }
 
     if (this.state === RUNNING || this.state === STOPPING) {
+      log('NativeWatcher %s is running or stopping.', this)
       return
     }
 
+    log('Starting NativeWatcher %s.', this)
     this.state = STARTING
 
     this.channel = await new Promise((resolve, reject) => {
@@ -64,6 +70,7 @@ class NativeWatcher {
         resolve(channel)
       }, this.onEvents)
     })
+    log('NativeWatcher %s assigned channel %d.', this, this.channel)
 
     this.state = RUNNING
     this.emitter.emit('did-start')
@@ -98,6 +105,7 @@ class NativeWatcher {
     return new Disposable(() => {
       sub.dispose()
       if (this.emitter.listenerCountForEventName('did-change') === 0) {
+        log('Last subscriber disposed on NativeWatcher %s.', this)
         this.stop()
       }
     })
@@ -149,22 +157,26 @@ class NativeWatcher {
   // Has no effect if the watcher is not running.
   async stop (split = true) {
     if (this.state === STOPPING) {
+      log('NativeWatcher %s is already stopping.', this)
       await new Promise(resolve => this.emitter.once('did-stop', resolve))
       return
     }
 
     if (this.state === STARTING) {
+      log('NativeWatcher %s is still starting.', this)
       await new Promise(resolve => this.emitter.once('did-start', resolve))
     }
 
     if (this.state === STOPPED) {
+      log('NativeWatcher %s has already stopped.', this)
       return
     }
 
     if (!this.channel) {
       throw new Error('Cannot stop a watcher with no channel')
     }
 
+    log('Stopping NativeWatcher %s with split %s.', this, split)
     this.state = STOPPING
     this.emitter.emit('will-stop', split)
 
@@ -173,6 +185,7 @@ class NativeWatcher {
     })
     this.channel = null
     this.state = STOPPED
+    log('NativeWatcher %s has been stopped.', this)
 
     this.emitter.emit('did-stop')
   }

lib/path-watcher.js

@@ -2,6 +2,7 @@ const fs = require('fs-extra')
 const path = require('path')
 
 const { Emitter, CompositeDisposable, Disposable } = require('event-kit')
+const { log } = require('./logger')
 
 // Extended: Manage a subscription to filesystem events that occur beneath a root directory. Construct these by
 // calling `watchPath`.
@@ -60,6 +61,7 @@ class PathWatcher {
     this.nativeWatcherRegistry = nativeWatcherRegistry
     this.watchedPath = watchedPath
     this.options = Object.assign({ recursive: true, include: () => true }, options)
+    log('create PathWatcher at %s with options %j.', watchedPath, options)
 
     this.normalizedPath = null
     this.native = null
@@ -81,6 +83,7 @@ class PathWatcher {
       fs.realpath(watchedPath),
       fs.stat(watchedPath)
     ]).then(([real, stat]) => {
+      log('normalized and stat path %s to %s.', watchedPath, real)
       if (stat.isDirectory()) {
         this.normalizedPath = real
       } else {
@@ -157,8 +160,10 @@ class PathWatcher {
 
       this.native.start()
     } else {
+      log('attaching watcher %s to registry because a change listener has been attached.', this)
       // Attach to a new native listener and retry
       this.nativeWatcherRegistry.attach(this).then(() => {
+        log('watcher %s attached successfully.', this)
         this.onDidChange(callback)
       }, err => this.rejectAttachedPromise(err))
     }
@@ -167,6 +172,7 @@ class PathWatcher {
       const sub = this.changeCallbacks.get(callback)
       this.changeCallbacks.delete(callback)
       sub.dispose()
+      log('disposed subscription from watcher %s.', this)
     })
   }
 
@@ -184,18 +190,23 @@ class PathWatcher {
   attachToNative (native) {
     this.subs.dispose()
     this.native = native
+    log('attaching watcher %s to native %s.', this, native)
 
     if (native.isRunning()) {
+      log('native %s is already running.', native)
       this.resolveStartPromise()
     } else {
+      log('waiting for native %s to start.', native)
       this.subs.add(native.onDidStart(() => {
+        log('native %s has started.')
         this.resolveStartPromise()
       }))
     }
 
     // Transfer any native event subscriptions to the new NativeWatcher once it starts.
     this.getStartPromise().then(() => {
       if (this.native === native) {
+        log('transferring %d existing event subscriptions to new native %s.', this.changeCallbacks.size, native)
         for (const [callback, formerSub] of this.changeCallbacks) {
           const newSub = native.onDidChange(events => this.onNativeEvents(events, callback))
           this.changeCallbacks.set(callback, newSub)
@@ -213,17 +224,21 @@ class PathWatcher {
       if (replacement === native) return
       if (!this.normalizedPath.startsWith(watchedPath)) return
       if (!options.recursive && this.normalizedPath !== watchedPath) return
+      log('received detachment request from native %s. replacement is at path %s with options %j.',
+        native, watchedPath, options)
 
       this.attachToNative(replacement)
     }))
 
     this.subs.add(native.onWillStop(() => {
       if (this.native === native) {
+        log('native %s is stopping.', native)
         this.subs.dispose()
         this.native = null
       }
     }))
 
+    log('watcher %s attached successfully to native %s.', this, native)
     this.resolveAttachedPromise()
   }
 
@@ -289,6 +304,7 @@ class PathWatcher {
 
     this.emitter.dispose()
     this.subs.dispose()
+    log('watcher %s disposed.', this)
   }
 
   // Extended: Print the directory that this watcher is watching.