From 2769efc5e38509015cc19832dceeb9f55f9b3d56 Mon Sep 17 00:00:00 2001 From: Jeff Yates Date: Wed, 24 Mar 2021 15:33:23 -0500 Subject: [PATCH] [FEI-2995] Logging enhancements and fixes (#455) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary: Two main changes here. 1. JSDOM console logging is now passed through to the render-gateway logging at the `silly` level. This avoids logging things we don't need in production, but supports them being available for devs as needed. 2. Fixes an issue where we started seeing some double logging and low level logging in production. Turns out that logging-winston has a fix for a bug we were working around, and this fix meant that our workaround started behaving like the original bug. So, we remove the workaround and now all is well. Issue: FEI-2995 ## Test plan: `yarn test` After deployment (staging or otherwise) we should no longer see any `TRACE` messages for downloading files, and we shouldn't see any JSDOM console warn/info/debug/log output (though these are relatively uncommon now). Author: somewhatabstract Reviewers: somewhatabstract, jeresig, kevinbarabash Required Reviewers: Approved by: jeresig, kevinbarabash Checks: ✅ Test (macOS-latest, 12.x), ✅ Test (macOS-latest, 10.x), ✅ Test (ubuntu-latest, 10.x), ✅ Coverage (ubuntu-latest, 12.x), ✅ Publish to branch, ✅ Lint and flow check (ubuntu-latest, 12.x), ⏭ Auto-approve dependabot PRs Pull request URL: https://github.com/Khan/render-gateway/pull/455 --- .../jsdom-sixteen/create-virtual-console.js | 47 +++---- .../create-virtual-console.js.map | 2 +- dist/shared/create-logger.js | 7 +- dist/shared/create-logger.js.map | 2 +- .../make-app-engine-request-id-middleware.js | 3 +- ...ke-app-engine-request-id-middleware.js.map | 2 +- .../middleware/make-request-middleware.js | 11 +- .../middleware/make-request-middleware.js.map | 2 +- .../__tests__/create-virtual-console.test.js | 119 +++++------------- .../jsdom-sixteen/create-virtual-console.js | 48 +++---- src/shared/__tests__/create-logger.test.js | 17 +++ src/shared/create-logger.js | 7 +- .../__tests__/make-request-middleware.test.js | 7 +- .../make-app-engine-request-id-middleware.js | 3 +- .../middleware/make-request-middleware.js | 11 +- 15 files changed, 129 insertions(+), 159 deletions(-) diff --git a/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js b/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js index fac11b2a..eed0333e 100644 --- a/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js +++ b/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js @@ -33,34 +33,39 @@ const createVirtualConsole = logger => { } const simplifiedError = (0, _index.extractError)(e); - logger.error(`JSDOM:${simplifiedError.error || ""}`, _objectSpread(_objectSpread({}, simplifiedError), {}, { + logger.error(`JSDOM jsdomError:${simplifiedError.error || ""}`, _objectSpread(_objectSpread({}, simplifiedError), {}, { kind: _index2.Errors.Internal })); - }); // NOTE: We pass args array as the metadata parameter for winston log. - // We don't worry about adding the error kind here; we mark these - // as Errors.Internal automatically if they don't already include a - // kind. + }); + /** + * NOTE(somewhatabstract): We pass args array as the metadata parameter for + * winston log. We don't worry about adding the error kind here; we mark + * these as Errors.Internal automatically if they don't already include a + * kind. + */ - virtualConsole.on("error", (message, ...args) => logger.error(`JSDOM:${message}`, { - args - })); - virtualConsole.on("warn", (message, ...args) => logger.warn(`JSDOM:${message}`, { + virtualConsole.on("error", (message, ...args) => logger.error(`JSDOM error:${message}`, { args })); - virtualConsole.on("info", (message, ...args) => logger.info(`JSDOM:${message}`, { - args - })); - virtualConsole.on("log", (message, ...args) => /** - * Winston uses log for a different, core thing, so let's map log to - * info. + * We log all other things as `silly`, since they are generally only useful + * to us when we're developing/debugging issues locally, and not in + * production. We could add some way to turn this on in production + * temporarily (like a temporary "elevate log level" query param) if + * we find that will be useful, but I haven't encountered an issue that + * needed these in production yet; they're just noise. */ - logger.info(`JSDOM:${message}`, { - args - })); - virtualConsole.on("debug", (message, ...args) => logger.debug(`JSDOM:${message}`, { - args - })); + + const passthruLog = method => { + virtualConsole.on(method, (message, ...args) => logger.silly(`JSDOM ${method}:${message}`, { + args + })); + }; + + passthruLog("warn"); + passthruLog("info"); + passthruLog("log"); + passthruLog("debug"); return virtualConsole; }; diff --git a/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js.map b/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js.map index 20edd135..0bc84a2b 100644 --- a/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js.map +++ b/dist/gateway/environments/jsdom-sixteen/create-virtual-console.js.map @@ -1 +1 @@ -{"version":3,"sources":["../../../../src/gateway/environments/jsdom-sixteen/create-virtual-console.js"],"names":["createVirtualConsole","logger","virtualConsole","VirtualConsole","on","e","message","indexOf","simplifiedError","error","kind","Errors","Internal","args","warn","info","debug"],"mappings":";;;;;;;AACA;;AACA;;AACA;;;;;;;;AAGA;AACA;AACA;AACA;AACA;AACA;AACO,MAAMA,oBAAoB,GAAIC,MAAD,IAAoC;AACpE,QAAMC,cAAc,GAAG,IAAIC,qBAAJ,EAAvB;AACAD,EAAAA,cAAc,CAACE,EAAf,CAAkB,YAAlB,EAAiCC,CAAD,IAAc;AAC1C,QAAIA,CAAC,CAACC,OAAF,CAAUC,OAAV,CAAkB,oBAAlB,KAA2C,CAA/C,EAAkD;AAC9C;AACA;AACA;AACH;;AACD,UAAMC,eAAe,GAAG,yBAAaH,CAAb,CAAxB;AACAJ,IAAAA,MAAM,CAACQ,KAAP,CAAc,SAAQD,eAAe,CAACC,KAAhB,IAAyB,EAAG,EAAlD,kCACOD,eADP;AAEIE,MAAAA,IAAI,EAAEC,eAAOC;AAFjB;AAIH,GAXD,EAFoE,CAepE;AACA;AACA;AACA;;AACAV,EAAAA,cAAc,CAACE,EAAf,CAAkB,OAAlB,EAA2B,CAACE,OAAD,EAAU,GAAGO,IAAb,KACvBZ,MAAM,CAACQ,KAAP,CAAc,SAAQH,OAAQ,EAA9B,EAAiC;AAACO,IAAAA;AAAD,GAAjC,CADJ;AAGAX,EAAAA,cAAc,CAACE,EAAf,CAAkB,MAAlB,EAA0B,CAACE,OAAD,EAAU,GAAGO,IAAb,KACtBZ,MAAM,CAACa,IAAP,CAAa,SAAQR,OAAQ,EAA7B,EAAgC;AAACO,IAAAA;AAAD,GAAhC,CADJ;AAGAX,EAAAA,cAAc,CAACE,EAAf,CAAkB,MAAlB,EAA0B,CAACE,OAAD,EAAU,GAAGO,IAAb,KACtBZ,MAAM,CAACc,IAAP,CAAa,SAAQT,OAAQ,EAA7B,EAAgC;AAACO,IAAAA;AAAD,GAAhC,CADJ;AAGAX,EAAAA,cAAc,CAACE,EAAf,CAAkB,KAAlB,EAAyB,CAACE,OAAD,EAAU,GAAGO,IAAb;AACrB;AACR;AACA;AACA;AACQZ,EAAAA,MAAM,CAACc,IAAP,CAAa,SAAQT,OAAQ,EAA7B,EAAgC;AAACO,IAAAA;AAAD,GAAhC,CALJ;AAOAX,EAAAA,cAAc,CAACE,EAAf,CAAkB,OAAlB,EAA2B,CAACE,OAAD,EAAU,GAAGO,IAAb,KACvBZ,MAAM,CAACe,KAAP,CAAc,SAAQV,OAAQ,EAA9B,EAAiC;AAACO,IAAAA;AAAD,GAAjC,CADJ;AAGA,SAAOX,cAAP;AACH,CAvCM","sourcesContent":["// @flow\nimport {VirtualConsole} from \"jsdom\";\nimport {extractError} from \"../../../shared/index.js\";\nimport {Errors} from \"../../../ka-shared/index.js\";\nimport type {Logger} from \"../../../shared/index.js\";\n\n/**\n * Create a virtual console for use with JSDOM.\n *\n * @param {Logger} logger The logger to which this virtual console logs.\n * @returns {VirtualConsole} A JSDOM VirtualConsole instance.\n */\nexport const createVirtualConsole = (logger: Logger): VirtualConsole => {\n const virtualConsole = new VirtualConsole();\n virtualConsole.on(\"jsdomError\", (e: Error) => {\n if (e.message.indexOf(\"Could not load img\") >= 0) {\n // We know that images cannot load. We're deliberately blocking\n // them.\n return;\n }\n const simplifiedError = extractError(e);\n logger.error(`JSDOM:${simplifiedError.error || \"\"}`, {\n ...simplifiedError,\n kind: Errors.Internal,\n });\n });\n\n // NOTE: We pass args array as the metadata parameter for winston log.\n // We don't worry about adding the error kind here; we mark these\n // as Errors.Internal automatically if they don't already include a\n // kind.\n virtualConsole.on(\"error\", (message, ...args) =>\n logger.error(`JSDOM:${message}`, {args}),\n );\n virtualConsole.on(\"warn\", (message, ...args) =>\n logger.warn(`JSDOM:${message}`, {args}),\n );\n virtualConsole.on(\"info\", (message, ...args) =>\n logger.info(`JSDOM:${message}`, {args}),\n );\n virtualConsole.on(\"log\", (message, ...args) =>\n /**\n * Winston uses log for a different, core thing, so let's map log to\n * info.\n */\n logger.info(`JSDOM:${message}`, {args}),\n );\n virtualConsole.on(\"debug\", (message, ...args) =>\n logger.debug(`JSDOM:${message}`, {args}),\n );\n return virtualConsole;\n};\n"],"file":"create-virtual-console.js"} \ No newline at end of file +{"version":3,"sources":["../../../../src/gateway/environments/jsdom-sixteen/create-virtual-console.js"],"names":["createVirtualConsole","logger","virtualConsole","VirtualConsole","on","e","message","indexOf","simplifiedError","error","kind","Errors","Internal","args","passthruLog","method","silly"],"mappings":";;;;;;;AACA;;AACA;;AACA;;;;;;;;AAGA;AACA;AACA;AACA;AACA;AACA;AACO,MAAMA,oBAAoB,GAAIC,MAAD,IAAoC;AACpE,QAAMC,cAAc,GAAG,IAAIC,qBAAJ,EAAvB;AACAD,EAAAA,cAAc,CAACE,EAAf,CAAkB,YAAlB,EAAiCC,CAAD,IAAc;AAC1C,QAAIA,CAAC,CAACC,OAAF,CAAUC,OAAV,CAAkB,oBAAlB,KAA2C,CAA/C,EAAkD;AAC9C;AACA;AACA;AACH;;AACD,UAAMC,eAAe,GAAG,yBAAaH,CAAb,CAAxB;AACAJ,IAAAA,MAAM,CAACQ,KAAP,CAAc,oBAAmBD,eAAe,CAACC,KAAhB,IAAyB,EAAG,EAA7D,kCACOD,eADP;AAEIE,MAAAA,IAAI,EAAEC,eAAOC;AAFjB;AAIH,GAXD;AAaA;AACJ;AACA;AACA;AACA;AACA;;AACIV,EAAAA,cAAc,CAACE,EAAf,CAAkB,OAAlB,EAA2B,CAACE,OAAD,EAAU,GAAGO,IAAb,KACvBZ,MAAM,CAACQ,KAAP,CAAc,eAAcH,OAAQ,EAApC,EAAuC;AAACO,IAAAA;AAAD,GAAvC,CADJ;AAIA;AACJ;AACA;AACA;AACA;AACA;AACA;AACA;;AACI,QAAMC,WAAW,GAAIC,MAAD,IAA+C;AAC/Db,IAAAA,cAAc,CAACE,EAAf,CAAkBW,MAAlB,EAA0B,CAACT,OAAD,EAAU,GAAGO,IAAb,KACtBZ,MAAM,CAACe,KAAP,CAAc,SAAQD,MAAO,IAAGT,OAAQ,EAAxC,EAA2C;AAACO,MAAAA;AAAD,KAA3C,CADJ;AAGH,GAJD;;AAKAC,EAAAA,WAAW,CAAC,MAAD,CAAX;AACAA,EAAAA,WAAW,CAAC,MAAD,CAAX;AACAA,EAAAA,WAAW,CAAC,KAAD,CAAX;AACAA,EAAAA,WAAW,CAAC,OAAD,CAAX;AACA,SAAOZ,cAAP;AACH,CA3CM","sourcesContent":["// @flow\nimport {VirtualConsole} from \"jsdom\";\nimport {extractError} from \"../../../shared/index.js\";\nimport {Errors} from \"../../../ka-shared/index.js\";\nimport type {Logger} from \"../../../shared/index.js\";\n\n/**\n * Create a virtual console for use with JSDOM.\n *\n * @param {Logger} logger The logger to which this virtual console logs.\n * @returns {VirtualConsole} A JSDOM VirtualConsole instance.\n */\nexport const createVirtualConsole = (logger: Logger): VirtualConsole => {\n const virtualConsole = new VirtualConsole();\n virtualConsole.on(\"jsdomError\", (e: Error) => {\n if (e.message.indexOf(\"Could not load img\") >= 0) {\n // We know that images cannot load. We're deliberately blocking\n // them.\n return;\n }\n const simplifiedError = extractError(e);\n logger.error(`JSDOM jsdomError:${simplifiedError.error || \"\"}`, {\n ...simplifiedError,\n kind: Errors.Internal,\n });\n });\n\n /**\n * NOTE(somewhatabstract): We pass args array as the metadata parameter for\n * winston log. We don't worry about adding the error kind here; we mark\n * these as Errors.Internal automatically if they don't already include a\n * kind.\n */\n virtualConsole.on(\"error\", (message, ...args) =>\n logger.error(`JSDOM error:${message}`, {args}),\n );\n\n /**\n * We log all other things as `silly`, since they are generally only useful\n * to us when we're developing/debugging issues locally, and not in\n * production. We could add some way to turn this on in production\n * temporarily (like a temporary \"elevate log level\" query param) if\n * we find that will be useful, but I haven't encountered an issue that\n * needed these in production yet; they're just noise.\n */\n const passthruLog = (method: \"warn\" | \"info\" | \"log\" | \"debug\") => {\n virtualConsole.on(method, (message, ...args) =>\n logger.silly(`JSDOM ${method}:${message}`, {args}),\n );\n };\n passthruLog(\"warn\");\n passthruLog(\"info\");\n passthruLog(\"log\");\n passthruLog(\"debug\");\n return virtualConsole;\n};\n"],"file":"create-virtual-console.js"} \ No newline at end of file diff --git a/dist/shared/create-logger.js b/dist/shared/create-logger.js index 0f68572c..2479e494 100644 --- a/dist/shared/create-logger.js +++ b/dist/shared/create-logger.js @@ -115,9 +115,10 @@ const getTransport = (mode, logLevel) => { * We must be in production, so we will use the Stackdriver logging * setup. * - * If using the Google-provided middleware that adds a log property - * to the express request, make sure this transport is passed to - * that middleware so that it doesn't add its own. + * The Google-provided logging-winston middleware, which adds a log + * property to the express request, looks for this transport before + * adding its own (if it didn't, we would get double logging of + * each message we logged). */ return new lw.LoggingWinston({ level: logLevel diff --git a/dist/shared/create-logger.js.map b/dist/shared/create-logger.js.map index f0beeab5..700f180d 100644 --- a/dist/shared/create-logger.js.map +++ b/dist/shared/create-logger.js.map @@ -1 +1 @@ -{"version":3,"sources":["../../src/shared/create-logger.js"],"names":["devFormatter","level","message","metadata","metadataString","Object","keys","length","JSON","stringify","getFormatters","mode","formatters","winston","format","splat","push","cli","printf","info","combine","getTransport","logLevel","sink","stream","Writable","write","_write","transports","Stream","Console","lw","LoggingWinston","getDefaultMetadata","instance","pid","instanceID","processID","createLogger","runtimeMode","winstonLogger","kind","Errors","Internal","defaultMeta","debug"],"mappings":";;;;;;;AACA;;AACA;;AACA;;AAGA;;AACA;;;;;;;;;;;;AAGA;AACA;AACA;AACA;AACA;AACA;AACA;AACA,MAAMA,YAAY,GAAG,UAAiD;AAAA,MAAhD;AAACC,IAAAA,KAAD;AAAQC,IAAAA;AAAR,GAAgD;AAAA,MAA5BC,QAA4B;;AAClE,QAAMC,cAAc,GAChBD,QAAQ,IAAI,IAAZ,IAAoBE,MAAM,CAACC,IAAP,CAAYH,QAAZ,EAAsBI,MAAtB,KAAiC,CAArD,GACM,EADN,GAEO,IAAGC,IAAI,CAACC,SAAL,CAAeN,QAAf,EAAyB,IAAzB,EAA+B,CAA/B,CAAkC,EAHhD;AAIA,SAAQ,GAAEF,KAAM,KAAIC,OAAQ,GAAEE,cAAe,EAA7C;AACH,CAND;AAQA;AACA;AACA;;;AACA,MAAMM,aAAa,GAAIC,IAAD,IAA2B;AAC7C,QAAMC,UAAyB,GAAG,CAC9BC,iBAAQC,MAAR,CAAeC,KAAf,EAD8B,CACN;AADM,GAAlC;;AAGA,MAAIJ,IAAI,KAAK,aAAb,EAA4B;AACxBC,IAAAA,UAAU,CAACI,IAAX,CAAgBH,iBAAQC,MAAR,CAAeG,GAAf,CAAmB;AAAChB,MAAAA,KAAK,EAAE;AAAR,KAAnB,CAAhB;AACH;AAED;AACJ;AACA;AACA;;;AACIW,EAAAA,UAAU,CAACI,IAAX,CAAgBH,iBAAQC,MAAR,CAAeI,MAAf,CAAuBC,IAAD,IAAenB,YAAY,CAACmB,IAAD,CAAjD,CAAhB;AACA,SAAON,iBAAQC,MAAR,CAAeM,OAAf,CAAuB,GAAGR,UAA1B,CAAP;AACH,CAdD;AAgBA;AACA;AACA;;;AACA,MAAMS,YAAY,GAAG,CAACV,IAAD,EAAgBW,QAAhB,KAAkD;AACnE,UAAQX,IAAR;AACI;AACR;AACA;AACA;AACA;AACQ;AACA,SAAK,MAAL;AACI;AACZ;AACA;AACA;AACA;AACA;AACA;AACA;AACA;AACY,YAAMY,IAAI,GAAG,IAAIC,gBAAOC,QAAX,CAAoB;AAACC,QAAAA,KAAK,EAAE,MAAM,CAAE;AAAhB,OAApB,CAAb;AACA;AACZ;AACA;AACA;;AACYH,MAAAA,IAAI,CAACI,MAAL,GAAcJ,IAAI,CAACG,KAAnB;AACA,aAAO,IAAIb,iBAAQe,UAAR,CAAmBC,MAAvB,CAA8B;AACjCf,QAAAA,MAAM,EAAEJ,aAAa,CAAC,MAAD,CADY;AAEjCc,QAAAA,MAAM,EAAED;AAFyB,OAA9B,CAAP;;AAKJ,SAAK,aAAL;AACI;AACZ;AACA;AACY,aAAO,IAAIV,iBAAQe,UAAR,CAAmBE,OAAvB,CAA+B;AAClChB,QAAAA,MAAM,EAAEJ,aAAa,CAAC,aAAD;AADa,OAA/B,CAAP;;AAIJ,SAAK,YAAL;AACI;AACZ;AACA;AACA;AACA;AACA;AACA;AACA;AACY,aAAO,IAAIqB,EAAE,CAACC,cAAP,CAAsB;AACzB/B,QAAAA,KAAK,EAAEqB;AADkB,OAAtB,CAAP;AA7CR;AAiDH,CAlDD;AAoDA;AACA;AACA;;;AACO,MAAMW,kBAAkB,GAAG,MAAW;AACzC,QAAM;AAACC,IAAAA,QAAD;AAAWC,IAAAA;AAAX,MAAkB,qCAAxB;AACA,SAAO;AACHC,IAAAA,UAAU,EAAEF,QADT;AAEHG,IAAAA,SAAS,EAAEF;AAFR,GAAP;AAIH,CANM;AAQP;AACA;AACA;;;;;AACO,MAAMG,YAAY,GAAG,CACxBC,WADwB,EAExBjB,QAFwB,KAGf;AACT,QAAMkB,aAAa,GAAG3B,iBAAQyB,YAAR,CAAmC;AACrDrC,IAAAA,KAAK,EAAEqB,QAD8C;AAErDM,IAAAA,UAAU,EAAEP,YAAY,CAACkB,WAAD,EAAcjB,QAAd,CAF6B;AAGrDR,IAAAA,MAAM,EAAED,iBAAQC,MAAR,CAAgBK,IAAD,IAAU;AAC7B;AACA;AACA,UAAIA,IAAI,CAAClB,KAAL,KAAe,OAAf,IAA0BkB,IAAI,CAACsB,IAAL,IAAa,IAA3C,EAAiD;AAC7CtB,QAAAA,IAAI,CAACsB,IAAL,GAAYC,eAAOC,QAAnB;AACH;;AACD,aAAOxB,IAAP;AACH,KAPO,GAH6C;AAWrDyB,IAAAA,WAAW,EAAEX,kBAAkB;AAXsB,GAAnC,CAAtB;;AAcAO,EAAAA,aAAa,CAACK,KAAd,CACK,yBAAwBvB,QAAS,SAAQiB,WAAY,GAD1D;AAIA,SAAOC,aAAP;AACH,CAvBM","sourcesContent":["// @flow\nimport stream from \"stream\";\nimport winston from \"winston\";\nimport * as lw from \"@google-cloud/logging-winston\";\nimport type {Transport, NpmLogLevels, Format} from \"winston\";\n\nimport {Errors} from \"./errors.js\";\nimport {getGatewayInfo} from \"./get-gateway-info.js\";\nimport type {Runtime, Logger, LogLevel, Info} from \"./types.js\";\n\n/**\n * This is how the log message gets formatted.\n *\n * We can expand this to include additional metadata as needed. For example,\n * if we have the profiling API from react-render-server, we could include\n * the duration metadata.\n */\nconst devFormatter = ({level, message, ...metadata}: Info): string => {\n const metadataString =\n metadata == null || Object.keys(metadata).length === 0\n ? \"\"\n : ` ${JSON.stringify(metadata, null, 4)}`;\n return `${level}: ${message}${metadataString}`;\n};\n\n/**\n * Build the formatters to give us some nice dev output.\n */\nconst getFormatters = (mode: Runtime): Format => {\n const formatters: Array = [\n winston.format.splat(), // Allows for %s style substitutions\n ];\n if (mode === \"development\") {\n formatters.push(winston.format.cli({level: true}));\n }\n\n /**\n * This must be added after the cli formatter if it is to be used in\n * the dev output.\n */\n formatters.push(winston.format.printf((info: any) => devFormatter(info)));\n return winston.format.combine(...formatters);\n};\n\n/**\n * Gets the logging transport for the given mode.\n */\nconst getTransport = (mode: Runtime, logLevel: LogLevel): Transport => {\n switch (mode) {\n /**\n * Our flow types guard against misuse as long as someone is using them.\n * Let's be defensive and cope with a bad value. In that case, we'll\n * assume our test mode as it's the most inert.\n */\n default:\n case \"test\":\n /**\n * During testing, we just dump logging.\n * This avoids storing it anywhere and keeps it out of our\n * test output.\n * To do this, we use a stream that just writes to nowhere.\n *\n * If you want to test logging, you can jest.spy on the logger's\n * log method, or any other of its more specific logging methods.\n */\n const sink = new stream.Writable({write: () => {}});\n /**\n * $FlowFixMe[cannot-write]\n * This is a hack to make our writable stream work\n */\n sink._write = sink.write;\n return new winston.transports.Stream({\n format: getFormatters(\"test\"),\n stream: sink,\n });\n\n case \"development\":\n /**\n * If we're in dev mode, just use a console transport.\n */\n return new winston.transports.Console({\n format: getFormatters(\"development\"),\n });\n\n case \"production\":\n /**\n * We must be in production, so we will use the Stackdriver logging\n * setup.\n *\n * If using the Google-provided middleware that adds a log property\n * to the express request, make sure this transport is passed to\n * that middleware so that it doesn't add its own.\n */\n return new lw.LoggingWinston({\n level: logLevel,\n });\n }\n};\n\n/**\n * Get default metadata to attach to logs.\n */\nexport const getDefaultMetadata = (): any => {\n const {instance, pid} = getGatewayInfo();\n return {\n instanceID: instance,\n processID: pid,\n };\n};\n\n/**\n * Create a logger for the given runtime mode and log level.\n */\nexport const createLogger = (\n runtimeMode: Runtime,\n logLevel: LogLevel,\n): Logger => {\n const winstonLogger = winston.createLogger({\n level: logLevel,\n transports: getTransport(runtimeMode, logLevel),\n format: winston.format((info) => {\n // Let's make sure that errors reported without a taxonomic\n // label get labelled.\n if (info.level === \"error\" && info.kind == null) {\n info.kind = Errors.Internal;\n }\n return info;\n })(),\n defaultMeta: getDefaultMetadata(),\n });\n\n winstonLogger.debug(\n `Created logger (Level=${logLevel} Mode=${runtimeMode})`,\n );\n\n return winstonLogger;\n};\n"],"file":"create-logger.js"} \ No newline at end of file +{"version":3,"sources":["../../src/shared/create-logger.js"],"names":["devFormatter","level","message","metadata","metadataString","Object","keys","length","JSON","stringify","getFormatters","mode","formatters","winston","format","splat","push","cli","printf","info","combine","getTransport","logLevel","sink","stream","Writable","write","_write","transports","Stream","Console","lw","LoggingWinston","getDefaultMetadata","instance","pid","instanceID","processID","createLogger","runtimeMode","winstonLogger","kind","Errors","Internal","defaultMeta","debug"],"mappings":";;;;;;;AACA;;AACA;;AACA;;AAGA;;AACA;;;;;;;;;;;;AAGA;AACA;AACA;AACA;AACA;AACA;AACA;AACA,MAAMA,YAAY,GAAG,UAAiD;AAAA,MAAhD;AAACC,IAAAA,KAAD;AAAQC,IAAAA;AAAR,GAAgD;AAAA,MAA5BC,QAA4B;;AAClE,QAAMC,cAAc,GAChBD,QAAQ,IAAI,IAAZ,IAAoBE,MAAM,CAACC,IAAP,CAAYH,QAAZ,EAAsBI,MAAtB,KAAiC,CAArD,GACM,EADN,GAEO,IAAGC,IAAI,CAACC,SAAL,CAAeN,QAAf,EAAyB,IAAzB,EAA+B,CAA/B,CAAkC,EAHhD;AAIA,SAAQ,GAAEF,KAAM,KAAIC,OAAQ,GAAEE,cAAe,EAA7C;AACH,CAND;AAQA;AACA;AACA;;;AACA,MAAMM,aAAa,GAAIC,IAAD,IAA2B;AAC7C,QAAMC,UAAyB,GAAG,CAC9BC,iBAAQC,MAAR,CAAeC,KAAf,EAD8B,CACN;AADM,GAAlC;;AAGA,MAAIJ,IAAI,KAAK,aAAb,EAA4B;AACxBC,IAAAA,UAAU,CAACI,IAAX,CAAgBH,iBAAQC,MAAR,CAAeG,GAAf,CAAmB;AAAChB,MAAAA,KAAK,EAAE;AAAR,KAAnB,CAAhB;AACH;AAED;AACJ;AACA;AACA;;;AACIW,EAAAA,UAAU,CAACI,IAAX,CAAgBH,iBAAQC,MAAR,CAAeI,MAAf,CAAuBC,IAAD,IAAenB,YAAY,CAACmB,IAAD,CAAjD,CAAhB;AACA,SAAON,iBAAQC,MAAR,CAAeM,OAAf,CAAuB,GAAGR,UAA1B,CAAP;AACH,CAdD;AAgBA;AACA;AACA;;;AACA,MAAMS,YAAY,GAAG,CAACV,IAAD,EAAgBW,QAAhB,KAAkD;AACnE,UAAQX,IAAR;AACI;AACR;AACA;AACA;AACA;AACQ;AACA,SAAK,MAAL;AACI;AACZ;AACA;AACA;AACA;AACA;AACA;AACA;AACA;AACY,YAAMY,IAAI,GAAG,IAAIC,gBAAOC,QAAX,CAAoB;AAACC,QAAAA,KAAK,EAAE,MAAM,CAAE;AAAhB,OAApB,CAAb;AACA;AACZ;AACA;AACA;;AACYH,MAAAA,IAAI,CAACI,MAAL,GAAcJ,IAAI,CAACG,KAAnB;AACA,aAAO,IAAIb,iBAAQe,UAAR,CAAmBC,MAAvB,CAA8B;AACjCf,QAAAA,MAAM,EAAEJ,aAAa,CAAC,MAAD,CADY;AAEjCc,QAAAA,MAAM,EAAED;AAFyB,OAA9B,CAAP;;AAKJ,SAAK,aAAL;AACI;AACZ;AACA;AACY,aAAO,IAAIV,iBAAQe,UAAR,CAAmBE,OAAvB,CAA+B;AAClChB,QAAAA,MAAM,EAAEJ,aAAa,CAAC,aAAD;AADa,OAA/B,CAAP;;AAIJ,SAAK,YAAL;AACI;AACZ;AACA;AACA;AACA;AACA;AACA;AACA;AACA;AACY,aAAO,IAAIqB,EAAE,CAACC,cAAP,CAAsB;AACzB/B,QAAAA,KAAK,EAAEqB;AADkB,OAAtB,CAAP;AA9CR;AAkDH,CAnDD;AAqDA;AACA;AACA;;;AACO,MAAMW,kBAAkB,GAAG,MAAW;AACzC,QAAM;AAACC,IAAAA,QAAD;AAAWC,IAAAA;AAAX,MAAkB,qCAAxB;AACA,SAAO;AACHC,IAAAA,UAAU,EAAEF,QADT;AAEHG,IAAAA,SAAS,EAAEF;AAFR,GAAP;AAIH,CANM;AAQP;AACA;AACA;;;;;AACO,MAAMG,YAAY,GAAG,CACxBC,WADwB,EAExBjB,QAFwB,KAGf;AACT,QAAMkB,aAAa,GAAG3B,iBAAQyB,YAAR,CAAmC;AACrDrC,IAAAA,KAAK,EAAEqB,QAD8C;AAErDM,IAAAA,UAAU,EAAEP,YAAY,CAACkB,WAAD,EAAcjB,QAAd,CAF6B;AAGrDR,IAAAA,MAAM,EAAED,iBAAQC,MAAR,CAAgBK,IAAD,IAAU;AAC7B;AACA;AACA,UAAIA,IAAI,CAAClB,KAAL,KAAe,OAAf,IAA0BkB,IAAI,CAACsB,IAAL,IAAa,IAA3C,EAAiD;AAC7CtB,QAAAA,IAAI,CAACsB,IAAL,GAAYC,eAAOC,QAAnB;AACH;;AACD,aAAOxB,IAAP;AACH,KAPO,GAH6C;AAWrDyB,IAAAA,WAAW,EAAEX,kBAAkB;AAXsB,GAAnC,CAAtB;;AAcAO,EAAAA,aAAa,CAACK,KAAd,CACK,yBAAwBvB,QAAS,SAAQiB,WAAY,GAD1D;AAIA,SAAOC,aAAP;AACH,CAvBM","sourcesContent":["// @flow\nimport stream from \"stream\";\nimport winston from \"winston\";\nimport * as lw from \"@google-cloud/logging-winston\";\nimport type {Transport, NpmLogLevels, Format} from \"winston\";\n\nimport {Errors} from \"./errors.js\";\nimport {getGatewayInfo} from \"./get-gateway-info.js\";\nimport type {Runtime, Logger, LogLevel, Info} from \"./types.js\";\n\n/**\n * This is how the log message gets formatted.\n *\n * We can expand this to include additional metadata as needed. For example,\n * if we have the profiling API from react-render-server, we could include\n * the duration metadata.\n */\nconst devFormatter = ({level, message, ...metadata}: Info): string => {\n const metadataString =\n metadata == null || Object.keys(metadata).length === 0\n ? \"\"\n : ` ${JSON.stringify(metadata, null, 4)}`;\n return `${level}: ${message}${metadataString}`;\n};\n\n/**\n * Build the formatters to give us some nice dev output.\n */\nconst getFormatters = (mode: Runtime): Format => {\n const formatters: Array = [\n winston.format.splat(), // Allows for %s style substitutions\n ];\n if (mode === \"development\") {\n formatters.push(winston.format.cli({level: true}));\n }\n\n /**\n * This must be added after the cli formatter if it is to be used in\n * the dev output.\n */\n formatters.push(winston.format.printf((info: any) => devFormatter(info)));\n return winston.format.combine(...formatters);\n};\n\n/**\n * Gets the logging transport for the given mode.\n */\nconst getTransport = (mode: Runtime, logLevel: LogLevel): Transport => {\n switch (mode) {\n /**\n * Our flow types guard against misuse as long as someone is using them.\n * Let's be defensive and cope with a bad value. In that case, we'll\n * assume our test mode as it's the most inert.\n */\n default:\n case \"test\":\n /**\n * During testing, we just dump logging.\n * This avoids storing it anywhere and keeps it out of our\n * test output.\n * To do this, we use a stream that just writes to nowhere.\n *\n * If you want to test logging, you can jest.spy on the logger's\n * log method, or any other of its more specific logging methods.\n */\n const sink = new stream.Writable({write: () => {}});\n /**\n * $FlowFixMe[cannot-write]\n * This is a hack to make our writable stream work\n */\n sink._write = sink.write;\n return new winston.transports.Stream({\n format: getFormatters(\"test\"),\n stream: sink,\n });\n\n case \"development\":\n /**\n * If we're in dev mode, just use a console transport.\n */\n return new winston.transports.Console({\n format: getFormatters(\"development\"),\n });\n\n case \"production\":\n /**\n * We must be in production, so we will use the Stackdriver logging\n * setup.\n *\n * The Google-provided logging-winston middleware, which adds a log\n * property to the express request, looks for this transport before\n * adding its own (if it didn't, we would get double logging of\n * each message we logged).\n */\n return new lw.LoggingWinston({\n level: logLevel,\n });\n }\n};\n\n/**\n * Get default metadata to attach to logs.\n */\nexport const getDefaultMetadata = (): any => {\n const {instance, pid} = getGatewayInfo();\n return {\n instanceID: instance,\n processID: pid,\n };\n};\n\n/**\n * Create a logger for the given runtime mode and log level.\n */\nexport const createLogger = (\n runtimeMode: Runtime,\n logLevel: LogLevel,\n): Logger => {\n const winstonLogger = winston.createLogger({\n level: logLevel,\n transports: getTransport(runtimeMode, logLevel),\n format: winston.format((info) => {\n // Let's make sure that errors reported without a taxonomic\n // label get labelled.\n if (info.level === \"error\" && info.kind == null) {\n info.kind = Errors.Internal;\n }\n return info;\n })(),\n defaultMeta: getDefaultMetadata(),\n });\n\n winstonLogger.debug(\n `Created logger (Level=${logLevel} Mode=${runtimeMode})`,\n );\n\n return winstonLogger;\n};\n"],"file":"create-logger.js"} \ No newline at end of file diff --git a/dist/shared/middleware/make-app-engine-request-id-middleware.js b/dist/shared/middleware/make-app-engine-request-id-middleware.js index 42a1c7b5..0515446c 100644 --- a/dist/shared/middleware/make-app-engine-request-id-middleware.js +++ b/dist/shared/middleware/make-app-engine-request-id-middleware.js @@ -33,7 +33,8 @@ function makeAppEngineRequestIDMiddleware(defaultLogger) { }); /* * NOTE: the $Request type doesn't have a log field, officially. - * However, we know that the Google middleware adds it. + * However, we know that the Google middleware adds it, so now we + * replace it with our own version. */ req.log = requestIDLog; diff --git a/dist/shared/middleware/make-app-engine-request-id-middleware.js.map b/dist/shared/middleware/make-app-engine-request-id-middleware.js.map index 0839dae4..01b18b86 100644 --- a/dist/shared/middleware/make-app-engine-request-id-middleware.js.map +++ b/dist/shared/middleware/make-app-engine-request-id-middleware.js.map @@ -1 +1 @@ -{"version":3,"sources":["../../../src/shared/middleware/make-app-engine-request-id-middleware.js"],"names":["makeAppEngineRequestIDMiddleware","defaultLogger","middleware","req","res","next","requestID","requestIDLog","child","log"],"mappings":";;;;;;;AAEA;;AACA;;AAGA;AACA;AACA;AACA;AACO,SAASA,gCAAT,CAGLC,aAHK,EAG0C;AAC7C,QAAMC,UAAU,GAAG,CACfC,GADe,EAEfC,GAFe,EAGfC,IAHe,KAIR;AACP,UAAMC,SAAS,GAAG,kDAAsBH,GAAtB,CAAlB;;AACA,QAAIG,SAAS,IAAI,IAAjB,EAAuB;AACnB;AACAD,MAAAA,IAAI;AACJ;AACH;AAED;AACR;AACA;AACA;;;AACQ,UAAME,YAAY,GAAG,wCAAiBN,aAAjB,EAAgCE,GAAhC,EAAqCK,KAArC,CAA2C;AAC5DF,MAAAA;AAD4D,KAA3C,CAArB;AAGA;AACR;AACA;AACA;;AACQH,IAAAA,GAAG,CAACM,GAAJ,GAAUF,YAAV;AACAF,IAAAA,IAAI;AACP,GAzBD;;AA0BA,SAAOH,UAAP;AACH","sourcesContent":["// @flow\nimport type {$Response, $Request, Middleware, NextFunction} from \"express\";\nimport {getAppEngineRequestID} from \"../get-app-engine-request-id.js\";\nimport {getRequestLogger} from \"../get-request-logger.js\";\nimport type {Logger, RequestWithLog} from \"../types.js\";\n\n/**\n * Create a middleware that sets the log property of a request to a logger\n * that will attach the GAE requestID to the log metadata.\n */\nexport function makeAppEngineRequestIDMiddleware<\n TReq: RequestWithLog<$Request>,\n TRes: $Response,\n>(defaultLogger: Logger): Middleware {\n const middleware = , TRes: $Response>(\n req: TReq,\n res: TRes,\n next: NextFunction,\n ): void => {\n const requestID = getAppEngineRequestID(req);\n if (requestID == null) {\n // We couldn't get the GAE request ID, so let's skip on.\n next();\n return;\n }\n\n /**\n * We have a requestID and we know req.log exists, so let's set\n * req.log to a derived child logger that adds the requestID metadata.\n */\n const requestIDLog = getRequestLogger(defaultLogger, req).child({\n requestID,\n });\n /*\n * NOTE: the $Request type doesn't have a log field, officially.\n * However, we know that the Google middleware adds it.\n */\n req.log = requestIDLog;\n next();\n };\n return middleware;\n}\n"],"file":"make-app-engine-request-id-middleware.js"} \ No newline at end of file +{"version":3,"sources":["../../../src/shared/middleware/make-app-engine-request-id-middleware.js"],"names":["makeAppEngineRequestIDMiddleware","defaultLogger","middleware","req","res","next","requestID","requestIDLog","child","log"],"mappings":";;;;;;;AAEA;;AACA;;AAGA;AACA;AACA;AACA;AACO,SAASA,gCAAT,CAGLC,aAHK,EAG0C;AAC7C,QAAMC,UAAU,GAAG,CACfC,GADe,EAEfC,GAFe,EAGfC,IAHe,KAIR;AACP,UAAMC,SAAS,GAAG,kDAAsBH,GAAtB,CAAlB;;AACA,QAAIG,SAAS,IAAI,IAAjB,EAAuB;AACnB;AACAD,MAAAA,IAAI;AACJ;AACH;AAED;AACR;AACA;AACA;;;AACQ,UAAME,YAAY,GAAG,wCAAiBN,aAAjB,EAAgCE,GAAhC,EAAqCK,KAArC,CAA2C;AAC5DF,MAAAA;AAD4D,KAA3C,CAArB;AAGA;AACR;AACA;AACA;AACA;;AACQH,IAAAA,GAAG,CAACM,GAAJ,GAAUF,YAAV;AACAF,IAAAA,IAAI;AACP,GA1BD;;AA2BA,SAAOH,UAAP;AACH","sourcesContent":["// @flow\nimport type {$Response, $Request, Middleware, NextFunction} from \"express\";\nimport {getAppEngineRequestID} from \"../get-app-engine-request-id.js\";\nimport {getRequestLogger} from \"../get-request-logger.js\";\nimport type {Logger, RequestWithLog} from \"../types.js\";\n\n/**\n * Create a middleware that sets the log property of a request to a logger\n * that will attach the GAE requestID to the log metadata.\n */\nexport function makeAppEngineRequestIDMiddleware<\n TReq: RequestWithLog<$Request>,\n TRes: $Response,\n>(defaultLogger: Logger): Middleware {\n const middleware = , TRes: $Response>(\n req: TReq,\n res: TRes,\n next: NextFunction,\n ): void => {\n const requestID = getAppEngineRequestID(req);\n if (requestID == null) {\n // We couldn't get the GAE request ID, so let's skip on.\n next();\n return;\n }\n\n /**\n * We have a requestID and we know req.log exists, so let's set\n * req.log to a derived child logger that adds the requestID metadata.\n */\n const requestIDLog = getRequestLogger(defaultLogger, req).child({\n requestID,\n });\n /*\n * NOTE: the $Request type doesn't have a log field, officially.\n * However, we know that the Google middleware adds it, so now we\n * replace it with our own version.\n */\n req.log = requestIDLog;\n next();\n };\n return middleware;\n}\n"],"file":"make-app-engine-request-id-middleware.js"} \ No newline at end of file diff --git a/dist/shared/middleware/make-request-middleware.js b/dist/shared/middleware/make-request-middleware.js index d2cf907d..ac1d1c2f 100644 --- a/dist/shared/middleware/make-request-middleware.js +++ b/dist/shared/middleware/make-request-middleware.js @@ -21,14 +21,11 @@ function _interopRequireWildcard(obj) { if (obj && obj.__esModule) { return obj; const makeRequestMiddleware = (mode, logger) => { if (mode === "production") { /** - * In production, we're using the Google middleware. This adds the - * log property to the request, allowing us to associate log entries - * with a request trace, if the request is being traced. - * - * WORKAROUND: We must pass the corresponding transport here or it will - * get added for us and then we'll have double logging. + * In production, we're using the Google logging-winston middleware. + * This adds the log property to the request, allowing us to associate + * log entries with a request trace, if the request is being traced. */ - return lw.express.makeMiddleware(logger, new lw.LoggingWinston()); + return lw.express.makeMiddleware(logger); } /** * In all other cases, we use express-winston to log requests for us. diff --git a/dist/shared/middleware/make-request-middleware.js.map b/dist/shared/middleware/make-request-middleware.js.map index b6ab9bc1..2a4491ea 100644 --- a/dist/shared/middleware/make-request-middleware.js.map +++ b/dist/shared/middleware/make-request-middleware.js.map @@ -1 +1 @@ -{"version":3,"sources":["../../../src/shared/middleware/make-request-middleware.js"],"names":["makeRequestMiddleware","mode","logger","lw","express","makeMiddleware","LoggingWinston","Promise","resolve","expressWinston","level","winstonInstance","expressFormat","colorize","meta"],"mappings":";;;;;;;AACA;;AACA;;;;;;;;AAKA;AACA;AACA;AACO,MAAMA,qBAAqB,GAAG,CACjCC,IADiC,EAEjCC,MAFiC,KAGC;AAClC,MAAID,IAAI,KAAK,YAAb,EAA2B;AACvB;AACR;AACA;AACA;AACA;AACA;AACA;AACA;AACQ,WAAOE,EAAE,CAACC,OAAH,CAAWC,cAAX,CAA0BH,MAA1B,EAAkC,IAAIC,EAAE,CAACG,cAAP,EAAlC,CAAP;AACH;AAED;AACJ;AACA;;;AACI,SAAOC,OAAO,CAACC,OAAR,CACHC,wBAAeP,MAAf,CAAsB;AAClB;AACZ;AACA;AACA;AACA;AACYQ,IAAAA,KAAK,EAAE,MANW;;AAQlB;AACZ;AACA;AACYC,IAAAA,eAAe,EAAET,MAXC;AAYlBU,IAAAA,aAAa,EAAE,IAZG;AAalBC,IAAAA,QAAQ,EAAE,IAbQ;AAclBC,IAAAA,IAAI,EAAE;AAdY,GAAtB,CADG,CAAP;AAkBH,CArCM","sourcesContent":["// @flow\nimport * as lw from \"@google-cloud/logging-winston\";\nimport expressWinston from \"express-winston\";\n\nimport type {Middleware, $Request, $Response} from \"express\";\nimport type {Logger, Runtime} from \"../types.js\";\n\n/**\n * Create middleware for tracking requests.\n */\nexport const makeRequestMiddleware = (\n mode: Runtime,\n logger: Logger,\n): Promise> => {\n if (mode === \"production\") {\n /**\n * In production, we're using the Google middleware. This adds the\n * log property to the request, allowing us to associate log entries\n * with a request trace, if the request is being traced.\n *\n * WORKAROUND: We must pass the corresponding transport here or it will\n * get added for us and then we'll have double logging.\n */\n return lw.express.makeMiddleware(logger, new lw.LoggingWinston());\n }\n\n /**\n * In all other cases, we use express-winston to log requests for us.\n */\n return Promise.resolve(\n expressWinston.logger({\n /**\n * Specify the level that this logger logs at.\n * (use a function to dynamically change level based on req and res)\n * `function(req, res) { return String; }`\n */\n level: \"info\",\n\n /**\n * Use the logger we already set up.\n */\n winstonInstance: logger,\n expressFormat: true,\n colorize: true,\n meta: false,\n }),\n );\n};\n"],"file":"make-request-middleware.js"} \ No newline at end of file +{"version":3,"sources":["../../../src/shared/middleware/make-request-middleware.js"],"names":["makeRequestMiddleware","mode","logger","lw","express","makeMiddleware","Promise","resolve","expressWinston","level","winstonInstance","expressFormat","colorize","meta"],"mappings":";;;;;;;AACA;;AACA;;;;;;;;AAKA;AACA;AACA;AACO,MAAMA,qBAAqB,GAAG,CACjCC,IADiC,EAEjCC,MAFiC,KAGC;AAClC,MAAID,IAAI,KAAK,YAAb,EAA2B;AACvB;AACR;AACA;AACA;AACA;AACQ,WAAOE,EAAE,CAACC,OAAH,CAAWC,cAAX,CAA0BH,MAA1B,CAAP;AACH;AAED;AACJ;AACA;;;AACI,SAAOI,OAAO,CAACC,OAAR,CACHC,wBAAeN,MAAf,CAAsB;AAClB;AACZ;AACA;AACA;AACA;AACYO,IAAAA,KAAK,EAAE,MANW;;AAQlB;AACZ;AACA;AACYC,IAAAA,eAAe,EAAER,MAXC;AAYlBS,IAAAA,aAAa,EAAE,IAZG;AAalBC,IAAAA,QAAQ,EAAE,IAbQ;AAclBC,IAAAA,IAAI,EAAE;AAdY,GAAtB,CADG,CAAP;AAkBH,CAlCM","sourcesContent":["// @flow\nimport * as lw from \"@google-cloud/logging-winston\";\nimport expressWinston from \"express-winston\";\n\nimport type {Middleware, $Request, $Response} from \"express\";\nimport type {Logger, Runtime} from \"../types.js\";\n\n/**\n * Create middleware for tracking requests.\n */\nexport const makeRequestMiddleware = (\n mode: Runtime,\n logger: Logger,\n): Promise> => {\n if (mode === \"production\") {\n /**\n * In production, we're using the Google logging-winston middleware.\n * This adds the log property to the request, allowing us to associate\n * log entries with a request trace, if the request is being traced.\n */\n return lw.express.makeMiddleware(logger);\n }\n\n /**\n * In all other cases, we use express-winston to log requests for us.\n */\n return Promise.resolve(\n expressWinston.logger({\n /**\n * Specify the level that this logger logs at.\n * (use a function to dynamically change level based on req and res)\n * `function(req, res) { return String; }`\n */\n level: \"info\",\n\n /**\n * Use the logger we already set up.\n */\n winstonInstance: logger,\n expressFormat: true,\n colorize: true,\n meta: false,\n }),\n );\n};\n"],"file":"make-request-middleware.js"} \ No newline at end of file diff --git a/src/gateway/environments/jsdom-sixteen/__tests__/create-virtual-console.test.js b/src/gateway/environments/jsdom-sixteen/__tests__/create-virtual-console.test.js index b2904406..678b0d61 100644 --- a/src/gateway/environments/jsdom-sixteen/__tests__/create-virtual-console.test.js +++ b/src/gateway/environments/jsdom-sixteen/__tests__/create-virtual-console.test.js @@ -46,11 +46,14 @@ describe("#createVirtualConsole", () => { underTest.emit("jsdomError", new Error("This is a jsdomError message")); // Assert - expect(fakeLogger.error).toHaveBeenCalledWith("JSDOM:ERROR_MESSAGE", { - error: "ERROR_MESSAGE", - kind: "Internal", - stack: "ERROR_STACK", - }); + expect(fakeLogger.error).toHaveBeenCalledWith( + "JSDOM jsdomError:ERROR_MESSAGE", + { + error: "ERROR_MESSAGE", + kind: "Internal", + stack: "ERROR_STACK", + }, + ); }); it("should pass errors to logger.error with args as metadata", () => { @@ -69,90 +72,36 @@ describe("#createVirtualConsole", () => { // Assert expect(fakeLogger.error).toHaveBeenCalledWith( - "JSDOM:This is an error message", + "JSDOM error:This is an error message", { args: ["and these are args"], }, ); }); - it("should pass warn to logger.warn with args as metadata", () => { - // Arrange - const fakeLogger: any = { - warn: jest.fn(), - }; - const underTest = createVirtualConsole(fakeLogger); - - // Act - underTest.emit("warn", "This is a warn message", "and these are args"); - - // Assert - expect(fakeLogger.warn).toHaveBeenCalledWith( - "JSDOM:This is a warn message", - { - args: ["and these are args"], - }, - ); - }); - - it("should pass info to logger.info with args as metadata", () => { - // Arrange - const fakeLogger: any = { - info: jest.fn(), - }; - const underTest = createVirtualConsole(fakeLogger); - - // Act - underTest.emit("info", "This is an info message", "and these are args"); - - // Assert - expect(fakeLogger.info).toHaveBeenCalledWith( - "JSDOM:This is an info message", - { - args: ["and these are args"], - }, - ); - }); - - it("should pass log to logger.info with args as metadata", () => { - // Arrange - const fakeLogger: any = { - info: jest.fn(), - }; - const underTest = createVirtualConsole(fakeLogger); - - // Act - underTest.emit("log", "This is a log message", "and these are args"); - - // Assert - expect(fakeLogger.info).toHaveBeenCalledWith( - "JSDOM:This is a log message", - { - args: ["and these are args"], - }, - ); - }); - - it("should pass debug to logger.debug with args as metadata", () => { - // Arrange - const fakeLogger: any = { - debug: jest.fn(), - }; - const underTest = createVirtualConsole(fakeLogger); - - // Act - underTest.emit( - "debug", - "This is a debug message", - "and these are args", - ); - - // Assert - expect(fakeLogger.debug).toHaveBeenCalledWith( - "JSDOM:This is a debug message", - { - args: ["and these are args"], - }, - ); - }); + it.each(["warn", "info", "log", "debug"])( + "should pass %s through to logger silly with args as metadata", + (method: string) => { + // Arrange + const fakeLogger: any = { + silly: jest.fn(), + }; + const underTest = createVirtualConsole(fakeLogger); + + // Act + underTest.emit( + method, + "This is a logged message", + "and these are args", + ); + + // Assert + expect(fakeLogger.silly).toHaveBeenCalledWith( + `JSDOM ${method}:This is a logged message`, + { + args: ["and these are args"], + }, + ); + }, + ); }); diff --git a/src/gateway/environments/jsdom-sixteen/create-virtual-console.js b/src/gateway/environments/jsdom-sixteen/create-virtual-console.js index 3f4c32bd..02ff51ca 100644 --- a/src/gateway/environments/jsdom-sixteen/create-virtual-console.js +++ b/src/gateway/environments/jsdom-sixteen/create-virtual-console.js @@ -19,34 +19,38 @@ export const createVirtualConsole = (logger: Logger): VirtualConsole => { return; } const simplifiedError = extractError(e); - logger.error(`JSDOM:${simplifiedError.error || ""}`, { + logger.error(`JSDOM jsdomError:${simplifiedError.error || ""}`, { ...simplifiedError, kind: Errors.Internal, }); }); - // NOTE: We pass args array as the metadata parameter for winston log. - // We don't worry about adding the error kind here; we mark these - // as Errors.Internal automatically if they don't already include a - // kind. + /** + * NOTE(somewhatabstract): We pass args array as the metadata parameter for + * winston log. We don't worry about adding the error kind here; we mark + * these as Errors.Internal automatically if they don't already include a + * kind. + */ virtualConsole.on("error", (message, ...args) => - logger.error(`JSDOM:${message}`, {args}), - ); - virtualConsole.on("warn", (message, ...args) => - logger.warn(`JSDOM:${message}`, {args}), - ); - virtualConsole.on("info", (message, ...args) => - logger.info(`JSDOM:${message}`, {args}), - ); - virtualConsole.on("log", (message, ...args) => - /** - * Winston uses log for a different, core thing, so let's map log to - * info. - */ - logger.info(`JSDOM:${message}`, {args}), - ); - virtualConsole.on("debug", (message, ...args) => - logger.debug(`JSDOM:${message}`, {args}), + logger.error(`JSDOM error:${message}`, {args}), ); + + /** + * We log all other things as `silly`, since they are generally only useful + * to us when we're developing/debugging issues locally, and not in + * production. We could add some way to turn this on in production + * temporarily (like a temporary "elevate log level" query param) if + * we find that will be useful, but I haven't encountered an issue that + * needed these in production yet; they're just noise. + */ + const passthruLog = (method: "warn" | "info" | "log" | "debug") => { + virtualConsole.on(method, (message, ...args) => + logger.silly(`JSDOM ${method}:${message}`, {args}), + ); + }; + passthruLog("warn"); + passthruLog("info"); + passthruLog("log"); + passthruLog("debug"); return virtualConsole; }; diff --git a/src/shared/__tests__/create-logger.test.js b/src/shared/__tests__/create-logger.test.js index 434db170..d152feaa 100644 --- a/src/shared/__tests__/create-logger.test.js +++ b/src/shared/__tests__/create-logger.test.js @@ -1,5 +1,6 @@ // @flow import winston from "winston"; +import {Errors} from "../errors.js"; import {createLogger} from "../create-logger.js"; jest.mock("@google-cloud/logging-winston", () => ({ @@ -126,6 +127,22 @@ describe("#createLogger", () => { // Assert expect(transports).toHaveProperty("__FAKE_LOGGING_WINSTON__"); }); + + it("should ensure errors get kind metadata", () => { + // Arrange + const mockFormat = jest.spyOn(winston, "format"); + + // Act + createLogger("production", "silly"); + const formatter = mockFormat.mock.calls[0][0]; + const result = formatter({level: "error"}); + + // Assert + expect(result).toStrictEqual({ + level: "error", + kind: Errors.Internal, + }); + }); }); it("should log creation parameters to created logger", () => { diff --git a/src/shared/create-logger.js b/src/shared/create-logger.js index 32b09954..39f2ae59 100644 --- a/src/shared/create-logger.js +++ b/src/shared/create-logger.js @@ -87,9 +87,10 @@ const getTransport = (mode: Runtime, logLevel: LogLevel): Transport => { * We must be in production, so we will use the Stackdriver logging * setup. * - * If using the Google-provided middleware that adds a log property - * to the express request, make sure this transport is passed to - * that middleware so that it doesn't add its own. + * The Google-provided logging-winston middleware, which adds a log + * property to the express request, looks for this transport before + * adding its own (if it didn't, we would get double logging of + * each message we logged). */ return new lw.LoggingWinston({ level: logLevel, diff --git a/src/shared/middleware/__tests__/make-request-middleware.test.js b/src/shared/middleware/__tests__/make-request-middleware.test.js index c3e59dca..62b8d855 100644 --- a/src/shared/middleware/__tests__/make-request-middleware.test.js +++ b/src/shared/middleware/__tests__/make-request-middleware.test.js @@ -43,7 +43,7 @@ describe("#makeRequestMiddleware", () => { expect(result).toBe(pretendLoggingWinstonMiddleware); }); - it("should create middleware with logger and transport", async () => { + it("should create middleware with logger", async () => { // Arrange const pretendLogger = ({}: any); const pretendLoggingWinstonMiddleware = ({}: any); @@ -55,10 +55,7 @@ describe("#makeRequestMiddleware", () => { await makeRequestMiddleware("production", pretendLogger); // Assert - expect(middlewareSpy).toHaveBeenCalledWith( - pretendLogger, - expect.objectContaining({__FAKE_LOGGING_WINSTON__: true}), - ); + expect(middlewareSpy).toHaveBeenCalledWith(pretendLogger); }); }); diff --git a/src/shared/middleware/make-app-engine-request-id-middleware.js b/src/shared/middleware/make-app-engine-request-id-middleware.js index 0a06b6bf..c72e4bd8 100644 --- a/src/shared/middleware/make-app-engine-request-id-middleware.js +++ b/src/shared/middleware/make-app-engine-request-id-middleware.js @@ -33,7 +33,8 @@ export function makeAppEngineRequestIDMiddleware< }); /* * NOTE: the $Request type doesn't have a log field, officially. - * However, we know that the Google middleware adds it. + * However, we know that the Google middleware adds it, so now we + * replace it with our own version. */ req.log = requestIDLog; next(); diff --git a/src/shared/middleware/make-request-middleware.js b/src/shared/middleware/make-request-middleware.js index 2064820c..a0d8345c 100644 --- a/src/shared/middleware/make-request-middleware.js +++ b/src/shared/middleware/make-request-middleware.js @@ -14,14 +14,11 @@ export const makeRequestMiddleware = ( ): Promise> => { if (mode === "production") { /** - * In production, we're using the Google middleware. This adds the - * log property to the request, allowing us to associate log entries - * with a request trace, if the request is being traced. - * - * WORKAROUND: We must pass the corresponding transport here or it will - * get added for us and then we'll have double logging. + * In production, we're using the Google logging-winston middleware. + * This adds the log property to the request, allowing us to associate + * log entries with a request trace, if the request is being traced. */ - return lw.express.makeMiddleware(logger, new lw.LoggingWinston()); + return lw.express.makeMiddleware(logger); } /**