New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

使用 mongoose 会导致 mongodb tracer 失效 #221

Closed
myfjdthink opened this Issue Apr 10, 2018 · 17 comments

Comments

Projects
None yet
4 participants
@myfjdthink

myfjdthink commented Apr 10, 2018

我写了一个 koa + mongoose 的 demo,想看看 Pandora 的 tracer 记录的效果,结果是只记录了 http 请求的信息,没有记录 mongo 相关的查询。
打开 debug,项目启动时输出了如下信息:

> pandora-koa-mongoose-demo@1.0.0 dev /Users/nick/nodePro/pandora-koa-mongoose-demo
> pandora dev

  PandoraHook:Mongodb:Shimmer instrument module  Gridstore +0ms
  PandoraHook:Mongodb:Shimmer instrument module  OrderedBulkOperation +1ms
  PandoraHook:Mongodb:Shimmer instrument module  UnorderedBulkOperation +1ms
  PandoraHook:Mongodb:Shimmer instrument module  CommandCursor +0ms
  PandoraHook:Mongodb:Shimmer instrument module  AggregationCursor +0ms
  PandoraHook:Mongodb:Shimmer instrument module  Cursor +0ms
  PandoraHook:Mongodb:Shimmer instrument module  Collection +0ms
  PandoraHook:Mongodb:Shimmer instrument module  Db +0ms
2018-04-10 17:29:13,485 INFO 52540 Process [name = klg-koa-demo, pid = 52543] Started successfully!
** Application start successful. **
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +211ms
enter connected
mongodb connected successfully
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +1ms
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +0ms
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +0ms
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +1ms
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +1ms
  PandoraHook:Mongodb:Shimmer No current tracer, skip trace +7ms

可以看到 PandoraHook:Mongodb:Shimmer No current tracer, skip trace +0ms 是因为没有找到 tracer,看了下代码,traceId 是在 TraceManager.create 方法中写入的,过了一遍代码并没有找到调用 TraceManager.create 的地方。

@guangwong

This comment has been minimized.

Member

guangwong commented Apr 10, 2018

@mariodu 看看

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 10, 2018

我看下

@czy88840616

This comment has been minimized.

Member

czy88840616 commented Apr 11, 2018

在dev模式下是不追踪的吧 ? @guangwong @mariodu

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 11, 2018

@myfjdthink 已经定位到问题了,在写解决方案。是因为 mongoose 依赖的 mquery 使用了一个异步调用(setImmediate/process.nextTick),导致了上下文丢失。默认支持的 mongodb 这个原生客户端。最近几天可以发布修复

@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 11, 2018

我刚好也大概定位到问题,只知道是上下文丢失了。
原来是 mongoose 这边的问题。
image
image

@myfjdthink myfjdthink changed the title from mongo tracer 是在哪里初始化的? to 使用 mongoose 会导致 mongodb tracer 失效 Apr 11, 2018

@czy88840616 czy88840616 added the bug label Apr 11, 2018

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 12, 2018

我又仔细看了一下,应该是 mongoose 的用法错误导致的,pandora 的 mongodb 节点采集没有问题的。

mongoose 查询分两种形式,callback 和 promise。但 mongoose 使用 promise 形式调用和我们常见的 promise 封装不太一样。

你调用 User.findOne 默认返回的是 Query 对象的实例,并不是 promise,此时 await 是没有意义的,查询并不会执行。你需要调用它的 then 方法来执行这个查询,才会真正返回 promise。

而当你使用 User.findOne(callback) 时,是直接执行这个查询,并返回结果到 callback 中。

所以你可以改成 User.findOne().then() 这样,就可以了。

mongoose 这个的 promise api 设计有点诡异,不合常规

相关链接:

https://github.com/Automattic/mongoose/blob/master/lib/query.js#L1608
https://github.com/Automattic/mongoose/blob/master/lib/query.js#L3044
https://github.com/aheckmann/mquery/blob/master/lib/mquery.js#L1802

@myfjdthink 调用逻辑应该就是这样,你可以仔细看下。不传 callback 默认是返回 Query 实例,不是 promise,query 不执行,需要自己 then 或者·exec

@mariodu mariodu added question and removed bug labels Apr 12, 2018

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 13, 2018

@czy88840616

This comment has been minimized.

Member

czy88840616 commented Apr 16, 2018

@myfjdthink 问题是否已经解决?

@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 17, 2018

@mariodu @czy88840616 抱歉回复晚了,这几天比较忙,今天开始跟进,稍后在这里 update。

@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 17, 2018

我目前跟踪发现的问题是:async_hooks 碰到“模拟的 Promise” 会丢失上下文。
先解释下什么是模拟的上下文。
根据 @mariodu 描述,mongoose 提供的查询方法类似 findOne 并没有返回原生的 Promise,返回的是 Query 对象,的确是这样,但是 Query 是带有 then 属性的,所以可以当做 Promise 来调用,实际上 mongoose 依赖的 mquery 是这样模拟 Promise 的

Query.prototype.then = function(resolve, reject) {
  var self = this;
  var promise = new Query.Promise(function(success, error) {
    self.exec(function(err, val) {
      if (err) error(err);
      else success(val);
      self = success = error = null;
    });
  });
  return promise.then(resolve, reject);
}

https://github.com/aheckmann/mquery/blob/9a922c28c46cde692faf0fa59daab197f00997e4/lib/mquery.js#L2773

通过 @mariodu 在 mongoose 那边发的 discussion: Automattic/mongoose#6335 可以知道,mongoose这样设计 Promise 是为了实现链式调用。

但是,经过测试,直接调用 findOne 会丢失 tracer 上下文,如下:

const user = await User.findOne({})

换一个写法,替换成原生的 Promise,tracer 上下文正确获取

const user = await User.findOne({}).then()

同样地,superagent 这个库也有同样的问题,因为它也是在 prototype 中添加 then 属性来模拟实现的 Promise
https://github.com/visionmedia/superagent/blob/c2f65c665cf1738c5ed8f31c9d255f0a0afa70b2/lib/request-base.js#L231

总之,现象就是:要是 trace 生效必须明确地调用 User.findOne({}).then() 来返回 Promise 对象。

这里我不太理解的地方是,既然 User.findOne({}) 返回的不是 Promise ,那为什么

const user = await User.findOne({})

实际上却能成功执行并返回值呢?

@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 17, 2018

为了方便测试,我添加了一段示例代码:
https://github.com/myfjdthink/pandora-koa-mongoose-demo/blob/master/src/AsyncHooks.js

两种调用方式会有区别

const result = await fake.query(233)    // end 方法内将拿不到 session user (非真正promise 对象)
const result = await fake.query(233).then()  // end 方法内可以拿到 session user 
@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 17, 2018

我猜测是 fake.query(233) 没有返回真正的 promise 对象,缺少了某项属性,导致 async-hooks 上下文断开,明天查一下资料看看是什么属性。
目前猜测是 AsyncResource petkaantonov/bluebird#1472

4-18 update: 不是这个原因

@myfjdthink

This comment has been minimized.

myfjdthink commented Apr 18, 2018

add issue in repository cls-hooked Jeff-Lewis/cls-hooked#23

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 18, 2018

await 之后的内容如果不是 promise,会做一个 promise.resolve 的处理。

@mariodu

This comment has been minimized.

Member

mariodu commented Apr 18, 2018

mongoose 会破坏 async-hooks 的上下文,这个是 nodejs/diagnostics 已知的问题。
https://github.com/nodejs/diagnostics/blob/master/tracing/AsyncHooks/problematic-modules.md

@czy88840616

This comment has been minimized.

Member

czy88840616 commented Apr 25, 2018

本 issue 由于长期未更新并暂时 close,如果后期有变化可以 reopen 继续讨论。

@myfjdthink

This comment has been minimized.

myfjdthink commented May 2, 2018

这里补充最后的解决方案吧。
目前明确是 mongoose 实现 Promise 的方式导致了这个问题。
也有人在 mongoose 那边提了 Issue: Automattic/mongoose#5929
在 mongoose 作者据称在 5.1 版本会修复这个问题。
在 mongoose 修复这个问题之前,我们可以先使用 cls-mongoose 解决问题。
最后,感谢各位的答疑。

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment