【问题标题】:Node JS with async unexpected infinite loop具有异步意外无限循环的节点 JS
【发布时间】:2020-09-24 18:02:17
【问题描述】:

我有一个 JS 文件,它仅在预期由于超时而导致错误时自动重复,例如:

  • 网站无法访问 -> 超时
  • 在“waitSelector”中查找的标记不存在 -> 需要达到超时时间

这会导致我无法理解的原因导致内存泄漏错误消息。已检查此类问题以尝试确定它是否以某种方式链接到 Node JS、Puppeteer 或 Forever 库,但尚未遇到其他人面临此问题。这是我找到的最接近的,但根据答案here,他的脚本似乎没有错误。

JS 文件基本上是创建一个带有基本 url 的服务器并监听 88 端口。当有人输入"http://localhost:88/some_parameters 时,似乎代码到达第一个 try-catch,然后通过console.log(2) 无限期直到 try catch 成功或失败。

我不理解这种行为,因为我预计脚本会一直执行到 try catch,然后等待响应,然后根据返回的成功或错误继续运行。

我输入了两个命令并在两种情况下得到了相同的结果: forever start forever.json node loadPage.js

我花了很长时间试图解决这个问题,但仍然不理解这种行为。我得到了我想要的图像,但它仍然很奇怪,最终污染了日志。

欢迎任何帮助!

更新

这种奇怪的行为只会在 try-catch 返回错误时发生。返回成功响应后,代码正常执行,不重复任何内容。

loadPage.js

var http = require('http');
var url = require('url');
const puppeteer = require('puppeteer');
const { exit } = require('process');


let baseUrl = "http://localhost:88";
// let url = "chrome://gpu";
// demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1

console.log(1);
http.createServer(function (req, res) {
    console.log(2);
    (async () => {

        console.log(3);
        // headless set to false opens new browser and closes it when process is completed
        const browser = await puppeteer.launch({
            headless: true,
            args: ['--no-sandbox'],
            timeout: 10000,
            devtools: true
        });
        console.log(4);
        const completeUrl = `${baseUrl}${req.url}`;
        console.log(5);
        const parsedUrl = url.parse(completeUrl, true);
        console.log(6);
        const page = await browser.newPage();
        console.log(7);

        // Variable to help determine and log required time for different operations lower in the code.
        let t0 = Date.now();

        // Console logs used in logs to make them easier to read
        // new Date().toISOString().replace('T', ' ').substr(0, 19) converts time in acceptable format
        // with space instead of weird characters.
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "------------------------------Process start for new url------------------------------"
        );
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "The url being called is: " + `${baseUrl}${parsedUrl.pathname}${parsedUrl.search}`
        );


        // ------------------------------START - GO TO URL PART------------------------------
        // Try-Catch reaching the targeted url
        try {
            await page.goto(`${baseUrl}${parsedUrl.pathname}${parsedUrl.search}`, {
                waitUntil: 'networkidle0',
                timeout: 10000
            }).then(() => {
                console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                    "Reached the website!"
                );
            });

        } catch (error) {
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "the following 'go to url action' error happened: ",
                error
            );
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "------------------------------Error 'go to action' end for new url------------------------------"
            );
            browser.close();
            process.exit();
        }

        let t2 = Date.now();
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "The 'go to url action' took " + (t2 - t0) + " milliseconds."
        );
        // ------------------------------END - GO TO URL PART------------------------------


        // ------------------------------START - WAIT FOR SELECTOR PART------------------------------
        // try catch to detect the agreed tag's ID selector
        // Once that selected is detected then it means that the model if fully loaded
        try {
            await page.waitForSelector('#uploadsuccess', {
                timeout: 30000
            }).then(() => {
                console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                    "Got the selector!"
                );
            });
        } catch (error) {
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "the following 'wait for selector action' error happened: ",
                error
            );
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "------------------------------Error 'wait for selector action' end for new url------------------------------"
            );
            browser.close();
            process.exit();
        }

        let t3 = Date.now();
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "The 'waitForSelector' action took " + (t3 - t2) + " milliseconds."
        );
        // ------------------------------END - WAIT FOR SELECTOR PART------------------------------


        // ------------------------------START - IMAGE SAVING PART------------------------------
        // Take a printscreen and saving the image in the corresponding folder
        try {
            await page.screenshot({
                path: "./images/" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "-apm-3d.png"
            }).then(() => {
                console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                    "Image saved"
                );
            });

        } catch (error) {
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "the following 'image saving' error happened: ",
                error
            );
            console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
                "------------------------------Error 'image saving' end for new url------------------------------"
            );
            browser.close();
            process.exit();
        }
        // ------------------------------END - IMAGE SAVING PART------------------------------


        let t1 = Date.now();
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "The whole process took " + (t1 - t0) + " milliseconds."
        );
        console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
            "------------------------------Process end for new url------------------------------"
        );
        browser.close();

    })()

}).listen(88)

forever.log

1
2
3
4
5
6
7
[2020-09-09 10:52:14] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:14] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:14] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:14] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:15] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:15] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:15] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:15] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:15] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:15] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:15] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:15] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:16] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:16] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:16] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:16] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:17] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:17] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:17] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:17] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
(node:12919) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(node:12919) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 SIGINT listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(node:12919) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 SIGTERM listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(node:12919) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 SIGHUP listeners added to [process]. Use emitter.setMaxListeners() to increase limit
4
5
6
7
[2020-09-09 10:52:17] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:17] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:18] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:18] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:18] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:18] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:18] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:18] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:19] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:19] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:19] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:19] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:19] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:19] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:19] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:19] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:20] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:20] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:20] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:20] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:20] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:20] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:21] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:21] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:21] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:21] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:21] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:21] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:22] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:22] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:22] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:22] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:22] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:22] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:23] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:23] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:23] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:23] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:23] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:23] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:24] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:24] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
4
5
6
7
[2020-09-09 10:52:24] - ------------------------------Process start for new url------------------------------
[2020-09-09 10:52:24] - The url being called is: http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1
2
3
[2020-09-09 10:52:24] - the following 'go to url action' error happened:  TimeoutError: Navigation timeout of 10000 ms exceeded
    at /Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/node_modules/puppeteer/lib/cjs/puppeteer/common/LifecycleWatcher.js:106:111
    at async FrameManager.navigateFrame (/Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/node_modules/puppeteer/lib/cjs/puppeteer/common/FrameManager.js:88:21)
    at async Frame.goto (/Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/node_modules/puppeteer/lib/cjs/puppeteer/common/FrameManager.js:405:16)
    at async Page.goto (/Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/node_modules/puppeteer/lib/cjs/puppeteer/common/Page.js:826:16)
    at async /Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/loadPage.js:49:13
[2020-09-09 10:52:24] - ------------------------------Error 'go to action' end for new url------------------------------
error: Forever detected script exited with code: 0
error: Script restart attempt #1
1
error: restarting script because /Users/sebastienponcelet/Documents/3d-puppeteer/3d-puppeteer/stack-overflow.md changed
error: Forever detected script was killed by signal: SIGKILL
error: Script restart attempt #2
1

【问题讨论】:

  • 如果你直接启动服务器而不是永远只获取第一个 url 会发生什么?除此之外,似乎 networkidle0 是罪魁祸首,你确定没有网络连接保持打开状态吗?如果你用 networkidle2 替换它呢?
  • 所以当我像$node loadPage.js 一样直接执行脚本时,我得到了相同的行为。用 networkidle2 替换了 networkidle0,但仍然有同样的问题。不确定打开的网络连接,但是在检查页面时,除了对 url 的调用之外,我没有看到任何其他事情发生。仍然对代码的行为感到困惑,我没有任何 while 或 for 循环,真的不明白为什么代码在等待 try-catch 返回响应时会重复自己。但是,当任何 try-catch 中没有错误时,就不会发生这种情况。

标签: node.js async-await puppeteer forever


【解决方案1】:

问题是您一次又一次地调用同一个 HTTP 服务器,却没有返回响应。

HTTP 服务器正在监听 88 端口:

http.createServer(function (req, res) {
  ...
}).listen(88)

然后您发出第一个 HTTP 请求,以便该过程开始。 2-7之后,流程到达该行:

await page.goto(`${baseUrl}${parsedUrl.pathname}${parsedUrl.search}`, {

这指示 puppeteer 转到页面 http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1,该页面也在 localhost:88 上,再次访问同一个 HTTP 服务器。

当第二个请求到来时,它会经历相同的过程,启动浏览器,提取 URL,然后向http://localhost:88/... 发出请求,然后生成另一个浏览器,发出另一个请求,等等。这就是为什么您一遍又一遍地看到 2-7,这是一个无限递归的教科书示例。

由于所有浏览器都在等待响应但始终没有响应,它们最终会超时,这就是您看到错误的原因。

【讨论】:

  • 我预计会超时,但其余部分很有见地。没想到过程是这样的。以为它会监听 88 端口,并且只有在我输入 localhost:88/... url 时才会启动进程。然后它会到达page.goto 操作的第一个try-catch 并实际等待响应或错误。但我仍然不确定我是否理解,这是否意味着在这种情况下它将向同一个 url 发出多个请求?因为我只输入一次。
  • goto 正在向 localhost:88 服务器发出新请求 (http://localhost:88/demo/love_down.php?clean=0&line1=1,8,0,0-125&orderid=ORDIB2B-9000105953_1)
  • 好的,我明白了。但是,为什么程序不等待 try-catch 答案,而是仅在预期错误并稍后收到时才返回代码的开头,而不是在收到响应时?
  • 答案是:它永远不会回头。这样想:请求 1 来了,2-7 执行,然后向 localhost:88 发出请求。请求 2 开始,执行 2-7,然后向 localhost:88 发出请求。请求 3 开始,....,直到请求 1 超时并且您看到错误
  • 很抱歉坚持,但有些事情仍然困扰着我。这只是在 try-catch 期间发生错误时发生。当我为了尝试而故意输入错误的网址时,就会发生您所描述的情况。但是,如果一切顺利,那么在日志中我只会看到一个请求,大 url 不仅仅是对端口 88 的调用,而且响应不是即时的。那么为什么当发生错误时,它会一一接收所有请求,但当一切顺利时,它会在 try-catch 处等待?
【解决方案2】:

您的 catch 块中有 process.exit(),它正在关闭您的服务器。永远比看到进程被杀死并重新启动它。只需删除该行。

【讨论】:

  • 我理解这是预期的行为,如果进程停止,那么 Forever 应该再次启动它。然而,当到达 try-catch 时,它似乎不会等待响应(成功或错误),而是回到脚本的开头(直到 console.log(2))并无限期地重复它,直到 try- catch 返回响应(在我的情况下,我预计会出现错误,因为我故意提供了错误的 url)。所以这种行为并不重要,因为最终它会做它应该做的事情,但是这种行为非常奇怪。
  • 你试过在 VS Code 中运行它并附加一个调试器吗?您应该能够通过在脚本中的各个点设置断点来遵循流程。我也不确定为什么你在主处理程序中有一个立即执行的函数。为什么不让主回调函数异步呢?即http.createServer(async function (req, res) {
  • 所以我尝试按照建议使主回调函数异步。但是,它并没有改变行为。仍然不明白为什么它无限期地重复请求而不是等待第一次尝试捕获响应。使用调试器不会提供比问题日志中显示的更多信息。在等待相同 url 的响应时,它仍然重复相同的行,但不会改变其他任何内容。
【解决方案3】:

我已经设法通过简单地删除 go to action 中的 try-catch 来解决这个问题。不知道为什么,但这会阻止程序无限循环,直到返回响应。

那里的代码现在看起来像这样:

// ------------------------------START - GO TO URL PART------------------------------
    await page.goto(`${baseUrl}${parsedUrl.pathname}${parsedUrl.search}`, {
        waitUntil: 'networkidle2',
        timeout: 10000
    })

    let t2 = Date.now();
    console.log("[" + new Date().toISOString().replace('T', ' ').substr(0, 19) + "] - " +
        "The 'go to url action' took " + (t2 - t0) + " milliseconds."
    );
    // ------------------------------END - GO TO URL PART------------------------------

很高兴有任何评论来解释为什么这样做会成功。

【讨论】:

    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 2019-05-27
    • 1970-01-01
    • 1970-01-01
    • 2020-05-11
    相关资源
    最近更新 更多