Skip to content

Add correct exception logging in the ExecutorUtil#2384

Merged
HoustonPutman merged 1 commit intoapache:mainfrom
HoustonPutman:better-logging
Apr 16, 2024
Merged

Add correct exception logging in the ExecutorUtil#2384
HoustonPutman merged 1 commit intoapache:mainfrom
HoustonPutman:better-logging

Conversation

@HoustonPutman
Copy link
Contributor

This actually logs the correct stack trace for an exception caught in the ExecutorUtil.

It also provides the correct ordering of "causes" unlike the way it was previously implemented, where the "cause" was actually the thread that called the Executor. Now the "cause" is the error in the executor, and the base exception is the thread that called the ExecutorUtil.

It may look strange that we always use an Exception class, but this is ok since these exceptions that we are copying are only made a few lines up and are always of class Exception. (They aren't real exceptions, they are merely storing the stackTrace of how the original thread called the Executor, or the tree of executor calls). Therefore, no information is being lost here.

@HoustonPutman
Copy link
Contributor Author

An example of how this would fix exception logging:

Existing implementation:

2024-04-01 21:01:38.810 ERROR (coreZkRegister-1-thread-1-processing-172.17.0.2:8983_solr test_shard1_replica_n1 test shard1 core_node2) [c: s: r: x: t:] o.a.s.c.u.ExecutorUtil Uncaught exception java.lang.StackOverflowError thrown by thread: coreZkRegister-1-thread-1-processing-172.17.0.2:8983_solr test_shard1_replica_n1 test shard1 core_node2 => java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279)
java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279) ~[?:?]
	at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:240) ~[?:?]
	at org.apache.solr.core.CoreContainer.lambda$loadInternal$12(CoreContainer.java:1067) ~[?:?]
	at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:212) ~[metrics-core-4.2.25.jar:4.2.25]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source) ~[?:?]
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:312) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279) ~[?:?]
	at java.base/java.util.concurrent.AbstractExecutorService.submit(Unknown Source) ~[?:?]
	at com.codahale.metrics.InstrumentedExecutorService.submit(InstrumentedExecutorService.java:104) ~[metrics-core-4.2.25.jar:4.2.25]
	at org.apache.solr.core.CoreContainer.loadInternal(CoreContainer.java:1046) ~[?:?]
	at org.apache.solr.core.CoreContainer.load(CoreContainer.java:760) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.createCoreContainer(CoreContainerProvider.java:427) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.init(CoreContainerProvider.java:246) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.contextInitialized(CoreContainerProvider.java:116) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1049) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:984) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1304) ~[jetty-webapp-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:901) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:532) ~[jetty-webapp-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:121) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:121) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.doStart(GzipHandler.java:221) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.Server.start(Server.java:470) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.Server.doStart(Server.java:415) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1919) ~[jetty-xml-10.0.20.jar:10.0.20]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
	at org.eclipse.jetty.start.Main.invokeMain(Main.java:229) ~[start.jar:10.0.20]
	at org.eclipse.jetty.start.Main.start(Main.java:528) ~[start.jar:10.0.20]
	at org.eclipse.jetty.start.Main.main(Main.java:76) ~[start.jar:10.0.20]

Fix:

2024-04-01 21:07:29.848 ERROR (coreZkRegister-1-thread-1-processing-172.17.0.2:8983_solr test_shard1_replica_n1 test shard1 core_node2) [c: s: r: x: t:] o.a.s.c.u.ExecutorUtil Uncaught exception java.lang.StackOverflowError thrown by thread: coreZkRegister-1-thread-1-processing-172.17.0.2:8983_solr test_shard1_replica_n1 test shard1 core_node2 => java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279)
java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279) ~[?:?]
	at java.base/java.util.concurrent.AbstractExecutorService.submit(Unknown Source) ~[?:?]
	at com.codahale.metrics.InstrumentedExecutorService.submit(InstrumentedExecutorService.java:104) ~[metrics-core-4.2.25.jar:4.2.25]
	at org.apache.solr.core.CoreContainer.loadInternal(CoreContainer.java:1046) ~[?:?]
	at org.apache.solr.core.CoreContainer.load(CoreContainer.java:760) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.createCoreContainer(CoreContainerProvider.java:427) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.init(CoreContainerProvider.java:246) ~[?:?]
	at org.apache.solr.servlet.CoreContainerProvider.contextInitialized(CoreContainerProvider.java:116) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1049) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:984) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1304) ~[jetty-webapp-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:901) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306) ~[jetty-servlet-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:532) ~[jetty-webapp-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:121) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:121) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.doStart(GzipHandler.java:221) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.Server.start(Server.java:470) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.server.Server.doStart(Server.java:415) ~[jetty-server-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) ~[jetty-util-10.0.20.jar:10.0.20]
	at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1919) ~[jetty-xml-10.0.20.jar:10.0.20]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
	at org.eclipse.jetty.start.Main.invokeMain(Main.java:229) ~[start.jar:10.0.20]
	at org.eclipse.jetty.start.Main.start(Main.java:528) ~[start.jar:10.0.20]
	at org.eclipse.jetty.start.Main.main(Main.java:76) ~[start.jar:10.0.20]
Caused by: java.lang.Exception: Submitter stack trace
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.execute(ExecutorUtil.java:279) ~[?:?]
	at org.apache.solr.core.ZkContainer.registerInZk(ZkContainer.java:240) ~[?:?]
	at org.apache.solr.core.CoreContainer.lambda$loadInternal$12(CoreContainer.java:1067) ~[?:?]
	at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:212) ~[metrics-core-4.2.25.jar:4.2.25]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source) ~[?:?]
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:312) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: java.lang.StackOverflowError
	at org.apache.solr.core.ZkContainer.lambda$registerInZk$1(ZkContainer.java:213) ~[?:?]
	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:312) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) ~[?:?]

Notice how the cause-submitter-stacktrace ordering is now correct, and that the downstream error is actually being reported as the ultimate cause. This will also work even if the error/exception has its own causes.

@HoustonPutman HoustonPutman requested a review from madrob April 1, 2024 22:38
@madrob
Copy link
Contributor

madrob commented Apr 1, 2024

This took me a bit of experimenting with locally, but I understand what's going on now and agree that the new ordering is correct. Thanks for cleaning this up @HoustonPutman!

if (t instanceof OutOfMemoryError) {
throw t;
}
if (enableSubmitterStackTrace) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't we still need to have this flag?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't believe so. So the baseCause, which is now always logged, will be t (the real throwable) if submitterStackTrace is null. Since when enableSumbitterStackTrace==false then submitterStackTrace=null (logic from above), then we will only be logging t if enableSubmitterStackTrace==false. The submitterStackTraces will only be included if enableSubmitterStackTrace==true.

It is still a little different than the previous logic, which only logged the error message, but I think the spirit of the flag is still the same.

@HoustonPutman HoustonPutman merged commit 07606c7 into apache:main Apr 16, 2024
@HoustonPutman HoustonPutman deleted the better-logging branch April 16, 2024 14:16
HoustonPutman added a commit that referenced this pull request Apr 16, 2024
tboeghk pushed a commit to otto-de/solr that referenced this pull request Feb 18, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants