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):

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

• How do I enable debugging for the messaging bridge?
• Subscribing to Weblogic logging Messages
• MessagingBridge Subsystem Messages