Multiline codec with http input

Elastic Stack Logstash
1

Greetings. I'm stumped trying to use a multiline filter (Logstash 5.1) on my data that is coming in via HTTPS POST.

I see that the plugin is being registered in the config...

[2018-04-23T21:26:07,256][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"multiline", :type=>"codec", :class=>LogStash::Codecs::Multiline}
[2018-04-23T21:26:07,263][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@pattern = "^\\s"
[2018-04-23T21:26:07,264][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@what = "previous"
[2018-04-23T21:26:07,264][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@auto_flush_interval = 1
[2018-04-23T21:26:07,264][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@id = "ab31790c1541b1d404e8a44995954d90c9d3bb70-1"
[2018-04-23T21:26:07,264][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@enable_metric = true
[2018-04-23T21:26:07,264][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@negate = false
[2018-04-23T21:26:07,266][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@patterns_dir = []
[2018-04-23T21:26:07,266][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@charset = "UTF-8"
[2018-04-23T21:26:07,266][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@multiline_tag = "multiline"
[2018-04-23T21:26:07,267][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@max_lines = 500
[2018-04-23T21:26:07,267][DEBUG][logstash.codecs.multiline] config LogStash::Codecs::Multiline/@max_bytes = 10485760

However, it never seems to trigger. After thinking about this way too much, I think I may be confused about what the plugin is actually doing... my events are coming in as JSON (see here for the format), and I'm beginning to suspect that the multiline filter is groking the entire event for my pattern, which would explain why it doesn't trigger, because I'm basing my pattern on one field, namely, the log field.

Here's some detailed output...

2018-04-23T21:17:00.423Z [welld-ls-web 24cbe615b2ff]: [2018-04-23T21:17:00,422][DEBUG][logstash.pipeline        ] filter received {"event"=>{"app"=>"welld-demo", "container"=>"353bd1f36a1b9a459a605cc9faa58b0335140485734d085d38b3fab9a753d14e", "headers"=>{"http_x_forwarded_port"=>"443", "http_version"=>"HTTP/1.1", "http_connection"=>"upgrade", "request_method"=>"POST", "http_x_forwarded_proto"=>"https", "http_host"=>"app-9093.on-aptible.com", "request_uri"=>"/", "http_x_request_start"=>"t=1524518220.410", "http_x_amzn_trace_id"=>"Root=1-5ade4d4c-885ddcb54af208eef5336d89", "http_user_agent"=>"Manticore 0.4.1", "content_type"=>"application/json", "http_accept_encoding"=>"gzip,deflate", "http_x_forwarded_for"=>"10.134.0.48, 10.134.6.105", "request_path"=>"/", "content_length"=>"564"}, "offset"=>"32627", "log"=>"F, [2018-04-23T21:16:58.210343 #18212] FATAL -- : \n", "source"=>"app", "type"=>"json", "layer"=>"app", "@timestamp"=>2018-04-23T21:16:58.210Z, "file"=>"/tmp/dockerlogs/353bd1f36a1b9a459a605cc9faa58b0335140485734d085d38b3fab9a753d14e/353bd1f36a1b9a459a605cc9faa58b0335140485734d085d38b3fab9a753d14e-json.log", "stream"=>"stdout", "service"=>"welld-demo-rails", "@version"=>"1", "host"=>"172.17.42.1", "time"=>"2018-04-23T21:16:58.210639874Z", "app_id"=>"8653"}}
2018-04-23T21:17:00.423Z [welld-ls-web 24cbe615b2ff]: [2018-04-23T21:17:00,423][DEBUG][logstash.filters.grok    ] Running grok filter {:event=>2018-04-23T21:16:58.210Z 172.17.42.1 %{message}}
2018-04-23T21:17:00.423Z [welld-ls-web 24cbe615b2ff]: [2018-04-23T21:17:00,423][DEBUG][logstash.filters.grok    ] Event now:  {:event=>2018-04-23T21:16:58.210Z 172.17.42.1 
2018-04-23T21:17:00.423Z [welld-ls-web 24cbe615b2ff]: }
2018-04-23T21:17:00.424Z [welld-ls-web 24cbe615b2ff]: [2018-04-23T21:17:00,423][DEBUG][logstash.util.decorators ] filters/LogStash::Filters::Mutate: adding tag {"tag"=>"welld-demo-rails"}

Larger dump of info in this gist.

Last but not least, here's the input section of my config:

input {
  http {
    port => 80
    codec => multiline { # grok patterns ok
      pattern => "^\s" #lines that start with space
      what => previous
      auto_flush_interval => 1
    }
  }
}

If my suspicion is right here, what is the best way to solve it? Write a pattern that matches the JSON?

Thanks for reading. Any help much appreciated!

2

Unless you want to join payloads from multiple HTTP requests (which sounds like a patently bad idea) you don't need the multiline codec.

3

Like I said, maybe I have misunderstood the appropriate solution to my problem, given that the multiline examples don't deal with HTTP input. But nevertheless, I want to capture fatal ruby events in one log message, despite the fact that each line of these multiline errors is parsed as its own event (albeit with the same timestamp), e.g.:

"log" => "F, [2018-04-23T21:16:58.210343 #18212] FATAL -- : \n",
"log" => "NoMethodError (undefined method `downcase' for nil:NilClass):\n",
"log" => "  app/models/activity_stream.rb:147:in `icon'\n",
"log" => "  app/controllers/users/activity_streams_controller.rb:14:in `index'\n",
"log" => "\n",
"log" => "\n",

Logically these are one event, and I want them to come out of logstash this way. Is this possible? Perhaps a clever use of the aggregate filter?

4

So you get multiple HTTP requests, each containing one physical line from the log? As I said, attempting to stitch those together is a really bad idea. Don't do it. If you provide more details about your setup we might be able to suggest something that would work better.

5

For some reason, yes, on these FATAL ruby errors, they do not come through as one event/call. My use case is kind of edgy... These events are coming in via an Enclave Log Drain. I'm running logstash in a docker container that captures all the posts from all my log drains, after which I send them to DataDog. It's really annoying that these critical errors aren't viewable as a single entry. Any other solutions welcome. Thanks.

6

Having the logging framework send logs over the network is rarely a good idea. I would've streamed the logs to disk and shipped them separately outside the application.

7

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.