Bunyan logger problems

[skhilliard]

I am attempting to upgrade from 2.x to 3.0.1 and have encountered several issues with the application insights shim. Among them are differences in how our trace/error logging is impacted.

1. Trace messages are "flattened". Here is what I mean...

with 2.x we see this form...

2. Errors logged with exception objects are not rendered at all in either traces or exceptions. Since the shim does not support enableLoggerErrorToTrace I didn't expect it to show up in traces, but it does not even show up in exceptions. Here is an example of it showing as a trace using 2.x

..again with 3.x no entries are found anywhere when this same error is logged.

[JacksonWeber]

Regarding the issue with "flattened" traces. Can you share your call to the Bunyan logger creating that record? The logs you're comparing between 2.X and 3.0.1 don't appear to be the same, so I'm trying to understand what the original structures look like so I can better understand what behavior you're expecting.

Regarding your second issue with errors, I'm not able to reproduce your issue with not seeing Bunyan error logging. The Telemetry type should be trace if it's coming from Bunyan, but with a severity level of "Error". An example trace from my testing:
.

If you're not able to find these error logs, please share what your Bunyan error log calls in your code look like. I'm happy to test them and take a look. Thanks!

[skhilliard]

@JacksonWeber Sure!

Here is where we create the logger...

import * as Logger from 'bunyan';

...

let logStreams = [];

if (process.env.enable_log_file === 'true') {
    logStreams.push({
        type: 'rotating-file',
        period: '1d',
        count: 10,
        path: `evolved${process.pid}.log`,
        level: process.env.log_level
    });
}

logStreams.push({
    stream: process.stderr,
    level: process.env.log_level
});

this.log = Logger.createLogger(<Logger.LoggerOptions>{
    name: 'EVolvED',
    streams: logStreams
});

Here is an example of an "info" level call...

this.log.info(
    `Retrieved ${options.length} CPOE order text options for site ${req.params.siteId} with configuration ${req.params.type}`
);

Here is an example of an "error" level call...

this.log.error(
    err,
    `Error finding encounter ${req.params.encounterId} or site ${req.params.siteId} to get encounter with export criteria`
);

[JacksonWeber]

@skhilliard Thank you for following up. Regarding the changes in Bunyan trace logging, I understand the changes you're referring to now. As a part of our move to OpenTelemetry we also moved away from our previous diagnostic-channel usage to an OpenTelemetry offering for tracking Bunyan, which explains why some fields are not identical here. Does this new data formatting break implementations on your end?

I also tested your error implementation, and I'm still seeing the logs being produced from these logging calls. The contained error object is not serialized correctly (this has just been fixed in the exporter and will roll out with the next release), but I'm not seeing issues with generation from the SDK. Are you seeing no traces with severityLevel: 3?

[skhilliard]

@JacksonWeber We do have some alerts and other queries that count on the structure of the messages field, so it'd be ideal if it was the same rather than "flattened" as a string.

I do have some traces with severity level of 3 but only when I'm not passing in an error object. E.g. this.log.error('this is an error') vs. this.log.error(err, 'The err here is an Error object')

[JacksonWeber]

@skhilliard I don't know that the message field is really "flattened" so much as it just reports the Bunyan's message field as the message attribute in Azure Monitor. For example, if I log a stringified object as Bunyan's message, I get:

so it should still be possible to log any necessary data in objects as a part of your message field.

I've tested further and haven't been able to find any type of object/data I can pass to the log.error() to cause it to not create an output in the traces table. Do you have an example of an error you're using there so I can test with the exact same data?

[skhilliard]

@JacksonWeber Thanks for delving into this! For my testing of the error condition, I just intentionally threw an error using an Error object like this:

let error = new Error('fakeError')
this.log.error(error, 'This is a fake error');

Kelly

[skhilliard]

@JacksonWeber Any updates for this? Thanks!

[JacksonWeber]

@skhilliard Apologies for the delay. I tested your above error with the following code:

let error = new Error('fakeError')

async function setupRoutes() {
    app.get('/', async (req, res) => {
        try {
            bunyanLog.error(
                error,
                `Error finding encounter`
            );
        } catch (error) {
            console.error(error);
        }
        res.send("Hello World!");
    });
}

setupRoutes().then(() => {
    app.listen(PORT);
    console.log(`Listening on http://localhost:${PORT}`);
});

And I get a resultant trace that looks like this:

Are you ensuring that the test you're using gives ample time to the SDK to export the error logs? If you want to make sure, you can await flush() on the default telemetry client.
I'm also using ApplicationInsights 3.1.0 for the above example.

[skhilliard]

@JacksonWeber Yeah....I am sure we were giving enough time for the logs to export. What version of bunyan are you using? We are using...

    "bunyan": "^1.8.15",
    "bunyan-middleware": "^1.0.2",

[JacksonWeber]

@skhilliard I'm using the same versions of both bunyan and the bunyan-middleware package. I also tested with both application insights 3.0.1 and 3.1.0, and both are behaving the same way for me.

shim-ts-sample-app.zip

Please let me know if my sample app is not representative of your scenario in any way!