记一次egg-init bug修复过程

一.起源

项目使用egg开发(win10)，几个月前使用egg-init 初始化项目时,选择类型后就经常卡住，原先以为是网的问题, 但是换成npm init egg --type=simple就可以了，大概率是哪里出bug了最近有时间看了下，记录一下 这个bug的奇特之处在于过程中没有任何报错信息，甚至连ctrl+c都失效了

二.初探

首先找到全局egg-init脚本（window），调用了egg-init.js，在egg-init.js中调用了init_command.js

从命令行看，项目卡在了找到最后一行打印位置fetching npm info 看起来curl似乎没有问题，也没有报错信息

// egg-init/lib/init_command.js
* getPackageInfo(pkgName, withFallback) {
    this.log(`fetching npm info of ${pkgName}`);
    try {
      const result = yield this.curl(`${this.registryUrl}/${pkgName}/latest`, {
        dataType: 'json',
        followRedirect: true,
        maxRedirects: 5,
        timeout: 5000,
      });
      assert(result.status === 200, `npm info ${pkgName} got error: ${result.status}, ${result.data.reason}`);
      return result.data;
    } catch (err) {
      if (withFallback) {
        this.log(`use fallback from ${pkgName}`);
        return require(`${pkgName}/package.json`);
      } else {
        throw err;
      }
    }
  }

再看调用getPackageInfo的地方，代码如下，咦，下一步应该打印downloading，但是控制台没有打印, 打印下result看看，控制台也是空的在往前一步，难道getPackageInfo出错了？但是用了try catch也没有打印错误，会不会阻塞在this.curl里了呢？

* downloadBoilerplate(pkgName) {
    const result = yield this.getPackageInfo(pkgName, false);
    const tgzUrl = result.dist.tarball;

    this.log(`downloading ${tgzUrl}`);

    const saveDir = path.join(os.tmpdir(), 'egg-init-boilerplate');
    yield rimraf(saveDir);

    const response = yield this.curl(tgzUrl, { streaming: true, followRedirect: true });
    yield compressing.tgz.uncompress(response.res, saveDir);

    this.log(`extract to ${saveDir}`);
    return path.join(saveDir, '/package');
  }

进去curl

* curl(url, options) {
  console.log('url', url, 'options', options)
    return yield this.httpClient.request(url, options);
  }

打印下看看 console.log('url', url, 'options', options)

url https://registry.npmjs.org/egg-boilerplate-simple/latest options {
  dataType: 'json',
  followRedirect: true,
  maxRedirects: 5,
  timeout: 5000
}

进去this.httpClient.request ，使用了urllib这个库之后在urllibli里控制台打印了start request,说明发起调用了，但是为何阻塞了呢，在res监听data, error,close事件处添加log,控制台均没有任何输出

  var req;
  // request headers checker will throw error
  try {
    req = httplib.request(options, onResponse);
    console.log('start request')
    if (args.trace) {
      req._callSite = {};
      Error.captureStackTrace(req._callSite, requestWithCallback);
    }
  } catch (err) {
    return done(err);
  }

用wireshark抓包有数据,也就是说curl调用了，但是console.log失效这时候有几种可能了， node文档里写在window下,终端是tty的话， process.stdout是异步的所以可能write了还没flush

Writes may be synchronous depending on what the stream is connected to and whether the system is Windows or POSIX:

Files: synchronous on Windows and POSIX TTYs (Terminals): asynchronous on Windows, synchronous on POSIX Pipes (and sockets): synchronous on Windows, asynchronous on POSIX

于是把this.log里的console.log 换成fs.writeFileSync

* downloadBoilerplate(pkgName) {
    this.log('begin')
    const result = yield this.getPackageInfo(pkgName, false);
    this.log('after')
    const tgzUrl = result.dist.tarball;
    this.log(`downloading ${tgzUrl}`);
  
  }
  
  * getPackageInfo(pkgName, withFallback) {
    this.log(`fetching npm info of ${pkgName}`);
    try {
      const result = yield this.curl(`${this.registryUrl}/${pkgName}/latest`, {
        dataType: 'json',
        followRedirect: true,
        maxRedirects: 5,
        timeout: 5000,
      });
      this.log(JSON.stringify(result))
      return result.data;
    } catch (err) {
  //...省略
   }
   
   log() {
    const args = Array.prototype.slice.call(arguments);
    // args[0] = `[${this.name}] `.blue + args[0];
    fs.writeFileSync('../temp', JSON.stringify(args) + '\n', { flag: 'a' })
    console.log.apply(console, args);
  }
  }

文件里打印如下，为何没有打印’after’呢？

["begin"]
["fetching npm info of egg-boilerplate-simple"]
[{"data":{"name":"egg-boilerplate-simple","version":"3.3...

一种可能是可能任务队列或事件队列里存在优先级更高的任务或事件

这时候看下整个过程

1.detect registry url —>2.ask for target dir---->3.use local template —>4.list boilerplate–>5.ask for boilerplate—>6.download boilerplate

在第6步阻塞了，看控制台，第4步也调用了getPackageInfo,然而后面的promise没有阻塞于是问题可能在第5步经过一系列探测，问题发生在inquirer.prompt，如果去掉inquirer.prompt，直接返回 boilerplateInfo ，程序执行成功~

* askForBoilerplateType(mapping) {
  ...
  choices.unshift(new inquirer.Separator());
  return choices[1].value //直接返回boilerplateInfo
  const { boilerplateInfo } = yield inquirer.prompt({
    name: 'boilerplateInfo',
    type: 'list',
    message: 'Please select a boilerplate type',
    choices,
    pageSize: choices.length,
  });
if (!boilerplateInfo.deprecate) return boilerplateInfo;

于是要么是choices数据的问题导致，要么是inquirer的bug egg-init依赖的inquirer版本是3.3.0，安装最新版7.0.0，程序执行成功，问题解决

为了复现这个问题，安装inquirer 3.3.0

demo1:

const inquirer = require("inquirer");
const fs = require('fs')
const choices = [
  {
    name: "asd",
    value: "asd"
  },
  {
    name: "a",
    value: "a"
  }
];
(async () => {
  setInterval(() => {
    console.log(1);
    fs.writeFileSync('./temp', 'test', { flag: 'a' })
  }, 1000);
  const p = await inquirer.prompt({
    name: "boilerplateInfo",
    type: "list",
    message: "Please select a boilerplate type",
    choices,
    pageSize: choices.length
  });
  console.log(3);
})();

output

? Please select a boilerplate type asd
3

这里没有打印1，temp文件也是空的,看起来定时器setInterval没有执行

到这里bug原因似乎找到了，由于第一个inquirer.prompt导致的

但是demo和前面egg-init行为有一点不一样此时ctrl+c 会终止程序，而egg-init按住ctrl+c 不会终止程序

复现inquirer的demo 去掉console.log 会怎么样呢，神奇的事发生了

temp文件有输出了!!每隔一秒输出’test’ 也就是说在inquirer.prompt之后异步调用（时间间隔大于1毫秒）console.log 导致程序阻塞了，没错是阻塞（永久暂停）了 (写了个小demo,用vscode+chrome debug确实是阻塞了，探索了下inquirer.prompt里的代码，顺便学了个rxjs,最后抽丝剥茧似乎像是node的bug，这里先略过)

结论一：重新捋一下，inquirer.prompt之后异步调用（时间间隔大于1毫秒）console.log 会导致程序阻塞

init_command和urllib的程序里面有 console.log，去掉会怎么样呢哇~after downloading都有了程序最后打印 collecting boilerplate

$ cat temp

["use boilerplate: simple(egg-boilerplate-simple)"]
["begin"]
["fetching npm info of egg-boilerplate-simple"]
["result"]
["after"]
["downloading https://registry.npmjs.org/egg-boilerplate-simple/-/egg-boilerplate-simple-3.3.1.tgz"]
["extract to C:\\Users\\tiany\\AppData\\Local\\Temp\\egg-init-boilerplate"]
["askForVariable"]
["collecting boilerplate config..."]

log之后又调用了inquirer.prompt，但是控制台没有任何输出所以问题和第两次inquirer.prompt也有关系，由于keys有几种，一个个去掉，现象均一样，所以和key的类型没有关系

if (this.argv.silent) {
     ...
      this.log('use default due to --silent, %j', result);
      return result;
    } else {
      return yield inquirer.prompt(keys.map(key => {
        const question = questions[key];
        return {
          type: question.type || 'input',
          name: key,
          message: question.description || question.desc,
          default: question.default,
          filter: question.filter,
          choices: question.choices,
        };
      }));
    }

于是抽出代码测试（建demo2）,果然行为和egg-init阻塞一样，按住ctrl+c也不会终止，去inquirer的Github上看了下，有几个相似的bug，https://github.com/SBoudrias/Inquirer.js/issues/811 inquirer@6.4.1居然还有这样的bug，(虽然6.4.1那个bug原因和这个底层不太一样)

demo2:

//inquirer@3.3.0
const inquirer = require("inquirer");
(async () => {
    const choices = [
        {
            name: "asd",
            value: "asd"
        },
        {
            name: "a",
            value: "a"
        }
    ];
    const choices1 = [
        {
            name: "asd",
            value: "asd"
        },
        {
            name: "a",
            value: "a"
        }
    ];
    const p = await inquirer.prompt({
        name: "boilerplateInfo",
        type: "list",
        message: "Please select a boilerplate type",
        choices,
        pageSize: choices.length
    });
    await inquirer.prompt({
        name: "boilerplateInfo",
        type: "list",
        message: "Please select a boilerplate type",
        choices1,
        pageSize: choices1.length
    });
})();

好了问题原因终于清楚了，是两个inquirer.prompt导致的

等等好像哪里有问题，查看downloadBoilerplate函数

* downloadBoilerplate(pkgName) {
    const result = yield this.getPackageInfo(pkgName, false);
    const tgzUrl = result.dist.tarball;
    fs.writeFileSync('../temp2', 'start print downloading', { flag: 'a' })
    this.log(`downloading ${tgzUrl}`);
    fs.writeFileSync("../temp2", "end print downloading", { flag: 'a' })
    const saveDir = path.join(os.tmpdir(), 'egg-init-boilerplate');
    yield rimraf(saveDir);

    const response = yield this.curl(tgzUrl, { streaming: true, followRedirect: true });
    yield compressing.tgz.uncompress(response.res, saveDir);

    this.log(`extract to ${saveDir}`);
    return path.join(saveDir, '/package');
  }

在 6.download boilerplate 执行过程是 getPackageInfo —>this.log(fetching npm info of ${pkgName})—> this.curl(${this.registryUrl}/${pkgName}/latest —>this.log(downloading ${tgzUrl});—>rimraf —>curl(tgzUrl)—>save

this.log(downloading ${tgzUrl})是在curl结束之后调用的,按前面的demo1，异步调用console.log程序会block 程序压根没有执行到第二个inquirer.prompt,上面执行是因为把console.log全部换成了fs.writeFileSync，包括程序init_command源码里的console.log，破坏了案发现场所以还原init_command源码，只在必要地方添加fs.writeFileSync打印，程序阻塞在了this.log(downloading ${tgzUrl})

所以问题还是第一个inquirer.prompt引起的，但是demo1 按ctrl+c会停止原因是demo1定时器在inquirer.prompt之前，改一下顺序见demo3，'1’没有被打印出来，按ctrl+c也没有停止,程序在执行console后block(hang)了

demo3:

//inquirer@3.3.0
const inquirer = require("inquirer");
const fs = require('fs')
const choices = [
  {
    name: "asd",
    value: "asd"
  },
  {
    name: "a",
    value: "a"
  }
];
(async () => {
  
  const p = await inquirer.prompt({
    name: "boilerplateInfo",
    type: "list",
    message: "Please select a boilerplate type",
    choices,
    pageSize: choices.length
  });
  console.log(3);
  setInterval(() => {
    console.log(1);
    fs.writeFileSync('./temp', 'test', { flag: 'a' })
  }, 1000);
})();

总结起来就是:

1. 问题还是第一个inquirer.prompt引起的，调用curl完成之后，又this.log(‘downloading’)，按上面的demo3，程序block/hang了（ctrl+c和任何输入都无效），这也解释了为什么wireshark抓包有数据,控制台却没有打印

至于demo3产生bug的深层次原因，还不太清楚-.- 解决方案: 更新inquier包到7.0.0版本

2. 为什么ctrl+c会失效呢

结论：inquirer.prompt结束后，程序处于非raw模式，当process.stdin处于非raw 模式时,ctrl+c会产生’SIGINT’信号

ctrl+c失效是由于：程序里监听了’SIGINT’信号,而当按ctrl+c产生’SIGINT’信号, 而监听’SIGINT’信号的函数由于程序block/hang了，所以该函数并没有执行

而如果没有主动监听’SIGINT’信号,默认的行为是退出程序

看demo3 inquirer.prompt内部会调用readline.createInterface实例化一个readline对象，监听SIGINT’信号

但是inquirer.prompt完成后会调用readline.close()，同时取消监听的SIGINT’信号,暂停process.stdin 所以之后还在哪监听了’SIGINT’事件呢

用vscode+chrome debug

node --inspect-brk index.js

//inquirer@3.3.0
const inquirer = require("inquirer");
const fs = require('fs')
const choices = [
  {
    name: "asd",
    value: "asd"
  },
  {
    name: "a",
    value: "a"
  }
];
(async () => {
  
  const p = await inquirer.prompt({
    name: "boilerplateInfo",
    type: "list",
    message: "Please select a boilerplate type",
    choices,
    pageSize: choices.length
  });
  let listeners = process.rawListeners('SIGINT')
  console.log(3);
  setInterval(() => {
    console.log(1);
    fs.writeFileSync('./temp', 'test', { flag: 'a' })
  }, 1000);
})();

查看listeners，原来是 inquirer 引入了cli-cursor， cli-cursor引入了restore-cursor restore-cursor引入了signal-exit signal-exit里监听了process.on(‘SIGINT’)

sigListeners[sig] = function listener() {
    // If there are no other listeners, an exit is coming!
    // Simplest way: remove us and then re-send the signal.
    // We know that this will kill the process, so we can
    // safely emit now.
    var listeners = process.listeners(sig)
    if (listeners.length === emitter.count) {
      unload()
      emit('exit', null, sig)
      /* istanbul ignore next */
      emit('afterexit', null, sig)
      /* istanbul ignore next */
      process.kill(process.pid, sig)
    }
  }

如果在demo3里移除监听SIGINT信号，则ctrl+c可以终止函数了

process.removeListener("SIGINT", listeners[0]);

3.为什么输入没显示呢

因为inquirer.prompt结束后会调用 process.stdin.pause() 暂停了输入流

4.解决方案

跟新inquirer到最新版本(7.0.0)解决问题

三.测试的bug

原以为问题解决了，运行egg-init测试用例的时候在win10上又阻塞了从控制台输出看执行完测试should work with prompt，程序block(hang)住了

it('should work with prompt', function* () {
    helper.mock([[ 'simple-app', 'this is xxx', 'TZ', helper.KEY_ENTER, 'test', helper.KEY_ENTER ]]);
    const boilerplatePath = path.join(__dirname, 'fixtures/simple-test');
    yield command.run(tmp, [ 'simple-app', '--force', '--template=' + boilerplatePath ]);

    assert(fs.existsSync(path.join(command.targetDir, '.gitignore')));
    assert(fs.existsSync(path.join(command.targetDir, '.eslintrc')));
    assert(fs.existsSync(path.join(command.targetDir, 'package.json')));
    assert(fs.existsSync(path.join(command.targetDir, 'simple-app')));
    assert(fs.existsSync(path.join(command.targetDir, 'test', 'simple-app.test.js')));

    const content = fs.readFileSync(path.join(command.targetDir, 'README.md'), 'utf-8');
    assert(/default-simple-app/.test(content));
    assert(/filter-test/.test(content));
  });

主要用到函数是mock

mock(actions) {
  this.inquirer.prompt = opts => {
    const result = this.originPrompt.call(this.inquirer, opts);
    const key = actions.shift() || '\n';
    if (key) {
      if (Array.isArray(opts) && !Array.isArray(key)) {
        throw new Error(`prompt multiple question, but mock with only one key \`${key}\`, should provide array`);
      } else {
        this.sendKey(key);
      }
    }
    return result;
  };
}

sendKey(arr) {
  if (Array.isArray(arr)) {
    return arr.reduce((promise, key) => {
      return promise.then(() => this.sendKey(key));
    }, Promise.resolve());
  } else {
    const key = arr;
    return new Promise(resolve => {
      setTimeout(() => {
        process.stdin.emit('data', key + '\n');
        resolve(key);
      }, 10);
    });
  }
}

test的执行过程可以简述为 helper.mock代理了inquirer.prompt方法，actions保存在闭包里，执行command.run，当新的inquirer.prompt执行时，会执行原先的originPrompt.prompt 此时等待用户输入，this.sendKey会将事先存在actions里的keys（[ ‘simple-app’, ‘this is xxx’, ‘TZ’, helper.KEY_ENTER, ‘test’, helper.KEY_ENTER ]）取出来每隔10毫秒递归调用，接着inquirer得到answers，inquirer.prompt执行完成，console.log输出，测试用例should work with prompt执行成功，开始执行新的测试用例 should prompt,当执行到console.log 程序block/hang住

下面用简单的demo描述这个bug

'use strict';
const inquirer = require('inquirer');
(async () => {
  const p1 = inquirer.prompt({
    type: 'input',
    name: 'name',
    message: 'project name',
  });

  // it will block
  setTimeout(() => {
    process.stdin.emit('data', 'simple-app\n');
  }, 10);

  await p1.then(() => {
    console.log('this is a test');
  });
  setTimeout(() => {
    console.log(2);
  }, 10);
})();

test里为了模拟用户输入，采用了emit 'data’事件如果是真人直接输入，程序能正常执行问题出在模拟用户输入,可能是node的bug 临时想到的解决方案是 inquirer.prompt完成后先恢复process.stdin流，再sleep很短的时间

'use strict';
const inquirer = require('inquirer');
function sleep(time) {
    return new Promise(resolve => {
        setTimeout(resolve, time);
    });
};
(async () => {
  const p1 = inquirer.prompt({
    type: 'input',
    name: 'name',
    message: 'project name',
  });

  // it will block
  setTimeout(() => {
    process.stdin.emit('data', 'simple-app\n');
  }, 10);
  await p1.then(() => p1.ui.rl.input.resume())
  await sleep(10) //this is neccessary
  await p1.then(() => {
    console.log('this is a test');
  });
  setTimeout(() => {
    console.log(2);
  }, 10);
})();

pr链接

atian25 1楼•4 年前

太赞了。。。整理下排版投稿一份到我们的知乎专栏吧。

这个问题之前偶尔也会有人反馈 issue，但没 Win 机器，感觉楼主很仔细的分析。

PS：惭愧，egg-init 是我当时参与到 Egg 时开始写的第一份代码，那段代码一直很不满意，一直没有时间重构。

supperchong 2楼•4 年前作者

@atian25 好的，重构了就没有我啥事了哈哈

hyj1991 3楼•4 年前

很有意思的问题，看了下感觉像是 libuv 使用 IOCP 在 windows 下实现 eventloop 的一个 bug，demo3 的 setInterval 不生效是因为 inquirer 里选择完毕后会去 close readline：

// lib/baseUI.js
this.rl.output.end();
this.rl.pause();
this.rl.close();

然而 readline close 逻辑导致了 event loop 阻塞了，但是也不是主线程死循环的那种阻塞，而是单纯的无法进入下一个 tick。我试了下，在这种情况下就算起一个额外的 uv thread 线程，然后等 demo3 选择完卡住后，在外部触发其调用 uv_async_send 也无法再触发主线程注册的回调，但是同样的例子在 mac/linux 下都是好的，说明基于 kqueue/epoll 实现的 event loop 是没有这个 bug 的

974806047 4楼•4 年前

太强了。。。

dengnan123 5楼•4 年前

一路调试到底，很猛

waitingsong 6楼•4 年前

这个坑是nodejs还是windows呢～

yviscool 7楼•4 年前

想必费了很大精力，佩服佩服

JianmingXia 8楼•4 年前

值得学习了~

supperchong 9楼•4 年前作者

@hyj1991 赞，奇怪的是以下的rl.close()不会阻塞

const readline = require("readline");

const rl = readline.createInterface({
 input: process.stdin,
 output: process.stdout
});
rl.input.on('keypress', () => {
 rl.close();
})

setInterval(() => {
 console.log('test')
}, 1000);

但是如果换成这样就阻塞了

const readline = require("readline");

const rl = readline.createInterface({
 input: process.stdin,
 output: process.stdout
});

 setTimeout(() => {
     rl.close();
 }, 1000);
setInterval(() => {
 console.log('test')
}, 5000);