PAS for OE - Logging control - Forum - OpenEdge Development - Progress Community
 Forum

PAS for OE - Logging control

  • 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?

  • What are you missing? What’s not forthcoming?
  • 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

    Regards,

    Irfan

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

    Regards,

    Irfan

  • 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.

    Regards,

    Irfan

  • Thx!

  • I don’t believe we do.
     
    You can log it from an activate procedure (look at the session:current-request-info:procedurename (IIRC) .
  • 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

    Regards,

    Irfan

  • 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.

    Regards,

    Irfan