RSS

Oracle Service Bus logging & tracing II – Execution & message tracing

23 Jan

Oracle Service Bus runtime execution and message tracing

One of the basics way of logging in the Oracle Service Bus is throwing your proxy services full with Log actions. Set them on debug level and if you need logging in production you change the Weblogic Log severity and check your log files. I see this happening a lot at multiple clients. However in production changing log severity to DEBUG will result is a log file output stuffed with hundreds of Log actions you implemented over the years on all of your services.

However there is another feature called tracing in the Oracle Service Bus sbconsole which might help you as well. You can find it on each service on the Operational Settings tab, called execution and message tracing.

Enabling Execution Tracing:

This setting allows you to enable logging of your service on a very detailed level, below is the output with execution tracing based upan a simple proxy/business service construction (SOAP/HTTP in and out) with a replace transformation. The log file shows the full content of MessageContextImpl in every step (stage, route, etc) of the service. The MessageContextImpl holds are the variables like $body, $operation, $inbound and $header you need. In addition to that the execution tracing shows you any changed and new variables during these steps.

####<SomeDateTime CET> <Info> <OSB Kernel> <myMachine> <AdminServer> ...
[OSB Tracing] Entering proxy myService/services/ProxyService with message context:
 [MessageContextImpl body="<soapenv:Body xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"/>"
 operation="getEmployeeDetails"
 attachments="<con:attachments xmlns:con="http://www.bea.com/wli/sb/context"/>"
 outbound="null"
 fault="null"
 inbound="<con:endpoint name="ProxyService$myService$services$ProxyService" xmlns:con="http://www.bea.com/wli/sb/context">
 <con:service/>
 <con:transport/>
 <con:security/>
</con:endpoint>"
 header="<soapenv:Header xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"/>"
.....
[OSB Tracing] Entering route node RouteNode with message context:
..... <=== CUT: identical MessageContextImpl here
[OSB Tracing] Routing to myService/services/BusinessService with message context:
 $body = <soapenv:Body xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" ..>
 <hr:LEGACY_HRSYSTEM_IN xmlns:hr="http://rubix.nl/schemas/legacy/hr">
 <hr:IDENTIFIER>2</hr:IDENTIFIER>
 </hr:LEGACY_HRSYSTEM_IN>
</soapenv:Body>
$header = <soapenv:Header xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" ..>
 <head:myHeader>
.....
[OSB Tracing] Exiting route node
[OSB Tracing] The following variables are added:
 $outbound = <con:endpoint name="BusinessService$myService$services$BusinessService" xmlns:con="http://www.bea.com/wli/sb/context">
 <con:service>
 <con:operation>LEGACY_HRSYSTEM_EMPLOYEE</con:operation>
 </con:service>
[OSB Tracing] The following variables are changed:
 $body = <soapenv:Body xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/">
 <sr01:Employee>
.....
[OSB Tracing] Exiting myService/services/ProxyService>

Enabling Message Tracing – Terse level:

Message tracing allows you to log messages passing through the service on a multiple details level. The first level is Terse which shows date, time, service type, service name, and URI in the logging.

[OSB Tracing] Inbound request was received.
 Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424131290118489--b954cde.234f563f371.-7fae
[OSB Tracing] Inbound response was sent.
Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424531290118489--a954cde.134f563f371.-7fa4

Enabling Message Tracing – Headers level:

The second level is headers, which extends terse and adds the XML representation of the message metadata

[OSB Tracing] Inbound request was received.
 Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424531290118489--a954cde.134f563f371.-7fa1
 Request metadata =
 <xml-fragment>
 <tran:headers xsi:type="http:HttpRequestHeaders" xmlns:http="http://www.bea.com/wli/sb/transports/http" xmlns:tran="http://www.bea.com/wli/sb/transports"  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
 <http:Accept-Encoding>gzip,deflate</http:Accept-Encoding>
 <http:Content-Length>740</http:Content-Length>
 <http:Content-Type>text/xml;charset=UTF-8</http:Content-Type>
 <http:Host>localhost:7001</http:Host>
 <http:SOAPAction>"http://rubix.nl/getEmployeeDetails"</http:SOAPAction>
 <http:User-Agent>Jakarta Commons-HttpClient/3.1</http:User-Agent>
 </tran:headers>
 <tran:encoding xmlns:tran="http://www.bea.com/wli/sb/transports">UTF-8</tran:encoding>
 <http:client-host xmlns:http="http://www.bea.com/wli/sb/transports/http">localhost</http:client-host>
 <http:client-address xmlns:http="http://www.bea.com/wli/sb/transports/http">127.0.0.1</http:client-address>
 <http:http-method xmlns:http="http://www.bea.com/wli/sb/transports/http">POST</http:http-method>
 </xml-fragment>

####<someDate> <Info> <OSB Kernel> <myMachine> <AdminServer> ...
[OSB Tracing] Inbound response was sent.
 Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424531290118489--a954cde.134f563f371.-7fa1
 Response metadata =
 <xml-fragment>
 <tran:headers xsi:type="http:HttpResponseHeaders" xmlns:http="http://www.bea.com/wli/sb/transports/http" xmlns:tran="http://www.bea.com/wli/sb/transports"  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
 <http:Content-Type>text/xml; charset=utf-8</http:Content-Type>
 </tran:headers>
 <tran:response-code xmlns:tran="http://www.bea.com/wli/sb/transports">0</tran:response-code>
 <tran:encoding xmlns:tran="http://www.bea.com/wli/sb/transports">utf-8</tran:encoding>
 </xml-fragment>

Enabling Message Tracing – Full level:

Most detailed message tracing level is full, which extends headers level along with the raw payload.


[OSB Tracing] Inbound request was received.
 Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424531290118489--a954cde.134f563f371.-7f9e
 Request metadata =
 <xml-fragment>
 <tran:headers xsi:type="http:HttpRequestHeaders" xmlns:http="http://www.bea.com/wli/sb/transports/http" xmlns:tran="http://www.bea.com/wli/sb/transports" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
 <http:Accept-Encoding>gzip,deflate</http:Accept-Encoding>
 <http:Content-Length>740</http:Content-Length>
 <http:Content-Type>text/xml;charset=UTF-8</http:Content-Type>
 <http:Host>localhost:7001</http:Host>
 <http:SOAPAction>"http://rubix.nl/getEmployeeDetails"</http:SOAPAction>
 <http:User-Agent>Jakarta Commons-HttpClient/3.1</http:User-Agent>
 </tran:headers>
 <tran:encoding xmlns:tran="http://www.bea.com/wli/sb/transports">UTF-8</tran:encoding>
 <http:client-host xmlns:http="http://www.bea.com/wli/sb/transports/http">localhost</http:client-host>
 <http:client-address xmlns:http="http://www.bea.com/wli/sb/transports/http">127.0.0.1</http:client-address>
 <http:http-method xmlns:http="http://www.bea.com/wli/sb/transports/http">POST</http:http-method>
 </xml-fragment>
 Payload =
<soapenv:Envelope xmlns:head="http://rubix.nl/schemas/cdm/header" xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sr01="http://rubix.nl/schemas/cdm/sr01">
 <soapenv:Header>
 <head:myHeader>
 <head:CurrentDateTime>2012-01-14T10:44:29.857Z</head:CurrentDateTime>
 <head:CorrelationID>550e8400-e29b-41d4-a716-446655440000</head:CorrelationID>
 <head:MessageID>25892e17-80f6-415f-9c65-7395632f0223</head:MessageID>
 </head:myHeader>
 </soapenv:Header>
 <soapenv:Body>
 <sr01:GetEmployeeDetailsRequest>
 <sr01:Employee>
 <sr01:Identifier>12346</sr01:Identifier>
 </sr01:Employee>
 </sr01:GetEmployeeDetailsRequest>
 </soapenv:Body>
</soapenv:Envelope>

>
####<someDate> <Info> <OSB Kernel> <myMachine> <AdminServer> ...
 [OSB Tracing] Inbound response was sent.

 Service Ref = myService/services/ProxyService
 URI = /service/employeedetails/v1
 Message ID = 3954424531290118489--a954cde.134f563f371.-7f9e
 Response metadata =
<xml-fragment>
 <tran:headers xsi:type="http:HttpResponseHeaders" xmlns:http="http://www.bea.com/wli/sb/transports/http" xmlns:tran="http://www.bea.com/wli/sb/transports" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
 <http:Content-Type>text/xml; charset=utf-8</http:Content-Type>
 </tran:headers>
 <tran:response-code xmlns:tran="http://www.bea.com/wli/sb/transports">0</tran:response-code>
 <tran:encoding xmlns:tran="http://www.bea.com/wli/sb/transports">utf-8</tran:encoding>
</xml-fragment>
 Payload =
<?xml version="1.0" encoding="UTF-8"?>
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Header xmlns:hr="http://rubix.nl/schemas/legacy/hr"/><soapenv:Body xmlns:hr="http://rubix.nl/schemas/legacy/hr"><sr01:GetEmployeeDetailsResponse xmlns:sr01="http://rubix.nl/schemas/cdm/sr01"><sr01:Employee><sr01:Identifier>12345</sr01:Identifier><sr01:FirstName>JAN</sr01:FirstName><sr01:LastName>DE VRIES</sr01:LastName><sr01:BirthDate>1950-01-01</sr01:BirthDate><sr01:Adres><sr01:Street>MYSTREET</sr01:Street><sr01:Number>20</sr01:Number><sr01:Extension/><sr01:PostalCode>1200AA</sr01:PostalCode><sr01:City>MYCITY</sr01:City></sr01:Adres></sr01:Employee></sr01:GetEmployeeDetailsResponse></soapenv:Body></soapenv:Envelope>

Conclusion:

Tracing messages in the Oracle Service Bus can give you a very good insight of what’s really happening inside your services. Message tracing can be very valuable for detailed monitoring the content of the requests (full) and give you insight on the amount of service calls going in your service (headers or terse). When really debugging a service it’s usually a matter of “what goes in” and “what goes out” and where did my transformation go wrong. So instead of flooding your services with Log Actions the execution tracing option is golden. For serious debugging your services you need this. So use it, and you will be amazed.

Reference:

About these ads
 
10 Comments

Posted by on 23-01-2012 in OSB

 

Tags: ,

10 responses to “Oracle Service Bus logging & tracing II – Execution & message tracing

  1. Pierluigi Vernetto

    24-01-2012 at 06:48

    you are right, my friend…. I will send your post to the developers. Very few people know about this and about the alsbdebug.xml

     
  2. Haowei

    05-03-2012 at 00:08

    Hi, do you know a way to enable message tracing on all services at once? The best way i know is through the “smart search” in SB console and enable them page by page. It’s become tedious when you have over 20 pages of services.

    Thanks!

     
  3. arpitrahi

    17-05-2012 at 16:04

    I enabled Execution Tracing at my end but i am not able to see any payload information in my logs.
    Can you please let us know which log files we need to check.I have my osb server in admin server itself so i am checking my admin server logs and base_domain logs but i am not able to find the logs what you have mentioned

     
    • jvzoggel

      21-05-2012 at 14:35

      Tracing information should be located in the admin server logs. Make sure that your log level is set low enough (check the server in weblogic console under Logging -> Advanced). Hope it helps. regards Jan

       

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
Follow

Get every new post delivered to your Inbox.

Join 335 other followers

%d bloggers like this: