问题描述

2022.06.19 突然有用户反馈， 作业的积压时间突然变为 24 个小时

排查过程

  1. 初步怀疑是配置state.savepoints.dir了导致从一个非常旧的offset恢复，导致作业消费越界，直接从 topic 的最旧的位置消费， 一般 topic 的保留时间为 24 小时

  2. 通过查看 topic 的消息过期时间， 可以发现是 7 天的超时时间，旧的 savepoint 路径的 checkpoint 时间是 5.24， 所以基本可以排除是 state.savepoints.dir造成的影响.

  3. 查看作业的监控，确认 checkpoint 是否正常

    • 查看 checkpoint 失败情况 (并没有 checkpoint 失败的情况， 对应的 metric 是 NumofFailedCheckpoint 无增长)
    • 查看 作业重启情况 (06.18 20:00 作业发生了重启)

  4. 通过查看日志， 确认 checkpoint 是否正常， 最后一次成功 checkpoint 时间为 21:40

2022-06-17 21:40:56.770 INFO org.apache.flink.runtime.checkpoint.CheckpointCoordinator - Triggering checkpoint 121061 (type=CHECKPOINT) @ 1655473256761 for job 2e2dbb876d892e170cb7418a5812cbad.

2022-06-17 21:40:57.099 INFO org.apache.flink.runtime.checkpoint.CheckpointCoordinator - Comp

  1. 再次查看 checkpoint 失败的相关监控， 确认是否有成功的 checkpoint (对应的 metric 为 NumOfCompleteCheckpoint)

    • 发现这个时间点开始， 一直没有成功的 checkpoint，但也没有触发失败的 checkpoint， 可以推断由于某种原因， checkpoint 未能正常触发

  2. 通过分析日志， 从 06.17 21:40 开始，有较多的 kerberos 异常的日志， 初步怀疑是机器的磁盘出现了问题， 通过可以发现， Flink UI 无法进入， 应该也是由于磁盘故障导致资源文件丢失。

2022-06-17 21:42:26.833 WARN org.apache.hadoop.hdfs.server.namenode.ha.RequestHedgingProxyProvider - Invocation returned exception on [xxxxxx/xxxx:xxxx]

org.apache.hadoop.security.KerberosAuthException: DestHost:destPort xxxxx , LocalHost:localPort xxxx/xxxxxx. Failed on local exception: org.apache.hadoop.security.KerberosAuthException: Login failure for user: xxxxxx@xxxxx.HADOOP javax.security.auth.login.LoginException: Unable to obtain password from user

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:831)

at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:806)

at org.apache.hadoop.ipc.Client.getRpcResponse(Client.java:1621)
  1. 登录具体的机器， 确认磁盘的问题
  • 可以发现， 从 6.17 09:11 开始， 就有非常多的 磁盘异常.
[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#0 CDB: Read(16) 88 00 00 00 00 00 1e 26 c2 48 00 00 00 08 00 00

[五 6月 17 09:11:34 2022] blk_update_request: I/O error, dev sdd, sector 505856584

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#5 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#5 CDB: Read(16) 88 00 00 00 00 01 b4 37 8e f0 00 00 00 18 00 00

[五 6月 17 09:11:34 2022] blk_update_request: I/O error, dev sdd, sector 7318507248

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#5 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#5 CDB: Read(16) 88 00 00 00 00 01 b4 37 8e f0 00 00 00 08 00 00

[五 6月 17 09:11:34 2022] blk_update_request: I/O error, dev sdd, sector 7318507248

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#6 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#6 CDB: Read(16) 88 00 00 00 00 01 b4 37 8e f8 00 00 00 08 00 00

[五 6月 17 09:11:34 2022] blk_update_request: I/O error, dev sdd, sector 7318507256

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#7 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK

[五 6月 17 09:11:34 2022] sd 0:2:3:0: [sdd] tag#7 CDB: Read(16) 88 00 00 00 00 01 b4 37 8f 00 00 00 00 08 00 00
  1. 原因推断
  • JobManager 的磁盘异常导致keytab 加载不成功，之后导致 checkpoint 失败， 但这个失败并没有被记录到 checkpoint 失败次数里面， 导致作业无法自动重启。

问题修复

  • Flink checkpoint 时，在遇到这种 keytab 异常的问题， 应该记录 checkpoint 失败， 进而触发作业的重启
  • 在 Flink Canary 逻辑里面增加异常检测的 case， 检测那些有配置的 checkpoint， 但 checkpoint 一直未成功的作业