Infinite logging with logstash through kafka

Question

Overview

I'm attempting to get Logstash working with Kafka, using docker containers.

For my Kafka container, I'm using the spotify build. I am also using the official Logstash container.

I want to achieve something like the following:

Here are the configs I am using for Logstash:

file_kafka.conf

input {
    file {
        path => ["/data/*.log"]
        start_position => "beginning"
    }
}

output {
    kafka {
        topic_id => "test"
        bootstrap_servers => "<host>:9092"
    }
}

kafka_stdout.conf

input {
    kafka {
        topics => ["test"]
        bootstrap_servers => "<host>:9092"
        auto_offset_reset => "latest"
    }
}

output {
    stdout {}
}

This setup seems entirely reasonable to me. In fact, it actually kind of worked at first.

The Problem

I started up the containers involved, and Logstash correctly picked up the single line in my test.log file and printed it to the screen.

However, I then ran the following:

echo 'blah' >> test.log

And I received this output from logstash:

2017-05-11T18:36:49.090Z %{host} 2017-05-11T18:36:49.082Z %{host} 2017-05-11T18:36:49.076Z %{host} 2017-05-11T18:36:49.069Z %{host} 2017-05-11T18:36:49.062Z %{host} 2017-05-11T18:36:49.053Z %{host} 2017-05-11T18:36:49.044Z %{host} 2017-05-11T18:36:49.034Z %{host} 2017-05-11T18:36:49.025Z %{host} 2017-05-11T18:36:49.016Z %{host} 2017-05-11T18:36:49.009Z %{host} 2017-05-11T18:36:49.003Z %{host} 2017-05-11T18:36:48.995Z %{host} 2017-05-11T18:36:48.988Z %{host} 2017-05-11T18:36:48.982Z %{host} 2017-05-11T18:36:48.975Z %{host} 2017-05-11T18:36:48.968Z %{host} 2017-05-11T18:36:48.948Z %{host} 2017-05-11T18:36:48.927Z %{host} 2017-05-11T18:36:48.911Z %{host} 2017-05-11T18:36:48.896Z %{host} 2017-05-11T18:36:48.881Z %{host} 2017-05-11T18:36:48.868Z %{host} 2017-05-11T18:36:48.857Z %{host} 2017-05-11T18:36:48.849Z %{host} 2017-05-11T18:36:48.841Z %{host} 2017-05-11T18:36:48.830Z %{host} 2017-05-11T18:36:48.820Z %{host} 2017-05-11T18:36:48.805Z %{host} 2017-05-11T18:36:48.791Z %{host} 2017-05-11T18:36:48.779Z %{host} 2017-05-11T18:36:48.492Z %{host} 2017-05-11T18:36:48.483Z %{host} 2017-05-11T18:36:48.471Z %{host} 2017-05-11T18:36:48.463Z %{host} 2017-05-11T18:36:48.454Z %{host} 2017-05-11T18:36:48.445Z %{host} 2017-05-11T18:36:48.437Z %{host} 2017-05-11T18:36:48.427Z %{host} 2017-05-11T18:36:48.420Z %{host} 2017-05-11T18:36:48.412Z %{host} 2017-05-11T18:36:48.406Z %{host} 2017-05-11T18:36:48.399Z %{host} 2017-05-11T18:36:48.391Z %{host} 2017-05-11T18:36:48.385Z %{host} 2017-05-11T18:36:48.378Z %{host} 2017-05-11T18:36:48.371Z %{host} 2017-05-11T18:36:48.356Z %{host} 2017-05-11T18:36:48.286Z %{host} 2017-05-11T18:36:48.278Z %{host} 2017-05-11T18:36:48.269Z %{host} 2017-05-11T18:36:48.261Z %{host} 2017-05-11T18:36:48.246Z %{host} 2017-05-11T18:36:48.238Z %{host} 2017-05-11T18:36:48.229Z %{host} 2017-05-11T18:36:48.219Z %{host} 2017-05-11T18:36:48.209Z %{host} 2017-05-11T18:36:48.201Z %{host} 2017-05-11T18:36:48.191Z %{host} 2017-05-11T18:36:48.182Z %{host} 2017-05-11T18:36:48.175Z %{host} 2017-05-11T18:36:48.167Z %{host} 2017-05-11T18:36:48.112Z %{host} 2017-05-11T18:36:48.103Z %{host} 2017-05-11T18:36:48.095Z %{host} 2017-05-11T18:36:48.086Z %{host} 2017-05-11T18:36:48.077Z %{host} 2017-05-11T18:36:48.068Z %{host} 2017-05-11T18:36:48.059Z %{host} 2017-05-11T18:36:48.048Z %{host} 2017-05-11T18:36:48.031Z %{host} 2017-05-11T18:36:48.016Z %{host} 2017-05-11T18:36:48.009Z %{host} 2017-05-11T18:36:48.002Z %{host} 2017-05-11T18:36:47.994Z %{host} 2017-05-11T18:36:47.986Z %{host} 2017-05-11T18:36:47.972Z %{host} 2017-05-11T18:36:47.947Z %{host} 2017-05-11T18:36:47.923Z %{host} 2017-05-11T18:36:47.904Z %{host} 2017-05-11T18:36:47.879Z %{host} 2017-05-11T18:36:47.864Z %{host} 2017-05-11T18:36:47.853Z %{host} 2017-05-11T18:36:47.842Z %{host} 2017-05-11T18:36:47.834Z %{host} 2017-05-11T18:36:47.820Z %{host} 2017-05-11T18:36:47.810Z %{host} 2017-05-11T18:36:47.799Z %{host} 2017-05-11T18:36:47.792Z %{host} 2017-05-11T18:36:47.785Z %{host} 2017-05-11T18:36:47.778Z %{host} 2017-05-11T18:36:47.768Z %{host} 2017-05-11T18:36:47.757Z %{host} 2017-05-11T18:36:47.741Z %{host} 2017-05-11T18:36:47.722Z %{host} 2017-05-11T18:36:47.702Z %{host} 2017-05-11T18:36:47.690Z %{host} 2017-05-11T18:36:47.674Z %{host} 2017-05-11T18:36:47.667Z %{host} 2017-05-11T18:36:47.659Z %{host} 2017-05-11T18:36:47.649Z %{host} 2017-05-11T18:36:47.639Z %{host} 2017-05-11T18:36:47.632Z %{host} 2017-05-11T18:36:47.626Z %{host} 2017-05-11T18:36:47.619Z %{host} 2017-05-11T18:36:47.612Z %{host} 2017-05-11T18:36:47.603Z %{host} 2017-05-11T18:36:47.592Z %{host} 2017-05-11T18:36:47.555Z %{host} 2017-05-11T18:36:47.537Z %{host} 2017-05-11T18:36:47.523Z %{host} 2017-05-11T18:36:47.513Z %{host} 2017-05-11T18:36:47.505Z %{host} 2017-05-11T18:36:47.492Z %{host} 2017-05-11T18:36:47.484Z %{host} 2017-05-11T18:36:47.476Z %{host} 2017-05-11T18:36:47.468Z %{host} 2017-05-11T18:36:47.456Z %{host} 2017-05-11T18:36:47.447Z %{host} 2017-05-11T18:36:47.437Z %{host} 2017-05-11T18:36:47.425Z %{host} 2017-05-11T18:36:47.416Z %{host} 2017-05-11T18:36:47.403Z %{host} 2017-05-11T18:36:47.395Z %{host} 2017-05-11T18:36:47.388Z %{host} 2017-05-11T18:36:47.379Z %{host} 2017-05-11T18:36:47.372Z %{host} 2017-05-11T18:36:47.364Z %{host} 2017-05-11T18:36:47.351Z %{host} 2017-05-11T18:36:47.318Z %{host} 2017-05-11T18:36:47.308Z %{host} 2017-05-11T18:36:47.293Z %{host} 2017-05-11T18:36:47.274Z %{host} 2017-05-11T18:36:47.255Z %{host} 2017-05-11T18:36:47.244Z %{host} 2017-05-11T18:36:47.232Z %{host} 2017-05-11T18:36:47.215Z %{host} 2017-05-11T18:36:47.205Z %{host} 2017-05-11T18:36:47.197Z %{host} 2017-05-11T18:36:47.188Z %{host} 2017-05-11T18:36:47.180Z %{host} 2017-05-11T18:36:47.170Z %{host} 2017-05-11T18:36:47.162Z %{host} 2017-05-11T18:36:47.155Z %{host} 2017-05-11T18:36:47.147Z %{host} 2017-05-11T18:36:47.141Z %{host} 2017-05-11T18:36:47.134Z %{host} 2017-05-11T18:36:47.127Z %{host} 2017-05-11T18:36:47.119Z %{host} 2017-05-11T18:36:47.111Z %{host} 2017-05-11T18:36:47.096Z %{host} 2017-05-11T18:36:47.082Z %{host} 2017-05-11T18:36:47.064Z %{host} 2017-05-11T18:36:47.047Z %{host} 2017-05-11T18:36:47.034Z %{host} 2017-05-11T18:36:47.026Z %{host} 2017-05-11T18:36:47.014Z %{host} 2017-05-11T18:36:47.006Z %{host} 2017-05-11T18:36:46.996Z %{host} 2017-05-11T18:36:46.975Z %{host} 2017-05-11T18:36:46.965Z %{host} 2017-05-11T18:36:46.935Z %{host} 2017-05-11T18:36:46.928Z %{host} 2017-05-11T18:36:46.921Z %{host} 2017-05-11T18:36:46.914Z %{host} 2017-05-11T18:36:46.907Z %{host} 2017-05-11T18:36:46.899Z %{host} 2017-05-11T18:36:46.888Z %{host} 2017-05-11T18:36:46.867Z %{host} 2017-05-11T18:36:46.845Z %{host} 2017-05-11T18:36:46.833Z %{host} 2017-05-11T18:36:46.817Z %{host} 2017-05-11T18:36:46.798Z %{host} 2017-05-11T18:36:46.783Z %{host} 2017-05-11T18:36:46.759Z %{host} 2017-05-11T18:36:46.743Z %{host} 2017-05-11T18:36:46.725Z %{host} 2017-05-11T18:36:46.712Z %{host} 2017-05-11T18:36:46.695Z %{host} 2017-05-11T18:36:46.685Z %{host} 2017-05-11T18:36:46.677Z %{host} 2017-05-11T18:36:46.666Z %{host} 2017-05-11T18:36:46.659Z %{host} 2017-05-11T18:36:46.642Z %{host} 2017-05-11T18:36:46.631Z %{host} 2017-05-11T18:36:46.620Z %{host} 2017-05-11T18:36:46.606Z %{host} 2017-05-11T18:36:46.593Z %{host} 2017-05-11T18:36:46.577Z %{host} 2017-05-11T18:36:46.568Z %{host} 2017-05-11T18:36:46.549Z %{host} 2017-05-11T18:36:46.541Z %{host} 2017-05-11T18:36:46.532Z %{host} 2017-05-11T18:36:46.524Z %{host} 2017-05-11T18:36:46.507Z %{host} 2017-05-11T18:36:46.491Z %{host} 2017-05-11T18:36:46.474Z %{host} 2017-05-11T18:36:46.429Z %{host} 2017-05-11T18:36:46.420Z %{host} 2017-05-11T18:36:46.408Z %{host} 2017-05-11T18:36:46.397Z %{host} 2017-05-11T18:36:46.382Z %{host} 2017-05-11T18:36:46.353Z %{host} 2017-05-11T18:36:46.345Z %{host} 2017-05-11T18:36:46.337Z %{host} 2017-05-11T18:36:46.330Z %{host} 2017-05-11T18:36:46.323Z %{host} 2017-05-11T18:36:46.314Z %{host} 2017-05-11T18:36:46.302Z %{host} 2017-05-11T18:36:46.293Z %{host} 2017-05-11T18:36:46.279Z %{host} 2017-05-11T18:36:46.265Z %{host} 2017-05-11T18:36:46.252Z %{host} 2017-05-11T18:36:46.181Z %{host} 2017-05-11T18:36:46.152Z %{host} 2017-05-11T18:36:46.128Z %{host} 2017-05-11T18:36:46.110Z %{host} 2017-05-11T18:36:46.088Z %{host} 2017-05-11T18:36:46.075Z %{host} 2017-05-11T18:36:46.067Z %{host} 2017-05-11T18:36:46.058Z %{host} 2017-05-11T18:36:46.045Z %{host} 2017-05-11T18:36:46.025Z %{host} 2017-05-11T18:36:46.016Z %{host} 2017-05-11T18:36:46.008Z %{host} 2017-05-11T18:36:45.995Z %{host} 2017-05-11T18:36:45.986Z %{host} 2017-05-11T18:36:45.972Z %{host} 2017-05-11T18:36:45.934Z %{host} 2017-05-11T18:36:45.915Z %{host} 2017-05-11T18:36:45.898Z %{host} 2017-05-11T18:36:45.887Z %{host} 2017-05-11T18:36:45.855Z dc6258001c01 blah

This block of text was repeated ad infinitum until I terminated the logstash process. It's as if it got into some sort of non-terminating loop. I was also seeing my topic offsets increment in the kafka instance while this was happening.

So this leaves me with two questions:

1. Why is logstash re-reading the same line over and over again, forever?
2. What is up with the format of that message? Isn't it just supposed to be timestamp host line? It looks to be correct at the very end, but the timestamp %{host} pattern is repeated uselessly about 232 times before that. Why?

Answer 1

I've run into a similar issue with both Kafka and RabbitMQ myself.

Logstash does not care that you split configurations into separate files, ultimately the ability to do so is for human consumption (to make configurations easier to find and modify). At runtime all Logstash configurations are merged together in the pipeline and are treated as a single configuration. While I don't necessarily know how order is applied, it would operate as such on a single host:

input {
    file {
        path => ["/data/*.log"]
        start_position => "beginning"
    }
    kafka {
        topics => ["test"]
        bootstrap_servers => "<host>:9092"
        auto_offset_reset => "latest"
    }
}

output {
    kafka {
        topic_id => "test"
        bootstrap_servers => "<host>:9092"
    }
    stdout {}
}

Given that one of your inputs is set to read the last offset that was written, it will just read that, apply no filter, and output it to the same topic. Kafka brokers have no concept of what the messages themselves are, but Kafka (ultimately ZooKeeper) keeps track of the offset of the messages written by a publisher, and the offset of the messages read by a subscriber.

You need to run a separate Logstash instance. To validate the input without the second configuration (with stdout), I suggest using kafkacat to read your Kafka topics (it can also be used to publish messages, as well).

kafkacat -C -b <broker>:9092 -t <topic>

The only alternative (that I'm aware works) that allows you to use a single Logstash instance is that you have to use the mutate method in the filter step, however this complicates the logic and it's best to adhere to the shipper/indexer pattern with Logstash.