We had been looking into  options on how to identify requests which are not logged in access logs because they could not be completed for any reason. So for those of you who are unaware,  access log only logs the request which are complete. Let us say users requests a page and for some reason the request never gets completed (Server crash, out of memory), you will never see that in access logs.

But more often than not you will need that request to identify what caused the crash

There are 3 potential options

Option 1:

Use Apache as a reverse proxy in front of Tomcat  and enabled mod_log_forensic to log all request

How does it work ?

Apache comes with a module mod_log_forensic

http://httpd.apache.org/docs/current/mod/mod_log_forensic.html

In this each request is logged two times

The first line logs the forensic ID, the request line and all received headers, separated by pipe characters (|).  A sample line looks like the following (all on one line):

+yQtJf8CoAB4AAFNXBIEAAAAA|GET /manual/de/images/down.gif HTTP/1.1|Host:localhost%3a8080|User-Agent:Mozilla/5.0 (X11; U; Linux i686; en-US; rv%3a1.6) Gecko/20040216 Firefox/0.8|Accept:image/png, etc…

The plus character at the beginning indicates that this is the first log line of this request. The second line just contains a minus character and the ID again:

Then next line would be , which signifies that request has been completed.

-yQtJf8CoAB4AAFNXBIEAAAAA

Advantage : Least invasive with very little noise. No code change in application.

Disadvantage : Apache is not a part of our deployment. So this requires IT to modify the infrastructure.

Option 2:

Development team does code changes to log incomplete request.

Advantage : Can control what to log and when to log.

Disadvantage : Code changes. Testing. Patch required for earlier versions of applications.

 Option 3:

Enable Request Dumper Filter in tomcat.

Tomcat comes with a  request dumper filter which logs all incoming and outgoing request.

https://tomcat.apache.org/tomcat-7.0-doc/config/filter.html

Advantage : Changes required in application’s web.xml  and server’s logging.properties. Technically this is code change but we can do directly on the application server.

Disadvantage : Very verbose. Logs everything in request.

From tomcat docs

WARNING: Using this filter has side-effects. The output from this filter includes any parameters included with the request. The parameters will be decoded using the default platform encoding. Any subsequent calls to request.setCharacterEncoding() within the web application will have no effect.

This is the output from one request with dumper filter enabled on webservice.

10-Apr-2017 11:49:27.409 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1 START TIME        =10-Apr-2017 11:49:27

10-Apr-2017 11:49:27.409 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         requestURI=/cdpImport

10-Apr-2017 11:49:27.409 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1           authType=null

10-Apr-2017 11:49:27.410 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1  characterEncoding=utf-8

10-Apr-2017 11:49:27.410 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1      contentLength=45

10-Apr-2017 11:49:27.410 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1        contentType=text/plain; charset=utf-8

10-Apr-2017 11:49:27.410 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1        contextPath=

10-Apr-2017 11:49:27.410 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             cookie=dummyCookie=make-sure-there-is-always-a-cookie

10-Apr-2017 11:49:27.420 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         remoteAddr=127.0.0.1

10-Apr-2017 11:49:27.421 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         remoteHost=127.0.0.1

10-Apr-2017 11:49:27.421 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         remoteUser=null

10-Apr-2017 11:49:27.421 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1 requestedSessionId=null

10-Apr-2017 11:49:27.421 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             scheme=http

10-Apr-2017 11:49:27.421 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         serverName=localhost

10-Apr-2017 11:49:27.422 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         serverPort=8085

10-Apr-2017 11:49:27.422 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1        servletPath=

10-Apr-2017 11:49:27.422 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1           isSecure=false

10-Apr-2017 11:51:07.619 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1           authType=null

10-Apr-2017 11:51:07.619 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1        contentType=text/plain;charset=ISO-8859-1

10-Apr-2017 11:51:07.620 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             header=Content-Type=text/plain;charset=ISO-8859-1

10-Apr-2017 11:51:07.620 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             header=Content-Length=211

10-Apr-2017 11:51:07.620 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             header=Date=Mon, 10 Apr 2017 15:51:07 GMT

10-Apr-2017 11:51:07.620 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1         remoteUser=null

10-Apr-2017 11:51:07.620 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1             status=202

10-Apr-2017 11:51:07.621 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1 END TIME          =10-Apr-2017 11:51:07

10-Apr-2017 11:51:07.621 INFO [http-nio-8085-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog http-nio-8085-exec-1 ===============================================================

This is what you add in web.xml of your application

</pre>
<filter>
 <filter-name>requestdumper</filter-name>
 <filter-class>
 org.apache.catalina.filters.RequestDumperFilter
 </filter-class>
 </filter>
 <filter-mapping>
 <filter-name>requestdumper</filter-name>
 <url-pattern>*</url-pattern>
 </filter-mapping>