search

ome / omero-blitz

Gradle project containing Ice remoting code for OMERO
https://www.openmicroscopy.org/omero
GNU General Public License v2.0
0 stars 15 forks source link

Have async helper log stack traces. #98

Closed mtbc closed 3 years ago

mtbc commented 4 years ago

Makes it more likely that async cmd instances will log more about failures. Many just log a Throwable.toString() among the String.format arguments which does not include the stack trace.

mtbc commented 4 years ago

omero delete Image:0 is an easy test.

joshmoore commented 4 years ago

Before and after both print

omero.cmd.Delete2 Image:0 failed: 'graph-fail'
failed: cannot read ome.model.core.Image[0]

on the CLI. I'm failing to see an updated log message though... perhaps minimally we could include the Excp: string as with the regular method handler?

mtbc commented 4 years ago

You looked in Blitz-0.log? It appeared for me. :confused:

joshmoore commented 4 years ago

Can you give me an example?

mtbc commented 4 years ago

Without this PR,

2020-08-28 14:49:21,770 INFO  [     omero.cmd.graphs.Delete2I.@1e08e6b9] (1-thread-4) Cancelled
2020-08-28 14:49:21,770 INFO  [                 org.perf4j.TimingLogger] (1-thread-4) start[1598622561666] time[104] tag[omero.request.step.0]
2020-08-28 14:49:21,770 INFO  [                 org.perf4j.TimingLogger] (1-thread-4) start[1598622561654] time[116] tag[omero.request]
2020-08-28 14:49:21,771 INFO  [                 org.perf4j.TimingLogger] (1-thread-4) start[1598622561634] time[137] tag[omero.call.exception]
2020-08-28 14:49:21,771 INFO  [        ome.services.util.ServiceHandler] (1-thread-4)  Excp:    omero.cmd.HandleI$Cancel: graph-fail
2020-08-28 14:49:21,772 DEBUG [     omero.cmd.graphs.Delete2I.@1e08e6b9] (1-thread-4) Request cancelled by ome.services.graphs.GraphException(message=cannot read ome.model.core.Image[0])
2020-08-28 14:49:21,772 INFO  [                 org.perf4j.TimingLogger] (1-thread-4) start[1598622561633] time[138] tag[omero.request.tx]
2020-08-28 14:49:21,772 INFO  [     omero.cmd.graphs.Delete2I.@1e08e6b9] (1-thread-4) notify cancelled: omero.cmd.GraphException@1fdd4068/omero.cmd.Status@736dc541

With this PR,

2020-08-28 14:56:41,701 INFO  [     omero.cmd.graphs.Delete2I.@11a7fb52] (1-thread-5) Cancelled
2020-08-28 14:56:41,701 INFO  [                 org.perf4j.TimingLogger] (1-thread-5) start[1598623001584] time[117] tag[omero.request.step.0]
2020-08-28 14:56:41,701 INFO  [                 org.perf4j.TimingLogger] (1-thread-5) start[1598623001573] time[128] tag[omero.request]
2020-08-28 14:56:41,702 INFO  [                 org.perf4j.TimingLogger] (1-thread-5) start[1598623001554] time[147] tag[omero.call.exception]
2020-08-28 14:56:41,702 INFO  [        ome.services.util.ServiceHandler] (1-thread-5)  Excp:    omero.cmd.HandleI$Cancel: graph-fail
2020-08-28 14:56:41,705 DEBUG [     omero.cmd.graphs.Delete2I.@11a7fb52] (1-thread-5) Request cancelled by ome.services.graphs.GraphException(message=cannot read ome.model.core.Image[0])
ome.services.graphs.GraphException: null
    at ome.services.graphs.GraphTraversal.getDetails(GraphTraversal.java:1089) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at ome.services.graphs.GraphTraversal.reviewObject(GraphTraversal.java:1124) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at ome.services.graphs.GraphTraversal.planOperation(GraphTraversal.java:617) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at ome.services.graphs.GraphTraversal.planOperation(GraphTraversal.java:523) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at omero.cmd.graphs.Delete2I.step(Delete2I.java:154) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at omero.cmd.HandleI.steps(HandleI.java:448) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at omero.cmd.HandleI$RunSteps.innerWork(HandleI.java:509) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at omero.cmd.HandleI$2.doWork(HandleI.java:383) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at omero.cmd.HandleI$2.doWork(HandleI.java:380) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at sun.reflect.GeneratedMethodAccessor293.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_265]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_265]
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop.jar:4.3.14.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop.jar:4.3.14.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop.jar:4.3.14.RELEASE]
    at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:568) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:119) ~[spring-orm.jar:4.3.14.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx.jar:4.3.14.RELEASE]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282) ~[spring-tx.jar:4.3.14.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx.jar:4.3.14.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop.jar:4.3.14.RELEASE]
    at com.sun.proxy.$Proxy81.doWork(Unknown Source) ~[na:na]
    at ome.services.util.Executor$Impl.execute(Executor.java:447) ~[omero-server.jar:5.6.1-SNAPSHOT]
    at omero.cmd.HandleI.run(HandleI.java:379) ~[omero-blitz.jar:5.5.8-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_265]
    at ome.services.util.Executor$Impl$1.call(Executor.java:488) [omero-server.jar:5.6.1-SNAPSHOT]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_265]
2020-08-28 14:56:41,706 INFO  [                 org.perf4j.TimingLogger] (1-thread-5) start[1598623001553] time[152] tag[omero.request.tx]
2020-08-28 14:56:41,706 INFO  [     omero.cmd.graphs.Delete2I.@11a7fb52] (1-thread-5) notify cancelled: omero.cmd.GraphException@2dd2e27d/omero.cmd.Status@43a9d378
mtbc commented 4 years ago

Ha, sorry, I seem to have <logger name="omero.cmd.graphs" level="DEBUG"/> set, not sure what other easy ways there are to get that code path exercised, e.g., causing something at INFO or WARN!

joshmoore commented 4 years ago

Gotcha :+1:

2020-08-28 14:01:37,386 INFO  [        ome.services.util.ServiceHandler] (1-thread-1)  Excp:    omero.cmd.HandleI$Cancel: graph-fail
2020-08-28 14:01:37,388 DEBUG [     omero.cmd.graphs.Delete2I.@7d935471] (1-thread-1) Request cancelled by ome.services.graphs.GraphException(message=cannot read ome.model.core.Image[0])
ome.services.graphs.GraphException: null
        at ome.services.graphs.GraphTraversal.getDetails(GraphTraversal.java:1089) ~[omero-server.jar:5.6.1-SNAPSHOT]
        at ome.services.graphs.GraphTraversal.reviewObject(GraphTraversal.java:1124) ~[omero-server.jar:5.6.1-SNAPSHOT]
        at ome.services.graphs.GraphTraversal.planOperation(GraphTraversal.java:617) ~[omero-server.jar:5.6.1-SNAPSHOT]
        at ome.services.graphs.GraphTraversal.planOperation(GraphTraversal.java:523) ~[omero-server.jar:5.6.1-SNAPSHOT]

Certainly no objection to the additional context. The fact that it needs additional logging setting isn't ideal. It might only be a half-way house but I could imagine serializing some or all of the Throwable from https://github.com/ome/omero-blitz/blob/master/src/main/java/omero/cmd/Helper.java#L306 into the Cancel instance if that would help. If that's more trouble than it's worth, good to go.

P.S. unrelated to this PR, but I did find myself struggling to find Image[0] rather than Image:0

joshmoore commented 4 years ago

not sure what other easy ways there are to get that code path exercised, e.g., causing something at INFO or WARN!

For reference, the DEBUG statement comes from https://github.com/ome/omero-blitz/blob/8dc4e29e80a36efa3b0499c3b49410b2817ed811/src/main/java/omero/cmd/HandleI.java#L395

mtbc commented 4 years ago

Hmmm, thank you for tracking that down, should we bump that line to helper.info(....)?

joshmoore commented 4 years ago

No objections.

joshmoore commented 4 years ago

Were there other examples of lines that were not showing the stack trace when you wanted it?

mtbc commented 4 years ago

Nothing jumps to mind but I'll keep an ongoing eye out for them! I try to fix them as I notice them.

joshmoore commented 4 years ago

Ok. Since I'm not how verbose the Helper changes are going to end up being, I was wondering if it would be possible just to serialize the exception in the cancel() method if that gets you what you want. (That's how I had originally understood https://github.com/ome/omero-blitz/pull/98#issuecomment-682669538 )

mtbc commented 4 years ago

I don't understand. I want the stack trace obtainable somehow for sure. I'd guess that async methods aren't commonly hitting fatal exceptions. I'm happy to just push away the latest commit though if that expediently gets this in.

joshmoore commented 3 years ago

Sorry for letting this linger. I guess I can't verify that this doesn't overly fill up logs. If you trust it, then feel free to leave it. If this is just to get more information on the cancel(), then I'd go for the more conservative path.

mtbc commented 3 years ago

We could look at the merge CI logs after a while?

joshmoore commented 3 years ago

We'd need to do so after certain unknown conditions which may or may not be triggered by testing. I just can't verify. (To potentially lower the impact, you could separately log the stracktraces at DEBUG)

mtbc commented 3 years ago

Taking the more conservative path then, have force-pushed away the second commit.

joshmoore commented 3 years ago

Sorry, I'm not made myself clear. What's here (the logging of all stacktraces at all levels) is what I can't gauge.

mtbc commented 3 years ago

Okay if we just want to close this instead, I can apply it locally when I want it.