Cherry-pick #11346 to 6.7: Don't use multiline options in Logstash mo…

…dule with json format (#11601)

Cherry-pick of PR #11346 to 6.7 branch. Original message: 

Multiline options were being applied to json log files with unexpected
results as several lines joined or lines lost.

CHANGELOG.next.asciidoc

@@ -39,6 +39,8 @@ https://github.com/elastic/beats/compare/v6.7.0...6.x[Check the HEAD diff]
 
 *Filebeat*
 
+- Don't apply multiline rules in Logstash json logs. {pull}11346[11346]
+
 *Heartbeat*
 
 *Journalbeat*

filebeat/module/logstash/log/config/log.yml

@@ -4,10 +4,13 @@ paths:
  - {{$path}}
 {{ end }}
 exclude_files: [".gz$"]
+
+{{ if eq .format "plain" }}
 multiline:
  pattern: ^\[[0-9]{4}-[0-9]{2}-[0-9]{2}
  negate: true
  match: after
+{{ end }}
 
 {{ if .convert_timezone }}
 processors:

filebeat/module/logstash/log/test/logstash-json.log

@@ -0,0 +1,11 @@
+{"level":"INFO","loggerName":"logstash.setting.writabledirectory","timeMillis":1554211185938,"thread":"main","logEvent":{"message":"Creating directory","setting":"path.queue","path":"/Users/shaunak/logstash-6.7.0/data/queue"}}
+{"level":"INFO","loggerName":"logstash.setting.writabledirectory","timeMillis":1554211185989,"thread":"main","logEvent":{"message":"Creating directory","setting":"path.dead_letter_queue","path":"/Users/shaunak/logstash-6.7.0/data/dead_letter_queue"}}
+{"level":"WARN","loggerName":"logstash.config.source.multilocal","timeMillis":1554211186100,"thread":"LogStash::Runner","logEvent":{"message":"Ignoring the 'pipelines.yml' file because modules or command line options are specified"}}
+{"level":"INFO","loggerName":"logstash.runner","timeMillis":1554211186118,"thread":"LogStash::Runner","logEvent":{"message":"Starting Logstash","logstash.version":"6.7.0"}}
+{"level":"INFO","loggerName":"logstash.agent","timeMillis":1554211186157,"thread":"LogStash::Runner","logEvent":{"message":"No persistent UUID file found. Generating new UUID","uuid":"9e1f7d9d-54df-4d5f-a8c6-a749cc6bc65e","path":"/Users/shaunak/logstash-6.7.0/data/uuid"}}
+{"level":"INFO","loggerName":"logstash.pipeline","timeMillis":1554211191608,"thread":"Converge PipelineAction::Create<main>","logEvent":{"message":"Starting pipeline","pipeline_id":"main","pipeline.workers":8,"pipeline.batch.size":125,"pipeline.batch.delay":50}}
+{"level":"INFO","loggerName":"logstash.pipeline","timeMillis":1554211191728,"thread":"Converge PipelineAction::Create<main>","logEvent":{"message":"Pipeline started successfully","pipeline_id":"main","thread":"#<Thread:0x6caf3d40 run>"}}
+{"level":"INFO","loggerName":"logstash.agent","timeMillis":1554211191782,"thread":"Ruby-0-Thread-1: /Users/shaunak/logstash-6.7.0/lib/bootstrap/environment.rb:6","logEvent":{"message":"Pipelines running","count":1,"running_pipelines":[{"metaClass":{"metaClass":{"metaClass":{"running_pipelines":"[:main]","non_running_pipelines":[]}}}}]}}
+{"level":"INFO","loggerName":"logstash.agent","timeMillis":1554211192126,"thread":"Api Webserver","logEvent":{"message":"Successfully started Logstash API endpoint","port":9600}}
+{"level":"WARN","loggerName":"logstash.runner","timeMillis":1554211198930,"thread":"SIGINT handler","logEvent":{"message":"SIGINT received. Shutting down."}}
+{"level":"INFO","loggerName":"logstash.pipeline","timeMillis":1554211199144,"thread":"[main]-pipeline-manager","logEvent":{"message":"Pipeline has terminated","pipeline_id":"main","thread":"#<Thread:0x6caf3d40 run>"}}

filebeat/module/logstash/log/test/logstash-json.log-expected.json

@@ -0,0 +1,174 @@
+[
+ {
+ "@timestamp": "2019-04-02T13:19:45.938Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.path": "/Users/shaunak/logstash-6.7.0/data/queue",
+ "logstash.log.log_event.setting": "path.queue",
+ "logstash.log.message": "Creating directory",
+ "logstash.log.module": "logstash.setting.writabledirectory",
+ "logstash.log.thread": "main",
+ "offset": 0,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:45.989Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.path": "/Users/shaunak/logstash-6.7.0/data/dead_letter_queue",
+ "logstash.log.log_event.setting": "path.dead_letter_queue",
+ "logstash.log.message": "Creating directory",
+ "logstash.log.module": "logstash.setting.writabledirectory",
+ "logstash.log.thread": "main",
+ "offset": 227,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:46.100Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "WARN",
+ "logstash.log.message": "Ignoring the 'pipelines.yml' file because modules or command line options are specified",
+ "logstash.log.module": "logstash.config.source.multilocal",
+ "logstash.log.thread": "LogStash::Runner",
+ "offset": 478,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:46.118Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.logstash.version": "6.7.0",
+ "logstash.log.message": "Starting Logstash",
+ "logstash.log.module": "logstash.runner",
+ "logstash.log.thread": "LogStash::Runner",
+ "offset": 712,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:46.157Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.path": "/Users/shaunak/logstash-6.7.0/data/uuid",
+ "logstash.log.log_event.uuid": "9e1f7d9d-54df-4d5f-a8c6-a749cc6bc65e",
+ "logstash.log.message": "No persistent UUID file found. Generating new UUID",
+ "logstash.log.module": "logstash.agent",
+ "logstash.log.thread": "LogStash::Runner",
+ "offset": 885,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:51.608Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.pipeline.batch.delay": 50,
+ "logstash.log.log_event.pipeline.batch.size": 125,
+ "logstash.log.log_event.pipeline.workers": 8,
+ "logstash.log.log_event.pipeline_id": "main",
+ "logstash.log.message": "Starting pipeline",
+ "logstash.log.module": "logstash.pipeline",
+ "logstash.log.thread": "Converge PipelineAction::Create<main>",
+ "offset": 1158,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:51.728Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.pipeline_id": "main",
+ "logstash.log.log_event.thread": "#<Thread:0x6caf3d40 run>",
+ "logstash.log.message": "Pipeline started successfully",
+ "logstash.log.module": "logstash.pipeline",
+ "logstash.log.thread": "Converge PipelineAction::Create<main>",
+ "offset": 1421,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:51.782Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.count": 1,
+ "logstash.log.log_event.running_pipelines": [
+ {
+ "metaClass": {
+ "metaClass": {
+ "metaClass": {
+ "non_running_pipelines": [],
+ "running_pipelines": "[:main]"
+ }
+ }
+ }
+ }
+ ],
+ "logstash.log.message": "Pipelines running",
+ "logstash.log.module": "logstash.agent",
+ "logstash.log.thread": "Ruby-0-Thread-1: /Users/shaunak/logstash-6.7.0/lib/bootstrap/environment.rb:6",
+ "offset": 1659,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:52.126Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.port": 9600,
+ "logstash.log.message": "Successfully started Logstash API endpoint",
+ "logstash.log.module": "logstash.agent",
+ "logstash.log.thread": "Api Webserver",
+ "offset": 1998,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:58.930Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "WARN",
+ "logstash.log.message": "SIGINT received. Shutting down.",
+ "logstash.log.module": "logstash.runner",
+ "logstash.log.thread": "SIGINT handler",
+ "offset": 2177,
+ "prospector.type": "log"
+ },
+ {
+ "@timestamp": "2019-04-02T13:19:59.144Z",
+ "event.dataset": "logstash.log",
+ "fileset.module": "logstash",
+ "fileset.name": "log",
+ "input.type": "log",
+ "logstash.log.level": "INFO",
+ "logstash.log.log_event.pipeline_id": "main",
+ "logstash.log.log_event.thread": "#<Thread:0x6caf3d40 run>",
+ "logstash.log.message": "Pipeline has terminated",
+ "logstash.log.module": "logstash.pipeline",
+ "logstash.log.thread": "[main]-pipeline-manager",
+ "offset": 2335,
+ "prospector.type": "log"
+ }
+]

filebeat/tests/system/test_modules.py

@@ -129,6 +129,11 @@ def run_on_file(self, module, fileset, test_file, cfgfile):
  "-M", "*.*.input.close_eof=true",
  ]
 
+ # Based on the convention that if a name contains -json the json format is needed. Currently used for LS.
+ if "-json" in test_file:
+ cmd.append("-M")
+ cmd.append("{module}.{fileset}.var.format=json".format(module=module, fileset=fileset))
+
  output_path = os.path.join(self.working_dir)
  output = open(os.path.join(output_path, "output.log"), "ab")
  output.write(" ".join(cmd) + "\n")