After a bit more checking it seems that Kafka isn't writing timestamps at
all in the .timeindex file for the topics where offset rewind is not
working.
The following output is from * a different 0.11.0.0 * which also has a
topic called data1_log (this cluster has not experienced any issues lately):
bash-4.2$ ls -ltr | tail
-rw-rw-r-- 1 ibiuser users 1073739867 Oct 24 20:42 00000000000723010092.log
-rw-rw-r-- 1 ibiuser users 926216 Oct 24 20:42
00000000000723010092.index
-rw-rw-r-- 1 ibiuser users 16 Oct 25 05:09 leader-epoch-checkpoint
-rw-rw-r-- 1 ibiuser users 1073741239 Oct 25 09:52 00000000000725186047.log
-rw-rw-r-- 1 ibiuser users 10485756 Oct 25 09:52
00000000000727395414.timeindex
-rw-rw-r-- 1 ibiuser users 10 Oct 25 09:52
00000000000727395414.snapshot
-rw-rw-r-- 1 ibiuser users 0 Oct 25 09:52
00000000000725186047.timeindex
-rw-rw-r-- 1 ibiuser users 961144 Oct 25 09:52
00000000000725186047.index
-rw-rw-r-- 1 ibiuser users 10485760 Oct 25 21:59
00000000000727395414.index
-rw-rw-r-- 1 ibiuser users 1028809456 Oct 25 21:59 00000000000727395414.log
bash-4.2$ /kafka/latest/bin/kafka-run-class.sh kafka.tools.DumpLogSegments
--files 00000000000727395414.timeindex > /tmp/timestamps 2>&1
The output looks like this:
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
timestamp: 0 offset: 727395414
The offset is the same on all of the records and not a single line has a
timestamp greater than zero.
bash-4.2$ cat /tmp/timestamps | grep timestamp | awk '{print $2}' | grep -v
0
bash-4.2$
For comparison, the .timeindex for the beats topic on the same cluster
looks like this:
Dumping 00000000000254410745.timeindex
timestamp: 1508978010544 offset: 254410759
timestamp: 1508978011084 offset: 254410763
timestamp: 1508978012080 offset: 254410770
timestamp: 1508978012789 offset: 254410796
timestamp: 1508978013981 offset: 254410808
timestamp: 1508978014526 offset: 254410812
timestamp: 1508978014698 offset: 254410828
timestamp: 1508978014959 offset: 254410834
timestamp: 1508978015677 offset: 254410854
timestamp: 1508978016980 offset: 254410870
timestamp: 1508978017212 offset: 254410883
On 26 October 2017 at 07:26, Elyahou Ittah <elyaho...@fiverr.com> wrote:
> Which driver is used yo produce these messages ?
>
> On Oct 26, 2017 07:11, "Dan Markhasin" <minimi...@gmail.com> wrote:
>
> > No, that flag doesn't affect which offsets are returned, only executes
> the
> > action (and resets the consumer to latest offset when used, regardless of
> > datetime value I provide).
> >
> > On 25 October 2017 at 23:44, Hans Jespersen <h...@confluent.io> wrote:
> >
> > > I think you are just missing the —execute flag.
> > >
> > > -hans
> > >
> > > > On Oct 25, 2017, at 1:24 PM, Ted Yu <yuzhih...@gmail.com> wrote:
> > > >
> > > > I wonder if you have hit KAFKA-5600.
> > > >
> > > > Is it possible that you try out 0.11.0.1 ?
> > > >
> > > > Thanks
> > > >
> > > >> On Wed, Oct 25, 2017 at 1:15 PM, Dan Markhasin <minimi...@gmail.com
> >
> > > wrote:
> > > >>
> > > >> I am using 0.11.0.0.
> > > >>
> > > >> There is no difference configuration-wise - both have 10 partitions
> > and
> > > 2
> > > >> replicas. There are no errors in the logs, but looking in the data
> > > folder
> > > >> it seems like Kafka is not updating the timeindex file for
> data1_log -
> > > >> notice how the timeindex file for the current log segment is not
> being
> > > >> updated.
> > > >>
> > > >> bash-4.2$ pwd
> > > >> /kafka/data/data1_log-1
> > > >> bash-4.2$ ls -ltr | tail
> > > >> -rw-rw-r-- 1 ibiuser it 1073731573 Oct 25 01:21
> > 00000000000337554984.log
> > > >> -rw-rw-r-- 1 ibiuser it 943616 Oct 25 01:21
> > > 00000000000337554984.index
> > > >> -rw-rw-r-- 1 ibiuser it 1073734199 Oct 25 13:38
> > 00000000000339816017.log
> > > >> -rw-rw-r-- 1 ibiuser it 10485756 Oct 25 13:38
> > > >> 00000000000341934289.timeindex
> > > >> -rw-rw-r-- 1 ibiuser it 10 Oct 25 13:38
> > > >> 00000000000341934289.snapshot
> > > >> -rw-rw-r-- 1 ibiuser it 0 Oct 25 13:38
> > > >> 00000000000339816017.timeindex
> > > >> -rw-rw-r-- 1 ibiuser it 566712 Oct 25 13:38
> > > 00000000000339816017.index
> > > >> -rw-rw-r-- 1 ibiuser it 17 Oct 25 20:23
> > leader-epoch-checkpoint
> > > >> -rw-rw-r-- 1 ibiuser it 10485760 Oct 25 23:03
> > > 00000000000341934289.index
> > > >> -rw-rw-r-- 1 ibiuser it 461590419 Oct 25 23:04
> > 00000000000341934289.log
> > > >>
> > > >> For comparison, the beats topic:
> > > >>
> > > >> bash-4.2$ cd ../beats-1
> > > >> bash-4.2$ ls -ltr
> > > >> total 3212088
> > > >> -rw-rw-r-- 1 ibiuser it 17 Oct 25 00:23
> > leader-epoch-checkpoint
> > > >> -rw-rw-r-- 1 ibiuser it 10 Oct 25 20:04
> > > >> 00000000000188672034.snapshot
> > > >> -rw-rw-r-- 1 ibiuser it 2773008 Oct 25 20:04
> > > >> 00000000000185224087.timeindex
> > > >> -rw-rw-r-- 1 ibiuser it 1073741779 Oct 25 20:04
> > 00000000000185224087.log
> > > >> -rw-rw-r-- 1 ibiuser it 1967440 Oct 25 20:04
> > > 00000000000185224087.index
> > > >> -rw-rw-r-- 1 ibiuser it 10485760 Oct 25 23:03
> > > 00000000000188672034.index
> > > >> -rw-rw-r-- 1 ibiuser it 10485756 Oct 25 23:04
> > > >> 00000000000188672034.timeindex
> > > >> -rw-rw-r-- 1 ibiuser it 50166645 Oct 25 23:04
> > 00000000000188672034.log
> > > >>
> > > >>
> > > >> To give some context to why I'm even trying to reset the offsets, we
> > had
> > > >> encountered a strange situation earlier today:
> > > >>
> > > >> 1) One of the brokers had a hardware failure, and had to be rebuilt
> > from
> > > >> scratch (data partition was gone)
> > > >> 2) When it went down, we noticed a spike in lag in one particular
> > > consumer
> > > >> group - it seems to have reset its offset to an earlier point in
> time
> > > (but
> > > >> not the earliest offset of the topic); I have read other messages on
> > > this
> > > >> mailing list of users who experienced the same behavior with
> 0.11.0.0
> > > >> 3) The broker was reinstalled and rejoined the cluster with the same
> > > >> broker.id (but with no data on it) - it rebalanced and eventually
> all
> > > >> replicas became synced and the cluster was functioning normally.
> > > >> 4) I then decided to bounce the same broker again to see if I can
> > > reproduce
> > > >> the issue I saw in #2 - and as soon as the broker was restarted, the
> > > exact
> > > >> same consumer group had its offset reset again and was lagging with
> > > >> millions of records behind the current offset.
> > > >> 5) I then tried to manually reset the consumer group's offset to a
> few
> > > >> minutes before I restarted the broker, only to discover this strange
> > > >> behavior where no matter which datetime value I provided, it kept
> > > resetting
> > > >> to the latest offset.
> > > >>
> > > >>
> > > >>> On 25 October 2017 at 22:48, Ted Yu <yuzhih...@gmail.com> wrote:
> > > >>>
> > > >>> Do you mind providing a bit more information ?
> > > >>>
> > > >>> Release of Kafka you use
> > > >>>
> > > >>> Any difference between data1_log and the other, normal topic ?
> > > >>>
> > > >>> Probably check the broker log where data1_log is hosted - see if
> > there
> > > is
> > > >>> some clue.
> > > >>>
> > > >>> Thanks
> > > >>>
> > > >>> On Wed, Oct 25, 2017 at 12:11 PM, Dan Markhasin <
> minimi...@gmail.com
> > >
> > > >>> wrote:
> > > >>>
> > > >>>> I'm trying to use the kafka-consumer-groups.sh tool in order to
> > rewind
> > > >> a
> > > >>>> consumer group's offset, however it seems to be returning the
> latest
> > > >>> offset
> > > >>>> regarding of the requested offset.
> > > >>>>
> > > >>>> You can see in the below example that two consecutive commands to
> > > reset
> > > >>> the
> > > >>>> offset to a specific point in time return different (increasing)
> > > >> offsets,
> > > >>>> which are actually the latest offsets for the topic.
> > > >>>>
> > > >>>> - The consumer group ("test_consumer") is a console consumer that
> > was
> > > >>>> started with --from-beginning and terminated after a few seconds,
> > just
> > > >>>> enough for it to commit its offsets.
> > > >>>> - The topic data1_log is very busy with thousands of incoming
> > messages
> > > >>> per
> > > >>>> second
> > > >>>> - The datetime value provided is approx. 5 hours earlier than the
> > > >> current
> > > >>>> UTC time
> > > >>>>
> > > >>>> [admin@broker01] ~> /kafka/latest/bin/kafka-consumer-groups.sh
> > > >>>> --bootstrap-server localhost:9092 --reset-offsets --group
> > > test_consumer
> > > >>>> --topic data1_log --to-datetime '2017-10-25T13:40:00.000'
> > > >>>> Note: This will only show information about consumers that use the
> > > Java
> > > >>>> consumer API (non-ZooKeeper-based consumers).
> > > >>>>
> > > >>>>
> > > >>>> TOPIC PARTITION NEW-OFFSET
> > > >>>> data1_log 8 301485420
> > > >>>> data1_log 1 342788637
> > > >>>> data1_log 7 287621428
> > > >>>> data1_log 3 268612266
> > > >>>> data1_log 0 201860717
> > > >>>> data1_log 9 202749553
> > > >>>> data1_log 4 188974032
> > > >>>> data1_log 6 234308481
> > > >>>> data1_log 2 263507741
> > > >>>> data1_log 5 232707238
> > > >>>>
> > > >>>> [admin@broker01] ~> /kafka/latest/bin/kafka-consumer-groups.sh
> > > >>>> --bootstrap-server localhost:9092 --reset-offsets --group
> > > test_consumer
> > > >>>> --topic data1_log --to-datetime '2017-10-25T13:40:00.000'
> > > >>>> Note: This will only show information about consumers that use the
> > > Java
> > > >>>> consumer API (non-ZooKeeper-based consumers).
> > > >>>>
> > > >>>>
> > > >>>> TOPIC PARTITION NEW-OFFSET
> > > >>>> data1_log 8 301485491
> > > >>>> data1_log 1 342788779
> > > >>>> data1_log 7 287621534
> > > >>>> data1_log 3 268612364
> > > >>>> data1_log 0 201860796
> > > >>>> data1_log 9 202749620
> > > >>>> data1_log 4 188974068
> > > >>>> data1_log 6 234308564
> > > >>>> data1_log 2 263507823
> > > >>>> data1_log 5 232707293
> > > >>>>
> > > >>>> This issue seems to be topic-specific - there is a different topic
> > > >> (also
> > > >>>> very active) where the same command consistently returns the
> correct
> > > >>>> offsets fixed in the time for the requested datetime.
> > > >>>>
> > > >>>> What could be the issue here?
> > > >>>>
> > > >>>> Thanks,
> > > >>>> Dan
> > > >>>>
> > > >>>
> > > >>
> > >
> >
>
