Kafka/Fluentd/Sparkを用いたデータ分析基盤の運用話

https://shinjuku-geek-lounge.connpass.com/event/83127/

新宿Geek Lounge#4 分析基盤Meetup ver2での発表資料

Transcript

1. Kafka/Fluentd/Sparkを用いたデータ分析基盤の運用話 2018/04/02 「新宿 Geek Lounge」 Kimura, Sotaro（@kimutansk） https://www.flickr.com/photos/wwworks/8693876413/
2. 自己紹介 •Kimura, Sotaro(@kimutansk) – データエンジニア IT系雑用係 ＠ ドワンゴ •オンプレ～クラウド、インフラ～個別機能 •バッチ～ストリーム、開発～プロマネ – すなわち雑用係 – 言語もScala/Java/Python/Ruby/Goと雑用のお仕事 – 好きな技術要素 •ストリームデータ処理
3. 背景：ニコニコファミリーサービス ユーザアクション - コンテンツ視聴 - コンテンツ投稿 - コメント - マイリスト - お気に入り - タグ編集 ユーザアクション ファミリーサービス アクセスデバイス 動画 静画 マンガ 電子書籍 生放送 チャンネル アプリ ブロマガ まとめ 大百科 市場 広告 実況 コモンズ コミュニティ ニュース ニコナレ RPGｱﾂﾏｰﾙ PC iOS Android SPモード Switch Xbox One 3DS PS4 Vii U PS Vita テレビ STB
4. 背景：ニコニコファミリーサービス ユーザアクション - コンテンツ視聴 - コンテンツ投稿 - コメント - マイリスト - お気に入り - タグ編集 ユーザアクション ファミリーサービス アクセスデバイス 動画 静画 マンガ 電子書籍 生放送 チャンネル アプリ ブロマガ まとめ 大百科 市場 広告 実況 コモンズ コミュニティ ニュース ニコナレ RPGｱﾂﾏｰﾙ PC iOS Android SPモード Switch Xbox One 3DS PS4 Vii U PS Vita テレビ STB - 多様なユーザアクション - 多様なファミリーサービス - 多様なアクセスデバイス これらが同一ユーザID体系の上で行われる。 ログ・データの種別もこれらの乗算で増大。（3桁 日常的にどんどん増える。
5. データ分析基盤の概要構成 社内利用システム 凡例 外部連携 ジョブ実行 内部連携
6. データ分析基盤の構築方針 •ホストが落ちても縮退して動作継続可能 – 各サービスからログを受け取るホスト – Kinesisからデータを取得するホスト etc... – プロセス単位・ホスト単位の自動復旧機構も併せて構築 •一部古い箇所や、Kafka等のストレージ部除く •対向システムや性能的に変動が大きい箇所は 問題が発生しても影響を限定化 – 対向システムへの送信箇所 – Norika + Influxdb + Grafana可視化部 •ユーザに提供しているため、性能負荷が読めない
7. データ分析基盤の構築方針 •データの重複はKafkaクラスタ以降のレイヤで除去 – Kafkaクラスタまではリトライしても冪等性は担保 •リアルタイム分散なんちゃらとか、 ヘタレなので極力やりたくないです... •Kafkaクラスタ未経由のデータ投入経路も用意 – 「こんなことあろうかと経路」＝奥の手 •ただ、後述のように「奥の手」を使ってしまっているので、 軽い奥の手だということもお察し。 •逆に考えるとたまに発動してるので奥の手の正常性が 適宜検証されてありがたいという説もあります。
8. データ収集部概要 社内利用システム 凡例 外部連携 ジョブ実行 内部連携
9. データ収集部概要 •使用プロダクト – Fluentd 1.0.2 (From td-agent3.1.1) – Kafka 1.0.0 •Replication=3、Ack=1、MinInSyncReplica=2 •DNS Roundrobinで、分散してデータ受信 – データ送信元サービスはFluentd 0.12系 - Fleuntd 1系 •数が多いので個別管理は諦めました・・・ •流量統計、エラー情報、ホスト生存状況などを Fluentdで整形・集計し、モニタリング
10. データ可視化部概要 社内利用システム 凡例 外部連携 ジョブ実行 内部連携
11. データ可視化部概要 •使用プロダクト – Norikra 1.5 – Influxdb 1.2.0 （バージョン古いのでこの間ひどい目に） – Grafana 5.0.1 •集計＞格納＞可視化をまとめて社内提供 – Grafana接続先は他データストアとの複合パターンも存在 •ユーザの利用状況で性能負荷が変動するため、 OOME連発等も起きるときはあります・・・
12. データ同期部概要 社内利用システム 凡例 外部連携 ジョブ実行 内部連携
13. データ同期部概要 •使用プロダクト – Spark 2.2.0（自前ビルド） •Kerberos HAに対するチケット維持のため自前ビルド •Continuous Processing ModeはConnectorまだないですので... •Spark Structured Streamingで構築 – 「対象Topic」を正規表現マッチで指定可能なため、 ログ追加時も自動的に同期対象に追加 •常駐するジョブのため、常時監視中 – DNディスク障害でYARNこけると結構あっさり落ちます
14. データ整形集計部概要 社内利用システム 凡例 外部連携 ジョブ実行 内部連携
15. データ整形集計部概要 •使用プロダクト – CDH 5.11.2 （近日更新予定） •Hadoopクラスタは全てKerberosによる認証 •データ整形ジョブ – 依存関係がシンプルなものはAzkabanで実行 •Spark + Hive on Spark + MapReduce（旧機能） •DWH生成ジョブ – 依存関係確認や並列実行柔軟性確保のためDigdagで実行 •Spark + Hive on Spark + Pig （旧機能）
16. その他の面倒な組織固有な個所 •以下などの組織固有な話は今回は省略 – 権限設定 – 権限付与 – 権限管理 – データ分析時の組織体制 – 利用者サポート •例に漏れず、ここが一番泥臭くて厄介な箇所 – 興味がある方は直接どうぞ – 今回の発表で触れていない個所への質問でも大丈夫です
17. 今回はどんな内容？ •「データ分析基盤はこうあるべき」とか、 「プロダクトの素晴らしい所」は 既に他の方々のより素晴らしい発表があります – 何でもやってる雑用係よりよほど深く参考になる発表です •そのため、雑用係っぽく 「どう困ってどう対応してきたか？」について この発表では挙げさせていただきます – 対処の妥当性・効率性については一切保証いたしません – むしろいい方法を教えていただきたいです – 解決しきれてない問題も複数あります
18. これまで遭遇した問題達 •Kafka – 電源＆ディスクインタフェース障害でメタデータ部分破損 •Kafka / Spark Structured Streaming – クラスタアップグレードでOffset巻き戻り •Fluentd – OSのTCPタイムアウトまで送信ブロック – out_forward時メタデータ復元失敗 – データ圧縮時zlibエラー – プロセス突然死
19. メタデータ破損 •発生事象 – ある平和な日中、電源障害でKafkaのホストがダウン – 再起動をかけてみると・・・ FATAL [Kafka Server 1], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) java.io.IOException: Input/output error at java.io.UnixFileSystem.canonicalize0(Native Method) at java.io.UnixFileSystem.canonicalize(UnixFileSystem.java:172) at java.io.File.getCanonicalPath(File.java:618) at kafka.log.LogManager.$anonfun$createAndValidateLogDirs$1(LogManager.scala:91) ・・・ at kafka.log.LogManager.createAndValidateLogDirs(LogManager.scala:91) at kafka.log.LogManager.<init>(LogManager.scala:69)
20. FATAL [Kafka Server 1], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) java.io.IOException: Input/output error at java.io.UnixFileSystem.canonicalize0(Native Method) at java.io.UnixFileSystem.canonicalize(UnixFileSystem.java:172) at java.io.File.getCanonicalPath(File.java:618) at kafka.log.LogManager.$anonfun$createAndValidateLogDirs$1(LogManager.scala:91) ・・・ at kafka.log.LogManager.createAndValidateLogDirs(LogManager.scala:91) at kafka.log.LogManager.<init>(LogManager.scala:69) メタデータ破損 •発生事象 – ある平和な日中、電源障害でKafkaのホストがダウン – 再起動をかけてみると・・・ Kafkaのホストでディスク障害（？）発生 3本程ディスクが見えなくなった。
21. メタデータ破損 •発生事象 – インタフェースの問題でディスクには問題ないことを確認 – インタフェースを交換後、再起動をかけてみると・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/01/kafka-logs (kafka.log.LogManager) java.io.IOException: Expected 40 entries in checkpoint file (/data/01/kafka-logs/log-start-offset-checkpoint), but found only 0 at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:103) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/03/kafka-logs (kafka.log.LogManager) java.io.IOException: Malformed line in checkpoint file (/data/03/kafka-logs/log-start-offset-checkpoint): __co' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/04/kafka-logs (kafka.log.LogManager) java.io.IOException: Malformed line in checkpoint file (/data/04/kafka-logs/log-start-offset-checkpoint): display' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81)
22. メタデータ破損 •発生事象 – インタフェースの問題でディスクには問題ないことを確認 – インタフェースを交換後、再起動をかけてみると・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/01/kafka-logs (kafka.log.LogManager) java.io.IOException: Expected 40 entries in checkpoint file (/data/01/kafka-logs/log-start-offset-checkpoint), but found only 0 at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:103) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/03/kafka-logs (kafka.log.LogManager) java.io.IOException: Malformed line in checkpoint file (/data/03/kafka-logs/log-start-offset-checkpoint): __co' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・ WARN Error occurred while reading log-start-offset-checkpoint file of directory /data/04/kafka-logs (kafka.log.LogManager) java.io.IOException: Malformed line in checkpoint file (/data/04/kafka-logs/log-start-offset-checkpoint): display' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) チェックポイントファイルが破損 （※これはKafkaが自動復旧を試みるためよし（？））
23. メタデータ破損 •発生事象 – インタフェースの問題でディスクには問題ないことを確認 – インタフェースを交換後、再起動をかけてみると・・・ FATAL [Kafka Server 1], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) java.lang.IllegalArgumentException: inconsistent range at java.util.concurrent.ConcurrentSkipListMap$SubMap.<init>(ConcurrentSkipListMap.java:2603) at java.util.concurrent.ConcurrentSkipListMap.subMap(ConcurrentSkipListMap.java:2061) at kafka.log.Log.logSegments(Log.scala:1426) at kafka.log.Log.recoverSegment(Log.scala:328) at kafka.log.Log.recoverLog(Log.scala:420) at kafka.log.Log.loadSegments(Log.scala:395) at kafka.log.Log.<init>(Log.scala:179) at kafka.log.Log$.apply(Log.scala:1581) at kafka.log.LogManager.$anonfun$loadLogs$12(LogManager.scala:172) at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:57) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
24. メタデータ破損 •発生事象 – インタフェースの問題でディスクには問題ないことを確認 – インタフェースを交換後、再起動をかけてみると・・・ FATAL [Kafka Server 1], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) java.lang.IllegalArgumentException: inconsistent range at java.util.concurrent.ConcurrentSkipListMap$SubMap.<init>(ConcurrentSkipListMap.java:2603) at java.util.concurrent.ConcurrentSkipListMap.subMap(ConcurrentSkipListMap.java:2061) at kafka.log.Log.logSegments(Log.scala:1426) at kafka.log.Log.recoverSegment(Log.scala:328) at kafka.log.Log.recoverLog(Log.scala:420) at kafka.log.Log.loadSegments(Log.scala:395) at kafka.log.Log.<init>(Log.scala:179) at kafka.log.Log$.apply(Log.scala:1581) at kafka.log.LogManager.$anonfun$loadLogs$12(LogManager.scala:172) at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:57) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) ？？？
25. メタデータ破損 •ソースを確認 – https://github.com/apache/kafka/blob/0.11.0.0/core/src/main/scala/kafka/log/LogManager.scala#L160 val jobsForDir = for { dirContent <- Option(dir.listFiles).toList logDir <- dirContent if logDir.isDirectory } yield { ★複数スレッドを起動して初期化処理を並列実行★ CoreUtils.runnable { debug("Loading log '" + logDir.getName + "'") （※省略） ★以下でエラー発生すると、どこに問題があるかがわからずに初期化失敗★ val current = Log(dir = logDir, config = config, logStartOffset = logStartOffset, recoveryPoint = logRecoveryPoint, maxProducerIdExpirationMs = maxPidExpirationMs, scheduler = scheduler, time = time, brokerTopicStats = brokerTopicStats) if (logDir.getName.endsWith(Log.DeleteDirSuffix)) { this.logsToBeDeleted.add(current) } else { val previous = this.logs.put(topicPartition, current) if (previous != null) { throw new IllegalArgumentException( "Duplicate log directories found: %s, %s!".format( current.dir.getAbsolutePath, previous.dir.getAbsolutePath))
26. メタデータ破損 •ソースを確認 – https://github.com/apache/kafka/blob/0.11.0.0/core/src/main/scala/kafka/log/LogManager.scala#L160 val jobsForDir = for { dirContent <- Option(dir.listFiles).toList logDir <- dirContent if logDir.isDirectory } yield { ★複数スレッドを起動して初期化処理を並列実行★ CoreUtils.runnable { debug("Loading log '" + logDir.getName + "'") （※省略） ★以下でエラー発生すると、どこに問題があるかがわからずに初期化失敗★ val current = Log(dir = logDir, config = config, logStartOffset = logStartOffset, recoveryPoint = logRecoveryPoint, maxProducerIdExpirationMs = maxPidExpirationMs, scheduler = scheduler, time = time, brokerTopicStats = brokerTopicStats) if (logDir.getName.endsWith(Log.DeleteDirSuffix)) { this.logsToBeDeleted.add(current) } else { val previous = this.logs.put(topicPartition, current) if (previous != null) { throw new IllegalArgumentException( "Duplicate log directories found: %s, %s!".format( current.dir.getAbsolutePath, previous.dir.getAbsolutePath)) LogLevel=debug設定、 スレッドIDと「Loading log」を用いて一つ一つ切分け （該当スレッドでLoading logが 最後に出力されるログが破損被疑） ファイル全削除＞全同期は 容量的に避けたかったため。
27. メタデータ破損 •被疑ファイルを全退避して再起動 java.io.IOException: Malformed line in checkpoint file (/data/01/kafka-logs/replication-offset-checkpoint): ' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・
28. メタデータ破損 •被疑ファイルを全退避して再起動 java.io.IOException: Malformed line in checkpoint file (/data/01/kafka-logs/replication-offset-checkpoint): ' at kafka.server.checkpoints.CheckpointFile.malformedLineException$1(CheckpointFile.scala:76) at kafka.server.checkpoints.CheckpointFile.liftedTree2$1(CheckpointFile.scala:99) at kafka.server.checkpoints.CheckpointFile.read(CheckpointFile.scala:81) ・・・ チェックポイントファイルに不正行が混じっており、 自動復旧不可だったため、 エディタで修正して復旧
29. メタデータ破損 •色々遭遇しながら復旧完了 •From Kafka 1.0.0 ReleaseNote – JBOD構成の時一部ディスクに障害があっても起動可能 •これは早急にアップグレードするしかない！
30. メタデータ破損 •色々遭遇しながら復旧完了 •From Kafka 1.0.0 ReleaseNote – JBOD構成の時一部ディスクに障害があっても起動可能 •これは早急にアップグレードするしかない！ そして、次の障害へ・・・
31. Offset巻き戻り •発生事象 – Kafka 0.11.0.0 > 1.0.0へアップグレード時、 2度目のクラスタ再起動後Offsetが巻き戻った – Kafkaをクラスタアップグレードは以下のフローで実施 •以下の設定を実施し、 Brokerのバージョンをアップし、1Brokerずつ再起動 – inter.broker.protocol.version=0.11.0 •上記完了後、設定を以下のように変更し、 1Brokerずつ再起動（2度目の再起動） – inter.broker.protocol.version=1.0.0
32. Offset巻き戻り •発生事象 – Kafka 0.11.0.0 > 1.0.0へアップグレード時、 2度目のクラスタ再起動後Offsetが巻き戻った •Spark Structured Streamingで以下のエラー発生 ERROR Executor: Exception in task 18.4 in stage 0.0 (TID 46) java.lang.IllegalStateException: Tried to fetch 988550579 but the returned record offset was 988550521 at org.apache.spark.sql.kafka010.CachedKafkaConsumer.org$apache$spark$sql$kafka010$CachedKafkaConsumer$$fetchData(Cac hedKafkaConsumer.scala:245) at org.apache.spark.sql.kafka010.CachedKafkaConsumer$$anonfun$get$1.apply(CachedKafkaConsumer.scala:117) at org.apache.spark.sql.kafka010.CachedKafkaConsumer$$anonfun$get$1.apply(CachedKafkaConsumer.scala:106) at org.apache.spark.util.UninterruptibleThread.runUninterruptibly(UninterruptibleThread.scala:85) at
33. Offset巻き戻り •ソースを確認 – https://github.com/apache/spark/blob/v2.2.0/external/kafka-0-10- sql/src/main/scala/org/apache/spark/sql/kafka010/CachedKafkaConsumer.scala#L242 } else { if (record.offset >= untilOffset) { reportDataLoss(false, s"Skip missing records in [$offset, $untilOffset)") null } else { reportDataLoss(false, s"Skip missing records in [$offset, ${record.offset})") record } } } else if (record.offset < offset) { // This should not happen. If it does happen, then we probably misunderstand Kafka internal // mechanism. throw new IllegalStateException( s"Tried to fetch $offset but the returned record offset was ${record.offset}") } else { record }
34. Offset巻き戻り •ソースを確認 – https://github.com/apache/spark/blob/v2.2.0/external/kafka-0-10- sql/src/main/scala/org/apache/spark/sql/kafka010/CachedKafkaConsumer.scala#L242 } else { if (record.offset >= untilOffset) { reportDataLoss(false, s"Skip missing records in [$offset, $untilOffset)") null } else { reportDataLoss(false, s"Skip missing records in [$offset, ${record.offset})") record } } } else if (record.offset < offset) { // This should not happen. If it does happen, then we probably misunderstand Kafka internal // mechanism. throw new IllegalStateException( s"Tried to fetch $offset but the returned record offset was ${record.offset}") } else { record } いや、起こるはずがないとコメントされても、 現実として目の前で発生しているんですが・・・・
35. Offset巻き戻り •実際にKafkaのデータを確認 # kafka-simple-consumer-shell.sh --print-offsets --offset 988550570 --no-wait-at-logend --topic .... （※省略） next offset = 988550577 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550578 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550579 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550522★ status:200 size:853 time:2018-01-23T15:25:20+09:00 next offset = 988550523 status:200 size:853 time:2018-01-23T15:25:21+09:00 next offset = 988550524 status:200 size:851 time:2018-01-23T15:25:21+09:00 next offset = 988550525 status:200 size:0 time:2018-01-23T15:25:21+09:00 next offset = 988550526 status:200 size:852 time:2018-01-23T15:25:21+09:00 （※省略）
36. Offset巻き戻り •実際にKafkaのデータを確認 # kafka-simple-consumer-shell.sh --print-offsets --offset 988550570 --no-wait-at-logend --topic .... （※省略） next offset = 988550577 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550578 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550579 status:200 size:853 time:2018-01-23T15:25:27+09:00 next offset = 988550522★ status:200 size:853 time:2018-01-23T15:25:20+09:00 next offset = 988550523 status:200 size:853 time:2018-01-23T15:25:21+09:00 next offset = 988550524 status:200 size:851 time:2018-01-23T15:25:21+09:00 next offset = 988550525 status:200 size:0 time:2018-01-23T15:25:21+09:00 next offset = 988550526 status:200 size:852 time:2018-01-23T15:25:21+09:00 （※省略） 実際にKafkaから取得する際の Offsetが巻き戻っている
37. Offset巻き戻り •現実的にKafkaのデータは戻せないため以下を実施 – Spark Structured Streamingのジョブを停止 – HDFS上のSpark Structured StreamingのOffsetを削除 – Spark Structured Streamingのジョブを停止 •startingOffsets = latestのため、 再起動時の最終Offsetから読み込みを再開 – 取得できない時刻範囲のデータを「奥の手」を使って HDFSに直投入 – 該当の時間帯を含むログ整形・集計を全部再実行
38. Offset巻き戻り •現実的にKafkaのデータは戻せないため以下を実施 – Spark Structured Streamingのジョブを停止 – HDFS上のSpark Structured StreamingのOffsetを削除 – Spark Structured Streamingのジョブを停止 •startingOffsets = latestのため、 再起動時の最終Offsetから読み込みを再開 – 取得できない時刻範囲のデータを「奥の手」を使って HDFSに直投入 – 該当の時間帯を含むログ整形・集計を全部再実行 暫定対処は完了 ただ、そもそもの原因はなんだったのか？
39. Offset巻き戻り •Kafkaのデータ同期メカニズムの概要 – 通常 •ProducerがLeaderにデータを送信 •Leaderがローカルにデータを書込 – Ack=1の場合、このタイミングで応答 •FollowerがLeaderに対してデータ取得要求（繰り返し） – 取得開始Offset、取得サイズを指定 – Ack=Allの場合、全Followerの取得開始Offsetが 書込みメッセージのOffset以上となったタイミングで応答
40. Offset巻き戻り •Kafkaのデータ同期メカニズムの概要 – Leader交代時 •FollowerはLeaderよりローカルデータが進んでいる場合、 ローカルデータをLeaderと同じ値まで削除 – https://github.com/apache/kafka/blob/1.0.0/core/src/main /scala/kafka/server/ReplicaFetcherThread.scala#L133 •※今回はログを見るに、 実際には上記の切り捨て処理は発生していない。
41. Offset巻き戻り •Kafkaはデータ書込時に以下のチェックを実施 – Leaderで書き込み時 •メッセージにOffsetを割り振りながらローカル書込 •Offsetは書込時にインクリメントするため、減少しない – https://github.com/apache/kafka/blob/1.0.0/core/src/main /scala/kafka/log/Log.scala#L643 – Followerで書き込み時 •以下の内容を確認の上でローカル書込 – 受信メッセージのOffsetがローカルのOffset以降の値であること – バッチで受信時、バッチ中のOffsetが単調増加していること – https://github.com/apache/kafka/blob/1.0.0/core/src/main /scala/kafka/log/Log.scala#L683
42. Offset巻き戻り •Kafkaはデータ書き込み時に以下のチェックを実施 – Leaderで書き込み時 •メッセージにOffsetを割り振りながらローカル書込 •Offsetは書込時にインクリメントするため、減少しない – https://github.com/apache/kafka/blob/1.0.0/core/src/main /scala/kafka/log/Log.scala#L643 – Followerで書き込み時 •以下の内容を確認の上でローカル書込 – 受信メッセージのOffsetがローカルのOffset以降の値であること – バッチで受信時、バッチ中のOffsetが単調増加していること – https://github.com/apache/kafka/blob/1.0.0/core/src/main /scala/kafka/log/Log.scala#L683 データの入り口を確認したところ、 Ackの値に関わらず基本は発生しないはずの挙動。 実際に検証環境で何度か試しても再現せず。 無論、分散システムで状態管理が そんなうまくいくはずもないのだが、 Corner Caseをたたき続ける時間もない・・・
43. Offset巻き戻り •根本解決はできず、 結局検知方法と復旧手順を整備するに終わる・・・
44. OSのTimeoutまで送信ブロック •FluentdでDNS Roundrobinを設定し、 受信ホストの一部がダウンした場合、 サービス側で以下のログが大量出力、送信量が激減 [warn]: detached forwarding server 'XXXXX-aggregation' host="XXXXX" port=24224 hard_timeout=true [warn]: temporarily failed to flush the buffer. next_retry=2018-02-15 19:01:11 +0900 error_class="Errno::ETIMEDOUT" error="Connection timed out - connect(2) for ¥"xx.xx.xx.xx¥" port 24224" plugin_id="forward_to_aggregation" [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/plugin/out_forward.rb:378:in `initialize' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/plugin/out_forward.rb:378:in `new' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/plugin/out_forward.rb:378:in `connect' ... [warn]: temporarily failed to flush the buffer. next_retry=2018-02-15 19:01:13 +0900 error_class="RuntimeError" error="no nodes are available" plugin_id="forward_to_aggregation" [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/plugin/out_forward.rb:222:in `write_objects' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/output.rb:490:in `write' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/buffer.rb:354:in `write_chunk' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.35/lib/fluent/buffer.rb:333:in `pop' ...
45. OSのTimeoutまで送信ブロック •Fluentdで送信先サーバに接続時、 ホストダウン時OSのTCPTimeoutまで待つため？ – ホスト生存時は即切断を検知可能 • https://github.com/fluent/fluentd/blob/v0.12.40/lib/fluent/plugin/out_forward.rb#L378 • https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/plugin_helper/socket.rb#L211 – HeartBeatはログを見にくくするためなので解除し、 スレッド数を増やして影響を少なくする方針で対処 •本来Consul DNS等で死亡ホストを除外するのが望ましいが、 社内DNSにそういった機構がないので仮対処で・・・ •受信サーバをホストレベルの復旧機構を備えた環境に 移行しきれば、概ね問題なくなるので、それまで我慢
46. out_forward時、メタデータ復元失敗 •Fluentdでout_forwardを有するプロセス再起動時 以下のエラーが稀に発生 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2018-03-12 10:36:49 +0900 chunk="56728fb50915066255ab6565a23e4f4b" error_class=NoMethodError error="undefined method `force_encoding' for nil:NilClass" [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:618:in `send_data_actual' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:635:in `send_data' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:285:in `block in try_write' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:304:in `block in select_a_healthy_node' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:298:in `times' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:298:in `select_a_healthy_node' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.0.2/lib/fluent/plugin/out_forward.rb:285:in `try_write' .....
47. out_forward時、メタデータ復元失敗 •bufferが実体ファイルとメタデータファイルで 別管理され、片方だけリネームされるため – https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/plugin/buffer/file_chunk.rb#L101 – 結果、メタデータファイルが読み込めず、 メタデータが復元失敗する •発生時にリネームして再起動をかけて対応 fluentd_aggregation.b56728fb50915066255ab6565a23e4f4b.log.meta staging状態(bのため) fluentd_aggregation.q56728fb50915066255ab6565a23e4f4b.log queued 状態(qのため)
48. データ圧縮時zlibエラー •ファイル出力時、圧縮すると以下のエラーが発生 – 該当ファイルが途中で壊れる – 別スクリプトで圧縮するようにして対応 •すみません、Cのコードに潜っていきたくないんです・・・ [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2018-03-12 22:41:53 +0900 chunk="567374d062b80d7652f8a46a79395153" error_class=Zlib::DataError error="data error" [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd- 1.0.2/lib/fluent/plugin/out_file.rb:219:in `close' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd- 1.0.2/lib/fluent/plugin/out_file.rb:219:in `block in write_gzip_with_compression' [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd- 1.0.2/lib/fluent/plugin/out_file.rb:216:in `open' ..... [warn]: retry succeeded. chunk_id="567374d062b80d7652f8a46a79395153" zlib(finalizer): Zlib::GzipWriter object must be closed explicitly. zlib(finalizer): the stream state was inconsistent.
49. Fluentdプロセス突然死 •以下構成のFluentdプロセスで しばしばSegmentation faultが発生 •kafka_groupでデータ取得 > kafka2(with SSL)でデータ送信 – https://github.com/ruby/openssl/blob/v2.0.5/ext/openssl/ossl_ssl.c#L1538 • ファイル破損とデータ欠損は発生していないことを確認し、 プロセス再起動（自動）で復旧するので静観... – in_forward > kafka2(with SSL)の時は発生しなかったため、 環境や状況の組み合わせで発生する可能性はあるが、現状詳細は不明 /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/ruby-kafka- 0.5.1/lib/kafka/ssl_socket_with_timeout.rb:66: [BUG] Segmentation fault at 0x00000000fffffff0 ruby 2.4.2p198 (2017-09-14 revision 59899) [x86_64-linux] /opt/td-agent/embedded/lib/ruby/2.4.0/x86_64-linux/openssl.so(ossl_start_ssl+0x95) [0x7f7b2d56ae05] ossl_ssl.c:1538 /opt/td-agent/embedded/lib/ruby/2.4.0/x86_64- linux/openssl.so(ossl_ssl_connect_nonblock+0x5d) [0x7f7b2d56b14d] ossl_ssl.c:1617
50. まとめ •Kafkaは素晴らしいOSSですが、 時々地雷を設置してくれます – 踏んだ時のために、 ダメージコントロールの準備をしておきましょう – 機能追加ごとに分岐の増改築が増えていくため、 ソース読むのは正直厄介です •全て問題を解消しきるのは 現実的に無理なため、ダメージコントロール重要
51. Thank you for your attention! https://www.flickr.com/photos/savannahcorps/7409364642