[MAGNOLIA-6697] Improve log behavior/levels of: RenderingFilter.getNodedataAsStream as any 404 request will trigger a full stacktrace into the log Created: 15/Jun/16  Updated: 23/Feb/17

Status: Open
Project: Magnolia
Component/s: rendering
Affects Version/s: 5.3.14, 5.4.7
Fix Version/s: None

Type: Improvement Priority: Neutral
Reporter: Christian Ringele Assignee: Unassigned
Resolution: Unresolved Votes: 2
Labels: support
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File MNGL-6697.patch    
Issue Links:
causality
Template:
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Date of First Response:

 Description   

When requesting an non existing page, trying to fetch the non existing content will trigger a JCR repository exception.
Clear, as the node does not exist.

The thrown exception is catched in the end in:
info.magnolia.rendering.engine.RenderingFilter.getNodedataAsStream(String, Session, HttpServletResponse) line 276

catch (RepositoryException e) {
            log.error("RepositoryException while reading Resource [{}]", path, e);
        }

The problem is, that the log level is error.
This means, on any 404 the logs gets a full stack trace.
And as bot attacks often search vulnerabilities by calling patterns of expected pages some clients have a huge amount of these log statements in the log. Which makes them grow rapidly in short time.

The only option the clinet currently have is switching of the logging of that class at all.
But then the two errors in line 154 & 158 hiden:

catch (RenderException e) {
            // TODO better handling of rendering exception
            // TODO dlipp: why not move this section up to the actual call to render() -> that's the only place where a RenderException could occur...
            log.error(e.getMessage(), e);
            throw new ServletException(e);
        } catch (Exception e) {
            // TODO dlipp: there's no other checked exceptions thrown in the code above - is it correct to react like that???
            log.error(e.getMessage(), e);
            if (!response.isCommitted()) {
                response.setContentType("text/html");
            }
            throw new RuntimeException(e);
        }

Pleas investigate into two directions:
1. Would the log level warn not be more accurate for this situation?
As it is an expected error when an item is not found in a 404 process.
2. As the minor solution/workaround:
Setting the method info.magnolia.rendering.engine.RenderingFilter.getNodedataAsStream from private to protected. So the customer could create a extended custom RenderingFilter and only override this one method to define a different log level.



 Comments   
Comment by Ilya Tatymachev [ 23/Feb/17 ]

The reason of this problem and solution is quite simple.

JackRabbit has three different behaviors when it can't find a resource:
1. If resource not found, but it's parent exist - it returns null
2. If resource not found and it's parent also doesn't exist - it throws PathNotFoundException
3. And if something really bad happened - it throws other type of RepositoryException

In first case we currently just log warning, that resource not found.
Second and third cases both handled by catch (RepositoryException e)

{ ... }

block.
I think, that in second case we also should just log warning, instead of full stacktrace.

I attached a patch to this message with a possible solution of this problem. MNGL-6697.patch

Generated at Mon Feb 12 04:16:59 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.