Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a way to get the log line number when console.log has been wrapped by a custom function #882

Closed
bzuillsmith opened this issue Dec 8, 2020 · 13 comments
Assignees
Labels
feature-request Request for new features or functionality verification-needed Verification of issue is requested verified Verification succeeded
Milestone

Comments

@bzuillsmith
Copy link

Is your feature request related to a problem? Please describe.
I am working on a TS express app and the logger will use a custom ConsoleTransport class that wraps console.log. Now whenever it outputs to the debug console, the line number shows the code within my ConsoleTransport class. I added the file to skipFiles of the launch config with the hope that it would ignore that file and perhaps show me the top call in the stack that was not ignored, but it did not.

// my launch.json configuration
{
        "name": "Run Backend",
        "type": "node",
        "request": "launch",
        "runtimeArgs": ["--nolazy", "-r", "ts-node/register", "-r", "tsconfig-paths/register"],
        "args": ["./src/index.ts", "--transpile-only"],
        "cwd": "${workspaceFolder}/backend",
        "internalConsoleOptions": "openOnSessionStart",
        "skipFiles": [
            "<node_internals>/**",
            "node_modules/**",
            "${workspaceFolder}/backend/src/modules/logger/ConsoleTransport.ts"
        ],
        "env": {
            // ommitted
        }
}

All the suggestions online show hacky or confusing ways of binding to console.log and/or overriding it which just feels wrong and unintuitive to me.

Describe the feature you'd like
I would love for it to use the first part of the stack that is not included in the skipFiles array or some way to tell the debugger to not use the strict line it called console.log but instead some custom function.

@bzuillsmith bzuillsmith added the feature-request Request for new features or functionality label Dec 8, 2020
@connor4312
Copy link
Member

connor4312 commented Dec 8, 2020

Can you share more details around the logger you use, or a small example repo? I'm not totally clear what the output or output structure are. Stack traces come in different shapes and sizes over the debug protocol.

@bzuillsmith
Copy link
Author

I'm actually using the winston logger, but a custom console transport because theirs doesn't work with the debug console. I got it working with the debug console but now the line numbers all show my custom Console transport class.

@connor4312
Copy link
Member

Can you share the custom transport?

@bzuillsmith
Copy link
Author

I can do that in about an hour as I'm away from my desk, but it's literally their transport but with the console._stdout lines removed (and the of statements around them so it calls console.log)

@bzuillsmith
Copy link
Author

//Modified winston Console logger to use console.log so it works with debugge
'use strict';

import os from 'os';
import { LEVEL, MESSAGE } from 'triple-beam';
import TransportStream from 'winston-transport';
import winston from 'winston';

/**
 * Transport for outputting to the console.
 * @type {Console}
 * @extends {TransportStream}
 */
export class ConsoleTransport extends TransportStream {
    
    name: string;
    stderrLevels: object;
    consoleWarnLevels: object;
    eol: string;

    /**
     * Constructor function for the Console transport object responsible for
     * persisting log messages and metadata to a terminal or TTY.
     * @param {!Object} [options={}] - Options for this instance.
     */
    constructor(options: winston.transports.ConsoleTransportOptions = {}) {
        super(options);

        // Expose the name of this Transport on the prototype
        this.name = 'console';
        this.stderrLevels = this._stringArrayToSet(options.stderrLevels);
        this.consoleWarnLevels = this._stringArrayToSet(options.consoleWarnLevels);
        this.eol = options.eol || os.EOL;

        this.setMaxListeners(30);
    }

    /**
     * Core logging method exposed to Winston.
     * @param {Object} info - TODO: add param description.
     * @param {Function} callback - TODO: add param description.
     * @returns {undefined}
     */
    log(info, callback) {
        setImmediate(() => this.emit('logged', info));

        // Remark: what if there is no raw...?
        if (this.stderrLevels[info[LEVEL]]) {

            console.error(info[MESSAGE]);

            if (callback) {
                callback(); // eslint-disable-line callback-return
            }
            return;
        } else if (this.consoleWarnLevels[info[LEVEL]]) {
            
            console.warn(info[MESSAGE]);

            if (callback) {
                callback(); // eslint-disable-line callback-return
            }
            return;
        }

        console.log(info[MESSAGE]);

        if (callback) {
            callback(); // eslint-disable-line callback-return
        }
    }

    /**
     * Returns a Set-like object with strArray's elements as keys (each with the
     * value true).
     * @param {Array} strArray - Array of Set-elements as strings.
     * @param {?string} [errMsg] - Custom error message thrown on invalid input.
     * @returns {Object} - TODO: add return description.
     * @private
     */
    _stringArrayToSet(strArray: string[], errMsg?: string): object {
        if (!strArray)
            return {};

        errMsg = errMsg || 'Cannot make set from type other than Array of string elements';

        if (!Array.isArray(strArray)) {
            throw new Error(errMsg);
        }

        return strArray.reduce((set, el) => {
            if (typeof el !== 'string') {
                throw new Error(errMsg);
            }
            set[el] = true;

            return set;
        }, {});
    }
};

And the abridged code from another file to configure it with winston and export a logger:

options.transports = [
    new ConsoleTransport({
        level: 'debug',
        format: format.combine(format.colorize(), format.errors({ stack: true }), format.simple()),
        handleExceptions: true
    }),
    new winston.transports['MongoDB'](mongoTransportOptions)
];

export default winston.createLogger(options);

And of course I use it in various places to like `mylogger.log('message here', meta);

and it looks like this in the debugger

info: Application is starting in 'development' mode.                     backend/src/modules/logger/ConsoleTransport.ts:73
info: A message somewhere else.                                          backend/src/modules/logger/ConsoleTransport.ts:73

@connor4312
Copy link
Member

connor4312 commented Dec 8, 2020

Thanks, I see what you mean.

I think your intuition to use skipFiles is the right approach. I've updated the debugger so that the location shown in log messages will be the first location that isn't matched by the skipFiles. It will be in the next nightly release.

@connor4312 connor4312 added the verification-needed Verification of issue is requested label Dec 8, 2020
@connor4312 connor4312 added this to the December 2020 milestone Dec 8, 2020
@bzuillsmith
Copy link
Author

Amazing! Thanks so much for the quick work, I look forward to using it.

@bzuillsmith
Copy link
Author

Just gave Insiders 1.53.0 a try and I'm still getting the skipped file line number. Pretty much the same setup as discussed above. I'm not sure what to do to debug it on my end. Feel free to send me a DM if you want to do a quick video/screen share to work it out. Otherwise let me know how I can be of help to debug this.

@connor4312
Copy link
Member

Insiders doesn't use the nightly release -- you'll want to install the nightly js-debug build manually.

@bzuillsmith
Copy link
Author

Ah got it. Would help if I read the readme, I apologize.

So now I have it running and I get line numbers within a node_module like backend/node_modules/winston-transport/index.js:103. This happens with or without my skip file line for my custom transport. Same config and code as above. I also tried changing the node_modules skip file to backend/node_modules/** and to ${workspaceFolder}/backend/node_modules/** but the output is the same.

@connor4312
Copy link
Member

I think you want ${workspaceFolder}/backend/node_modules/**/*.js in order to match the glob. With that it should work, I think -- I remember testing using the code you sent last week

@bzuillsmith
Copy link
Author

Ah, yes. That does the trick. Also I was hitting restart on the debug session which apparently uses the same cached launch config. It is working as expected with the glob pattern you just gave. Thanks a ton!

@connor4312
Copy link
Member

sure thing, thanks for filing the issue and verifying :)

@connor4312 connor4312 added the verified Verification succeeded label Dec 16, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature-request Request for new features or functionality verification-needed Verification of issue is requested verified Verification succeeded
Projects
None yet
Development

No branches or pull requests

2 participants