diff --git a/README.md b/README.md index ffc2dcf8..bf637f17 100644 --- a/README.md +++ b/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: diff --git a/lib/binding.js b/lib/binding.js index 54793ed5..fc0154bb 100644 --- a/lib/binding.js +++ b/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 diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 00000000..7bca0037 --- /dev/null +++ b/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) } +} diff --git a/lib/native-watcher-registry.js b/lib/native-watcher-registry.js index 11787000..563d82f1 100644 --- a/lib/native-watcher-registry.js +++ b/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 diff --git a/lib/native-watcher.js b/lib/native-watcher.js index 067229a3..ecc700c2 100644 --- a/lib/native-watcher.js +++ b/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,6 +38,8 @@ 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. @@ -44,14 +47,17 @@ class NativeWatcher { // 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,15 +157,18 @@ 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 } @@ -165,6 +176,7 @@ class NativeWatcher { 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') } diff --git a/lib/path-watcher.js b/lib/path-watcher.js index 7b1be43d..eae5a1dc 100644 --- a/lib/path-watcher.js +++ b/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,11 +190,15 @@ 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() })) } @@ -196,6 +206,7 @@ class PathWatcher { // 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. diff --git a/lib/registry/tree.js b/lib/registry/tree.js index ffdcd545..aa1dea21 100644 --- a/lib/registry/tree.js +++ b/lib/registry/tree.js @@ -3,6 +3,7 @@ const { absolute } = require('./helper') const { DirectoryNode } = require('./directory-node') const { RecursiveWatcherNode } = require('./recursive-watcher-node') const { NonrecursiveWatcherNode } = require('./nonrecursive-watcher-node') +const { log } = require('../logger') // Private: Map userland filesystem watcher subscriptions efficiently to deliver filesystem change notifications to // each watcher with the most efficient coverage of native watchers. @@ -37,6 +38,7 @@ class Tree { add (pathSegments, options, attachToNative) { const absolutePathSegments = this.basePathSegments.concat(pathSegments) const absolutePath = absolute(...absolutePathSegments) + log('Tree: adding %j with options %j. absolute = %s.', pathSegments, options, absolutePath) const attachToNew = (children, immediate) => { const native = this.createNative(absolutePath, options) @@ -57,15 +59,21 @@ class Tree { this.root.lookup(pathSegments).when({ parent: (parent, remaining) => { + log('Tree: discovered parent node with remaining segments %j.', remaining) + // An existing NativeWatcher is watching the same directory or a parent directory of the requested path. const existingNative = parent.getNativeWatcher() const absoluteParentPath = absolute(...parent.getAbsolutePathSegments()) if (parent.isCompatible(options)) { + log('Tree: adding child path and attaching to existing native %s.', existingNative) + // Attach this Watcher to it as a filtering watcher and record it as a dependent child path. parent.addChildPath(remaining, options) attachToNative(existingNative, absoluteParentPath, parent.getOptions()) } else { + log('Tree: broadening existing native watcher %s.', existingNative) + // Construct and attach a new {NativeWatcher} that will deliver events suitable for both the old and // new watchers. Reattach consumers of the existing {NativeWatcher} and stop it. const newNative = attachToNew([], {}) @@ -74,11 +82,14 @@ class Tree { } }, children: (children, immediate) => { + log('Tree: discovered watched children %j.', children) + // One or more NativeWatchers exist on child directories of the requested path. Create a new native watcher // on the parent directory. const newNative = attachToNew(children, immediate) if (options.recursive) { + log('Tree: adopting %d existing children.', children.length) // Create a new native watcher on the parent directory, note the subscribed child paths, and cleanly stop the // child native watchers. @@ -90,7 +101,10 @@ class Tree { } } }, - missing: () => attachToNew([], {}) + missing: () => { + log('Tree: creating and attaching new native watcher.') + attachToNew([], {}) + } }) }