OAG Access Log Response Time Is Negative Number (Doc ID 2012032.1)

Last updated on OCTOBER 13, 2016

Applies to:

Oracle API Gateway - Version 11.1.2 and later
Information in this document applies to any platform.

Symptoms

PROBLEM DESCRIPTION
-------------------------------------

After enabling access log on a production servers in OAG 11.1.2.3.0 using log pattern as follow:
%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" RspHdr-Loc="%{Location}o" RqHdr-XFwdFor="%{X-Forwarded-For}i" RspTime="%D"
based on OAG and Apache documentation, %D should log response time in microseconds, but the resulting number is not in micro and also shows as a negative number such as the following:

localhost - - "GET http://xxx.xx.xxx:9200/category/US/147 HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-19"
 - -  "GET http://xxx.xx.xxx:9200/product2.0/_search?q=sku:010-01020-00&size=1 HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-21"
 - -  "GET /customerWebServices_v1.2/CustomerBusinessService?wsdl HTTP/1.0" 200 46894 "" ",Java/1.7.0_25" RspHdr-Loc="" RqHdr-XFwdFor=",192.168.19.213" RspTime="-22"
 - -  "GET http://local.com/appsBusinessServices_v0/rest/apps/dacc5c22-c100-216f-67fb-eca11k3809bb HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-21"
 - -  "GET http:/local.com/appsBusinessServices_v0/rest/apps/1q56caa8-9a50-1000-8765-12t3c11111m1/stats HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-29"
- -  "GET http://local.com/appsBusinessServices_v0/rest/apps/54321z34-99aj-12tt-77d5-1dal98g3f66f/stats HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-25"
a10-10-11-266.deploy.localhost.com - - "POST http://local.com/appsProcessServices_v0/rest/apps/appIconUrl HTTP/1.0" 200 - "" "" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-93"

ERROR
-------------

No error was received. However, the results are not what is expected.

WHAT IS WORKING
--------------------------------

The access log is getting populated but the RspTime shows as a negative value and also the value is not in micro seconds as expected.

ENVIRONMENT
------------
OAG 11.1.2.3
OS: Linux x86-64
Access log

STEPS
----------
1. Open Policy Studio
2. Click on Server Settings --> Expand Logging --> Click on Access Log then make sure the "Access Log Enabled" is checked.
2. Update Pattern to the following:
%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" RspHdr-Loc="%{Location}o" RqHdr-XFwdFor="%{X-Forwarded-For}i" RspTime="%D"
3. Check "Enable Apache Access File Logger"
4. Under Listeners --> Default Services --> Paths, click on /healthcheck path.
5. In the Audit Settings tab, check "Include in server access log records" and click Ok
6. Deploy.
7. In a browser, type http://localhost:8080/healthcheck
8. Navigate to OAG11123\apigateway\groups\group-2\instance-1\logs\access then open access.log; observe the following:

localhost - - "GET /healthcheck HTTP/1.0" 200 19 "" ",Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.118 Safari/537.36" RspHdr-Loc="" RqHdr-XFwdFor="" RspTime="-11"

Notice that the RspTime is a negative value.



Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms