Tracking of a Weblogic JMS bridge

I’ve been talking about JMS bridges between Weblogic and HornetQ for a while, today I’d like to deal with the issue of tracking, which is especially useful when you need to know the time when a message was dispatched to the destination system.

The idea is to configure Weblogic to debug messaging bridge runtime events, add a custom logging handler that captures and saves these events into a table and to analyze them, in order to track the pass of the messages through the bridge.

Therefore, the first task is to enable the debugging of the messaging bridge events in Weblogic. One of the methods to achieve this goal is to add the following lines to the setDomainEnv.cmd script:

set JAVA_OPTIONS=%JAVA_OPTIONS% -Dweblogic.debug.DebugMessagingBridgeStartup=true
set JAVA_OPTIONS=%JAVA_OPTIONS% -Dweblogic.debug.DebugMessagingBridgeRuntime=true

The next step is to create a table to give persistence to the events:

CREATE TABLE wl_log
(log_id        NUMBER              CONSTRAINT wl_log_pk PRIMARY KEY,
 log_timestamp TIMESTAMP           NOT NULL,
 msg_id        VARCHAR2(25 CHAR)   NOT NULL,
 log_level     VARCHAR2(25 CHAR)   NOT NULL,
 subsystem     VARCHAR2(50 CHAR)   NOT NULL,
 message       VARCHAR2(4000 CHAR) NOT NULL);

CREATE SEQUENCE wl_log_s
INCREMENT BY 1
START WITH 1
MAXVALUE 999999999999
MINVALUE 1
CACHE 20;

The following task is to create a custom logging handler that will capture and save the events into the former table (this class has references to a properties file, where I put the parameters needed to connect to the Oracle database):

public class WLCustomLoggingHandler extends Handler {
    private Connection dbConn = null;
    private PreparedStatement psmt = null;

    public WLCustomLoggingHandler() throws IOException,
                                           ClassNotFoundException,
                                           SQLException {
        super();

        Properties dbProperties;

        dbProperties = new Properties();
        dbProperties.load(this.getClass().getResourceAsStream(
                                            "WLCustomLoggingHandlerDB.properties"));
        Class.forName(dbProperties.getProperty("DRIVER"));
        this.dbConn =
                DriverManager.getConnection(dbProperties.getProperty("URL"),
                                            dbProperties.getProperty("USER"),
                                            dbProperties.getProperty("PASS"));
        this.psmt =
                this.dbConn.prepareStatement("INSERT INTO wl_log " +
                                             "(log_id, log_timestamp, msg_id, " +
                                             "log_level, subsystem, message) " +
                                             "VALUES(wl_log_s.nextval, ?, ?, ?, ?, ?)");

        this.setErrorManager(new ErrorManager() {
            public void error(String msg, Exception ex, int code) {
                System.err.println("Error reported by TestWLLoggingHandler "
                                   + msg + ex.getMessage());
                LoggingHelper.getServerLogger().removeHandler(WLCustomLoggingHandler.this);
            }
        });
    }

    @Override
    public void publish(LogRecord record) {
        WLLogRecord wlLogRecord = (WLLogRecord)record;
        if (this.isLoggable(wlLogRecord)) {
            try {
                psmt.setEscapeProcessing(true);
                psmt.setTimestamp(1, new Timestamp(wlLogRecord.getMillis()));
                psmt.setString(2, wlLogRecord.getId());
                psmt.setString(3, wlLogRecord.getLevel().getName());
                psmt.setString(4, wlLogRecord.getLoggerName());
                psmt.setString(5, wlLogRecord.getMessage());
                psmt.executeUpdate();
                this.flush();
            } catch (SQLException ex) {
                this.reportError("WLCustomLoggingHandlerpublish: ",
                                 ex,
                                 ErrorManager.WRITE_FAILURE);
            }
        }
    }

    @Override
    public void flush() {
        try {
            this.dbConn.commit();
        } catch (SQLException ex) {
            this.reportError("WLCustomLoggingHandlerflush: ",
                             ex,
                             ErrorManager.FLUSH_FAILURE);
        }
    }

    @Override
    public void close() throws SecurityException {
        try {
            this.dbConn.close();
        } catch (SQLException ex) {
            this.reportError("WLCustomLoggingHandlerclose: ",
                             ex,
                             ErrorManager.CLOSE_FAILURE);
        }
    }
}

We just want to analyze the events regarding to the messaging bridge, so we have to create a logging filter:

public class WLCustomLoggingFilter implements Filter {
    public WLCustomLoggingFilter() {
        super();
    }

    @Override
    public boolean isLoggable(LogRecord record) {
        if (record instanceof WLLogRecord) {
            WLLogRecord wlLogRecord = (WLLogRecord)record;

            return wlLogRecord.getSubsystem().equals("MessagingBridge") ||
                wlLogRecord.getSubsystem().equals("MessagingBridgeRuntime");
        } else {
            return false;
        }
    }
}

The next step is to code a Weblogic startup class:

public class WLCustomLoggingHandlerStartupClass {
    public WLCustomLoggingHandlerStartupClass() {
        super();
    }

    public void configureLogger() {
        Logger logger = null;
        Handler handler = null;

        try {
            logger = LoggingHelper.getServerLogger();
            handler = new WLCustomLoggingHandler();
            handler.setFilter(new WLCustomLoggingFilter());
            logger.addHandler(handler);
        } catch (Exception ex) {
            System.err.println("WLCustomLoggingHandlerStartupClass.configureLogger: "
                               + ex.getMessage());
            ex.printStackTrace();
            try {
                logger.removeHandler(handler);
            } catch (Exception ignore) {
            }
        }
    }

    public static void main(String[] args) {
        WLCustomLoggingHandlerStartupClass testWLCustomLoggingHandlerStartupClass =
            new WLCustomLoggingHandlerStartupClass();
        testWLCustomLoggingHandlerStartupClass.configureLogger();
    }
}

This class has to be configured in Weblogic by going to the Enviroment->Startup and Shutdown Classes of the console (obviously, the corresponding jar file containing the former code has to be available on the weblogic classpath):

Weblogic Startup and Shutdown Classes
The last step is to analyze the log entries in order to know when each message is dispatched to its destination, when the bridge was up and running, etc. MessagingBridge Subsystem Messages are helpful to achieve this goal, especially:

  • BEA-200028: The bridge “arg01” has started transferring messages.
  • BEA-200024: Bridge “arg0” refused to obtain connections and transfer any messages, because it has been stopped or suspended, or is shutting down.
  • BEA-200015: An error occurred in bridge “arg0” during the transfer of messages (e).

But, the pass of a message through a bridge has to be discovered by analyzing the log entries with id BEA-000000, of course the sender program has to save the message and its ID on persistent storage at the time it sends it. The bridge dequeues each message from the source and enqueues it to the destination, all in the context of a XA batch transaction (10 messages by default):

03/03/12 10:12:11,859000000	"Bridge: TestBridge (processMessages()) received message:
                                 JMS Message Class: TextMessage
                                 JMSMessageID: ID:B3AD885BC54B4391976BEDA9EC00E8F4
                                 JMSCorrelationID: null
                                 JMSDeliveryMode: PERSISTENT
                                 JMSDestination: TestQueue
                                 JMSExpiration: 0
                                 JMSPriority: 8
                                 JMSRedelivered: false
                                 JMSReplyTo: null
                                 JMSTimestamp: 1330851452000 (Sun Mar 04 09:57:32 CET 2012)
                                 JMSType: null
                                 Transaction Id: BEA1-00018D19CC5B9E472B1E
                                 This is a test message: 010"
03/03/12 10:12:11,859000000	"Bridge: TestBridge (processMessages()) successfully sent message:
                                 JMS Message Class: TextMessage
                                 Old JMS MessageID: ID:B3AD885BC54B4391976BEDA9EC00E8F4
                                 New JMS MessageID: ID:2064fac7-65da-11e1-9824-005056c00008
                                 This is a test message: 010"
03/03/12 10:12:12,671000000	Bridge: TestBridge (processMessages()) committed the transaction

References


Debugging Java Stored Procedures

I’ve been a fan of developing Java software stored in Oracle Databases for the last years, it’s the perfect partner of PL/SQL,  where this structured language is difficult to deal with or simply can’t achieve the goal.

One of my first problems was remote debugging, a common issue for every programmer.

First of all, I asked my DBA for the DEBUG CONNECT SESSION system privilege. When I got it, I had to configure my JDeveloper project for remote debugging, I started using the version 10g of this powerful IDE, so I changed the project properties in order to listen for JPDA (Java Platform Debugger Architecture) connections:

Project properties for remote debugging, JDeveloper 10g

Nowadays, I’m working with JDeveloper 11g, where I have to configure a Run/Debug/Profile within the project properties, clicking on the Remote Debugging check-box of the Launch Settings and adjusting the same parameters of the former version:

Project properties for remote debugging, JDeveloper 11g

Later on, the next step was to set the breakpoints I needed in the code, so I could go to the menu Run → Debug, in order to listen for remote debugging sessions. At this point, I was asked for the details of the connection:

Listening process parameters

Once I started the listening process, I could check for it checking the Run Manager.

The next step was to run SQL*Plus (nowadays I use SQLDeveloper), logging on the Database and calling the procedure dbms_debug_jdwp.connect_tcp with two VARCHAR2 parameters: the IP direction of my PC and  the port where my IDE was listening for JPDA connections.

After that, I started my debugging session calling the PL/SQL wrapper from SQL*Plus.

When I finished my debugging session, I ran the procedure dbms_debug_jdwp.disconnect from SQL*Plus and I used the Run Manager of JDeveloper to terminate the listening process.

Finally, I would like to talk of some problems I’ve suffered from: sometimes the debugger disconnects the session without any reason, others it disconnects when the Java code throws an exception in order to be managed by the calling PL/SQL, both times the Oracle Database connection is finished too.