drainer发kafka异常

🪐 TiDB 技术问题 备份&数据迁移
1

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

  • 【TiDB 版本】：4.0.0-rc2
  • 【问题描述】： drainer下流是kafka，我们发现偶尔会丢失一下数据，看了一下INFO日志（drainer.log）有一些“write: broken pipe”，不知道这个是不是异常，日志如下： [2020/05/26 10:29:49.489 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929620803977217]

[2020/05/26 10:29:52.492 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929621590409217]

[2020/05/26 10:29:55.494 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929622376841217]

[2020/05/26 10:29:58.898 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929623399202821]

[2020/05/26 10:30:02.323 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929624434671620]

[2020/05/26 10:30:07.726 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929625221103620]

[2020/05/26 10:30:11.577 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929626754646020]

[2020/05/26 10:30:18.586 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929627999830019]

[2020/05/26 10:30:21.588 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929629402300421]

[2020/05/26 10:30:25.526 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929630241161217]

[2020/05/26 10:30:29.400 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929631447023627]

[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka018.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:818] ["[sarama] client/metadata got error from broker 17 while fetching metadata: write tcp 10.160.16.115:56964->10.160.67.46:9092: write: broken pipe\ "]

[2020/05/26 10:30:32.128 +08:00] [INFO] [broker.go:253] ["[sarama] Closed connection to broker kafka018.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:556] ["[sarama] client/brokers deregistered broker #17 at kafka018.wd.hb.ted:9092"]

[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka023.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:818] ["[sarama] client/metadata got error from broker 22 while fetching metadata: write tcp 10.160.16.115:60392->10.160.73.114:9092: write: broken pipe\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [broker.go:253] ["[sarama] Closed connection to broker kafka023.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:556] ["[sarama] client/brokers deregistered broker #22 at kafka023.wd.hb.ted:9092"]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka037.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:818] ["[sarama] client/metadata got error from broker 36 while fetching metadata: write tcp 10.160.16.115:58560->10.160.73.110:9092: write: broken pipe\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [broker.go:253] ["[sarama] Closed connection to broker kafka037.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:556] ["[sarama] client/brokers deregistered broker #36 at kafka037.wd.hb.ted:9092"]

[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka004.wd.hb.ted:9092\ "]

[2020/05/26 10:30:32.129 +08:00] [INFO] [broker.go:212] ["[sarama] Connected to broker at kafka004.wd.hb.ted:9092 (registered as #3)\ "]

[2020/05/26 10:30:32.130 +08:00] [INFO] [client.go:534] ["[sarama] client/brokers registered new broker #17 at kafka018.wd.hb.ted:9092"]

[2020/05/26 10:30:32.130 +08:00] [INFO] [client.go:534] ["[sarama] client/brokers registered new broker #22 at kafka023.wd.hb.ted:9092"]

[2020/05/26 10:30:32.130 +08:00] [INFO] [client.go:534] ["[sarama] client/brokers registered new broker #36 at kafka037.wd.hb.ted:9092"]

[2020/05/26 10:30:32.504 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929632298991619]

[2020/05/26 10:30:36.208 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929632888815619]

[2020/05/26 10:30:39.611 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929634120892421]

[2020/05/26 10:30:43.048 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929635313647619]

[2020/05/26 10:30:46.079 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929636322902019]

[2020/05/26 10:30:49.325 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929636781654019]

[2020/05/26 10:30:55.563 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929637397692419]

[2020/05/26 10:30:58.697 +08:00] [INFO] [syncer.go:257] [“write save point”] [ts=416929639245807619]

若提问为性能优化、故障排查类问题，请下载脚本运行。终端输出的打印结果，请务必全选并复制粘贴上传。

2

你好，

kafka 的同时间段日志，这边帮忙反馈下，

3

kafka服务端的日志暂时没法拿到。 目前通过drainer的日志，能大概确认是发送数据异常了么？

4

你好，

当前日志属于正常输出日志，可否上传下完整的 drainer 日志，看下是否有其他 error 输出，

  1. 可以检查下 kafka 是否正确消费了日志，
  2. 最好结合具体丢失日志来看，实锤下是哪个阶段导致数据丢失，
5

drainer.log.tmp (2.7 MB)

日志已上传，检查过kafka端的offset，只要有数据就会被消费，这块有问题的可能性不大。 我的问题是基于什么原因，drainer打印出了如下日志，这个日志打印是正常的吗？

[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:772] [“[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka018.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:818] [”[sarama] client/metadata got error from broker 17 while fetching metadata: write tcp 10.160.16.115:56964->10.160.67.46:9092: write: broken pipe
“]
[2020/05/26 10:30:32.128 +08:00] [INFO] [broker.go:253] [”[sarama] Closed connection to broker kafka018.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:556] [”[sarama] client/brokers deregistered broker #17 at kafka018.wd.hb.ted:9092”]
[2020/05/26 10:30:32.128 +08:00] [INFO] [client.go:772] [“[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka023.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:818] [”[sarama] client/metadata got error from broker 22 while fetching metadata: write tcp 10.160.16.115:60392->10.160.73.114:9092: write: broken pipe
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [broker.go:253] [”[sarama] Closed connection to broker kafka023.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:556] [”[sarama] client/brokers deregistered broker #22 at kafka023.wd.hb.ted:9092”]
[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:772] [“[sarama] client/metadata fetching metadata for [newsfeed_tidb_binlog] from broker kafka037.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:818] [”[sarama] client/metadata got error from broker 36 while fetching metadata: write tcp 10.160.16.115:58560->10.160.73.110:9092: write: broken pipe
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [broker.go:253] [”[sarama] Closed connection to broker kafka037.wd.hb.ted:9092
“]
[2020/05/26 10:30:32.129 +08:00] [INFO] [client.go:556] [”[sarama] client/brokers deregistered broker #36 at kafka037.wd.hb.ted:9092”]

6

你好，

这个是 drainer 用的第三方库打的日志，研发同学正在找相关代码，稍后贴出来看下。