Bug 63879 - Unessesary log noise under DEBUG
Summary: Unessesary log noise under DEBUG
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Util (show other bugs)
Version: 9.0.21
Hardware: Macintosh All
: P2 trivial (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-10-24 14:42 UTC by Michael Bazos
Modified: 2019-10-29 08:33 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Bazos 2019-10-24 14:42:36 UTC
Introduced in tomcat 9.0.21 there was a log DEBUG message introduced in org.apache.tomcat.util.net.NioEndpoint.NioSocketWrapper#doClose

```
        @Override
        protected void doClose() {
            if (log.isDebugEnabled()) {
                log.debug("Calling [" + getEndpoint() + "].closeSocket([" + this + "])", new Exception());
            }
```

Adding log message with the exception like this causes noise to clients and could be alarming here is a sample output from the clients perspective: 

[10-24-19 10:29:44.066] [http-nio-8080-exec-8] DEBUG  o.a.tomcat.util.net.NioEndpoint - Calling [org.apache.tomcat.util.net.NioEndpoint@7073a1db].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5e5a7392:org.apache.tomcat.util.net.NioChannel@5fa6a12b:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8080 remote=/0:0:0:0:0:0:0:1:57802]])
java.lang.Exception: null
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose(NioEndpoint.java:1163) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at org.apache.tomcat.util.net.SocketWrapperBase.close(SocketWrapperBase.java:402) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:665) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1582) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.27.jar:9.0.27]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

I think it would be best to remove the Exception from the debug statement or if the stack trace is needed to output this in a better manner.
Comment 1 Christopher Schultz 2019-10-24 14:55:15 UTC
Looks like leftover debugging code. Should be changed to TRACE at the very least. Rémy, do you think this log message even needs to stay in there?
Comment 2 Michael Bazos 2019-10-24 15:19:51 UTC
TRACE would be okay as I feel most people wouldn't need that but I think it could be left at DEBUG probably just want to not add the Exception?
Comment 3 Steve Sanders 2019-10-26 13:43:53 UTC
Ive submitted a patch for this: https://github.com/apache/tomcat/pull/220
Comment 4 Remy Maucherat 2019-10-27 21:01:02 UTC
The stack trace is used to know what called close (obviously). This is the same in the NIO 2 connector. This might be a little bit too much (= not that useful) and I will likely remove them, but I don't see why you are enabling debug logging and complain about it as this logging level is very verbose on the endpoints. HTTP/2 has similar verbosity on debug logging BTW.
Comment 5 Christopher Schultz 2019-10-28 12:59:33 UTC
I think switching the log message to TRACE is the best solution.
Comment 6 Michael Bazos 2019-10-28 13:54:01 UTC
I agree switching to TRACE is the best option. Also it might be helpful to not throw new Exception(); as this produces this message "java.lang.Exception: null" If you are going to have this it might be best to provide a message to let people know this is intended and testing.

This issue came up as it was forwarded to me by another team at my company and my response was it's fine it's `DEBUG` but I also feel seeing a stack trace like this can clue to some potential issue happening or maybe something not being done in an optimal way. 

Either way I think checking the rest of the code base in NIO and NIO2 for this pattern and switching the statements to TRACE at a minimum should be fine.
Comment 7 Michael Bazos 2019-10-28 13:54:01 UTC
I agree switching to TRACE is the best option. Also it might be helpful to not throw new Exception(); as this produces this message "java.lang.Exception: null" If you are going to have this it might be best to provide a message to let people know this is intended and testing.

This issue came up as it was forwarded to me by another team at my company and my response was it's fine it's `DEBUG` but I also feel seeing a stack trace like this can clue to some potential issue happening or maybe something not being done in an optimal way. 

Either way I think checking the rest of the code base in NIO and NIO2 for this pattern and switching the statements to TRACE at a minimum should be fine.
Comment 8 Christopher Schultz 2019-10-28 14:01:16 UTC
(In reply to Michael Bazos from comment #6)
> I agree switching to TRACE is the best option. Also it might be helpful to
> not throw new Exception()

Note that the exception is not thrown, only constructed. Yes, this requires the runtime to walk the the stack to produce the stack trace (Which is precisely why it's being done at all) but we don't incur the penalty of actually throwing the exception.

> this produces this message
> "java.lang.Exception: null" If you are going to have this it might be best
> to provide a message to let people know this is intended and testing.

+1 to adding a message e.g. new Exception("Intentional stack trace")
Comment 9 Steve Sanders 2019-10-28 23:51:13 UTC
(In reply to Christopher Schultz from comment #8)
> (In reply to Michael Bazos from comment #6)
> > I agree switching to TRACE is the best option. Also it might be helpful to
> > not throw new Exception()
> 
> Note that the exception is not thrown, only constructed. Yes, this requires
> the runtime to walk the the stack to produce the stack trace (Which is
> precisely why it's being done at all) but we don't incur the penalty of
> actually throwing the exception.
> 
> > this produces this message
> > "java.lang.Exception: null" If you are going to have this it might be best
> > to provide a message to let people know this is intended and testing.
> 
> +1 to adding a message e.g. new Exception("Intentional stack trace")

Good idea! I've updated my patch to use isTraceEnabled, and added the exception message.
Comment 10 Remy Maucherat 2019-10-29 08:33:07 UTC
I removed the stack trace but kept the debug log, as I didn't see much use to the stack trace. This was added in NIO2 when I was looking at how close was called (NIO2 being mostly async), and it's not generally useful but it was added when I did the doClose refactoring.

This will be in 9.0.28.