Which driver is used yo produce these messages ?
On Thu, Oct 26, 2017 at 8:14 AM, Dan Markhasin <minimi...@gmail.com> wrote:
> Furthermore, when looking at messages produced to the data1_log topic with
> print.timestamp=true they all have CreateTime:-1 whereas messages produced
> to the beats topic have valid timestamps. The producers that are sending to
> data1_log are older than the producers that are sending to beats - if this
> is where the broker takes the timestamps from, it explains why they are all
> empty for data1_log.
>
> On 26 October 2017 at 08:07, Dan Markhasin <minimi...@gmail.com> wrote:
>
> > 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 <5016%206645> 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
> >> > > >>>>
> >> > > >>>
> >> > > >>
> >> > >
> >> >
> >>
> >
> >
>
