最近一周都在看一个线上问题，焦头烂额，所幸最后问题得到解决。这里记录一下trouble shooting的过程。

现象

客户使用我们的一个order-export job每隔半小时定时run，把所有已付款订单发送至ERP系统，通知仓库准备发货。结果时间到了，job没有被trigger起来，尝试手工trigger也没有任何的反应。

trouble shooting

1. 检查log，发现大量的404问题，根据log查到发生该问题的job是另一个，我们自己设计的job表里已经没有该job了，但是quartz里trigger还在定时发生； 还有一些job因为系统平台刚刚从cf（cloudFoundry）升级到K8S，该异常job还是call以前的老的调用URI导致出错。这个导致的困扰是产生大量的error log，非常干扰调查。

2. 检查log关键词，定位问题是在quartz scheduler里发生，还没有call到我们自己的service业务代码，关键查询quartz里几个表的信息（quartz_trigger, quartz_fired_trigger)。 结果发现trigger一直在BLOCK state， fired trigger里一条处于“EXECUTING”状态的记录一直没有被删除，看fired time，已经过了几个小时，正常情况fired trigger应该在job执行完就被删除，然后trigger state被设置为“WAITING”状态，等待下一次执行时间点到来。检查schedule开始trigger job附近时间点的log（吐槽一下log数目，几秒时间都有几千条。。），发现了大量的DB SQL state 08001错误。比对google的一些信息https://github.com/quartz-scheduler/quartz/issues/145， 基本可以肯定是在执行过程时，db连接出错导致了trigger异常，没有正常返回处理。

org.quartz.SchedulerException: TriggerListener 'DefaultTriggerListener' threw exception: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

3. 方向有了，开始检查我们的db部分配置如下：

 由于我们有大量的job有时在整点或者整半点被触发，怀疑因为DB connection数目不够导致的，比对quartz的best practice建议，调整原来的数目50到100（我们的thread worker数目40，后来又调整db max connection数目到120），部署测试。与此同时，修改我们的后台自动运行的job trigger 时间，将它们错开执行。在看代码时发现我们还有一个interceptor，在trigger listener， job listener和scheduler listener run时，记录了大量的log并且持久化了。为了减轻负担，我们把该interceptor禁用。

部署一天后观察log，还是有大量的db error，job也再次stuck。。

4. 调查方向再次卡住，期间我们为了快速解决客户问题，手工删除了fired trigger记录，然后再次手工run我们的job，可以暂时解决问题但是手工trigger导致job run了两次，有重复导出客户订单的风险。最后发现不用手工再次execute，删除卡着的fired trigger后直接修改quartz trigger的state到“WAITING”，stuck的job会马上重新执行。副作用是本来整半小时执行的时间变成非整半小时了，因为我们的job是SIMPLE类型，run的下一次时间是根据interval来的，不是CRON类型。

5. 再次调查，老板发现另一个service里也爆出类似问题，它们的现象和我们类似，但是解决方案是调整loginTimeout时间，而且最终问题得到了解决。于是我们尝试着将timeout时间加大到8s，部署测试。问题解决。

后记小结

1. 几个同事共同努力排查问题，迅速定位问题所在

2. 老板的线索是关键，感谢老板涉猎广

3. 后头又具体去看了一下log，发现如果下信息，所以如果log看的更仔细，可能还可以早一点往timeout方向去想。kibana看log，特别是海量log时，真是非常不友好，根据关键词查询容易漏掉更详细的信息，需要更细致排查。