Announcement Announcement Module
Collapse
No announcement yet.
Identifying error source best practice Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Identifying error source best practice

    I am getting an exception:

    Code:
    2013-04-03 16:38:02,890 ERROR org.springframework.integration.handler.LoggingHandler - org.springframework.integration.MessageHandlingException: java.lang.UnsupportedOperationException
    	at org.springframework.integration.handler.MethodInvokingMessageProcessor.processMessage(MethodInvokingMessageProcessor.java:76)
    	at org.springframework.integration.handler.ServiceActivatingHandler.handleRequestMessage(ServiceActivatingHandler.java:67)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.handleMessageInternal(AbstractReplyProducingMessageHandler.java:134)
    	at org.springframework.integration.handler.AbstractMessageHandler.handleMessage(AbstractMessageHandler.java:73)
    	at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    	at java.lang.reflect.Method.invoke(Method.java:597)
    	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    	at org.springframework.integration.monitor.SimpleMessageHandlerMetrics.handleMessage(SimpleMessageHandlerMetrics.java:106)
    	at org.springframework.integration.monitor.SimpleMessageHandlerMetrics.invoke(SimpleMessageHandlerMetrics.java:86)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    	at com.sun.proxy.$Proxy62.handleMessage(Unknown Source)
    	at org.springframework.integration.dispatcher.UnicastingDispatcher.doDispatch(UnicastingDispatcher.java:115)
    	at org.springframework.integration.dispatcher.UnicastingDispatcher.dispatch(UnicastingDispatcher.java:102)
    	at org.springframework.integration.channel.AbstractSubscribableChannel.doSend(AbstractSubscribableChannel.java:77)
    	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:157)
    	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:128)
    	at sun.reflect.GeneratedMethodAccessor106.invoke(Unknown Source)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    	at java.lang.reflect.Method.invoke(Method.java:597)
    	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    	at org.springframework.integration.monitor.DirectChannelMetrics.monitorSend(DirectChannelMetrics.java:113)
    	at org.springframework.integration.monitor.DirectChannelMetrics.doInvoke(DirectChannelMetrics.java:97)
    	at org.springframework.integration.monitor.DirectChannelMetrics.invoke(DirectChannelMetrics.java:91)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    	at com.sun.proxy.$Proxy48.send(Unknown Source)
    	at org.springframework.integration.core.MessagingTemplate.doSend(MessagingTemplate.java:288)
    	at org.springframework.integration.core.MessagingTemplate.send(MessagingTemplate.java:149)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.sendMessage(AbstractReplyProducingMessageHandler.java:216)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.sendReplyMessage(AbstractReplyProducingMessageHandler.java:200)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.produceReply(AbstractReplyProducingMessageHandler.java:165)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.handleResult(AbstractReplyProducingMessageHandler.java:159)
    	at org.springframework.integration.handler.AbstractReplyProducingMessageHandler.handleMessageInternal(AbstractReplyProducingMessageHandler.java:141)
    	at org.springframework.integration.handler.AbstractMessageHandler.handleMessage(AbstractMessageHandler.java:73)
    	at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    	at java.lang.reflect.Method.invoke(Method.java:597)
    	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    	at org.springframework.integration.monitor.SimpleMessageHandlerMetrics.handleMessage(SimpleMessageHandlerMetrics.java:106)
    	at org.springframework.integration.monitor.SimpleMessageHandlerMetrics.invoke(SimpleMessageHandlerMetrics.java:86)
    	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    	at com.sun.proxy.$Proxy62.handleMessage(Unknown Source)
    	at org.springframework.integration.dispatcher.UnicastingDispatcher.doDispatch(UnicastingDispatcher.java:115)
    	at org.springframework.integration.dispatcher.UnicastingDispatcher.dispatch(UnicastingDispatcher.java:102)
    	at 
    
    ... lines trimmed due to size ...
    
    org.springframework.integration.endpoint.AbstractPollingEndpoint$Poller.run(AbstractPollingEndpoint.java:231)
    	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:53)
    	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
    	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
    	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
    	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
    	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
    	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
    	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
    	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
    	at java.lang.Thread.run(Thread.java:680)
    Caused by: java.lang.UnsupportedOperationException
    	at java.util.AbstractList.set(AbstractList.java:115)
    	at java.util.AbstractList$ListItr.set(AbstractList.java:412)
    	at java.util.Collections.sort(Collections.java:161)
    	at org.springframework.expression.spel.support.ReflectiveMethodResolver.resolve(ReflectiveMethodResolver.java:106)
    	at org.springframework.expression.spel.ast.MethodReference.findAccessorForMethod(MethodReference.java:262)
    	at org.springframework.expression.spel.ast.MethodReference.access$400(MethodReference.java:40)
    	at org.springframework.expression.spel.ast.MethodReference$MethodValueRef.getValue(MethodReference.java:94)
    	at org.springframework.expression.spel.ast.CompoundExpression.getValueInternal(CompoundExpression.java:82)
    	at org.springframework.expression.spel.ast.SpelNodeImpl.getTypedValue(SpelNodeImpl.java:102)
    	at org.springframework.expression.spel.standard.SpelExpression.getValue(SpelExpression.java:103)
    	at org.springframework.integration.util.AbstractExpressionEvaluator.evaluateExpression(AbstractExpressionEvaluator.java:126)
    	at org.springframework.integration.util.MessagingMethodInvokerHelper.processInternal(MessagingMethodInvokerHelper.java:227)
    	at org.springframework.integration.util.MessagingMethodInvokerHelper.process(MessagingMethodInvokerHelper.java:127)
    	at org.springframework.integration.handler.MethodInvokingMessageProcessor.processMessage(MethodInvokingMessageProcessor.java:73)
    	... 88 more
    This is all well and good except I find nothing identifiable to anything in my code (which I am sure it is). Everything is so abstracted out with Spring via proxies, reflection, executors, ad nauseoum, that when I get an exception like this I find it could be in any one of hundreds of classes. I usually end up commenting out entire tracts of configuration to enable/disable huge sections of code just to find where this is coming from. In general, it seems there must be some tidbit of information of exactly _which_ handler/adapter/component which should be attached to the logged exception. If I had a dump of the message itself I could divine sufficient information from the message history, but I can't seem to find out how to do that (I have message history turned on, but this just has the stack trace).

    Any best practices, hints on this sort of problem would be appreciated. Yes, I do see it is coming from a problem with an UnsupportedOperationException from a List, and it is being thrown in a ServiceActivatingHandler somewhere in my code, which isolates it to almost anywhere in my codebase. <sigh/> I will be able to find it, and most of the time I find an identifiable class in the trace where I can straight to the problem. This is just one of those rare ones that does not fit that category, and I see this sort of thing once or twice a year, and I hoped not to have to go through the brute force method of problem isolation and identification.

  • #2
    I understand your frustration but, typically, these situations are usually made obvious by simply turning on DEBUG logging and the copious logging by the framework makes everything crystal clear. For example "preSend on channel X"... crash.

    Comment


    • #3
      I do have the logging on DEBUG, but with so many things happening in this system in parallel (hundreds of channels and components, thousands of messages / sec), and with this being such an intermittent error which is triggered by external data coming into the application, it is hard to find the correlation. I even have a runtime controllable logging level mechanism with class-level granularity to adjust the log levels dynamically. Well, back to the tried and true "divide and conquer"...

      And I would agree that the situations are "usually made obvious", that is why this sort of thing only happens once or twice a year to me. Usually there is something in the stack trace that points directly at the offender (other than myself). And when I find the bug, I even perform a Opus Dei style Corporal Mortification so I won't make that mistake again, but alas, I always put another bug or two into the system eventually.

      Comment


      • #4
        The default LoggingHandler on the errorChannel will log just the payload of the ErrorMessage (which is a MessagingException).

        The default errorChannel is a <publish-subscribe-channel/>.

        You could add an additional subscriber - a transformer with
        Code:
        expression="payload.failedMessage"
        and then send that to a logging channel adapter that has "log-full-message" set to true. That way, you can see the headers so, if message-history is on, you can see where the failure occurred.

        Comment


        • #5
          I find your comment #4 very helpful. I had already found, using my rather brutish method, the source of the error, but I added the transformer hint for future problems. The original error I solved by moving a annotated method configuration back to xml configuration. I will be revisiting that one to figure out what it did not like about the annotation.

          Comment

          Working...
          X