Having seen a lot of benefit while debugging and solving problems with customer hosted services, this is one of the most important items as we move and more to API’s which are hosted over HTTP. Enabling wire logging for outbound HTTP requests helps us understand if the product is sending the right request and also if the response coming back from the server is converted right by BW6. Here’s how you do it.

In the most basic scenario if you are in TIBCO BusinessStudio, you can add the relevant logging as VM Arguments to you BWApplication Launch Configuration which you would use for debugging. This will result in writing the logs to the console view.

-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog
-Dorg.apache.commons.logging.simplelog.showdatetime=true
-Dorg.apache.commons.logging.simplelog.log.org.apache.http=DEBUG
-Dorg.apache.commons.logging.simplelog.log.org.apache.http.wire=ERROR

The logs will be in RED as the logging used is Apache Commons logging which is writing to STD Err on the console. Here is the output in Eclipse Console View 

...
<>@BWEclipseAppNode> 12:28:41.494 INFO  [main] com.tibco.thor.frwk.Deployer - Started by BusinessStudio.


12:28:45.022 INFO  [main] com.tibco.bw.frwk.engine.BWEngine - TIBCO-BW-FRWK-300002: BW Engine [Main] started successfully.

12:28:45.217 INFO  [Framework Event Dispatcher: Equinox Container: 20cf4fcf-2560-0017-1576-fe3330229c24] com.tibco.thor.frwk.Deployer - TIBCO-THOR-FRWK-300001: Started OSGi Framework of AppNode [BWEclipseAppNode] in AppSpace [BWEclipseAppSpace] of Domain [BWEclipseDomain]

12:28:45.298 INFO  [Framework Event Dispatcher: Equinox Container: 20cf4fcf-2560-0017-1576-fe3330229c24] com.tibco.thor.frwk.Application - TIBCO-THOR-FRWK-300018: Deploying BW Application [HttpLoggingTest.application:1.0].

12:28:45.344 INFO  [Framework Event Dispatcher: Equinox Container: 20cf4fcf-2560-0017-1576-fe3330229c24] com.tibco.thor.frwk.Application - TIBCO-THOR-FRWK-300021: All Application dependencies are resolved for Application [HttpLoggingTest.application:1.0]

12:28:46.509 INFO  [Thread-12] com.tibco.thor.frwk.Application - TIBCO-THOR-FRWK-300006: Started BW Application [HttpLoggingTest.application:1.0]

12:28:46.519 INFO  [Framework Event Dispatcher: Equinox Container: 20cf4fcf-2560-0017-1576-fe3330229c24] com.tibco.thor.frwk.Application - Started by BusinessStudio, ignoring .enabled settings.

2017/07/03 12:28:46:793 PDT [DEBUG] RequestAddCookies - CookieSpec selected: best-match

2017/07/03 12:28:46:802 PDT [DEBUG] RequestAuthCache - Auth cache not set in the context

2017/07/03 12:28:46:803 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {}->http://petstore.swagger.io:80][total kept alive: 0; route allocated: 0 of 20; total allocated: 0 of 200]

2017/07/03 12:28:46:816 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {}->http://petstore.swagger.io:80][total kept alive: 0; route allocated: 1 of 20; total allocated: 1 of 200]

2017/07/03 12:28:46:821 PDT [DEBUG] MainClientExec - Opening connection {}->http://petstore.swagger.io:80

2017/07/03 12:28:46:980 PDT [DEBUG] HttpClientConnectionOperator - Connecting to petstore.swagger.io/23.22.16.221:80

2017/07/03 12:28:47:070 PDT [DEBUG] HttpClientConnectionOperator - Connection established 192.168.1.7:61078<->23.22.16.221:80

2017/07/03 12:28:47:070 PDT [DEBUG] MainClientExec - Executing request GET /v2/pet/1 HTTP/1.1

2017/07/03 12:28:47:070 PDT [DEBUG] MainClientExec - Target auth state: UNCHALLENGED

2017/07/03 12:28:47:070 PDT [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED

2017/07/03 12:28:47:073 PDT [DEBUG] headers - http-outgoing-0 >> GET /v2/pet/1 HTTP/1.1

2017/07/03 12:28:47:073 PDT [DEBUG] headers - http-outgoing-0 >> Accept: application/json

2017/07/03 12:28:47:074 PDT [DEBUG] headers - http-outgoing-0 >> User-Agent: Jersey/2.21.1 (Apache HttpClient 4.3.3)

2017/07/03 12:28:47:074 PDT [DEBUG] headers - http-outgoing-0 >> Host: petstore.swagger.io:80

2017/07/03 12:28:47:074 PDT [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive

2017/07/03 12:28:47:074 PDT [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate

2017/07/03 12:28:47:171 PDT [DEBUG] headers - http-outgoing-0 << HTTP/1.1 200 OK

2017/07/03 12:28:47:171 PDT [DEBUG] headers - http-outgoing-0 << Date: Mon, 03 Jul 2017 19:28:38 GMT

2017/07/03 12:28:47:171 PDT [DEBUG] headers - http-outgoing-0 << Access-Control-Allow-Origin: *

2017/07/03 12:28:47:172 PDT [DEBUG] headers - http-outgoing-0 << Access-Control-Allow-Methods: GET, POST, DELETE, PUT

2017/07/03 12:28:47:172 PDT [DEBUG] headers - http-outgoing-0 << Access-Control-Allow-Headers: Content-Type, api_key, Authorization

2017/07/03 12:28:47:172 PDT [DEBUG] headers - http-outgoing-0 << Content-Type: application/json

2017/07/03 12:28:47:172 PDT [DEBUG] headers - http-outgoing-0 << Connection: close

2017/07/03 12:28:47:172 PDT [DEBUG] headers - http-outgoing-0 << Server: Jetty(9.2.9.v20150224)

2017/07/03 12:28:47:190 PDT [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: Shutdown connection

2017/07/03 12:28:47:190 PDT [DEBUG] MainClientExec - Connection discarded

2017/07/03 12:28:47:190 PDT [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: Close connection

2017/07/03 12:28:47:191 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://petstore.swagger.io:80][total kept alive: 0; route allocated: 0 of 20; total allocated: 0 of 200]

2017/07/03 12:28:50:638 PDT [DEBUG] PoolingHttpClientConnectionManager - Closing expired connections

2017/07/03 12:28:50:639 PDT [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 3000 SECONDS

2017/07/03 12:28:55:641 PDT [DEBUG] PoolingHttpClientConnectionManager - Closing expired connections

2017/07/03 12:28:55:641 PDT [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 3000 SECONDS

Since we are using HTTP components wire logging can be configured as defined here.

This seems good for using in Eclipse but since the logs are printed in Console view they aren’t in the actual log file.  In the next post I’ll go over how this can be done so that they show up in the Log file instead of the console.