jaeger-ingester consumer error

[chopper-poet]

[chopper-poet]

When ingester has more than one instance,it will display those messages.

[guanw]

There is not enough info, could you dump the entire log to a file maybe?

[vprithvi]

All of these messages are logged at INFO, and is part of normal operations. The log line indicates processing of the errors channel.

Perhaps the logs can be moved to a DEBUG level.

[chopper-poet]

All of these messages are logged at INFO, and is part of normal operations. The log line indicates processing of the errors channel.

Perhaps the logs can be moved to a DEBUG level.

When ingester has more than one instance,it will display those messages.

[vprithvi]

This is normal operation, these messages would be displayed on every Kafka rebalance.

[chopper-poet]

This is normal operation, these messages would be displayed on every Kafka rebalance.

@vprithvi @yurishkuro
i think is not a normal operation,the num of jaeger-ingester always 2,but those message continual,maybe a bug.

Here are env info:
ingester:1.14.0
kafka:2.3

Here are error msgs:
====ingester====
2019/09/21 10:42:18 maxprocs: Leaving GOMAXPROCS=1: CPU quota undefined
WARNING: found deprecated command line option --span-storage.type=elasticsearch, please use environment variable SPAN_STORAGE_TYPE instead
{"level":"info","ts":1569033738.0063226,"caller":"flags/service.go:115","msg":"Mounting metrics handler on admin server","route":"/metrics"}
{"level":"info","ts":1569033738.006453,"caller":"flags/admin.go:108","msg":"Mounting health check on admin server","route":"/"}
{"level":"info","ts":1569033738.006529,"caller":"flags/admin.go:114","msg":"Starting admin HTTP server","http-port":14270}
{"level":"info","ts":1569033738.006546,"caller":"flags/admin.go:100","msg":"Admin server started","http-port":14270,"health-status":"unavailable"}
{"level":"info","ts":1569033738.023475,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1569033738.023505,"caller":"consumer/consumer.go:78","msg":"Starting main loop"}
{"level":"info","ts":1569033738.151742,"caller":"consumer/consumer.go:169","msg":"Starting error handler","partition":0}
{"level":"info","ts":1569033738.1518486,"caller":"consumer/consumer.go:112","msg":"Starting message handler","partition":0}
{"level":"info","ts":1569033741.4189322,"caller":"consumer/consumer.go:180","msg":"Finished handling errors","partition":0}
{"level":"info","ts":1569033741.4189994,"caller":"consumer/consumer.go:138","msg":"Message channel closed. ","partition":0}
{"level":"info","ts":1569033741.4190173,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033741.4191213,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033741.8808475,"caller":"consumer/consumer.go:169","msg":"Starting error handler","partition":0}
{"level":"info","ts":1569033741.8809078,"caller":"consumer/consumer.go:112","msg":"Starting message handler","partition":0}
{"level":"info","ts":1569033744.2168658,"caller":"consumer/processor_factory.go:62","msg":"Creating new processors","partition":0}
{"level":"info","ts":1569033745.9766564,"caller":"consumer/consumer.go:180","msg":"Finished handling errors","partition":0}
{"level":"info","ts":1569033745.9767509,"caller":"consumer/consumer.go:138","msg":"Message channel closed. ","partition":0}
{"level":"info","ts":1569033745.9780123,"caller":"processor/parallel_processor.go:78","msg":"Completed shutdown of processor goroutines"}
{"level":"info","ts":1569033745.9780428,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033745.9780908,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033746.7944613,"caller":"consumer/consumer.go:169","msg":"Starting error handler","partition":0}
{"level":"info","ts":1569033746.7945256,"caller":"consumer/consumer.go:112","msg":"Starting message handler","partition":0}
{"level":"info","ts":1569033750.0735219,"caller":"consumer/consumer.go:180","msg":"Finished handling errors","partition":0}
{"level":"info","ts":1569033750.07358,"caller":"consumer/consumer.go:138","msg":"Message channel closed. ","partition":0}
{"level":"info","ts":1569033750.0735936,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033750.0736668,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033750.5355024,"caller":"consumer/consumer.go:169","msg":"Starting error handler","partition":0}
{"level":"info","ts":1569033750.535565,"caller":"consumer/consumer.go:112","msg":"Starting message handler","partition":0}
{"level":"info","ts":1569033753.813964,"caller":"consumer/consumer.go:180","msg":"Finished handling errors","partition":0}
{"level":"info","ts":1569033753.8140304,"caller":"consumer/consumer.go:138","msg":"Message channel closed. ","partition":0}
{"level":"info","ts":1569033753.8140442,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033753.8141136,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033754.2764068,"caller":"consumer/consumer.go:169","msg":"Starting error handler","partition":0}
{"level":"info","ts":1569033754.2764654,"caller":"consumer/consumer.go:112","msg":"Starting message handler","partition":0}
^C{"level":"info","ts":1569033755.513566,"caller":"flags/service.go:145","msg":"Shutting down"}
{"level":"info","ts":1569033755.5136282,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"unavailable"}
{"level":"info","ts":1569033755.5136454,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033755.5326853,"caller":"consumer/consumer.go:180","msg":"Finished handling errors","partition":0}
{"level":"info","ts":1569033755.5327137,"caller":"consumer/consumer.go:138","msg":"Message channel closed. ","partition":0}
{"level":"info","ts":1569033755.532727,"caller":"consumer/consumer.go:162","msg":"Closing partition consumer","partition":0}
{"level":"info","ts":1569033755.5328152,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033755.5328388,"caller":"consumer/consumer.go:165","msg":"Closed partition consumer","partition":0}
{"level":"info","ts":1569033755.53285,"caller":"consumer/consumer.go:107","msg":"Closing parent consumer"}
{"level":"info","ts":1569033755.5365846,"caller":"flags/service.go:153","msg":"Shutdown complete"}
You have new mail in /var/spool/mail/root

====ingester====

====kafka server.log===
[2019-09-21 10:42:08,286] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1689 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-e9c21519-a721-4745-aa80-c6d2aee64231 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:08,290] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1690 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:08,293] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1690 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:18,130] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1690 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-0eb85261-1de8-4f6f-b53a-29a2944c5765 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:18,147] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1691 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:18,148] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1691 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,124] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1691 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-a30be48c-7c7c-4011-9c83-071ee7140cb6 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,134] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1692 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,136] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1692 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,876] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1692 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-0bb14181-b214-476f-a77e-cab9dbaa08d7 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,877] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1693 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:21,877] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1693 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:24,674] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1693 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-e1043d6a-0134-4ad3-af1f-c0285b355e0d with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:24,675] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1694 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:24,676] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1694 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:26,790] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1694 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-7231aa34-d430-42d7-bfd0-ffbcb87de626 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:26,791] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1695 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:26,791] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1695 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:28,408] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1695 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-cc9fa2c5-cbbf-4b11-956a-a2b2baf51513 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:28,408] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1696 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:28,437] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1696 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:30,531] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1696 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-56a13689-d051-4e97-8819-1dd028a2dff3 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:30,532] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1697 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:30,532] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1697 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:32,178] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1697 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-05ed8b29-cda5-4fb4-a730-bb206d25f66a with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:32,179] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1698 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:32,180] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1698 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:34,270] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1698 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-0b4bcbb0-5cbc-49f1-a93d-fc0b211e9000 with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:34,271] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1699 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:34,272] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1699 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,534] INFO [GroupCoordinator 188]: Member jaeger-ingester-0b4bcbb0-5cbc-49f1-a93d-fc0b211e9000 in group jaeger-ingester-20190906 has left, removing it from the group (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,534] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1699 (__consumer_offsets-38) (reason: removing member jaeger-ingester-0b4bcbb0-5cbc-49f1-a93d-fc0b211e9000 on LeaveGroup) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,534] INFO [GroupCoordinator 188]: Group jaeger-ingester-20190906 with generation 1700 is now empty (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,914] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1700 (__consumer_offsets-38) (reason: Adding new member jaeger-ingester-1f04fc99-d91b-4559-a1d5-507bdaa0010d with group instanceid None) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,915] INFO [GroupCoordinator 188]: Stabilized group jaeger-ingester-20190906 generation 1701 (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:35,916] INFO [GroupCoordinator 188]: Assignment received from leader for group jaeger-ingester-20190906 for generation 1701 (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:39,191] INFO [GroupCoordinator 188]: Member jaeger-ingester-1f04fc99-d91b-4559-a1d5-507bdaa0010d in group jaeger-ingester-20190906 has left, removing it from the group (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:39,192] INFO [GroupCoordinator 188]: Preparing to rebalance group jaeger-ingester-20190906 in state PreparingRebalance with old generation 1701 (__consumer_offsets-38) (reason: removing member jaeger-ingester-1f04fc99-d91b-4559-a1d5-507bdaa0010d on LeaveGroup) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:42:39,192] INFO [GroupCoordinator 188]: Group jaeger-ingester-20190906 with generation 1702 is now empty (__consumer_offsets-38) (kafka.coordinator.group.GroupCoordinator)
[2019-09-21 10:47:53,329] INFO [GroupMetadataManager brokerId=188] Removed 0 expired offsets in 11 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
====kafka server.log===

The rebalance is too frequently too Unbelievable.

ps:when use kafka 2.2.1 ,that's ok.