exist icon indicating copy to clipboard operation
exist copied to clipboard

Add request log to log configuration

Open line-o opened this issue 2 years ago • 9 comments

Description:

With the update to jetty 11 request logs are now implicitly written to exist.log (the exist.core appender to be more accurate). This PR adds the requestLogger explicitly to the log4j configuration along with some comments.

        <!--
            the requestlog was previously written into separate files
            if you want to retain that you need to add a new appender
            and change the AppenderRef to reference it here
        -->
        <Logger name="org.eclipse.jetty.server.RequestLog" additivity="false" level="info">
            <AppenderRef ref="STDOUT"/>
            <AppenderRef ref="exist.core"/><!-- request log is now written to exist.log -->
        </Logger>

It also appends the request log to STDOUT so that when existdb is started on the command line those requests will be available right after the notification that jetty has started:

16 Feb 2023 12:51:10,904 [main] INFO  (JettyStart.java [startJetty]:478) - [Starting jetty component : org.eclipse.jetty.server.Server]
16 Feb 2023 12:51:10,904 [main] INFO  (JettyStart.java [lifeCycleStarting]:635) - Jetty server starting...
16 Feb 2023 12:51:11,409 [main] INFO  (JettyStart.java [lifeCycleStarted]:644) - Jetty server started.
16 Feb 2023 12:51:11,409 [main] INFO  (JettyStart.java [run]:288) - -----------------------------------------------------
16 Feb 2023 12:51:11,410 [main] INFO  (JettyStart.java [run]:289) - Server has started, listening on:
16 Feb 2023 12:51:11,410 [main] INFO  (JettyStart.java [run]:291) - http://127.0.0.1:8080/
16 Feb 2023 12:51:11,410 [main] INFO  (JettyStart.java [run]:291) - https://127.0.0.1:8443/
16 Feb 2023 12:51:11,410 [main] INFO  (JettyStart.java [run]:294) - Configured contexts:
16 Feb 2023 12:51:11,410 [main] INFO  (JettyStart.java [run]:300) - /exist (eXist XML Database)
16 Feb 2023 12:51:11,411 [main] INFO  (JettyStart.java [run]:300) - / (eXist-db portal)
16 Feb 2023 12:51:11,411 [main] INFO  (JettyStart.java [run]:324) - -----------------------------------------------------
16 Feb 2023 12:51:18,272 [qtp536994956-44] INFO  (Slf4jRequestLogWriter.java [write]:57) - 127.0.0.1 - - [16/Feb/2023:11:51:18 +0000] "GET /exist/apps/eXide/index.html HTTP/1.1" 200 54409 "-" "curl/7.79.1"

Reference:

change introduced in c7083be047af5637fd119530874387073eb0eb5e

Type of tests:

none

line-o avatar Feb 16 '23 12:02 line-o

@line-o just out of curiosity have you actually been able to confirm that the old request.logs no longer exist? I'd hate for us to log this stuff in two locations

duncdrum avatar Feb 16 '23 12:02 duncdrum

@duncdrum since the old configuration for jetty request logs was replaced I am sure the old log files are no more.

line-o avatar Feb 16 '23 12:02 line-o

@duncdrum also out of curiosity: what are the implications on running existdb in docker when it comes to request logs appended to exist.log and/or STDOUT?

line-o avatar Feb 16 '23 12:02 line-o

none really, write access to the container filesystem is the same irrespective of path or filename. Since this is easily user configurable its just a question of what you prefer as a default. Personally i m leaning towards just logging to standard out, and leave the files alone.

duncdrum avatar Feb 16 '23 13:02 duncdrum

From yesterdays community call:

While it is generally good to have as few separate log files as possible (preferably just one), I think that the jetty request log with one line per request is excessive. This will flood the default logs. In general we could see the upcoming major version as an opportunity to rethink the log setup. @reinhapa

line-o avatar Feb 21 '23 11:02 line-o

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
No Duplication information No Duplication information

sonarqubecloud[bot] avatar Feb 21 '23 11:02 sonarqubecloud[bot]

While I share @reinhapa 's concern about flooding the exist.log file, previously the requests where logged by jetty in a separate location, that wasn't user accessible and equally verbose. We already have a number of *.log files pre-configured for exist, that receive little to no entries. Creating another one, or reusing one of the existing logs for the requests is a good feature to tackle for v7.

Yet, getting the requests to be logged within the log4j logs that control all this in the first place, is a precondition and a separate step in my mind. So I would merge this PR first, and tackle the broader refactoring of the default logs later.

duncdrum avatar Feb 21 '23 12:02 duncdrum

I don't think this is ready yet. There should be a jetty request log in the same way we previously had, I'm not certain that log4j is the correct place to handle this. Instead we may just need a tweak to the jetty config files (if something changed around lodging config between jetty 9 and 11)

adamretter avatar Apr 09 '23 09:04 adamretter

As discussed in today's Community Call, we should resolve the request logging situation before the release of eXist 7, since users expect request logs to be stored in logs/YYYY_MM_DD.request.log and not to appear in exist.log.

joewiz avatar Jul 17 '23 18:07 joewiz