Bug 60161 - RewriteValve: Add more logging support similar to mod-rewrite
Summary: RewriteValve: Add more logging support similar to mod-rewrite
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.35
Hardware: PC Mac OS X 10.1
: P2 enhancement (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-09-21 13:04 UTC by Santhana Preethi
Modified: 2016-10-14 14:10 UTC (History)
1 user (show)



Attachments
Patch for providing detailed logging in RewriteValve (8.69 KB, text/plain)
2016-09-21 13:04 UTC, Santhana Preethi
Details
Modified patch for Rewrite Logging (8.11 KB, patch)
2016-09-22 07:23 UTC, Santhana Preethi
Details | Diff
Valve logging change (9.53 KB, patch)
2016-09-22 16:39 UTC, Remy Maucherat
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Santhana Preethi 2016-09-21 13:04:51 UTC
Created attachment 34287 [details]
Patch for providing detailed logging in RewriteValve

The logging provided for RewriteValve is minimal. httpd provides detailed logging support with configurable log levels. Also It would be useful while debugging, if the time taken for rewrite is logged. I've added a patch replicating apache mod_rewrite behaviour.
Comment 1 Remy Maucherat 2016-09-21 13:25:10 UTC
This patch is not very good. Changing the log level from debug to info is not acceptable (debug is more than appropriate given what this is, and there's also going to be a large performance impact ...), and that's what most of the patch is doing in addition to logging statistics that don't look very useful (given the precision of currentTimeMillis).
Comment 2 Mark Thomas 2016-09-21 13:42:55 UTC
The switch from the container's logger to a dedicated Rewrite logger is problematic too.

There might be a case for recording the time taken to rewrite the URL but a) it should only be collected and logged when debug logging is enabled and b) should use nanoTime.

As a general rule, please keep the coding style of any patches consistent with the code being patched.
Comment 3 Christopher Schultz 2016-09-21 14:28:47 UTC
(In reply to Mark Thomas from comment #2)
> The switch from the container's logger to a dedicated Rewrite logger is
> problematic too.

Now so? I would think this might be the one good part of this proposed patch, because it makes it easier to adjust the log level of *only* the RewriteValve. Honestly, that should have been the only thing necessary, here. Everything else would have been configuration of the log as per usual.
Comment 4 Remy Maucherat 2016-09-21 16:16:33 UTC
If there are more than one rewrite valves used, it doesn't sound like a good idea.
Comment 5 Christopher Schultz 2016-09-21 17:00:19 UTC
That's a good point, Rémy, but it's no worse than the current situation where the rewrite logs all go to the container's logger.

I think there's still some useful work that can be done, here.
Comment 6 Santhana Preethi 2016-09-22 07:21:57 UTC
(In reply to Mark Thomas from comment #2)

> The switch from the container's logger to a dedicated Rewrite logger is
> problematic too.

I don't think writing all rewrite logs to container's logger is a good idea. In the current situation, adjusting container's logger level to DEBUG is required to write rewrite logs. 

(In reply to Christopher Schultz from comment #3)

> Now so? I would think this might be the one good part of this proposed
> patch, because it makes it easier to adjust the log level of *only* the
> RewriteValve. 

As Christopher pointed out, this would make it easier to configure log level for RewriteValve. 

(In reply to Mark Thomas from comment #2)

> There might be a case for recording the time taken to rewrite the URL but a)
> it should only be collected and logged when debug logging is enabled and b)
> should use nanoTime.

I've reworked the patch with log levels DEBUG,TRACE and nanoTime. I've replicated httpd mod_rewrite logging behaviour where level 2 logs only the rewrite information and level 3 also logs all the rules that were applied before the rewrite happened.
Comment 7 Santhana Preethi 2016-09-22 07:23:38 UTC
Created attachment 34290 [details]
Modified patch for Rewrite Logging
Comment 8 Remy Maucherat 2016-09-22 07:29:12 UTC
(In reply to Santhana Preethi from comment #6)
> > Now so? I would think this might be the one good part of this proposed
> > patch, because it makes it easier to adjust the log level of *only* the
> > RewriteValve. 
> 
> As Christopher pointed out, this would make it easier to configure log level
> for RewriteValve. 

That's his opinion and I happen to disagree with it. You can configure the log level of the container.
I also don't see what the processing time is used for in a sub component, this screams like a feature from 15 years ago [use a debugger instead].
Comment 9 Remy Maucherat 2016-09-22 16:39:21 UTC
Created attachment 34293 [details]
Valve logging change

Since the issue is about configuring the valve logging, I have a possible patch for that. It allows creating subcategories for the container logger, and exploits the ValveBase.containerLog field to use that other logger.
Not sure if it's really a good idea though.
Comment 10 Santhana Preethi 2016-09-23 10:24:31 UTC
(In reply to Remy Maucherat from comment #9)
> 
> Since the issue is about configuring the valve logging, I have a possible
> patch for that. It allows creating subcategories for the container logger,
> and exploits the ValveBase.containerLog field to use that other logger.

The proposed patch does allow adjusting the log level of ONLY the RewriteValve. It is definitely better than the current situation. 

(In reply to Remy Maucherat from comment #8)
>
> I also don't see what the processing time is used for in a sub component,
> this screams like a feature from 15 years ago [use a debugger instead].

Often, Url Rewriting involves complex regex matching. Logging the processing time for the rewrite will be useful for debugging any slow requests. Also, httpd already logs the rules applied for every URI at a higher log level (3 and above).
Comment 11 Santhana Preethi 2016-09-27 13:17:42 UTC
Any update regarding writing RewriteValve logs based on Remy Maucherat's patch?
Comment 12 Remy Maucherat 2016-10-14 14:10:43 UTC
Although I didn't get feedback, I decided to include the change (with some fixes). So this is now "fixed".