Merge Multiline Java Stack trace via syslog

[michaelhobbs]

I'm having a heck of a time figuring out the best way to get splunk to show these multiline events in one event. Any help would be appreciated.

Each event is broken up by the line that looks like this:

2011-03-22 18:43:58 -04:00 info critical_en8.web: 22 Mar 2011 18:43:58,906 [ERROR] [crm] [Misc] misc

OR

2011-03-22 18:44:00 -04:00 info critical_en8.web: 22 Mar 2011 18:44:00,061 [ERROR] [crm] [Misc] misc

Example log:

2011-03-22 18:43:58 -04:00 info critical_en8.web: 22 Mar 2011 18:43:58,906 [ERROR] [crm] [Misc] misc
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm] javax.servlet.ServletException: 
com.infusion.util.db.LoadingException: Couldn't find the record with primary key 0 in Contact
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.PageContextImpl.doHandlePageException(PageContextImpl.java:862)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.PageContextImpl.handlePageException(PageContextImpl.java:791)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jsp.Contact.tab.address_jsp._jspService(address_jsp.java:130)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:377)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm] Caused by: com.infusion.util.db.LoadingException: Couldn't find the record with primary key 0 in Contact
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at com.infusion.crm.db.DatabaseObject.loadFromDatabase(DatabaseObject.java:1700)
2011-03-22 18:43:58 -04:00 info critical_en8.web: [ERROR] [crm]         at com.infusion.crm.db.DatabaseObject.loadFromDatabase(DatabaseObject.java:1675)
2011-03-22 18:44:00 -04:00 info critical_en8.web: 22 Mar 2011 18:44:00,061 [ERROR] [crm] [Misc] misc
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm] javax.servlet.ServletException: com.infusion.util.db.LoadingException: No primary key defined to load Contact
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.PageContextImpl.doHandlePageException(PageContextImpl.java:862)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.PageContextImpl.handlePageException(PageContextImpl.java:791)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jsp.Contact.tab.filebox_jsp._jspService(filebox_jsp.java:281)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:377)
2011-03-22 18:44:00 -04:00 info critical_en8.web: [ERROR] [crm]         at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)

[gkanapathy]

I would simply use:

[java_over_syslog]
SHOULD_LINEMERGE = false
TRUNCATE = 9999999
LINE_BREAKER = ([\r\n]+)(?=(\S+\s*){5}\:\d{1,2}\s+\w\s+\d{4}\s+\d{1,2}:\d{2}:\d{2},\d{4}\D)
TIME_PREFIX = ^(\S+\s*){5}\:\s+
TIME_FORMAT = %d %b %Y %H:%M:%S,%3N

Which pretty much means, "break when you see the next line has the base syslog headers (which are 5 "words") followed by something that looks like the Java timestamp".

This is what I'd do with non-syslog Java as well, except that you have to account for the forced syslog timestamp before the java timestamp. I've taken the liberty of setting the time via the Java timestamp, since it is more likely to be correct and it has milliseconds.

[michaelhobbs]

Actually this might be ok. Splunk is combining separate events into one but they are the same error just happening in succession. It does seem to be splitting everything else. Thanks for the help!

[michaelhobbs]

This did not:
2011-03-24 13:12:52 -04:00 info critical_ft3both.web: 24 Mar 2011 13:12:52,854 [ERROR] [valueone] [Database] database
2011-03-24 13:12:52 -04:00 info critical_ft3both.web: [ERROR] [valueone] com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Unknown database 'valueone'
2011-03-24 13:12:52 -04:00 info critical_ft3both.web: 24 Mar 2011 13:12:52,855 [ERROR] [valueone] [Database] database
2011-03-24 13:12:52 -04:00 info critical_ft3both.web: [ERROR] [valueone] at com.infusion.databridge.DatabridgeConnectionImpl.prepareForRetry(DatabridgeConnectionImpl.java:726)

[michaelhobbs]

This worked:
2011-03-24 13:12:54 -04:00 info critical_mn31.web: 24 Mar 2011 13:12:54,904 [ERROR] [iu] [User] Could not load user with Id: 2
2011-03-24 13:12:54 -04:00 info critical_mn31.web:Caused by: java.lang.Exception: Couldn't find the record with primary key 2 in User
2011-03-24 13:12:54 -04:00 info critical_mn31.web: [ERROR] [iu] at com.infusion.crm.db.DatabaseObject.loadFromDatabase(DatabaseObject.java:1697)
2011-03-24 13:12:54 -04:00 info critical_mn31.web: [ERROR] [iu] ... 64 more

[michaelhobbs]

This seems to get close. However, now it's combining some events into one that should not.

[gkanapathy]

Although what I'd really use is a Splunk forwarder instead of syslog. In addition to the advantages dwaddle cites, you will also be able to tell apart different files using a forwarder, which isn't that easy with syslog, since everything gets merged into a single stream and may even have multiple files interleaved.

[dwaddle]

My first thought is "can you use a forwarder instead of syslog?"

You may be able to get syslog to work, but Splunk has a default setting in props.conf of "BREAK_ONLY_BEFORE_DATE=true". Meaning that, on most inputs, the datestamp on each line will make it treat each line as a new event and not merge them.

You can reconfigure to avoid this, but it may be easier in the long run to configure a forwarder reading this log file directly. Forwarders also have an advantage over syslog-via-UDP in that TCP is more reliable in the event of packet loss.