Blog Viewer

Tech Tip: How to change log4j format to show threadid (for Ag/SPS httpclient.log)

By Mark ODonohue posted 10-04-2017 06:45 PM



This project has deployment of .jar file that changes the format of the httpclientX.log file in Access Gateway/Secure Proxy Server to print threadid and some other useful format changes.



The Current httpclient.log Format is  : 

Oct 04, 2017 5:21:49 PM org.apache.http.impl.conn.Wire wire
FINE: >> "GET /unprotected/dump.aspx HTTP/1.1[\r][\n]"


To a format like :

[2017-10-04][17:03:16.759][FINE][1620][39][org.apache.http.impl.conn.Wire][wire][][>> "GET /unprotected/dump.aspx HTTP/1.1[\r] [\n]"]


The single line format, containing threadId and ms time is a more useful format for tracing and debugging individual transactions and being able to identify the response to individual requests. 



Tracing requests to through the Access Gateway/ Secure Proxy Server to determine the cause of delays, requires us to have a good handle on the request as we trace it from the client browser : 


A request from the client browser:


Goes through the Ag server to the backend. 


The trace of the data sent and received between SPS -> backend server is logged in httpclient.log and the log4j formatting looks like this : 


That format make it difficult (virtually impossible) to identify which response from the backend sever is tied to a specific sent request.


The new format :  


Allows us to tie, via the threadid the request ">>" with its' response data "<<" received from the backend, via the Pid and Tid [1620][39].


The advantages of this log4j format are: 

a) It shows PID & threadId for each log line [1620][39]

  Currently it is not possible in httpclient log to identify the response to an individual request. 

  with the threadid it is possible to tie the request sent to the backend with ">>" tag and the response from the 

  backend with "<<" tag as they will have the same threadid. 


b) It shows SrcFile line of code 

  Not as useful, in this case, but in other log4j circumstances can identify the line of code responsible for 

  writing the log file entry.


c) MS timeframe 

       Most transactions occur in ms timeframe so this is better default.


d) Data is all one one line 

       Having the data all on one line makes it simpler to use tools like grep and find since 

       they then have the complete log record, not just half of it.



   Doing extra work takes time, threadid is not a lot of work, log4j dont guarantee the threaid is the same

   but in all my test cases it has been the same (if you have some remote logger for example the threadid may 

   be different).


   SrcFile does add a bit of overhead (which is why they dont normally do it) - but can be useful - if you dont 

   need it and speed is important you can comment it out in the code.


I didn't work really hard on making the formatting efficient - so that could probably be improved if speed is needed in my case this is used for those odd occasions where there is some delay in the backedn and we need to identify which transactions have the delay.  



The deployment .zip file is attached.  It contains a README.txt, the deployment .jar file, and the src code if it needs to be recompiled for you java runtime. 




1) Copy : 


 to : 

    C:\Program Files (x86)\CA\secure-proxy\Tomcat\endorsed


2) Edit  :

Change :

#Specifies the name of a Formatter class to use.
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
to : 
#Specifies the name of a Formatter class to use.
#java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.formatter =



3) Restart SPS proxy-engine Service 


    Use services, or sps-ctl script.




    1) Move package to Access Gateway/Secure Proxy Server machine.

Generally it is easiest to build on the Ag/SPS machine since it has the JDK that you need, and also you can be sure the  .jar libraries are going to be compatable. 


    2) Edit build.bat 

Change the location of the JAVA_HOME and SPSPATH to locations of JDK and secure-proxy deployment locations.

set JAVA_HOME=C:\Program Files (x86)\Java\jdk1.7.0_51

set SPSPATH=C:\Program Files (x86)\CA\secure-proxy


    3) Run build.bat



1 comment
1 view


10-04-2017 07:53 PM

Thanks Mark!

It really allows me to split the log by threads and track specific transactions.



Having both "org.apache.http.level = FINEST" and "org.apache.http.wire.level = FINEST" enabled actually logged the same transaction twice.

So to reduce the log size and unwanted duplicated entries, it would be good to comment out the "org.apache.http.level".