PAS for OE - Logging control

Posted by Tim Kuehn on 19-Oct-2016 13:24

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?

All Replies

Posted by Peter Judge on 19-Oct-2016 13:38
What are you missing? What’s not forthcoming?
Posted by Irfan on 19-Oct-2016 13:39

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

documentation.progress.com/.../index.html

Posted by Tim Kuehn on 19-Oct-2016 14:09

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

Posted by Irfan on 19-Oct-2016 14:28

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 ===============================================================

Posted by Tim Kuehn on 19-Oct-2016 15:38

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.

Posted by Irfan on 19-Oct-2016 16:04

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.

Posted by Tim Kuehn on 19-Oct-2016 16:06

Thx!

Posted by Peter Judge on 19-Oct-2016 18:42
I don’t believe we do.
 
You can log it from an activate procedure (look at the session:current-request-info:procedurename (IIRC) .
Posted by Tim Kuehn on 20-Oct-2016 15:19

I found this:

OERequestInfo:ProcedureName

and for my call it returns this:

LogClass&GetVerb

Posted by Tim Kuehn on 20-Oct-2016 15:30

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?

Posted by Irfan on 20-Oct-2016 20:17

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

Posted by Jeffrey Z. Wolf on 21-Oct-2016 07:06

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

Posted by Tim Kuehn on 21-Oct-2016 08:09

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. 

Posted by Irfan on 21-Oct-2016 09:57

Cool.

Posted by Irfan on 21-Oct-2016 10:03

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>

   -->

Posted by Tim Kuehn on 21-Oct-2016 11:29

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.

Posted by Irfan on 21-Oct-2016 11:37

Did you add the AsyncFileHandler and see if that did the trick ?

Posted by Tim Kuehn on 21-Oct-2016 11:53

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.

Posted by Irfan on 21-Oct-2016 14:26

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 ?

Posted by Tim Kuehn on 21-Oct-2016 14:34

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.

Posted by Tim Kuehn on 21-Oct-2016 14:34

Also, I've added two enhancement requests pertaining to OE logging and I'm encouraging interested parties to +1 them. :)

Posted by Irfan on 21-Oct-2016 15:34

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

Posted by Tim Kuehn on 21-Oct-2016 15:39

I'm done for this week - will pick this up again next week. Thx for the offer!

Posted by Tim Kuehn on 25-Oct-2016 06:45

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.

Posted by Jeffrey Z. Wolf on 25-Oct-2016 12:06

Hello Irfan

You made the following statement, "After enabling request dumper".

How do you enable "request dumper"?

Thank you,

Jeffrey

Posted by Irfan on 25-Oct-2016 12:12

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>

Posted by Jeffrey Z. Wolf on 25-Oct-2016 13:42

Hello Irfan

Great, thanks for pointing me at it.

Thanks

Jeffrey

Posted by Tim Kuehn on 08-Nov-2016 16:26

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! 

Posted by Tim Kuehn on 09-Nov-2016 14:24

Apache Logging main page:

https://logging.apache.org/

This thread is closed