diff --git a/package-lock.json b/package-lock.json index 0bcce7b048..fff718c45b 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 4feb985aa1..c12b489658 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 0000000000..89041f4bb1 --- /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 0000000000..05214a8073 --- /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 0000000000..c20d5ff05b --- /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 0000000000..ccd208cd8c --- /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 0000000000..20f84ee7d1 --- /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 b192707782..52a2ed161a 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 0000000000..8b3d1c8977 --- /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 c26f998cff..2418a3b930 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 0a3a8102a7..c78e27b50b 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 1e1559b463..7a2f5f686b 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 e82b912638..5ca3744d3d 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(); + }); }); });