Not transferring Multiline messages

Elastic Stack Beats
1

It seems my multiline filter in Filebeat is not working I was
looking at the log file for the multiline messages and found that they
were not being transferred to Elastisearch. My config file is

filebeat:
  # List of prospectors to fetch data.
  prospectors:
    # Each - is a prospector. Below are the prospector specific configurations
    -
      paths:
        - /local/gstapps/development/jboss/domain/servers/axeda68dev/log/server.log
        - /local/gstapps/development/jboss/domain/servers/axeda68dev/log/customobjects.log
      input_type: log
      exclude_lines: ["^$"]
      multiline:
        pattern: '^[[:space:]]+|^Caused by:'
        negate: false
        match: after
      close_older: 15m
output:
  ### Elasticsearch as output
  elasticsearch:
    hosts: ["3.28.180.76:9200"]
    index: "filebeat-jboss-dev"

A sample from the server.log file is, where the message at 15:20 is tranferred but the message at 15:22 is not.

15:20:30,233 ERROR [com.axeda.drm.config.validation.AbstractCacheClusterValidator] (EHCACHE ClusterValidator Thread) Found cache key 3.20.244.80-e555b44:157c4a58579:-8000:3.20.244.82--8bae67c:157c4a880e3:-8000 when it should have been deleted (invalidated) for validatorType=EHCACHE nodeId='3.20.244.80-e555b44:157c4a58579:-8000'
15:22:47,141 ERROR [com.axeda.drm.services.eventsubscription.AMQServer] (ESS-Periodic-Reaper-%d thread-1) Error acquiring MBean server connection, username: GEHC, password: gehcManager, jmxUri: service:jmx:rmi:///jndi/rmi://usmkersvpvmd2l.am.health.ge.com:3099/jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd3l.am.health.ge.com:3099/jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd4l.am.health.ge.com:3099/jmxrmi: java.io.IOException: Failed to retrieve RMIServer stub: javax.naming.NameNotFoundException: jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd3l.am.health.ge.com:3099/jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd4l.am.health.ge.com:3099/jmxrmi
    at javax.management.remote.rmi.RMIConnector.connect(RMIConnector.java:369) [rt.jar:1.7.0_75]
    at javax.management.remote.rmi.RMIConnector.connect(RMIConnector.java:249) [rt.jar:1.7.0_75]
    at com.axeda.drm.services.eventsubscription.AMQServer.getMBeanServerConnection(AMQServer.java:164)
    at com.axeda.drm.services.eventsubscription.AMQHelper.getBrokerViewMbean(AMQHelper.java:98)
    at com.axeda.drm.services.eventsubscription.QueueManagerImpl.getSamePrefixQueues(QueueManagerImpl.java:222)
    at com.axeda.drm.services.eventsubscription.AMQConnectionMonitor.reapQueues(AMQConnectionMonitor.java:159)
    at com.axeda.drm.services.eventsubscription.PeriodicReaperRunnable.run(PeriodicReaperRunnable.java:50)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_75]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [rt.jar:1.7.0_75]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [rt.jar:1.7.0_75]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [rt.jar:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_75]
    at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_75]
Caused by: javax.naming.NameNotFoundException: jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd3l.am.health.ge.com:3099/jmxrmi,service:jmx:rmi:///jndi/rmi://usmkersvpvmd4l.am.health.ge.com:3099/jmxrmi
    at com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:116) [rt.jar:1.7.0_75]
    at com.sun.jndi.toolkit.url.GenericURLContext.lookup(GenericURLContext.java:203) [rt.jar:1.7.0_75]
    at javax.naming.InitialContext.lookup(InitialContext.java:411) [rt.jar:1.7.0_75]
    at javax.management.remote.rmi.RMIConnector.findRMIServerJNDI(RMIConnector.java:1929) [rt.jar:1.7.0_75]
    at javax.management.remote.rmi.RMIConnector.findRMIServer(RMIConnector.java:1896) [rt.jar:1.7.0_75]
    at javax.management.remote.rmi.RMIConnector.connect(RMIConnector.java:286) [rt.jar:1.7.0_75]
    ... 13 more
2

any message right after the message from 15:22 ? The event is still actively processed by the multiline filter. It can not detect multiline being over without seen the next log line starting with a timestamp. By default multiline filter has a timeout of 5 seconds. That is, latest on timeout or after timeout the event should be pushed.

P.S.: Please format logs and config files with </> button or three back-ticks to make your post more readable.

3

Steffen,

Thanks for the reply and the tip on formatting the messages. Are you suggesting that I increase that value to more than the default of 5 seconds? There were several messages after the 15:22 message that are withing the 5 second time period.

4

the messages after the multiline one have been send? You have a more complete log for testing?

5

Steffen,

Yes, I have a more complete log for testing. Can you direct me to documentation on how to send the file. When I tried to upload one before it complained about the file type.

6

Steffen,

I have found the problem, but not the solution. The problem is in the line pattern: '^[[:space:]]+|^Caused by:'. When I remove the Caused by: following the pipe, it will add the "\n\tat " lines to the error message and will create a separate entry for the Caused by: entries.

I have tried several different options to add the additional pattern to the string, and even tried two separate pattern entries, but none of my attempts have worked. Any suggestions?

7

Steffen,

I found the option of using Multiline as an array, so I tried that. The configuration I am using is

  multiline:
    patterns:
      -
        pattern: '^[[:space:]]+'
        negate: false
        match: after
      -
        pattern: '^Caused by:'
        negate: false
        match: after

But this is giving me the error of "ERR Stop Harvesting. Unexpected encoding line reader error: unknown matcher type:"

Is this not supported in Filebeat v 1,3?

8

The multi-pattern-multiline feature is not implemented in any beat. It has been discussed early on, but not being implemented. I think the implementation originally intended would not be usable the way you expect here, though.

The pattern works for me: https://play.golang.org/p/4DJ8Nlqvq4
But mileage might vary, as I copied logs from your post.

Here is a multiline test by some community member: https://github.com/hartfordfive/filebeat-multiline-tester

The Caused by: should be no problem. I wonder about when/how the next log line after a stack trace is printed. Sometimes buffering in application logger (not writing content to file) can block the multiline matcher.

9

Steffen,

Here is the abbreviated log file that I am using in my local testing along with the yml file.

Gary D Keller
GE Healthcare, consultant

Office: 262-548-2470 (42470)
Cell: 262-497-6264

10

Steffen,

I found my problem in the filebeat config. I was trying to bypass blank log file lines and it was causing it to discard the complete multiline message. I deleted the exclude_lines: ["^$"] statement and am now able to correctly record the multiline message in the elasticsearch index. I found this out by using the -d "*" option while running filebeat with my abbreviated test file.

Will have to experiment with how to bypass blank lines in my testing.

Thanks for all of your help.