Tapestry
  1. Tapestry
  2. TAPESTRY-1308

Exceptions while building services are poorly reported

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 5.0
    • Fix Version/s: 5.0.3
    • Component/s: tapestry-ioc
    • Labels:
      None

      Description

      Take the sample app built by tapestry-simple, and change buildTimingFilter to:

      public RequestFilter buildTimingFilter(final Log log, final @InjectService("Test") Object test)

      ... body unchanged ...

      Add:

      public static Object buildTest()

      { throw new RuntimeException("Bang"); }

      When you run this, you get a 500 page:

      HTTP ERROR: 500

      INTERNAL_SERVER_ERROR
      RequestURI=/myapp/start

      Caused by:

      java.lang.NullPointerException
      at $Request_1110563691a.getContextPath($Request_1110563691a.java)
      at $Request_111056368ca.getContextPath($Request_111056368ca.java)
      at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:34)
      at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:24)
      at $ObjectRenderer_11105636919.render($ObjectRenderer_11105636919.java)
      at $ObjectRenderer_111056368c7.render($ObjectRenderer_111056368c7.java)
      at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java:37)
      at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java)
      at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10$1.run(ComponentPageElementImpl.java:334)
      at org.apache.tapestry.internal.structure.ComponentPageElementImpl.invoke(ComponentPageElementImpl.java:931)
      at org.apache.tapestry.internal.structure.ComponentPageElementImpl.access$100(ComponentPageElementImpl.java:68)
      at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10.render(ComponentPageElementImpl.java:338)
      at org.apache.tapestry.internal.services.RenderQueueImpl.run(RenderQueueImpl.java:57)
      at org.apache.tapestry.internal.services.PageMarkupRendererImpl.renderPageMarkup(PageMarkupRendererImpl.java:40)
      at $PageMarkupRenderer_11105636915.renderPageMarkup($PageMarkupRenderer_11105636915.java)
      at org.apache.tapestry.internal.services.PageResponseRendererImpl.renderPageResponse(PageResponseRendererImpl.java:45)
      at $PageResponseRenderer_111056368da.renderPageResponse($PageResponseRenderer_111056368da.java)
      at org.apache.tapestry.internal.services.DefaultRequestExceptionHandler.handleRequestException(DefaultRequestExceptionHandler.java:56)
      at $RequestExceptionHandler_111056368b1.handleRequestException($RequestExceptionHandler_111056368b1.java)
      at org.apache.tapestry.services.TapestryModule$6.service(TapestryModule.java:523)
      at $RequestHandler_111056368ee.service($RequestHandler_111056368ee.java)
      at org.apache.tapestry.internal.services.StaticFilesFilter.service(StaticFilesFilter.java:56)
      at $RequestHandler_111056368ee.service($RequestHandler_111056368ee.java)
      at org.apache.tapestry.internal.services.LocalizationFilter.service(LocalizationFilter.java:43)
      at $RequestHandler_111056368ee.service($RequestHandler_111056368ee.java)
      at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:91)
      at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:82)
      at org.apache.tapestry.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:77)
      at org.apache.tapestry.internal.services.CheckForUpdatesFilter.service(CheckForUpdatesFilter.java:104)
      at $RequestHandler_111056368ee.service($RequestHandler_111056368ee.java)
      at $RequestHandler_111056368e8.service($RequestHandler_111056368e8.java)
      at org.apache.tapestry.services.TapestryModule$3.service(TapestryModule.java:402)
      at $HttpServletRequestHandler_111056368e7.service($HttpServletRequestHandler_111056368e7.java)
      at org.apache.tapestry.TapestryFilter.doFilter(TapestryFilter.java:114)
      at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1065)
      at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:365)
      at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:185)
      at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
      at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:690)
      at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:401)
      at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:191)
      at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
      at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
      at org.mortbay.jetty.Server.handle(Server.java:285)
      at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:457)
      at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:751)
      at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:500)
      at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:209)
      at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:357)
      at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:329)
      at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

      The logs are no more informative.

      1. log.txt
        16 kB
        Tom Davies
      2. tapestry-1308.patch
        3 kB
        Tom Davies

        Activity

        Hide
        Howard M. Lewis Ship added a comment -

        The new behavior is more reasonable; with an error in a key service such as a contribution to the RequestHandler pipeline, Tapestry is handicapped (there isn't enough of the system reachable to render the ExceptionReport page), but it does log more reasonably now:

        16:39:28.224 ERROR! [SocketListener0-1] org.apache.tapestry.ioc.internal.OneShotServiceCreator.createObject(OneShotServiceCreator.java:63) >32> Construction of service app.TimingFilter failed: Error invoking service builder method org.example.hilo.services.AppModule.buildTimingFilter(Log) (for service 'app.TimingFilter'): Forced exception inside buildTimingFilter.
        java.lang.RuntimeException: Error invoking service builder method org.example.hilo.services.AppModule.buildTimingFilter(Log) (for service 'app.TimingFilter'): Forced exception inside buildTimingFilter.
        at org.apache.tapestry.ioc.internal.ServiceBuilderMethodInvoker.createObject(ServiceBuilderMethodInvoker.java:263)
        at org.apache.tapestry.ioc.internal.SingletonServiceLifecycle.createService(SingletonServiceLifecycle.java:31)
        at org.apache.tapestry.ioc.internal.LifecycleWrappedServiceCreator.createObject(LifecycleWrappedServiceCreator.java:50)
        at org.apache.tapestry.ioc.internal.InterceptorStackBuilder.createObject(InterceptorStackBuilder.java:55)
        at org.apache.tapestry.ioc.internal.OneShotServiceCreator.createObject(OneShotServiceCreator.java:59)
        at $RequestFilter_11129d5ef58._delegate($RequestFilter_11129d5ef58.java)
        at $RequestFilter_11129d5ef58.service($RequestFilter_11129d5ef58.java)
        at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java)
        at org.apache.tapestry.services.TapestryModule$6.service(TapestryModule.java:534)
        at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java)
        at org.apache.tapestry.internal.services.StaticFilesFilter.service(StaticFilesFilter.java:56)
        at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java)
        at org.apache.tapestry.internal.services.LocalizationFilter.service(LocalizationFilter.java:43)
        at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java)
        at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:91)
        at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:82)
        at org.apache.tapestry.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:77)
        at org.apache.tapestry.internal.services.CheckForUpdatesFilter.service(CheckForUpdatesFilter.java:104)
        at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java)
        at $RequestHandler_11129d5ef55.service($RequestHandler_11129d5ef55.java)
        at org.apache.tapestry.services.TapestryModule$3.service(TapestryModule.java:408)
        at $HttpServletRequestHandler_11129d5ef54.service($HttpServletRequestHandler_11129d5ef54.java)
        at org.apache.tapestry.TapestryFilter.doFilter(TapestryFilter.java:115)
        at org.mortbay.jetty.servlet.WebApplicationHandler$CachedChain.doFilter(WebApplicationHandler.java:821)
        at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:471)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:568)
        at org.mortbay.http.HttpContext.handle(HttpContext.java:1530)
        at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:633)
        at org.mortbay.http.HttpContext.handle(HttpContext.java:1482)
        at org.mortbay.http.HttpServer.service(HttpServer.java:909)
        at org.mortbay.http.HttpConnection.service(HttpConnection.java:820)
        at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:986)
        at org.mortbay.http.HttpConnection.handle(HttpConnection.java:837)
        at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:245)
        at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:357)
        at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:534)
        Caused by: java.lang.RuntimeException: Forced exception inside buildTimingFilter.
        at org.example.hilo.services.AppModule.buildTimingFilter(AppModule.java:47)
        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:585)
        at org.apache.tapestry.ioc.internal.ServiceBuilderMethodInvoker.createObject(ServiceBuilderMethodInvoker.java:251)
        ... 35 more

        Show
        Howard M. Lewis Ship added a comment - The new behavior is more reasonable; with an error in a key service such as a contribution to the RequestHandler pipeline, Tapestry is handicapped (there isn't enough of the system reachable to render the ExceptionReport page), but it does log more reasonably now: 16:39:28.224 ERROR! [SocketListener0-1] org.apache.tapestry.ioc.internal.OneShotServiceCreator.createObject(OneShotServiceCreator.java:63) >32> Construction of service app.TimingFilter failed: Error invoking service builder method org.example.hilo.services.AppModule.buildTimingFilter(Log) (for service 'app.TimingFilter'): Forced exception inside buildTimingFilter. java.lang.RuntimeException: Error invoking service builder method org.example.hilo.services.AppModule.buildTimingFilter(Log) (for service 'app.TimingFilter'): Forced exception inside buildTimingFilter. at org.apache.tapestry.ioc.internal.ServiceBuilderMethodInvoker.createObject(ServiceBuilderMethodInvoker.java:263) at org.apache.tapestry.ioc.internal.SingletonServiceLifecycle.createService(SingletonServiceLifecycle.java:31) at org.apache.tapestry.ioc.internal.LifecycleWrappedServiceCreator.createObject(LifecycleWrappedServiceCreator.java:50) at org.apache.tapestry.ioc.internal.InterceptorStackBuilder.createObject(InterceptorStackBuilder.java:55) at org.apache.tapestry.ioc.internal.OneShotServiceCreator.createObject(OneShotServiceCreator.java:59) at $RequestFilter_11129d5ef58._delegate($RequestFilter_11129d5ef58.java) at $RequestFilter_11129d5ef58.service($RequestFilter_11129d5ef58.java) at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java) at org.apache.tapestry.services.TapestryModule$6.service(TapestryModule.java:534) at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java) at org.apache.tapestry.internal.services.StaticFilesFilter.service(StaticFilesFilter.java:56) at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java) at org.apache.tapestry.internal.services.LocalizationFilter.service(LocalizationFilter.java:43) at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java) at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:91) at org.apache.tapestry.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:82) at org.apache.tapestry.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:77) at org.apache.tapestry.internal.services.CheckForUpdatesFilter.service(CheckForUpdatesFilter.java:104) at $RequestHandler_11129d5ef5a.service($RequestHandler_11129d5ef5a.java) at $RequestHandler_11129d5ef55.service($RequestHandler_11129d5ef55.java) at org.apache.tapestry.services.TapestryModule$3.service(TapestryModule.java:408) at $HttpServletRequestHandler_11129d5ef54.service($HttpServletRequestHandler_11129d5ef54.java) at org.apache.tapestry.TapestryFilter.doFilter(TapestryFilter.java:115) at org.mortbay.jetty.servlet.WebApplicationHandler$CachedChain.doFilter(WebApplicationHandler.java:821) at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:471) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:568) at org.mortbay.http.HttpContext.handle(HttpContext.java:1530) at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:633) at org.mortbay.http.HttpContext.handle(HttpContext.java:1482) at org.mortbay.http.HttpServer.service(HttpServer.java:909) at org.mortbay.http.HttpConnection.service(HttpConnection.java:820) at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:986) at org.mortbay.http.HttpConnection.handle(HttpConnection.java:837) at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:245) at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:357) at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:534) Caused by: java.lang.RuntimeException: Forced exception inside buildTimingFilter. at org.example.hilo.services.AppModule.buildTimingFilter(AppModule.java:47) 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:585) at org.apache.tapestry.ioc.internal.ServiceBuilderMethodInvoker.createObject(ServiceBuilderMethodInvoker.java:251) ... 35 more
        Hide
        Tom Davies added a comment -

        Patch which logs original exception iff the error page can't be displayed

        Show
        Tom Davies added a comment - Patch which logs original exception iff the error page can't be displayed
        Hide
        Tom Davies added a comment -

        A reasonable solution would be to log the exception at the start of DefaultRequestExceptionHandler.handleRequestException – otherwise it gets completely lost.

        Show
        Tom Davies added a comment - A reasonable solution would be to log the exception at the start of DefaultRequestExceptionHandler.handleRequestException – otherwise it gets completely lost.
        Hide
        Tom Davies added a comment -

        Hi Howard,

        I don't think the example above is actually showing what I said it did, although I think it is a bug – there really isn't anything more useful in the logs.

        In the example above, buildTest() doesn't seem to get called (at least Idea doesn't stop at a breakpoint).

        Here's a simpler example:

        First change contributeRequestFilters to inject a service which doesn't exist – you get a nice error page explaining the problem.

        Then change buildTimingFilter to:

        public RequestFilter buildTimingFilter(final Log log,
        @InjectService("Foo") Object foo)

        And you get a 500 error:

        java.lang.NullPointerException
        at $Request_11105b89475.getContextPath($Request_11105b89475.java)
        at $Request_11105b89426.getContextPath($Request_11105b89426.java)
        at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:34)
        at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:24)
        at $ObjectRenderer_11105b89474.render($ObjectRenderer_11105b89474.java)
        at $ObjectRenderer_11105b89423.render($ObjectRenderer_11105b89423.java)
        at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java:37)
        at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java)
        at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10$1.run(ComponentPageElementImpl.java:334)
        at org.apache.tapestry.internal.structure.ComponentPageElementImpl.invoke(ComponentPageElementImpl.java:931)
        at org.apache.tapestry.internal.structure.ComponentPageElementImpl.access$100(ComponentPageElementImpl.java:68)
        at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10.render(ComponentPageElementImpl.java:338)
        at org.apache.tapestry.internal.services.RenderQueueImpl.run(RenderQueueImpl.java:57)
        at org.apache.tapestry.internal.services.PageMarkupRendererImpl.renderPageMarkup(PageMarkupRendererImpl.java:40)
        at $PageMarkupRenderer_11105b89470.renderPageMarkup($PageMarkupRenderer_11105b89470.java)
        at org.apache.tapestry.internal.services.PageResponseRendererImpl.renderPageResponse(PageResponseRendererImpl.java:45)
        at $PageResponseRenderer_11105b89436.renderPageResponse($PageResponseRenderer_11105b89436.java)
        at org.apache.tapestry.internal.services.DefaultRequestExceptionHandler.handleRequestException(DefaultRequestExceptionHandler.java:56)
        at $RequestExceptionHandler_11105b8940d.handleRequestException($RequestExceptionHandler_11105b8940d.java)

        Log is attached.

        Shouldn't getting a service name wrong always give a nice error?

        Tom

        Show
        Tom Davies added a comment - Hi Howard, I don't think the example above is actually showing what I said it did, although I think it is a bug – there really isn't anything more useful in the logs. In the example above, buildTest() doesn't seem to get called (at least Idea doesn't stop at a breakpoint). Here's a simpler example: First change contributeRequestFilters to inject a service which doesn't exist – you get a nice error page explaining the problem. Then change buildTimingFilter to: public RequestFilter buildTimingFilter(final Log log, @InjectService("Foo") Object foo) And you get a 500 error: java.lang.NullPointerException at $Request_11105b89475.getContextPath($Request_11105b89475.java) at $Request_11105b89426.getContextPath($Request_11105b89426.java) at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:34) at org.apache.tapestry.internal.services.RequestRenderer.render(RequestRenderer.java:24) at $ObjectRenderer_11105b89474.render($ObjectRenderer_11105b89474.java) at $ObjectRenderer_11105b89423.render($ObjectRenderer_11105b89423.java) at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java:37) at org.apache.tapestry.corelib.components.RenderObject.beginRender(RenderObject.java) at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10$1.run(ComponentPageElementImpl.java:334) at org.apache.tapestry.internal.structure.ComponentPageElementImpl.invoke(ComponentPageElementImpl.java:931) at org.apache.tapestry.internal.structure.ComponentPageElementImpl.access$100(ComponentPageElementImpl.java:68) at org.apache.tapestry.internal.structure.ComponentPageElementImpl$10.render(ComponentPageElementImpl.java:338) at org.apache.tapestry.internal.services.RenderQueueImpl.run(RenderQueueImpl.java:57) at org.apache.tapestry.internal.services.PageMarkupRendererImpl.renderPageMarkup(PageMarkupRendererImpl.java:40) at $PageMarkupRenderer_11105b89470.renderPageMarkup($PageMarkupRenderer_11105b89470.java) at org.apache.tapestry.internal.services.PageResponseRendererImpl.renderPageResponse(PageResponseRendererImpl.java:45) at $PageResponseRenderer_11105b89436.renderPageResponse($PageResponseRenderer_11105b89436.java) at org.apache.tapestry.internal.services.DefaultRequestExceptionHandler.handleRequestException(DefaultRequestExceptionHandler.java:56) at $RequestExceptionHandler_11105b8940d.handleRequestException($RequestExceptionHandler_11105b8940d.java) Log is attached. Shouldn't getting a service name wrong always give a nice error? Tom
        Hide
        Howard M. Lewis Ship added a comment -

        I think that's a somewhat specialized case; it made it far enough into Tapestry to try and render an exception page, but the bad service crippled the normal initialization. I suspect you would get more exception reporting in the logs as you'd see the exception that led to this exception. The NPEs are probably de-referencing stuff inside RequestGlobals.

        Show
        Howard M. Lewis Ship added a comment - I think that's a somewhat specialized case; it made it far enough into Tapestry to try and render an exception page, but the bad service crippled the normal initialization. I suspect you would get more exception reporting in the logs as you'd see the exception that led to this exception. The NPEs are probably de-referencing stuff inside RequestGlobals.

          People

          • Assignee:
            Howard M. Lewis Ship
            Reporter:
            Tom Davies
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development