Unwanted truncating of multiline message

Elastic Stack Beats
1

I'm having an issue with an XML log file being ingested by Filebeat and some of the messages being passed onto Logstash with the opening tag truncated. There's no pattern to the failures that I can spot and works 95% of the time.

I'm not 100% certain the issue is with Filebeat, it could be with Logstash.

The open tag is <event but it is being truncated to nt by the time it hits ElasticSearch.

Original Log entry:

  <event seq="1373559" time="2019-10-06 05:33:24.821336 +0100" app="BvSshServer 8.32" name="I_CONNECT_ACCEPTED" desc="Connection accepted.">
    <session id="564645" service="SSH" remoteAddress="168.6.1.1:59730"/>
    <parameters addressRule="AnyIP" listenAddress="10.5.1.2:22"/>
    <sessions ssh="4" sshAuth="2" ftp="0" ftpAuth="0"/>
  </event>

Filebeat config:

- type: log
  enabled: true
- L:\Bitvise\Logs\*
  tags: ["bitvise"]
  exclude_lines: ['<?xml','<log>','<start time','</log>']
  ### Multiline options
  multiline.pattern: '^  <event '
  multiline.negate: true
Logstash
  multiline.match: after
  multiline.flush_pattern: '</event>'

Logstash filter:

filter {
  if "bitvise" in [tags] {
    xml {
      force_array => false
      source => "message"
      store_xml => true
      target => "sftp"
    }
    mutate {
        convert => {"bytes_written" => "integer"}
        convert => {"bytes_read" => "integer"}
        convert => {"time_ms" => "integer"}
    }
  }
}

ElasticSearch example entry:

"tags": [
	"bitvise",
	"beats_input_codec_plain_applied",
	"_xmlparsefailure"
],

"message": "nt seq=\"621306\" time=\"2019-11-06 13:46:21.481477 +0000\" app=\"BvSshServer 8.36\" name=\"I_CONNECT_ACCEPTED\" desc=\"Connection accepted.\">\n <session id=\"226641\" service=\"SSH\" remoteAddress=\"10.0.0.1:36236\"/>\n <parameters addressRule=\"AnyIP\" listenAddress=\"10.5.1.28:22\"/>\n <sessions ssh=\"4\" sshAuth=\"2\" ftp=\"0\" ftpAuth=\"0\"/>\n </event>"

Does anyone have any idea why the opening tag gets truncated? I changed the pattern to be <ev and the results were the same.

2

Found this in the logstash-plain.log, but doesn't help as far as I can tell:

[2019-11-08T17:21:34,349][WARN ][logstash.filters.xml     ] Error parsing xml with XmlSimple {:source=>"message", :value=>"nt seq=\"1879455\" time=\"2019-11-08 17:21:28.259809 +0000\" app=\"BvSshServer 8.36\" name=\"I_CONNECT_ACCEPTED\" desc=\"Connection accepted.\">\n    <session id=\"397581\" service=\"SSH\" remoteAddress=\"16.6.12.1:59398\"/>\n    <parameters addressRule=\"AnyIP\" listenAddress=\"10.5.1.2:22\"/>\n    <sessions ssh=\"2\" sshAuth=\"0\" ftp=\"0\" ftpAuth=\"0\"/>\n  </event>", :exception=>#<REXML::ParseException: #<RuntimeError: attempted adding second root element to document>
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:96:in `add'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/element.rb:904:in `add'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/child.rb:22:in `initialize'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/parent.rb:14:in `initialize'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/element.rb:60:in `initialize'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/element.rb:902:in `add'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/element.rb:298:in `add_element'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:103:in `add_element'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/parsers/treeparser.rb:34:in `parse'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:288:in `build'
uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:45:in `initialize'
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:971:in `parse'
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:164:in `xml_in'
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:203:in `xml_in'
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-filter-xml-4.0.7/lib/logstash/filters/xml.rb:185:in `filter'
/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:143:in `do_filter'
/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:162:in `block in multi_filter'
org/jruby/RubyArray.java:1800:in `each'
/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:159:in `multi_filter'
org/logstash/config/ir/compiler/AbstractFilterDelegatorExt.java:115:in `multi_filter'
/usr/share/logstash/logstash-core/lib/logstash/java_pipeline.rb:243:in `block in start_workers'
...
attempted adding second root element to document
Line: 3
Position: 282
Last 80 unconsumed characters:
>, :backtrace=>["uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/parsers/treeparser.rb:96:in `parse'", "uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:288:in `build'", "uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rexml/document.rb:45:in `initialize'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:971:in `parse'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:164:in `xml_in'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/xml-simple-1.1.5/lib/xmlsimple.rb:203:in `xml_in'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-filter-xml-4.0.7/lib/logstash/filters/xml.rb:185:in `filter'", "/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:143:in `do_filter'", "/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:162:in `block in multi_filter'", "org/jruby/RubyArray.java:1800:in `each'", "/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:159:in `multi_filter'", "org/logstash/config/ir/compiler/AbstractFilterDelegatorExt.java:115:in `multi_filter'", "/usr/share/logstash/logstash-core/lib/logstash/java_pipeline.rb:243:in `block in start_workers'"]}
3

I'm still completely stuck on this one. No matter what I change in filebeat the opening tag sometimes gets truncated from <event to nt

Is it a bug perhaps?

4

Upgraded to the latest Filebeat and Logstash with no change in behavior.

5

Could you please share the debug logs of Filebeat when it is reading the XML input and forwarding it to Logstash?

1 Like
6

Thanks for the reply @kvch . :slightly_smiling_face:

Look for the lines like this:
"message": "nt seq in https://gist.github.com/bhozar/2500c54a025c33fe0ae6700f14a7b30b

7

Tried changing the multiline.pattern to:
multiline.pattern: '.*nt seq'

No change. My thinking was the filebeat debut log was showing the message line without the start so thought it might pick it up if I changed the multiline pattern.
debug log:

8

Added a bug report to GitHub for Filebeat as there doesn't seem to be a solution to this.

9

I have closed your issue on Github. Please do not open issues until someone from Elastic asks you to.

According to the Filebeat logs, a multiline message had been published due to timeout before the truncated message was published. Have you tried setting multiline.timeout to a higher value?

10

Thanks. Raising it to 15s has stopped the issue.

11

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