Tuesday, January 17, 2012

Automatic Error Reports / Client Detection

I'm usually a pretty sound sleeper, but not the night of a release.  Last night was no exception with the release of 4.4.14.  My son usually wakes up around 6 AM and as soon as my wife leaves to go get him, I check my phone for server alerts and error messages.

As most Flex users know, we have something called a quality feedback agent in the system that automatically sends the development team emails when a user encounters a popup error.   This has a been a huge help to us on the dev team because the vast majority of errors go unreported to support.  We've been able to fix problems that we never would have known about otherwise.

It's fairly common to get error messages after a release.  Most of them are what we call serialization errors and look like this:

Active Panel Component: financialDocument
Active Panel Data: 09d97e22-3e10-11e1-846d-
12313f02cc9b

Event Stack...
[Event type="sendErrorEvent" bubbles=false cancelable=false eventPhase=2]

 Java Exception...
[FaultEvent fault=[RPC Fault faultString="Didn't receive an acknowledgement of message" faultCode="Server.Acknowledge.Failed" faultDetail="Was expecting message '9CA3DB5D-7B88-DD87-905A-EC04433901A3' but received '886101D0-9777-45C5-852A-765E23DBB6A8'."] messageId="6DD73431-CB83-C376-2B49-EC0443E227B5" type="fault" bubbles=false cancelable=true eventPhase=2]
To the trained eye, these errors tell us that the user is using a stale version of the Flash client.  Whenever Devon or Chris tell you to clear your cache or refresh, it's usually to correct this problem.


What we look for the morning after a release are other errors -- anything other than a simple stale client error.  This morning we had a different kind of error come in, but only from one customer.   It looked like this:

Facade Processing Exception
Report ID: ebd44295-0134-1000-0324-
123140010de4
Facade Method:com.shoptick.projects.facade.impl.ProjectElementFacadeImpl.searchProjectElements()
Arguments:com.mf.roundhouse.core.system.SessionCollaborator@6978a836,9bfb850c-b117-11df-b8d5-00e08175e43e,null,true,null,false,

java.lang.RuntimeException: java.lang.IllegalStateException: No data type for node: org.hibernate.hql.ast.tree.IdentNode
 \-[IDENT] IdentNode: 'totalPrepTimeAsTimeString' {originalText=totalPrepTimeAsTimeString}

       at com.shoptick.bizops.dao.impl.ExpressionHintProcessingDaoImpl.processHibernateBatch(ExpressionHintProcessingDaoImpl.java:140)
       at com.shoptick.bizops.dao.impl.ExpressionHintProcessingDaoImpl.resolveExpressionsHints(ExpressionHintProcessingDaoImpl.java:54)
       at com.shoptick.bizops.util.PropertyExpressionUtils.resolveExpressionsHints(PropertyExpressionUtils.java:55)
       at com.shoptick.projects.facade.impl.ProjectElementFacadeImpl.searchProjectElements(ProjectElementFacadeImpl.java:2505)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       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:309)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
       at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
       at com.mf.roundhouse.core.util.FlexOmnibusProcessingAspect.processLockableJoinpoint(FlexOmnibusProcessingAspect.java:183)
       at com.mf.roundhouse.core.util.FlexOmnibusProcessingAspect.executeFacadeMonitoringAdvice(FlexOmnibusProcessingAspect.java:99)
       at sun.reflect.GeneratedMethodAccessor2361.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
       at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
       at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
       at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
       at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
       at $Proxy274.searchProjectElements(Unknown Source)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       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:309)
       at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196)
       at $Proxy275.searchProjectElements(Unknown Source)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       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:309)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
       at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
       at com.mf.roundhouse.core.util.FlexOmnibusProcessingAspect.processLockableJoinpoint(FlexOmnibusProcessingAspect.java:183)
       at com.mf.roundhouse.core.util.FlexOmnibusProcessingAspect.executeFacadeMonitoringAdvice(FlexOmnibusProcessingAspect.java:99)
       at sun.reflect.GeneratedMethodAccessor2361.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
       at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
       at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
       at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
       at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
       at $Proxy275.searchProjectElements(Unknown Source)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.granite.messaging.service.ServiceInvocationContext.invoke(ServiceInvocationContext.java:79)
       at com.mf.roundhouse.core.security.FlexSecurityService.authorize(FlexSecurityService.java:187)
       at org.granite.messaging.service.ServiceInvoker.invoke(ServiceInvoker.java:123)
       at org.granite.messaging.amf.process.AMF3RemotingMessageProcessor.process(AMF3RemotingMessageProcessor.java:59)
       at org.granite.messaging.amf.process.AMF0MessageProcessor.process(AMF0MessageProcessor.java:79)
       at org.granite.messaging.webapp.AMFMessageServlet.doPost(AMFMessageServlet.java:62)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
       at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
       at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
       at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:198)
       at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
       at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
       at org.granite.messaging.webapp.AMFMessageFilter.doFilter(AMFMessageFilter.java:93)
       at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
       at com.mf.roundhouse.core.servlet.ExceptionEmailFilter.doFilter(ExceptionEmailFilter.java:43)
       at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
       at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
       at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
       at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
       at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
       at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
       at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
       at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
       at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
       at org.mortbay.jetty.Server.handle(Server.java:326)
       at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:536)
       at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:930)
       at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
       at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
       at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:405)
       at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
       at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
Caused by: java.lang.IllegalStateException: No data type for node: org.hibernate.hql.ast.tree.IdentNode
 \-[IDENT] IdentNode: 'totalPrepTimeAsTimeString' {originalText=totalPrepTimeAsTimeString}

       at org.hibernate.hql.ast.tree.SelectClause.initializeExplicitSelectClause(SelectClause.java:145)
       at org.hibernate.hql.ast.HqlSqlWalker.useSelectClause(HqlSqlWalker.java:705)
       at org.hibernate.hql.ast.HqlSqlWalker.processQuery(HqlSqlWalker.java:529)
       at org.hibernate.hql.antlr.HqlSqlBaseWalker.query(HqlSqlBaseWalker.java:645)
       at org.hibernate.hql.antlr.HqlSqlBaseWalker.selectStatement(HqlSqlBaseWalker.java:281)
       at org.hibernate.hql.antlr.HqlSqlBaseWalker.statement(HqlSqlBaseWalker.java:229)
       at org.hibernate.hql.ast.QueryTranslatorImpl.analyze(QueryTranslatorImpl.java:228)
       at org.hibernate.hql.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:160)
       at org.hibernate.hql.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:111)
       at org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:77)
       at org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:56)
       at org.hibernate.engine.query.QueryPlanCache.getHQLQueryPlan(QueryPlanCache.java:72)
       at org.hibernate.impl.AbstractSessionImpl.getHQLQueryPlan(AbstractSessionImpl.java:133)
       at org.hibernate.impl.AbstractSessionImpl.createQuery(AbstractSessionImpl.java:112)
       at org.hibernate.impl.SessionImpl.createQuery(SessionImpl.java:1623)
       at com.shoptick.bizops.dao.impl.ExpressionHintProcessingDaoImpl.processHibernateBatch(ExpressionHintProcessingDaoImpl.java:121)
       ... 89 more

We knew right away this was related to the search optimization we released last night, so some mild panic set in.  I unpacked the error, dug into it and realized that it was just a false alarm.  This particular customer just had an invalid property expression configured for quotes.  It was an easy mistake to make, because the expression is valid for Pull Sheets and Manifests, just not for quotes.  Removing the bad expression from their configuration resolved the error.  Never surfaced before because the old non-optimized property expression processor is designed to return a blank string when resolving an invalid property.

Now, back to these stale client errors.  For a long time we've had bigger fish to fry and just sort of lived with them.  Recently we've taken steps to handle this more gracefully.  If the user has a stale version of the client, they should get a nice friendly message telling them to refresh, not an obscure technical error.

Users may notice that we've added client and server versions to the login page and if you have a stale version of the client, you'll get a message warning you about it.  What we've since realized is that many of our customers leave Flex open all the time, all night, even.  When a system update happens, the user usually just gets automatically logged out and logs back in -- all without refreshing the client.  By adding server version checks to a few key remote events (remote events are what we call actions that initiate communication with the server) we could validate the client version before the user gets that ugly technical error.  As of now, we'll probably add these checks to all events related to authentication, the process scan event and the event that retrieves the day book.

These checks will probably be in the next maintenance release, but the benefits of better client/server version detection will take a second release to manifest themselves.

No comments:

Post a Comment