Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
38 commits
Select commit Hold shift + click to select a range
59f11f3
feat(instrumentation-bunyan): add log sending to Logs Bridge API
trentm Sep 22, 2023
7d8a21f
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Oct 3, 2023
03c1c16
markdown lint fixes
trentm Oct 3, 2023
3fbfc0c
markdown lint fixes
trentm Oct 3, 2023
57b6628
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Oct 15, 2023
d5a92d1
catch up with recent core-deps update
trentm Oct 15, 2023
5b9aecb
some type tweaks suggested by David
trentm Oct 15, 2023
e3ed22c
more specific type
trentm Nov 8, 2023
bd507e2
use more self-explanatory code for mapping Bunyan level to OTel sever…
trentm Nov 8, 2023
45f2b1d
export OpenTelemetryBunyanStream for direct usage in Bunyan loggers w…
trentm Nov 8, 2023
7d1532f
.apply over .call suggestion
trentm Nov 8, 2023
ed9ddaf
consistency suggestion
trentm Nov 8, 2023
0f77516
suggestion to use the longer (perhaps clearer) logger var name
trentm Nov 8, 2023
aa81256
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Nov 8, 2023
4c94dba
switch to false-by-default config vars to avoid surprises with undefi…
trentm Nov 8, 2023
21e3a55
document using OpenTelemetryBunyanStream without the instrumentation
trentm Nov 8, 2023
44d20bd
fix https://eslint.org/docs/latest/rules/prefer-spread lint error
trentm Nov 9, 2023
751f95a
drop options to OpenTelemetryBunyanStream constructor because YAGNI
trentm Nov 9, 2023
43ab672
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Nov 9, 2023
2f0a89a
temporarily drop CI caching to test theory on unit-test (18) CI failure
trentm Nov 9, 2023
c283178
more CI debugging: restore cache, add some 'npm ls -a' to look into N…
trentm Nov 9, 2023
3638f72
elide Bunyan 'pid' and 'hostname' fields in OTel log record attributes
trentm Nov 9, 2023
303b6ab
update test for having elided 'pid' and 'hostname' fields
trentm Nov 9, 2023
018118e
CI debugging: ignore the 'npm ls -a' exit status, they shouldn't brea…
trentm Nov 9, 2023
284e4d6
fix lint and compile errors
trentm Nov 9, 2023
7fc0842
CI debugging: turn on diag DEBUG to test a theory
trentm Nov 10, 2023
54d2477
turn off diag in this example
trentm Nov 11, 2023
6de5de1
undo CI debugging changes
trentm Nov 11, 2023
bb9b2e4
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Nov 11, 2023
af2a216
Merge branch 'main' into trentm/logs-bridge-bunyan
hectorhdzg Nov 20, 2023
f3c4d03
update deps to current releases and sync package-lock.json
trentm Nov 21, 2023
c740b76
disableInjection -> disableLogCorrelation
trentm Nov 22, 2023
f850a63
disableLogsBridge -> disableLogSending
trentm Nov 23, 2023
45cbb8b
Merge branch 'main' into trentm/logs-bridge-bunyan
trentm Nov 23, 2023
b597a92
Merge branch 'main' into trentm/logs-bridge-bunyan
hectorhdzg Nov 27, 2023
39b8507
correct the default instrumentation scope name (as discussed earlier)
trentm Nov 27, 2023
a149912
tests: fix test for intrumentationScope.name change in previous commit
trentm Nov 27, 2023
ca18034
fix lint
trentm Nov 27, 2023
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
Next Next commit
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.
  • Loading branch information
trentm committed Nov 9, 2023
commit 3638f7212b901b235c3445e78334bc433e9e1671
Original file line number Diff line number Diff line change
Expand Up @@ -34,13 +34,14 @@ const sdk = new NodeSDK({
]
})

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 "bridging".

const tracer = api.getTracer('example');
const tracer = api.trace.getTracer('example');
tracer.startActiveSpan('manual-span', span => {
logger.info('in a span');
// 2. Fields identifying the current span will be injected into log records:
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ $ node -r ./telemetry.js app.js
severityText: 'debug',
severityNumber: 5,
body: 'hi',
attributes: { name: 'myapp', hostname: 'amachine.local', pid: 93017 }
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"}
{
Expand All @@ -42,8 +42,6 @@ $ node -r ./telemetry.js app.js
body: 'this record will have trace_id et al fields for the current span',
attributes: {
name: 'myapp',
hostname: 'amachine.local',
pid: 93017,
trace_id: 'af5ce23816c4feabb713ee1dc84ef4d3',
span_id: '5f50e181ec7bc621',
trace_flags: '01'
Expand All @@ -65,15 +63,53 @@ $ node -r ./telemetry.js app.js
}
```

There are two separate Bunyan instrumentation functionalities. The first 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 collect
tracing data. Line 3 shows an example of this.
There are two separate Bunyan instrumentation functionalities. The first, called
"log injection", 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 is that a [Bunyan
The second, called "logs bridging", 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
Bridge API. 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.) Lines 2
and 4 show a dumped OpenTelemetry Log Record.
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': '...'
}
```
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@ const bunyan = require('bunyan');

const log = bunyan.createLogger({name: 'myapp', level: 'debug'});

log.debug('hi');
log.debug({foo: 'bar'}, 'hi');

const tracer = otel.trace.getTracer('example');
tracer.startActiveSpan('manual-span', span => {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@ import bunyan from 'bunyan';

const log = bunyan.createLogger({name: 'myapp', level: 'debug'});

log.debug('hi');
log.debug({foo: 'bar'}, 'hi');

const tracer = trace.getTracer('example');
tracer.startActiveSpan('manual-span', span => {
Expand Down
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
{
"name": "bunyan-example",
"private": true,
"version": "0.43.0",
"version": "0.45.1",
"description": "Example of Bunyan integration with OpenTelemetry",
"scripts": {
"start": "node -r ./telemetry.js app.js"
Expand All @@ -19,7 +19,8 @@
"dependencies": {
"@opentelemetry/api": "^1.6.0",
"@opentelemetry/instrumentation-bunyan": "../",
"@opentelemetry/sdk-node": "^0.43.0",
"@opentelemetry/resources": "^1.17.0",
"@opentelemetry/sdk-node": "^0.44.0",
"bunyan": "^1.8.15"
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -21,12 +21,23 @@
// for viewing and analysis.

const { NodeSDK, tracing, logs, api } = require('@opentelemetry/sdk-node');
// api.diag.setLogger(new api.DiagConsoleLogger(), api.DiagLogLevel.DEBUG);
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: [
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -52,7 +52,7 @@
"@opentelemetry/sdk-logs": "^0.44.0",
"@opentelemetry/sdk-trace-base": "^1.8.0",
"@opentelemetry/sdk-trace-node": "^1.8.0",
"@opentelemetry/semantic-conventions": "^1.17.0",
"@opentelemetry/semantic-conventions": "^1.0.0",
"@types/mocha": "7.0.2",
"@types/node": "18.6.5",
"@types/sinon": "10.0.18",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -116,19 +116,33 @@ export class OpenTelemetryBunyanStream {
* 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`.
* - Some Bunyan fields would naturally map to Resource attributes:
* hostname -> host.name
* name -> service.name
* pid -> process.pid
* However, AFAIK there isn't a way to influence the LoggerProvider's
* `resource` from here.
* - 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<string, any>) {
// eslint-disable-next-line @typescript-eslint/no-unused-vars
const { time, level, msg, v, trace_id, span_id, trace_flags, ...fields } =
rec;
const {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want to control the log level that will generate log telemetry here? Python supports a env variable called OTEL_PYTHON_LOG_LEVEL more info here, is a common ask in Azure side to control which level of logs to get telemetry for

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this would be fairly straightforward. A starter patch, without error-checking:

diff --git a/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts
index 8fd0d5bc..0007a119 100644
--- a/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts
+++ b/plugins/node/opentelemetry-instrumentation-bunyan/src/instrumentation.ts
@@ -160,7 +160,7 @@ export class BunyanInstrumentation extends InstrumentationBase<
     logger.addStream({
       type: 'raw',
       stream: new OpenTelemetryBunyanStream(),
-      level: logger.level(),
+      level: process.env.OTEL_NODE_LOG_LEVEL || logger.level(), // XXX obviously missing error checking
     });
   }

To be clear, my understanding is that this level would be independent of the level used for the other output streams on the logger. So instrumenting the following with OTEL_NODE_LOG_LEVEL=trace:

const logger = bunyan.createLogger({name: 'myapp', level: 'debug'})
logger.debug('hi at debug level')
logger.trace('hi at trace level')

would result in just "hi at debug level" being written to stdout, but both log messages being sent to the Logs Bridge API.

One hesitation I have here: I know Bunyan can support having different levels on different output streams/appenders/destinations. I'm not positive for Pino and Winston. What do you think about defering supporting this configuration until I (or someone else) has worked on equivalent instrumentation for those logging frameworks?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah my comment was more about adding the option to configure it, not necessary by env variable, I don't see any OTEL_NODE or similar env variable being used anywhere, maybe we can just allow it by Instrumentation config but these need to be applicable to all Instrumentations that will create logs so we need to use OTel severity names to configure it. We can follow up later and should be fine for me as well, we just need to support it eventually, if you don't add it most likely I will add it very soon. This is becoming a higher priority for us in Azure side :)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, okay. I think it would be good and useful to add the configuration option to the constructor for this.

maybe we can just allow it by Instrumentation config

+1

but these need to be applicable to all Instrumentations that will create logs so we need to use OTel severity names to configure it.

Hrm, I'm still undecided/unsure on this. If I am configuring the log level for my Winston logger, for example, should I not be able to specify the "crit" level defined at https://github.com/winstonjs/winston#logging-levels?
The Logs data model somewhat goes out of its way to not define specific level/severity names: https://opentelemetry.io/docs/specs/otel/logs/data-model/#field-severitytext

Or perhaps we need to clearly show the mappings of Bunyan, Pino, Winston log levels in this table: https://opentelemetry.io/docs/specs/otel/logs/data-model-appendix/#appendix-b-severitynumber-example-mappings
and then the config var accepts those "SeverityNumber" strings (and/or perhaps the SeverityNumber integer values).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've spun this out to a separate issue #1821
after some discussion on yesterday's OTel JS SIG.

time,
level,
msg,
v,
hostname,
pid,
trace_id,
span_id,
trace_flags,
...fields
} = rec;
let timestamp = undefined;
if (typeof time.getTime === 'function') {
timestamp = time.getTime(); // ms
Expand Down