kafka-jira mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Hanlin Liu (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (KAFKA-3039) Temporary loss of leader resulted in log being completely truncated
Date Fri, 23 Jun 2017 10:42:00 GMT

    [ https://issues.apache.org/jira/browse/KAFKA-3039?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16060711#comment-16060711
] 

Hanlin Liu commented on KAFKA-3039:
-----------------------------------

We are seeing similar issue when restarting KAFKA 0.10.2.0

```
[2017-06-23 05:50:35,082] WARN Found a corrupted index file due to requirement failed: Corrupt
index found, index file (/var/lib/kafka/data/__consumer_offsets-22/00000000000000074220.index)
has non-zero size but the last offset is 74220 which is no larger than the base offset 74220.}.
deleting /var/lib/kafka/data/__consumer_offsets-22/00000000000000074220.timeindex, /var/lib/kafka/data/__consumer_offsets-22/00000000000000074220.index
and rebuilding index... (kafka.log.Log)
[2017-06-23 05:50:35,091] INFO Recovering unflushed segment 74220 in log __consumer_offsets-22.
(kafka.log.Log)
[2017-06-23 05:50:35,095] INFO Completed load of log __consumer_offsets-22 with 2 log segments
and log end offset 75825 in 35 ms (kafka.log.Log)
[2017-06-23 06:14:57,133] TRACE Controller 1 epoch 1 sending UpdateMetadata request (Leader:2,ISR:2,3,1,LeaderEpoch:0,ControllerEpoch:1)
to brokers Set(1, 2, 3) for partition __consumer_offsets-22 (state.change.logger)
[2017-06-23 06:14:57,482] TRACE Broker 1 handling LeaderAndIsr request correlationId 7 from
controller 1 epoch 1 starting the become-follower transition for partition __consumer_offsets-22
(state.change.logger)
[2017-06-23 06:14:57,587] INFO Partition [__consumer_offsets,22] on broker 1: No checkpointed
highwatermark is found for partition __consumer_offsets-22 (kafka.cluster.Partition)
[2017-06-23 06:14:57,606] INFO [ReplicaFetcherManager on broker 1] Removed fetcher for partitions
__consumer_offsets-28,__consumer_offsets-10,__consumer_offsets-32,__consumer_offsets-14,__consumer_offsets-40,__consumer_offsets-37,__consumer_offsets-22,__consumer_offsets-41,__consumer_offsets-4,__consumer_offsets-23,__consumer_offsets-26,__consumer_offsets-8,__consumer_offsets-49,__consumer_offsets-31,__consumer_offsets-13,__consumer_offsets-35,__consumer_offsets-17,__consumer_offsets-43,__consumer_offsets-25,__consumer_offsets-44,__consumer_offsets-47,__consumer_offsets-7,__consumer_offsets-29,__consumer_offsets-11,__consumer_offsets-34,__consumer_offsets-19,__consumer_offsets-16,__consumer_offsets-38,__consumer_offsets-1,__consumer_offsets-20,__consumer_offsets-5,__consumer_offsets-46,__consumer_offsets-2
(kafka.server.ReplicaFetcherManager)
[2017-06-23 06:14:57,606] TRACE Broker 1 stopped fetchers as part of become-follower request
from controller 1 epoch 1 with correlation id 7 for partition __consumer_offsets-22 (state.change.logger)
[2017-06-23 06:14:57,608] INFO The cleaning for partition __consumer_offsets-22 is aborted
and paused (kafka.log.LogCleaner)
[2017-06-23 06:14:57,608] INFO Truncating log __consumer_offsets-22 to offset 0. (kafka.log.Log)
[2017-06-23 06:14:57,609] INFO Scheduling log segment 42456 for log __consumer_offsets-22
for deletion. (kafka.log.Log)
[2017-06-23 06:14:57,609] INFO Scheduling log segment 74220 for log __consumer_offsets-22
for deletion. (kafka.log.Log)
[2017-06-23 06:14:57,611] INFO Compaction for partition __consumer_offsets-22 is resumed (kafka.log.LogCleaner)
[2017-06-23 06:14:57,904] TRACE Broker 1 truncated logs and checkpointed recovery boundaries
for partition __consumer_offsets-22 as part of become-follower request with correlation id
7 from controller 1 epoch 1 (state.change.logger)
[2017-06-23 06:14:57,910] INFO [ReplicaFetcherManager on broker 1] Added fetcher for partitions
List([__consumer_offsets-22, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)]
, [__consumer_offsets-8, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-4,
initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-7, initOffset
0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-46, initOffset 0 to
broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-25, initOffset 0 to broker
BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-35, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)]
, [__consumer_offsets-41, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-23,
initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-49, initOffset
0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-47, initOffset 0 to
broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-16, initOffset 0 to broker
BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-28, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)]
, [__consumer_offsets-31, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-37,
initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-38, initOffset
0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-17, initOffset 0 to
broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-19, initOffset 0 to broker
BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-11, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)]
, [__consumer_offsets-13, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-2,
initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-43, initOffset
0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-14, initOffset 0 to
broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-20, initOffset 0 to broker
BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-44, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)]
, [__consumer_offsets-1, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-5,
initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-26, initOffset
0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-29, initOffset 0 to
broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-34, initOffset 0 to broker
BrokerEndPoint(2,192.168.1.214,9093)] , [__consumer_offsets-10, initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)]
, [__consumer_offsets-32, initOffset 0 to broker BrokerEndPoint(3,192.168.1.214,9094)] , [__consumer_offsets-40,
initOffset 0 to broker BrokerEndPoint(2,192.168.1.214,9093)] ) (kafka.server.ReplicaFetcherManager)
[2017-06-23 06:14:57,910] TRACE Broker 1 started fetcher to new leader as part of become-follower
request from controller 1 epoch 1 with correlation id 7 for partition __consumer_offsets-22
(state.change.logger)
[2017-06-23 06:14:57,911] TRACE Broker 1 completed LeaderAndIsr request correlationId 7 from
controller 1 epoch 1 for the become-follower transition for partition __consumer_offsets-22
(state.change.logger)
[2017-06-23 06:14:57,922] TRACE Broker 1 cached leader info (LeaderAndIsrInfo:(Leader:2,ISR:2,3,1,LeaderEpoch:0,ControllerEpoch:1),ReplicationFactor:3),AllReplicas:1,2,3)
for partition __consumer_offsets-22 in response to UpdateMetadata request sent by controller
1 epoch 1 with correlation id 8 (state.change.logger)
[2017-06-23 06:15:57,610] INFO Deleting segment 42456 from log __consumer_offsets-22. (kafka.log.Log)
[2017-06-23 06:15:57,610] INFO Deleting segment 74220 from log __consumer_offsets-22. (kafka.log.Log)
[2017-06-23 06:15:57,612] INFO Deleting index /var/lib/kafka/data/__consumer_offsets-22/00000000000000042456.index.deleted
(kafka.log.OffsetIndex)
[2017-06-23 06:15:57,613] INFO Deleting index /var/lib/kafka/data/__consumer_offsets-22/00000000000000042456.timeindex.deleted
(kafka.log.TimeIndex)
[2017-06-23 06:15:58,311] INFO Deleting index /var/lib/kafka/data/__consumer_offsets-22/00000000000000074220.index.deleted
(kafka.log.OffsetIndex)
[2017-06-23 06:15:58,912] INFO Deleting index /var/lib/kafka/data/__consumer_offsets-22/00000000000000074220.timeindex.deleted
(kafka.log.TimeIndex)



```
INFO KafkaConfig values: 
	advertised.host.name = null
	advertised.listeners = PLAINTEXT://192.168.1.214:9092
	advertised.port = null
	authorizer.class.name = 
	auto.create.topics.enable = true
	auto.leader.rebalance.enable = true
	background.threads = 10
	broker.id = 1
	broker.id.generation.enable = true
	broker.rack = null
	compression.type = producer
	connections.max.idle.ms = 600000
	controlled.shutdown.enable = true
	controlled.shutdown.max.retries = 3
	controlled.shutdown.retry.backoff.ms = 5000
	controller.socket.timeout.ms = 30000
	create.topic.policy.class.name = null
	default.replication.factor = 3
	delete.topic.enable = false
	fetch.purgatory.purge.interval.requests = 1000
	group.max.session.timeout.ms = 300000
	group.min.session.timeout.ms = 6000
	host.name = 
	inter.broker.listener.name = null
	inter.broker.protocol.version = 0.10.2-IV0
	leader.imbalance.check.interval.seconds = 300
	leader.imbalance.per.broker.percentage = 10
	listener.security.protocol.map = SSL:SSL,SASL_PLAINTEXT:SASL_PLAINTEXT,TRACE:TRACE,SASL_SSL:SASL_SSL,PLAINTEXT:PLAINTEXT
	listeners = PLAINTEXT://0.0.0.0:9092
	log.cleaner.backoff.ms = 15000
	log.cleaner.dedupe.buffer.size = 134217728
	log.cleaner.delete.retention.ms = 86400000
	log.cleaner.enable = true
	log.cleaner.io.buffer.load.factor = 0.9
	log.cleaner.io.buffer.size = 524288
	log.cleaner.io.max.bytes.per.second = 1.7976931348623157E308
	log.cleaner.min.cleanable.ratio = 0.5
	log.cleaner.min.compaction.lag.ms = 0
	log.cleaner.threads = 1
	log.cleanup.policy = [delete]
	log.dir = /tmp/kafka-logs
	log.dirs = /var/lib/kafka/data
	log.flush.interval.messages = 9223372036854775807
	log.flush.interval.ms = null
	log.flush.offset.checkpoint.interval.ms = 60000
	log.flush.scheduler.interval.ms = 9223372036854775807
	log.index.interval.bytes = 4096
	log.index.size.max.bytes = 10485760
	log.message.format.version = 0.10.2-IV0
	log.message.timestamp.difference.max.ms = 9223372036854775807
	log.message.timestamp.type = CreateTime
	log.preallocate = false
	log.retention.bytes = 10000000000
	log.retention.check.interval.ms = 300000
	log.retention.hours = 168
	log.retention.minutes = null
	log.retention.ms = null
	log.roll.hours = 168
	log.roll.jitter.hours = 0
	log.roll.jitter.ms = null
	log.roll.ms = null
	log.segment.bytes = 1073741824
	log.segment.delete.delay.ms = 60000
	max.connections.per.ip = 2147483647
	max.connections.per.ip.overrides = 
	message.max.bytes = 2000000
	metric.reporters = []
	metrics.num.samples = 2
	metrics.recording.level = INFO
	metrics.sample.window.ms = 30000
	min.insync.replicas = 1
	num.io.threads = 8
	num.network.threads = 3
	num.partitions = 1
	num.recovery.threads.per.data.dir = 1
	num.replica.fetchers = 1
	offset.metadata.max.bytes = 4096
	offsets.commit.required.acks = -1
	offsets.commit.timeout.ms = 5000
	offsets.load.buffer.size = 5242880
	offsets.retention.check.interval.ms = 600000
	offsets.retention.minutes = 1440
	offsets.topic.compression.codec = 0
	offsets.topic.num.partitions = 50
	offsets.topic.replication.factor = 3
	offsets.topic.segment.bytes = 104857600
	port = 9092
	principal.builder.class = class org.apache.kafka.common.security.auth.DefaultPrincipalBuilder
	producer.purgatory.purge.interval.requests = 1000
	queued.max.requests = 500
	quota.consumer.default = 9223372036854775807
	quota.producer.default = 9223372036854775807
	quota.window.num = 11
	quota.window.size.seconds = 1
	replica.fetch.backoff.ms = 1000
	replica.fetch.max.bytes = 3000000
	replica.fetch.min.bytes = 1
	replica.fetch.response.max.bytes = 10485760
	replica.fetch.wait.max.ms = 500
	replica.high.watermark.checkpoint.interval.ms = 5000
	replica.lag.time.max.ms = 10000
	replica.socket.receive.buffer.bytes = 65536
	replica.socket.timeout.ms = 30000
	replication.quota.window.num = 11
	replication.quota.window.size.seconds = 1
	request.timeout.ms = 30000
	reserved.broker.max.id = 1000
	sasl.enabled.mechanisms = [GSSAPI]
	sasl.kerberos.kinit.cmd = /usr/bin/kinit
	sasl.kerberos.min.time.before.relogin = 60000
	sasl.kerberos.principal.to.local.rules = [DEFAULT]
	sasl.kerberos.service.name = null
	sasl.kerberos.ticket.renew.jitter = 0.05
	sasl.kerberos.ticket.renew.window.factor = 0.8
	sasl.mechanism.inter.broker.protocol = GSSAPI
	security.inter.broker.protocol = PLAINTEXT
	socket.receive.buffer.bytes = 102400
	socket.request.max.bytes = 104857600
	socket.send.buffer.bytes = 102400
	ssl.cipher.suites = null
	ssl.client.auth = none
	ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
	ssl.endpoint.identification.algorithm = null
	ssl.key.password = null
	ssl.keymanager.algorithm = SunX509
	ssl.keystore.location = null
	ssl.keystore.password = null
	ssl.keystore.type = JKS
	ssl.protocol = TLS
	ssl.provider = null
	ssl.secure.random.implementation = null
	ssl.trustmanager.algorithm = PKIX
	ssl.truststore.location = null
	ssl.truststore.password = null
	ssl.truststore.type = JKS
	unclean.leader.election.enable = true
	zookeeper.connect = zk1:2181,zk2:2181,zk3:2181
	zookeeper.connection.timeout.ms = null
	zookeeper.session.timeout.ms = 6000
	zookeeper.set.acl = false
	zookeeper.sync.time.ms = 2000

> Temporary loss of leader resulted in log being completely truncated
> -------------------------------------------------------------------
>
>                 Key: KAFKA-3039
>                 URL: https://issues.apache.org/jira/browse/KAFKA-3039
>             Project: Kafka
>          Issue Type: Bug
>          Components: core
>    Affects Versions: 0.9.0.0
>         Environment: Debian 3.2.54-2 x86_64 GNU/Linux
>            Reporter: Imran Patel
>            Priority: Critical
>              Labels: reliability
>
> We had an event recently where the temporarily loss of a leader for a partition (during
a manual restart), resulted in the leader coming back with no high watermark state and truncating
its log to zero. Logs (attached below) indicate that it did have the data but not the commit
state. How is this possible?
> Leader (broker 3)
> [2015-12-18 21:19:44,666] INFO Completed load of log messages-14 with log end offset
14175963374 (kafka.log.Log)
> [2015-12-18 21:19:45,170] INFO Partition [messages,14] on broker 3: No checkpointed highwatermark
is found for partition [messages,14] (kafka.cluster.Partition)
> [2015-12-18 21:19:45,238] INFO Truncating log messages-14 to offset 0. (kafka.log.Log)
> [2015-12-18 21:20:34,066] INFO Partition [messages,14] on broker 3: Expanding ISR for
partition [messages,14] from 3 to 3,10 (kafka.cluster.Partition)
> Replica (broker 10)
> [2015-12-18 21:19:19,525] INFO Partition [messages,14] on broker 10: Shrinking ISR for
partition [messages,14] from 3,10,4 to 10,4 (kafka.cluster.Partition)
> [2015-12-18 21:20:34,049] ERROR [ReplicaFetcherThread-0-3], Current offset 14175984203
for partition [messages,14] out of range; reset offset to 35977 (kafka.server.ReplicaFetcherThread)
> [2015-12-18 21:20:34,033] WARN [ReplicaFetcherThread-0-3], Replica 10 for partition [messages,14]
reset its fetch offset from 14175984203 to current leader 3's latest offset 35977 (kafka.server.ReplicaFetcherThread)
> Some relevant config parameters:
>         offsets.topic.replication.factor = 3
>         offsets.commit.required.acks = -1
>         replica.high.watermark.checkpoint.interval.ms = 5000
>         unclean.leader.election.enable = false



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Mime
View raw message