Multiline Java stack trace...yes another one

Elastic Stack Beats
1

I have combed through the similar questions but the few with solutions have not applied to my case.

This log file contains both single line and multiple lines. All lines start with the same label. My grok expression on the logstash side has been verified. The multilne pattern is taken directly from the ELK documentation since it seems to directly apply to my java log file syntax. This was also tested using the GO playground.

Here is a sample from the log file:

TID: [-1234] [] [2019-04-09 22:18:40,097] ERROR {org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator} -  Exception in Authentication Framework
org.wso2.carbon.identity.application.authentication.framework.exception.FrameworkException: Invalid authentication request. Session data key : 00ce861b-b525-49a3-93f5-04e7ceddba40
        at org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator.handle(DefaultRequestCoordinator.java:101)
        at org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doPost(CommonAuthenticationServlet.java:53)
        at org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doGet(CommonAuthenticationServlet.java:43)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.eclipse.equinox.http.helper.ContextPathServletAdaptor.service(ContextPathServletAdaptor.java:37)
        at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61)

Over on Kibana I can see that logstash is still parsing the single like log entries correctly, however, the multiline entries are showing a _grokparsefailure tag and I am not sure how to troubleshoot further.

Here is my filebeat.yml config:

- type: log

  enabled: true
  paths:
    - /u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log*
  fields_under_root: true
  fields:
    type: carbonlog
  multiline.pattern: '^[[:space:]]'
  multiline.negate: true
  multiline.match: after

Any further help is appreciated as always.

2

From your post I assume you are using output.logstash in your filebeat.yml. For debugging purposes, could you temporarily use output.console or output.file instead and check if the events being generated by Filebeat are parsing your logs as expected?

If they are as expected then we can narrow this down to Logstash configuration. If not, then we can focus more on the Filebeat configuration.

3

You are correct, and I am redirecting the output now. Will reply once I have a sample. Thanks!

4

You were correct, it appears that filebeat itself is not joining the lines as I expected. I am just going to post the first few lines, but they all appear to be the same with a new entry/message for each line.

Original log entry:

TID: [-1234] [] [2019-04-16 14:13:35,799] ERROR {org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator} -  Exception in Authentication Framework
org.wso2.carbon.identity.application.authentication.framework.exception.FrameworkException: Invalid authentication request. Session data key : 189c23cc-3116-4641-bd48-dc4f76ad556a
        at org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator.handle(DefaultRequestCoordinator.java:101)
        at org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doPost(CommonAuthenticationServlet.java:53)
        at org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doGet(CommonAuthenticationServlet.java:43)

And here is how filebeat is parsing them:

{
  "@timestamp": "2019-04-16T19:13:33.464Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.4.2"
  },
  "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log",
  "offset": 103918,
  "message": "TID: [-1234] [] [2019-04-16 14:13:28,132] ERROR {org.wso2.carbon.identity.sso.cas.util.CASSSOUtil} -  org.wso2.carbon.identity.sso.cas.exception.ServiceProviderNotFoundException \nTID: [-1234] [] [2019-04-16 14:13:35,799] ERROR {org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator} -  Exception in Authentication Framework \norg.wso2.carbon.identity.application.authentication.framework.exception.FrameworkException: Invalid authentication request. Session data key : 189c23cc-3116-4641-bd48-dc4f76ad556a",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "type": "carbonlog",
  "host": {
    "name": "ssoprod"
  },
  "beat": {
    "hostname": "ssoprod",
    "version": "6.4.2",
    "name": "ssoprod"
  }
}
{
  "@timestamp": "2019-04-16T19:13:36.465Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.4.2"
  },
  "type": "carbonlog",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "beat": {
    "name": "ssoprod",
    "hostname": "ssoprod",
    "version": "6.4.2"
  },
  "host": {
    "name": "ssoprod"
  },
  "offset": 104478,
  "message": "\tat org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator.handle(DefaultRequestCoordinator.java:101)",
  "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log"
}
{
  "@timestamp": "2019-04-16T19:13:36.465Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.4.2"
  },
  "input": {
    "type": "log"
  },
  "type": "carbonlog",
  "beat": {
    "version": "6.4.2",
    "name": "ssoprod",
    "hostname": "ssoprod"
  },
  "host": {
    "name": "ssoprod"
  },
  "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log",
  "offset": 104634,
  "message": "\tat org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doPost(CommonAuthenticationServlet.java:53)",
  "prospector": {
    "type": "log"
  }
}
{
  "@timestamp": "2019-04-16T19:13:36.465Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.4.2"
  },
  "input": {
    "type": "log"
  },
  "type": "carbonlog",
  "beat": {
    "name": "ssoprod",
    "hostname": "ssoprod",
    "version": "6.4.2"
  },
  "host": {
    "name": "ssoprod"
  },
  "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log",
  "offset": 104780,
  "message": "\tat org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doGet(CommonAuthenticationServlet.java:43)",
  "prospector": {
    "type": "log"
  }

See first message for my filebeat.yml configuration. Thank you.

5

I played with your sample log data and filebeat.yml configuration options. You just need to remove the multiline.negate: true setting and let it default to false.

6

I am testing this now, but of course the system won't kick off the error now. Will update as soon as I have confirmed. Really appreciate the assistance.

7

I finally caught one. It is definitely improved, but the multiline event is being parsed into two different events. The first one is here:

{
  "_index": "carbonlog-2019.04.18",
  "_type": "doc",
  "_id": "jqahMWoBZPlQAlNtlnjo",
  "_version": 1,
  "_score": null,
  "_source": {
    "beat": {
      "version": "6.4.2",
      "name": "ssoprod",
      "hostname": "ssoprod"
    },
    "prospector": {
      "type": "log"
    },
    "host": {
      "name": "ssoprod"
    },
    "result": "ERROR",
    "value": " Exception in Authentication Framework ",
    "message": "TID: [-1234] [] [2019-04-18 13:07:10,903] ERROR {org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator} -  Exception in Authentication Framework ",
    "date": "2019-04-18 13:07:10,903",
    "type": "carbonlog",
    "tid": "-1234",
    "offset": 104626,
    "@timestamp": "2019-04-18T18:07:13.558Z",
    "@version": "1",
    "input": {
      "type": "log"
    },
    "tags": [
      "beats_input_codec_plain_applied"
    ],
    "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log",
    "resultsource": "org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator"
  },
  "fields": {
    "@timestamp": [
      "2019-04-18T18:07:13.558Z"
    ]
  },
  "sort": [
    1555610833558
  ]
}

The rest is then parsed into a subsequent event, although this part suffers the _grokparsefailure error.

{
  "_index": "carbonlog-2019.04.18",
  "_type": "doc",
  "_id": "7qahMWoBZPlQAlNtqniW",
  "_version": 1,
  "_score": null,
  "_source": {
    "beat": {
      "version": "6.4.2",
      "name": "ssoprod",
      "hostname": "ssoprod"
    },
    "prospector": {
      "type": "log"
    },
    "host": {
      "name": "ssoprod"
    },
    "message": "org.wso2.carbon.identity.application.authentication.framework.exception.FrameworkException: Invalid authentication request. Session data key : 6fdf99d4-118b-4759-8526-3d77039564e1\n\tat org.wso2.carbon.identity.application.authentication.framework.handler.request.impl.DefaultRequestCoordinator.handle(DefaultRequestCoordinator.java:101)\n\tat org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doPost(CommonAuthenticationServlet.java:53)\n\tat org.wso2.carbon.identity.application.authentication.framework.servlet.CommonAuthenticationServlet.doGet(CommonAuthenticationServlet.java:43)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:620)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:727)\n\tat org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)\n\tat org.wso2.carbon.tomcat.ext.valves.CarbonContextCreatorValve.invoke(CarbonContextCreatorValve.java:57)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)\n\tat org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)\n\tat org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1739)\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1698)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.lang.Thread.run(Thread.java:745)",
    "type": "carbonlog",
    "offset": 104827,
    "@timestamp": "2019-04-18T18:07:13.558Z",
    "@version": "1",
    "input": {
      "type": "log"
    },
    "tags": [
      "beats_input_codec_plain_applied",
      "_grokparsefailure"
    ],
    "source": "/u01/ellucian/EllucianEthosIdentity/repository/logs/wso2carbon.log"
  },
  "fields": {
    "@timestamp": [
      "2019-04-18T18:07:13.558Z"
    ]
  },
  "sort": [
    1555610833558
  ]
}

So filebeat is taking the first line and parsing this as its own even, then the second which does not start with a space and remaining lines into another event with a parse error.

8

I don't believe my regex statement accounts for the first two lines correctly.

9

I finally found "a" solution, although I am sure some regex savant out there will have a better one. So officially my initial regex would work against my single instance of the log event I was testing against, but when parsed against the entire log there were apparently other logs that were confusing it. In my logs case the ultimate solution was to search for any line that DID NOT start with a "T", instead of searching for lines that started with white space. This resolved the parsing error.

I then had to used the following multiline parameters:

multiline.negate: true
multiline.match: after

This seems to have accounted for all variabilities in this particular log.

10

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