google-code-export / wro4j

Automatically exported from code.google.com/p/wro4j
1 stars 1 forks source link

Too verbose logging on missing resources #564

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago
After update from 1.4.8.1 to 1.4.9 I'm getting this error:

01:21:47,606 DEBUG AbstractConfigurableSingleStrategy:39 - using strategy: 
ro.isdc.wro.model.resource.support.hash.SHA1HashStrategy@11bd5093
01:21:47,630 DEBUG AbstractDigesterHashStrategy:46 - SHA1HashStrategy hash: 
113c2548aedfd8cd3da6e21803b7c87cb1ada355
01:21:47,631 DEBUG ResourceWatcher:139 - Checking if resource 
/assets/third-party/aui/aui-skin-base/css/aui-skin-base.css is changed..
01:21:47,631 DEBUG ServletContextUriLocator:130 - locate resource: 
/assets/third-party/aui/aui-skin-base/css/aui-skin-base.css
01:21:47,632 DEBUG DispatcherStreamLocator:70 - dispatching request to 
location: /assets/third-party/aui/aui-skin-base/css/aui-skin-base.css
01:21:47,633 DEBUG AbstractConfigurableSingleStrategy:39 - using strategy: 
ro.isdc.wro.model.resource.support.hash.SHA1HashStrategy@16e7fc04
01:21:47,636 DEBUG AbstractDigesterHashStrategy:46 - SHA1HashStrategy hash: 
113c2548aedfd8cd3da6e21803b7c87cb1ada355
01:21:47,637 DEBUG ResourceWatcher:139 - Checking if resource 
/assets/third-party/aui/aui-skin-base/css/aui-skin-base.css is changed..
01:21:47,637 DEBUG ServletContextUriLocator:130 - locate resource: 
/assets/third-party/aui/aui-skin-base/css/aui-skin-base.css
01:21:47,638 DEBUG DispatcherStreamLocator:70 - dispatching request to 
location: /assets/third-party/aui/aui-skin-base/css/aui-skin-base.css
01:21:47,639 DEBUG AbstractConfigurableSingleStrategy:39 - using strategy: 
ro.isdc.wro.model.resource.support.hash.SHA1HashStrategy@dd87daa
01:21:47,642 DEBUG AbstractDigesterHashStrategy:46 - SHA1HashStrategy hash: 
cad733cd9b02f0d35d18cf4c49dcfe4ec78bb769
01:21:47,642 DEBUG ResourceWatcher:139 - Checking if resource 
/assets/third-party/aui/aui-skin-base/css/layout.css is changed..
01:21:47,643 DEBUG ServletContextUriLocator:130 - locate resource: 
/assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,644 DEBUG DispatcherStreamLocator:70 - dispatching request to 
location: /assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,644 DEBUG AbstractDigesterHashStrategy:46 - SHA1HashStrategy hash: 
cad733cd9b02f0d35d18cf4c49dcfe4ec78bb769
01:21:47,648 DEBUG ResourceWatcher:139 - Checking if resource 
/assets/third-party/aui/aui-skin-base/css/layout.css is changed..
01:21:47,649 DEBUG ServletContextUriLocator:130 - locate resource: 
/assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,649 DEBUG DispatcherStreamLocator:70 - dispatching request to 
location: /assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,650 DEBUG RedirectedStreamServletResponseWrapper:95 - Error detected 
with code: 404 and message: 
/dds/assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,644 DEBUG RedirectedStreamServletResponseWrapper:95 - Error detected 
with code: 404 and message: 
/dds/assets/third-party/aui/aui-skin-base/css/layout.css
01:21:47,690 DEBUG SchedulerHelper:98 - period: 0 [SECONDS]
01:21:47,690 DEBUG SchedulerHelper:98 - period: 0 [SECONDS]
01:21:47,698 DEBUG AbstractSynchronizedCacheStrategyDecorator:37 - Searching 
cache key: java.lang.String@1fd874e8[layout,CSS,true]
01:21:47,699 DEBUG DefaultSynchronizedCacheStrategyDecorator:153 - 
shouldWatchForChange
01:21:47,699 DEBUG DefaultSynchronizedCacheStrategyDecorator:131 - 
ResourceWatcher check key: java.lang.String@1fd874e8[layout,CSS,true]
01:21:47,699 DEBUG ResourceWatcher:61 - ResourceWatcher started...
01:21:47,700 DEBUG WroRuntimeException:30 - There is no such group: 'layout'. 
Available groups are: [jquery-query, aui, jquery-tools]
01:21:47,705 ERROR ResourceWatcher:75 - Exception while checking for resource 
changes
ro.isdc.wro.model.group.InvalidGroupNameException: There is no such group: 
'layout'. Available groups are: [jquery-query, aui, jquery-tools]
    at ro.isdc.wro.model.WroModel.getGroupByName(WroModel.java:116)
    at ro.isdc.wro.model.resource.support.ResourceWatcher.check(ResourceWatcher.java:65)
    at ro.isdc.wro.cache.DefaultSynchronizedCacheStrategyDecorator.onBeforeGet(DefaultSynchronizedCacheStrategyDecorator.java:132)
    at ro.isdc.wro.cache.DefaultSynchronizedCacheStrategyDecorator.onBeforeGet(DefaultSynchronizedCacheStrategyDecorator.java:32)
    at ro.isdc.wro.cache.AbstractSynchronizedCacheStrategyDecorator.get(AbstractSynchronizedCacheStrategyDecorator.java:40)
    at ro.isdc.wro.manager.ResourceBundleProcessor.serveProcessedBundle(ResourceBundleProcessor.java:74)
    at ro.isdc.wro.manager.WroManager.process(WroManager.java:126)
    at ro.isdc.wro.http.WroFilter.processRequest(WroFilter.java:331)
    at ro.isdc.wro.http.WroFilter.doFilter(WroFilter.java:267)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:548)
    at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:393)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:875)
    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
    at java.lang.Thread.run(Thread.java:680)
01:21:47,708 DEBUG ResourceWatcher:78 - resource watcher info: StopWatch '': 
running time (millis) = 7

Note my ignoreMissingResources=true
so I assume this missed resource should be ignored.

Original issue reported on code.google.com by lystoc...@gmail.com on 26 Sep 2012 at 10:31

GoogleCodeExporter commented 9 years ago
You have DEBUG log level enabled. It is supposed to be verbose. Use INFO or 
ERROR instead. 

What I can do, is to show stacktrace only for DEBUG level, however you still 
will see an error message with for INFO or ERROR log level.

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 9:41

GoogleCodeExporter commented 9 years ago
Sorry I was probably not clear enough. I set it to DEBUG level just to check 
more detailed information, and although I do find that DEBUG messages on the 
top are repetitive and if it is possible they should be minimized to not 
duplicate, but my main concern in this issue was about ERROR with stack trace 
when
ignoreMissingResources=true
it should be shown in DEBUG level in case when missing resources are set to be 
ignored.
This is similar to
http://code.google.com/p/wro4j/issues/detail?id=479#c4
but you said to open new ticket if code place is different.

Note such issues that are reappearing are important and blockers for someone 
who sends emails on each error log message that application sends and where it 
is difficult to control suppress offending logging messages (e.g. lots of 
server boxes).

Original comment by lystoc...@gmail.com on 27 Sep 2012 at 10:19

GoogleCodeExporter commented 9 years ago
The ignoreMissingResources=true exist to continue processing also when there is 
an invalid resource found. It has nothing to do with logging level. 
As I mentioned earlier, the stacktrace will go away, but you'll still see an 
error message saying that "Resource detection check failed because  There is no 
such group: 'layout'. Available groups are: [jquery-query, aui, jquery-tools]". 

This will be printed with ERROR log level, since there was an exception which 
wasn't expected. Don't you agree?

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 10:41

GoogleCodeExporter commented 9 years ago
Also, the exception occurs in ResourceWatcher which is recommended to be used 
only in DEV mode. Do you use it in production?

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 10:49

GoogleCodeExporter commented 9 years ago
Fixed in branch 1.4.x

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 11:47

GoogleCodeExporter commented 9 years ago

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 12:26

GoogleCodeExporter commented 9 years ago
I specifically set ignoreMissingResources=true because both our wro filter is 
mapped on /assets and all our assets (css/js/images) are in their corresponding 
subdirectories of /assets. So we have a lot of not found resources and keep to 
ignore missing resources. But as we know about what is missed we don't want to 
see any ERROR. It should be the same fix as in issue #479 for consistency so if 
ignoreMissingResources=true it should log messages in DEBUG level only.

Original comment by lystoc...@gmail.com on 27 Sep 2012 at 3:37

GoogleCodeExporter commented 9 years ago
If you find offending the error level log message reportedy by ResourceWatcher, 
you can always disable it from log4j configuration. It is debatable what should 
be logged with error and what shouldn't... in 1.5.0 (which was released 
recently - it will be reported with ERROR level but without stacktrace).

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 3:42

GoogleCodeExporter commented 9 years ago
Sorry, as I wrote above, we are sending email on each ERROR that is logged (so 
we should treat out logging system right), and we can't simply disable ERROR 
logging for some file because a) it is not good practice (but just good as 
temporary workaround) b) our logging file is not in the application but on 
servers and it requires to go to each of the server to modify them which is not 
practical just for some offending line of code which doesn't ignore what it is 
said to ignore.

Original comment by lystoc...@gmail.com on 27 Sep 2012 at 4:04

GoogleCodeExporter commented 9 years ago
Pertaining resourceWatcherUpdatePeriod, yes we keep it set only in development 
=1. And it works good serving fresh resources on each change. If you want to 
say that this error log message is printed only in development then it is still 
difficult/annoying to tell each developer to configure their logging levels 
(they are not centralized). Basically as there were such issues reported to 
wro4j most of them already set wro4j logging OFF which I don't think is good.

Original comment by lystoc...@gmail.com on 27 Sep 2012 at 4:08

GoogleCodeExporter commented 9 years ago
I understand your problem. I'm willing to find a solution which would make you 
happy for your specific use-case. 

The problem is that the current implementation logs errors using ERROR log 
level for a good reason and probably changing ERROR with DEBUG level is not the 
best possible solution, because it might lead to a elimination of all ERROR 
logs eventually....

For instance, the ERROR you are getting in your logs is saying that: 
"ResourceWatcher:75 - Exception while checking for resource changes because 
There is no such group: 'layout'"
Maybe the question you should ask yourself is how to avoid ResourceWatcher 
being invoked with an invalid group? Maybe mapping WroFilter to /assets/* or 
similar is not an appropriate solution? Maybe you should consider a different 
approach or maybe wro4j should allow to customize the logging level somehow...

I don't know what is the best solution at this point, but this definitely 
requires some analysis on both sides. 

Looking forward for you feedback.

Cheers,
Alex

Original comment by alex.obj...@gmail.com on 27 Sep 2012 at 9:08

GoogleCodeExporter commented 9 years ago
The solution that would work for both is:
if ignoreMissingResources=true we should log in DEBUG level for missing 
resources, but if it is ignoreMissingResources=false it still can be ERROR. So 
it just get conditional.
I have general wro.xml configuration which is used by few apps but some apps 
don't have resources declared in wro.xml so in this case I also want such 
errors to be ignored and this is not only case to move /assets/* mapping to 
something else (although I have hard time thinking about any other mapping 
because I want all the assets to be under /assets and not to be tied/show some 
technology they are generated with e.g. not /wro/*).

Original comment by lystoc...@gmail.com on 28 Sep 2012 at 8:15

GoogleCodeExporter commented 9 years ago
Would it be ok for you if when the ignoreMissingResources=true the WARN level 
is used instead of DEBUG? I'll open a new task for this.

Original comment by alex.obj...@gmail.com on 7 Oct 2012 at 11:43

GoogleCodeExporter commented 9 years ago
Sorry but why it should WARN me if in property it is said to be ignored?
I think INFO would be acceptable if it will not include stack trace.

Original comment by lystoc...@gmail.com on 7 Oct 2012 at 7:15

GoogleCodeExporter commented 9 years ago
The INFO is used usually to inform. WARN seems more appropriate since it closer 
to ERROR than INFO and it also warns you about a potential problem.

Original comment by alex.obj...@gmail.com on 7 Oct 2012 at 7:30

GoogleCodeExporter commented 9 years ago
The new issue is issue574 
Feel free to add comments there.

Original comment by alex.obj...@gmail.com on 7 Oct 2012 at 7:36