From 5caea0cf045e29522c6eddd00fd0f124af6ae28f Mon Sep 17 00:00:00 2001 From: Jeff Wear Date: Thu, 19 Sep 2019 16:58:46 -0700 Subject: [PATCH] Fix logfile tailing under Node 10.16.0 `fs.watch` does not consistently emit `'change'` events on Node 10.16.0, possibly due to https://github.com/nodejs/node/issues/29460. `fs.watchFile` still works, but is less efficient, per the docs, so fall back to that only if necessary and also suggest that users run custody under an older version of Node. I explored several Node file-watching libraries (e.g. chokidar, sane) to try to find a more performant solution for Node 10.16.0 and it seems that they pretty much all fall back to `fs.watch` / `fs.watchFile`, unfortunately. sane offers the option to use watchman, but that requires installing a daemon so is a non-starter. Fixes https://github.com/mixmaxhq/custody/issues/82. https://github.com/mixmaxhq/custody/issues/83 tracks reverting this when the underlying Node issue has been fixed. Tested that log files update both when running custody under v8.9.3 and v10.16.0, and that `node-tail` only uses `fs.watchFile` in the latter. --- README.md | 5 +++++ package-lock.json | 33 +++++++++++++++++++++++++++++---- package.json | 1 + src/components/FileLog.jsx | 25 ++++++++++++++++++++++++- 4 files changed, 59 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index c54f99b..129bdb1 100644 --- a/README.md +++ b/README.md @@ -31,6 +31,11 @@ to set it. ## Usage +> Node 10.16.0 shipped [a regression](https://github.com/mixmaxhq/custody/issues/82#issuecomment-533348756) +in file watching that may degrade performance when custody is tailing log files. If you experience +high CPU utilization while using custody, please try running custody under an older version of Node +e.g. using [`nvm`](https://github.com/nvm-sh/nvm). + Make sure that Supervisor is running. Then run ```sh diff --git a/package-lock.json b/package-lock.json index acf021a..32f28d2 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,6 +9,7 @@ "resolved": "https://registry.npmjs.org/@babel/code-frame/-/code-frame-7.0.0-beta.44.tgz", "integrity": "sha512-cuAuTTIQ9RqcFRJ/Y8PvTh+paepNcaGxwQwjIDRWPXmzzyAeCO4KqS9ikMvq0MCbRk6GlYKwfzStrcP3/jSL8g==", "dev": true, + "optional": true, "requires": { "@babel/highlight": "7.0.0-beta.44" } @@ -73,6 +74,7 @@ "resolved": "https://registry.npmjs.org/@babel/highlight/-/highlight-7.0.0-beta.44.tgz", "integrity": "sha512-Il19yJvy7vMFm8AVAh6OZzaFoAd0hbkeMZiX3P5HGD+z7dyI7RzndHB0dg6Urh/VAFfHtpOIzDUSxmY6coyZWQ==", "dev": true, + "optional": true, "requires": { "chalk": "^2.0.0", "esutils": "^2.0.2", @@ -166,6 +168,7 @@ "resolved": "https://registry.npmjs.org/@babel/types/-/types-7.0.0-beta.44.tgz", "integrity": "sha512-5eTV4WRmqbaFM3v9gHAIljEQJU4Ssc6fxL61JN+Oe2ga/BwyjzjamwkCVVAQjHGuAX8i0BWo42dshL8eO5KfLQ==", "dev": true, + "optional": true, "requires": { "esutils": "^2.0.2", "lodash": "^4.2.0", @@ -176,7 +179,8 @@ "version": "2.0.0", "resolved": "https://registry.npmjs.org/to-fast-properties/-/to-fast-properties-2.0.0.tgz", "integrity": "sha1-3F5pjL0HkmW8c+A3doGk5Og/YW4=", - "dev": true + "dev": true, + "optional": true } } }, @@ -955,6 +959,14 @@ "browserslist": "^2.1.2", "invariant": "^2.2.2", "semver": "^5.3.0" + }, + "dependencies": { + "semver": { + "version": "5.7.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.1.tgz", + "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==", + "dev": true + } } }, "babel-register": { @@ -1471,6 +1483,12 @@ "minimist": "0.0.8" } }, + "semver": { + "version": "5.7.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.1.tgz", + "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==", + "dev": true + }, "strip-ansi": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/strip-ansi/-/strip-ansi-4.0.0.tgz", @@ -2218,6 +2236,13 @@ "semver": "^5.4.1", "shellwords": "^0.1.1", "which": "^1.3.0" + }, + "dependencies": { + "semver": { + "version": "5.7.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.1.tgz", + "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==" + } } }, "npm-root": { @@ -2718,9 +2743,9 @@ "integrity": "sha512-NqVDv9TpANUjFm0N8uM5GxL36UgKi9/atZw+x7YFnQ8ckwFGKrl4xX4yWtrey3UJm5nP1kUbnYgLopqWNSRhWw==" }, "semver": { - "version": "5.5.0", - "resolved": "https://registry.npmjs.org/semver/-/semver-5.5.0.tgz", - "integrity": "sha512-4SJ3dm0WAwWy/NVeioZh5AntkdJoWKxHxcmyP622fOkgHa4z3R0TdBJICINyaSDE6uNwVc8gZr+ZinwZAH4xIA==" + "version": "6.3.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", + "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==" }, "set-blocking": { "version": "2.0.0", diff --git a/package.json b/package.json index a63f50d..88f1e45 100644 --- a/package.json +++ b/package.json @@ -43,6 +43,7 @@ "react-blessed": "^0.3.0", "readline-sync": "^1.4.9", "sanitize-filename": "^1.6.1", + "semver": "^6.3.0", "supervisord": "^0.1.0", "underscore": "^1.9.0", "yargs": "^11.0.0" diff --git a/src/components/FileLog.jsx b/src/components/FileLog.jsx index 4e12fbe..91755a9 100644 --- a/src/components/FileLog.jsx +++ b/src/components/FileLog.jsx @@ -2,6 +2,7 @@ import PropTypes from 'prop-types'; import React, {Component} from 'react'; import {Tail} from '@mixmaxhq/tail'; import screen, {enableMouse} from '/screen'; +import * as semver from 'semver'; import {statSync} from 'fs'; // It might be nice to render the entire log file. However this is probably (?) unnecessary and @@ -54,11 +55,33 @@ export default class FileLog extends Component { return; } + /** + * `fs.watch` does not consistently emit 'change' events when data is written to the log files + * under Node 10.16.0, possibly due to https://github.com/nodejs/node/issues/29460. + * `fs.watchFile` still works, but is less efficient, per the docs, so only use it if necessary + * and also suggest that users run custody under an older version of Node. See + * https://github.com/mixmaxhq/custody/issues/82 for more information. + */ + const mustUseWatchFile = semver.gte(process.version, '10.16.0'); + if (mustUseWatchFile) { + screen.debug('WARNING: `fs.watch` is broken when using this version of Node, falling back ' + + 'to `fs.watchFile`. To reduce CPU utilization, run `custody-cli` under an older version ' + + 'of Node. For more information see https://github.com/mixmaxhq/custody/issues/82.'); + } + // As documented on `INITIAL_SCROLLBACK`, we can't render the entire log file. However, the // 'tail' module lacks a `-n`-like option to get the last `INITIAL_SCROLLBACK` lines. So what we // do is load the entire file, but wait to render only the last `INITIAL_SCROLLBACK` lines, then // start streaming. - this.tail = new Tail(logfile, { fromBeginning: true }); + this.tail = new Tail(logfile, { + fromBeginning: true, + ...(mustUseWatchFile && { + useWatchFile: true, + fsWatchOptions: { + interval: 100, + } + }) + }); let logs = []; let initialDataFlushed = false;