logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Michael Erskine <michael.ersk...@ketech.com>
Subject RE: Writing to Database
Date Fri, 09 Jan 2009 09:39:12 GMT
Aswani Kommireddy [mailto:sriaswani@gmail.com]:-
> We want to write Logs to database, but not one DB call per logging
> event.
> Plans are like collecting all logging events till the end of each
> server request, and commit that to database as a single message(single
> record). I mean collect all log messages of a request (client - server
> client) into some sort of buffer, and insert all those messages buffer
> as a single message (clob data) into the DB table.

I don't know what's stopping you just coding this -- I could write it for you but my standard
contract rate applies :)

Some hints below: with a custom appender, queue up all your logged events and flush them upon
some trigger using a background thread for db writing...

import java.beans.PropertyChangeListener;
import java.beans.PropertyChangeSupport;
import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.Timestamp;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.BlockingDeque;
import java.util.concurrent.LinkedBlockingDeque;

import org.apache.commons.lang.StringUtils;
import org.apache.commons.lang.math.NumberUtils;
import org.apache.commons.lang.time.DateUtils;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.Layout;
import org.apache.log4j.Level;
import org.apache.log4j.helpers.LogLog;
import org.apache.log4j.spi.LoggingEvent;

public class CollectingAppender extends AppenderSkeleton {
     /**
     * Time in epoch milliseconds that any CollectingAppender instance last
     * failed to connect to its database: initialised to -1 which means no
     * appender has yet tried, 0 means connected OK, and a positive value is a
     * timestamp
     */
    public static long dbFailureTime = -1;
    /**
     * Upon failure don't hammer the connection port
     */
    private static long dbFailureRetryInterval = 60000;
    /**
     * Blocking double-ended queue allowing asynchronous processing of event
     * information by a background thread.
     */
    private BlockingDeque<EvtData> evtDataQueue = null;
    /** Logging database driver class name */
    private String dbdriver = "com.mysql.jdbc.Driver";
    /** Logging database url - normally contains user and password too */
    private String dburl = "jdbc:mysql://localhost/whatever?user=whatever&password=whatever";
    /** Logging database username - only used if set */
    private String dbuser = null;
    /** Logging database password - only used if set */
    private String dbpass = null;
    /** The single database connection - initially null */
    private Connection dbcon = null;
    /** The database prepared statement - initially null */
    private PreparedStatement dbps = null;
    /** The connection can be flagged suspect */
    private boolean dbconsuspect = false;
    /** Limited size for logged message text. */
    private int maxMessageLength = 1200;
    /** Limited size for logged exception text. */
    private int maxExceptionLength = 1200;
    /** Timestamp of last database purge. */
    /** Database purge statement - configurable. */
    private String purgeStatement = "delete from whatever_log "
            + "WHERE evt_time < DATE_SUB(CURDATE(),INTERVAL 10 DAY)";
    /** Time between database purges in hours - defaults to 4. */
    private long purgeIntervalHours = 4;
    private long purgeLast = 0;

    /** Last logged message property that can be tracked by observers. */
    private String lastLoggedMessage = "nothing logged!";
    /** Property change support mechanism for tracking logs */
    private PropertyChangeSupport changes = new PropertyChangeSupport(this);

    /**
     * Have a limited length queue for incoming log events. A zero size means
     * unlimited.
     */
    private int maxQueueSize = 300;

    /**
     * The database event logging insert statement - must have correct
     * parameters
     */
    private String dbinsert = "INSERT INTO whatever_log ("
            + "evt_time, evt_level, evt_loggername, evt_threadname,"
            + "evt_rendered, evt_exception, evt_layout"
            + ") VALUES (?, ?, ?, ?, ?, ?, ?)";

    /**
     * Simple query to test a database connection. Should return a single row
     * with a single column
     */
    private String dbteststring = "SELECT VERSION()";

    /** Background thread to process async queue */
    private Thread bg_thread;

    /** Set when shutdown */
    private boolean shutdown = false;
    /**
     * A logged event that is queued for writing to the logging database in a
     * background thread.
     *
     * @author Michael Erskine
     */
    public class EvtData {

        private String level;
        private long timeStamp;
        private String loggerName;
        private String threadName;
        private String renderedMessage;
        private String exception;
        private String layoutMsg;

        /**
         * @param level
         * @param timeStamp
         * @param loggerName
         * @param threadName
         * @param renderedMessage
         * @param throwableStrRep
         * @param layoutMsg
         */
        public EvtData(String level, long timeStamp, String loggerName,
                String threadName, String renderedMessage,
                String[] throwableStrRep, String layoutMsg) {

            this.level = level;
            this.timeStamp = timeStamp;
            this.loggerName = loggerName;
            this.threadName = threadName;
            this.renderedMessage = StringUtils.abbreviate(renderedMessage,
                getMaxMessageLength());
            if (throwableStrRep != null) {
                exception = sm.join(Arrays.asList(throwableStrRep));
                exception = StringUtils.abbreviate(exception,
                    getMaxExceptionLength());
                // Tack on to the layout message...
                layoutMsg += exception;
            }
            this.layoutMsg = StringUtils.abbreviate(layoutMsg,
                getMaxMessageLength());
        }
    }

    /*
     * (non-Javadoc)
     *
     * @see org.apache.log4j.AppenderSkeleton#requiresLayout()
     */
    public boolean requiresLayout() {
        return true;
    }

    /*
     * (non-Javadoc)
     *
     * @see org.apache.log4j.AppenderSkeleton#activateOptions()
     */
    @Override
    public void activateOptions() {
        LogLog.debug("lma activateOptions called!");
        if (evtDataQueue != null) {
            LogLog.warn("lma queue exists already and will be discarded ("
                    + evtDataQueue.size() + " items lost)");
            evtDataQueue.clear();
            evtDataQueue = null;
        }
        ensureQueue();
    }

    /*
     * (non-Javadoc)
     *
     * @see org.apache.log4j.AppenderSkeleton#append(org.apache.log4j.spi.LoggingEvent)
     */
    @Override
    protected void append(LoggingEvent ev) {
        if (shutdown) {
            LogLog.error("lma append when shutdown - Main closing?");
            return;
        }

        // Get the useful elements from the event object...
        Level lev = ev.getLevel();
        String level = lev == null ? null : lev.toString();
        // The timestamp is in epoch milliseconds as received
        // from System.currentTimeMillis() and is a wall clock time
        // that tracks system clock changes. It is for human consumption only!
        // and should not be used as an interval measurement...
        long timeStamp = ev.getTimeStamp();
        String loggerName = ev.getLoggerName();
        String threadName = ev.getThreadName();
        String renderedMessage = ev.getRenderedMessage();
        String[] throwableStrRep = ev.getThrowableStrRep();
        Layout lay = getLayout();
        String layoutMsg = null;
        if (lay != null) {
            layoutMsg = lay.format(ev);
        }

        // Add an event data object to the queue to be processed soon...
        EvtData ed = new EvtData(level, timeStamp, loggerName, threadName,
            renderedMessage, throwableStrRep, layoutMsg);
        // Bootstrap bg thread...
        if (bg_thread == null)
            startBgThread();
        // Attempt to add to queue - if full then there's nothing we can do
        if (!evtDataQueue.offer(ed))
            LogLog.error("lma queue is full - message lost!");
    }

    /**
     * Write the given event data to the logging database.
     * <p>
     * Performed in background thread.
     *
     * @param evtData
     *                Event data.
     */
    private void writeDbEvtData(EvtData evtData) {
        if (evtData == null) {
            LogLog.error("lma - null event data");
            return;
        }
        // Forward logged event to any listeners...
        setLastLoggedMessage(evtData.layoutMsg);
        // Bootstrap db connection if necessary...
        if (findConnection() == null) {
            LogLog.debug("lma no connection found");
            return;
        }
        // Prepare the logging insert statement if necessary...
        if (dbps == null) {
            try {
                dbps = dbcon.prepareStatement(dbinsert);
            } catch (SQLException e) {
                LogLog.error("lma failed to prepare insert statement", e);
                return;
            }
        }
        try {
            int col = 0;
            dbps.setTimestamp(++col, new Timestamp(evtData.timeStamp));
            dbps.setString(++col, evtData.level);
            dbps.setString(++col, evtData.loggerName);
            dbps.setString(++col, evtData.threadName);
            dbps.setString(++col, evtData.renderedMessage);
            dbps.setString(++col, evtData.exception);
            dbps.setString(++col, evtData.layoutMsg);
            dbps.execute();
            if (evtData.layoutMsg != null) {
                // LogLog.debug("lma wrote: " + evtData.layoutMsg);
            }
        } catch (SQLException e) {
            LogLog.error("lma failed to execute insert statement", e);
            dbconsuspect = true;
        }
    }

    /**
     * Database connection finder. - when not connected, connect
     *
     * @return a possibly usable database connection or null if none found.
     */
    private Connection findConnection() {
        // Some database activity previously failed on this connection:
        // test the connection to the database with a simple known working
        // query and if that fails abandon the connection so that it will
        // be re-established...
        if (dbcon != null && dbconsuspect) {
            try {
                List<String[]> lsa = DbUtils.doquery(dbcon, getDbteststring());
                String[] row = lsa.get(1);
                LogLog.debug("lma suspect test result: '" + row[0] + "'");
                dbconsuspect = false;
                // continue to use this connection since it works
            } catch (Exception e) {
                LogLog.error("lma suspect test failed", e);
            }
            // Still suspect so close...
            if (dbconsuspect) {
                DbUtils.closeQuietly(dbcon, dbps, null);
                dbcon = null;
                dbps = null;
                // How about using Connection.isValid(timeout)
            }
        }

        // A null connection requires us to attempt to make a connection...
        // TODO: could also cope with a config change here!
        if (dbcon == null) {
            dbconsuspect = true;

            // Back off reconnecting when operating in db failure mode...
            if (dbFailureTime > 0
                    && now() < dbFailureTime + dbFailureRetryInterval) {
                return dbcon;
            }
            LogLog.debug("lma null dbcon - try connect");
            try {
                dbcon = DbUtils.dbConnect(dbdriver, dburl, dbuser, dbpass);
                LogLog.debug("lma got connection");
                dbFailureTime = 0;
            } catch (SQLException e) {
                LogLog.error("lma jdbc connect problem - check db");
                dbFailureTime = now();
            } catch (ClassNotFoundException e) {
                LogLog.error("lma jdbc driver problem: ", e);
            }
        }

        return dbcon;
    }

    /**
     * Get a timestamp that can be used in the same manner as
     * {@link System#currentTimeMillis()}.
     *
     * @return a millisecond resolution timestamp
     */
    private long now() {
        return TimeBroker.offsetLaunch();
    }

    @Override
    public void close() {
        shutdown = true;
        // Close the database connection
        DbUtils.closeQuietly(dbcon, dbps, null);
        dbcon = null;
        dbps = null;
        // Stop the background thread...
        stopBgThread();
    }

    private void startBgThread() {
        Runnable r = new Runnable() {
            @Override
            public void run() {
                LogLog.debug("lma bgthread starting");
                while (!shutdown) {
                    try {

OK, here you'll want to hang fire until a signal to flush is made by whatever means

                        EvtData e = evtDataQueue.take();
                        if (!shutdown) {
                            writeDbEvtData(e);
                        }
                    } catch (InterruptedException e) {
                        LogLog.debug("lma bgthread interrupted");
                    }
                }
                LogLog.debug("lma bgthread finished");
            }
        };
        bg_thread = new Thread(r, "lma-bg");
        bg_thread.setDaemon(true);
        bg_thread.start();
    }

    private void stopBgThread() {
        if (bg_thread == null)
            return;
        // If already completed, dereference...
        if (!bg_thread.isAlive()) {
            bg_thread = null;
        } else {

            // TODO properly interrupt thread when blocking on queue - how is
            // this done in other systems?
            bg_thread.interrupt();

        }

    }

    private void ensureQueue() {
        // Bootstrap queue...
        if (evtDataQueue == null) {
            LogLog.debug("lma creating queue with max " + getMaxQueueSize());
            if (getMaxQueueSize() > 0) {
                evtDataQueue = new LinkedBlockingDeque<EvtData>(
                    getMaxQueueSize());
            } else {
                evtDataQueue = new LinkedBlockingDeque<EvtData>();
            }
        }
    }

    /**
     * Get the size of the Logged Event Queue.
     *
     * @return event queue size or zero if the queue is null
     */
    public int getEvtDataQueueSize() {
        if (evtDataQueue == null) {
            return 0;
        }
        return evtDataQueue.size();
    }

    /**
     * Delete old log entries using the configured dbpurge statement.
     * <p>
     * Limited frequency of execution controlled by a timestamp.
     */
    public void purgeExpiredDbEvents() {
        // Do nothing if not enough time has passed since previous purge...
        if (now() < purgeLast
                + (purgeIntervalHours * DateUtils.MILLIS_PER_HOUR)) {
            return;
        }
        LogLog.debug("purgeExpiredDbEvents running");

        // Operate with temporary objects...
        try {
            Connection con = DbUtils.dbConnect(dbdriver, dburl, dbuser, dbpass);
            Statement stmt = con.createStatement();
            stmt.execute(purgeStatement);
            int updateCount = stmt.getUpdateCount();
            LogLog.debug("purgeExpiredDbEvents rows deleted: " + updateCount);
            DbUtils.closeQuietly(con, stmt, null);
        } catch (SQLException e) {
            LogLog.error("failed:" + e.getMessage(), e);
        } catch (ClassNotFoundException e) {
            LogLog.error("failed:" + e.getMessage(), e);
        }
        // Update the timestamp...
        purgeLast = now();
    }

    public String getPurgeStatement() {
        return purgeStatement;
    }

    public void setPurgeStatement(String st) {
        this.purgeStatement = st;
    }

    public long getPurgeIntervalHours() {
        return purgeIntervalHours;
    }

    public void setPurgeIntervalHours(long val) {
        this.purgeIntervalHours = val;
    }

    public void setBuffer(String invalue) {
        int v = NumberUtils.toInt(invalue, -1);
        if (v < 0) {
            String errorMsg = "lma buffer value '" + invalue + "' not valid";
            LogLog.error(errorMsg);
            errorHandler.error(errorMsg, null, 0);
            return;
        }
// buffer_size = v;
    }

    public void setDbdriver(String dbdriver) {
        this.dbdriver = dbdriver;
    }

    public String getDbdriver() {
        return dbdriver;
    }

    public void setDburl(String dburl) {
        this.dburl = dburl;
    }

    public String getDburl() {
        return dburl;
    }

    public void setDbuser(String dbuser) {
        this.dbuser = dbuser;
    }

    public String getDbuser() {
        return dbuser;
    }

    public void setDbpass(String dbpass) {
        this.dbpass = dbpass;
    }

    public String getDbpass() {
        return dbpass;
    }

    public void setDbteststring(String dbteststring) {
        this.dbteststring = dbteststring;
    }

    public String getDbteststring() {
        return dbteststring;
    }

    public void setDbinsert(String dbinsert) {
        this.dbinsert = dbinsert;
    }

    public String getDbinsert() {
        return dbinsert;
    }

    public void setMaxMessageLength(int maxMessageLength) {
        int v = maxMessageLength;
        if (v < 6) {
            LogLog.error("lma maxMessageLength must be > 5");
            v = 6;
        }
        this.maxMessageLength = v;
    }

    public int getMaxMessageLength() {
        return maxMessageLength;
    }

    public void setMaxExceptionLength(int maxExceptionLength) {
        int v = maxExceptionLength;
        if (v < 6) {
            LogLog.error("lma maxExceptionLength must be > 5");
            v = 6;
        }
        this.maxExceptionLength = v;
    }

    public int getMaxExceptionLength() {
        return maxExceptionLength;
    }

    public void setMaxQueueSize(int maxQueueSize) {
        this.maxQueueSize = maxQueueSize;
    }

    public int getMaxQueueSize() {
        return maxQueueSize;
    }

    /**
     * Gets the last logged message.
     *
     * @return the last logged message
     */
    public String getLastLoggedMessage() {
        return lastLoggedMessage;
    }

    /**
     * Sets the last logged message.
     *
     * @param lastLoggedMessage
     *                the new last logged message
     */
    public void setLastLoggedMessage(String lastLoggedMessage) {
        // Avoid firing off noise when nothing is really happening - this is
        // generally good practice for PropertyChangeSupport...
        if (this.lastLoggedMessage == null && lastLoggedMessage == null) {
            return;
        }
        changes.firePropertyChange("lastLoggedMessage", this.lastLoggedMessage,
            this.lastLoggedMessage = lastLoggedMessage);
    }

    /**
     * Adds a listener to receive last logged message changes.
     *
     * @param propertyName
     *                the property to listen on
     * @param listener
     *                the listener
     */
    public void addEventsListener(String propertyName,
            PropertyChangeListener listener) {
        changes.addPropertyChangeListener("lastLoggedMessage", listener);
    }

}

...of course there's a lot more to it - this is (most of) a generic asynchronous JDBC appender
with a fault-tolerant DB connection (pooling would be preferred) which serves me very well.
When I get round to it I'll publish my Log4j extensions under a suitable license.

Regards,
Michael Erskine.


---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
View raw message