Sling
  1. Sling
  2. SLING-3

Use RequestProgressTracker to log request processing steps

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Engine, JCR, Scripting, Servlets
    • Labels:
      None

      Description

      The RequestProgressTacker interface defines an API which may be used to track the process of request processing. Parties taking part in request processing, most notably resource resolution, script and servlet resolution and also request filters should track their progress in the tracker.

        Activity

        Hide
        Bertrand Delacretaz added a comment -

        Another (probably better) idea would be to accumulate this info per request, and allow it to be dumped in the generated pages.

        When a web page is assembled by Sling from multiple Components, having trace information in HTML comments in the page itselft would make it much easier to understand how the page was generated, for example:

        <body>
        <div id="nav">
        <!-- SLING_LOG_START -->
        Sling request: /content/pages/mypage.navigation.html
        LocaleFilter: using locale "fr" based on HTTP header...
        URLMapperFilter: trying /content/pages/mypage
        URLMapperFilter: trying /content/mypage
        URLMapperFilter: found /content/mypage
        ComponentResolver: GenericContent maps to DefaultComponent
        ...
        <!-- SLING_LOG_END -->
        ...actual content comes here
        <div>

        <div id="content">
        <!-- SLING_LOG_START -->
        .similar log for the Sling request that generates this div
        <!-- SLING_LOG_END -->
        ...actual content comes here
        <div>
        </body>

        Maybe this could be implemented using a wrapper for the log object (enabled by a request parameter?), stored in the ComponentRequest, that saves log info for the current request only and is available for the final rendering.

        Show
        Bertrand Delacretaz added a comment - Another (probably better) idea would be to accumulate this info per request, and allow it to be dumped in the generated pages. When a web page is assembled by Sling from multiple Components, having trace information in HTML comments in the page itselft would make it much easier to understand how the page was generated, for example: <body> <div id="nav"> <!-- SLING_LOG_START --> Sling request: /content/pages/mypage.navigation.html LocaleFilter: using locale "fr" based on HTTP header... URLMapperFilter: trying /content/pages/mypage URLMapperFilter: trying /content/mypage URLMapperFilter: found /content/mypage ComponentResolver: GenericContent maps to DefaultComponent ... <!-- SLING_LOG_END --> ...actual content comes here <div> <div id="content"> <!-- SLING_LOG_START --> .similar log for the Sling request that generates this div <!-- SLING_LOG_END --> ...actual content comes here <div> </body> Maybe this could be implemented using a wrapper for the log object (enabled by a request parameter?), stored in the ComponentRequest, that saves log info for the current request only and is available for the final rendering.
        Hide
        Felix Meschberger added a comment -

        Retarget the issue to the new Sling API and module structure

        Show
        Felix Meschberger added a comment - Retarget the issue to the new Sling API and module structure
        Hide
        Felix Meschberger added a comment -

        Descheduling from initial release.

        This may be worked on as an ongoing task. Nevertheless some time in the near future, this should be resolved.

        Show
        Felix Meschberger added a comment - Descheduling from initial release. This may be worked on as an ongoing task. Nevertheless some time in the near future, this should be resolved.
        Hide
        Bertrand Delacretaz added a comment -

        Added RequestProgressTrackerLogFilter in revision 654519, logs RequestProgressTracker info at the DEBUG level, with a unique identifier for each request.

        Example output:
        REQUEST_117 - 0 (2008-05-08 15:26:32) Starting Request Processing
        REQUEST_117 - 2 (2008-05-08 15:26:32) Starting ResourceResolution
        REQUEST_117 - 4 (2008-05-08 15:26:32) URI=/index.html resolves to Resource=JcrNodeResource, type=nt:file, path=/index.html, elapsed = 2ms
        REQUEST_117 - 4 (2008-05-08 15:26:32) Starting ServletResolution
        REQUEST_117 - 9 (2008-05-08 15:26:32) URI=/index.html handled by Servlet=DefaultGetServlet, elapsed = 5ms
        REQUEST_117 - 10 (2008-05-08 15:26:32) Starting org.apache.sling.servlets.DefaultGetServlet#0
        REQUEST_117 - 10 (2008-05-08 15:26:32) org.apache.sling.servlets.DefaultGetServlet#0, elapsed = 0ms

        That's only a first step towards making the RequestProgressTracker info available, of course having it in the generated pages would be useful as well.

        Show
        Bertrand Delacretaz added a comment - Added RequestProgressTrackerLogFilter in revision 654519, logs RequestProgressTracker info at the DEBUG level, with a unique identifier for each request. Example output: REQUEST_117 - 0 (2008-05-08 15:26:32) Starting Request Processing REQUEST_117 - 2 (2008-05-08 15:26:32) Starting ResourceResolution REQUEST_117 - 4 (2008-05-08 15:26:32) URI=/index.html resolves to Resource=JcrNodeResource, type=nt:file, path=/index.html, elapsed = 2ms REQUEST_117 - 4 (2008-05-08 15:26:32) Starting ServletResolution REQUEST_117 - 9 (2008-05-08 15:26:32) URI=/index.html handled by Servlet=DefaultGetServlet, elapsed = 5ms REQUEST_117 - 10 (2008-05-08 15:26:32) Starting org.apache.sling.servlets.DefaultGetServlet#0 REQUEST_117 - 10 (2008-05-08 15:26:32) org.apache.sling.servlets.DefaultGetServlet#0, elapsed = 0ms That's only a first step towards making the RequestProgressTracker info available, of course having it in the generated pages would be useful as well.
        Hide
        Bertrand Delacretaz added a comment -

        Revision 654541 logs more details, here's an example for the http://localhost:8888/content/mynode.html at the end of the "Sling in 15 minutes" example. Log messages go to target/sling/logs/error.log if Sling is started with "mvn jetty:run" in launchpad/webapp.

        Note that Sling logging must be set to "debug" for this to work - go to http://localhost:8888/system/console/configMgr and select the "Sling logging configuration".

        REQUEST_28 - 0 (2008-05-08 16:54:10) Starting Request Processing
        REQUEST_28 - 0 (2008-05-08 16:54:10) Starting ResourceResolution
        REQUEST_28 - 6 (2008-05-08 16:54:10) URI=/content/mynode.html resolves to Resource=JcrNodeResource, type=foo/bar, path=/content/mynode, elapsed = 6ms
        REQUEST_28 - 6 (2008-05-08 16:54:10) Starting ServletResolution
        REQUEST_28 - 6 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=foo/bar, path=/content/mynode)
        REQUEST_28 - 24 (2008-05-08 16:54:10) Using Servlet /apps/foo/bar/html.esp, elapsed = 18ms
        REQUEST_28 - 25 (2008-05-08 16:54:10) URI=/content/mynode.html handled by Servlet=Script /apps/foo/bar/html.esp, elapsed = 19ms
        REQUEST_28 - 25 (2008-05-08 16:54:10) Starting /apps/foo/bar/html.esp#0
        REQUEST_28 - 37 (2008-05-08 16:54:10) Including resource /content/header
        REQUEST_28 - 37 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=foo/header, path=/content/header)
        REQUEST_28 - 47 (2008-05-08 16:54:10) Using Servlet /apps/foo/header/html.esp, elapsed = 10ms
        REQUEST_28 - 47 (2008-05-08 16:54:10) Starting /apps/foo/header/html.esp#1
        REQUEST_28 - 68 (2008-05-08 16:54:10) /apps/foo/header/html.esp#1, elapsed = 21ms
        REQUEST_28 - 69 (2008-05-08 16:54:10) /apps/foo/bar/html.esp#0, elapsed = 44ms
        REQUEST_28 - 69 (2008-05-08 16:54:10) Request Processing ends, elapsed = 69ms

        REQUEST_29 - 0 (2008-05-08 16:54:10) Starting Request Processing
        REQUEST_29 - 1 (2008-05-08 16:54:10) Starting ResourceResolution
        REQUEST_29 - 3 (2008-05-08 16:54:10) URI=/images/sling.jpg resolves to Resource=JcrNodeResource, type=nt:file, path=/images/sling.jpg, elapsed = 2ms
        REQUEST_29 - 3 (2008-05-08 16:54:10) Starting ServletResolution
        REQUEST_29 - 3 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=nt:file, path=/images/sling.jpg)
        REQUEST_29 - 11 (2008-05-08 16:54:10) Using Servlet org.apache.sling.servlets.DefaultGetServlet, elapsed = 8ms
        REQUEST_29 - 12 (2008-05-08 16:54:10) URI=/images/sling.jpg handled by Servlet=DefaultGetServlet, elapsed = 9ms
        REQUEST_29 - 12 (2008-05-08 16:54:10) Starting org.apache.sling.servlets.DefaultGetServlet#0
        REQUEST_29 - 12 (2008-05-08 16:54:10) Using org.apache.sling.servlets.helpers.StreamRendererServlet to render for extension=null
        REQUEST_29 - 12 (2008-05-08 16:54:10) org.apache.sling.servlets.DefaultGetServlet#0, elapsed = 0ms
        REQUEST_29 - 12 (2008-05-08 16:54:10) Request Processing ends, elapsed = 12ms

        Show
        Bertrand Delacretaz added a comment - Revision 654541 logs more details, here's an example for the http://localhost:8888/content/mynode.html at the end of the "Sling in 15 minutes" example. Log messages go to target/sling/logs/error.log if Sling is started with "mvn jetty:run" in launchpad/webapp. Note that Sling logging must be set to "debug" for this to work - go to http://localhost:8888/system/console/configMgr and select the "Sling logging configuration". REQUEST_28 - 0 (2008-05-08 16:54:10) Starting Request Processing REQUEST_28 - 0 (2008-05-08 16:54:10) Starting ResourceResolution REQUEST_28 - 6 (2008-05-08 16:54:10) URI=/content/mynode.html resolves to Resource=JcrNodeResource, type=foo/bar, path=/content/mynode, elapsed = 6ms REQUEST_28 - 6 (2008-05-08 16:54:10) Starting ServletResolution REQUEST_28 - 6 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=foo/bar, path=/content/mynode) REQUEST_28 - 24 (2008-05-08 16:54:10) Using Servlet /apps/foo/bar/html.esp, elapsed = 18ms REQUEST_28 - 25 (2008-05-08 16:54:10) URI=/content/mynode.html handled by Servlet=Script /apps/foo/bar/html.esp, elapsed = 19ms REQUEST_28 - 25 (2008-05-08 16:54:10) Starting /apps/foo/bar/html.esp#0 REQUEST_28 - 37 (2008-05-08 16:54:10) Including resource /content/header REQUEST_28 - 37 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=foo/header, path=/content/header) REQUEST_28 - 47 (2008-05-08 16:54:10) Using Servlet /apps/foo/header/html.esp, elapsed = 10ms REQUEST_28 - 47 (2008-05-08 16:54:10) Starting /apps/foo/header/html.esp#1 REQUEST_28 - 68 (2008-05-08 16:54:10) /apps/foo/header/html.esp#1, elapsed = 21ms REQUEST_28 - 69 (2008-05-08 16:54:10) /apps/foo/bar/html.esp#0, elapsed = 44ms REQUEST_28 - 69 (2008-05-08 16:54:10) Request Processing ends, elapsed = 69ms REQUEST_29 - 0 (2008-05-08 16:54:10) Starting Request Processing REQUEST_29 - 1 (2008-05-08 16:54:10) Starting ResourceResolution REQUEST_29 - 3 (2008-05-08 16:54:10) URI=/images/sling.jpg resolves to Resource=JcrNodeResource, type=nt:file, path=/images/sling.jpg, elapsed = 2ms REQUEST_29 - 3 (2008-05-08 16:54:10) Starting ServletResolution REQUEST_29 - 3 (2008-05-08 16:54:10) Starting resolverServlet(JcrNodeResource, type=nt:file, path=/images/sling.jpg) REQUEST_29 - 11 (2008-05-08 16:54:10) Using Servlet org.apache.sling.servlets.DefaultGetServlet, elapsed = 8ms REQUEST_29 - 12 (2008-05-08 16:54:10) URI=/images/sling.jpg handled by Servlet=DefaultGetServlet, elapsed = 9ms REQUEST_29 - 12 (2008-05-08 16:54:10) Starting org.apache.sling.servlets.DefaultGetServlet#0 REQUEST_29 - 12 (2008-05-08 16:54:10) Using org.apache.sling.servlets.helpers.StreamRendererServlet to render for extension=null REQUEST_29 - 12 (2008-05-08 16:54:10) org.apache.sling.servlets.DefaultGetServlet#0, elapsed = 0ms REQUEST_29 - 12 (2008-05-08 16:54:10) Request Processing ends, elapsed = 12ms
        Hide
        Renaud Richardet added a comment - - edited

        >having trace information in HTML comments in the page itselft would make it much easier to understand how the page was generated

        What about doing it in 2-steps:

        1) in RequestProgressTrackerLogFilter, save debug information (in a JCR node), add debugId parameter in response
        2) add small js script on html page that gets debug information via AJAX (using debugId param)

        Please see attached patch for a proof of concept. Let me know if you think it's a valid approach, and I will produce a real patch.

        Update: moved this to SLING-688

        Show
        Renaud Richardet added a comment - - edited >having trace information in HTML comments in the page itselft would make it much easier to understand how the page was generated What about doing it in 2-steps: 1) in RequestProgressTrackerLogFilter, save debug information (in a JCR node), add debugId parameter in response 2) add small js script on html page that gets debug information via AJAX (using debugId param) Please see attached patch for a proof of concept. Let me know if you think it's a valid approach, and I will produce a real patch. Update: moved this to SLING-688
        Hide
        Bertrand Delacretaz added a comment -

        The SLING-1000 console plugin makes the RequestProgressTracker information available in the console.

        Show
        Bertrand Delacretaz added a comment - The SLING-1000 console plugin makes the RequestProgressTracker information available in the console.

          People

          • Assignee:
            Unassigned
            Reporter:
            Felix Meschberger
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development