Sunday Mar 10, 2013

EDN Debugging

I have a customer asked me about how to debug EDN. This blog will show you how to debug EDN and the tools that can be used to debug EDN.

1. Using EDN-DB-LOG

EDN comes with a useful EDN DB logging servlet to view logging information generated by the EDN component. It is only available for END-DB which is based on AQ, it will not work for EDN with JMS. The servlet uses a table called “EDN_LOG_MESSAGES” in SOA_INFRA schema. It logs the operation on “main” operation of event_queue and oaoo-queue with timestamp information.

The default URL is http://<host_name>:<port_number>/soa-infra/events/edn-db-log.  In this servlet, you can enable, disable and clear logs but you need to have the administrative role in order to access the servlet.  This is a good tool to use to display dynamic counts of un-deq'ed events (potentially "stuck") in the "main" and "OAOO" queues. The log also provides information of EDN bus when it is being connected to AQ-DB.  In the screenshot below, “EVENT_SEQ:202” shows that the EDN bus is being started.

When the logging is enabled, the EDN_LOG_MESSAGES table will be populated with messages until the logging is disabled, so it is inadvisable to leave logging turned on for large amounts of events. It is recommended to clear the log regularly.

Messages in the log are grouped together. Usually the first line in the group will indicate what operation is being performed, and the event sequence number is used to group the messages together and each group will be highlighted using the same color (e.g. enqueuing an event or handling an event that has been dequeued). In the screenshots below, “EVENT_SEQ:204” is dequeuing an event and “EVENT_SEQ:205” is enqueuing an event.

2. Database tables

The second method is to examine the database table. You can check on count of potentially “stuck” events currently in the following queue tables:

  • EDN_EVENT_QUEUE_TABLE – This table is for “EDN_EVENT_QUEUE” AQ. Every event published is temporarily enqueued into this table.
  • EDN_OAOO_DELIVERY_TABLE – This table only stores the event with “OAOO” (one-and-only-one) delivery target(s). The event is temporarily enqueued into this table for END_OAOO_QUEUE AQ.

For event with OAOO delivery target, it travels through both tables, first it is stored in EDN_EVENT_QUEUE_TABLE and then in EDN_OAOO_DELIVERY_TABLE.

This example shows the event enq'ed in "edn_event_queue".

Another alternative is to check the count from the following database views:

  • AQ$EDN_EVENT_QUEUE_TABLE: There are two rows for every event enqueued into "edn_event_queue".
  • AQ$EDN_OAOO_DELIVERY_TABLE: There is one row for every event enqueued into "edn_oaoo_queue". 

This example shows further details about that event which is deq'ed by the subscribers of "edn_event_queue".

The AQ$EDN_EVENT_QUEUE_TABLE.MSG_STATE shows the state of the message.  The states are listed in the table below:

State Code





The message is ready to be processed, i.e., either the delay
time of the message has passed or the message did not have a delay time specified



The delay specified by message_properties_t.delay while executing dbms_aq.enqueue has not been reached.



The message has been successfully processed (dequeued) but will remain in the queue until the retention_time specified for the queue while executing dbms_aqadm.create_queue has been reached.



The message was not successfully processed (dequeued) in either 1) the time specified by message_properties_t.expiration while executing dbms_aq.enqueue or 2) the maximum number of dequeue attempts (max_retries) specified for the queue while executing dbms_aqadm.create_queue.



Buffered messages enqueued by a Streams Capture process


Buffered Expired

User-enqueued expired buffered messages

If the subscriber type is equal to 2 when there is no subscribers to the message, and there is no transaction id due to invalid transaction, it will be marked as UNDELIVERABLE.

When the state message is expired, the AQ$EDN_EVENT_QUEUE_TABLE.EXPIRATION_REASON will be populated with one of the following value:

  • Messages to be cleaned up later

3. Server Logs

The third method is using EM log configuration and log viewer. There are few logger names related the EDN:

  • oracle.integration.platform.blocks.event
  • oracle.integration.platform.blocks.event
  • oracle.integration.platform.blocks.event.saq
  • oracle.integration.platform.blocks.event.jms

You can set log level to one of the following to capture more details:

    • TRACE:1 (FINE) - Logging the event content details, XPath filter results, event enqueue, dequeue, publish and send operations
    • TRACE:16 (FINER) – Logging the begin, commit and rollback statements of XA transaction (for OAOO) and retry count.
    • TRACE:32 (FINEST)  - All above.

    The log level changes take effect immediately without server restart. However, if you want the changes to persist after server restart, make sure to check on the “Persist Log Level State Across Component Restarts” prior to server restart.

    At FINER or FINEST level, you may see loggings like "Began XA for OAOO." and "Rolled back XA for OAOO." These are normal messages of OAOO event delivery when there are no events waiting to be delivered. They are NOT errorred conditions. You may turn off these messages by setting the Java logging level to "TRACE:1 (FINE)" or a higher value. All detailed logging goes into SOA server's diagnostic.log file configured in EM.  Below is a snippet of the diagnostic log showing the event delivery to an OAOO subscriber:

    [SRC_METHOD: finerBeganXA] Began XA for OAOO.

    [SRC_METHOD: fineEventPublished] Received event: Subject: ... Sender: .... Event: ...

    [SRC_METHOD: fineFilterResults] Filter [XPath Filter: …] for subscriber "..." returned true/false

    [SRC_METHOD: fineDequeuedEvent] Dequeued event, Subject: ... [source type ..]: business-event...

    [SRC_METHOD: fineOAOOEnqueuedEvent] Enqueued OAOO event, Subject: ... [source: ..., target: ... ]: business-event...

    [SRC_METHOD: fineOAOODequeuedEvent] Dequeued OAOO event, Subject: ... [source: ..., target: ...]: business-event...

    [SRC_METHOD: finerInsertedTryCount] Inserted try count for msgId: .... Status: ...

    [SRC_METHOD: finerRemovedTryCount] Removed try count for msgId: ...

    [SRC_METHOD: fineSentOAOOEvent] Sent OAOO event [QName: ... to target: ...]: business-event...

    [SRC_METHOD: fineCommittedOAOODelivery] Committed OAOO Delivery, Subject: ... [source: ..., target: ...]: business-event...

    [SRC_METHOD: finerBeganXA] Began XA for OAOO.

    [SRC_METHOD: finerRolledbackXA] Rolled back XA for OAOO.

    In some cases, more than one method may be necessary to assist in the debugging process. Below is a comparison of server and DB logging that might help you in evaluating and determining which method(s) is/are most suitable in your environment.

    Server Logging

    • EDN will generate standard Java logging messages when events are published, when they are pulled from persistent storage and when they are delivered.
    • The logger used by EDN depends on the implementation. For instance, EDN-DB uses "oracle.integration.platform.blocks.event.saq" and EDN-JMS uses "oracle.integration.platform.blocks.event.jms".
    • As in all Java logging, messages are written at different log levels from ERROR to FINEST. The most detailed messages (including the event body) use FINEST.
    • Loggers can also be configured in logging.xml in your config directory.

    DB Logging

    • If you are using EDN-DB, a lot of debugging information may not be accessible due to the many activities that occurred in the database which couldn’t be logged in the server. Hence, a servlet web page that accesses the debug logging table is implemented to assist the debugging process. The page is located at: http://hostname:port/soa-infra/events/edn-db-log and you do need to have administrative role to access the servlet page.
    • There are commands on the servlet web page to enable and disable logging and for clearing the log table. The table will be filled with messages, so it is inadvisable to leave logging turned on for large amounts of events. It is recommended to clear the log regularly.
    • Messages in the log are grouped together. Usually the first line in the group will indicate what operation is being performed (e.g. enqueuing an event or handling an event that has been dequeued).

    Mediator Instance Tracking

    Mediator supports three modes for instance tracking by changing the audit level in EM->SOA->SOA-INFRA->SOA Administration->Mediator Properties:

    1. Off - No instance tracking for successfully completed instance, however, instances and faulted instances are created even in this mode.  Audit trail will not be created with this flag.
    2. Production - Instance tracking is enabled for all.  All audit details are logged, except the details of assign activities, but the instances and payloads are not captured.
    3. Development - Instance tracking is enabled for all.  All audit details are logged, and the instances and payloads are also captured.

    The following tables are used by Mediator to store the instance and audit trail data:

    1. MEDIATOR_INSTANCE - This table contains one row for each mediator instance. Each instance has a unique id. It stores ecid, composite instance id and parent component id from normalized message and overall state of an instance in the component_state column.  The component state depends on the combination of the mediator case instance states, the states are listed here.
    2. MEDIATOR_CASE_INSTANCE - This table contains one row for each mediator routing rule and fault information for a routing rule is also stored.  Each case instance has one unique id.  It stores mediator instance id and case name, related fault information and information pertaining to retries.  This is the base table for executing automatic retries using fault policies.
    3. MEDIATOR_CASE_DETAIL - This table contains multiple rows for each routing rule and stores mediator audit trail xml as a blob for each routing rule. Each case detail rows are bound together by case id.  It stores case detail state, audit trail for each case detail.  The state of the latest case detail is the current state of the case.
    4. MEDIATOR_AUDIT_DOCUMENT- This table stores payload at each stage of mediator message flow and payloads are stored only when instance tracking audit level is set to "Development". Each row in this table stores the payload at a point in the message flow. e,g, transformed payload, payload being sent to the target service.

    Below is a screenshot of a basic mediator project with 2 routing rules which polls an xml file from an input folder, transforms the content and writes the xml file to a folder. 

    When the mediator receives a massage, it creates a mediator instance, and then depending on the number of routing rule, one or more case instance will be created in the MEDIATOR CASE INSTANCE table. The engine will then initializes the audit trail xml and stores it as an XML document. After each processing point (e.g. transformation, filter evaluation etc), it stores the trail messages to audit trail xml and persists to audit trail table (MEDIATOR_CASE_DETAIL.AUDIT_TRAIL  and/or MEDIATOR_AUDIT_DOCUMENT), then the mediator instance state will be updated.

    1. When the mediator instance kicks off, a composite instance will be created in the COMPOSITE_INSTANCE table, and unique ECID will be assigned to the instance.

    select * from composite_instance where ecid='1b7e5955c26b51de:-56440391:13d41f410c6:-8000-000000000000144b'

    2. Using ECID, you can retrieve the mediator instance data and the component state from the mediator instance table.  From this point onward, MEDIATOR_INSTANCE.ID will be used to retrieve the mediator case data.

    select * from mediator_instance where ecid='1b7e5955c26b51de:-56440391:13d41f410c6:-8000-000000000000144b'

     3. Depending on the number of routing rules, the mediator will store each routing rule separately in the MEDIATOR_CASE_INSTANCE table and the MEDIATOR_CASE_INSTANCE .ID will be used to retrieve the case detail for each routing rule.  In the above example, there are 2 routing rules.

    select * from mediator_case_instance where instance_id = 'C64B82E086BB11E2BFBE1B53FB1929E1';

    4. The audit trail of each routing rule is stored in the MEDIATOR_CASE_DETAIL table in compressed format.

    select * from mediator_case_detail where instance_id = 'C64B82E086BB11E2BFBE1B53FB1929E1';

    Below are the xml data that are stored in the MEDIATOR_CASE_DETAIL.AUDIT_TRAIL column.  In the example below, two routing rules were being executed. The first event routing rule’s result was equal to “false”, then the second routing rule was executed. The second event routing rule’s result was successful, subsequently the message was transformed and published to the destination. If you have the audit trail level set to “Development”, you can use the audit id in the case trail to retrieve the payload from the MEDIATOR_AUDIT_DOCUMENT table for further investigation.

    CASE=ID= C64BA9F086BB11E2BFBE1B53FB1929E1


      <event type="inputPayloadReceived" status="Completed"

             parentId="C64B82E086BB11E2BFBE1B53FB1929E1" date="1362615182063"





    CASE_ID= C66EE96086BB11E2BFBE1B53FB1929E1


      <event type="case" id="C66EE96086BB11E2BFBE1B53FB1929E1"

             parentId="C64B82E086BB11E2BFBE1B53FB1929E1" caseName="USCustomer.Write"

             date="1362615182073" auditId="C64BA9F086BB11E2BFBE1B53FB1929E1">



      <event type="condition" status="Completed"

             parentId="C66EE96086BB11E2BFBE1B53FB1929E1" date="1362615182074"





    CASE _ID= C670700086BB11E2BFBE1B53FB1929E1


      <event type="case" id="C670700086BB11E2BFBE1B53FB1929E1"


             caseName="CanadaCustomer.Write" date="1362615182083"




      <event type="condition" status="Completed"

             parentId="C670700086BB11E2BFBE1B53FB1929E1" date="1362615182083"




      <event type="transform" status="Completed"

             parentId="C670700086BB11E2BFBE1B53FB1929E1" date="1362615182102"




      <event type="publish" status="Completed"

             parentId="C670700086BB11E2BFBE1B53FB1929E1" date="1362615182124"

             auditId="C67292E086BB11E2BFBE1B53FB1929E1" parentRefId="mediator:C64B82E086BB11E2BFBE1B53FB1929E1:C670700086BB11E2BFBE1B53FB1929E1:oneway">





    This is the blog for the Oracle FMW Architects team fondly known as the A-Team. The A-Team is the central, technical, outbound team as part of the FMW Development organization working with Oracle's largest and most important customers. We support Oracle Sales, Consulting and Support when deep technical and architectural help is needed from Oracle Development.
    Primarily this blog is tailored for SOA issues (BPEL, OSB, BPM, Adapters, CEP, B2B, JCAP)that are encountered by our team. Expect real solutions to customer problems, encountered during customer engagements.
    We will highlight best practices, workarounds, architectural discussions, and discuss topics that are relevant in the SOA technical space today.


    « March 2013 »