收集堆信息时，进程退出

yunnysunny commented 2 years ago

在管理后台点击生成堆快照，然后应用进程就退出了，进程退出返回码 3221225477 xprofiler 用的最新的 1.4.0 版本，node 用的 14.19.1，操作系统是 win 10

hyj1991 commented 2 years ago

v1.4x 的 v8 确实存在 bug：

function that() {
  const p = new Promise(resolve => {
    setTimeout(resolve, 1);
  });
  Promise.all([p]); // <= 关键问题点，创建了一个 PromiseAllResolveElementContext
}
that();

const v8 = require('v8');
const fs = require('fs');
const stream = fs.createWriteStream('./node.heapsnapshot');
v8.getHeapSnapshot().pipe(stream);

这种 Promise.all 会导致调用 v8 提供的快照 api crash，这个问题在 v16.x 以及 v14.x 的最新版本中已经修复，可以升级下解决，比如升级到 v14.19.2

另一种可能就是你抓取的时候堆使用率过高，导致序列化快照的时候 OOM

hyj1991 commented 2 years ago

具体的上游 issue 修复可以参见：https://github.com/nodejs/node/issues/42558

yunnysunny commented 2 years ago

应用刚启动的时候收集的，堆空间只有100MB，所以不是 OOM 的问题。那看起来就是这个node 14.9.1 的bug 了。我尝试升级一下node版本。

yunnysunny commented 2 years ago

我看官方在 14.19.2 版本修复了这个bug https://github.com/nodejs/node/pull/42637 ，所以我装了这个版本，然后重新在管理后台生成堆快照，现在应用进程不退出了，但是会弹窗报 Inner server error,同时留意到应用程序标准输出中有如下日志：

[2022-05-17 10:42:34] [1.5.0] [error] [25468] checkActionFile failed: Unexpected end of JSON input

hyj1991 commented 2 years ago

你有没有自己改过代码？

yunnysunny commented 2 years ago

你有没有自己改过代码？

没有改过

hyj1991 commented 2 years ago

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥，正常不会有 parse 的问题

yunnysunny commented 2 years ago

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥，正常不会有 parse 的问题

options 是 {} ，stdout 没有数据，是空字符串

hyj1991 commented 2 years ago

看下 xtransit 的版本，然后增加一个配置 logLevel: 3，再完整抓一次堆快照，把 xtransit 的 debug 日志贴出来看下

hyj1991 commented 2 years ago

[from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","type":"exec_command","data":{"command":"xprofctl 11532 heapdump {}","expiredTime":15000}}
[2022-05-17 11:20:41] [2.0.1] [debug] [11532] [execute command] C:\Program Files\nodejs\node.exe C:\Users\hyj1991\AppData\Roaming\nvm\v16.15.0\node_modules\xtransit\commands\xprofctl.js 11532 heapdump {}
[2022-05-17 11:20:43] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757643005,"type":"response","data":{"ok":true,"data":{"stdout":"{\"filepath\":\"C:\\\\Users\\\\hyj1991\\\\AppData\\\\Local\\\\Temp\\\\x-heapdump-11532-20220517-0.heapsnapshot\"}\n","stderr":""}},"signature":"e84243c151449e0bf6da702a21b3e8c8803f29ef"}
[2022-05-17 11:20:47] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"54a540bd-08c2-4dff-bc7a-be94013f91d7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757647015,"type":"action","data":{"filePath":"C:\\Users\\hyj1991\\AppData\\Local\\Temp\\x-heapdump-11532-20220517-0.heapsnapshot"},"signature":"e7cb08446c73c2d2b99415d6a592087056b59c51"}

正常 win 下的一次快照 action 交互应该可以看到这样的 debug 日志。

yunnysunny commented 2 years ago

xtransit用的最新的版本 1.5.0，我再抓下日志看看

yunnysunny commented 2 years ago

[from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","type":"exec_command","data":{"command":"xprofctl 11532 heapdump {}","expiredTime":15000}}
[2022-05-17 11:20:41] [2.0.1] [debug] [11532] [execute command] C:\Program Files\nodejs\node.exe C:\Users\hyj1991\AppData\Roaming\nvm\v16.15.0\node_modules\xtransit\commands\xprofctl.js 11532 heapdump {}
[2022-05-17 11:20:43] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"aa9cfee6-ae05-43c9-9023-a616719ee2a7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757643005,"type":"response","data":{"ok":true,"data":{"stdout":"{\"filepath\":\"C:\\\\Users\\\\hyj1991\\\\AppData\\\\Local\\\\Temp\\\\x-heapdump-11532-20220517-0.heapsnapshot\"}\n","stderr":""}},"signature":"e84243c151449e0bf6da702a21b3e8c8803f29ef"}
[2022-05-17 11:20:47] [2.0.1] [debug] [11532] [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":1,"agentId":"GDP-WIN3","traceId":"54a540bd-08c2-4dff-bc7a-be94013f91d7","clientId":"4e8c9e3a82065e047c9c81a8ddb39d4b","timestamp":1652757647015,"type":"action","data":{"filePath":"C:\\Users\\hyj1991\\AppData\\Local\\Temp\\x-heapdump-11532-20220517-0.heapsnapshot"},"signature":"e7cb08446c73c2d2b99415d6a592087056b59c51"}

正常 win 下的一次快照 action 交互应该可以看到这样的 debug 日志。

xtransit的logLevel由2改为了3，但是发现并没有上述日志

hyj1991 commented 2 years ago

你是集成到你自己的应用启动的？如果是这样你要看下你应用实现的 debug logger 是否启用了。

我这里给出来的日志样例是全局启动的方式，用的是内置的 logger

yunnysunny commented 2 years ago

[2022-05-17T12:12:36.300+0800] DEBUG default  [report_core] coredirs: 
[2022-05-17T12:12:36.544+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"c4af3757-1a26-41fe-a04d-f6429be6e5aa","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760756544,"type":"log","data":{"type":"core_files","data":{"list":[]}},"signature":"a30537398fda3115d9d3ce7f1ccd5e2bfb05d8db"}
[2022-05-17T12:12:36.875+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"60891d0d-c8b0-4df2-bdfb-912348e1ba06","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760756875,"type":"log","data":{"type":"system_log","data":{"cpu_count":8,"total_memory":17013510144,"uptime":132962,"log_time":"2022-05-17 12:12:35","log_timestamp":1652760755270,"version":"1.5.0","used_cpu":0.13440305921607587,"free_memory":1238106112,"load1":0,"load5":0,"load15":0,"disks":{},"node_count":29}},"signature":"24901fd2d05a98308d42aeb649c53503746cedfd"}
[2022-05-17T12:12:56.204+0800] DEBUG default  [from xtransit-server] >>>>>>>>>>>>>>>>>>> {"traceId":"2ee18e89-8863-493a-bfa7-f3b9eaa2e813","type":"exec_command","data":{"command":"xprofctl 24840 heapdump {}","expiredTime":15000}}
[2022-05-17T12:12:56.621+0800] DEBUG default  [execute command] d:\Program Files\nodejs\node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
[2022-05-17T12:13:25.013+0800] ERROR default  checkActionFile failed: Unexpected end of JSON input
[2022-05-17T12:13:25.014+0800] DEBUG default  [to xtransit-server] <<<<<<<<<<<<<<<<<<< {"appId":2,"agentId":"DESKTOP-188QF22","traceId":"2ee18e89-8863-493a-bfa7-f3b9eaa2e813","clientId":"37629a0d751cd2574a9e89ed9b7a32c0","timestamp":1652760805014,"type":"response","data":{"ok":true,"data":{"stdout":"","stderr":""}},"signature":"3dccd5519d359b6bd81b398faab78f12a9b53586"}

同时留意到在系统temp目录中堆快照是生成成功的。

hyj1991 commented 2 years ago

看起来是 node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {} 这个执行有点问题，stdout 和 stderr 都是空。

https://github.com/X-Profiler/xtransit/blob/v1.5.0/commands/xprofctl.js#L34

可以手动执行下这个文件，看看这里返回了什么信息，我本地的 windows 机器试了下没什么问题

yunnysunny commented 2 years ago

改了一下源代码：

'use strict';

const fs = require('fs');
const os = require('os');
const path = require('path');
const { promisify } = require('util');
const exists = promisify(fs.exists);
const readFile = promisify(fs.readFile);

const [pid, command, options] = process.argv.slice(2);

async function takeAction() {
  const hiddenFile = path.join(os.homedir(), '.xprofiler');
  if (!await exists(hiddenFile)) {
    return console.error(`${hiddenFile} not exists`);
  }

  let result;
  const content = await readFile(hiddenFile, 'utf8');
  for (const proc of content.trim().split('\n')) {
    const [xpid, , , , , mod] = proc.split('\u0000');
    if (Number(pid) !== Number(xpid)) {
      continue;
    }

    // find xctl
    const xctl = path.join(mod, 'lib/xctl.js');
    if (!await exists(xctl)) {
      result = false;
      console.error(`${xctl} not exists`);
      break;
    }
    let _options = {};
    try {
        _options=JSON.parse(options);
    } catch (e) {
    console.error('invalid options',e);
    break;
    }
    const { ok, data, message } = await require(xctl)(pid, command, JSON.parse(options));
    if (!ok) {
      result = false;
      console.error(message);
      break;
    }

    result = true;
    console.log(JSON.stringify(data));
  }

  if (result === undefined) {
    console.error(`process <${pid}> not enable xprofiler`);
  }
}

takeAction().catch(err => console.error(err.message));

然后运行 node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}，结果输出

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
invalid options SyntaxError: Unexpected token e in JSON at position 1
    at JSON.parse (<anonymous>)
    at takeAction (E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js:35:17)
process <24840> not enable xprofiler

通过控制台看xprofile是没有问题的：

hyj1991 commented 2 years ago

你手动执行的时候在命令行的 {} 参数要加引号，要不然当然会解析失败，通过控制台调用的时候有转义，其实已经是字符串了

yunnysunny commented 2 years ago

加了引号确实正常输出了：

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
Unexpected token e in JSON at position 1
PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump {}
invalid options SyntaxError: Unexpected token e in JSON at position 1
    at JSON.parse (<anonymous>)
    at takeAction (E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js:35:17)
process <24840> not enable xprofiler
PS C:\Users\lenovo> tasklist | findstr 24840
node.exe                     24840 Console                    3    133,828 K
PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump "{}"
{"filepath":"C:\\Users\\lenovo\\AppData\\Local\\Temp\\x-heapdump-24840-20220517-1.heapsnapshot"}

hyj1991 commented 2 years ago

PS C:\Users\lenovo> node.exe E:\kuaipan\code\node7\authing-server-orbiter\node_modules\xtransit\commands\xprofctl.js 24840 heapdump "{}"
{"filepath":"C:\\Users\\lenovo\\AppData\\Local\\Temp\\x-heapdump-24840-20220517-1.heapsnapshot"}

这个是正常的输出，stdout 是一个 json 字符串，parse 后里面有 filepath 属性

那么你在控制台调用的时候，看看这里会输出什么

hyj1991 commented 2 years ago

由于 windows 下文件盘符是 \，我猜测还是处理转义的时候哪里出了问题导致 JSON 的 parse 挂了

yunnysunny commented 2 years ago

由于 windows 下文件盘符是 \，我猜测还是处理转义的时候哪里出了问题导致 JSON 的 parse 挂了

既然你的windows下能用的话，感觉不像是一个必现的问题。

hyj1991 commented 2 years ago

你可以调试下这个文件，看看在你的机器上这里通过控制台调用的时候输出了什么，如果 stdout 正常能拿到 filepath 的话，控制台调用就可以成功。

yunnysunny commented 2 years ago

https://github.com/X-Profiler/xtransit/blob/master/lib/handler.js#L34

看下进了这个 if 判断后这里的 options 和 stdout 输出了啥，正常不会有 parse 的问题

我在这行打印了，stdout 是空 stderr 也是空

hyj1991 commented 2 years ago

你可以在本机 dbeug 下这段逻辑，我试了下无法复现，没法帮你看这个问题。

hyj1991 commented 2 years ago

没有更多反馈先关闭了

X-Profiler / xprofiler

收集堆信息时，进程退出 #179