"Not updating metadata" INFO has become ERROR in recent Druid version, and happens all the time

Hi all,

When we were runinng on Druid 0.12.3, we would get this message 2 times per hour (maybe because we have 2 kafka indexing service taskCount, and 2 replicas, on 6 kafka partitions). But its INFO, so we were not worried about it.

2019-11-21T16:35:27,806 INFO [qtp1788036341-144] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Not updating metadata, existing state is not the expected start state.

Upgrading to 0.16.0 in our staging environment, we are having 2 of these per hour, but now its an “ERROR”:

2019-11-21T17:12:29,698 ERROR [qtp716996660-74] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Not updating metadata, existing state[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2213841, 1=2439257, 2=2218260, 3=2207035, 4=2186169, 5=2171536}}}] in metadata store doesn’t match to the new start

Should this really be an ERROR and should we do something about it?

Thank you,

Michael

Hi Michael,
Are your kafka ingestions getting successful?

If YES, we might have to take at your logs starting with overlord logs.
If NO, are you seeing any gaps in your data source ingested by this kafka?

If yes, you might have to reset the kafka supervisor.

Please also take a look at your druid_datasource metadata table related to this task.

Thanks,

–siva

Hi Siva,

Thank you for looking into it.

I believe the ingestions are happening successfully. Looking at the segments in the druid UI, new ones are definitely being created.

I upgraded from 0.12.3 to 0.16.0, since then i have submitted the supervisor through API which updated it, but I never reset it or remove and recreated it.

Also of note - I have 6 kafka partitions, 2 taskCount and 2 partitionCount. I did it this way so if I need to increase to 3 task count, I won’t have to change number of kafka partitions.

Here are the surrounding logs in the coordinator/overlord, note that there are 2 “Not updating metadata” messages:

14648-2019-11-27T06:08:26,006 INFO [TaskQueue-Manager] org.apache.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb

14649-2019-11-27T06:08:26,006 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd with status: TaskStatus{id=index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd, status=RUNNING, duration=-1, errorMsg=null}

14650-2019-11-27T06:08:26,007 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_campaignsummary_1ee75630db13821_imcbnafp switched from pending to running (on [ip-10-0-2-242.ec2.internal:8091])

14651-2019-11-27T06:08:26,007 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_1ee75630db13821_imcbnafp] status changed to [RUNNING].

14652-2019-11-27T06:08:26,009 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-5-40.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_1ee75630db13821_pjopjfbm] on [TaskLocation{host=‘ip-10-0-5-40.ec2.internal’, port=20002, tlsPort=-1}]

14653-2019-11-27T06:08:26,009 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_1ee75630db13821_pjopjfbm] location changed to [TaskLocation{host=‘ip-10-0-5-40.ec2.internal’, port=20002, tlsPort=-1}].

14654-2019-11-27T06:08:26,017 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.overlord.TaskLockbox - Adding task[index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd] to activeTasks

14655-2019-11-27T06:08:26,017 INFO [TaskQueue-Manager] org.apache.druid.indexing.overlord.RemoteTaskRunner - Assigned a task[index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb] that is already pending!

14656-2019-11-27T06:08:26,017 INFO [TaskQueue-Manager] org.apache.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd

14657-2019-11-27T06:08:26,017 INFO [TaskQueue-Manager] org.apache.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd

14658-2019-11-27T06:08:26,017 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:08:26.017Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=, publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1799}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1799}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1799}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1799}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14659-2019-11-27T06:08:26,021 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-2-242.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_1ee75630db13821_imcbnafp] on [TaskLocation{host=‘null’, port=-1, tlsPort=-1}]

14660-2019-11-27T06:08:26,021 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[ip-10-0-5-40.ec2.internal:8091] to add task[index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb]

14661-2019-11-27T06:08:26,025 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb switched from pending to running (on [ip-10-0-5-40.ec2.internal:8091])

14662-2019-11-27T06:08:26,025 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb] status changed to [RUNNING].

14663-2019-11-27T06:08:26,028 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-2-242.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_1ee75630db13821_imcbnafp] on [TaskLocation{host=‘ip-10-0-2-242.ec2.internal’, port=20002, tlsPort=-1}]

14664-2019-11-27T06:08:26,028 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_1ee75630db13821_imcbnafp] location changed to [TaskLocation{host=‘ip-10-0-2-242.ec2.internal’, port=20002, tlsPort=-1}].

14665-2019-11-27T06:08:26,042 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-5-40.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb] on [TaskLocation{host=‘null’, port=-1, tlsPort=-1}]

14666-2019-11-27T06:08:26,042 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[ip-10-0-2-242.ec2.internal:8091] to add task[index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd]

14667-2019-11-27T06:08:26,046 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd switched from pending to running (on [ip-10-0-2-242.ec2.internal:8091])

14668-2019-11-27T06:08:26,046 INFO [rtr-pending-tasks-runner-0] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd] status changed to [RUNNING].

14669-2019-11-27T06:08:26,055 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-2-242.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd] on [TaskLocation{host=‘null’, port=-1, tlsPort=-1}]

14670-2019-11-27T06:08:26,067 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-5-40.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb] on [TaskLocation{host=‘ip-10-0-5-40.ec2.internal’, port=20003, tlsPort=-1}]

14671-2019-11-27T06:08:26,067 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb] location changed to [TaskLocation{host=‘ip-10-0-5-40.ec2.internal’, port=20003, tlsPort=-1}].

14672-2019-11-27T06:08:26,100 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Worker[ip-10-0-2-242.ec2.internal:8091] wrote RUNNING status for task [index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd] on [TaskLocation{host=‘ip-10-0-2-242.ec2.internal’, port=20003, tlsPort=-1}]

14673-2019-11-27T06:08:26,100 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd] location changed to [TaskLocation{host=‘ip-10-0-2-242.ec2.internal’, port=20003, tlsPort=-1}].

14674-2019-11-27T06:08:26,632 INFO [qtp716996660-104] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc]: SegmentTransactionalInsertAction{segmentsToBeOverwritten=null, segments=[DataSegment{binaryVersion=9, id=campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z, loadSpec={type=>s3_zip, bucket=>viralgains-staging, key=>druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/0/a43619b3-6fa3-4697-a81a-44b4d94f0d3d/index.zip, S3Schema=>s3n}, dimensions=[campaignid, creativeid, creativetype, videocreativetype, mediatype, accountid, lineitemid, countryname, countrycode, regionname, regioncode, city, gender, age, dsp, surveyid, srcshortdomain, ismoatviewable, ismrcviewable, zipcode, timezone, hourofday, dayofweek, devicecategory, devicebrandname, operatingsystem, operatingsystemversion, browsername, browserversion, engagementexperiencetemplate, advertiserid, vendorid, engagementexperiencesource], metrics=[count, load, playerloadtime, impression, adimpressionsuccess, start, skip, mute, unmute, pause, custom1, firstquartile, midpoint, thirdquartile, error, adrequested, adstopped, inferredlowintenders, inferredmediumintenders, inferredhighintenders, complete, clickthrough, displaytagclickthrough, displayimageclickthrough, fullscreen, close, custom2, custom3, custom4, custom5, custom6, custom7, custom8, custom9, custom10, surveysubmission, surveyexposure, surveyexposure5s, surveyexposure10s, surveyclickthrough, surveyresponsechoice, sharecopyandpasteshareurl, sharesms, shareemail, sharegmail, shareyahoo, shareoutlook, shareaol, sharepinterest, sharelinkedin, sharetwitter, sharefacebook, deliveredview, hotspotinteraction, hotspotdrivetositeclick, customimagesplashscreenclickformore, splashscreenclickformore, splashscreenmoreinfo, videoexplorerengagecard, videoscreenimagebottomlink, videoscreenimagetoplink, videoscreenhyperlink, storelocatorstoreinfo, storelocatordirections, storelocatorcall, optout, startfail, loadfail, pricepaid, bidprice, pricepaidmillicents, bidpricemillicents, pricepaidnanocents, bidpricenanocents, adinteraction, surveyattempt], shardSpec=NumberedShardSpec{partitionNum=0, partitions=0}, size=32570}], startMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214032, 2=2218314, 4=2186206}, exclusivePartitions=}}, endMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 2=2218314, 4=2186206}}}}

14675-2019-11-27T06:08:26,634 INFO [qtp716996660-104] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Updated metadata from[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214032, 1=2439379, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}] to[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 1=2439379, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}].

14676-2019-11-27T06:08:26,635 INFO [qtp716996660-104] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Published segment [campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z] to DB with used flag [true], json[{“dataSource”:“campaignsummary”,“interval”:“2019-11-27T05:00:00.000Z/2019-11-27T06:00:00.000Z”,“version”:“2019-11-27T05:51:14.209Z”,“loadSpec”:{“type”:“s3_zip”,“bucket”:“viralgains-staging”,“key”:“druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/0/a43619b3-6fa3-4697-a81a-44b4d94f0d3d/index.zip”,“S3Schema”:“s3n”},“dimensions”:“campaignid,creativeid,creativetype,videocreativetype,mediatype,accountid,lineitemid,countryname,countrycode,regionname,regioncode,city,gender,age,dsp,surveyid,srcshortdomain,ismoatviewable,ismrcviewable,zipcode,timezone,hourofday,dayofweek,devicecategory,devicebrandname,operatingsystem,operatingsystemversion,browsername,browserversion,engagementexperiencetemplate,advertiserid,vendorid,engagementexperiencesource”,“metrics”:“count,load,playerloadtime,impression,adimpressionsuccess,start,skip,mute,unmute,pause,custom1,firstquartile,midpoint,thirdquartile,error,adrequested,adstopped,inferredlowintenders,inferredmediumintenders,inferredhighintenders,complete,clickthrough,displaytagclickthrough,displayimageclickthrough,fullscreen,close,custom2,custom3,custom4,custom5,custom6,custom7,custom8,custom9,custom10,surveysubmission,surveyexposure,surveyexposure5s,surveyexposure10s,surveyclickthrough,surveyresponsechoice,sharecopyandpasteshareurl,sharesms,shareemail,sharegmail,shareyahoo,shareoutlook,shareaol,sharepinterest,sharelinkedin,sharetwitter,sharefacebook,deliveredview,hotspotinteraction,hotspotdrivetositeclick,customimagesplashscreenclickformore,splashscreenclickformore,splashscreenmoreinfo,videoexplorerengagecard,videoscreenimagebottomlink,videoscreenimagetoplink,videoscreenhyperlink,storelocatorstoreinfo,storelocatordirections,storelocatorcall,optout,startfail,loadfail,pricepaid,bidprice,pricepaidmillicents,bidpricemillicents,pricepaidnanocents,bidpricenanocents,adinteraction,surveyattempt”,“shardSpec”:{“type”:“numbered”,“partitionNum”:0,“partitions”:0},“binaryVersion”:9,“size”:32570,“identifier”:“campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z”}]

14677-2019-11-27T06:08:26,706 INFO [qtp716996660-71] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc]: SegmentTransactionalInsertAction{segmentsToBeOverwritten=null, segments=[DataSegment{binaryVersion=9, id=campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z, loadSpec={type=>s3_zip, bucket=>viralgains-staging, key=>druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/0/41646eba-305b-4bf0-8539-b8eff4e64370/index.zip, S3Schema=>s3n}, dimensions=[campaignid, creativeid, creativetype, videocreativetype, mediatype, accountid, lineitemid, countryname, countrycode, regionname, regioncode, city, gender, age, dsp, surveyid, srcshortdomain, ismoatviewable, ismrcviewable, zipcode, timezone, hourofday, dayofweek, devicecategory, devicebrandname, operatingsystem, operatingsystemversion, browsername, browserversion, engagementexperiencetemplate, advertiserid, vendorid, engagementexperiencesource], metrics=[count, load, playerloadtime, impression, adimpressionsuccess, start, skip, mute, unmute, pause, custom1, firstquartile, midpoint, thirdquartile, error, adrequested, adstopped, inferredlowintenders, inferredmediumintenders, inferredhighintenders, complete, clickthrough, displaytagclickthrough, displayimageclickthrough, fullscreen, close, custom2, custom3, custom4, custom5, custom6, custom7, custom8, custom9, custom10, surveysubmission, surveyexposure, surveyexposure5s, surveyexposure10s, surveyclickthrough, surveyresponsechoice, sharecopyandpasteshareurl, sharesms, shareemail, sharegmail, shareyahoo, shareoutlook, shareaol, sharepinterest, sharelinkedin, sharetwitter, sharefacebook, deliveredview, hotspotinteraction, hotspotdrivetositeclick, customimagesplashscreenclickformore, splashscreenclickformore, splashscreenmoreinfo, videoexplorerengagecard, videoscreenimagebottomlink, videoscreenimagetoplink, videoscreenhyperlink, storelocatorstoreinfo, storelocatordirections, storelocatorcall, optout, startfail, loadfail, pricepaid, bidprice, pricepaidmillicents, bidpricemillicents, pricepaidnanocents, bidpricenanocents, adinteraction, surveyattempt], shardSpec=NumberedShardSpec{partitionNum=0, partitions=0}, size=32570}], startMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214032, 2=2218314, 4=2186206}, exclusivePartitions=}}, endMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 2=2218314, 4=2186206}}}}

14678:2019-11-27T06:08:26,707 ERROR [qtp716996660-71] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Not updating metadata, existing state[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 1=2439379, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}] in metadata store doesn’t match to the new start state[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214032, 2=2218314, 4=2186206}, exclusivePartitions=}}].

14679-2019-11-27T06:08:26,724 INFO [qtp716996660-86] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc]: SegmentListUsedAction{dataSource=‘campaignsummary’, intervals=[2019-11-27T05:00:00.000Z/2019-11-27T06:00:00.000Z]}

14680-2019-11-27T06:08:26,802 INFO [qtp716996660-104] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp]: SegmentTransactionalInsertAction{segmentsToBeOverwritten=null, segments=[DataSegment{binaryVersion=9, id=campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z_1, loadSpec={type=>s3_zip, bucket=>viralgains-staging, key=>druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/1/5eb934f2-fb24-4679-9a8d-dd46c0426e34/index.zip, S3Schema=>s3n}, dimensions=[campaignid, creativeid, creativetype, videocreativetype, mediatype, accountid, lineitemid, countryname, countrycode, regionname, regioncode, city, gender, age, dsp, surveyid, srcshortdomain, ismoatviewable, ismrcviewable, zipcode, timezone, hourofday, dayofweek, devicecategory, devicebrandname, operatingsystem, operatingsystemversion, browsername, browserversion, engagementexperiencetemplate, advertiserid, vendorid, engagementexperiencesource], metrics=[count, load, playerloadtime, impression, adimpressionsuccess, start, skip, mute, unmute, pause, custom1, firstquartile, midpoint, thirdquartile, error, adrequested, adstopped, inferredlowintenders, inferredmediumintenders, inferredhighintenders, complete, clickthrough, displaytagclickthrough, displayimageclickthrough, fullscreen, close, custom2, custom3, custom4, custom5, custom6, custom7, custom8, custom9, custom10, surveysubmission, surveyexposure, surveyexposure5s, surveyexposure10s, surveyclickthrough, surveyresponsechoice, sharecopyandpasteshareurl, sharesms, shareemail, sharegmail, shareyahoo, shareoutlook, shareaol, sharepinterest, sharelinkedin, sharetwitter, sharefacebook, deliveredview, hotspotinteraction, hotspotdrivetositeclick, customimagesplashscreenclickformore, splashscreenclickformore, splashscreenmoreinfo, videoexplorerengagecard, videoscreenimagebottomlink, videoscreenimagetoplink, videoscreenhyperlink, storelocatorstoreinfo, storelocatordirections, storelocatorcall, optout, startfail, loadfail, pricepaid, bidprice, pricepaidmillicents, bidpricemillicents, pricepaidnanocents, bidpricenanocents, adinteraction, surveyattempt], shardSpec=NumberedShardSpec{partitionNum=1, partitions=0}, size=32314}], startMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={1=2439379, 3=2207080, 5=2171568}, exclusivePartitions=}}, endMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={1=2439384, 3=2207080, 5=2171568}}}}

14681-2019-11-27T06:08:26,804 INFO [qtp716996660-104] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Updated metadata from[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 1=2439379, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}] to[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 1=2439384, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}].

14682-2019-11-27T06:08:26,804 INFO [qtp716996660-104] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Published segment [campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z_1] to DB with used flag [true], json[{“dataSource”:“campaignsummary”,“interval”:“2019-11-27T05:00:00.000Z/2019-11-27T06:00:00.000Z”,“version”:“2019-11-27T05:51:14.209Z”,“loadSpec”:{“type”:“s3_zip”,“bucket”:“viralgains-staging”,“key”:“druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/1/5eb934f2-fb24-4679-9a8d-dd46c0426e34/index.zip”,“S3Schema”:“s3n”},“dimensions”:“campaignid,creativeid,creativetype,videocreativetype,mediatype,accountid,lineitemid,countryname,countrycode,regionname,regioncode,city,gender,age,dsp,surveyid,srcshortdomain,ismoatviewable,ismrcviewable,zipcode,timezone,hourofday,dayofweek,devicecategory,devicebrandname,operatingsystem,operatingsystemversion,browsername,browserversion,engagementexperiencetemplate,advertiserid,vendorid,engagementexperiencesource”,“metrics”:“count,load,playerloadtime,impression,adimpressionsuccess,start,skip,mute,unmute,pause,custom1,firstquartile,midpoint,thirdquartile,error,adrequested,adstopped,inferredlowintenders,inferredmediumintenders,inferredhighintenders,complete,clickthrough,displaytagclickthrough,displayimageclickthrough,fullscreen,close,custom2,custom3,custom4,custom5,custom6,custom7,custom8,custom9,custom10,surveysubmission,surveyexposure,surveyexposure5s,surveyexposure10s,surveyclickthrough,surveyresponsechoice,sharecopyandpasteshareurl,sharesms,shareemail,sharegmail,shareyahoo,shareoutlook,shareaol,sharepinterest,sharelinkedin,sharetwitter,sharefacebook,deliveredview,hotspotinteraction,hotspotdrivetositeclick,customimagesplashscreenclickformore,splashscreenclickformore,splashscreenmoreinfo,videoexplorerengagecard,videoscreenimagebottomlink,videoscreenimagetoplink,videoscreenhyperlink,storelocatorstoreinfo,storelocatordirections,storelocatorcall,optout,startfail,loadfail,pricepaid,bidprice,pricepaidmillicents,bidpricemillicents,pricepaidnanocents,bidpricenanocents,adinteraction,surveyattempt”,“shardSpec”:{“type”:“numbered”,“partitionNum”:1,“partitions”:0},“binaryVersion”:9,“size”:32314,“identifier”:“campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z_1”}]

14683-2019-11-27T06:08:26,887 INFO [qtp716996660-71] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil]: SegmentTransactionalInsertAction{segmentsToBeOverwritten=null, segments=[DataSegment{binaryVersion=9, id=campaignsummary_2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z_2019-11-27T05:51:14.209Z_1, loadSpec={type=>s3_zip, bucket=>viralgains-staging, key=>druid_odyssey/segments/campaignsummary/2019-11-27T05:00:00.000Z_2019-11-27T06:00:00.000Z/2019-11-27T05:51:14.209Z/1/50223aa9-3210-4372-a891-7053d7740d9e/index.zip, S3Schema=>s3n}, dimensions=[campaignid, creativeid, creativetype, videocreativetype, mediatype, accountid, lineitemid, countryname, countrycode, regionname, regioncode, city, gender, age, dsp, surveyid, srcshortdomain, ismoatviewable, ismrcviewable, zipcode, timezone, hourofday, dayofweek, devicecategory, devicebrandname, operatingsystem, operatingsystemversion, browsername, browserversion, engagementexperiencetemplate, advertiserid, vendorid, engagementexperiencesource], metrics=[count, load, playerloadtime, impression, adimpressionsuccess, start, skip, mute, unmute, pause, custom1, firstquartile, midpoint, thirdquartile, error, adrequested, adstopped, inferredlowintenders, inferredmediumintenders, inferredhighintenders, complete, clickthrough, displaytagclickthrough, displayimageclickthrough, fullscreen, close, custom2, custom3, custom4, custom5, custom6, custom7, custom8, custom9, custom10, surveysubmission, surveyexposure, surveyexposure5s, surveyexposure10s, surveyclickthrough, surveyresponsechoice, sharecopyandpasteshareurl, sharesms, shareemail, sharegmail, shareyahoo, shareoutlook, shareaol, sharepinterest, sharelinkedin, sharetwitter, sharefacebook, deliveredview, hotspotinteraction, hotspotdrivetositeclick, customimagesplashscreenclickformore, splashscreenclickformore, splashscreenmoreinfo, videoexplorerengagecard, videoscreenimagebottomlink, videoscreenimagetoplink, videoscreenhyperlink, storelocatorstoreinfo, storelocatordirections, storelocatorcall, optout, startfail, loadfail, pricepaid, bidprice, pricepaidmillicents, bidpricemillicents, pricepaidnanocents, bidpricenanocents, adinteraction, surveyattempt], shardSpec=NumberedShardSpec{partitionNum=1, partitions=0}, size=32314}], startMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={1=2439379, 3=2207080, 5=2171568}, exclusivePartitions=}}, endMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={1=2439384, 3=2207080, 5=2171568}}}}

14684:2019-11-27T06:08:26,888 ERROR [qtp716996660-71] org.apache.druid.metadata.IndexerSQLMetadataStorageCoordinator - Not updating metadata, existing state[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamEndSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={0=2214042, 1=2439384, 2=2218314, 3=2207080, 4=2186206, 5=2171568}}}] in metadata store doesn’t match to the new start state[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream=‘campaignsummary’, partitionSequenceNumberMap={1=2439379, 3=2207080, 5=2171568}, exclusivePartitions=}}].

14685-2019-11-27T06:08:26,916 INFO [qtp716996660-86] org.apache.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil]: SegmentListUsedAction{dataSource=‘campaignsummary’, intervals=[2019-11-27T05:00:00.000Z/2019-11-27T06:00:00.000Z]}

14686-2019-11-27T06:08:28,780 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Starting coordination. Getting used segments.

14687-2019-11-27T06:08:28,781 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Found [3,683] used segments.

14688-2019-11-27T06:08:28,787 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.

14689-2019-11-27T06:08:28,812 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - Found 3 active servers, 0 decommissioning servers

14690-2019-11-27T06:08:28,812 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - Processing 4 segments for moving from decommissioning servers

14691-2019-11-27T06:08:28,812 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - All servers to move segments from are empty, ending run.

14692-2019-11-27T06:08:28,812 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - Processing 5 segments for balancing between active servers

14693-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - No good moves found in tier [_default_tier]

14694-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorBalancer - [_default_tier]: Segments Moved: [0] Segments Let Alone: [5]

14695-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Assigned 0 segments among 3 servers

14696-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Dropped 0 segments among 3 servers

14697-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Moved 0 segment(s)

14698-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Let alone 5 segment(s)

14699-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - Load Queues:

14700-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[ip-10-0-2-221.ec2.internal:9081, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 413,847,385 bytes served.

14701-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[ip-10-0-5-225.ec2.internal:9081, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 471,496,720 bytes served.

14702-2019-11-27T06:08:28,819 INFO [Coordinator-Exec–0] org.apache.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[ip-10-0-5-145.ec2.internal:9081, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 500,031,363 bytes served.

14703-2019-11-27T06:08:33,437 INFO [ServerInventoryView-0] org.apache.druid.curator.inventory.CuratorInventoryManager - Created new InventoryCacheListener for /druid_odyssey/segments/ip-10-0-2-242.ec2.internal:20003

14704-2019-11-27T06:08:33,437 INFO [ServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - New Server[DruidServerMetadata{name=‘ip-10-0-2-242.ec2.internal:20003’, hostAndPort=‘ip-10-0-2-242.ec2.internal:20003’, hostAndTlsPort=‘null’, maxSize=0, tier=’_default_tier’, type=indexer-executor, priority=0}]

14705-2019-11-27T06:08:33,442 INFO [NodeTypeWatcher[PEON]] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Node[ip-10-0-2-242.ec2.internal:20003:DiscoveryDruidNode{druidNode=DruidNode{serviceName=‘druid/peon’, host=‘ip-10-0-2-242.ec2.internal’, bindOnHost=false, port=-1, plaintextPort=20003, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType=‘PEON’, services={dataNodeService=DataNodeService{tier=’_default_tier’, maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier=’__default’}}}] appeared.

14706-2019-11-27T06:08:33,558 INFO [ServerInventoryView-0] org.apache.druid.curator.inventory.CuratorInventoryManager - Created new InventoryCacheListener for /druid_odyssey/segments/ip-10-0-2-242.ec2.internal:20002

14707-2019-11-27T06:08:33,559 INFO [ServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - New Server[DruidServerMetadata{name=‘ip-10-0-2-242.ec2.internal:20002’, hostAndPort=‘ip-10-0-2-242.ec2.internal:20002’, hostAndTlsPort=‘null’, maxSize=0, tier=’_default_tier’, type=indexer-executor, priority=0}]

14708-2019-11-27T06:08:33,560 INFO [NodeTypeWatcher[PEON]] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Node[ip-10-0-2-242.ec2.internal:20002:DiscoveryDruidNode{druidNode=DruidNode{serviceName=‘druid/peon’, host=‘ip-10-0-2-242.ec2.internal’, bindOnHost=false, port=-1, plaintextPort=20002, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType=‘PEON’, services={dataNodeService=DataNodeService{tier=’_default_tier’, maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier=’__default’}}}] appeared.

14709-2019-11-27T06:08:33,616 INFO [ServerInventoryView-0] org.apache.druid.curator.inventory.CuratorInventoryManager - Created new InventoryCacheListener for /druid_odyssey/segments/ip-10-0-5-40.ec2.internal:20003

14710-2019-11-27T06:08:33,616 INFO [ServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - New Server[DruidServerMetadata{name=‘ip-10-0-5-40.ec2.internal:20003’, hostAndPort=‘ip-10-0-5-40.ec2.internal:20003’, hostAndTlsPort=‘null’, maxSize=0, tier=’_default_tier’, type=indexer-executor, priority=0}]

14711-2019-11-27T06:08:33,620 INFO [NodeTypeWatcher[PEON]] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Node[ip-10-0-5-40.ec2.internal:20003:DiscoveryDruidNode{druidNode=DruidNode{serviceName=‘druid/peon’, host=‘ip-10-0-5-40.ec2.internal’, bindOnHost=false, port=-1, plaintextPort=20003, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType=‘PEON’, services={dataNodeService=DataNodeService{tier=’_default_tier’, maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier=’__default’}}}] appeared.

14712-2019-11-27T06:08:33,699 INFO [ServerInventoryView-0] org.apache.druid.curator.inventory.CuratorInventoryManager - Created new InventoryCacheListener for /druid_odyssey/segments/ip-10-0-5-40.ec2.internal:20002

14713-2019-11-27T06:08:33,699 INFO [ServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - New Server[DruidServerMetadata{name=‘ip-10-0-5-40.ec2.internal:20002’, hostAndPort=‘ip-10-0-5-40.ec2.internal:20002’, hostAndTlsPort=‘null’, maxSize=0, tier=’_default_tier’, type=indexer-executor, priority=0}]

14714-2019-11-27T06:08:33,700 INFO [NodeTypeWatcher[PEON]] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Node[ip-10-0-5-40.ec2.internal:20002:DiscoveryDruidNode{druidNode=DruidNode{serviceName=‘druid/peon’, host=‘ip-10-0-5-40.ec2.internal’, bindOnHost=false, port=-1, plaintextPort=20002, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType=‘PEON’, services={dataNodeService=DataNodeService{tier=’_default_tier’, maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier=’__default’}}}] appeared.

14715-2019-11-27T06:08:37,169 INFO [KafkaSupervisor-campaignsummary-Worker-1] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - Setting taskGroup sequences to [{0={1=2439384, 3=2207080, 5=2171568}}] for group [1]

14716-2019-11-27T06:08:37,170 INFO [KafkaSupervisor-campaignsummary-Worker-0] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - Setting taskGroup sequences to [{0={0=2214042, 2=2218314, 4=2186206}}] for group [0]

14717-2019-11-27T06:08:37,184 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - [campaignsummary] supervisor is running.

14718-2019-11-27T06:08:37,184 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:08:37.184Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=[{id=‘index_kafka_campaignsummary_1ee75630db13821_pjopjfbm’, startTime=2019-11-27T06:08:32.891Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_1ee75630db13821_imcbnafp’, startTime=2019-11-27T06:08:32.667Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}], publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1788}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14719-2019-11-27T06:08:37,191 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - [campaignsummary] supervisor is running.

14720-2019-11-27T06:08:37,191 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:08:37.191Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=[{id=‘index_kafka_campaignsummary_1ee75630db13821_pjopjfbm’, startTime=2019-11-27T06:08:32.891Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_1ee75630db13821_imcbnafp’, startTime=2019-11-27T06:08:32.667Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}], publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1788}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14721-2019-11-27T06:08:40,933 INFO [org.apache.druid.metadata.SQLMetadataSegmentManager-Exec–0] org.apache.druid.metadata.SQLMetadataSegmentManager - Polled and found 3,685 segments in the database

14722-2019-11-27T06:08:43,290 INFO [DatabaseRuleManager-Exec–0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 1 datasource(s)

14723-2019-11-27T06:08:43,674 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 8 tasks from storage (0 tasks added, 0 tasks removed).

14724-2019-11-27T06:08:45,341 INFO [LookupCoordinatorManager–4] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists

14725-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-2 to offset 2218314.

14726-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-3 to offset 2207080.

14727-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-0 to offset 2214042.

14728-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-1 to offset 2439384.

14729-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-4 to offset 2186206.

14730-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-5 to offset 2171568.

14731-2019-11-27T06:09:05,578 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - [campaignsummary] supervisor is running.

14732-2019-11-27T06:09:05,578 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:09:05.578Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=[{id=‘index_kafka_campaignsummary_1ee75630db13821_pjopjfbm’, startTime=2019-11-27T06:08:32.891Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_1ee75630db13821_imcbnafp’, startTime=2019-11-27T06:08:32.667Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3567}], publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1760}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14733-2019-11-27T06:09:20,587 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-2 to offset 2218314.

14734-2019-11-27T06:09:20,587 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-3 to offset 2207080.

And here are my segments, note that this is a staging server, so I don’t have constant traffic going to it, so some intervals don’t even get a segment:

Can you make sense of what’s going on here?

Thank you!!!

Michael

Sorry, some of the log got cut off, here is a bit more:

14719-2019-11-27T06:08:37,191 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - [campaignsummary] supervisor is running.

14720-2019-11-27T06:08:37,191 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:08:37.191Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=[{id=‘index_kafka_campaignsummary_1ee75630db13821_pjopjfbm’, startTime=2019-11-27T06:08:32.891Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_1ee75630db13821_imcbnafp’, startTime=2019-11-27T06:08:32.667Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3595}], publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1788}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1788}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14721-2019-11-27T06:08:40,933 INFO [org.apache.druid.metadata.SQLMetadataSegmentManager-Exec–0] org.apache.druid.metadata.SQLMetadataSegmentManager - Polled and found 3,685 segments in the database

14722-2019-11-27T06:08:43,290 INFO [DatabaseRuleManager-Exec–0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 1 datasource(s)

14723-2019-11-27T06:08:43,674 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 8 tasks from storage (0 tasks added, 0 tasks removed).

14724-2019-11-27T06:08:45,341 INFO [LookupCoordinatorManager–4] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists

14725-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-2 to offset 2218314.

14726-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-3 to offset 2207080.

14727-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-0 to offset 2214042.

14728-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-1 to offset 2439384.

14729-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-4 to offset 2186206.

14730-2019-11-27T06:08:50,582 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-5 to offset 2171568.

14731-2019-11-27T06:09:05,578 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - [campaignsummary] supervisor is running.

14732-2019-11-27T06:09:05,578 INFO [KafkaSupervisor-campaignsummary] org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor - {id=‘campaignsummary’, generationTime=2019-11-27T06:09:05.578Z, payload=KafkaSupervisorReportPayload{dataSource=‘campaignsummary’, topic=‘campaignsummary’, partitions=6, replicas=2, durationSeconds=3600, active=[{id=‘index_kafka_campaignsummary_1ee75630db13821_pjopjfbm’, startTime=2019-11-27T06:08:32.891Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_1ee75630db13821_imcbnafp’, startTime=2019-11-27T06:08:32.667Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_eihjhinb’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3567}, {id=‘index_kafka_campaignsummary_556f4ac8f985a2d_hgcjbedd’, startTime=2019-11-27T06:08:32.790Z, remainingSeconds=3567}], publishing=[{id=‘index_kafka_campaignsummary_1f8867fb0e26515_ecckalkc’, startTime=2019-11-27T05:08:24.861Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_1f8867fb0e26515_cmnpmacc’, startTime=2019-11-27T05:08:24.877Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jmdmbdil’, startTime=2019-11-27T05:08:24.902Z, remainingSeconds=1760}, {id=‘index_kafka_campaignsummary_ab68e0f1e803d15_jfmmgmjp’, startTime=2019-11-27T05:08:24.958Z, remainingSeconds=1760}], suspended=false, healthy=true, state=RUNNING, detailedState=RUNNING, recentErrors=}}

14733-2019-11-27T06:09:20,587 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-2 to offset 2218314.

14734-2019-11-27T06:09:20,587 INFO [KafkaSupervisor-campaignsummary-Reporting-0] org.apache.kafka.clients.consumer.internals.Fetcher - [Consumer clientId=consumer-5, groupId=kafka-supervisor-bebmfiod] Resetting offset for partition campaignsummary-3 to offset 2207080.

Hi Michael,
Thanks for showing logs.

I am glad that kafka ingestions are successful and you are getting new segments.

I am bit doubtful whether druid is throwing an aggressive log message(may be it is WARN but thrown as ERROR) but need to check with other druid committers on this aspect.

Will come back to you.

Thanks,

–siva

Thanks Siva!

Hi Michael,
This is the Github PR where they changed this from INFO to ERROR – https://github.com/apache/incubator-druid/pull/7339.

In your specific case, I guess you don’t need to worry about this error message in logs.

Thanks,

–siva

Hi Siva,

Thanks for finding the PR!

I am just wondering, what is special about my case that these errors are happening regularly. Perhaps jihoonson who made the change could weigh in? If these are expected to happen whenever there are 2 taskCount or 2 replicas for a kafka indexing service, then they shouldn’t be an ERROR. But if they are not expected, perhaps I am doing something different than others, and I could change to a more “mainstream” approach?

Thank you,

Michael