[MGNLDAM-1305] Avoid extensive logging in DamDownloadServlet Created: 17/Nov/23  Updated: 02/Feb/24  Resolved: 02/Feb/24

Status: Closed
Project: Magnolia DAM Module
Component/s: None
Affects Version/s: 3.0.27
Fix Version/s: 3.1.0

Type: Improvement Priority: Neutral
Reporter: Denis Lobo Assignee: ricardo gonzalez
Resolution: Fixed Votes: 0
Labels: None
Σ Remaining Estimate: 0d Remaining Estimate: 0d
Σ Time Spent: 0.5h Time Spent: 0.5h
Σ Original Estimate: Not Specified Original Estimate: Not Specified

Issue Links:
Problem/Incident
duplicate
duplicates MGNLDAM-1310 Excessive Logging for non-existant or... Closed
Sub-Tasks:
Key
Summary
Type
Status
Assignee
MGNLDAM-1306 Implementation Sub-task To Do  
MGNLDAM-1307 Review Sub-task To Do  
MGNLDAM-1308 Pre-Integration QA Sub-task To Do  
MGNLDAM-1309 QA Sub-task To Do  
Template:
Patch included:
Yes
Acceptance criteria:
Empty
Task DoD:
[X]* Doc/release notes changes? Comment present?
[X]* Downstream builds green?
[X]* Solution information and context easily available?
[X]* Tests
[X]* FixVersion filled and not yet released
[X]  Architecture Decision Record (ADR)
Date of First Response:
Epic Link: AuthorX Support
Team: AuthorX
Work Started:
Approved:
Yes

 Description   

On a production environment, we receive large amounts of requests pointing to e.g. non existing dam-documents. For any requested asset, which can't be found, the DamDownloadServlet logs an exception with stacktrace (WARN as loglevel), which unfortunately spams production logs.

Thus we propose a solution, where the error with stacktrace is logged in DEBUG mode only, as well a decent log entry without stacktrace for WARN.

Reproduce

FYI: Working link is https://demopublic.magnolia-cms.com/dam/jcr:e236c74c-6b35-4467-b322-933419ecfd87/beach.svg

Expected
It should log brief information for WARN 

It should log detailed information for DEBUG

Actual

It logs detailed information on WARN

WARN  info.magnolia.dam.core.download.DamDownloadServlet 20.11.2023 14:02:03 -- Could not retrieve an asset based on the following pathInfo /jcr:e236c74c-6b35-4467-b322-933419ecfd88/beach.svg
info.magnolia.dam.api.AssetProvider$AssetNotFoundException: No Asset found for ItemKey <info.magnolia.dam.api.ItemKey@78d7c7b>
	at info.magnolia.dam.jcr.JcrAssetProvider.getNodeByIdentifier(JcrAssetProvider.java:477) ~[magnolia-dam-jcr-3.0.27.jar:?]
	at info.magnolia.dam.jcr.JcrAssetProvider.getAsset(JcrAssetProvider.java:195) ~[magnolia-dam-jcr-3.0.27.jar:?]
	at info.magnolia.dam.core.download.DamDownloadServlet.getAssetBasedOnIdentifier(DamDownloadServlet.java:228) ~[magnolia-dam-core-3.0.27.jar:?]
	at info.magnolia.dam.core.download.DamDownloadServlet.getAsset(DamDownloadServlet.java:149) [magnolia-dam-core-3.0.27.jar:?]
	at info.magnolia.dam.core.download.DamDownloadServlet.process(DamDownloadServlet.java:125) [magnolia-dam-core-3.0.27.jar:?]
	at info.magnolia.dam.core.download.DamDownloadServlet.doGet(DamDownloadServlet.java:106) [magnolia-dam-core-3.0.27.jar:?]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:529) [servlet-api.jar:4.0.FR]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:623) [servlet-api.jar:4.0.FR]
	at info.magnolia.cms.filters.ServletDispatchingFilter.doFilter(ServletDispatchingFilter.java:148) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:75) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.module.cache.executor.Store.processCacheRequest(Store.java:96) [magnolia-cache-core-5.9.8.jar:?]
	at info.magnolia.module.cache.executor.CompositeExecutor.processCacheRequest(CompositeExecutor.java:66) [magnolia-cache-core-5.9.8.jar:?]
	at info.magnolia.module.cache.filter.CacheFilter.doFilter(CacheFilter.java:164) [magnolia-cache-core-5.9.8.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.i18n.I18nContentSupportFilter.doFilter(I18nContentSupportFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.virtualuri.VirtualUriFilter.doFilter(VirtualUriFilter.java:108) [magnolia-virtual-uri-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.RangeSupportFilter.doFilter(RangeSupportFilter.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.security.BaseSecurityFilter.doFilter(BaseSecurityFilter.java:57) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.multisite.filters.CrossSiteSecurityFilter.doFilter(CrossSiteSecurityFilter.java:104) [magnolia-module-multisite-2.1.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cors.AbstractCorsFilter.doFilter(AbstractCorsFilter.java:77) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.security.SecurityCallbackFilter.doFilter(SecurityCallbackFilter.java:86) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.security.LogoutFilter.doFilter(LogoutFilter.java:93) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.module.site.filters.SiteMergeFilter.doFilter(SiteMergeFilter.java:115) [magnolia-site-1.4.5.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.multisite.filters.MultiSiteFilter.doFilter(MultiSiteFilter.java:120) [magnolia-module-multisite-2.1.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MultiChannelFilter.doFilter(MultiChannelFilter.java:83) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:128) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:92) [magnolia-module-enterprise-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.UnicodeNormalizationFilter.doFilter(UnicodeNormalizationFilter.java:89) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:164) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:90) [magnolia-personalization-preview-app-2.1.10.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:156) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:75) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:110) [magnolia-core-6.2.40.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:96) [magnolia-core-6.2.40.jar:?]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) [catalina.jar:9.0.82]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [catalina.jar:9.0.82]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168) [catalina.jar:9.0.82]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) [catalina.jar:9.0.82]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481) [catalina.jar:9.0.82]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130) [catalina.jar:9.0.82]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) [catalina.jar:9.0.82]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:670) [catalina.jar:9.0.82]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [catalina.jar:9.0.82]
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:765) [catalina.jar:9.0.82]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [catalina.jar:9.0.82]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390) [tomcat-coyote.jar:9.0.82]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) [tomcat-coyote.jar:9.0.82]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:928) [tomcat-coyote.jar:9.0.82]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1794) [tomcat-coyote.jar:9.0.82]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) [tomcat-coyote.jar:9.0.82]
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) [tomcat-util.jar:9.0.82]
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) [tomcat-util.jar:9.0.82]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.82]
	at java.base/java.lang.Thread.run(Thread.java:829) [?:?]

Notes
A PR has been provided.



 Comments   
Comment by Denis Lobo [ 20/Nov/23 ]

Pls find the PR here

Comment by Richard Gange [ 20/Nov/23 ]

IMO we don't need the stack trace at all. I think e.getMessage() would be enough in this case.

We might consider logging the requesting ip for possible blacklisting.

Comment by Philipp Gaschuetz [ 20/Nov/23 ]

abolutely agreed - no need for the stacktrace.

As for logging the requesting IP address:

( this might go off-topic now...)

IMHO this should generally be solved via MDC. Magnolia is already doing some MDC setup in 
info.magnolia.cms.filters.ContextFilter, but unfortunately in a non-configurable way and with a limited number of context variables (i.e. in our setup we don't really care about the requesting IP address, but much more about the Request-Span-ID)
 
Long story short:

  • removing the relevant parts from info.magnolia.cms.filters.ContextFilter
  • introducing a dedicated MDCFilter early in the filter chain
  • and adapting the LogLayout where necessary

would probably be the cleaner way.

Comment by Denis Lobo [ 09/Jan/24 ]

Hi Richard, 

the given PR has been automatically closed due to inactivity,.. how do we proceed further?

Should i change my PR (i.e. remove the logging completely)?

Comment by Richard Gange [ 09/Jan/24 ]

Hello Denis-

At the moment the PD team hasn't gotten around to this ticket. We do receive a lot of change requests. We use a scoring system in order to determine the highest priority tickets to serve next.

Maybe for the mean time it might be better to suppress the stack trace from the log file by changing the configuration of your log4j2 file. You can adjust the level from the DamDownloadServlet there.

HTH
Rich

Generated at Mon Feb 12 05:08:07 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.