# Unwanted truncating of multiline message

**URL:** <https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872>\
**Category:** Beats\
**Tags:** filebeat\
**Created:** [November 6, 2019, 11:08pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872 "2019-11-06T23:08:41Z")\
**Posts on this page:** 11\
**Page:** 1

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 6, 2019, 11:08pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/1 "2019-11-06T23:08:41Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 8, 2019, 5:23pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/2 "2019-11-08T17:23:25Z")

</div>

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'"]}
```

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 13, 2019, 11:05am UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/3 "2019-11-13T11:05:21Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 15, 2019, 3:08pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/4 "2019-11-15T15:08:57Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kvch](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kvch/32/72058_2.png) [@kvch](https://discuss.elastic.co/u/kvch)\
**Post date:** [November 18, 2019, 3:56pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/5 "2019-11-18T15:56:07Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 18, 2019, 10:03pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/6 "2019-11-18T22:03:41Z")

</div>

> [@kvch](#):
>
> Could you please share the debug logs of Filebeat when it is reading the XML input and forwarding it to Logstash?

Thanks for the reply @kvch . 🙂

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

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 22, 2019, 5:36pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/7 "2019-11-22T17:36:46Z")

</div>

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:

> <https://gist.github.com/bhozar/2500c54a025c33fe0ae6700f14a7b30b>

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 28, 2019, 9:29am UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/8 "2019-11-28T09:29:57Z")

</div>

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

> <https://github.com/elastic/beats/issues/14831>
>
> I'm having an issue with an XML log file being ingested by Filebeat and some of the messages being passed onto...

---

<div class="post-metadata">

**Author:** ![kvch](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kvch/32/72058_2.png) [@kvch](https://discuss.elastic.co/u/kvch)\
**Post date:** [November 28, 2019, 3:28pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/9 "2019-11-28T15:28:31Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![Bhozar](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bhozar/32/57994_2.png) [@Bhozar](https://discuss.elastic.co/u/Bhozar)\
**Post date:** [November 29, 2019, 10:15pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/10 "2019-11-29T22:15:46Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [December 27, 2019, 10:15pm UTC](https://discuss.elastic.co/t/unwanted-truncating-of-multiline-message/206872/11 "2019-12-27T22:15:49Z")

</div>

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