Issue logging with Bunyan

[skhilliard]

We recently updated from version 1.8.10 to 2.5.0 and are having some issues with how logs are being handled with the Bunyan monkey patching. In our code, we log errors and warnings using a pattern such as this

                        this.log.error(
                            err,
                            `Error - url: ${req.url} userId: ${!!req.claims ? req.claims.userId : ''} userName: ${
                                !!req.claims ? req.claims.userName : ''
                            }`
                        );

                        this.log.warn(
                            err,
                            `Warning - url: ${req.url} userId: ${!!req.claims ? req.claims.userId : ''} userName: ${
                                !!req.claims ? req.claims.userName : ''
                            }`
                        );

With the 1.8.10 version of application insights, these would all show up in traces with varying severity levels with its message property containing a property of err that contains details about the error object we send in for the first parameter. In addition, ther would be a msg property that contained our formatted message we use for the second parameter. For example:

Error - url: /api/encounters/0/site/57d1d8185f672f881e8a3dd8/query userId: 590b6052b9c9960d98a9e3a9 userName: khilliard@tsysevolved.onmicrosoft.com

However, with the new 2.5.0 version, nothing shows up in traces anymore. They are all in exceptions and we do not get the formatted string that we provide to the log.error or log.warn messages. Losing this information in our logs is very problematic.

[JacksonWeber]

@skhilliard looks to be related to #978. Would it be possible given how you want to use Bunyan to record the contextual information in a companion log.info call or to extend the native Error object to include a message field to capture that information? If that's not a viable solution, please let me know.

[skhilliard]

@JacksonWeber Unfortunately, that'd mean updating hundreds (maybe thousands) of locations in the code. I'd prefer not to go that route.

[JacksonWeber]

@skhilliard I see. I'll investigate creating a customer-set flag to determine how errors are logged from bunyan.

[skhilliard]

@skhilliard I see. I'll investigate creating a customer-set flag to determine how errors are logged from bunyan.

Thanks! Just as a reference: https://github.com/trentm/node-bunyan#log-method-api

The way the code is currently particularly "breaks" cases like the 6th one listed.

[skhilliard]

@JacksonWeber For now, I will just use our forked version with this update until a more permanent solution is committed. Thanks!

const subscriber = (event: IStandardEvent<bunyan.IBunyanData>) => {
    let message = event.data.result as string;
    clients.forEach((client) => {
        // For now, we will simply log everything as a trace.
        //   The older 1.8.x code would actually never log an
        //   exception anyway since message was NEVER of type
        //   Error(shown here):
        //
        // var subscriber = function (event) {
        //     var message = event.data.result;
        //     clients.forEach(function (client) {
        //         var AIlevel = bunyanToAILevelMap[event.data.level];
        //         if (message instanceof Error) {
        //             client.trackException({ exception: (message) });
        //         }
        //         else {
        //             client.trackTrace({ message: message, severity: AIlevel });
        //         }
        //     });
        // };

        // The way this code is written effectively breaks the Bunyan interface.
        //   For now, bypass writing any exceptions.
        //   For example, additional error detail is lost if you supplied a custom message.
        //   https://github.com/trentm/node-bunyan#log-method-api
        /*
        try {
            // Try to parse message as Bunyan log is JSON
            let log: any = JSON.parse(message);
            if (log.err) {
                let bunyanError = new Error(log.err.message);
                bunyanError.name = log.err.name;
                bunyanError.stack = log.err.stack;
                client.trackException({ exception: bunyanError });
                return;
            }
        }
        catch (err) {
            // Ignore error
        }
        */
        const AIlevel = bunyanToAILevelMap[event.data.level];
        client.trackTrace({ message: message, severity: AIlevel });
    });

[JacksonWeber]

@skhilliard Is your idea case for this to be able to set a flag that allows you to see the bunyan errors and related messages as a trace given that you set an appropriate flag in the ApplicationInsights configuration?

[skhilliard]

@JacksonWeber That would be a good solution I think....it would give us the option to have everything logged as traces even when an "err" is present.