I have an PAS REST app that I need to log activity hitting the adapter including some header content, the class & method being hit, the request type, and some return information.
I've tweaked WEB-INF/logging.xml settings, and while I've gotten some information that way, the rest of the info - particularly the header content - isn't forthcoming.
Has anyone else solved this, and if so - what settings did you change?
To get the HTTP Request & Response information, we can use tomcat HTTP Request dumper. Below is the documentation for using it with tomcat having a REST Adapter, it can be used for PASOE also
What I need to track is the REST activity
Verb: GET, PUT, etc.
URI /Logging/rest/LogService/LogResource/Something
Application Name Logging
Application Relative location LogService
Application endpoint LogResource/Something
I also need to track a couple of headers on the REST request.
Irfan - I've tried that and no luck so far.
I was able to get all kinds of data by setting this to "TRACE" in logging.xml:
<root level="TRACE">
<appender-ref ref="SIFT" />
</root>
I'm going through the logs now to see if I can figure out which settings I need to use.
I've found this - which have no corresponding logging.xml setting:
[catalina-exec-1] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request path is: /LogResource
[catalina-exec-1] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request HTTP method is: GET
[catalina-exec-1] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request contentType is: */*
[catalina-exec-1] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Accept contentType is: */*
[catalina-exec-1] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Found operation: LogClass..GetVerb
Tim,
This is the data I got while accessing "oeping" service using HTTP Request dumping. It has all the information you were looking for. Am I missing anything .
9-Oct-2016 15:24:31.169 INFO [catalina-exec-1] com.progress.appserv.adapters.rest.OERequestDumperFilter.doLog catalina-exec-1 Request Body=[]
19-Oct-2016 15:24:31.173 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 START TIME =19-Oct-2016 15:24:31
19-Oct-2016 15:24:31.173 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 requestURI=/rest/_oepingService/_oeping
19-Oct-2016 15:24:31.173 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 authType=null
19-Oct-2016 15:24:31.174 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 characterEncoding=null
19-Oct-2016 15:24:31.174 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 contentLength=-1
19-Oct-2016 15:24:31.174 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 contentType=null
19-Oct-2016 15:24:31.174 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 contextPath=
19-Oct-2016 15:24:31.175 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 header=user-agent=curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.15.3 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
19-Oct-2016 15:24:31.175 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 header=host=localhost:9711
19-Oct-2016 15:24:31.175 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 header=accept=*/*
19-Oct-2016 15:24:31.175 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 locale=en_US
19-Oct-2016 15:24:31.176 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 method=GET
19-Oct-2016 15:24:31.176 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 pathInfo=/_oepingService/_oeping
19-Oct-2016 15:24:31.176 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 protocol=HTTP/1.1
19-Oct-2016 15:24:31.176 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 queryString=null
19-Oct-2016 15:24:31.176 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 remoteAddr=0:0:0:0:0:0:0:1
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 remoteHost=0:0:0:0:0:0:0:1
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 remoteUser=null
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 requestedSessionId=null
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 scheme=http
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 serverName=localhost
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 serverPort=9711
19-Oct-2016 15:24:31.177 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 servletPath=/rest
19-Oct-2016 15:24:31.178 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 isSecure=false
19-Oct-2016 15:24:31.178 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 ------------------=--------------------------------------------
19-Oct-2016 15:24:32.019 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 ------------------=--------------------------------------------
og catalina-exec-1 ------------------=--------------------------------------------
19-Oct-2016 15:24:32.019 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 authType=null
19-Oct-2016 15:24:32.019 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 contentType=application/json
19-Oct-2016 15:24:32.019 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 header=Set-Cookie=JSESSIONID=BCFD2BC5B16A9AACD5711088391B62E5.tt_ablunit;path=/;HttpOnly
19-Oct-2016 15:24:32.019 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 header=Date=Wed, 19 Oct 2016 19:24:32 GMT
19-Oct-2016 15:24:32.020 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 remoteUser=null
19-Oct-2016 15:24:32.020 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 status=200
19-Oct-2016 15:24:32.020 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 END TIME =19-Oct-2016 15:24:32
19-Oct-2016 15:24:32.020 INFO [catalina-exec-1] org.apache.catalina.filters.RequestDumperFilter.doLog catalina-exec-1 ===============================================================
19-Oct-2016 15:24:32.020 INFO [catalina-exec-1] com.progress.appserv.adapters.rest.OERequestDumperFilter.doLog catalina-exec-1 Response Body =[{"response":{"_retVal":""}}]
19-Oct-2016 15:24:32.021 INFO [catalina-exec-1] com.progress.appserv.adapters.rest.OERequestDumperFilter.doLog catalina-exec-1 ===============================================================
I found a dumper file in work\${openedge.weblogs} - it has a different format, and I'm still missing the target class.method for the call.
I'll do some more looking and see if I can't link this http dump with the other logging information and get it that way.
Tim,
Request Dumper will not give class or method information. It will only dump and Request and Response Info.
I am sure if we dump or expose the information of the classes or methods we execute for REST in logging.xml. I will look into it.
Thx!
I found this:
OERequestInfo:ProcedureName
and for my call it returns this:
LogClass&GetVerb
Irfan - looking at what you posted and it looks a lot like something I'd expect to result from a logging.xml configuration. Is that how you set this up?
Tim,
RequestInfo Object might be the best choice to get the procedure,class and method related information.
As Request dumping was solving what we want, we never looked on why we cant dump the same information from logging.xml. It might also be possible that the same information can be dumped by logging.xml but might be hidden somewhere,we might not have exposed it or I am not aware of it. I shall check with team and see what we can do with logging.xml to dump the HTTP Request/Response information.
After enabling request dumper, I have set the below setting in logging.properties
handlers = 1catalina.org.apache.juli.AsyncFileHandler, 2localhost.org.apache.juli.AsyncFileHandler, 3manager.org.apache.juli.AsyncFileHandler, 4host-manager.org.apache.juli.AsyncFileHandler, java.util.logging.ConsoleHandler, 5request-dumper.org.apache.juli.FileHandler
5request-dumper.org.apache.juli.FileHandler.level = FINEST
5request-dumper.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
5request-dumper.org.apache.juli.FileHandler.prefix = requestdumper
org.apache.catalina.filters.RequestDumperFilter.level = FINEST
org.apache.catalina.filters.RequestDumperFilter.handlers = 5request-dumper.org.apache.juli.FileHandler
Hello Irfan
I am assuming the logging.properties file to which you refer is in
DLC\servers\tomcat\conf, is that correct?
Your comment "After enabling request dumper", where is that done?
In the handler definition in logging.properties it looks as though you added "Async" to most of the FileHandler definitions. Does that deal with the buffering?
Thanks,
Jeffrey
What I wound up doing was, in logging.xml I removed all the "logger" entries leaving this behind:
<root level="TRACE"><appender-ref ref="SIFT" /> </root>
I then ran a call to the REST service and trimmed out the stuff I didn't want. Marking org.apache.camel as "INFO" got rid of the most chaff I didn't need. Once I got the logs down to most of what I wanted, my logger.xml was left like this:
<logger name="org.apache.catalina.filters.RequestDumperFilter.doLog" level="INFO" />
<logger name="com.progress.appserv.services.security.OECORSFilter" level="TRACE" />
<logger name="com.progress.caf.cxf.jaxrs.interceptor.CafJAXRSInInterceptor" level="TRACE" />
<logger name="com.progress.appserv.endpoints.oe.Request" level="DEBUG" />
<logger name="com.progress.appserv.endpoints.oe.Endpoint" level="DEBUG" />
<logger name="com.progress.caf.services.http.HttpELResolver" level="DEBUG" />
<logger name="com.progress.appserv.adapters.rest.OERequestDumperFilter.doLog" level="INFO" />
<logger name="org.apache.cxf" level="INFO" />
<logger name="com.progress.UBroker" level="INFO" />
<logger name="org.apache.camel.impl.converter.DefaultTypeConverter" level="INFO"/>
<logger name="com.progress.Rest" level="INFO" />
<logger name="com.progress.appserv.Session" level="INFO" />
<logger name="com.progress.appserv.Agent" level="INFO" />
<logger name="org.springframework.security.web.util" level="INFO" />
<logger name="com.progress.appserv.manager" level="INFO" />
<logger name="org.apache.camel.support.TimerListenerManager" level="INFO" />
<logger name="com.progress.el.expression" level="INFO" />
<logger name="org.springframework.security.filterChainProxy" level="INFO" />
<logger name="org.springframework.security.web.filterChainProxy" level="INFO" />
<logger name="org.springframework" level="INFO" />
<logger name="com.progress.Rest" level="INFO" />
<logger name="com.progress.O4gl" level="WARN" />
<logger name="com.progress.adapters.rest.Binding" level="WARN" />
<logger name="com.progress.adapters.web.Management" level="WARN" />
<logger name="com.progress.appserv.PoolMgt" level="WARN" />
<logger name="com.progress.appserv.Timing" level="WARN" />
<logger name="com.progress.appserv.Agent" level="WARN" />
<logger name="com.progress.appserv.adapters.rest.Binding" level="WARN" />
<logger name="com.progress.appserv.adapters.rest.Management" level="WARN" />
<logger name="com.progress.appserv.adapters.rest.Request" level="WARN" />
<logger name="com.progress.appserv.adapters.soap" level="WARN" />
<logger name="com.progress.appserv.adapters.web.Management" level="WARN" />
<logger name="com.progress.appserv.adapters.web.Properties" level="WARN" />
<logger name="com.progress.appserv.oe.AppServerProducer" level="WARN" />
<logger name="com.progress.appserv.Mgmt" level="WARN" />
<logger name="com.progress.appserv.services.Properties" level="WARN" />
<logger name="com.progress.caf.services.http" level="WARN" />
<logger name="com.progress.caf.services.http.HttpELResolver" level="WARN" />
<logger name="com.progress.el.mapping.MappingManager" level="WARN" />
<logger name="com.progress.O4gl" level="WARN" />
<logger name="com.progress.appserv.manager.admin" level="WARN" />
<logger name="com.progress.appserv.services.metrics" level="WARN" />
<logger name="com.progress.Rest.uBroker-Client" level="WARN" />
<logger name="org.apache.velocity" level="WARN" />
<logger name="org.apache.camel" level="WARN" />
<logger name="org.apache.camel.impl" level="WARN" />
<logger name="org.apache.camel.util.AsyncProcessorHelper" level="WARN" />
<logger name="com.progress.appserv.endpoints.oe.AppServerProducer" level="WARN" />
<logger name="com.progress.appserv.endpoints.oe.Request" level="WARN" />
<logger name="com.progress.appserv.adapters.apsv.Management" level="WARN" />
<root level="INFO">
<appender-ref ref="SIFT" />
</root>
All the "WARN" entries effectively silenced those logs under normal operation. Once that was done I'd get the following in the log on each call:
16:32:20.968/137624 [catalina-exec-6] DEBUG c.p.a.services.security.OECORSFilter - Processing GET to URL: '/Logging/rest/LogService/LogResource' of type ACTUAL null
16:32:20.971/137627 [catalina-exec-6] DEBUG c.p.a.services.security.OECORSFilter - Allow non-CORS access: '/Logging/rest/LogService/LogResource'
16:32:20.994/137650 [catalina-exec-6] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request path is: /LogResource
16:32:20.994/137650 [catalina-exec-6] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request HTTP method is: GET
16:32:20.994/137650 [catalina-exec-6] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Request contentType is: */*
16:32:20.995/137651 [catalina-exec-6] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Accept contentType is: */*
16:32:20.995/137651 [catalina-exec-6] DEBUG c.p.c.c.j.i.CafJAXRSInInterceptor - Found operation: LogClass..GetVerb
16:32:21.774/138430 [catalina-exec-6] DEBUG c.p.appserv.endpoints.oe.Endpoint - AppServer Endpoint connected: null
16:32:21.774/138430 [catalina-exec-6] DEBUG c.p.appserv.endpoints.oe.Endpoint - Creating singleton class LogClass
16:32:21.778/138434 [catalina-exec-6] DEBUG c.p.appserv.endpoints.oe.Endpoint - Running internal procedure: LogClass.GetVerb
The catalina-exec-6 and the date/time fields may enable me to link this with the corresponding records in the dumper file.
Cool.
The logging.properties file will be under $DLC/servers/pasoe/conf folder. Request dumper can be enabled from the individual OEABL Web Applications's web.xml file.
<!--
<filter>
<display-name>OERequestDumperFilter</display-name>
<filter-name>OERequestDumperFilter</filter-name>
<filter-class>com.progress.appserv.adapters.rest.OERequestDumperFilter</filter-class>
</filter>
<filter-mapping>
<filter-name>OERequestDumperFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
-->
I made that change - my difference is that I put it in my LogTest PAS instance under LogTest\conf\logging.properties.
I wonder why you're getting the timestamp for each line and I'm not as the only difference I can see is you're using AsyncFileHandler and I'm not.
Did you add the AsyncFileHandler and see if that did the trick ?
I changed my "handlers" line to what you had:
handlers = 1catalina.org.apache.juli.AsyncFileHandler, 2localhost.org.apache.juli.AsyncFileHandler, 3manager.org.apache.juli.AsyncFileHandler, 4host-manager.org.apache.juli.AsyncFileHandler, java.util.logging.ConsoleHandler, 5request-dumper.org.apache.juli.FileHandler
and saw no change in the request-dumper.date.log file.
Tim,
I am running with the default configurations, so it should also be same for you. So all you have changed is the logging.properties by adding the Request dumper information and adding that to the handlers list right ?
Also, why do you need the set the Request dumper logger information in logigng.xml instead of logging.properties ?
I've created a new PASOE instance using OE, and when I did that some of the configuration information in the new instance was different than what was in the default config created when I first installed PDS. Thinking there's something missing in the new instances, I added the RequestDumper reference to logging.xml - to no effect.
My logging.properties is just like yours, except when I changed just the request dumper to use async instead of the regular file handler, I didn't get a log file at all.
Also, I've added two enhancement requests pertaining to OE logging and I'm encouraging interested parties to +1 them. :)
Thanks for submitting Ideas. I have added bug for one of the request.
It might be a good Idea, if you can pass me your logging.xml,web.xml and logging.properties. I see what the differences are. Otherwise, I can also pass mine
I'm done for this week - will pick this up again next week. Thx for the offer!
Irfan and I swapped files and figured out that I had this in my logging.properties and he didn't:
5request-dumper.org.apache.juli.FileHandler.formatter = org.apache.juli.VerbatimFormatter
commenting this out resulted in each output line in the dumper file getting a timestamp, which is what he was seeing.
Hello Irfan
You made the following statement, "After enabling request dumper".
How do you enable "request dumper"?
Thank you,
Jeffrey
Jeffrey,
In the webapps/<webApplication/WEB-INF/web.xml, you will see a filter for enabling RequestDumper as below. If you enable this part then RequestDumper will be enabled
<filter>
<display-name>OERequestDumperFilter</display-name>
<filter-name>OERequestDumperFilter</filter-name>
<filter-class>com.progress.appserv.adapters.rest.OERequestDumperFilter</filter-class>
</filter>
<filter-mapping>
<filter-name>OERequestDumperFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
Hello Irfan
Great, thanks for pointing me at it.
Thanks
Jeffrey
Last update - the stock logging.xml configuration
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
will result in the package of a class being shortened to a single character like so:
o.s.b.f.xml.XmlBeanDefinitionReader
The {36} portion sets the size for the package.class size, and if the reference doesn't fit, the logger'll shorten it.
Getting rid of the {36} segment like so:
<pattern>%d{HH:mm:ss.SSS}/%r [%thread] %-5level %logger - %msg%n</pattern>
results in the full package name being reported:
org.springframework.beans.factory.xml.XmlBeanDefinitionReader
which is what I was looking for.
Thanks to PSC Tech support and Jeffrey Wolf for digging this up!
Apache Logging main page: