caolan / async

Async utilities for node and the browser
http://caolan.github.io/async/
MIT License
28.18k stars 2.41k forks source link

[Suggest] About error stack of `async.waterfall` #1768

Closed finscn closed 2 years ago

finscn commented 2 years ago

When there is a Callback was already called error in async.waterfall, the error stack is useless for debugging the code. example:

const async = require('./async.js')

function MyFuncA() {
    async.waterfall([
        (next) => {
            console.log(0)
            next()
        },
        (next) => {
            console.log(1)
            next()
        },
        (next) => {
            console.log(2)
            next()
        },
        (next) => {
            console.log(3)
            next()

            // ****
            // There is a wrong function-call
            // ****
            next()
        },
        (next) => {
            console.log(4)
            next()
        },
    ], (error) => {
        console.log("Done")
    })
}

function MyFuncB() {
    MyFuncA()
}

MyFuncB()

When I run the code, I will get an error stack like this :

Error: Callback was already called.
    at /Users/rocky/DEV/test-async/async.js:335:23
    at /Users/rocky/DEV/test-async/test.js:23:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:15:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:11:13

There is no any useful information . I can't get the key value MyFuncA & MyFuncB . Even I can't know it's thrown by waterfall() function .

This is just a simple test case , so I know I can try to see what happen at test.js:23:13 and test.js:15:13. In fact , when I deploy my complex project ( the js size > 800kb , and compiled with webpack) , the log often like this :main.js:17:2548281 .

And make matters worse , the main.js is compiled at user's client (I will upload the error-log file to my server) , so Different client maybe have different the line number & column number . I can't get any help from line & column info , and it's too hard to find out the bug.

In conclusion , I hope the async.waterwall could give me some useful error stack, when there is a Callback was already called error.


Then, I try to hack the code of async , to solve my problem. But it's not good , even ugly , so I don't create a PR.

I just changed function waterfall and onlyOnce . ( seer the part /* add by finscn */ ).

    function waterfall (tasks, callback) {
        callback = once(callback);
        if (!Array.isArray(tasks)) return callback(new Error('First argument to waterfall must be an array of functions'));
        if (!tasks.length) return callback();
        var taskIndex = 0;

        /* add by finscn */
        const errorInfo = {
            name: 'waterfall',
            stack: new Error().stack
        }

        function nextTask(args) {
            /* add by finscn */
            errorInfo.taskIndex = taskIndex;

            var task = wrapAsync(tasks[taskIndex++]);
            task(...args, onlyOnce(next, errorInfo /* add by finscn */ ));
        }

        function next(err, ...args) {
            if (err === false) return
            if (err || taskIndex === tasks.length) {
                return callback(err, ...args);
            }
            nextTask(args);
        }

        nextTask([]);
    }
    function onlyOnce(fn, errorInfo) {
        const taskIndex = errorInfo ? errorInfo.taskIndex : null;
        return function (...args) {
            if (fn === null) {
                let msg = "Callback was already called.";

                /* add by finscn */
                if (errorInfo) {
                    msg += '\n  Error Info: ' + errorInfo.name;
                    msg += ' , taskIndex: ' + taskIndex;
                    msg += ' , stack:\n' + errorInfo.stack;
                    msg += '\n  ---------------';
                }

                throw new Error(msg);
            }
            var callFn = fn;
            fn = null;
            callFn.apply(this, args);
        };
    }

Now, the error log like this :

Error: Callback was already called.
  Error Info: waterfall , taskIndex: 3 , stack:
Error
    at Object.waterfall (/Users/rocky/DEV/test-async/async.js:5775:20)
    at Object.awaitable [as waterfall] (/Users/rocky/DEV/test-async/async.js:211:32)
    at MyFuncA (/Users/rocky/DEV/test-async/test.js:4:11)
    at MyFuncB (/Users/rocky/DEV/test-async/test.js:35:5)
    at Object.<anonymous> (/Users/rocky/DEV/test-async/test.js:38:1)
    at Module._compile (internal/modules/cjs/loader.js:999:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1027:10)
    at Module.load (internal/modules/cjs/loader.js:863:32)
    at Function.Module._load (internal/modules/cjs/loader.js:708:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:60:12)
  ---------------
    at /Users/rocky/DEV/test-async/async.js:335:23
    at /Users/rocky/DEV/test-async/test.js:23:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:15:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:11:13

I can know, this error is at waterfall , which task is wrong ( by taskIndex ) , and error stack of waterfall(). I can get the key value MyFuncA and MyFuncB.

aearly commented 2 years ago

I think you already have the information you need to debug.

Error: Callback was already called.
    at /Users/rocky/DEV/test-async/async.js:335:23
    at /Users/rocky/DEV/test-async/test.js:23:13 // <--------------  tells you where the error originated
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:15:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:11:13

Using named function expressions in a waterfall can also help.

finscn commented 2 years ago

I think you already have the information you need to debug.

Error: Callback was already called.
    at /Users/rocky/DEV/test-async/async.js:335:23
    at /Users/rocky/DEV/test-async/test.js:23:13 // <--------------  tells you where the error originated
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:15:13
    at nextTask (/Users/rocky/DEV/test-async/async.js:5783:27)
    at next (/Users/rocky/DEV/test-async/async.js:5791:13)
    at /Users/rocky/DEV/test-async/async.js:339:20
    at /Users/rocky/DEV/test-async/test.js:11:13

Using named function expressions in a waterfall can also help.

I said This is just a simple test case In my real project , the message like this :

Error: Callback was already called.
at https://usr/game.js:18:543330
at https://usr/subpackages/main/game.js:3:2793258
at https://usr/subpackages/main/game.js:2:1962563
at https://usr/subpackages/main/game.js:3:2268912
...
Error: Callback was already called.
at https://usr/game.js:17:838920
at https://usr/subpackages/main/game.js:3:2688532
at https://usr/subpackages/main/game.js:2:1943215
at https://usr/subpackages/main/game.js:3:2310234
...

the 1st thing : I don't know this error is thrown by what api , waterfall ? each ? parallel? ...

the 2nd : the code is compiled at user's client , so the different clients maybe have different the line number & column number .

I can't know the function that calls async API from the simple information game.js:18:543330 or game.js:17:838920 .


After patch my code , the error becomes like this :

Callback was already called.
Error Info: waterfall , taskIndex: 2 , stack:
Error
at Object.<anonymous> (https://usr/game.js:18:18870)
at Object.waterfall (https://usr/game.js:18:1641)
at Ce.unLockArea (https://usr/subpackages/main/game.js:3:2903838)
at Ce.startRegionTutorial (https://usr/subpackages/main/game.js:3:2903749)
at i.startRegionTutorialSignal.dispatch (https://usr/subpackages/main/game.js:3:2507558)

I known that path of error : startRegionTutorial() --> unLockArea() --> async.waterfall() , And there is something is wrong in the 3rd ( the index start from 0) task of waterfall.

finscn commented 2 years ago

By the way, If I use named function , after compiled / minify / obfuscated , the name will become unrecognizable.

aearly commented 2 years ago

If you have source maps configured for every step of the compile/minification process, you should be able to have your errors mapped back to the original lines and function names.

finscn commented 2 years ago

the code is compiled at user's client

there is no source-map. because the code is compiled at user's client . I can't force user to do that. In fact , I run my code at a special platform named wechat game & wechat cloud . I don't know how to explain it for you. Do you know there is an app named wechat/weixin at China ?