线上风暴：事故排查与应对实战（二）

浮雷
2,370 阅读3分钟

kafka异常日志大量打印问题

一、现象

1、版本信息
  • spring boot： 2.3.5.RELEASE
  • spring-kafka：2.5.7.RELEASE
2、日志报错
2022-11-11 14:31:08| 799f9b65f-84sx7||org.springframework.kafka.KafkaListenerEndpointContainer#8-0-C-1|149|ERROR|org.springframework.kafka.listener.SeekToCurrentErrorHandler|Backoff FixedBackOff{interval=0, currentAttempts=10, maxAttempts=9} exhausted for ConsumerRecord(topic = xxxxx, partition = 3, leaderEpoch = 29, offset = 45674373, LogAppendTime = 1668148217315, serialized key size = -1, serialized value size = 2237, headers = RecordHeaders(headers = [], isReadOnly = false), key = null, value = xxxx
    org.springframework.kafka.listener.ListenerExecutionFailedException: Listener method 'public void xxxxxx threw exception; nested exception is java.lang.NullPointerException; nested exception is java.lang.NullPointerException
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.decorateException(KafkaMessageListenerContainer.java:2037)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeErrorHandler(KafkaMessageListenerContainer.java:2025)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:1924)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:1851)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:1748)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:1472)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1135)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1038)
    	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    	at java.lang.Thread.run(Thread.java:748)
    Caused by: java.lang.NullPointerException: null
    2022-11-11 14:31:08| -799f9b65f-84sx7||org.springframework.kafka.KafkaListenerEndpointContainer#8-0-C-1|149|ERROR|org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer|Error handler threw an exception
    org.springframework.kafka.KafkaException: Seek to current after exception; nested exception is org.springframework.kafka.listener.ListenerExecutionFailedException: Listener method 'public void xxxxxxxx(java.lang.String)' threw exception; nested exception is java.lang.NullPointerException; nested exception is java.lang.NullPointerException
    	at org.springframework.kafka.listener.SeekUtils.seekOrRecover(SeekUtils.java:157)
    	at org.springframework.kafka.listener.SeekToCurrentErrorHandler.handle(SeekToCurrentErrorHandler.java:113)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeErrorHandler(KafkaMessageListenerContainer.java:2025)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:1924)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:1851)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:1748)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:1472)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1135)
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1038)
    	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    	at java.lang.Thread.run(Thread.java:748)
    Caused by: org.springframework.kafka.listener.ListenerExecutionFailedException: Listener method 'xxxxxxxxxx(java.lang.String)' threw exception; nested exception is java.lang.NullPointerException; nested exception is java.lang.NullPointerException
    	at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.decorateException(KafkaMessageListenerContainer.java:2037)
    	... 10 common frames omitted
    Caused by: java.lang.NullPointerException: null
3、日志文件迅速膨胀，每个节点每天产生几十个G的大小。

二、初步猜想

  • 1、从日志中可以看到有NPE的日志报错，只要找到对应的堆栈信息，就能快速解决。
  • 2、大量重复的kafka堆栈打印，有可能是Spirng Kafka Client的Bug（例如死循环） ，也有可能是kafka consumer的消息异常处理策略。

三、排查过程

1、分析日志

因为日志太大，传输不方便，只能让现场交付同学从服务器中拿出其中几千条日志发给我。但是这几千行日志中并没有出现任何与应用相关的异常堆栈，第一个猜想看起来被排除了。

2、根据kafka client堆栈信息分析产生的原因

排查到这一步，看起来要解决这个问题我们就必须要结合spring kafka的堆栈信息以及源码去寻找蛛丝马迹了，下边是抛出异常的堆栈。

2022-11-11 14:31:08|data-writer-admin-799f9b65f-84sx7||org.springframework.kafka.KafkaListenerEndpointContainer#8-0-C-1|149|ERROR|org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer|Error handler threw an exception
org.springframework.kafka.KafkaException: Seek to current after exception; nested exception is org.springframework.kafka.listener.ListenerExecutionFailedException: Listener method 'xxxxxxx(java.lang.String)' threw exception; nested exception is java.lang.NullPointerException; nested exception is java.lang.NullPointerException
    at org.springframework.kafka.listener.SeekUtils.seekOrRecover(SeekUtils.java:157)
    at org.springframework.kafka.listener.SeekToCurrentErrorHandler.handle(SeekToCurrentErrorHandler.java:113)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeErrorHandler(KafkaMessageListenerContainer.java:2025)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:1924)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:1851)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:1748)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:1472)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1135)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1038)

2.1 消费入口： KafkaMessageListenerContainer -> run()

可以看到kafka是在一个条件while循环中一直执行message poll。

2.2、消费失败触发kafka异常处理逻辑：KafkaMessageListenerContainer -> doInvokeRecordListener()

  • 当invokeOnMessage()消息处理失败时，触发下边的catch逻辑。

2.3、异常封装

从上边的处理逻辑可以看出来，kafka的所有异常都会被封装为org.springframework.kafka.listener.ListenerExecutionFailedException。然后错误的处理默认是类是org.springframework.kafka.listener.SeekToCurrentErrorHandler。

2.4、异常处理逻辑（重要）

  • SeekToCurrentErrorHandler的行为是将消费者偏移量重置为失败记录的偏移量。 同时SeekToCurrentErrorHandler方法在调用SeekUtils.seekOrRecover的时，先调用了FailedRecordProcessor类的getSkipPredicate()方法，而getSkipPredicate()方法中则调用了org.springframework.kafka.listener.FailedRecordTracker -> skip()方法来测试是否应该跳过分区偏移量。如果不是,当前消费者记录的分区/偏移量将被添加到map.put(topicPartition, failedRecord)映射中，并且kafkaConsumer.seek(partition, offset)将从org.springframework.kafka.listener.SeekUtils.seekOrRecover()方法中调用发起再次消费的逻辑。

2.5、重试逻辑

  • 默认情况下，每条失败的记录最多重试10次，为什么会这样？ 关键逻辑在FailedRecordTracker.skip方法中。 FailedRecordTracker会在内部跟踪重试次数，并将其与SeekToCurrentErrorHandler的构造函数中backoff对象中的最大重试参数进行比较。

四、解决方案

1、先解决日志量太大的问题（治标）

从上一步的分析已经可以看出来，之前大量日志打印，是因为kafka消费异常之后的重试逻辑，而这个逻辑就是重试10次，那我们来自定义重试次数，来覆盖kakfa模型的重试次数即可。

@Bean
public ConcurrentKafkaListenerContainerFactory<String, String> factory(){
    ConcurrentKafkaListenerContainerFactory<String, String> factory =
            new ConcurrentKafkaListenerContainerFactory<>();
    FixedBackOff backOff = new FixedBackOff(0, 3);
    SeekToCurrentErrorHandler errorHandler = new SeekToCurrentErrorHandler(backOff);
    factory.setErrorHandler(errorHandler);
    return factory;

还有个问题：从代码里边看到是10次，那么能在日志里边验证吗？ 仔细从日志里边找，可以看到重试的次数确实是10次

2、解决根源问题（治本）

在上边虽然可以减少日志量的打印，但是还是无法避免仍然有较多的日志打印，干扰我们排查其他问题。而在远程复现问题也比较困难，所以到用户现场仔细观察日志，发现了NPE的根本问题其实是业务原因导致，只是机缘巧合在那几千行日志中没有体现出来，而定位到业务代码中的NPE解决就很简单了，这里不多加描述。

五、总结

其实这个问题要是出现在C端的场景，处理起来会很快，但是由于是B端的场景，由因为网络的隔离，无法在比较直观的查看到监控、日志，而是选择去分析部分样本日志，这就导致了上边的场景——真正的原因刚才在样本日志中没有体现，不得不走一些弯路，总体来说采用分析第三库源码的方式来位问题其成本将是通过分析业务代码的20 ~ 50倍。 所以不到万不得已，不要直接上来就撸源码，切记切记。

avatar
文章
阅读
粉丝