celery踩坑记

0 概述

以前所接触业务从未使用过celery，都是采用类似redis中做一个队列来处理异步任务。
但是这样的缺点是显而易见的，比如debug过程不够直观，每次都要紧盯着redis中的内容，尤其格式还是bytes。
另外一个明显的缺点就是只有一个队列，串行处理起来太慢。
所以这次项目启动，涉及多个异步任务，比如邮件，短信，提币等等，决定使用celery。
然而没有想到的是，在测试阶段都没啥bug，但是在正式服务器上，却时不时报错。
鉴于这种报错从未在测试阶段发现，且严重影响了业务逻辑，一直搞得压力很大。

1 获取日志

第一步，把正式服务器上的celery日志脱到本地去分析。

• 1 发现bug出现的时间不稳定，有时候不会报错。
• 2 报错的bug出现时，一般都是流量高峰。
• 3 报错bug请求前一秒内基本都有同样请求。
• 4 ps： 之前定位bug的时候思路都被带到了报错信息上面，结果花了很多时间，问题还是没有解决。
  直到发现只有在流量高峰的时候才会出现bug。

2 本地稳定复现。

既然高流量才能激发bug，索性来个for循环个100次，去调用celery异步任务A。
终于bug能稳定复现了，但是报错原因不统一，存在多个，同时跟正式服务器日志的报错日志匹配上了。
error1

 [2018-07-24 10:48:43,833: WARNING/ForkPoolWorker-3] (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT token_s      ys_model.id AS token_sys_model_id, token_sys_model.gas_price_gwei AS token_sys_model_gas_price_gwei, token_sys_model.withdraw_eth_fee AS token_sys_model_withdraw_eth_f      ee, token_sys_model.is_deleted AS token_sys_model_is_deleted, token_sys_model.dt_create AS token_sys_model_dt_create \nFROM token_sys_model ORDER BY token_sys_model.id       DESC \n LIMIT %(param_1)s'] [parameters: [{}]]

error2

 7 [2018-07-24 10:28:43,705: WARNING/ForkPoolWorker-3] (pymysql.err.OperationalError) (2006, "MySQL server has gone away (TimeoutError(110, 'Connection timed out'))") [SQ      L: 'SELECT token_sys_model.id AS token_sys_model_id, token_sys_model.gas_price_gwei AS token_sys_model_gas_price_gwei, token_sys_model.withdraw_eth_fee AS token_sys_mo      del_withdraw_eth_fee, token_sys_model.is_deleted AS token_sys_model_is_deleted, token_sys_model.dt_create AS token_sys_model_dt_create \nFROM token_sys_model ORDER BY       token_sys_model.id DESC \n LIMIT %(param_1)s'] [parameters: {'param_1': 1}] (Background on this error at: http://sqlalche.me/e/e3q8)

3 bug初探

目前所有的报错信息都指向了与数据库的连接上面。
那就从连接层面入手：
首先启动celery，不加任何额外参数，数据库执行 show process list ，发现只有一个连接。
观察这个链接，排除超时的原因（如何排除可以查看我的另外一篇文章）

然后去分析celery的并发模型，发现一个concurrency 参数。
默认个数为cpu核数，默认并发模型为prefork，也就是多线程or多进程（这块不太明白）。
目前端倪已初现，很有可能是因为 并行程序共用数据库连接

4 stack over flow 确认

搜索关键词为celery connection error的帖子，很多都没有大的用处，都是在说参数什么的。
直到看到了这篇帖子

https://stackoverflow.com/questions/19300644/resourceclosederror-with-mysql-sqlalchemy-and-celery

这个帖子虽然还没有正式回答，但是目前来看，他的问题与我的log是最接近的。
同时在comments部分，楼主指出使用-c 1 指定一个线程去执行，并不会触发bug。
果然，在本地测试-c 1 参数也没有出现bug。
至此。bug已确认。

5 学习

官方文档明确指出：

"The Session object is entirely designed to be used in a non-concurrent fashion,
which in terms of multithreading means "only in one thread at a time" ..
some process needs to be in place such that mutltiple calls across many threads don’t actually get a handle to the same session. 
We call this notion thread local storage."

即，session对象只能在一个线程中使用，不能多个线程同时使用同一个session
，如果非要公用session，那么可以使用ScopedSession

The ScopedSession object by default uses [threading.local()] as storage, 
so that a single Session is maintained for all who call upon the ScopedSession registry, 
but only within the scope of a single thread.
Callers who call upon the registry in a different thread get a Session instance that is local to that other thread.
Using this technique, the ScopedSession provides a quick and relatively simple way of providing a single, 
global object in an application that is safe to be called upon from multiple threads.

至此，bug得到官方文档的确认。

6 解决方式：

如果能确定了bug，解决方式就是再简单不过了

• 1 用-c1参数来指定只有一个线程，考虑并发，可以启动4个worker处理。
• 2 异步中的session对象全部替换为ScopedSession来使用。

7 反思

• 1 测试阶段不够完善，没有对高并发情况下进行测试
• 2 对于系统的监控不够及时，时候发现在测试阶段偶尔会出现此bug，但是因为没有注意到，并且急于上线，
• 3所有异步任务因为本来就是长耗时的操作，更需要进行并发测试
• 4 log日志监控增加了sentry来监控
• 5 发现问题也不要死盯着报错信息去解决。
• 6 直觉有时候很重要。