Discrepancy between Apache httpd log time and JBoss log time

Environment

• Red Hat JBoss Enterprise Application Platform (EAP)
  • 6.x (JBossWeb)
  • 7.x (Undertow)
• Red Hat JBoss Enterprise Web Server (EWS/JWS) (Tomcat)
  • 1.x
  • 2.x
  • 3.x

Issue

In Apache httpd the %t in LogFormat is the time the request was received and the access log is written once the process has been completed. This means that in httpd the access can be logged out of order based on timestamp.

In JBoss, the access log appears to be written once the page processing is completed. Is this how JBoss writes to it's access log? Can we make JBoss writes time (%t pattern) to its access log the same way apache does?

Resolution

• The timestamp (%t) being logged by Apache httpd is the time when a request was received.
• The timestamp (%t) being logged by JBoss EAP 6.x (JBossWeb), JBoss EAP 7.x (Undertow) and Tomcat is not the time when a request was received but actually the time when the access logging was written at the completion of a request/response.
• There's no log format template in JBoss to take on the behavior like Apache httpd.

Root Cause

• JBossWeb/Tomcat'sAccessLogValve does not log the time a request was received for %t, it logs the time when the log is written.

    public void invoke(Request request, Response response) throws IOException,
            ServletException {

        if (started && getEnabled()) {
            // Pass this request on to the next valve in our pipeline                                                                                                                         
            long t1 = System.currentTimeMillis(); <-------- current time

            getNext().invoke(request, response);

            long t2 = System.currentTimeMillis();
            long time = t2 - t1;

            if (logElements == null || condition != null
                    && null != request.getRequest().getAttribute(condition)) {
                return;
            }

            Date date = getDate();
	            StringBuilder result = new StringBuilder();

            for (int i = 0; i < logElements.length; i++) {
                logElements[i].addElement(result, date, request, response, time);
            }

            log(result.toString());
        } else
            getNext().invoke(request, response);
    }

• Undertow's DateTimeAttribute (%t, %{DATE_TIME}, %{time,<your-custom-date-format>}) also log the time when the log is writen:

 66     @Override
 67     public String readAttribute(final HttpServerExchange exchange) {
 68         if(dateFormat == null) {
 69             return DateUtils.toCommonLogFormat(new Date()); <---- current time
 70         } else {
 71             final SimpleDateFormat dateFormat = this.cachedFormat.get();
 72             return dateFormat.format(new Date()); <---- current time
 73         }
 74     }

• These are different than Apache httpd's logging for %t which logs the time the request was received.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.