mocha 忽略未定义变量错误问题定位

问题描述

在开发云感上位机软件时，使用 mocha 进行测试，发现一个奇怪的现象：如下面这段代码，on open 的回调函数里面的"abcde"是一个语法错误，但 mocha 不会报错。

const SerialPort = require('@serialport/stream')
const MockBinding = require('@serialport/binding-mock')

describe('serialport', function () {
  it('should throw error', function () {
    SerialPort.Binding = MockBinding

    MockBinding.createPort('/dev/ROBOT', { echo: false, record: false })
    const port = new SerialPort('/dev/ROBOT')

    port.on('open', () => {
      // The following line is a syntax error, but mocha doesn't report it.
      abcde
      console.log('The port is opened.\n')
    })
  })
})

定位过程

确认是否与 mocha 有关

首先去掉 mocha 相关代码，去掉后的代码如下：

const SerialPort = require('@serialport/stream')
const MockBinding = require('@serialport/binding-mock')

SerialPort.Binding = MockBinding

MockBinding.createPort('/dev/ROBOT', { echo: true, record: true })
const port = new SerialPort('/dev/ROBOT')

port.on('open', () => {
  abcde
  console.log('opened')
})

使用 node 运行以上代码，是可以报错的：

along:/tmp/js/learn-serialport$ node demo.js
/tmp/js/learn-serialport/demo.js:10
  abcde
  ^

ReferenceError: abcde is not defined
    at SerialPort.<anonymous> (/tmp/js/learn-serialport/demo.js:10:3)
    at SerialPort.emit (node:events:527:28)
    at binding.open.then.opening (/tmp/js/learn-serialport/node_modules/@serialport/stream/lib/index.js:234:12)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

Node.js v17.7.0

这足以说明确实与 mocha 有关。

另外少彪同学发现在他的电脑上（node v10.16.3，mocha@5.2.0），运行以下代码也不会报错：

describe('setTimeout', function () {
  it('throws error', function () {
    setTimeout(function () {
      throw new Error('boo')
    }, 1000)
  })
})

但在我电脑上（node v17.7.0，mocha@9.2.2）运行是会报错的：

along:/tmp/js/learn-serialport$ npx mocha 3_test.js

  describe
    ✔ fails

  1 passing (3ms)

/tmp/js/learn-serialport/node_modules/mocha/lib/runner.js:962
    throw err;
    ^

Error: boo
    at Timeout._onTimeout (/tmp/js/learn-serialport/3_test.js:4:13)
    at listOnTimeout (node:internal/timers:559:17)
    at processTimers (node:internal/timers:502:7)

Node.js v17.7.0

这又说明不同版本的 mocha 处理异常的行为还不太一样。

确认是否「mocha + 事件回调」就能触发该问题

现在的问题是「mocha + serialport 事件回调」的场景触发的，很自然想到是否「mocha + 普通的事件回调」也能触发同样的问题，于是写了以下代码：

const chai = require('chai')
const EventEmitter = require('events')

class MyEmitter extends EventEmitter {}

const myEmitter = new MyEmitter()

myEmitter.on('event', () => {
  daf
  console.log('an event occurred!')
})

describe('EventEmitter', function () {
  it('should throw error', function () {
    myEmitter.emit('event')
  })
})

运行时会报错（如下所示），看来普通的事件回调不能触发该问题。

along:/tmp/js/learn-serialport$ npx mocha 4_test.js

  EventEmitter
    1) should throw error

  0 passing (4ms)
  1 failing

  1) EventEmitter
       should throw error:
     ReferenceError: daf is not defined
      at MyEmitter.<anonymous> (4_test.js:9:3)
      at MyEmitter.emit (node:events:527:28)
      at Context.<anonymous> (4_test.js:15:15)
      at processImmediate (node:internal/timers:466:21)

确认是否与多线程有关

我一直有个疑点：

测试用例代码（describe 和 it 的回调函数）与 serialport 的回调函数代码，会不会是在不同线程执行的？后者由于语法错误导致线程崩溃，但前者无法感知，导致不会报错。

因此我尝试使用 ps 命令来观察运行测试用例时的进程状态。

首先，我在原来的脚本中使用 setInterval 增加一个定时任务，目的是让进程一直不退出，以便观察。

然后使用npx mocha serialport_interval_test.js运行该脚本，再使用ps -elf找到对应进程的 pid（如下所示）。

从控制台输出可以发现，运行npx mocha xxx.js时，会启动 npm 程序，而 npm 程序会 fork 一个进程会执行 mocha 程序， mocha 程序会 fork 一个进程来执行node mocha命令。所以，使用 mocha 运行测试用例，其实是使用 node 工具来执行 mocha 脚本，mocha 脚本运行时则会执行测试用例脚本。

along:/tmp/js/learn-serialport$ ps -elf | grep serialport
0 S along      90498   76455  4  80   0 - 177186 ep_pol 10:09 pts/8   00:00:00 npm exec mocha serialport_interval_test.js
0 S along      90509   90498  0  80   0 -   655 do_wai 10:09 pts/8    00:00:00 sh -c mocha "serialport_interval_test.js"
0 S along      90510   90509  3  80   0 - 2770702 ep_pol 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js

查看进程 90510 的线程情况，发现线程数量自始至终不会改变，一直是7个。（至于为啥是7个，这个要了解 node 的实现）这说明并不存在线程崩溃的情况。我之前的猜测是有问题的。

along:/tmp/js/learn-serialport$ ps -elfL -q 90510
F S UID          PID    PPID     LWP  C NLWP PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
0 S along      90510   90509   90510  0    7  80   0 - 2770702 ep_pol 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90511  0    7  80   0 - 2770702 ep_pol 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90512  0    7  80   0 - 2770702 futex_ 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90513  0    7  80   0 - 2770702 futex_ 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90514  0    7  80   0 - 2770702 futex_ 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90515  0    7  80   0 - 2770702 futex_ 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js
1 S along      90510   90509   90516  0    7  80   0 - 2770702 futex_ 10:09 pts/8  00:00:00 node /tmp/js/learn-serialport/node_modules/.bin/mocha serialport_interval_test.js

分析 mocha 源码

使用 ps 命令观察进程状态，虽然没能证明问题与多线程有关，但增加了我对 mocha 的认识：

如上所述，运行npx mocha xxx.js，实质上是使用 node 运行 mocha 程序，mocha 程序再处理测试用例脚本。
更重要的是，我发现 node_modules 目录里的 mocha 程序也是个 js 脚本，我可以直接分析和调试 mocha 程序啦。

接下来，开始阅读 mocha 源码，并简单粗暴地加上 console.log 来理解其执行流程，最终找到了问题原因。

线索出现在 mocha 源码（mocha@9.2.2）的lib/runner.js文件中：

lib/runner.js第1092行注册了 unhandledRejection 事件的处理函数（如下所示）。

this._addEventListener(process, 'unhandledRejection', this.unhandled);

lib/runner.js第187行定义了unhandled函数：

this.unhandled = (reason, promise) => {
  if (isMochaError(reason)) {
    debug(
      'trapped unhandled rejection coming out of Mocha; forwarding to uncaught handler:',
      reason
    );
    this.uncaught(reason);
  } else {
    debug(
      'trapped unhandled rejection from (probably) user code; re-emitting on process'
    );
    this._removeEventListener(
      process,
      'unhandledRejection',
      this.unhandled
    );
    try {
      process.emit('unhandledRejection', reason, promise);
    } finally {
      this._addEventListener(process, 'unhandledRejection', this.unhandled);
    }
  }
};

我们在unhandled的函数入口处增加一行来打印 reason 这个输入参数：

console.log('unhandled:', reason)

重新运行npx mocha test.js，我们发现这时候能报告语法错误了！

along:/tmp/js/learn-serialport$ npx mocha test.js

  serialport
    ✔ should throw error
unhandled: ReferenceError: abcde is not defined
    at SerialPort.<anonymous> (/tmp/js/learn-serialport/test.js:13:7)
    at SerialPort.emit (node:events:527:28)
    at binding.open.then.opening (/tmp/js/learn-serialport/node_modules/@serialport/stream/lib/index.js:234:12)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)


  1 passing (5ms)

这个时候，基本可以确定问题原因了：

mocha 注册了unhandledRejection事件的处理函数，其内部会直接忽略掉用户代码中抛出的异常。导致我们注册的 serialport 的 open 事件处理函数中的语法错误被忽略掉了。

这里还有一个问题，open 事件处理函数中有语法错误，会导致触发unhandledRejection事件吗？

先来看一下 node 官方文档对 unhandledRejection 的解释：

The ‘unhandledRejection’ event is emitted whenever a Promise is rejected and no error handler is attached to the promise within a turn of the event loop. When programming with Promises, exceptions are encapsulated as “rejected promises”.

根据官方说明，如果一个 promise 被 reject 或抛出异常，并且没被捕获处理，就会触发unhandledRejection事件。

那么剩下的问题是确认 open事件处理函数是以 promise 的形式运行的。

查看@serialport/stream/lib/index.js第213 ~ 245行（serialport@9.0.0），发现openCallback确实是在 promise 中被调用。

/**
 * Opens a connection to the given serial port.
 * @param {errorCallback=} openCallback - Called after a connection is opened. If this is not provided and an error occurs, it will be emitted on the port's `error` event.
 * @emits open
 * @returns {undefined}
 */
SerialPort.prototype.open = function (openCallback) {
  if (this.isOpen) {
    return this._asyncError(new Error('Port is already open'), openCallback)
  }

  if (this.opening) {
    return this._asyncError(new Error('Port is opening'), openCallback)
  }

  this.opening = true
  debug('opening', `path: ${this.path}`)
  this.binding.open(this.path, this.settings).then(
    () => {
      debug('opened', `path: ${this.path}`)
      this.opening = false
      this.emit('open')
      if (openCallback) {
        openCallback.call(this, null)
      }
    },
    err => {
      this.opening = false
      debug('Binding #open had an error', err)
      this._error(err, openCallback)
    }
  )
}

总结

回顾整个问题，原因其实很简单，就是 mocha 注册了unhandledRejection的处理函数，把我们代码中出现的异常给拦截掉了。

这启示我们可以写出一些充斥语法错误但不会报错的代码（下面贡献两段）。这也许就是js的神奇（扯淡？）之处吧。

忽略掉未定义变量的错误：

const process = require('process')

process.on('uncaughtException', (err, origin) => {
  console.log('No complaint, I can manage.')
})

You_can_write_something_undefined_here, and_nodejs_would_not_complain_it

忽略掉 Promise reject 错误：

function myPromise() {
  return new Promise((resolve, reject) => {
    setTimeout(() => {
      resolve()
    }, 1000)
  })
}

process.on('unhandledRejection', (err, origin) => {
  console.log('No complaint, I can manage.')
})

myPromise().then((result) => {
  You_can_write_something_undefined_here, and_nodejs_would_not_complain_it
})

遗留问题

使用 node 运行脚本时，会创建7个线程，这7个线程分别是干啥的？
由于使用 Mocha + EventEmitter 无法复现问题，估计 EventEmitter 的回调函数不是在 promise 中执行的，需要确认一下？
serialport 的回调函数为啥要放在 promise 中执行？ EventEmitter 的回调函数为啥不放在 promise 中执行？如何理解 serialport 与 EventEmitter 在处理回调函数上的差异？
node 的事件循环机制是怎样的？
mocha 为什么要这样处理 unhandledRejection 事件？为什么不把用户代码的错误打印出来？作为一个测试框架应该尽可能暴露用户错误吧。

问题描述#

定位过程#

确认是否与 mocha 有关#

确认是否「mocha + 事件回调」就能触发该问题#

确认是否与多线程有关#

分析 mocha 源码#

总结#

遗留问题#