Stacktrace filtering in server environments (EAR/WAR) not working

Question

Stacktrace filtering in server environments (EAR/WAR) not working

Lonzak opened this issue 4 years ago · 10 comments

I searched and found your library. It is a great idea to create such a library - highly appreciated. If it didn't already exist, I would have written it :-)
To my question:
I used the following command in the hope that the stacktraces are filtered, however they are not.
log.error(TextUtils.getStacktrace(e, true, "our.package"));

The resulting stacktrace has the exact same number of lines but additionally the deployment path is added, which makes it even more hard to read.

Part of the packages which should be filtered out remain unchanged.
The deployment path is added before each line

The filtering isn't suited for server environments. Or is there some option I am missing?

For example:
(Original)

our.package.CustomTool - Error eating food
com.lib.DigestiveException: Potential stomach upset was detected
	at our.package.util.FoodHacking.washing(FoodHacking.java:391) ~[classes:?]
	at our.package.CustomTool.parseFood(CustomTool.java:307) ~[classes:?]
	at our.package.CustomTool.initTable(CustomTool.java:300) ~[classes:?]
	at our.package.CustomTool.<init>(CustomTool.java:52) ~[classes:?]
	at our.package.CustomToolServlet.doGetOrPost(CustomToolServlet.java:323) ~[classes:?]
	at our.package.CustomToolServlet.doPost(CustomToolServlet.java:261) ~[classes:?]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:523) ~[jboss-servlet-api.jar]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:590) ~[jboss-servlet-api.jar]
	at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74) ~[undertow-servlet.jar!/:.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129) ~[undertow-servlet.jar!/:.Final]
	at our.package.filter.Poison.doFilter(ldskhgoias:59) ~[our.jar:?]
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) ~[spring-web]
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) ~[spring-web]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet.jar!/:.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet.jar!/:.Final]

Mgnt:

our.package.CustomTool - Error eating food
com.lib.DigestiveException: Potential stomach upset was detected
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.util.FoodHacking.washing(FoodHacking.java:391)
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.parseFood(CustomTool.java:307)
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.initTable(CustomTool.java:300)
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.<init>(CustomTool.java:52)
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomToolServlet.doGetOrPost(CustomToolServlet.java:323)
	at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomToolServlet.doPost(CustomToolServlet.java:261)
	at javax.servlet.api@.Final//javax.servlet.http.HttpServlet.service(HttpServlet.java:523)
	at javax.servlet.api@.Final//javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
	at io.undertow.servlet@.Final//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
	at io.undertow.servlet@.Final//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
	at deployment.our-1.0.0.ear//our.package.filter.Poison.doFilter(ldskhgoias:59)
	at deployment.our-1.0.0.ear//org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
	at deployment.our-1.0.0.ear//org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
	at io.undertow.servlet@.Final//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet@.Final//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)

Answer 1 · 2021-02-19T00:59:16.000Z

Hello.
First of all, thank you so much for such kind words about the library, And of course for using it.
Now to your problem. First, please let me know which version of the library are you using? What is your java version? What logging framework are you using (Native Java logging, Log4J, Logback or anything else?), What server do you use to run your EAR/WAR files, also what do you use to build your EAR/WAR files?
I assume you already know, but if you don't the source code of the library is available here on the Github, so you can debug the library code in your project as well.
Now, the good news, I already know what causes the feature not to behave as expected. However (the bad news), I do not know why that cause came to be. Anyway, all the methods getStacktrace may or may not remove some lines from the original stacktrace, but they never modify any of the lines. So here is the problem - since the lines of the stacktrace are not modified, it means that the prefix "deployment.our-1.0.0.ear.foodlocker-service.war//" is part of the original stacktrace. You can try and
run the code with TextUtils.getStacktrace(e, false) which does not modify or filter stacktrace at all, and I am sure that you will see it with the prefix "deployment.our-1.0.0.ear.foodlocker-service.war//". That begs the question - how did you print out your original stacktrace that doesn't contain that weird prefix? May be whatever framework printed it filtered those prefixes out? BTW, I have never seen stacktrace with such prefixes, it is very weird.
So, here is the cause of the problem: when method filters the stacktrace it looks for the string that starts with "at [relevantPackage]" in your case "at our.package" as a trigger to start filtering. So since it somehow gets the lines "at deployment.our-1.0.0.ear.foodlocker-service.war//our.package..." it never finds the match and thus does not filter.

Now here some results of my testing: BTW if you use MgntUtils 1.5.0.3 or higher than you can filter that stacktrace from exception or as an input string. See the method public static java.lang.String getStacktrace(java.lang.CharSequence stacktrace,
java.lang.String relevantPackage) - http://michaelgantman.github.io/Mgnt/docs/com/mgnt/utils/TextUtils.html#getStacktrace-java.lang.CharSequence-java.lang.String-

So I took your original stacktrace as a String and ran the following code:

System.out.println(TextUtils.getStacktrace(stacktrace, "our.package"));
Not surprisingly, I got the desired output:

com.lib.DigestiveException: Potential stomach upset was detected
at our.package.util.FoodHacking.washing(FoodHacking.java:391) ~[classes:?]
at our.package.CustomTool.parseFood(CustomTool.java:307) ~[classes:?]
at our.package.CustomTool.initTable(CustomTool.java:300) ~[classes:?]
at our.package.CustomTool.(CustomTool.java:52) ~[classes:?]
at our.package.CustomToolServlet.doGetOrPost(CustomToolServlet.java:323) ~[classes:?]
at our.package.CustomToolServlet.doPost(CustomToolServlet.java:261) ~[classes:?]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:523) ~[jboss-servlet-api.jar]
...
at our.package.filter.Poison.doFilter(ldskhgoias:59) ~[our.jar:?]
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) ~[spring-web]
...

Then, I took your problematic stacktrace and when I ran the same code I got it the same as the input - unmodified. But when I changed my code to:

System.out.println(TextUtils.getStacktrace(wierdStacktrace, "deployment.our-1.0.0.ear.foodlocker-service.war//our.package"));
I got this output:

com.lib.DigestiveException: Potential stomach upset was detected
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.util.FoodHacking.washing(FoodHacking.java:391)
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.parseFood(CustomTool.java:307)
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.initTable(CustomTool.java:300)
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomTool.(CustomTool.java:52)
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomToolServlet.doGetOrPost(CustomToolServlet.java:323)
at deployment.our-1.0.0.ear.foodlocker-service.war//our.package.CustomToolServlet.doPost(CustomToolServlet.java:261)
at javax.servlet.api@.Final//javax.servlet.http.HttpServlet.service(HttpServlet.java:523)
...

So, at least it demonstrates what causes undesired behavior. In any case, I really would like to help you to resolve this issue. But just a note on the sidelines, I used this feature almost exclusively on the server-run code for more then 10 years (even before I published it as an open-source library) and it always worked for me as well as some others. So, I think we will resolve your issue as well.

Best regards,

Michael Gantman

Answer 2 · 2021-02-19T08:19:40.000Z

Thank you for your extensive answer. It was already late yesterday so I missed out on my environment. So here are the details:

Version used: 1.5.1.2 (should be the latest stable since we just started using it)
Logging is slf4j with a log4j2 implementation (slf4j 1.7.30 and log4j 2.13.3)
Wildfly 18 to run everything
Built war and EAR with the classic Java 1.8.0 (oracle)

The original stacktrace was logged like this (quite standard)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
private static Logger log = LoggerFactory.getLogger(FoodHacking.class);
...
try{
...
}
catch (IOException e) {
  log.error("Something went wrong fetching your food. ", e);
}

I just debugged the server and looked at the stacktrace but there are no such paths part of the stacktrace.

Adding the EAR/WAR path to the filter would have been my next try however since sometimes it is the EAR + WAR path and sometimes it is only the EAR it would only work for one of those. Or is it possible to specify a list of packages?
And the downside is that the version string is part of the path so I would have to change all logging statements for each new version which is quite often (since .RC, SNAPSHOTS etc also count...). Right now I really can't see what is special about my setup.

Answer 3 · 2021-02-19T14:22:54.000Z

Sounds very strange. I worked with similar environments and have never seen stacktrace that includes this path. I usually use it slightly differently though. Try this way:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
private static Logger log = LoggerFactory.getLogger(FoodHacking.class);
...
try{
...
}
catch (IOException e) {
  log.error("Something went wrong fetching your food. {}", TextUtils.getStacktrace(e, true, "our.package."));
}

See if it helps. Also, I would recommend to use method TextUtils.setRelevantPackage("our.package.") somewhere in your setup, and then instead of using TextUtils.getStacktrace(e, true, "our.package.") you can just use TextUtils.getStacktrace(e), which makes it more consize. Try it this way let me know if it helps

Answer 4 · 2021-02-19T14:23:49.000Z

BTW, no you can not set multiple packages for now at least

Answer 5 · 2021-02-22T19:22:50.000Z

Are there any developments?

Answer 6 · 2021-02-22T23:14:04.000Z

I have changed the code to your suggestion but nothing changed.
Also I debugged locally and there it works. So now I tried to debug the server which didn't work however. So I need to consult our admin to find out what's the problem...

Answer 7 · 2021-02-23T00:23:47.000Z

This is just my guess, but I think, that this is how the WildFly reports its staketrace. It might be that it has the root path misconfigured, so it sees your JARs as part of the path. Anyway, I think it is a WildFly configuration issue. (Well, at least you saw that the feature actually works)

Answer 8 · 2021-02-23T00:47:41.000Z

I would check the following config props: user.dir. Actually, may be you need to include folder "deployment" into your path in user.dir (Look at the stacktrace element: deployment.our-1.0.0.ear.foodlocker-service.war//... It sees deployment as part of the package and not as part of the root from which to look for the package path.

Answer 9 · 2021-03-01T10:36:38.000Z

Any new developments on the issue?

Answer 10 · 2021-03-07T18:09:35.000Z

I am closing the issue due to the lack of response. However, if this is still a relevant problem please don't hesitate to contact me, by reopening this issue, opening a new one.