From 50d28568413ff8e94cd81705dfcca1c967f0060a Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Fri, 3 Jul 2020 07:17:49 +0100 Subject: [PATCH 01/22] Re-instate metadata request as fallback for CLSI --- libraries/logger/logging-manager.js | 33 +- libraries/logger/package-lock.json | 291 +++++++++++++++++- libraries/logger/package.json | 1 + .../logger/test/unit/loggingManagerTests.js | 107 ++++++- 4 files changed, 418 insertions(+), 14 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index a54cf4f139..c830d04378 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -1,4 +1,5 @@ const bunyan = require('bunyan') +const request = require('request') const fs = require('fs') const yn = require('yn') const OError = require('@overleaf/o-error') @@ -41,7 +42,7 @@ const Logger = (module.exports = { return this }, - checkLogLevel() { + checkLogLevelFile() { fs.readFile('/logging/tracingEndTime', (error, end) => { if (error || !end) { this.logger.level(this.defaultLevel) @@ -55,6 +56,36 @@ const Logger = (module.exports = { }) }, + checkLogLevelMetadata() { + const options = { + headers: { + 'Metadata-Flavor': 'Google' + }, + uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + } + request(options, (err, response, body) => { + if (err) { + this.logger.level(this.defaultLevel) + return + } + if (parseInt(body) > Date.now()) { + this.logger.level('trace') + } else { + this.logger.level(this.defaultLevel) + } + }) + }, + + checkLogLevel() { + fs.access('/logging', (err) => { + if (err) { + this.checkLogLevelMetadata() + } else { + this.checkLogLevelFile() + } + }) + }, + initializeErrorReporting(sentryDsn, options) { const raven = require('raven') this.raven = new raven.Client(sentryDsn, options) diff --git a/libraries/logger/package-lock.json b/libraries/logger/package-lock.json index 3837260f94..8248bcff61 100644 --- a/libraries/logger/package-lock.json +++ b/libraries/logger/package-lock.json @@ -425,7 +425,6 @@ "version": "6.12.2", "resolved": "https://registry.npmjs.org/ajv/-/ajv-6.12.2.tgz", "integrity": "sha512-k+V+hzjm5q/Mr8ef/1Y9goCmlsK4I6Sm74teeyGvFk1XrOsbsKLjEdrvny42CZ+a8sXbk8KWpY/bDwS+FLL2UQ==", - "dev": true, "requires": { "fast-deep-equal": "^3.1.1", "fast-json-stable-stringify": "^2.0.0", @@ -511,6 +510,19 @@ "resolved": "https://registry.npmjs.org/arrify/-/arrify-2.0.1.tgz", "integrity": "sha512-3duEwti880xqi4eAMN8AyR4a0ByT90zoYdLlevfrvU43vb0YZwZVfxOgxWrLXXXpyugL0hNZc9G6BiB5B3nUug==" }, + "asn1": { + "version": "0.2.4", + "resolved": "https://registry.npmjs.org/asn1/-/asn1-0.2.4.tgz", + "integrity": "sha512-jxwzQpLQjSmWXgwaCZE9Nz+glAG01yF1QnWgbhGwHI5A6FRIEY6IVqtHhIepHqI7/kyEyQEagBC5mBEFlIYvdg==", + "requires": { + "safer-buffer": "~2.1.0" + } + }, + "assert-plus": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz", + "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU=" + }, "assertion-error": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/assertion-error/-/assertion-error-1.1.0.tgz", @@ -539,6 +551,21 @@ } } }, + "asynckit": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz", + "integrity": "sha1-x57Zf380y48robyXkLzDZkdLS3k=" + }, + "aws-sign2": { + "version": "0.7.0", + "resolved": "https://registry.npmjs.org/aws-sign2/-/aws-sign2-0.7.0.tgz", + "integrity": "sha1-tG6JCTSpWR8tL2+G1+ap8bP+dqg=" + }, + "aws4": { + "version": "1.10.0", + "resolved": "https://registry.npmjs.org/aws4/-/aws4-1.10.0.tgz", + "integrity": "sha512-3YDiu347mtVtjpyV3u5kVqQLP242c06zwDOgpeRnybmXlYYsLbtTrUBUm8i8srONt+FWobl5aibnU1030PeeuA==" + }, "balanced-match": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-1.0.0.tgz", @@ -549,6 +576,14 @@ "resolved": "https://registry.npmjs.org/base64-js/-/base64-js-1.3.1.tgz", "integrity": "sha512-mLQ4i2QO1ytvGWFWmcngKO//JXAQueZvwEKtjgQFM4jIK0kU+ytMfplL8j+n5mspOfjHwoAg+9yhb7BwAHm36g==" }, + "bcrypt-pbkdf": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/bcrypt-pbkdf/-/bcrypt-pbkdf-1.0.2.tgz", + "integrity": "sha1-pDAdOJtqQ/m2f/PKEaP2Y342Dp4=", + "requires": { + "tweetnacl": "^0.14.3" + } + }, "bignumber.js": { "version": "9.0.0", "resolved": "https://registry.npmjs.org/bignumber.js/-/bignumber.js-9.0.0.tgz", @@ -629,6 +664,11 @@ "quick-lru": "^4.0.1" } }, + "caseless": { + "version": "0.12.0", + "resolved": "https://registry.npmjs.org/caseless/-/caseless-0.12.0.tgz", + "integrity": "sha1-G2gcIf+EAzyCZUMJBolCDRhxUdw=" + }, "chai": { "version": "4.2.0", "resolved": "https://registry.npmjs.org/chai/-/chai-4.2.0.tgz", @@ -738,6 +778,14 @@ "integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU=", "dev": true }, + "combined-stream": { + "version": "1.0.8", + "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", + "integrity": "sha512-FQN4MRfuJeHf7cBbBMJFXhKSDq+2kAArBlmRBvcvFE5BB1HZKXtSFASDhdlz9zOYwxh8lDdnvmMOe/+5cdoEdg==", + "requires": { + "delayed-stream": "~1.0.0" + } + }, "common-tags": { "version": "1.8.0", "resolved": "https://registry.npmjs.org/common-tags/-/common-tags-1.8.0.tgz", @@ -811,6 +859,14 @@ "resolved": "https://registry.npmjs.org/d64/-/d64-1.0.0.tgz", "integrity": "sha1-QAKofoUMv8n52XBrYPymE6MzbpA=" }, + "dashdash": { + "version": "1.14.1", + "resolved": "https://registry.npmjs.org/dashdash/-/dashdash-1.14.1.tgz", + "integrity": "sha1-hTz6D3y+L+1d4gMmuN1YEDX24vA=", + "requires": { + "assert-plus": "^1.0.0" + } + }, "debug": { "version": "4.1.1", "resolved": "https://registry.npmjs.org/debug/-/debug-4.1.1.tgz", @@ -849,6 +905,11 @@ "object-keys": "^1.0.12" } }, + "delayed-stream": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/delayed-stream/-/delayed-stream-1.0.0.tgz", + "integrity": "sha1-3zrhmayt+31ECqrgsp4icrJOxhk=" + }, "diff": { "version": "4.0.2", "resolved": "https://registry.npmjs.org/diff/-/diff-4.0.2.tgz", @@ -898,6 +959,15 @@ "stream-shift": "^1.0.0" } }, + "ecc-jsbn": { + "version": "0.1.2", + "resolved": "https://registry.npmjs.org/ecc-jsbn/-/ecc-jsbn-0.1.2.tgz", + "integrity": "sha1-OoOpBOVDUyh4dMVkt1SThoSamMk=", + "requires": { + "jsbn": "~0.1.0", + "safer-buffer": "^2.1.0" + } + }, "ecdsa-sig-formatter": { "version": "1.0.11", "resolved": "https://registry.npmjs.org/ecdsa-sig-formatter/-/ecdsa-sig-formatter-1.0.11.tgz", @@ -1566,17 +1636,20 @@ "tmp": "^0.0.33" } }, + "extsprintf": { + "version": "1.3.0", + "resolved": "https://registry.npmjs.org/extsprintf/-/extsprintf-1.3.0.tgz", + "integrity": "sha1-lpGEQOMEGnpBT4xS48V06zw+HgU=" + }, "fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", - "integrity": "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q==", - "dev": true + "integrity": "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q==" }, "fast-json-stable-stringify": { "version": "2.1.0", "resolved": "https://registry.npmjs.org/fast-json-stable-stringify/-/fast-json-stable-stringify-2.1.0.tgz", - "integrity": "sha512-lhd/wF+Lk98HZoTCtlVraHtfh5XYijIjalXck7saUtuanSDyLMxnHhSXEDJqHxD7msR8D0uCmqlkwjCV8xvwHw==", - "dev": true + "integrity": "sha512-lhd/wF+Lk98HZoTCtlVraHtfh5XYijIjalXck7saUtuanSDyLMxnHhSXEDJqHxD7msR8D0uCmqlkwjCV8xvwHw==" }, "fast-levenshtein": { "version": "2.0.6", @@ -1675,6 +1748,21 @@ "integrity": "sha512-r5wGx7YeOwNWNlCA0wQ86zKyDLMQr+/RB8xy74M4hTphfmjlijTSSXGuH8rnvKZnfT9i+75zmd8jcKdMR4O6jA==", "dev": true }, + "forever-agent": { + "version": "0.6.1", + "resolved": "https://registry.npmjs.org/forever-agent/-/forever-agent-0.6.1.tgz", + "integrity": "sha1-+8cfDEGt6zf5bFd60e1C2P2sypE=" + }, + "form-data": { + "version": "2.3.3", + "resolved": "https://registry.npmjs.org/form-data/-/form-data-2.3.3.tgz", + "integrity": "sha512-1lLKB2Mu3aGP1Q/2eCOx0fNbRMe7XdwktwOruhfqqd0rIJWwN4Dh+E3hrPSlDCXnSR7UtZ1N38rVXm+6+MEhJQ==", + "requires": { + "asynckit": "^0.4.0", + "combined-stream": "^1.0.6", + "mime-types": "^2.1.12" + } + }, "fs.realpath": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/fs.realpath/-/fs.realpath-1.0.0.tgz", @@ -1739,6 +1827,14 @@ "integrity": "sha512-jp4tHawyV7+fkkSKyvjuLZswblUtz+SQKzSWnBbii16BuZksJlU1wuBYXY75r+duh/llF1ur6oNwi+2ZzjKZ7g==", "dev": true }, + "getpass": { + "version": "0.1.7", + "resolved": "https://registry.npmjs.org/getpass/-/getpass-0.1.7.tgz", + "integrity": "sha1-Xv+OPmhNVprkyysSgmBOi6YhSfo=", + "requires": { + "assert-plus": "^1.0.0" + } + }, "glob": { "version": "6.0.4", "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", @@ -1907,6 +2003,20 @@ "mime": "^2.2.0" } }, + "har-schema": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/har-schema/-/har-schema-2.0.0.tgz", + "integrity": "sha1-qUwiJOvKwEeCoNkDVSHyRzW37JI=" + }, + "har-validator": { + "version": "5.1.3", + "resolved": "https://registry.npmjs.org/har-validator/-/har-validator-5.1.3.tgz", + "integrity": "sha512-sNvOCzEQNr/qrvJgc3UG/kD4QtlHycrzwS+6mfTrrSq97BvaYcPZZI1ZSqGSPR73Cxn4LKTD4PttRwfU7jWq5g==", + "requires": { + "ajv": "^6.5.5", + "har-schema": "^2.0.0" + } + }, "has": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/has/-/has-1.0.3.tgz", @@ -1972,6 +2082,16 @@ "debug": "4" } }, + "http-signature": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/http-signature/-/http-signature-1.2.0.tgz", + "integrity": "sha1-muzZJRFHcvPZW2WmCruPfBj7rOE=", + "requires": { + "assert-plus": "^1.0.0", + "jsprim": "^1.2.2", + "sshpk": "^1.7.0" + } + }, "https-proxy-agent": { "version": "5.0.0", "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-5.0.0.tgz", @@ -2147,6 +2267,11 @@ "has-symbols": "^1.0.1" } }, + "is-typedarray": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/is-typedarray/-/is-typedarray-1.0.0.tgz", + "integrity": "sha1-5HnICFjfDBsR3dppQPlgEfzaSpo=" + }, "isarray": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/isarray/-/isarray-1.0.0.tgz", @@ -2158,6 +2283,11 @@ "integrity": "sha1-6PvzdNxVb/iUehDcsFctYz8s+hA=", "dev": true }, + "isstream": { + "version": "0.1.2", + "resolved": "https://registry.npmjs.org/isstream/-/isstream-0.1.2.tgz", + "integrity": "sha1-R+Y/evVa+m+S4VAOaQ64uFKcCZo=" + }, "iterate-iterator": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/iterate-iterator/-/iterate-iterator-1.0.1.tgz", @@ -2190,6 +2320,11 @@ "esprima": "^4.0.0" } }, + "jsbn": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/jsbn/-/jsbn-0.1.1.tgz", + "integrity": "sha1-peZUwuWi3rXyAdls77yoDA7y9RM=" + }, "json-bigint": { "version": "0.3.1", "resolved": "https://registry.npmjs.org/json-bigint/-/json-bigint-0.3.1.tgz", @@ -2198,11 +2333,15 @@ "bignumber.js": "^9.0.0" } }, + "json-schema": { + "version": "0.2.3", + "resolved": "https://registry.npmjs.org/json-schema/-/json-schema-0.2.3.tgz", + "integrity": "sha1-tIDIkuWaLwWVTOcnvT8qTogvnhM=" + }, "json-schema-traverse": { "version": "0.4.1", "resolved": "https://registry.npmjs.org/json-schema-traverse/-/json-schema-traverse-0.4.1.tgz", - "integrity": "sha512-xbbCH5dCYU5T8LcEhhuh7HJ88HXuW3qsI3Y0zOZFKfZEHcpWiHU/Jxzk629Brsab/mMiHQti9wMP+845RPe3Vg==", - "dev": true + "integrity": "sha512-xbbCH5dCYU5T8LcEhhuh7HJ88HXuW3qsI3Y0zOZFKfZEHcpWiHU/Jxzk629Brsab/mMiHQti9wMP+845RPe3Vg==" }, "json-stable-stringify-without-jsonify": { "version": "1.0.1", @@ -2210,6 +2349,11 @@ "integrity": "sha1-nbe1lJatPzz+8wp1FC0tkwrXJlE=", "dev": true }, + "json-stringify-safe": { + "version": "5.0.1", + "resolved": "https://registry.npmjs.org/json-stringify-safe/-/json-stringify-safe-5.0.1.tgz", + "integrity": "sha1-Epai1Y/UXxmg9s4B1lcB4sc1tus=" + }, "json5": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/json5/-/json5-1.0.1.tgz", @@ -2219,6 +2363,17 @@ "minimist": "^1.2.0" } }, + "jsprim": { + "version": "1.4.1", + "resolved": "https://registry.npmjs.org/jsprim/-/jsprim-1.4.1.tgz", + "integrity": "sha1-MT5mvB5cwG5Di8G3SZwuXFastqI=", + "requires": { + "assert-plus": "1.0.0", + "extsprintf": "1.3.0", + "json-schema": "0.2.3", + "verror": "1.10.0" + } + }, "just-extend": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/just-extend/-/just-extend-4.1.0.tgz", @@ -2458,6 +2613,19 @@ "resolved": "https://registry.npmjs.org/mime/-/mime-2.4.6.tgz", "integrity": "sha512-RZKhC3EmpBchfTGBVb8fb+RL2cWyw/32lshnsETttkBAyAUXSGHxbEJWWRXc751DrIxG1q04b8QwMbAwkRPpUA==" }, + "mime-db": { + "version": "1.44.0", + "resolved": "https://registry.npmjs.org/mime-db/-/mime-db-1.44.0.tgz", + "integrity": "sha512-/NOTfLrsPBVeH7YtFPgsVWveuL+4SjjYxaQ1xtM1KMFj7HdxlBlxeyNLzhyJVx7r4rZGJAZ/6lkKCitSc/Nmpg==" + }, + "mime-types": { + "version": "2.1.27", + "resolved": "https://registry.npmjs.org/mime-types/-/mime-types-2.1.27.tgz", + "integrity": "sha512-JIhqnCasI9yD+SsmkquHBxTSEuZdQX5BuQnS2Vc7puQQQ+8yiP5AY5uWhpdv4YL4VM5c6iliiYWPgJ/nJQLp7w==", + "requires": { + "mime-db": "1.44.0" + } + }, "minimatch": { "version": "3.0.4", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.0.4.tgz", @@ -2721,6 +2889,11 @@ "integrity": "sha512-6eZs5Ls3WtCisHWp9S2GUy8dqkpGi4BVSz3GaqiE6ezub0512ESztXUwUB6C6IKbQkY2Pnb/mD4WYojCRwcwLA==", "dev": true }, + "oauth-sign": { + "version": "0.9.0", + "resolved": "https://registry.npmjs.org/oauth-sign/-/oauth-sign-0.9.0.tgz", + "integrity": "sha512-fexhUFFPTGV8ybAtSIGbV6gOkSv8UtRbDBnAyLQw4QPKkgNlsH2ByPGtMUqdWkos6YCRmAqViwgZrJc/mRDzZQ==" + }, "object-inspect": { "version": "1.8.0", "resolved": "https://registry.npmjs.org/object-inspect/-/object-inspect-1.8.0.tgz", @@ -2896,6 +3069,11 @@ "integrity": "sha1-uULm1L3mUwBe9rcTYd74cn0GReA=", "dev": true }, + "performance-now": { + "version": "2.1.0", + "resolved": "https://registry.npmjs.org/performance-now/-/performance-now-2.1.0.tgz", + "integrity": "sha1-Ywn04OX6kT7BxpMHrjZLSzd8nns=" + }, "picomatch": { "version": "2.2.2", "resolved": "https://registry.npmjs.org/picomatch/-/picomatch-2.2.2.tgz", @@ -3582,6 +3760,11 @@ "long": "^4.0.0" } }, + "psl": { + "version": "1.8.0", + "resolved": "https://registry.npmjs.org/psl/-/psl-1.8.0.tgz", + "integrity": "sha512-RIdOzyoavK+hA18OGGWDqUTsCLhtA7IcZ/6NCs4fFJaHBDab+pDDmDIByWFRQJq2Cd7r1OoQxBGKOaztq+hjIQ==" + }, "pump": { "version": "3.0.0", "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", @@ -3627,8 +3810,12 @@ "punycode": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.1.1.tgz", - "integrity": "sha512-XRsRjdf+j5ml+y/6GKHPZbrF/8p2Yga0JPtdqTIY2Xe5ohJPD9saDJJLPvp9+NSBprVvevdXZybnj2cv8OEd0A==", - "dev": true + "integrity": "sha512-XRsRjdf+j5ml+y/6GKHPZbrF/8p2Yga0JPtdqTIY2Xe5ohJPD9saDJJLPvp9+NSBprVvevdXZybnj2cv8OEd0A==" + }, + "qs": { + "version": "6.5.2", + "resolved": "https://registry.npmjs.org/qs/-/qs-6.5.2.tgz", + "integrity": "sha512-N5ZAX4/LxJmF+7wN74pUD6qAh9/wnvdQcjq9TZjevvXzSUo7bfmw91saqMjzGS2xq91/odN2dW/WOl7qQHNDGA==" }, "quick-lru": { "version": "4.0.1", @@ -3711,6 +3898,40 @@ "integrity": "sha512-lv0M6+TkDVniA3aD1Eg0DVpfU/booSu7Eev3TDO/mZKHBfVjgCGTV4t4buppESEYDtkArYFOxTJWv6S5C+iaNw==", "dev": true }, + "request": { + "version": "2.88.2", + "resolved": "https://registry.npmjs.org/request/-/request-2.88.2.tgz", + "integrity": "sha512-MsvtOrfG9ZcrOwAW+Qi+F6HbD0CWXEh9ou77uOb7FM2WPhwT7smM833PzanhJLsgXjN89Ir6V2PczXNnMpwKhw==", + "requires": { + "aws-sign2": "~0.7.0", + "aws4": "^1.8.0", + "caseless": "~0.12.0", + "combined-stream": "~1.0.6", + "extend": "~3.0.2", + "forever-agent": "~0.6.1", + "form-data": "~2.3.2", + "har-validator": "~5.1.3", + "http-signature": "~1.2.0", + "is-typedarray": "~1.0.0", + "isstream": "~0.1.2", + "json-stringify-safe": "~5.0.1", + "mime-types": "~2.1.19", + "oauth-sign": "~0.9.0", + "performance-now": "^2.1.0", + "qs": "~6.5.2", + "safe-buffer": "^5.1.2", + "tough-cookie": "~2.5.0", + "tunnel-agent": "^0.6.0", + "uuid": "^3.3.2" + }, + "dependencies": { + "uuid": { + "version": "3.4.0", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.4.0.tgz", + "integrity": "sha512-HjSDRw6gZE5JMggctHBcjVak08+KEVhSIiDzFnT9S9aegmp85S/bReBVTb4QTFaRNptJ9kuYaNhnbNEOkbKb/A==" + } + } + }, "require-directory": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/require-directory/-/require-directory-2.1.1.tgz", @@ -3797,8 +4018,7 @@ "safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", - "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", - "dev": true + "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==" }, "sandboxed-module": { "version": "2.0.4", @@ -3965,6 +4185,22 @@ "integrity": "sha1-BOaSb2YolTVPPdAVIDYzuFcpfiw=", "dev": true }, + "sshpk": { + "version": "1.16.1", + "resolved": "https://registry.npmjs.org/sshpk/-/sshpk-1.16.1.tgz", + "integrity": "sha512-HXXqVUq7+pcKeLqqZj6mHFUMvXtOJt1uoUx09pFW6011inTMxqI8BA8PM95myrIyyKwdnzjdFjLiE6KBPVtJIg==", + "requires": { + "asn1": "~0.2.3", + "assert-plus": "^1.0.0", + "bcrypt-pbkdf": "^1.0.0", + "dashdash": "^1.12.0", + "ecc-jsbn": "~0.1.1", + "getpass": "^0.1.1", + "jsbn": "~0.1.0", + "safer-buffer": "^2.0.2", + "tweetnacl": "~0.14.0" + } + }, "stack-trace": { "version": "0.0.10", "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz", @@ -4168,6 +4404,15 @@ "to-no-case": "^1.0.0" } }, + "tough-cookie": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/tough-cookie/-/tough-cookie-2.5.0.tgz", + "integrity": "sha512-nlLsUzgm1kfLXSXfRZMc1KLAugd4hqJHDTvc2hDIwS3mZAfMEuMbc03SujMF+GEcpaX/qboeycw6iO8JwVv2+g==", + "requires": { + "psl": "^1.1.28", + "punycode": "^2.1.1" + } + }, "tsconfig-paths": { "version": "3.9.0", "resolved": "https://registry.npmjs.org/tsconfig-paths/-/tsconfig-paths-3.9.0.tgz", @@ -4186,6 +4431,19 @@ "integrity": "sha512-i/6DQjL8Xf3be4K/E6Wgpekn5Qasl1usyw++dAA35Ue5orEn65VIxOA+YvNNl9HV3qv70T7CNwjODHZrLwvd1Q==", "dev": true }, + "tunnel-agent": { + "version": "0.6.0", + "resolved": "https://registry.npmjs.org/tunnel-agent/-/tunnel-agent-0.6.0.tgz", + "integrity": "sha1-J6XeoGs2sEoKmWZ3SykIaPD8QP0=", + "requires": { + "safe-buffer": "^5.0.1" + } + }, + "tweetnacl": { + "version": "0.14.5", + "resolved": "https://registry.npmjs.org/tweetnacl/-/tweetnacl-0.14.5.tgz", + "integrity": "sha1-WuaBd/GS1EViadEIr6k/+HQ/T2Q=" + }, "type-check": { "version": "0.3.2", "resolved": "https://registry.npmjs.org/type-check/-/type-check-0.3.2.tgz", @@ -4216,7 +4474,6 @@ "version": "4.2.2", "resolved": "https://registry.npmjs.org/uri-js/-/uri-js-4.2.2.tgz", "integrity": "sha512-KY9Frmirql91X2Qgjry0Wd4Y+YTdrdZheS8TFwvkbLWf/G5KNJDCh6pKL5OZctEW4+0Baa5idK2ZQuELRwPznQ==", - "dev": true, "requires": { "punycode": "^2.1.0" } @@ -4247,6 +4504,16 @@ "spdx-expression-parse": "^3.0.0" } }, + "verror": { + "version": "1.10.0", + "resolved": "https://registry.npmjs.org/verror/-/verror-1.10.0.tgz", + "integrity": "sha1-OhBcoXBTr1XW4nDB+CiGguGNpAA=", + "requires": { + "assert-plus": "^1.0.0", + "core-util-is": "1.0.2", + "extsprintf": "^1.2.0" + } + }, "vue-eslint-parser": { "version": "2.0.3", "resolved": "https://registry.npmjs.org/vue-eslint-parser/-/vue-eslint-parser-2.0.3.tgz", diff --git a/libraries/logger/package.json b/libraries/logger/package.json index d6b370c559..9e1189b363 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -19,6 +19,7 @@ "@overleaf/o-error": "^3.0.0", "bunyan": "^1.8.14", "raven": "^2.6.4", + "request": "^2.88.2", "yn": "^4.0.0" }, "devDependencies": { diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index ba2e89ca49..b1a915f283 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -40,8 +40,10 @@ describe('LoggingManager', function () { this.Raven = { Client: sinon.stub().returns(this.ravenClient) } + this.Request = sinon.stub() this.Fs = { - readFile: sinon.stub() + readFile: sinon.stub(), + access: sinon.stub() } this.stackdriverStreamConfig = { stream: 'stackdriver' } this.stackdriverClient = { @@ -55,6 +57,7 @@ describe('LoggingManager', function () { requires: { bunyan: this.Bunyan, raven: this.Raven, + request: this.Request, fs: this.Fs, '@google-cloud/logging-bunyan': this.GCPLogging } @@ -288,8 +291,16 @@ describe('LoggingManager', function () { }) describe('checkLogLevel', function () { + beforeEach(function () { + this.Fs.access.yields(null) + }) + + it('should request log level override from the config map', function () { this.logger.checkLogLevel() + this.Fs.access.should.have.been.calledWithMatch( + '/logging' + ) this.Fs.readFile.should.have.been.calledWithMatch( '/logging/tracingEndTime' ) @@ -361,6 +372,100 @@ describe('LoggingManager', function () { 'trace' ) }) + }) + + describe('when /logging does not exist', function () { + beforeEach(function () { + this.Fs.access.yields(new Error) + }) + + describe('checkLogLevel', function() { + it('should request log level override from google meta data service', function() { + this.logger.checkLogLevel() + const options = { + headers: { + 'Metadata-Flavor': 'Google' + }, + uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + } + this.Request.should.have.been.calledWithMatch(options) + }) + + describe('when request has error', function() { + beforeEach(function() { + this.Request.yields('error') + this.logger.checkLogLevel() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when statusCode is not 200', function() { + beforeEach(function() { + this.Request.yields(null, { statusCode: 404 }) + this.logger.checkLogLevel() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when time value returned that is less than current time', function() { + beforeEach(function() { + this.Request.yields(null, { statusCode: 200 }, '1') + this.logger.checkLogLevel() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when time value returned that is more than current time', function() { + describe('when level is already set', function() { + beforeEach(function() { + this.bunyanLogger.level.returns(10) + this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.logger.checkLogLevel() + }) + + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) + }) + }) + + describe('when level is not already set', function() { + beforeEach(function() { + this.bunyanLogger.level.returns(20) + this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.logger.checkLogLevel() + }) + + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) + }) + }) + }) + }) + + + + + + }) }) }) From 40a08bebdb8ac6135fcd875e7822d43b377e1ada Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Mon, 6 Jul 2020 14:53:49 +0100 Subject: [PATCH 02/22] WIP --- libraries/logger/logging-manager.js | 15 +- libraries/logger/package-lock.json | 291 +----------------- libraries/logger/package.json | 2 +- .../logger/test/unit/loggingManagerTests.js | 23 +- 4 files changed, 37 insertions(+), 294 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index c830d04378..34bc08cd6d 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -1,5 +1,5 @@ const bunyan = require('bunyan') -const request = require('request') +const fetch = require('node-fetch') const fs = require('fs') const yn = require('yn') const OError = require('@overleaf/o-error') @@ -60,19 +60,18 @@ const Logger = (module.exports = { const options = { headers: { 'Metadata-Flavor': 'Google' - }, - uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - } - request(options, (err, response, body) => { - if (err) { - this.logger.level(this.defaultLevel) - return } + } + const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + fetch.fetch(uri,options).then(res => res.text()).then(body => { if (parseInt(body) > Date.now()) { this.logger.level('trace') } else { this.logger.level(this.defaultLevel) } + }).catch(err => { + this.logger.level(this.defaultLevel) + return }) }, diff --git a/libraries/logger/package-lock.json b/libraries/logger/package-lock.json index 8248bcff61..3837260f94 100644 --- a/libraries/logger/package-lock.json +++ b/libraries/logger/package-lock.json @@ -425,6 +425,7 @@ "version": "6.12.2", "resolved": "https://registry.npmjs.org/ajv/-/ajv-6.12.2.tgz", "integrity": "sha512-k+V+hzjm5q/Mr8ef/1Y9goCmlsK4I6Sm74teeyGvFk1XrOsbsKLjEdrvny42CZ+a8sXbk8KWpY/bDwS+FLL2UQ==", + "dev": true, "requires": { "fast-deep-equal": "^3.1.1", "fast-json-stable-stringify": "^2.0.0", @@ -510,19 +511,6 @@ "resolved": "https://registry.npmjs.org/arrify/-/arrify-2.0.1.tgz", "integrity": "sha512-3duEwti880xqi4eAMN8AyR4a0ByT90zoYdLlevfrvU43vb0YZwZVfxOgxWrLXXXpyugL0hNZc9G6BiB5B3nUug==" }, - "asn1": { - "version": "0.2.4", - "resolved": "https://registry.npmjs.org/asn1/-/asn1-0.2.4.tgz", - "integrity": "sha512-jxwzQpLQjSmWXgwaCZE9Nz+glAG01yF1QnWgbhGwHI5A6FRIEY6IVqtHhIepHqI7/kyEyQEagBC5mBEFlIYvdg==", - "requires": { - "safer-buffer": "~2.1.0" - } - }, - "assert-plus": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz", - "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU=" - }, "assertion-error": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/assertion-error/-/assertion-error-1.1.0.tgz", @@ -551,21 +539,6 @@ } } }, - "asynckit": { - "version": "0.4.0", - "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz", - "integrity": "sha1-x57Zf380y48robyXkLzDZkdLS3k=" - }, - "aws-sign2": { - "version": "0.7.0", - "resolved": "https://registry.npmjs.org/aws-sign2/-/aws-sign2-0.7.0.tgz", - "integrity": "sha1-tG6JCTSpWR8tL2+G1+ap8bP+dqg=" - }, - "aws4": { - "version": "1.10.0", - "resolved": "https://registry.npmjs.org/aws4/-/aws4-1.10.0.tgz", - "integrity": "sha512-3YDiu347mtVtjpyV3u5kVqQLP242c06zwDOgpeRnybmXlYYsLbtTrUBUm8i8srONt+FWobl5aibnU1030PeeuA==" - }, "balanced-match": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-1.0.0.tgz", @@ -576,14 +549,6 @@ "resolved": "https://registry.npmjs.org/base64-js/-/base64-js-1.3.1.tgz", "integrity": "sha512-mLQ4i2QO1ytvGWFWmcngKO//JXAQueZvwEKtjgQFM4jIK0kU+ytMfplL8j+n5mspOfjHwoAg+9yhb7BwAHm36g==" }, - "bcrypt-pbkdf": { - "version": "1.0.2", - "resolved": "https://registry.npmjs.org/bcrypt-pbkdf/-/bcrypt-pbkdf-1.0.2.tgz", - "integrity": "sha1-pDAdOJtqQ/m2f/PKEaP2Y342Dp4=", - "requires": { - "tweetnacl": "^0.14.3" - } - }, "bignumber.js": { "version": "9.0.0", "resolved": "https://registry.npmjs.org/bignumber.js/-/bignumber.js-9.0.0.tgz", @@ -664,11 +629,6 @@ "quick-lru": "^4.0.1" } }, - "caseless": { - "version": "0.12.0", - "resolved": "https://registry.npmjs.org/caseless/-/caseless-0.12.0.tgz", - "integrity": "sha1-G2gcIf+EAzyCZUMJBolCDRhxUdw=" - }, "chai": { "version": "4.2.0", "resolved": "https://registry.npmjs.org/chai/-/chai-4.2.0.tgz", @@ -778,14 +738,6 @@ "integrity": "sha1-p9BVi9icQveV3UIyj3QIMcpTvCU=", "dev": true }, - "combined-stream": { - "version": "1.0.8", - "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", - "integrity": "sha512-FQN4MRfuJeHf7cBbBMJFXhKSDq+2kAArBlmRBvcvFE5BB1HZKXtSFASDhdlz9zOYwxh8lDdnvmMOe/+5cdoEdg==", - "requires": { - "delayed-stream": "~1.0.0" - } - }, "common-tags": { "version": "1.8.0", "resolved": "https://registry.npmjs.org/common-tags/-/common-tags-1.8.0.tgz", @@ -859,14 +811,6 @@ "resolved": "https://registry.npmjs.org/d64/-/d64-1.0.0.tgz", "integrity": "sha1-QAKofoUMv8n52XBrYPymE6MzbpA=" }, - "dashdash": { - "version": "1.14.1", - "resolved": "https://registry.npmjs.org/dashdash/-/dashdash-1.14.1.tgz", - "integrity": "sha1-hTz6D3y+L+1d4gMmuN1YEDX24vA=", - "requires": { - "assert-plus": "^1.0.0" - } - }, "debug": { "version": "4.1.1", "resolved": "https://registry.npmjs.org/debug/-/debug-4.1.1.tgz", @@ -905,11 +849,6 @@ "object-keys": "^1.0.12" } }, - "delayed-stream": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/delayed-stream/-/delayed-stream-1.0.0.tgz", - "integrity": "sha1-3zrhmayt+31ECqrgsp4icrJOxhk=" - }, "diff": { "version": "4.0.2", "resolved": "https://registry.npmjs.org/diff/-/diff-4.0.2.tgz", @@ -959,15 +898,6 @@ "stream-shift": "^1.0.0" } }, - "ecc-jsbn": { - "version": "0.1.2", - "resolved": "https://registry.npmjs.org/ecc-jsbn/-/ecc-jsbn-0.1.2.tgz", - "integrity": "sha1-OoOpBOVDUyh4dMVkt1SThoSamMk=", - "requires": { - "jsbn": "~0.1.0", - "safer-buffer": "^2.1.0" - } - }, "ecdsa-sig-formatter": { "version": "1.0.11", "resolved": "https://registry.npmjs.org/ecdsa-sig-formatter/-/ecdsa-sig-formatter-1.0.11.tgz", @@ -1636,20 +1566,17 @@ "tmp": "^0.0.33" } }, - "extsprintf": { - "version": "1.3.0", - "resolved": "https://registry.npmjs.org/extsprintf/-/extsprintf-1.3.0.tgz", - "integrity": "sha1-lpGEQOMEGnpBT4xS48V06zw+HgU=" - }, "fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", - "integrity": "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q==" + "integrity": "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q==", + "dev": true }, "fast-json-stable-stringify": { "version": "2.1.0", "resolved": "https://registry.npmjs.org/fast-json-stable-stringify/-/fast-json-stable-stringify-2.1.0.tgz", - "integrity": "sha512-lhd/wF+Lk98HZoTCtlVraHtfh5XYijIjalXck7saUtuanSDyLMxnHhSXEDJqHxD7msR8D0uCmqlkwjCV8xvwHw==" + "integrity": "sha512-lhd/wF+Lk98HZoTCtlVraHtfh5XYijIjalXck7saUtuanSDyLMxnHhSXEDJqHxD7msR8D0uCmqlkwjCV8xvwHw==", + "dev": true }, "fast-levenshtein": { "version": "2.0.6", @@ -1748,21 +1675,6 @@ "integrity": "sha512-r5wGx7YeOwNWNlCA0wQ86zKyDLMQr+/RB8xy74M4hTphfmjlijTSSXGuH8rnvKZnfT9i+75zmd8jcKdMR4O6jA==", "dev": true }, - "forever-agent": { - "version": "0.6.1", - "resolved": "https://registry.npmjs.org/forever-agent/-/forever-agent-0.6.1.tgz", - "integrity": "sha1-+8cfDEGt6zf5bFd60e1C2P2sypE=" - }, - "form-data": { - "version": "2.3.3", - "resolved": "https://registry.npmjs.org/form-data/-/form-data-2.3.3.tgz", - "integrity": "sha512-1lLKB2Mu3aGP1Q/2eCOx0fNbRMe7XdwktwOruhfqqd0rIJWwN4Dh+E3hrPSlDCXnSR7UtZ1N38rVXm+6+MEhJQ==", - "requires": { - "asynckit": "^0.4.0", - "combined-stream": "^1.0.6", - "mime-types": "^2.1.12" - } - }, "fs.realpath": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/fs.realpath/-/fs.realpath-1.0.0.tgz", @@ -1827,14 +1739,6 @@ "integrity": "sha512-jp4tHawyV7+fkkSKyvjuLZswblUtz+SQKzSWnBbii16BuZksJlU1wuBYXY75r+duh/llF1ur6oNwi+2ZzjKZ7g==", "dev": true }, - "getpass": { - "version": "0.1.7", - "resolved": "https://registry.npmjs.org/getpass/-/getpass-0.1.7.tgz", - "integrity": "sha1-Xv+OPmhNVprkyysSgmBOi6YhSfo=", - "requires": { - "assert-plus": "^1.0.0" - } - }, "glob": { "version": "6.0.4", "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", @@ -2003,20 +1907,6 @@ "mime": "^2.2.0" } }, - "har-schema": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/har-schema/-/har-schema-2.0.0.tgz", - "integrity": "sha1-qUwiJOvKwEeCoNkDVSHyRzW37JI=" - }, - "har-validator": { - "version": "5.1.3", - "resolved": "https://registry.npmjs.org/har-validator/-/har-validator-5.1.3.tgz", - "integrity": "sha512-sNvOCzEQNr/qrvJgc3UG/kD4QtlHycrzwS+6mfTrrSq97BvaYcPZZI1ZSqGSPR73Cxn4LKTD4PttRwfU7jWq5g==", - "requires": { - "ajv": "^6.5.5", - "har-schema": "^2.0.0" - } - }, "has": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/has/-/has-1.0.3.tgz", @@ -2082,16 +1972,6 @@ "debug": "4" } }, - "http-signature": { - "version": "1.2.0", - "resolved": "https://registry.npmjs.org/http-signature/-/http-signature-1.2.0.tgz", - "integrity": "sha1-muzZJRFHcvPZW2WmCruPfBj7rOE=", - "requires": { - "assert-plus": "^1.0.0", - "jsprim": "^1.2.2", - "sshpk": "^1.7.0" - } - }, "https-proxy-agent": { "version": "5.0.0", "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-5.0.0.tgz", @@ -2267,11 +2147,6 @@ "has-symbols": "^1.0.1" } }, - "is-typedarray": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/is-typedarray/-/is-typedarray-1.0.0.tgz", - "integrity": "sha1-5HnICFjfDBsR3dppQPlgEfzaSpo=" - }, "isarray": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/isarray/-/isarray-1.0.0.tgz", @@ -2283,11 +2158,6 @@ "integrity": "sha1-6PvzdNxVb/iUehDcsFctYz8s+hA=", "dev": true }, - "isstream": { - "version": "0.1.2", - "resolved": "https://registry.npmjs.org/isstream/-/isstream-0.1.2.tgz", - "integrity": "sha1-R+Y/evVa+m+S4VAOaQ64uFKcCZo=" - }, "iterate-iterator": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/iterate-iterator/-/iterate-iterator-1.0.1.tgz", @@ -2320,11 +2190,6 @@ "esprima": "^4.0.0" } }, - "jsbn": { - "version": "0.1.1", - "resolved": "https://registry.npmjs.org/jsbn/-/jsbn-0.1.1.tgz", - "integrity": "sha1-peZUwuWi3rXyAdls77yoDA7y9RM=" - }, "json-bigint": { "version": "0.3.1", "resolved": "https://registry.npmjs.org/json-bigint/-/json-bigint-0.3.1.tgz", @@ -2333,15 +2198,11 @@ "bignumber.js": "^9.0.0" } }, - "json-schema": { - "version": "0.2.3", - "resolved": "https://registry.npmjs.org/json-schema/-/json-schema-0.2.3.tgz", - "integrity": "sha1-tIDIkuWaLwWVTOcnvT8qTogvnhM=" - }, "json-schema-traverse": { "version": "0.4.1", "resolved": "https://registry.npmjs.org/json-schema-traverse/-/json-schema-traverse-0.4.1.tgz", - "integrity": "sha512-xbbCH5dCYU5T8LcEhhuh7HJ88HXuW3qsI3Y0zOZFKfZEHcpWiHU/Jxzk629Brsab/mMiHQti9wMP+845RPe3Vg==" + "integrity": "sha512-xbbCH5dCYU5T8LcEhhuh7HJ88HXuW3qsI3Y0zOZFKfZEHcpWiHU/Jxzk629Brsab/mMiHQti9wMP+845RPe3Vg==", + "dev": true }, "json-stable-stringify-without-jsonify": { "version": "1.0.1", @@ -2349,11 +2210,6 @@ "integrity": "sha1-nbe1lJatPzz+8wp1FC0tkwrXJlE=", "dev": true }, - "json-stringify-safe": { - "version": "5.0.1", - "resolved": "https://registry.npmjs.org/json-stringify-safe/-/json-stringify-safe-5.0.1.tgz", - "integrity": "sha1-Epai1Y/UXxmg9s4B1lcB4sc1tus=" - }, "json5": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/json5/-/json5-1.0.1.tgz", @@ -2363,17 +2219,6 @@ "minimist": "^1.2.0" } }, - "jsprim": { - "version": "1.4.1", - "resolved": "https://registry.npmjs.org/jsprim/-/jsprim-1.4.1.tgz", - "integrity": "sha1-MT5mvB5cwG5Di8G3SZwuXFastqI=", - "requires": { - "assert-plus": "1.0.0", - "extsprintf": "1.3.0", - "json-schema": "0.2.3", - "verror": "1.10.0" - } - }, "just-extend": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/just-extend/-/just-extend-4.1.0.tgz", @@ -2613,19 +2458,6 @@ "resolved": "https://registry.npmjs.org/mime/-/mime-2.4.6.tgz", "integrity": "sha512-RZKhC3EmpBchfTGBVb8fb+RL2cWyw/32lshnsETttkBAyAUXSGHxbEJWWRXc751DrIxG1q04b8QwMbAwkRPpUA==" }, - "mime-db": { - "version": "1.44.0", - "resolved": "https://registry.npmjs.org/mime-db/-/mime-db-1.44.0.tgz", - "integrity": "sha512-/NOTfLrsPBVeH7YtFPgsVWveuL+4SjjYxaQ1xtM1KMFj7HdxlBlxeyNLzhyJVx7r4rZGJAZ/6lkKCitSc/Nmpg==" - }, - "mime-types": { - "version": "2.1.27", - "resolved": "https://registry.npmjs.org/mime-types/-/mime-types-2.1.27.tgz", - "integrity": "sha512-JIhqnCasI9yD+SsmkquHBxTSEuZdQX5BuQnS2Vc7puQQQ+8yiP5AY5uWhpdv4YL4VM5c6iliiYWPgJ/nJQLp7w==", - "requires": { - "mime-db": "1.44.0" - } - }, "minimatch": { "version": "3.0.4", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.0.4.tgz", @@ -2889,11 +2721,6 @@ "integrity": "sha512-6eZs5Ls3WtCisHWp9S2GUy8dqkpGi4BVSz3GaqiE6ezub0512ESztXUwUB6C6IKbQkY2Pnb/mD4WYojCRwcwLA==", "dev": true }, - "oauth-sign": { - "version": "0.9.0", - "resolved": "https://registry.npmjs.org/oauth-sign/-/oauth-sign-0.9.0.tgz", - "integrity": "sha512-fexhUFFPTGV8ybAtSIGbV6gOkSv8UtRbDBnAyLQw4QPKkgNlsH2ByPGtMUqdWkos6YCRmAqViwgZrJc/mRDzZQ==" - }, "object-inspect": { "version": "1.8.0", "resolved": "https://registry.npmjs.org/object-inspect/-/object-inspect-1.8.0.tgz", @@ -3069,11 +2896,6 @@ "integrity": "sha1-uULm1L3mUwBe9rcTYd74cn0GReA=", "dev": true }, - "performance-now": { - "version": "2.1.0", - "resolved": "https://registry.npmjs.org/performance-now/-/performance-now-2.1.0.tgz", - "integrity": "sha1-Ywn04OX6kT7BxpMHrjZLSzd8nns=" - }, "picomatch": { "version": "2.2.2", "resolved": "https://registry.npmjs.org/picomatch/-/picomatch-2.2.2.tgz", @@ -3760,11 +3582,6 @@ "long": "^4.0.0" } }, - "psl": { - "version": "1.8.0", - "resolved": "https://registry.npmjs.org/psl/-/psl-1.8.0.tgz", - "integrity": "sha512-RIdOzyoavK+hA18OGGWDqUTsCLhtA7IcZ/6NCs4fFJaHBDab+pDDmDIByWFRQJq2Cd7r1OoQxBGKOaztq+hjIQ==" - }, "pump": { "version": "3.0.0", "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", @@ -3810,12 +3627,8 @@ "punycode": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.1.1.tgz", - "integrity": "sha512-XRsRjdf+j5ml+y/6GKHPZbrF/8p2Yga0JPtdqTIY2Xe5ohJPD9saDJJLPvp9+NSBprVvevdXZybnj2cv8OEd0A==" - }, - "qs": { - "version": "6.5.2", - "resolved": "https://registry.npmjs.org/qs/-/qs-6.5.2.tgz", - "integrity": "sha512-N5ZAX4/LxJmF+7wN74pUD6qAh9/wnvdQcjq9TZjevvXzSUo7bfmw91saqMjzGS2xq91/odN2dW/WOl7qQHNDGA==" + "integrity": "sha512-XRsRjdf+j5ml+y/6GKHPZbrF/8p2Yga0JPtdqTIY2Xe5ohJPD9saDJJLPvp9+NSBprVvevdXZybnj2cv8OEd0A==", + "dev": true }, "quick-lru": { "version": "4.0.1", @@ -3898,40 +3711,6 @@ "integrity": "sha512-lv0M6+TkDVniA3aD1Eg0DVpfU/booSu7Eev3TDO/mZKHBfVjgCGTV4t4buppESEYDtkArYFOxTJWv6S5C+iaNw==", "dev": true }, - "request": { - "version": "2.88.2", - "resolved": "https://registry.npmjs.org/request/-/request-2.88.2.tgz", - "integrity": "sha512-MsvtOrfG9ZcrOwAW+Qi+F6HbD0CWXEh9ou77uOb7FM2WPhwT7smM833PzanhJLsgXjN89Ir6V2PczXNnMpwKhw==", - "requires": { - "aws-sign2": "~0.7.0", - "aws4": "^1.8.0", - "caseless": "~0.12.0", - "combined-stream": "~1.0.6", - "extend": "~3.0.2", - "forever-agent": "~0.6.1", - "form-data": "~2.3.2", - "har-validator": "~5.1.3", - "http-signature": "~1.2.0", - "is-typedarray": "~1.0.0", - "isstream": "~0.1.2", - "json-stringify-safe": "~5.0.1", - "mime-types": "~2.1.19", - "oauth-sign": "~0.9.0", - "performance-now": "^2.1.0", - "qs": "~6.5.2", - "safe-buffer": "^5.1.2", - "tough-cookie": "~2.5.0", - "tunnel-agent": "^0.6.0", - "uuid": "^3.3.2" - }, - "dependencies": { - "uuid": { - "version": "3.4.0", - "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.4.0.tgz", - "integrity": "sha512-HjSDRw6gZE5JMggctHBcjVak08+KEVhSIiDzFnT9S9aegmp85S/bReBVTb4QTFaRNptJ9kuYaNhnbNEOkbKb/A==" - } - } - }, "require-directory": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/require-directory/-/require-directory-2.1.1.tgz", @@ -4018,7 +3797,8 @@ "safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", - "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==" + "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", + "dev": true }, "sandboxed-module": { "version": "2.0.4", @@ -4185,22 +3965,6 @@ "integrity": "sha1-BOaSb2YolTVPPdAVIDYzuFcpfiw=", "dev": true }, - "sshpk": { - "version": "1.16.1", - "resolved": "https://registry.npmjs.org/sshpk/-/sshpk-1.16.1.tgz", - "integrity": "sha512-HXXqVUq7+pcKeLqqZj6mHFUMvXtOJt1uoUx09pFW6011inTMxqI8BA8PM95myrIyyKwdnzjdFjLiE6KBPVtJIg==", - "requires": { - "asn1": "~0.2.3", - "assert-plus": "^1.0.0", - "bcrypt-pbkdf": "^1.0.0", - "dashdash": "^1.12.0", - "ecc-jsbn": "~0.1.1", - "getpass": "^0.1.1", - "jsbn": "~0.1.0", - "safer-buffer": "^2.0.2", - "tweetnacl": "~0.14.0" - } - }, "stack-trace": { "version": "0.0.10", "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz", @@ -4404,15 +4168,6 @@ "to-no-case": "^1.0.0" } }, - "tough-cookie": { - "version": "2.5.0", - "resolved": "https://registry.npmjs.org/tough-cookie/-/tough-cookie-2.5.0.tgz", - "integrity": "sha512-nlLsUzgm1kfLXSXfRZMc1KLAugd4hqJHDTvc2hDIwS3mZAfMEuMbc03SujMF+GEcpaX/qboeycw6iO8JwVv2+g==", - "requires": { - "psl": "^1.1.28", - "punycode": "^2.1.1" - } - }, "tsconfig-paths": { "version": "3.9.0", "resolved": "https://registry.npmjs.org/tsconfig-paths/-/tsconfig-paths-3.9.0.tgz", @@ -4431,19 +4186,6 @@ "integrity": "sha512-i/6DQjL8Xf3be4K/E6Wgpekn5Qasl1usyw++dAA35Ue5orEn65VIxOA+YvNNl9HV3qv70T7CNwjODHZrLwvd1Q==", "dev": true }, - "tunnel-agent": { - "version": "0.6.0", - "resolved": "https://registry.npmjs.org/tunnel-agent/-/tunnel-agent-0.6.0.tgz", - "integrity": "sha1-J6XeoGs2sEoKmWZ3SykIaPD8QP0=", - "requires": { - "safe-buffer": "^5.0.1" - } - }, - "tweetnacl": { - "version": "0.14.5", - "resolved": "https://registry.npmjs.org/tweetnacl/-/tweetnacl-0.14.5.tgz", - "integrity": "sha1-WuaBd/GS1EViadEIr6k/+HQ/T2Q=" - }, "type-check": { "version": "0.3.2", "resolved": "https://registry.npmjs.org/type-check/-/type-check-0.3.2.tgz", @@ -4474,6 +4216,7 @@ "version": "4.2.2", "resolved": "https://registry.npmjs.org/uri-js/-/uri-js-4.2.2.tgz", "integrity": "sha512-KY9Frmirql91X2Qgjry0Wd4Y+YTdrdZheS8TFwvkbLWf/G5KNJDCh6pKL5OZctEW4+0Baa5idK2ZQuELRwPznQ==", + "dev": true, "requires": { "punycode": "^2.1.0" } @@ -4504,16 +4247,6 @@ "spdx-expression-parse": "^3.0.0" } }, - "verror": { - "version": "1.10.0", - "resolved": "https://registry.npmjs.org/verror/-/verror-1.10.0.tgz", - "integrity": "sha1-OhBcoXBTr1XW4nDB+CiGguGNpAA=", - "requires": { - "assert-plus": "^1.0.0", - "core-util-is": "1.0.2", - "extsprintf": "^1.2.0" - } - }, "vue-eslint-parser": { "version": "2.0.3", "resolved": "https://registry.npmjs.org/vue-eslint-parser/-/vue-eslint-parser-2.0.3.tgz", diff --git a/libraries/logger/package.json b/libraries/logger/package.json index 9e1189b363..a94381f849 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -18,8 +18,8 @@ "@google-cloud/logging-bunyan": "^3.0.0", "@overleaf/o-error": "^3.0.0", "bunyan": "^1.8.14", + "node-fetch": "^2.6.0", "raven": "^2.6.4", - "request": "^2.88.2", "yn": "^4.0.0" }, "devDependencies": { diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index b1a915f283..3a143c3eed 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -29,6 +29,9 @@ describe('LoggingManager', function () { captureException: this.captureException, once: sinon.stub().yields() } + this.fetchResponse = { + text: sinon.stub().resolves('') + } this.Bunyan = { createLogger: sinon.stub().returns(this.bunyanLogger), RingBuffer: bunyan.RingBuffer, @@ -40,7 +43,9 @@ describe('LoggingManager', function () { this.Raven = { Client: sinon.stub().returns(this.ravenClient) } - this.Request = sinon.stub() + this.Fetch = { + fetch: sinon.stub().resolves(this.fetchResponse) + } this.Fs = { readFile: sinon.stub(), access: sinon.stub() @@ -57,7 +62,7 @@ describe('LoggingManager', function () { requires: { bunyan: this.Bunyan, raven: this.Raven, - request: this.Request, + 'node-fetch': this.Fetch, fs: this.Fs, '@google-cloud/logging-bunyan': this.GCPLogging } @@ -385,10 +390,10 @@ describe('LoggingManager', function () { const options = { headers: { 'Metadata-Flavor': 'Google' - }, - uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + } } - this.Request.should.have.been.calledWithMatch(options) + const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + this.Fetch.fetch.should.have.been.calledWithMatch(uri,options) }) describe('when request has error', function() { @@ -448,7 +453,13 @@ describe('LoggingManager', function () { describe('when level is not already set', function() { beforeEach(function() { this.bunyanLogger.level.returns(20) - this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + //this.fetchResponse = sinon.stub().resolves + + + //{data: this.start + 1000, status: 200} this.logger.checkLogLevel() }) From 14bac3922210f04e9d578800b5dce32b8782fcba Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Wed, 8 Jul 2020 11:22:54 +0100 Subject: [PATCH 03/22] Add MOCHA_GREP for testing --- libraries/logger/package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/logger/package.json b/libraries/logger/package.json index a94381f849..f2947379a7 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -9,7 +9,7 @@ "license": "AGPL-3.0-only", "version": "2.1.1", "scripts": { - "test": "mocha test/**/*.js", + "test": "mocha --grep=$MOCHA_GREP test/**/*.js", "format": "prettier-eslint $PWD'**/*.js' --list-different", "format:fix": "prettier-eslint $PWD'**/*.js' --write", "lint": "eslint -f unix ." From 6b8dd86a26df28fe8db64f3e34af2ea317f885b8 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Wed, 8 Jul 2020 11:24:56 +0100 Subject: [PATCH 04/22] WIP --- libraries/logger/logging-manager.js | 5 +++++ libraries/logger/test/unit/loggingManagerTests.js | 11 ++++++++--- 2 files changed, 13 insertions(+), 3 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 34bc08cd6d..7f61360d5f 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -64,12 +64,17 @@ const Logger = (module.exports = { } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` fetch.fetch(uri,options).then(res => res.text()).then(body => { + console.log("About to parse Int", body) if (parseInt(body) > Date.now()) { + console.log("About to set logger level to trace") + console.log(this.logger) this.logger.level('trace') } else { + console.log("About to set logger level to default") this.logger.level(this.defaultLevel) } }).catch(err => { + console.log("ERROR: About to set logger level to default") this.logger.level(this.defaultLevel) return }) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 3a143c3eed..d822432028 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -30,7 +30,9 @@ describe('LoggingManager', function () { once: sinon.stub().yields() } this.fetchResponse = { - text: sinon.stub().resolves('') + text: sinon.stub().resolves(''), + status: 200, + ok: true } this.Bunyan = { createLogger: sinon.stub().returns(this.bunyanLogger), @@ -439,11 +441,14 @@ describe('LoggingManager', function () { describe('when level is already set', function() { beforeEach(function() { this.bunyanLogger.level.returns(10) - this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + console.log("In test ", this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) this.logger.checkLogLevel() }) - it('should set trace level', function() { + it.only('should set trace level', function() { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'trace' ) From 6961f4148843693963c0a90907a7f6844cdf9419 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Mon, 20 Jul 2020 16:57:43 +0100 Subject: [PATCH 05/22] Promisfy log level checks --- libraries/logger/logging-manager.js | 61 ++++++++++--------- .../logger/test/unit/loggingManagerTests.js | 20 +++--- 2 files changed, 44 insertions(+), 37 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 7f61360d5f..16c0154955 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,6 +22,7 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { + this.useMetadata = (process.env.USE_METADATA || '').toLowerCase() === 'true' this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' this.defaultLevel = @@ -42,52 +43,54 @@ const Logger = (module.exports = { return this }, - checkLogLevelFile() { - fs.readFile('/logging/tracingEndTime', (error, end) => { - if (error || !end) { - this.logger.level(this.defaultLevel) - return - } - if (parseInt(end) > Date.now()) { + async checkLogLevelFile() { + try { + const end = await fs.promises.readFile('/logging/tracingEndTime') + if (!end) throw new Error("No end time found") + if (parseInt(end,10) > Date.now()) { this.logger.level('trace') } else { this.logger.level(this.defaultLevel) } - }) + } catch (err) { + this.logger.level(this.defaultLevel) + return + } }, - checkLogLevelMetadata() { +async checkLogLevelMetadata() { const options = { headers: { 'Metadata-Flavor': 'Google' } } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - fetch.fetch(uri,options).then(res => res.text()).then(body => { - console.log("About to parse Int", body) - if (parseInt(body) > Date.now()) { - console.log("About to set logger level to trace") - console.log(this.logger) - this.logger.level('trace') - } else { - console.log("About to set logger level to default") - this.logger.level(this.defaultLevel) - } - }).catch(err => { + try { + const res = await fetch(uri,options) + if (!res.ok) throw new Error("Metadata not okay") + const body = await res.text() + console.log("About to parse Int", body) + if (parseInt(body) > Date.now()) { + console.log("About to set logger level to trace") + console.log(this.logger) + this.logger.level('trace') + } else { + console.log("About to set logger level to default") + this.logger.level(this.defaultLevel) + } + } catch (err) { console.log("ERROR: About to set logger level to default") this.logger.level(this.defaultLevel) return - }) + } }, - checkLogLevel() { - fs.access('/logging', (err) => { - if (err) { - this.checkLogLevelMetadata() - } else { - this.checkLogLevelFile() - } - }) + async checkLogLevel() { + if (this.useMetadata) { + await this.checkLogLevelMetadata() + } else { + await this.checkLogLevelFile() + } }, initializeErrorReporting(sentryDsn, options) { diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index d822432028..505928a9cb 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -45,9 +45,7 @@ describe('LoggingManager', function () { this.Raven = { Client: sinon.stub().returns(this.ravenClient) } - this.Fetch = { - fetch: sinon.stub().resolves(this.fetchResponse) - } + this.Fetch = sinon.stub().resolves(this.fetchResponse) this.Fs = { readFile: sinon.stub(), access: sinon.stub() @@ -381,9 +379,14 @@ describe('LoggingManager', function () { }) }) - describe('when /logging does not exist', function () { + describe('when not running in GKE', function () { beforeEach(function () { - this.Fs.access.yields(new Error) + process.env.USE_METADATA = 'TRUE' + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + afterEach(function() { + process.env.USE_METADATA = undefined }) describe('checkLogLevel', function() { @@ -439,13 +442,14 @@ describe('LoggingManager', function () { describe('when time value returned that is more than current time', function() { describe('when level is already set', function() { - beforeEach(function() { + beforeEach(async function() { this.bunyanLogger.level.returns(10) //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) console.log("In test ", this.start + 1000) this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) - this.logger.checkLogLevel() + //this.Fetch = sinon.stub().resolves(this.fetchResponse) + + await this.logger.checkLogLevel() }) it.only('should set trace level', function() { From 02356c7f27b1cec8aa38c29bb133bd79d6af3abc Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 23 Jul 2020 17:03:55 +0100 Subject: [PATCH 06/22] All logging manager tests working --- .../logger/test/unit/loggingManagerTests.js | 69 ++++++++++--------- 1 file changed, 35 insertions(+), 34 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 505928a9cb..39ab807fac 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -4,6 +4,8 @@ const chai = require('chai') const path = require('path') const sinon = require('sinon') const sinonChai = require('sinon-chai') +const { promises } = require('dns') +//const fetchMock = require('fetch-mock') chai.use(sinonChai) chai.should() @@ -48,7 +50,10 @@ describe('LoggingManager', function () { this.Fetch = sinon.stub().resolves(this.fetchResponse) this.Fs = { readFile: sinon.stub(), - access: sinon.stub() + access: sinon.stub(), + promises: { + readFile: sinon.stub() + } } this.stackdriverStreamConfig = { stream: 'stackdriver' } this.stackdriverClient = { @@ -296,24 +301,17 @@ describe('LoggingManager', function () { }) describe('checkLogLevel', function () { - beforeEach(function () { - this.Fs.access.yields(null) - }) - - it('should request log level override from the config map', function () { - this.logger.checkLogLevel() - this.Fs.access.should.have.been.calledWithMatch( - '/logging' - ) - this.Fs.readFile.should.have.been.calledWithMatch( + it('should request log level override from the config map', async function () { + await this.logger.checkLogLevel() + this.Fs.promises.readFile.should.have.been.calledWithMatch( '/logging/tracingEndTime' ) }) describe('when read errors', function () { beforeEach(function () { - this.Fs.readFile.yields(new Error('error')) + this.Fs.promises.readFile.yields(new Error('error')) this.logger.checkLogLevel() }) @@ -326,7 +324,7 @@ describe('LoggingManager', function () { describe('when the file is empty', function () { beforeEach(function () { - this.Fs.readFile.yields(null, '') + this.Fs.promises.readFile.yields(null, '') this.logger.checkLogLevel() }) @@ -339,7 +337,7 @@ describe('LoggingManager', function () { describe('when time value returned that is less than current time', function () { beforeEach(function () { - this.Fs.readFile.yields(null, '1') + this.Fs.promises.readFile.yields(null, '1') this.logger.checkLogLevel() }) @@ -352,10 +350,10 @@ describe('LoggingManager', function () { describe('when time value returned that is more than current time', function () { describe('when level is already set', function () { - beforeEach(function () { + beforeEach(async function () { this.bunyanLogger.level.returns(10) - this.Fs.readFile.yields(null, (this.start + 1000).toString()) - this.logger.checkLogLevel() + this.Fs.promises.readFile.returns((this.start + 1000).toString()) + await this.logger.checkLogLevel() }) it('should set trace level', function () { @@ -366,10 +364,10 @@ describe('LoggingManager', function () { }) describe('when level is not already set', function () { - beforeEach(function () { + beforeEach(async function () { this.bunyanLogger.level.returns(20) - this.Fs.readFile.yields(null, (this.start + 1000).toString()) - this.logger.checkLogLevel() + this.Fs.promises.readFile.returns((this.start + 1000).toString()) + await this.logger.checkLogLevel() }) it('should set trace level', function () { @@ -379,7 +377,7 @@ describe('LoggingManager', function () { }) }) - describe('when not running in GKE', function () { + describe('when using metadata', function () { beforeEach(function () { process.env.USE_METADATA = 'TRUE' this.logger = this.LoggingManager.initialize(this.loggerName) @@ -398,13 +396,14 @@ describe('LoggingManager', function () { } } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - this.Fetch.fetch.should.have.been.calledWithMatch(uri,options) + this.Fetch.should.have.been.calledWithMatch(uri,options) }) describe('when request has error', function() { - beforeEach(function() { - this.Request.yields('error') - this.logger.checkLogLevel() + beforeEach(async function() { + this.Fetch = sinon.stub().throws() + //this.Request.yields('error') + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -415,9 +414,10 @@ describe('LoggingManager', function () { }) describe('when statusCode is not 200', function() { - beforeEach(function() { - this.Request.yields(null, { statusCode: 404 }) - this.logger.checkLogLevel() + beforeEach(async function() { + this.fetchResponse.status = 404 + //this.Request.yields(null, { statusCode: 404 }) + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -428,9 +428,10 @@ describe('LoggingManager', function () { }) describe('when time value returned that is less than current time', function() { - beforeEach(function() { - this.Request.yields(null, { statusCode: 200 }, '1') - this.logger.checkLogLevel() + beforeEach(async function() { + //this.Request.yields(null, { statusCode: 200 }, '1') + this.fetchResponse.text = sinon.stub().resolves('1') + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -452,7 +453,7 @@ describe('LoggingManager', function () { await this.logger.checkLogLevel() }) - it.only('should set trace level', function() { + it('should set trace level', function() { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'trace' ) @@ -460,7 +461,7 @@ describe('LoggingManager', function () { }) describe('when level is not already set', function() { - beforeEach(function() { + beforeEach(async function() { this.bunyanLogger.level.returns(20) this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) @@ -469,7 +470,7 @@ describe('LoggingManager', function () { //{data: this.start + 1000, status: 200} - this.logger.checkLogLevel() + await this.logger.checkLogLevel() }) it('should set trace level', function() { From 0a15fedb34a6f561ff501781d9cd6c3e78f63730 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 23 Jul 2020 17:10:09 +0100 Subject: [PATCH 07/22] Remove debug logs --- libraries/logger/logging-manager.js | 5 ----- libraries/logger/test/unit/loggingManagerTests.js | 1 - 2 files changed, 6 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 16c0154955..14e7cb2c35 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -69,17 +69,12 @@ async checkLogLevelMetadata() { const res = await fetch(uri,options) if (!res.ok) throw new Error("Metadata not okay") const body = await res.text() - console.log("About to parse Int", body) if (parseInt(body) > Date.now()) { - console.log("About to set logger level to trace") - console.log(this.logger) this.logger.level('trace') } else { - console.log("About to set logger level to default") this.logger.level(this.defaultLevel) } } catch (err) { - console.log("ERROR: About to set logger level to default") this.logger.level(this.defaultLevel) return } diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 39ab807fac..f9532875ea 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -446,7 +446,6 @@ describe('LoggingManager', function () { beforeEach(async function() { this.bunyanLogger.level.returns(10) //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - console.log("In test ", this.start + 1000) this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) //this.Fetch = sinon.stub().resolves(this.fetchResponse) From 6bc0d15d78ae4bff064656a50138a46c3f49b51d Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Fri, 24 Jul 2020 11:59:23 +0100 Subject: [PATCH 08/22] LOG_LEVEL_SOURCE env taking values file, gce_metadata or none, default file --- libraries/logger/logging-manager.js | 27 +- .../logger/test/unit/loggingManagerTests.js | 279 ++++++++++-------- 2 files changed, 170 insertions(+), 136 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 14e7cb2c35..4b384df0f1 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,7 +22,7 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { - this.useMetadata = (process.env.USE_METADATA || '').toLowerCase() === 'true' + this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase() this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' this.defaultLevel = @@ -80,14 +80,6 @@ async checkLogLevelMetadata() { } }, - async checkLogLevel() { - if (this.useMetadata) { - await this.checkLogLevelMetadata() - } else { - await this.checkLogLevelFile() - } - }, - initializeErrorReporting(sentryDsn, options) { const raven = require('raven') this.raven = new raven.Client(sentryDsn, options) @@ -274,10 +266,19 @@ async checkLogLevelMetadata() { if (this.checkInterval) { clearInterval(this.checkInterval) } - // check for log level override on startup - this.checkLogLevel() - // re-check log level every minute - this.checkInterval = setInterval(this.checkLogLevel.bind(this), 1000 * 60) + if (this.logLevelSource === 'file') { + // check for log level override on startup + this.checkLogLevelFile() + // re-check log level every minute + this.checkInterval = setInterval(this.checkLogLevelFile.bind(this), 1000 * 60) + } else if (this.logLevelSource === 'gce_metadata') { + // check for log level override on startup + this.checkLogLevelMetadata() + // re-check log level every minute + this.checkInterval = setInterval(this.checkLogLevelMetadata.bind(this), 1000 * 60) + } else if (this.logLevelSource !== 'none') { + console.log('Unrecognised log level source') + } } } }) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index f9532875ea..ee13dbc56d 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -83,12 +83,14 @@ describe('LoggingManager', function () { describe('initialize', function () { beforeEach(function () { - this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel') + this.checkLogLevelFileStub = sinon.stub(this.LoggingManager, 'checkLogLevelFile') + this.checkLogLevelMetadataStub = sinon.stub(this.LoggingManager, 'checkLogLevelMetadata') this.Bunyan.createLogger.reset() }) afterEach(function () { - this.checkLogLevelStub.restore() + this.checkLogLevelFileStub.restore() + this.checkLogLevelMetadataStub.restore() }) describe('not in production', function () { @@ -103,41 +105,76 @@ describe('LoggingManager', function () { }) it('should not run checkLogLevel', function () { - this.checkLogLevelStub.should.not.have.been.called + this.checkLogLevelFileStub.should.not.have.been.called + this.checkLogLevelMetadataStub.should.not.have.been.called }) }) describe('in production', function () { beforeEach(function () { process.env.NODE_ENV = 'production' - this.logger = this.LoggingManager.initialize(this.loggerName) }) afterEach(() => delete process.env.NODE_ENV) it('should default to log level warn', function () { + this.logger = this.LoggingManager.initialize(this.loggerName) this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( 'warn' ) }) - it('should run checkLogLevel', function () { - this.checkLogLevelStub.should.have.been.calledOnce + describe('logLevelSource file', function () { + beforeEach(function() { + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + it('should run checkLogLevel', function () { + this.checkLogLevelFileStub.should.have.been.calledOnce + }) + + describe('after 1 minute', () => + it('should run checkLogLevel again', function () { + this.clock.tick(61 * 1000) + this.checkLogLevelFileStub.should.have.been.calledTwice + })) + + describe('after 2 minutes', () => + it('should run checkLogLevel again', function () { + this.clock.tick(121 * 1000) + this.checkLogLevelFileStub.should.have.been.calledThrice + })) }) - describe('after 1 minute', () => - it('should run checkLogLevel again', function () { - this.clock.tick(61 * 1000) - this.checkLogLevelStub.should.have.been.calledTwice - })) + describe('logLevelSource gce_metadata', function () { + beforeEach(function () { + process.env.LOG_LEVEL_SOURCE = 'gce_metadata' + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + afterEach(() => delete process.env.LOG_LEVEL_SOURCE) + + it('should run checkLogLevel', function () { + this.checkLogLevelMetadataStub.should.have.been.calledOnce + }) + + describe('after 1 minute', () => + it('should run checkLogLevel again', function () { + this.clock.tick(61 * 1000) + this.checkLogLevelMetadataStub.should.have.been.calledTwice + })) + + describe('after 2 minutes', () => + it('should run checkLogLevel again', function () { + this.clock.tick(121 * 1000) + this.checkLogLevelMetadataStub.should.have.been.calledThrice + })) + }) - describe('after 2 minutes', () => - it('should run checkLogLevel again', function () { - this.clock.tick(121 * 1000) - this.checkLogLevelStub.should.have.been.calledThrice - })) }) + + describe('when LOG_LEVEL set in env', function () { beforeEach(function () { process.env.LOG_LEVEL = 'trace' @@ -300,10 +337,10 @@ describe('LoggingManager', function () { }) }) - describe('checkLogLevel', function () { + describe('checkLogLevelFile', function () { it('should request log level override from the config map', async function () { - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() this.Fs.promises.readFile.should.have.been.calledWithMatch( '/logging/tracingEndTime' ) @@ -312,7 +349,7 @@ describe('LoggingManager', function () { describe('when read errors', function () { beforeEach(function () { this.Fs.promises.readFile.yields(new Error('error')) - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -325,7 +362,7 @@ describe('LoggingManager', function () { describe('when the file is empty', function () { beforeEach(function () { this.Fs.promises.readFile.yields(null, '') - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -338,7 +375,7 @@ describe('LoggingManager', function () { describe('when time value returned that is less than current time', function () { beforeEach(function () { this.Fs.promises.readFile.yields(null, '1') - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -353,7 +390,7 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(10) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() }) it('should set trace level', function () { @@ -367,7 +404,7 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(20) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() }) it('should set trace level', function () { @@ -376,118 +413,114 @@ describe('LoggingManager', function () { ) }) }) + }) + }) - describe('when using metadata', function () { - beforeEach(function () { - process.env.USE_METADATA = 'TRUE' - this.logger = this.LoggingManager.initialize(this.loggerName) +describe('checkLogLevelMetadata', function () { + beforeEach(function () { + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + describe('checkLogLevel', function() { + it('should request log level override from google meta data service', function() { + this.logger.checkLogLevelMetadata() + const options = { + headers: { + 'Metadata-Flavor': 'Google' + } + } + const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + this.Fetch.should.have.been.calledWithMatch(uri,options) + }) + + describe('when request has error', function() { + beforeEach(async function() { + this.Fetch = sinon.stub().throws() + //this.Request.yields('error') + await this.logger.checkLogLevelMetadata() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when statusCode is not 200', function() { + beforeEach(async function() { + this.fetchResponse.status = 404 + //this.Request.yields(null, { statusCode: 404 }) + await this.logger.checkLogLevelMetadata() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when time value returned that is less than current time', function() { + beforeEach(async function() { + //this.Request.yields(null, { statusCode: 200 }, '1') + this.fetchResponse.text = sinon.stub().resolves('1') + await this.logger.checkLogLevelMetadata() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when time value returned that is more than current time', function() { + describe('when level is already set', function() { + beforeEach(async function() { + this.bunyanLogger.level.returns(10) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + //this.Fetch = sinon.stub().resolves(this.fetchResponse) + + await this.logger.checkLogLevelMetadata() }) - afterEach(function() { - process.env.USE_METADATA = undefined + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) + }) + }) + + describe('when level is not already set', function() { + beforeEach(async function() { + this.bunyanLogger.level.returns(20) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + //this.fetchResponse = sinon.stub().resolves + + + //{data: this.start + 1000, status: 200} + await this.logger.checkLogLevelMetadata() }) - describe('checkLogLevel', function() { - it('should request log level override from google meta data service', function() { - this.logger.checkLogLevel() - const options = { - headers: { - 'Metadata-Flavor': 'Google' - } - } - const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - this.Fetch.should.have.been.calledWithMatch(uri,options) - }) - - describe('when request has error', function() { - beforeEach(async function() { - this.Fetch = sinon.stub().throws() - //this.Request.yields('error') - await this.logger.checkLogLevel() - }) - - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when statusCode is not 200', function() { - beforeEach(async function() { - this.fetchResponse.status = 404 - //this.Request.yields(null, { statusCode: 404 }) - await this.logger.checkLogLevel() - }) - - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when time value returned that is less than current time', function() { - beforeEach(async function() { - //this.Request.yields(null, { statusCode: 200 }, '1') - this.fetchResponse.text = sinon.stub().resolves('1') - await this.logger.checkLogLevel() - }) - - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when time value returned that is more than current time', function() { - describe('when level is already set', function() { - beforeEach(async function() { - this.bunyanLogger.level.returns(10) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - //this.Fetch = sinon.stub().resolves(this.fetchResponse) - - await this.logger.checkLogLevel() - }) - - it('should set trace level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'trace' - ) - }) - }) - - describe('when level is not already set', function() { - beforeEach(async function() { - this.bunyanLogger.level.returns(20) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - //this.fetchResponse = sinon.stub().resolves - - - //{data: this.start + 1000, status: 200} - await this.logger.checkLogLevel() - }) - - it('should set trace level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'trace' - ) - }) - }) - }) + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) }) + }) + }) + }) - }) - }) + }) describe('ringbuffer', function () { From d42bd2da50d07a2d7fb08c3917ddb1ff8e2ed7ca Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Fri, 24 Jul 2020 12:17:31 +0100 Subject: [PATCH 09/22] Tidy up --- .../logger/test/unit/loggingManagerTests.js | 163 ++++++++---------- 1 file changed, 76 insertions(+), 87 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index ee13dbc56d..b525114bad 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -5,7 +5,6 @@ const path = require('path') const sinon = require('sinon') const sinonChai = require('sinon-chai') const { promises } = require('dns') -//const fetchMock = require('fetch-mock') chai.use(sinonChai) chai.should() @@ -50,7 +49,6 @@ describe('LoggingManager', function () { this.Fetch = sinon.stub().resolves(this.fetchResponse) this.Fs = { readFile: sinon.stub(), - access: sinon.stub(), promises: { readFile: sinon.stub() } @@ -173,8 +171,6 @@ describe('LoggingManager', function () { }) - - describe('when LOG_LEVEL set in env', function () { beforeEach(function () { process.env.LOG_LEVEL = 'trace' @@ -416,113 +412,106 @@ describe('LoggingManager', function () { }) }) -describe('checkLogLevelMetadata', function () { - beforeEach(function () { - this.logger = this.LoggingManager.initialize(this.loggerName) - }) - - describe('checkLogLevel', function() { - it('should request log level override from google meta data service', function() { - this.logger.checkLogLevelMetadata() - const options = { - headers: { - 'Metadata-Flavor': 'Google' - } - } - const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - this.Fetch.should.have.been.calledWithMatch(uri,options) + describe('checkLogLevelMetadata', function () { + beforeEach(function () { + this.logger = this.LoggingManager.initialize(this.loggerName) }) - describe('when request has error', function() { - beforeEach(async function() { - this.Fetch = sinon.stub().throws() - //this.Request.yields('error') - await this.logger.checkLogLevelMetadata() + describe('checkLogLevel', function() { + it('should request log level override from google meta data service', function() { + this.logger.checkLogLevelMetadata() + const options = { + headers: { + 'Metadata-Flavor': 'Google' + } + } + const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + this.Fetch.should.have.been.calledWithMatch(uri,options) }) - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when statusCode is not 200', function() { - beforeEach(async function() { - this.fetchResponse.status = 404 - //this.Request.yields(null, { statusCode: 404 }) - await this.logger.checkLogLevelMetadata() - }) - - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when time value returned that is less than current time', function() { - beforeEach(async function() { - //this.Request.yields(null, { statusCode: 200 }, '1') - this.fetchResponse.text = sinon.stub().resolves('1') - await this.logger.checkLogLevelMetadata() - }) - - it('should only set default level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'debug' - ) - }) - }) - - describe('when time value returned that is more than current time', function() { - describe('when level is already set', function() { + describe('when request has error', function() { beforeEach(async function() { - this.bunyanLogger.level.returns(10) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - //this.Fetch = sinon.stub().resolves(this.fetchResponse) - + this.Fetch = sinon.stub().throws() + //this.Request.yields('error') await this.logger.checkLogLevelMetadata() }) - it('should set trace level', function() { + it('should only set default level', function() { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'trace' + 'debug' ) }) }) - describe('when level is not already set', function() { + describe('when statusCode is not 200', function() { beforeEach(async function() { - this.bunyanLogger.level.returns(20) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - //this.fetchResponse = sinon.stub().resolves - - - //{data: this.start + 1000, status: 200} + this.fetchResponse.status = 404 + //this.Request.yields(null, { statusCode: 404 }) await this.logger.checkLogLevelMetadata() }) - it('should set trace level', function() { + it('should only set default level', function() { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'trace' + 'debug' ) }) }) + + describe('when time value returned that is less than current time', function() { + beforeEach(async function() { + //this.Request.yields(null, { statusCode: 200 }, '1') + this.fetchResponse.text = sinon.stub().resolves('1') + await this.logger.checkLogLevelMetadata() + }) + + it('should only set default level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'debug' + ) + }) + }) + + describe('when time value returned that is more than current time', function() { + describe('when level is already set', function() { + beforeEach(async function() { + this.bunyanLogger.level.returns(10) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + //this.Fetch = sinon.stub().resolves(this.fetchResponse) + + await this.logger.checkLogLevelMetadata() + }) + + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) + }) + }) + + describe('when level is not already set', function() { + beforeEach(async function() { + this.bunyanLogger.level.returns(20) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + //this.fetchResponse = sinon.stub().resolves + + + //{data: this.start + 1000, status: 200} + await this.logger.checkLogLevelMetadata() + }) + + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) + }) + }) + }) }) }) - - - - - - - }) - describe('ringbuffer', function () { beforeEach(function () { this.logBufferMock = [ From 1ca6269aa58a57232a7ceb291e2416038f37bdaf Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Fri, 24 Jul 2020 12:18:33 +0100 Subject: [PATCH 10/22] Bump version to 2.2.0 --- libraries/logger/package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/logger/package.json b/libraries/logger/package.json index f2947379a7..5ab7496e8f 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -7,7 +7,7 @@ "url": "http://github.com/sharelatex/logger-sharelatex.git" }, "license": "AGPL-3.0-only", - "version": "2.1.1", + "version": "2.2.0", "scripts": { "test": "mocha --grep=$MOCHA_GREP test/**/*.js", "format": "prettier-eslint $PWD'**/*.js' --list-different", From 74e2a5eaa1046a6fe4071f7af04ba686b3a2e2d7 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 30 Jul 2020 12:49:54 +0100 Subject: [PATCH 11/22] WIP --- libraries/logger/logging-manager.js | 49 ++++----- .../logger/test/unit/loggingManagerTests.js | 101 ++++++++++-------- 2 files changed, 77 insertions(+), 73 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 4b384df0f1..decdb0b1d5 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -43,41 +43,33 @@ const Logger = (module.exports = { return this }, - async checkLogLevelFile() { + async checkLogLevel() { try { - const end = await fs.promises.readFile('/logging/tracingEndTime') - if (!end) throw new Error("No end time found") - if (parseInt(end,10) > Date.now()) { + const end = await this.getTracingEndTime() + if (parseInt(end, 10) > Date.now()) { this.logger.level('trace') } else { this.logger.level(this.defaultLevel) } } catch (err) { this.logger.level(this.defaultLevel) - return } }, -async checkLogLevelMetadata() { + async getTracingEndTimeFile() { + return fs.promises.readFile('/logging/tracingEndTime') + }, + +async getTracingEndTimeMetadata() { const options = { headers: { 'Metadata-Flavor': 'Google' } } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - try { - const res = await fetch(uri,options) - if (!res.ok) throw new Error("Metadata not okay") - const body = await res.text() - if (parseInt(body) > Date.now()) { - this.logger.level('trace') - } else { - this.logger.level(this.defaultLevel) - } - } catch (err) { - this.logger.level(this.defaultLevel) - return - } + const res = await fetch(uri,options) + if (!res.ok) throw new Error("Metadata not okay") + return res.text() }, initializeErrorReporting(sentryDsn, options) { @@ -267,18 +259,19 @@ async checkLogLevelMetadata() { clearInterval(this.checkInterval) } if (this.logLevelSource === 'file') { - // check for log level override on startup - this.checkLogLevelFile() - // re-check log level every minute - this.checkInterval = setInterval(this.checkLogLevelFile.bind(this), 1000 * 60) + this.getTracingEndTime = this.getTracingEndTimeFile } else if (this.logLevelSource === 'gce_metadata') { - // check for log level override on startup - this.checkLogLevelMetadata() - // re-check log level every minute - this.checkInterval = setInterval(this.checkLogLevelMetadata.bind(this), 1000 * 60) - } else if (this.logLevelSource !== 'none') { + this.getTracingEndTime = this.getTracingEndTimeMetadata + } else if (this.logLevelSource === 'none') { + return + } else { console.log('Unrecognised log level source') + return } + // check for log level override on startup + this.checkLogLevel() + // re-check log level every minute + this.checkInterval = setInterval(this.checkLogLevel.bind(this), 1000 * 60) } } }) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index b525114bad..aafde78d93 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -81,14 +81,14 @@ describe('LoggingManager', function () { describe('initialize', function () { beforeEach(function () { - this.checkLogLevelFileStub = sinon.stub(this.LoggingManager, 'checkLogLevelFile') - this.checkLogLevelMetadataStub = sinon.stub(this.LoggingManager, 'checkLogLevelMetadata') + this.getTracingEndTimeFileStub = sinon.stub(this.LoggingManager, 'getTracingEndTimeFile') + this.getTracingEndTimeMetadataStub = sinon.stub(this.LoggingManager, 'getTracingEndTimeMetadata') this.Bunyan.createLogger.reset() }) afterEach(function () { - this.checkLogLevelFileStub.restore() - this.checkLogLevelMetadataStub.restore() + this.getTracingEndTimeFileStub.restore() + this.getTracingEndTimeMetadataStub.restore() }) describe('not in production', function () { @@ -102,9 +102,9 @@ describe('LoggingManager', function () { ) }) - it('should not run checkLogLevel', function () { - this.checkLogLevelFileStub.should.not.have.been.called - this.checkLogLevelMetadataStub.should.not.have.been.called + it('should not run getTracingEndTime', function () { + this.getTracingEndTimeFileStub.should.not.have.been.called + this.getTracingEndTimeMetadataStub.should.not.have.been.called }) }) @@ -115,32 +115,40 @@ describe('LoggingManager', function () { afterEach(() => delete process.env.NODE_ENV) - it('should default to log level warn', function () { - this.logger = this.LoggingManager.initialize(this.loggerName) - this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( - 'warn' - ) + describe('blah', function () { + beforeEach(function () { + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + it.only('should default to log level warn', function () { + + const level = this.Bunyan.createLogger.firstCall.args[0].streams[0].level + console.log(level) + level.should.equal( + 'warn' + ) + }) }) + describe('logLevelSource file', function () { beforeEach(function() { this.logger = this.LoggingManager.initialize(this.loggerName) }) it('should run checkLogLevel', function () { - this.checkLogLevelFileStub.should.have.been.calledOnce + this.getTracingEndTimeFileStub.should.have.been.calledOnce }) describe('after 1 minute', () => it('should run checkLogLevel again', function () { this.clock.tick(61 * 1000) - this.checkLogLevelFileStub.should.have.been.calledTwice + this.getTracingEndTimeFileStub.should.have.been.calledTwice })) describe('after 2 minutes', () => it('should run checkLogLevel again', function () { this.clock.tick(121 * 1000) - this.checkLogLevelFileStub.should.have.been.calledThrice + this.getTracingEndTimeFileStub.should.have.been.calledThrice })) }) @@ -153,19 +161,19 @@ describe('LoggingManager', function () { afterEach(() => delete process.env.LOG_LEVEL_SOURCE) it('should run checkLogLevel', function () { - this.checkLogLevelMetadataStub.should.have.been.calledOnce + this.getTracingEndTimeMetadataStub.should.have.been.calledOnce }) describe('after 1 minute', () => it('should run checkLogLevel again', function () { this.clock.tick(61 * 1000) - this.checkLogLevelMetadataStub.should.have.been.calledTwice + this.getTracingEndTimeMetadataStub.should.have.been.calledTwice })) describe('after 2 minutes', () => it('should run checkLogLevel again', function () { this.clock.tick(121 * 1000) - this.checkLogLevelMetadataStub.should.have.been.calledThrice + this.getTracingEndTimeMetadataStub.should.have.been.calledThrice })) }) @@ -336,16 +344,18 @@ describe('LoggingManager', function () { describe('checkLogLevelFile', function () { it('should request log level override from the config map', async function () { - await this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() this.Fs.promises.readFile.should.have.been.calledWithMatch( '/logging/tracingEndTime' ) }) describe('when read errors', function () { - beforeEach(function () { + beforeEach(async function () { this.Fs.promises.readFile.yields(new Error('error')) - this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() }) it('should only set default level', function () { @@ -356,9 +366,10 @@ describe('LoggingManager', function () { }) describe('when the file is empty', function () { - beforeEach(function () { + beforeEach(async function () { this.Fs.promises.readFile.yields(null, '') - this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() }) it('should only set default level', function () { @@ -369,9 +380,10 @@ describe('LoggingManager', function () { }) describe('when time value returned that is less than current time', function () { - beforeEach(function () { + beforeEach(async function () { this.Fs.promises.readFile.yields(null, '1') - this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() }) it('should only set default level', function () { @@ -386,7 +398,8 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(10) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() }) it('should set trace level', function () { @@ -400,7 +413,8 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(20) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevelFile() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile + await this.logger.checkLogLevel() }) it('should set trace level', function () { @@ -418,8 +432,9 @@ describe('LoggingManager', function () { }) describe('checkLogLevel', function() { - it('should request log level override from google meta data service', function() { - this.logger.checkLogLevelMetadata() + it('should request log level override from google meta data service', async function() { + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata + await this.logger.checkLogLevel() const options = { headers: { 'Metadata-Flavor': 'Google' @@ -432,8 +447,8 @@ describe('LoggingManager', function () { describe('when request has error', function() { beforeEach(async function() { this.Fetch = sinon.stub().throws() - //this.Request.yields('error') - await this.logger.checkLogLevelMetadata() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -446,8 +461,8 @@ describe('LoggingManager', function () { describe('when statusCode is not 200', function() { beforeEach(async function() { this.fetchResponse.status = 404 - //this.Request.yields(null, { statusCode: 404 }) - await this.logger.checkLogLevelMetadata() + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -459,9 +474,9 @@ describe('LoggingManager', function () { describe('when time value returned that is less than current time', function() { beforeEach(async function() { - //this.Request.yields(null, { statusCode: 200 }, '1') + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata this.fetchResponse.text = sinon.stub().resolves('1') - await this.logger.checkLogLevelMetadata() + await this.logger.checkLogLevel() }) it('should only set default level', function() { @@ -475,11 +490,10 @@ describe('LoggingManager', function () { describe('when level is already set', function() { beforeEach(async function() { this.bunyanLogger.level.returns(10) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - //this.Fetch = sinon.stub().resolves(this.fetchResponse) + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata - await this.logger.checkLogLevelMetadata() + await this.logger.checkLogLevel() }) it('should set trace level', function() { @@ -493,13 +507,10 @@ describe('LoggingManager', function () { beforeEach(async function() { this.bunyanLogger.level.returns(20) this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - //this.fetchResponse = sinon.stub().resolves - - - //{data: this.start + 1000, status: 200} - await this.logger.checkLogLevelMetadata() + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) + this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata + + await this.logger.checkLogLevel() }) it('should set trace level', function() { From 6917847b10ca4621e41eb3044d9e2ac3d1ed687a Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 30 Jul 2020 14:45:49 +0100 Subject: [PATCH 12/22] catch --- libraries/logger/logging-manager.js | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index decdb0b1d5..11c06f2716 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,6 +22,7 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { + console.log("IN INIT") this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase() this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' @@ -39,6 +40,7 @@ const Logger = (module.exports = { }) this._setupRingBuffer() this._setupStackdriver() + console.log(this.logger) this._setupLogLevelChecker() return this }, @@ -52,6 +54,7 @@ const Logger = (module.exports = { this.logger.level(this.defaultLevel) } } catch (err) { + console.log(err) this.logger.level(this.defaultLevel) } }, @@ -253,6 +256,8 @@ async getTracingEndTimeMetadata() { }, _setupLogLevelChecker() { + console.log("In _setupLogLevelChecker") + console.log(this.logger) if (this.isProduction) { // clear interval if already set if (this.checkInterval) { @@ -269,7 +274,9 @@ async getTracingEndTimeMetadata() { return } // check for log level override on startup - this.checkLogLevel() + this.checkLogLevel().catch((error) => { + console.log(error) + }) // re-check log level every minute this.checkInterval = setInterval(this.checkLogLevel.bind(this), 1000 * 60) } From 8376cf1ca256ca957ad8009f4ffcd844d579b24f Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 30 Jul 2020 15:06:32 +0100 Subject: [PATCH 13/22] Get acceptance tests working --- .../logger/test/unit/loggingManagerTests.js | 42 ++++--------------- 1 file changed, 7 insertions(+), 35 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index aafde78d93..ee918a507d 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -81,14 +81,12 @@ describe('LoggingManager', function () { describe('initialize', function () { beforeEach(function () { - this.getTracingEndTimeFileStub = sinon.stub(this.LoggingManager, 'getTracingEndTimeFile') - this.getTracingEndTimeMetadataStub = sinon.stub(this.LoggingManager, 'getTracingEndTimeMetadata') + this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel').resolves('') this.Bunyan.createLogger.reset() }) afterEach(function () { - this.getTracingEndTimeFileStub.restore() - this.getTracingEndTimeMetadataStub.restore() + this.checkLogLevelStub.restore() }) describe('not in production', function () { @@ -103,8 +101,7 @@ describe('LoggingManager', function () { }) it('should not run getTracingEndTime', function () { - this.getTracingEndTimeFileStub.should.not.have.been.called - this.getTracingEndTimeMetadataStub.should.not.have.been.called + this.checkLogLevelStub.should.not.have.been.called }) }) @@ -119,7 +116,7 @@ describe('LoggingManager', function () { beforeEach(function () { this.logger = this.LoggingManager.initialize(this.loggerName) }) - it.only('should default to log level warn', function () { + it('should default to log level warn', function () { const level = this.Bunyan.createLogger.firstCall.args[0].streams[0].level console.log(level) @@ -136,44 +133,19 @@ describe('LoggingManager', function () { }) it('should run checkLogLevel', function () { - this.getTracingEndTimeFileStub.should.have.been.calledOnce + this.checkLogLevelStub.should.have.been.calledOnce }) describe('after 1 minute', () => it('should run checkLogLevel again', function () { this.clock.tick(61 * 1000) - this.getTracingEndTimeFileStub.should.have.been.calledTwice + this.checkLogLevelStub.should.have.been.calledTwice })) describe('after 2 minutes', () => it('should run checkLogLevel again', function () { this.clock.tick(121 * 1000) - this.getTracingEndTimeFileStub.should.have.been.calledThrice - })) - }) - - describe('logLevelSource gce_metadata', function () { - beforeEach(function () { - process.env.LOG_LEVEL_SOURCE = 'gce_metadata' - this.logger = this.LoggingManager.initialize(this.loggerName) - }) - - afterEach(() => delete process.env.LOG_LEVEL_SOURCE) - - it('should run checkLogLevel', function () { - this.getTracingEndTimeMetadataStub.should.have.been.calledOnce - }) - - describe('after 1 minute', () => - it('should run checkLogLevel again', function () { - this.clock.tick(61 * 1000) - this.getTracingEndTimeMetadataStub.should.have.been.calledTwice - })) - - describe('after 2 minutes', () => - it('should run checkLogLevel again', function () { - this.clock.tick(121 * 1000) - this.getTracingEndTimeMetadataStub.should.have.been.calledThrice + this.checkLogLevelStub.should.have.been.calledThrice })) }) From 57ef07dc672d6a51f17182b4dba46dd6a5ed4f56 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 30 Jul 2020 15:08:22 +0100 Subject: [PATCH 14/22] lint and format --- libraries/logger/logging-manager.js | 14 +++++++------- libraries/logger/test/unit/loggingManagerTests.js | 1 - 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 11c06f2716..a4b4caeaa7 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,7 +22,7 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { - console.log("IN INIT") + console.log('IN INIT') this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase() this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' @@ -60,18 +60,18 @@ const Logger = (module.exports = { }, async getTracingEndTimeFile() { - return fs.promises.readFile('/logging/tracingEndTime') + return fs.promises.readFile('/logging/tracingEndTime') }, -async getTracingEndTimeMetadata() { + async getTracingEndTimeMetadata() { const options = { headers: { 'Metadata-Flavor': 'Google' } } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - const res = await fetch(uri,options) - if (!res.ok) throw new Error("Metadata not okay") + const res = await fetch(uri, options) + if (!res.ok) throw new Error('Metadata not okay') return res.text() }, @@ -256,7 +256,7 @@ async getTracingEndTimeMetadata() { }, _setupLogLevelChecker() { - console.log("In _setupLogLevelChecker") + console.log('In _setupLogLevelChecker') console.log(this.logger) if (this.isProduction) { // clear interval if already set @@ -266,7 +266,7 @@ async getTracingEndTimeMetadata() { if (this.logLevelSource === 'file') { this.getTracingEndTime = this.getTracingEndTimeFile } else if (this.logLevelSource === 'gce_metadata') { - this.getTracingEndTime = this.getTracingEndTimeMetadata + this.getTracingEndTime = this.getTracingEndTimeMetadata } else if (this.logLevelSource === 'none') { return } else { diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index ee918a507d..d0de9ad64b 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -4,7 +4,6 @@ const chai = require('chai') const path = require('path') const sinon = require('sinon') const sinonChai = require('sinon-chai') -const { promises } = require('dns') chai.use(sinonChai) chai.should() From e32411eaaa2bee65fbfae2a76b6875bfd335a542 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Thu, 30 Jul 2020 15:23:04 +0100 Subject: [PATCH 15/22] Clean up acceptance tests --- libraries/logger/logging-manager.js | 4 ---- .../logger/test/unit/loggingManagerTests.js | 24 +++++++------------ 2 files changed, 8 insertions(+), 20 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index a4b4caeaa7..20156ec417 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,7 +22,6 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { - console.log('IN INIT') this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase() this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' @@ -40,7 +39,6 @@ const Logger = (module.exports = { }) this._setupRingBuffer() this._setupStackdriver() - console.log(this.logger) this._setupLogLevelChecker() return this }, @@ -256,8 +254,6 @@ const Logger = (module.exports = { }, _setupLogLevelChecker() { - console.log('In _setupLogLevelChecker') - console.log(this.logger) if (this.isProduction) { // clear interval if already set if (this.checkInterval) { diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index d0de9ad64b..23438a673a 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -111,21 +111,13 @@ describe('LoggingManager', function () { afterEach(() => delete process.env.NODE_ENV) - describe('blah', function () { - beforeEach(function () { - this.logger = this.LoggingManager.initialize(this.loggerName) - }) - it('should default to log level warn', function () { - - const level = this.Bunyan.createLogger.firstCall.args[0].streams[0].level - console.log(level) - level.should.equal( - 'warn' - ) - }) - }) - - + it('should default to log level warn', function () { + this.logger = this.LoggingManager.initialize(this.loggerName) + this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( + 'warn' + ) + }) + describe('logLevelSource file', function () { beforeEach(function() { this.logger = this.LoggingManager.initialize(this.loggerName) @@ -324,7 +316,7 @@ describe('LoggingManager', function () { describe('when read errors', function () { beforeEach(async function () { - this.Fs.promises.readFile.yields(new Error('error')) + this.Fs.promises.readFile.throws(new Error('error')) this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile await this.logger.checkLogLevel() }) From 46b22b30c7f39443953c4856f96675552bc85540 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 09:46:52 +0100 Subject: [PATCH 16/22] Fix test description --- libraries/logger/test/unit/loggingManagerTests.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 23438a673a..c543b6321b 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -99,7 +99,7 @@ describe('LoggingManager', function () { ) }) - it('should not run getTracingEndTime', function () { + it('should not run checkLogLevel', function () { this.checkLogLevelStub.should.not.have.been.called }) }) From 5e9dca7ddf1c5ed3bf13e4163f6c149bdf1455a0 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 09:53:29 +0100 Subject: [PATCH 17/22] Ensure fetchResponse.text is a string in sinon stub --- libraries/logger/test/unit/loggingManagerTests.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index c543b6321b..5f6ed7ca96 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -453,7 +453,7 @@ describe('LoggingManager', function () { describe('when level is already set', function() { beforeEach(async function() { this.bunyanLogger.level.returns(10) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() @@ -469,7 +469,7 @@ describe('LoggingManager', function () { describe('when level is not already set', function() { beforeEach(async function() { this.bunyanLogger.level.returns(20) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata From 9b21292b44e979b2edb423c4e02ce07a8b7f9e58 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 09:53:29 +0100 Subject: [PATCH 18/22] Ensure fetchResponse.text is a string in sinon stub --- libraries/logger/test/unit/loggingManagerTests.js | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index c543b6321b..5f8c3a9d81 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -316,7 +316,7 @@ describe('LoggingManager', function () { describe('when read errors', function () { beforeEach(async function () { - this.Fs.promises.readFile.throws(new Error('error')) + this.Fs.promises.readFile.throws(new Error('test read error')) this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile await this.logger.checkLogLevel() }) @@ -330,7 +330,7 @@ describe('LoggingManager', function () { describe('when the file is empty', function () { beforeEach(async function () { - this.Fs.promises.readFile.yields(null, '') + this.Fs.promises.readFile.returns('') this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile await this.logger.checkLogLevel() }) @@ -344,7 +344,7 @@ describe('LoggingManager', function () { describe('when time value returned that is less than current time', function () { beforeEach(async function () { - this.Fs.promises.readFile.yields(null, '1') + this.Fs.promises.readFile.returns('1') this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile await this.logger.checkLogLevel() }) @@ -453,7 +453,7 @@ describe('LoggingManager', function () { describe('when level is already set', function() { beforeEach(async function() { this.bunyanLogger.level.returns(10) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() @@ -469,7 +469,7 @@ describe('LoggingManager', function () { describe('when level is not already set', function() { beforeEach(async function() { this.bunyanLogger.level.returns(20) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata From 20f2e1eb1d9620e4f583e95b8632bef4f698597e Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 10:48:44 +0100 Subject: [PATCH 19/22] Don't catch checkLogLevel --- libraries/logger/logging-manager.js | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 20156ec417..e6ed94fedb 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -270,9 +270,7 @@ const Logger = (module.exports = { return } // check for log level override on startup - this.checkLogLevel().catch((error) => { - console.log(error) - }) + this.checkLogLevel() // re-check log level every minute this.checkInterval = setInterval(this.checkLogLevel.bind(this), 1000 * 60) } From ea502a062383fca4ba5184a44b15c27eee03bc09 Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 10:52:53 +0100 Subject: [PATCH 20/22] Put LoggingManager.initialize back as it was in tests --- libraries/logger/test/unit/loggingManagerTests.js | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 5f8c3a9d81..6874425010 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -107,21 +107,18 @@ describe('LoggingManager', function () { describe('in production', function () { beforeEach(function () { process.env.NODE_ENV = 'production' + this.logger = this.LoggingManager.initialize(this.loggerName) }) afterEach(() => delete process.env.NODE_ENV) it('should default to log level warn', function () { - this.logger = this.LoggingManager.initialize(this.loggerName) this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( 'warn' ) }) describe('logLevelSource file', function () { - beforeEach(function() { - this.logger = this.LoggingManager.initialize(this.loggerName) - }) it('should run checkLogLevel', function () { this.checkLogLevelStub.should.have.been.calledOnce From 8649277c9fdb6f40eb042183bd16400d7f0feb0b Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 10:55:03 +0100 Subject: [PATCH 21/22] Format:fix --- .../logger/test/unit/loggingManagerTests.js | 61 ++++++++++--------- 1 file changed, 32 insertions(+), 29 deletions(-) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 6874425010..93c57bd807 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -80,7 +80,9 @@ describe('LoggingManager', function () { describe('initialize', function () { beforeEach(function () { - this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel').resolves('') + this.checkLogLevelStub = sinon + .stub(this.LoggingManager, 'checkLogLevel') + .resolves('') this.Bunyan.createLogger.reset() }) @@ -116,10 +118,9 @@ describe('LoggingManager', function () { this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( 'warn' ) - }) - - describe('logLevelSource file', function () { + }) + describe('logLevelSource file', function () { it('should run checkLogLevel', function () { this.checkLogLevelStub.should.have.been.calledOnce }) @@ -136,7 +137,6 @@ describe('LoggingManager', function () { this.checkLogLevelStub.should.have.been.calledThrice })) }) - }) describe('when LOG_LEVEL set in env', function () { @@ -302,7 +302,6 @@ describe('LoggingManager', function () { }) describe('checkLogLevelFile', function () { - it('should request log level override from the config map', async function () { this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile await this.logger.checkLogLevel() @@ -391,89 +390,93 @@ describe('LoggingManager', function () { this.logger = this.LoggingManager.initialize(this.loggerName) }) - describe('checkLogLevel', function() { - it('should request log level override from google meta data service', async function() { + describe('checkLogLevel', function () { + it('should request log level override from google meta data service', async function () { this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() const options = { headers: { 'Metadata-Flavor': 'Google' - } + } } const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - this.Fetch.should.have.been.calledWithMatch(uri,options) + this.Fetch.should.have.been.calledWithMatch(uri, options) }) - describe('when request has error', function() { - beforeEach(async function() { + describe('when request has error', function () { + beforeEach(async function () { this.Fetch = sinon.stub().throws() this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() }) - it('should only set default level', function() { + it('should only set default level', function () { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'debug' ) }) }) - describe('when statusCode is not 200', function() { - beforeEach(async function() { + describe('when statusCode is not 200', function () { + beforeEach(async function () { this.fetchResponse.status = 404 this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() }) - it('should only set default level', function() { + it('should only set default level', function () { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'debug' ) }) }) - describe('when time value returned that is less than current time', function() { - beforeEach(async function() { + describe('when time value returned that is less than current time', function () { + beforeEach(async function () { this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata this.fetchResponse.text = sinon.stub().resolves('1') await this.logger.checkLogLevel() }) - it('should only set default level', function() { + it('should only set default level', function () { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'debug' ) }) }) - describe('when time value returned that is more than current time', function() { - describe('when level is already set', function() { - beforeEach(async function() { + describe('when time value returned that is more than current time', function () { + describe('when level is already set', function () { + beforeEach(async function () { this.bunyanLogger.level.returns(10) - this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) + this.fetchResponse.text = sinon + .stub() + .resolves((this.start + 1000).toString()) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() }) - it('should set trace level', function() { + it('should set trace level', function () { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'trace' ) }) }) - describe('when level is not already set', function() { - beforeEach(async function() { + describe('when level is not already set', function () { + beforeEach(async function () { this.bunyanLogger.level.returns(20) - this.fetchResponse.text = sinon.stub().resolves((this.start + 1000).toString()) - this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) + this.fetchResponse.text = sinon + .stub() + .resolves((this.start + 1000).toString()) + this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse) this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata await this.logger.checkLogLevel() }) - it('should set trace level', function() { + it('should set trace level', function () { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'trace' ) From a66708a3195e0e2c6fde452a8ef11ce94a6b066f Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Tue, 11 Aug 2020 10:56:51 +0100 Subject: [PATCH 22/22] Ignore error --- libraries/logger/logging-manager.js | 1 - 1 file changed, 1 deletion(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index e6ed94fedb..4351722209 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -52,7 +52,6 @@ const Logger = (module.exports = { this.logger.level(this.defaultLevel) } } catch (err) { - console.log(err) this.logger.level(this.defaultLevel) } },