How to log incomplete request in apache tomcat
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>