From 4a1d83ccaa73fa0f11af1d775de4e89ceed75f4d Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Tue, 28 Nov 2023 07:05:07 -0800 Subject: [PATCH] feat(instrumentation-bunyan): add log sending to Logs Bridge API (#1713) * feat(instrumentation-bunyan): add log sending to Logs Bridge API This extends the Bunyan instrumentation to automatically add a Bunyan stream to created loggers that will send log records to the Logs Bridge API: https://opentelemetry.io/docs/specs/otel/logs/bridge-api/ Now that the instrumentation supports separate "injection" of fields and "bridging" of log records functionality, this also adds two boolean options to disable those independently: `enableInjection` and `enableLogsBridge`. This also updates the instrumentation to work with ES module usage. Closes: #1559 * markdown lint fixes * markdown lint fixes * catch up with recent core-deps update * some type tweaks suggested by David * more specific type Co-authored-by: Amir Blum * use more self-explanatory code for mapping Bunyan level to OTel severity, from blumamir * export OpenTelemetryBunyanStream for direct usage in Bunyan loggers without the instrumentation * .apply over .call suggestion * consistency suggestion * suggestion to use the longer (perhaps clearer) logger var name * switch to false-by-default config vars to avoid surprises with undefined values See https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/configuration/sdk-environment-variables.md#boolean-value Suggestion from blumamir. * document using OpenTelemetryBunyanStream without the instrumentation * fix https://eslint.org/docs/latest/rules/prefer-spread lint error * drop options to OpenTelemetryBunyanStream constructor because YAGNI * temporarily drop CI caching to test theory on unit-test (18) CI failure * more CI debugging: restore cache, add some 'npm ls -a' to look into NoopContextManager being used * elide Bunyan 'pid' and 'hostname' fields in OTel log record attributes Because they are redundant with 'process.pid' and 'host.name' resource attributes. Add some docs on how to use resource detectors to the example, because the HostDetector is not on by default in the NodeSDK. * update test for having elided 'pid' and 'hostname' fields * CI debugging: ignore the 'npm ls -a' exit status, they shouldn't break the build * fix lint and compile errors * CI debugging: turn on diag DEBUG to test a theory * turn off diag in this example * undo CI debugging changes * update deps to current releases and sync package-lock.json * disableInjection -> disableLogCorrelation * disableLogsBridge -> disableLogSending Avoid using 'bridge' terminology at suggestion from specs that the Bridge API is an internal detail. * correct the default instrumentation scope name (as discussed earlier) * tests: fix test for intrumentationScope.name change in previous commit * fix lint --------- Co-authored-by: Amir Blum Co-authored-by: Hector Hernandez <39923391+hectorhdzg@users.noreply.github.com> --- package-lock.json | 92 +++-- .../README.md | 106 ++++-- .../examples/README.md | 114 ++++++ .../examples/app.js | 32 ++ .../examples/app.mjs | 33 ++ .../examples/package.json | 26 ++ .../examples/telemetry.js | 56 +++ .../package.json | 5 +- .../src/OpenTelemetryBunyanStream.ts | 162 +++++++++ .../src/index.ts | 1 + .../src/instrumentation.ts | 103 +++++- .../src/types.ts | 19 + .../test/bunyan.test.ts | 332 ++++++++++++++++-- 13 files changed, 971 insertions(+), 110 deletions(-) create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/examples/README.md create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/examples/app.mjs create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/examples/package.json create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/examples/telemetry.js create mode 100644 plugins/node/opentelemetry-instrumentation-bunyan/src/OpenTelemetryBunyanStream.ts diff --git a/package-lock.json b/package-lock.json index 0bcce7b0480..fff718c45b1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -12012,7 +12012,7 @@ "version": "1.0.2", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-1.0.2.tgz", "integrity": "sha512-3oSeUO0TMV67hN1AmbXsK4yaqU7tjiHlbxRDZOpH0KW9+CeX4bRAaX0Anxt0tx2MrpRpWwQaPwIlISEJhYU5Pw==", - "dev": true + "devOptional": true }, "node_modules/base": { "version": "0.11.2", @@ -12332,7 +12332,7 @@ "version": "1.1.11", "resolved": "https://registry.npmjs.org/brace-expansion/-/brace-expansion-1.1.11.tgz", "integrity": "sha512-iCuPHDFgrHX7H2vEI/5xpz07zSHB00TpugqhmYtVmMO6518mCuRMoOYFldEBl0g187ufozdaHgWKcYFb61qGiA==", - "dev": true, + "devOptional": true, "dependencies": { "balanced-match": "^1.0.0", "concat-map": "0.0.1" @@ -12561,7 +12561,6 @@ "version": "1.8.15", "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.8.15.tgz", "integrity": "sha512-0tECWShh6wUysgucJcBAoYegf3JJoZWibxdqhTm7OHPeT42qdjkZ29QCMcKwbgU1kiH+auSIasNRXMLWXafXig==", - "dev": true, "engines": [ "node >=0.10.0" ], @@ -12575,6 +12574,10 @@ "safe-json-stringify": "~1" } }, + "node_modules/bunyan-example": { + "resolved": "plugins/node/opentelemetry-instrumentation-bunyan/examples", + "link": true + }, "node_modules/busboy": { "version": "1.6.0", "resolved": "https://registry.npmjs.org/busboy/-/busboy-1.6.0.tgz", @@ -13490,7 +13493,7 @@ "version": "0.0.1", "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz", "integrity": "sha512-/Srv4dswyQNBfohGpz9o6Yb3Gz3SrUDqBH5rTuhGR7ahtlbYKnVxw2bCFMRljaA7EXHaXZ8wsHdodFvbkhKmqg==", - "dev": true + "devOptional": true }, "node_modules/concat-stream": { "version": "2.0.0", @@ -14518,7 +14521,6 @@ "version": "0.8.8", "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.8.8.tgz", "integrity": "sha512-b7Z7cNtHPhH9EJhNNbbeqTcXB8LGFFZhq1PGgEvpeHlzd36bhbdTWoE/Ba/YguqpBSlAPKnARWhVlhunCMwfxg==", - "dev": true, "hasInstallScript": true, "optional": true, "dependencies": { @@ -18251,7 +18253,7 @@ "version": "1.0.6", "resolved": "https://registry.npmjs.org/inflight/-/inflight-1.0.6.tgz", "integrity": "sha512-k92I/b08q4wvFscXCLvqfsHCrjrF7yiXsQuIVvVE7N82W3+aqpzuUdBbfhWcy/FZR3/4IgflMgKLOsvPDrGCJA==", - "dev": true, + "devOptional": true, "dependencies": { "once": "^1.3.0", "wrappy": "1" @@ -22651,7 +22653,7 @@ "version": "3.1.2", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.1.2.tgz", "integrity": "sha512-J7p63hRiAjw1NDEww1W7i37+ByIrOWO5XQQAzZ3VOcL0PNybwpfmV/N05zFAzwQ9USyEcX6t3UO+K5aqBQOIHw==", - "dev": true, + "devOptional": true, "dependencies": { "brace-expansion": "^1.1.7" }, @@ -23494,7 +23496,6 @@ "version": "2.29.4", "resolved": "https://registry.npmjs.org/moment/-/moment-2.29.4.tgz", "integrity": "sha512-5LC9SOxjSc2HF6vO2CyuTDNivEdoz2IvyJJGj6X8DJ0eFyfszE0QiEd+iXmBvUP3WHxSjFH/vIsA0EN00cgr8w==", - "dev": true, "optional": true, "engines": { "node": "*" @@ -23865,7 +23866,6 @@ "version": "2.1.1", "resolved": "https://registry.npmjs.org/mv/-/mv-2.1.1.tgz", "integrity": "sha512-at/ZndSy3xEGJ8i0ygALh8ru9qy7gWW1cmkaqBN29JmMlIvM//MEO9y1sk/avxuwnPcfhkejkLsuPxH81BrkSg==", - "dev": true, "optional": true, "dependencies": { "mkdirp": "~0.5.1", @@ -23880,7 +23880,6 @@ "version": "6.0.4", "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", "integrity": "sha512-MKZeRNyYZAVVVG1oZeLaWie1uweH40m9AZwIwxyPbTSX4hHrVYSzLg0Ro5Z5R7XKkIX+Cc6oD1rqeDJnwsB8/A==", - "dev": true, "optional": true, "dependencies": { "inflight": "^1.0.4", @@ -23897,7 +23896,6 @@ "version": "0.5.6", "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-0.5.6.tgz", "integrity": "sha512-FP+p8RB8OWpF3YZBCrP5gtADmtXApB5AMLn+vdyA+PyxCjrCs00mjyUozssO33cwDeT3wNGdLxJ5M//YqtHAJw==", - "dev": true, "optional": true, "dependencies": { "minimist": "^1.2.6" @@ -23910,7 +23908,6 @@ "version": "2.4.5", "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-2.4.5.tgz", "integrity": "sha512-J5xnxTyqaiw06JjMftq7L9ouA448dw/E7dKghkP9WpKNuwmARNNg+Gk8/u5ryb9N/Yo2+z3MCwuqFK/+qPOPfQ==", - "dev": true, "optional": true, "dependencies": { "glob": "^6.0.1" @@ -24069,7 +24066,7 @@ "version": "2.18.0", "resolved": "https://registry.npmjs.org/nan/-/nan-2.18.0.tgz", "integrity": "sha512-W7tfG7vMOGtD30sHoZSSc/JVYiyDPEyQVso/Zz+/uQd0B0L46gtC+pHha5FFMRpil6fm/AoEcRWyOVi4+E/f8w==", - "dev": true + "devOptional": true }, "node_modules/nanomatch": { "version": "1.2.13", @@ -24160,7 +24157,6 @@ "version": "2.0.0", "resolved": "https://registry.npmjs.org/ncp/-/ncp-2.0.0.tgz", "integrity": "sha512-zIdGUrPRFTUELUvr3Gmc7KZ2Sw/h1PiVM0Af/oHB6zgnV1ikqSfRk+TOufi79aHYCW3NiOXmr1BP5nWbzojLaA==", - "dev": true, "optional": true, "bin": { "ncp": "bin/ncp" @@ -25868,7 +25864,7 @@ "version": "1.4.0", "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", "integrity": "sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w==", - "dev": true, + "devOptional": true, "dependencies": { "wrappy": "1" } @@ -26747,7 +26743,7 @@ "version": "1.0.1", "resolved": "https://registry.npmjs.org/path-is-absolute/-/path-is-absolute-1.0.1.tgz", "integrity": "sha512-AVbw3UJ2e9bq64vSaS9Am0fje1Pa8pbGqTTsmXfaIiMpnr5DlDhfJOuLj9Sf95ZPVDAUerDfEk88MPmPe7UCQg==", - "dev": true, + "devOptional": true, "engines": { "node": ">=0.10.0" } @@ -28848,7 +28844,6 @@ "version": "1.2.0", "resolved": "https://registry.npmjs.org/safe-json-stringify/-/safe-json-stringify-1.2.0.tgz", "integrity": "sha512-gH8eh2nZudPQO6TytOvbxnuhYBOvDBBLW52tz5q6X58lJcd/tkmqFR+5Z9adS8aJtURSXWThWy/xJtJwixErvg==", - "dev": true, "optional": true }, "node_modules/safe-regex": { @@ -33787,7 +33782,7 @@ "version": "1.0.2", "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz", "integrity": "sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==", - "dev": true + "devOptional": true }, "node_modules/write-file-atomic": { "version": "4.0.1", @@ -35167,14 +35162,17 @@ "version": "0.33.0", "license": "Apache-2.0", "dependencies": { + "@opentelemetry/api-logs": "^0.45.1", "@opentelemetry/instrumentation": "^0.45.1", "@types/bunyan": "1.8.9" }, "devDependencies": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-logs": "^0.45.1", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", + "@opentelemetry/semantic-conventions": "^1.0.0", "@types/mocha": "7.0.2", "@types/node": "18.6.5", "@types/sinon": "10.0.18", @@ -35194,6 +35192,20 @@ "@opentelemetry/api": "^1.3.0" } }, + "plugins/node/opentelemetry-instrumentation-bunyan/examples": { + "version": "0.45.1", + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/api": "^1.3.0", + "@opentelemetry/instrumentation-bunyan": "../", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-node": "^0.45.1", + "bunyan": "^1.8.15" + }, + "engines": { + "node": ">=14" + } + }, "plugins/node/opentelemetry-instrumentation-bunyan/node_modules/@types/mocha": { "version": "7.0.2", "resolved": "https://registry.npmjs.org/@types/mocha/-/mocha-7.0.2.tgz", @@ -44129,10 +44141,13 @@ "version": "file:plugins/node/opentelemetry-instrumentation-bunyan", "requires": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/api-logs": "^0.45.1", "@opentelemetry/instrumentation": "^0.45.1", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-logs": "^0.45.1", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", + "@opentelemetry/semantic-conventions": "^1.0.0", "@types/bunyan": "1.8.9", "@types/mocha": "7.0.2", "@types/node": "18.6.5", @@ -49074,7 +49089,7 @@ "version": "1.0.2", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-1.0.2.tgz", "integrity": "sha512-3oSeUO0TMV67hN1AmbXsK4yaqU7tjiHlbxRDZOpH0KW9+CeX4bRAaX0Anxt0tx2MrpRpWwQaPwIlISEJhYU5Pw==", - "dev": true + "devOptional": true }, "base": { "version": "0.11.2", @@ -49344,7 +49359,7 @@ "version": "1.1.11", "resolved": "https://registry.npmjs.org/brace-expansion/-/brace-expansion-1.1.11.tgz", "integrity": "sha512-iCuPHDFgrHX7H2vEI/5xpz07zSHB00TpugqhmYtVmMO6518mCuRMoOYFldEBl0g187ufozdaHgWKcYFb61qGiA==", - "dev": true, + "devOptional": true, "requires": { "balanced-match": "^1.0.0", "concat-map": "0.0.1" @@ -49540,7 +49555,6 @@ "version": "1.8.15", "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.8.15.tgz", "integrity": "sha512-0tECWShh6wUysgucJcBAoYegf3JJoZWibxdqhTm7OHPeT42qdjkZ29QCMcKwbgU1kiH+auSIasNRXMLWXafXig==", - "dev": true, "requires": { "dtrace-provider": "~0.8", "moment": "^2.19.3", @@ -49548,6 +49562,16 @@ "safe-json-stringify": "~1" } }, + "bunyan-example": { + "version": "file:plugins/node/opentelemetry-instrumentation-bunyan/examples", + "requires": { + "@opentelemetry/api": "^1.3.0", + "@opentelemetry/instrumentation-bunyan": "../", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-node": "^0.45.1", + "bunyan": "^1.8.15" + } + }, "busboy": { "version": "1.6.0", "resolved": "https://registry.npmjs.org/busboy/-/busboy-1.6.0.tgz", @@ -50240,7 +50264,7 @@ "version": "0.0.1", "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz", "integrity": "sha512-/Srv4dswyQNBfohGpz9o6Yb3Gz3SrUDqBH5rTuhGR7ahtlbYKnVxw2bCFMRljaA7EXHaXZ8wsHdodFvbkhKmqg==", - "dev": true + "devOptional": true }, "concat-stream": { "version": "2.0.0", @@ -51066,7 +51090,6 @@ "version": "0.8.8", "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.8.8.tgz", "integrity": "sha512-b7Z7cNtHPhH9EJhNNbbeqTcXB8LGFFZhq1PGgEvpeHlzd36bhbdTWoE/Ba/YguqpBSlAPKnARWhVlhunCMwfxg==", - "dev": true, "optional": true, "requires": { "nan": "^2.14.0" @@ -54104,7 +54127,7 @@ "version": "1.0.6", "resolved": "https://registry.npmjs.org/inflight/-/inflight-1.0.6.tgz", "integrity": "sha512-k92I/b08q4wvFscXCLvqfsHCrjrF7yiXsQuIVvVE7N82W3+aqpzuUdBbfhWcy/FZR3/4IgflMgKLOsvPDrGCJA==", - "dev": true, + "devOptional": true, "requires": { "once": "^1.3.0", "wrappy": "1" @@ -57601,7 +57624,7 @@ "version": "3.1.2", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.1.2.tgz", "integrity": "sha512-J7p63hRiAjw1NDEww1W7i37+ByIrOWO5XQQAzZ3VOcL0PNybwpfmV/N05zFAzwQ9USyEcX6t3UO+K5aqBQOIHw==", - "dev": true, + "devOptional": true, "requires": { "brace-expansion": "^1.1.7" } @@ -58289,7 +58312,6 @@ "version": "2.29.4", "resolved": "https://registry.npmjs.org/moment/-/moment-2.29.4.tgz", "integrity": "sha512-5LC9SOxjSc2HF6vO2CyuTDNivEdoz2IvyJJGj6X8DJ0eFyfszE0QiEd+iXmBvUP3WHxSjFH/vIsA0EN00cgr8w==", - "dev": true, "optional": true }, "mongodb": { @@ -58586,7 +58608,6 @@ "version": "2.1.1", "resolved": "https://registry.npmjs.org/mv/-/mv-2.1.1.tgz", "integrity": "sha512-at/ZndSy3xEGJ8i0ygALh8ru9qy7gWW1cmkaqBN29JmMlIvM//MEO9y1sk/avxuwnPcfhkejkLsuPxH81BrkSg==", - "dev": true, "optional": true, "requires": { "mkdirp": "~0.5.1", @@ -58598,7 +58619,6 @@ "version": "6.0.4", "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", "integrity": "sha512-MKZeRNyYZAVVVG1oZeLaWie1uweH40m9AZwIwxyPbTSX4hHrVYSzLg0Ro5Z5R7XKkIX+Cc6oD1rqeDJnwsB8/A==", - "dev": true, "optional": true, "requires": { "inflight": "^1.0.4", @@ -58612,7 +58632,6 @@ "version": "0.5.6", "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-0.5.6.tgz", "integrity": "sha512-FP+p8RB8OWpF3YZBCrP5gtADmtXApB5AMLn+vdyA+PyxCjrCs00mjyUozssO33cwDeT3wNGdLxJ5M//YqtHAJw==", - "dev": true, "optional": true, "requires": { "minimist": "^1.2.6" @@ -58622,7 +58641,6 @@ "version": "2.4.5", "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-2.4.5.tgz", "integrity": "sha512-J5xnxTyqaiw06JjMftq7L9ouA448dw/E7dKghkP9WpKNuwmARNNg+Gk8/u5ryb9N/Yo2+z3MCwuqFK/+qPOPfQ==", - "dev": true, "optional": true, "requires": { "glob": "^6.0.1" @@ -58791,7 +58809,7 @@ "version": "2.18.0", "resolved": "https://registry.npmjs.org/nan/-/nan-2.18.0.tgz", "integrity": "sha512-W7tfG7vMOGtD30sHoZSSc/JVYiyDPEyQVso/Zz+/uQd0B0L46gtC+pHha5FFMRpil6fm/AoEcRWyOVi4+E/f8w==", - "dev": true + "devOptional": true }, "nanomatch": { "version": "1.2.13", @@ -58869,7 +58887,6 @@ "version": "2.0.0", "resolved": "https://registry.npmjs.org/ncp/-/ncp-2.0.0.tgz", "integrity": "sha512-zIdGUrPRFTUELUvr3Gmc7KZ2Sw/h1PiVM0Af/oHB6zgnV1ikqSfRk+TOufi79aHYCW3NiOXmr1BP5nWbzojLaA==", - "dev": true, "optional": true }, "negotiator": { @@ -60242,7 +60259,7 @@ "version": "1.4.0", "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", "integrity": "sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w==", - "dev": true, + "devOptional": true, "requires": { "wrappy": "1" } @@ -60914,7 +60931,7 @@ "version": "1.0.1", "resolved": "https://registry.npmjs.org/path-is-absolute/-/path-is-absolute-1.0.1.tgz", "integrity": "sha512-AVbw3UJ2e9bq64vSaS9Am0fje1Pa8pbGqTTsmXfaIiMpnr5DlDhfJOuLj9Sf95ZPVDAUerDfEk88MPmPe7UCQg==", - "dev": true + "devOptional": true }, "path-key": { "version": "3.1.1", @@ -62533,7 +62550,6 @@ "version": "1.2.0", "resolved": "https://registry.npmjs.org/safe-json-stringify/-/safe-json-stringify-1.2.0.tgz", "integrity": "sha512-gH8eh2nZudPQO6TytOvbxnuhYBOvDBBLW52tz5q6X58lJcd/tkmqFR+5Z9adS8aJtURSXWThWy/xJtJwixErvg==", - "dev": true, "optional": true }, "safe-regex": { @@ -66466,7 +66482,7 @@ "version": "1.0.2", "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz", "integrity": "sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==", - "dev": true + "devOptional": true }, "write-file-atomic": { "version": "4.0.1", diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/README.md b/plugins/node/opentelemetry-instrumentation-bunyan/README.md index 4feb985aa12..c12b489658d 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/README.md +++ b/plugins/node/opentelemetry-instrumentation-bunyan/README.md @@ -3,7 +3,7 @@ [![NPM Published Version][npm-img]][npm-url] [![Apache License][license-image]][license-image] -This module provides automatic instrumentation for the injection of trace context to [`bunyan`](https://www.npmjs.com/package/bunyan), which may be loaded using the [`@opentelemetry/sdk-trace-node`](https://github.com/open-telemetry/opentelemetry-js/tree/main/packages/opentelemetry-sdk-trace-node) package and is included in the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle. +This module provides automatic instrumentation of the [`bunyan`](https://www.npmjs.com/package/bunyan) module to inject trace-context into Bunyan log records (log correlation) and to send Bunyan logging to the OpenTelemetry Logging SDK (log sending). It may be loaded using the [`@opentelemetry/sdk-trace-node`](https://github.com/open-telemetry/opentelemetry-js/tree/main/packages/opentelemetry-sdk-trace-node) package and is included in the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle. If total installation size is not constrained, it is recommended to use the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle with [@opentelemetry/sdk-node](`https://www.npmjs.com/package/@opentelemetry/sdk-node`) for the most seamless instrumentation experience. @@ -15,46 +15,106 @@ Compatible with OpenTelemetry JS API and SDK `1.0+`. npm install --save @opentelemetry/instrumentation-bunyan ``` -### Supported Versions +## Supported Versions -- `^1.0.0` +- `bunyan@^1.0.0` ## Usage ```js -const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node'); +const { NodeSDK, tracing, logs, api } = require('@opentelemetry/sdk-node'); const { BunyanInstrumentation } = require('@opentelemetry/instrumentation-bunyan'); -const { registerInstrumentations } = require('@opentelemetry/instrumentation'); - -const provider = new NodeTracerProvider(); -provider.register(); - -registerInstrumentations({ +const sdk = new NodeSDK({ + spanProcessor: new tracing.SimpleSpanProcessor(new tracing.ConsoleSpanExporter()), + logRecordProcessor: new logs.SimpleLogRecordProcessor(new logs.ConsoleLogRecordExporter()), instrumentations: [ new BunyanInstrumentation({ - // Optional hook to insert additional context to bunyan records. - // Called after trace context is added to the record. - logHook: (span, record) => { - record['resource.service.name'] = provider.resource.attributes['service.name']; - }, + // See below for Bunyan instrumentation options. }), - // other instrumentations - ], -}); - -bunyan.createLogger({ name: 'example' }).info('foo'); -// {"name":"example","msg":"foo","trace_id":"e21c7a95fff34e04f77c7bd518779621","span_id":"b7589a981fde09f4","trace_flags":"01", ...} + ] +}) + +const bunyan = require('bunyan'); +const logger = bunyan.createLogger({name: 'example'}); + +logger.info('hi'); +// 1. Log records will be sent to the SDK-registered log record processor, if any. +// This is called "log sending". + +const tracer = api.trace.getTracer('example'); +tracer.startActiveSpan('manual-span', span => { + logger.info('in a span'); + // 2. Fields identifying the current span will be added to log records: + // {"name":"example",...,"msg":"in a span","trace_id":"d61b4e4af1032e0aae279d12f3ab0159","span_id":"d140da862204f2a2","trace_flags":"01"} + // This is called "log correlation". +}) ``` -### Fields added to bunyan records +### Log sending + +Creation of a Bunyan Logger will automatically add a [Bunyan stream](https://github.com/trentm/node-bunyan#streams) that sends log records to the OpenTelemetry Logs SDK. The OpenTelemetry SDK can be configured to handle those records -- for example, sending them on to an OpenTelemetry collector for log archiving and processing. The example above shows a minimal configuration that emits OpenTelemetry log records to the console for debugging. -For the current active span, the following will be added to the bunyan record: +If the OpenTelemetry SDK is not configured with a Logger provider, then this added stream will be a no-op. + +Log sending can be disabled with the `disableLogSending: true` option. + +### Log correlation + +Bunyan logger calls in the context of a tracing span will have fields +indentifying the span added to the log record. This allows +[correlating](https://opentelemetry.io/docs/specs/otel/logs/#log-correlation) +log records with tracing data. The added fields are +([spec](https://opentelemetry.io/docs/specs/otel/compatibility/logging_trace_context/)): - `trace_id` - `span_id` - `trace_flags` +After adding these fields, the optional `logHook` is called to allow injecting additional fields. For example: + +```js + logHook: (span, record) => { + record['resource.service.name'] = provider.resource.attributes['service.name']; + } +``` + When no span context is active or the span context is invalid, injection is skipped. +Log injection can be disabled with the `disableLogCorrelation: true` option. + +### Bunyan instrumentation options + +| Option | Type | Description | +| ----------------------- | ----------------- | ----------- | +| `disableLogSending` | `boolean` | Whether to disable [log sending](#log-sending). Default `false`. | +| `disableLogCorrelation` | `boolean` | Whether to disable [log correlation](#log-correlation). Default `false`. | +| `logHook` | `LogHookFunction` | An option hook to inject additional context to a log record after trace-context has been added. This requires `disableLogCorrelation` to be false. | + +### Using OpenTelemetryBunyanStream without instrumentation + +This package exports the Bunyan stream class that is used to send records to the +OpenTelemetry Logs SDK. It can be used directly when configuring a Bunyan logger +if one is not using the `BunyanInstrumentation` for whatever reason. For +example: + +```js +const { OpenTelemetryBunyanStream } = require('@opentelemetry/instrumentation-bunyan'); +const bunyan = require('bunyan'); + +// You must register an OpenTelemetry LoggerProvider, otherwise log records will +// be sent to a no-op implementation. "examples/telemetry.js" shows one way +// to configure one. +// ... + +const logger = bunyan.createLogger({ + name: 'my-logger', + streams: [ + { + type: 'raw', + stream: new OpenTelemetryBunyanStream() + } + ], +}); +``` ## Useful links diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/examples/README.md b/plugins/node/opentelemetry-instrumentation-bunyan/examples/README.md new file mode 100644 index 00000000000..89041f4bb1d --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/examples/README.md @@ -0,0 +1,114 @@ +This is a small example app, "app.js", that shows using the +[Bunyan](https://github.com/trentm/node-bunyan) logger with OpenTelemetry. See +[the OpenTelemetry Bunyan instrumentation README](../) for full details. + +# Usage + +```bash +npm install +node -r ./telemetry.js app.js +``` + +# Overview + +"telemetry.js" sets up the OpenTelemetry SDK to write OTel tracing spans and +log records to the *console* for simplicity. In a real setup you would +configure exporters to send to remote observability apps for viewing and +analysis. + +An example run looks like this: + +```bash +$ node -r ./telemetry.js app.js +{"name":"myapp","hostname":"amachine.local","pid":93017,"level":20,"msg":"hi","time":"2023-09-27T23:24:06.074Z","v":0} +{ + timestamp: 1695857046074000, + traceId: undefined, + spanId: undefined, + traceFlags: undefined, + severityText: 'debug', + severityNumber: 5, + body: 'hi', + attributes: { name: 'myapp', foo: 'bar' } +} +{"name":"myapp","hostname":"amachine.local","pid":93017,"level":30,"msg":"this record will have trace_id et al fields for the current span","time":"2023-09-27T23:24:06.079Z","v":0,"trace_id":"af5ce23816c4feabb713ee1dc84ef4d3","span_id":"5f50e181ec7bc621","trace_flags":"01"} +{ + timestamp: 1695857046079000, + traceId: 'af5ce23816c4feabb713ee1dc84ef4d3', + spanId: '5f50e181ec7bc621', + traceFlags: 1, + severityText: 'info', + severityNumber: 9, + body: 'this record will have trace_id et al fields for the current span', + attributes: { + name: 'myapp', + trace_id: 'af5ce23816c4feabb713ee1dc84ef4d3', + span_id: '5f50e181ec7bc621', + trace_flags: '01' + } +} +{ + traceId: 'af5ce23816c4feabb713ee1dc84ef4d3', + parentId: undefined, + traceState: undefined, + name: 'manual-span', + id: '5f50e181ec7bc621', + kind: 0, + timestamp: 1695857046079000, + duration: 1407.196, + attributes: {}, + status: { code: 0 }, + events: [], + links: [] +} +``` + +There are two separate Bunyan instrumentation features. The first, called "log +correlation", is that Bunyan log records emitted in the context of a tracing +span will include `trace_id` and `span_id` fields that can be used for +correlating with collected tracing data. + +The second, called "log sending", is that a [Bunyan +stream](https://github.com/trentm/node-bunyan#streams) is automatically added +to created Loggers that will send every log record to the OpenTelemetry Logs +SDK. This means that if the OpenTelemetry SDK has been configured with a Logger +Provider, it will receive them. (If the OpenTelemetry SDK is not configured for +this, then the added Bunyan stream will be a no-op.) + +# Resource attributes + +One thing the `ConsoleLogRecordExporter` output above does not show is some +additional data that is included in exported log records: resource attributes. + +Every OpenTelemetry LoggerProvider has a "resource". The OpenTelemetry SDK +provides configurable "resource detectors" that collect data that is then +included with log records. This can include "host.name" (provided by the +`HostDetector`) and "process.pid" (provided by the `ProcessDetector`) -- which +is why this instrumentation does **not** include the Bunyan "hostname" and "pid" +fields in the log record attributes. + +When configured with the `HostDetector` and `ProcessDetector` (as shown in +"telemetry.js") the log records above also include resource attributes such +as the following: + +```js +{ + 'process.pid': 93017, + 'process.executable.name': 'node', + 'process.executable.path': '/Users/trentm/.nvm/versions/node/v18.18.2/bin/node', + 'process.command_args': [ + '/Users/trentm/.nvm/versions/node/v18.18.2/bin/node', + '-r', + './telemetry.js', + '/Users/trentm/src/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js' + ], + 'process.runtime.version': '18.18.2', + 'process.runtime.name': 'nodejs', + 'process.runtime.description': 'Node.js', + 'process.command': '/Users/trentm/src/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js', + 'process.owner': 'trentm' + 'host.name': 'amachine.local', + 'host.arch': 'amd64', + 'host.id': '...' +} +``` diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js b/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js new file mode 100644 index 00000000000..05214a80738 --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.js @@ -0,0 +1,32 @@ +/* + * Copyright The OpenTelemetry Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +// A small example that shows using OpenTelemetry's instrumentation of +// Bunyan loggers. Usage: +// node --require ./telemetry.js app.js + +const otel = require('@opentelemetry/api'); +const bunyan = require('bunyan'); + +const log = bunyan.createLogger({name: 'myapp', level: 'debug'}); + +log.debug({foo: 'bar'}, 'hi'); + +const tracer = otel.trace.getTracer('example'); +tracer.startActiveSpan('manual-span', span => { + log.info('this record will have trace_id et al fields for the current span'); + span.end(); +}); diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.mjs b/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.mjs new file mode 100644 index 00000000000..c20d5ff05bf --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/examples/app.mjs @@ -0,0 +1,33 @@ +/* + * Copyright The OpenTelemetry Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +// The equivalent of "app.js", but showing usage with ESM code. +// Usage: +// node --require ./telemetry.js --experimental-loader ../node_modules/@opentelemetry/instrumentation/hook.mjs app.js + +import { trace } from '@opentelemetry/api'; +import bunyan from 'bunyan'; + +const log = bunyan.createLogger({name: 'myapp', level: 'debug'}); + +log.debug({foo: 'bar'}, 'hi'); + +const tracer = trace.getTracer('example'); +tracer.startActiveSpan('manual-span', span => { + log.info('this record will have trace_id et al fields for the current span'); + span.end(); +}); + diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/examples/package.json b/plugins/node/opentelemetry-instrumentation-bunyan/examples/package.json new file mode 100644 index 00000000000..ccd208cd8cd --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/examples/package.json @@ -0,0 +1,26 @@ +{ + "name": "bunyan-example", + "private": true, + "version": "0.45.1", + "description": "Example of Bunyan integration with OpenTelemetry", + "scripts": { + "start": "node -r ./telemetry.js app.js" + }, + "repository": { + "type": "git", + "url": "git+ssh://git@github.com/open-telemetry/opentelemetry-js.git" + }, + "engines": { + "node": ">=14" + }, + "author": "OpenTelemetry Authors", + "license": "Apache-2.0", + "// @opentelemetry/instrumentation-bunyan": "TODO: change to a ver when there is a next release", + "dependencies": { + "@opentelemetry/api": "^1.3.0", + "@opentelemetry/instrumentation-bunyan": "../", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-node": "^0.45.1", + "bunyan": "^1.8.15" + } +} diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/examples/telemetry.js b/plugins/node/opentelemetry-instrumentation-bunyan/examples/telemetry.js new file mode 100644 index 00000000000..20f84ee7d14 --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/examples/telemetry.js @@ -0,0 +1,56 @@ +/* + * Copyright The OpenTelemetry Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +// Setup telemetry for tracing and Bunyan logging. +// +// This writes OTel spans and log records to the console for simplicity. In a +// real setup you would configure exporters to send to remote observability apps +// for viewing and analysis. + +const { NodeSDK, tracing, logs, api } = require('@opentelemetry/sdk-node'); +const { envDetectorSync, hostDetectorSync, processDetectorSync } = require('@opentelemetry/resources'); +// api.diag.setLogger(new api.DiagConsoleLogger(), api.DiagLogLevel.DEBUG); + +const { BunyanInstrumentation } = require('@opentelemetry/instrumentation-bunyan'); + +const sdk = new NodeSDK({ + serviceName: 'bunyan-example', + resourceDetectors: [ + envDetectorSync, + // ProcessDetector adds `process.pid` (among other resource attributes), + // which replaces the usual Bunyan `pid` field. + processDetectorSync, + // The HostDetector adds `host.name` and `host.arch` fields. `host.name` + // replaces the usual Bunyan `hostname` field. HostDetector is *not* a + // default detector of the `NodeSDK`. + hostDetectorSync + ], + spanProcessor: new tracing.SimpleSpanProcessor(new tracing.ConsoleSpanExporter()), + logRecordProcessor: new logs.SimpleLogRecordProcessor(new logs.ConsoleLogRecordExporter()), + instrumentations: [ + new BunyanInstrumentation(), + ] +}) +process.on("SIGTERM", () => { + sdk + .shutdown() + .then( + () => {}, + (err) => console.log("warning: error shutting down OTel SDK", err) + ) + .finally(() => process.exit(0)); +}); +sdk.start(); diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/package.json b/plugins/node/opentelemetry-instrumentation-bunyan/package.json index b192707782a..52a2ed161a5 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/package.json +++ b/plugins/node/opentelemetry-instrumentation-bunyan/package.json @@ -45,9 +45,11 @@ }, "devDependencies": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/resources": "^1.8.0", + "@opentelemetry/sdk-logs": "^0.45.1", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", + "@opentelemetry/semantic-conventions": "^1.0.0", "@types/mocha": "7.0.2", "@types/node": "18.6.5", "@types/sinon": "10.0.18", @@ -61,6 +63,7 @@ "typescript": "4.4.4" }, "dependencies": { + "@opentelemetry/api-logs": "^0.45.1", "@opentelemetry/instrumentation": "^0.45.1", "@types/bunyan": "1.8.9" }, diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/src/OpenTelemetryBunyanStream.ts b/plugins/node/opentelemetry-instrumentation-bunyan/src/OpenTelemetryBunyanStream.ts new file mode 100644 index 00000000000..8b3d1c8977b --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-bunyan/src/OpenTelemetryBunyanStream.ts @@ -0,0 +1,162 @@ +/* + * Copyright The OpenTelemetry Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import { logs, SeverityNumber, Logger } from '@opentelemetry/api-logs'; +import type { LogLevelString } from 'bunyan'; +import { VERSION } from './version'; + +const DEFAULT_INSTRUMENTATION_SCOPE_NAME = + '@opentelemetry/instrumentation-bunyan'; +const DEFAULT_INSTRUMENTATION_SCOPE_VERSION = VERSION; + +// This block is a copy (modulo code style and TypeScript types) of the Bunyan +// code that defines log level value and names. These values won't ever change +// in bunyan@1. This file is part of *instrumenting* Bunyan, so we want to +// avoid a dependency on the library. +const TRACE = 10; +const DEBUG = 20; +const INFO = 30; +const WARN = 40; +const ERROR = 50; +const FATAL = 60; +const levelFromName: Record = { + trace: TRACE, + debug: DEBUG, + info: INFO, + warn: WARN, + error: ERROR, + fatal: FATAL, +}; +const nameFromLevel: { [level: number]: string } = {}; +Object.keys(levelFromName).forEach(function (name) { + nameFromLevel[levelFromName[name as LogLevelString]] = name; +}); + +const OTEL_SEV_NUM_FROM_BUNYAN_LEVEL: { [level: number]: SeverityNumber } = { + [TRACE]: SeverityNumber.TRACE, + [DEBUG]: SeverityNumber.DEBUG, + [INFO]: SeverityNumber.INFO, + [WARN]: SeverityNumber.WARN, + [ERROR]: SeverityNumber.ERROR, + [FATAL]: SeverityNumber.FATAL, +}; + +const EXTRA_SEV_NUMS = [ + SeverityNumber.TRACE2, + SeverityNumber.TRACE3, + SeverityNumber.TRACE4, + SeverityNumber.DEBUG2, + SeverityNumber.DEBUG3, + SeverityNumber.DEBUG4, + SeverityNumber.INFO2, + SeverityNumber.INFO3, + SeverityNumber.INFO4, + SeverityNumber.WARN2, + SeverityNumber.WARN3, + SeverityNumber.WARN4, + SeverityNumber.ERROR2, + SeverityNumber.ERROR3, + SeverityNumber.ERROR4, + SeverityNumber.FATAL2, + SeverityNumber.FATAL3, + SeverityNumber.FATAL4, +]; + +function severityNumberFromBunyanLevel(lvl: number) { + // Fast common case: one of the known levels + const sev = OTEL_SEV_NUM_FROM_BUNYAN_LEVEL[lvl]; + if (sev !== undefined) { + return sev; + } + + // Otherwise, scale the Bunyan level range -- 10 (TRACE) to 70 (FATAL+10) + // -- onto the extra OTel severity numbers (TRACE2, TRACE3, ..., FATAL4). + // Values below bunyan.TRACE map to SeverityNumber.TRACE2, which may be + // considered a bit weird, but it means the unnumbered levels are always + // just for exactly values. + const relativeLevelWeight = (lvl - 10) / (70 - 10); + const otelSevIdx = Math.floor(relativeLevelWeight * EXTRA_SEV_NUMS.length); + const cappedOTelIdx = Math.min( + EXTRA_SEV_NUMS.length - 1, + Math.max(0, otelSevIdx) + ); + const otelSevValue = EXTRA_SEV_NUMS[cappedOTelIdx]; + return otelSevValue; +} + +/** + * A Bunyan stream for sending log records to the OpenTelemetry Logs SDK. + */ +export class OpenTelemetryBunyanStream { + private _otelLogger: Logger; + + constructor() { + this._otelLogger = logs.getLogger( + DEFAULT_INSTRUMENTATION_SCOPE_NAME, + DEFAULT_INSTRUMENTATION_SCOPE_VERSION + ); + } + + /** + * Convert from https://github.com/trentm/node-bunyan#log-record-fields + * to https://opentelemetry.io/docs/specs/otel/logs/data-model/ + * + * Dev Notes: + * - We drop the Bunyan 'v' field. It is meant to indicate the format + * of the Bunyan log record. FWIW, it has always been `0`. + * - The standard Bunyan `hostname` and `pid` fields are removed because they + * are redundant with the OpenTelemetry `host.name` and `process.pid` + * Resource attributes, respectively. This code cannot change the + * LoggerProvider's `resource`, so getting the OpenTelemetry equivalents + * depends on the user using relevant OpenTelemetry resource detectors. + * "examples/telemetry.js" shows using HostDetector and ProcessDetector for + * this. + * - The Bunyan `name` field *could* naturally map to OpenTelemetry's + * `service.name` resource attribute. However, that is debatable, as some + * users might use `name` more like a log4j logger name. + * - Strip the `trace_id` et al fields that may have been added by the + * the _emit wrapper. + */ + write(rec: Record) { + const { + time, + level, + msg, + v, // eslint-disable-line @typescript-eslint/no-unused-vars + hostname, // eslint-disable-line @typescript-eslint/no-unused-vars + pid, // eslint-disable-line @typescript-eslint/no-unused-vars + trace_id, // eslint-disable-line @typescript-eslint/no-unused-vars + span_id, // eslint-disable-line @typescript-eslint/no-unused-vars + trace_flags, // eslint-disable-line @typescript-eslint/no-unused-vars + ...fields + } = rec; + let timestamp = undefined; + if (typeof time.getTime === 'function') { + timestamp = time.getTime(); // ms + } else { + fields.time = time; // Expose non-Date "time" field on attributes. + } + const otelRec = { + timestamp, + observedTimestamp: timestamp, + severityNumber: severityNumberFromBunyanLevel(level), + severityText: nameFromLevel[level], + body: msg, + attributes: fields, + }; + this._otelLogger.emit(otelRec); + } +} diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/src/index.ts b/plugins/node/opentelemetry-instrumentation-bunyan/src/index.ts index c26f998cff6..2418a3b9308 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/src/index.ts +++ b/plugins/node/opentelemetry-instrumentation-bunyan/src/index.ts @@ -16,3 +16,4 @@ export * from './instrumentation'; export * from './types'; +export * from './OpenTelemetryBunyanStream'; diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts index 0a3a8102a76..c78e27b50be 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts @@ -14,22 +14,32 @@ * limitations under the License. */ +import { inherits } from 'util'; import { context, trace, isSpanContextValid, Span } from '@opentelemetry/api'; import { InstrumentationBase, InstrumentationNodeModuleDefinition, - isWrapped, safeExecuteInTheMiddle, } from '@opentelemetry/instrumentation'; import { BunyanInstrumentationConfig } from './types'; import { VERSION } from './version'; +import { OpenTelemetryBunyanStream } from './OpenTelemetryBunyanStream'; import type * as BunyanLogger from 'bunyan'; +const DEFAULT_CONFIG: BunyanInstrumentationConfig = { + disableLogSending: false, + disableLogCorrelation: false, +}; + export class BunyanInstrumentation extends InstrumentationBase< typeof BunyanLogger > { constructor(config: BunyanInstrumentationConfig = {}) { - super('@opentelemetry/instrumentation-bunyan', VERSION, config); + super( + '@opentelemetry/instrumentation-bunyan', + VERSION, + Object.assign({}, DEFAULT_CONFIG, config) + ); } protected init() { @@ -37,27 +47,55 @@ export class BunyanInstrumentation extends InstrumentationBase< new InstrumentationNodeModuleDefinition( 'bunyan', ['<2.0'], - (logger, moduleVersion) => { + (module: any, moduleVersion) => { this._diag.debug(`Applying patch for bunyan@${moduleVersion}`); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - const proto = logger.prototype as any; - if (isWrapped(proto['_emit'])) { - this._unwrap(proto, '_emit'); - } + const instrumentation = this; + const Logger = + module[Symbol.toStringTag] === 'Module' + ? module.default // ESM + : module; // CommonJS this._wrap( - proto, + Logger.prototype, '_emit', // eslint-disable-next-line @typescript-eslint/no-explicit-any this._getPatchedEmit() as any ); - return logger; - }, - (logger, moduleVersion) => { - if (logger === undefined) return; - this._diag.debug(`Removing patch for bunyan@${moduleVersion}`); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - this._unwrap(logger.prototype as any, '_emit'); + + function LoggerTraced(this: any, ...args: unknown[]) { + let inst; + let retval = undefined; + if (this instanceof LoggerTraced) { + // called with `new Logger()` + inst = this; + Logger.apply(this, args); + } else { + // called without `new` + inst = Logger(...args); + retval = inst; + } + // If `_childOptions` is defined, this is a `Logger#child(...)` + // call. We must not add an OTel stream again. + if (args[1] /* _childOptions */ === undefined) { + instrumentation._addStream(inst); + } + return retval; + } + // Must use the deprecated `inherits` to support this style: + // const log = require('bunyan')({name: 'foo'}); + // i.e. calling the constructor function without `new`. + inherits(LoggerTraced, Logger); + + const patchedExports = Object.assign(LoggerTraced, Logger); + + this._wrap( + patchedExports, + 'createLogger', + // eslint-disable-next-line @typescript-eslint/no-explicit-any + this._getPatchedCreateLogger() as any + ); + + return patchedExports; } ), ]; @@ -68,21 +106,24 @@ export class BunyanInstrumentation extends InstrumentationBase< } override setConfig(config: BunyanInstrumentationConfig) { - this._config = config; + this._config = Object.assign({}, DEFAULT_CONFIG, config); } private _getPatchedEmit() { return (original: (...args: unknown[]) => void) => { const instrumentation = this; return function patchedEmit(this: BunyanLogger, ...args: unknown[]) { - const span = trace.getSpan(context.active()); + const config = instrumentation.getConfig(); + if (!instrumentation.isEnabled() || config.disableLogCorrelation) { + return original.apply(this, args); + } + const span = trace.getSpan(context.active()); if (!span) { return original.apply(this, args); } const spanContext = span.spanContext(); - if (!isSpanContextValid(spanContext)) { return original.apply(this, args); } @@ -99,6 +140,30 @@ export class BunyanInstrumentation extends InstrumentationBase< }; } + private _getPatchedCreateLogger() { + return (original: (...args: unknown[]) => void) => { + const instrumentation = this; + return function patchedCreateLogger(...args: unknown[]) { + const logger = original(...args); + instrumentation._addStream(logger); + return logger; + }; + }; + } + + private _addStream(logger: any) { + const config: BunyanInstrumentationConfig = this.getConfig(); + if (!this.isEnabled() || config.disableLogSending) { + return; + } + this._diag.debug('Adding OpenTelemetryBunyanStream to logger'); + logger.addStream({ + type: 'raw', + stream: new OpenTelemetryBunyanStream(), + level: logger.level(), + }); + } + private _callHook(span: Span, record: Record) { const hook = this.getConfig().logHook; diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/src/types.ts b/plugins/node/opentelemetry-instrumentation-bunyan/src/types.ts index 1e1559b463d..7a2f5f686b6 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/src/types.ts +++ b/plugins/node/opentelemetry-instrumentation-bunyan/src/types.ts @@ -21,5 +21,24 @@ import { InstrumentationConfig } from '@opentelemetry/instrumentation'; export type LogHookFunction = (span: Span, record: Record) => void; export interface BunyanInstrumentationConfig extends InstrumentationConfig { + /** + * Whether to disable the automatic sending of log records to the + * OpenTelemetry Logs SDK. + * @default false + */ + disableLogSending?: boolean; + + /** + * Whether to disable the injection trace-context fields, and possibly other + * fields from `logHook()`, into log records for log correlation. + * @default false + */ + disableLogCorrelation?: boolean; + + /** + * A function that allows injecting additional fields in log records. It is + * called, as `logHook(span, record)`, for each log record emitted in a valid + * span context. It requires `disableLogCorrelation` to be false. + */ logHook?: LogHookFunction; } diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/test/bunyan.test.ts b/plugins/node/opentelemetry-instrumentation-bunyan/test/bunyan.test.ts index e82b9126382..5ca3744d3da 100644 --- a/plugins/node/opentelemetry-instrumentation-bunyan/test/bunyan.test.ts +++ b/plugins/node/opentelemetry-instrumentation-bunyan/test/bunyan.test.ts @@ -19,47 +19,73 @@ import { SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; import { context, INVALID_SPAN_CONTEXT, trace } from '@opentelemetry/api'; +import { logs, SeverityNumber } from '@opentelemetry/api-logs'; +import { + LoggerProvider, + SimpleLogRecordProcessor, + InMemoryLogRecordExporter, +} from '@opentelemetry/sdk-logs'; import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import { isWrapped } from '@opentelemetry/instrumentation'; -import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; +import { Resource } from '@opentelemetry/resources'; +import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'; import * as assert from 'assert'; -import * as Logger from 'bunyan'; import * as sinon from 'sinon'; import { Writable } from 'stream'; -import { BunyanInstrumentation } from '../src'; +import { BunyanInstrumentation, OpenTelemetryBunyanStream } from '../src'; +import { VERSION } from '../src/version'; + +import type * as BunyanLogger from 'bunyan'; + +// import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api'; +// diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG); + +const tracerProvider = new NodeTracerProvider(); +tracerProvider.register(); +tracerProvider.addSpanProcessor( + new SimpleSpanProcessor(new InMemorySpanExporter()) +); +const tracer = tracerProvider.getTracer('default'); + +const resource = new Resource({ + [SemanticResourceAttributes.SERVICE_NAME]: 'test-instrumentation-bunyan', +}); +const loggerProvider = new LoggerProvider({ resource }); +const memExporter = new InMemoryLogRecordExporter(); +loggerProvider.addLogRecordProcessor(new SimpleLogRecordProcessor(memExporter)); +logs.setGlobalLoggerProvider(loggerProvider); -const memoryExporter = new InMemorySpanExporter(); -const provider = new NodeTracerProvider(); -const tracer = provider.getTracer('default'); -provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter)); -context.setGlobalContextManager(new AsyncHooksContextManager()); +const instrumentation = new BunyanInstrumentation(); +const Logger = require('bunyan'); describe('BunyanInstrumentation', () => { - let logger: Logger; - let stream; + let log: BunyanLogger; + let stream: Writable; let writeSpy: sinon.SinonSpy; - let instrumentation: BunyanInstrumentation; - before(() => { - instrumentation = new BunyanInstrumentation(); - require('bunyan'); + it('is instrumented', () => { assert.ok(isWrapped((Logger.prototype as any)['_emit'])); }); describe('enabled instrumentation', () => { beforeEach(() => { - instrumentation.setConfig({ enabled: true }); + instrumentation.setConfig({}); // reset to defaults + memExporter.getFinishedLogRecords().length = 0; // clear stream = new Writable(); stream._write = () => {}; writeSpy = sinon.spy(stream, 'write'); - logger = Logger.createLogger({ name: 'test', stream }); + log = Logger.createLogger({ + name: 'test-logger-name', + level: 'debug', + stream, + }); }); it('injects span context to records', () => { const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { const { traceId, spanId, traceFlags } = span.spanContext(); - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['trace_id'], traceId); @@ -73,16 +99,15 @@ describe('BunyanInstrumentation', () => { }); }); - it('calls the users log hook', () => { + it('calls the logHook', () => { const span = tracer.startSpan('abc'); instrumentation.setConfig({ - enabled: true, logHook: (_span, record) => { record['resource.service.name'] = 'test-service'; }, }); context.with(trace.setSpan(context.active(), span), () => { - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['resource.service.name'], 'test-service'); @@ -90,7 +115,7 @@ describe('BunyanInstrumentation', () => { }); it('does not inject span context if no span is active', () => { - logger.info('foo'); + log.info('foo'); assert.strictEqual(trace.getSpan(context.active()), undefined); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); @@ -103,7 +128,7 @@ describe('BunyanInstrumentation', () => { it('does not inject span context if span context is invalid', () => { const span = trace.wrapSpanContext(INVALID_SPAN_CONTEXT); context.with(trace.setSpan(context.active(), span), () => { - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['trace_id'], undefined); @@ -113,17 +138,16 @@ describe('BunyanInstrumentation', () => { }); }); - it('does not propagate exceptions from user hooks', () => { + it('does not propagate exceptions from logHook', () => { const span = tracer.startSpan('abc'); instrumentation.setConfig({ - enabled: true, logHook: () => { throw new Error('Oops'); }, }); context.with(trace.setSpan(context.active(), span), () => { const { traceId, spanId } = span.spanContext(); - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['trace_id'], traceId); @@ -131,6 +155,170 @@ describe('BunyanInstrumentation', () => { assert.strictEqual('foo', record['msg']); }); }); + + it('does not inject or call logHook if disableLogCorrelation=true', () => { + instrumentation.setConfig({ + disableLogCorrelation: true, + logHook: (_span, record) => { + record['resource.service.name'] = 'test-service'; + }, + }); + tracer.startActiveSpan('abc', span => { + log.info('foo'); + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual('foo', record['msg']); + assert.strictEqual(record['trace_id'], undefined); + assert.strictEqual(record['span_id'], undefined); + assert.strictEqual(record['trace_flags'], undefined); + assert.strictEqual(record['resource.service.name'], undefined); + assert.strictEqual( + memExporter.getFinishedLogRecords().length, + 1, + 'Log sending still works' + ); + span.end(); + }); + }); + + it('emits log records to Logs SDK', () => { + const logRecords = memExporter.getFinishedLogRecords(); + + // levels + log.trace('at trace level'); + log.debug('at debug level'); + log.info('at info level'); + log.warn('at warn level'); + log.error('at error level'); + log.fatal('at fatal level'); + assert.strictEqual(logRecords.length, 5); + assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.DEBUG); + assert.strictEqual(logRecords[0].severityText, 'debug'); + assert.strictEqual(logRecords[1].severityNumber, SeverityNumber.INFO); + assert.strictEqual(logRecords[1].severityText, 'info'); + assert.strictEqual(logRecords[2].severityNumber, SeverityNumber.WARN); + assert.strictEqual(logRecords[2].severityText, 'warn'); + assert.strictEqual(logRecords[3].severityNumber, SeverityNumber.ERROR); + assert.strictEqual(logRecords[3].severityText, 'error'); + assert.strictEqual(logRecords[4].severityNumber, SeverityNumber.FATAL); + assert.strictEqual(logRecords[4].severityText, 'fatal'); + + // attributes, resource, instrumentationScope, etc. + log.info({ foo: 'bar' }, 'a message'); + const rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'a message'); + assert.deepStrictEqual(rec.attributes, { + name: 'test-logger-name', + foo: 'bar', + }); + assert.strictEqual( + rec.resource.attributes['service.name'], + 'test-instrumentation-bunyan' + ); + assert.strictEqual( + rec.instrumentationScope.name, + '@opentelemetry/instrumentation-bunyan' + ); + assert.strictEqual(rec.instrumentationScope.version, VERSION); + assert.strictEqual(rec.spanContext, undefined); + + // spanContext + tracer.startActiveSpan('abc', span => { + const { traceId, spanId, traceFlags } = span.spanContext(); + log.info('in active span'); + const rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.spanContext?.traceId, traceId); + assert.strictEqual(rec.spanContext?.spanId, spanId); + assert.strictEqual(rec.spanContext?.traceFlags, traceFlags); + + // This rec should *NOT* have the `trace_id` et al attributes. + assert.strictEqual(rec.attributes.trace_id, undefined); + assert.strictEqual(rec.attributes.span_id, undefined); + assert.strictEqual(rec.attributes.trace_flags, undefined); + + span.end(); + }); + }); + + it('handles log record edge cases', () => { + let rec; + const logRecords = memExporter.getFinishedLogRecords(); + + // A non-Date "time" Bunyan field. + log.info({ time: 'miller' }, 'hi'); + rec = logRecords[logRecords.length - 1]; + assert.deepEqual( + rec.hrTime.map(n => typeof n), + ['number', 'number'] + ); + assert.strictEqual(rec.attributes.time, 'miller'); + + // An atypical Bunyan level number. + log.info({ level: 42 }, 'just above Bunyan WARN==40'); + rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.severityNumber, SeverityNumber.WARN2); + assert.strictEqual(rec.severityText, undefined); + + log.info({ level: 200 }, 'far above Bunyan FATAL==60'); + rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.severityNumber, SeverityNumber.FATAL4); + assert.strictEqual(rec.severityText, undefined); + }); + + it('does not emit to the Logs SDK if disableLogSending=true', () => { + instrumentation.setConfig({ disableLogSending: true }); + + // Changing `disableLogSending` only has an impact on Loggers created + // *after* it is set. So we cannot test with the `log` created in + // `beforeEach()` above. + log = Logger.createLogger({ name: 'test-logger-name', stream }); + + tracer.startActiveSpan('abc', span => { + const { traceId, spanId } = span.spanContext(); + log.info('foo'); + assert.strictEqual(memExporter.getFinishedLogRecords().length, 0); + + // Test log correlation still works. + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual('foo', record['msg']); + assert.strictEqual(record['trace_id'], traceId); + assert.strictEqual(record['span_id'], spanId); + span.end(); + }); + }); + + it('emits to the Logs SDK with `new Logger(...)`', () => { + log = new Logger({ name: 'test-logger-name', stream }); + log.info('foo'); + + const logRecords = memExporter.getFinishedLogRecords(); + assert.strictEqual(logRecords.length, 1); + let rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'foo'); + + const child = log.child({ aProperty: 'bar' }); + child.info('hi'); + rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'hi'); + assert.strictEqual(rec.attributes.aProperty, 'bar'); + }); + + it('emits to the Logs SDK with `Logger(...)`', () => { + log = Logger({ name: 'test-logger-name', stream }); + log.info('foo'); + + const logRecords = memExporter.getFinishedLogRecords(); + assert.strictEqual(logRecords.length, 1); + let rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'foo'); + + const child = log.child({ aProperty: 'bar' }); + child.info('hi'); + rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'hi'); + assert.strictEqual(rec.attributes.aProperty, 'bar'); + }); }); describe('disabled instrumentation', () => { @@ -146,13 +334,14 @@ describe('BunyanInstrumentation', () => { stream = new Writable(); stream._write = () => {}; writeSpy = sinon.spy(stream, 'write'); - logger = Logger.createLogger({ name: 'test', stream }); + log = Logger.createLogger({ name: 'test', stream }); + memExporter.getFinishedLogRecords().length = 0; // clear }); it('does not inject span context', () => { const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['trace_id'], undefined); @@ -166,17 +355,102 @@ describe('BunyanInstrumentation', () => { it('does not call log hook', () => { const span = tracer.startSpan('abc'); instrumentation.setConfig({ - enabled: false, logHook: (_span, record) => { record['resource.service.name'] = 'test-service'; }, }); context.with(trace.setSpan(context.active(), span), () => { - logger.info('foo'); + log.info('foo'); sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); assert.strictEqual(record['resource.service.name'], undefined); }); }); + + it('does not emit to the Logs SDK', () => { + tracer.startActiveSpan('abc', span => { + log.info('foo'); + assert.strictEqual(memExporter.getFinishedLogRecords().length, 0); + }); + }); + }); +}); + +describe('OpenTelemetryBunyanStream', () => { + before(() => { + instrumentation.disable(); + }); + + beforeEach(() => { + memExporter.getFinishedLogRecords().length = 0; // clear + }); + + it('can be used directly with createLogger', () => { + const log = Logger.createLogger({ + name: 'test-logger-name', + streams: [ + { + type: 'raw', + stream: new OpenTelemetryBunyanStream(), + level: 'debug', + }, + ], + }); + + // levels + log.trace('at trace level'); + log.debug('at debug level'); + log.info('at info level'); + log.warn('at warn level'); + log.error('at error level'); + log.fatal('at fatal level'); + const logRecords = memExporter.getFinishedLogRecords(); + assert.strictEqual(logRecords.length, 5); + assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.DEBUG); + assert.strictEqual(logRecords[0].severityText, 'debug'); + assert.strictEqual(logRecords[1].severityNumber, SeverityNumber.INFO); + assert.strictEqual(logRecords[1].severityText, 'info'); + assert.strictEqual(logRecords[2].severityNumber, SeverityNumber.WARN); + assert.strictEqual(logRecords[2].severityText, 'warn'); + assert.strictEqual(logRecords[3].severityNumber, SeverityNumber.ERROR); + assert.strictEqual(logRecords[3].severityText, 'error'); + assert.strictEqual(logRecords[4].severityNumber, SeverityNumber.FATAL); + assert.strictEqual(logRecords[4].severityText, 'fatal'); + + // attributes, resource, instrumentationScope, etc. + log.info({ foo: 'bar' }, 'a message'); + const rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.body, 'a message'); + assert.deepStrictEqual(rec.attributes, { + name: 'test-logger-name', + foo: 'bar', + }); + assert.strictEqual( + rec.resource.attributes['service.name'], + 'test-instrumentation-bunyan' + ); + assert.strictEqual( + rec.instrumentationScope.name, + '@opentelemetry/instrumentation-bunyan' + ); + assert.strictEqual(rec.instrumentationScope.version, VERSION); + assert.strictEqual(rec.spanContext, undefined); + + // spanContext + tracer.startActiveSpan('abc', span => { + const { traceId, spanId, traceFlags } = span.spanContext(); + log.info('in active span'); + const rec = logRecords[logRecords.length - 1]; + assert.strictEqual(rec.spanContext?.traceId, traceId); + assert.strictEqual(rec.spanContext?.spanId, spanId); + assert.strictEqual(rec.spanContext?.traceFlags, traceFlags); + + // This rec should *NOT* have the `trace_id` et al attributes. + assert.strictEqual(rec.attributes.trace_id, undefined); + assert.strictEqual(rec.attributes.span_id, undefined); + assert.strictEqual(rec.attributes.trace_flags, undefined); + + span.end(); + }); }); });