Compose end to end tracing, logging and monitoring with ECID set from WebLogic in Database (exposed in V$SESSION)

The title of this blog is unfashionably long – and really says it all. The ECID (Execution Context ID) that is used in Fusion Middleware to identify a conversation across components in one or more WebLogic servers can be used to trace that conversation into the database. When an HTTP requests enter the FMW world, the ECID is established and when that request causes various components – such as ADF, Service Bus, SOA Composite – to be activated, the ECID is passed through to them. This article describes how the ECID is also passed from WebLogic to the Oracle Database – exposed in the database through the V$SESSION view, in trace files and in the Active Session History (ASH – part of the Oracle Database Diagnostics Pack).

It seems that whenever a database is accessed from WebLogic through a JDBC Data Source acquired by the application from the WebLogic Java EE JDBC service, WebLogic ensures that the ECID context is set on the JDBC connection. So for example when an ADF application uses ADF BC, then the ECID of the request that indirectly makes ADF BC go out to the database  is set in the database. And when a SOA Suite composite application uses the Database Adapter to invoke a PL/SQL package, the ECID set for the request to the exposed Web Service is passed to the database and is available from V$SESSION.

The picture below illustrates this last example: a REST service is exposed from Service Bus (on one WebLogic Managed Server). When the service is invoked, the FMW infrastructure receives the HTTP request and assigns an ECID to the conversation. When Service Bus next calls out to a SOA Composite application on another WLS Managed Server, this ECID is passed. In the logging for both managed servers (and for both Service Bus and SOA Suite SCA engine), this ECID is associated with log entries. When the a database adapter binding is used in the SOA Composite to call a PL/SQL package in the database, the ECID is carried across to the database session and is available in V$SESSION. This allows us to associate any trace, audit and log details available from the database for the session with the request processing in the FMW platform – by correlating the ECID value. Multiple calls to the database from various components during the same FMW conversation will all be handled in the same ECID context. Perhaps we can even have state associated with this conversation (using an application context identified by client identifier and using ECID as the value for the client identifier – a thought for another day).

Detailed Example

Using the illustration overhead, let’s actually follow the trace across middleware and database.

The request to the REST service is made in the browser:

This results in an instance of the SOA Composite in the SCA engine, which can be found in the EM FMW Control console – along with the ECID assigned to this request:

When we drill down to look at the message flow trace, we see how the flow extended from Service Bus to SCA engine – which is across managed servers. The ECID is used to tie these steps together.

As we drill down even further, on the Mediator component, we see the interaction inside the SCA composite – include the call to the Database Adapter binding:

The details for this step reveal that the ECID is passed from the Mediator component to the Database Adapter. And we will see next how apparently between the Database Adapter, the  WebLogic Java EE JDBC Service and the database this ECID is carried across.

When we query V$SESSION using the ECID value:

select s.ECID , s.SID, s.ACTION, s.MODULE, s.TERMINAL, s.client_info, s.PLSQL_SUBPROGRAM_ID,s.PROGRAM
, ( SELECT max( substr( sql_text , 1, 40 )) FROM v$sql sq WHERE sq.sql_id = s.sql_id ) AS sql_text
,      ( SELECT object_name    FROM dba_procedures WHERE object_id = plsql_entry_object_id AND subprogram_id = 0) AS plsql_entry_object
,      ( SELECT procedure_name FROM dba_procedures WHERE object_id = plsql_entry_object_id AND subprogram_id = plsql_entry_subprogram_id) AS plsql_entry_subprogram
,      ( SELECT object_name    FROM dba_procedures WHERE object_id = plsql_object_id       AND subprogram_id = 0) AS plsql_entry_object
,      ( SELECT procedure_name FROM dba_procedures WHERE object_id = plsql_object_id       AND subprogram_id = PLSQL_SUBPROGRAM_ID) AS plsql_entry_subprogram
from v$session s
where s.ecid = ‘5292e5f8-6db1-49b1-9d98-d8fdd4ed2533-000122e1’

We do not get an awful lot of useful information, except of course the session id and an indication of the SQL or in this case PL/SQL that is being executed:

A call is made to the function RETRIEVE… in the PL/SQL package FLI.FLIGHT_SERVICE. Note that the ECID is not available to the session itself using SYS_CONTEXT(‘USEREND’). A DBA user can query ECID from V$SESSION using the session id – and presumably through a PL/SQL function granted to the FLI schema owner, we could get hold of ECID inside the FLIGHT_SERVICE package.

This allows us to start combining information associated with the database session with middleware activities explicitly associated with ECID. The value of ECID can also be found in database trace files.

Thanks to several colleagues and community members for thinking along with me on this subject – especially Jacco Landlust and Jacco Cijsouw.

Note: as of PS 6 – the database adapter in SOA Suite 11g includes the capability to not only bring the ECID along in a call to the database but also to start a new instance from an inbound database adapter using an ECID retrieved from the database by the inbound adapter. While it is not exactly the use case this article was meant to describe, it is certainly quite related. Details are in this article by the Oracle A-Team.

Resources

This blog article (in German) explains more about ECID and its appearance in the database.

Another – French – blog article: Injecter le contexte d’execution (ECID) de Weblogic dans V$SESSION

.

OTN Community Forum thread on PL/SQL Object Id – https://community.oracle.com/thread/2232972