Multiline Java Stack Trace parsing doesn't work

ramokarahasan · April 13, 2020, 2:39pm

I'm reviewing and trying: https://www.elastic.co/guide/en/beats/filebeat/current/multiline-examples.html
and also followed: Filebeat Multiline Java Stack Trace

I've deployed the latest ELK stack and running logfiles -> filebeat -> logstash -> ES -> Kibana

I'm receiving Spring Boot 2.x logs in this format and store them into logfiles.

2020-04-13 14:13:08.895 ERROR 1 --- [   elastic-1228] s.ConnectorConfigServiceExceptionHandler : Exception handled

com.itembase.iws.connector.config.ConnectorConfigNotFoundException: Requested configuration was not found
	at com.itembase.iws.connector.config.webservice.connection.ConnectionEntityService.getByInstanceIdAndUniqueIdentifier(ConnectionEntityService.java:146) ~[classes/:na]
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint â¢ Handler com.itembase.iws.connector.config.webservice.connection.ConnectionRestController#getByInstanceAndUniqueIdentifier(UUID, String) [DispatcherHandler]
Stack trace:
		at com.itembase.iws.connector.config.webservice.connection.ConnectionEntityService.getByInstanceIdAndUniqueIdentifier(ConnectionEntityService.java:146) ~[classes/:na]
		at com.itembase.iws.connector.config.webservice.connection.ConnectionRestController.getByInstanceAndUniqueIdentifier(ConnectionRestController.java:66) ~[classes/:na]
		at jdk.internal.reflect.GeneratedMethodAccessor204.invoke(Unknown Source) ~[na:na]
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
		at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
		at org.springframework.web.reactive.result.method.InvocableHandlerMethod.lambda$invoke$0(InvocableHandlerMethod.java:147) ~[spring-webflux-5.2.4.RELEASE.jar:5.2.4.RELEASE]
		at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1705) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoZip$ZipCoordinator.signal(MonoZip.java:247) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoZip$ZipInner.onNext(MonoZip.java:329) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:173) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:92) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2267) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2075) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1949) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxFlatMap.trySubscribeScalarMap(FluxFlatMap.java:191) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoFlatMap.subscribeOrReturn(MonoFlatMap.java:53) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Mono.subscribe(Mono.java:4095) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoZip.subscribe(MonoZip.java:128) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:153) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:76) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:274) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:851) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:173) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2267) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request(MonoPeekTerminal.java:132) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:162) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2075) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1949) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:90) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe(MonoPeekTerminal.java:145) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Mono.subscribe(Mono.java:4110) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:441) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:211) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:161) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.Mono.subscribe(Mono.java:4110) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:172) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:55) ~[reactor-core-3.3.3.RELEASE.jar:3.3.3.RELEASE]
		at reactor.netty.http.server.HttpServerHandle.onStateChange(HttpServerHandle.java:64) ~[reactor-netty-0.9.5.RELEASE.jar:0.9.5.RELEASE]
		at reactor.netty.tcp.TcpServerBind$ChildObserver.onStateChange(TcpServerBind.java:228) ~[reactor-netty-0.9.5.RELEASE.jar:0.9.5.RELEASE]
		at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:465) ~[reactor-netty-0.9.5.RELEASE.jar:0.9.5.RELEASE]
		at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:90) ~[reactor-netty-0.9.5.RELEASE.jar:0.9.5.RELEASE]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:170) ~[reactor-netty-0.9.5.RELEASE.jar:0.9.5.RELEASE]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321) ~[netty-codec-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:295) ~[netty-codec-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377) ~[netty-transport-4.1.45.Final.jar:4.1.45.Final]


2020-04-13 14:13:08.895 ERROR 1 --- [   elastic-1228] s.ConnectorConfigServiceExceptionHandler : Reported error: status=404, error=Not Found, errorId=b770d910-c8e5-446a-80b7-f88453b34a62, message=Requested configuration was not found

this is my filebeat.yml file

filebeat:
  # List of inputs.
  inputs:
    [{"paths": ["/srv/iws/logs/*/*.log"], "type": "log"}]


  processors:
    - drop_fields:
      fields: ["host"]

      #multiline.pattern: '^\[0-9]{4}-[0-9]{2}-[0-9]{2}'
      #multiline.negate: false
      #multiline.match: after


  multiline.pattern: '^([0-9]{4}-[0-9]{2}-[0-9]{2})'
  multiline.negate: true
  multiline.match: after

  multiline.timeout: 120s #default 5s
  multiline.max_lines: 10000 #default 500

# Configure what outputs to use when sending the data collected by the beat.
# Multiple outputs may be used.
output:


  ### Logstash as output
  logstash:
    # The Logstash hosts
    hosts: ["10.0.106.36:5044"]

    # Number of workers per Logstash host.
    #worker: 1

    # Optional load balance the events between the Logstash hosts
    #loadbalance: true

    # Optional index name. The default index name depends on the each beat.
    # For Packetbeat, the default is set to packetbeat, for Topbeat
    # top topbeat and for Filebeat to filebeat.
    #index: filebeat



logging.level: debug
logging.to_files: true
logging.files:
  path: /var/log/filebeat
  name: debug.log
  keepfiles: 3

with the applied multiline filter I still see a lot of events created in the debug logs where a log of "messages" are created starting with "at" for the specified log posted above.

I'd exped to get the full stacktrace in a single event.

I'd be happy to receive any hint on how that could work out.

ramokarahasan · April 14, 2020, 9:34am

I've followed Filebeat multiline regexp patterns help which uses the following pattern:

multiline.pattern: ^\d\d\d\d-\d\d-\d\d
multiline.negate: true
multiline.match: after

which I'm testing on: https://play.golang.org/p/IZagant7bJN

Which passes. I still see in the logfiles the following

{
  "@timestamp": "2020-04-14T09:24:07.385Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.6.2"
  },
  "host": {
    "name": "iws-02"
  },
  "agent": {
    "hostname": "iws-02",
    "id": "7c3b9efe-6ddb-4fac-99b9-b47855873fd1",
    "version": "7.6.2",
    "type": "filebeat",
    "ephemeral_id": "402e53ea-fb3e-4e82-b90a-519fe7913122"
  },
  "log": {
    "offset": 25105,
    "file": {
      "path": "/srv/iws/logs/iws-connector-config-service/iws-connector-config-webservice.log"
    }
  },
  "message": "2020-04-14 09:23:57.417 ERROR 1 --- [elastic-1358] s.ConnectorConfigServiceExceptionHandler : Exception handled",
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.4.0"
  }
}

{
  "@timestamp": "2020-04-14T09:24:07.386Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.6.2"
  },
  "agent": {
    "hostname": "iws-02",
    "id": "7c3b9efe-6ddb-4fac-99b9-b47855873fd1",
    "version": "7.6.2",
    "type": "filebeat",
    "ephemeral_id": "402e53ea-fb3e-4e82-b90a-519fe7913122"
  },
  "log": {
    "file": {
      "path": "/srv/iws/logs/iws-connector-config-service/iws-connector-config-webservice.log"
    },
    "offset": 25218
  },
  "message": "com.itembase.iws.connector.config.ConnectorConfigNotFoundException: Requested configuration was not found",
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.4.0"
  },
  "host": {
    "name": "iws-02"
  }
}


{
  "@timestamp": "2020-04-14T09:24:07.386Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.6.2"
  },
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.4.0"
  },
  "host": {
    "name": "iws-02"
  },
  "agent": {
    "hostname": "iws-02",
    "id": "7c3b9efe-6ddb-4fac-99b9-b47855873fd1",
    "version": "7.6.2",
    "type": "filebeat",
    "ephemeral_id": "402e53ea-fb3e-4e82-b90a-519fe7913122"
  },
  "log": {
    "offset": 25324,
    "file": {
      "path": "/srv/iws/logs/iws-connector-config-service/iws-connector-config-webservice.log"
    }
  },
  "message": "\tat com.itembase.iws.connector.config.webservice.connection.ConnectionEntityService.getById(ConnectionEntityService.java:80) ~[classes/:na]"
}

...

So it's still not aggregated in one message but splitted across a lot of events.

I really don't understand what's wrong here.

Christian_Dahlqvist · April 14, 2020, 9:47am

I believe your multiline config should be nested under filebeat.inputs rather than directly under filebeat.

ramokarahasan · April 14, 2020, 10:00am

@Christian_Dahlqvist

I thought it is already under the inputs section. I see that vi is indenting the multiline blcok when i add a comment. However, I've changed it to:

filebeat:
  # List of inputs.
  inputs:
    [{"paths": ["/srv/iws/logs/*/*.log"], "type": "log"}]

  processors:
    - drop_fields:
      fields: ["host"]

      #multiline.pattern: '^\[0-9]{4}-[0-9]{2}-[0-9]{2}'
      #multiline.negate: false
      #multiline.match: after


      #multiline.pattern: '^[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2},[[:digit:]]{3}'
      #multiline.negate: true
      #multiline.match: after

      #multiline.timeout: 120s #default 5s

   #multiline.max_lines: 10000 #default 500


filebeat.inputs:
  multiline.pattern: '^\d\d\d\d-\d\d-\d\d'
  multiline.negate: true
  multiline.match: after

  multiline.timeout: 120s #default 5s
  multiline.max_lines: 10000 #default 500
# Configure what outputs to use when sending the data collected by the beat.
# Multiple outputs may be used.

output.file:
  path: "/var/log/filebeat"
  filename: debug_file

The provided configuration still produced multiple events into the debug file.

ramokarahasan · April 15, 2020, 6:08am

Thanks,

this worked out.

The only issue right now is, that I'm not receiving any ERROR logs into Kibana but just INFO. Filebeat dumps the error events into my debug file.

I'll close this topic.

system · May 13, 2020, 6:14am

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