All Downloads are FREE. Search and download functionalities are using the official Maven repository.

net.sf.log4jdbc.Slf4jSpyLogDelegator Maven / Gradle / Ivy

/**
 * Copyright 2007-2010 Arthur Blake
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *    http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package net.sf.log4jdbc;

import java.util.StringTokenizer;


import org.slf4j.LoggerFactory;
import org.slf4j.Logger;

/**
 * Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
 * 
 * @author Arthur Blake
 */
public class Slf4jSpyLogDelegator implements SpyLogDelegator
{
    /**
   * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
     */
    public Slf4jSpyLogDelegator()
    {
    }

    // logs for sql and jdbc

    /**
     * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
     */
    private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");

    /**
     * Logger that shows JDBC calls for ResultSet operations
     */
    private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");

    /**
     * Logger that shows the forward scrolled result sets in a table
     */
    private final Logger resultSetTableLogger = LoggerFactory.getLogger("jdbc.resultsettable");
    
    /**
     * Logger that shows only the SQL that is occuring
     */
    private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");

    public Logger getSqlOnlyLogger()
    {
        return sqlOnlyLogger;
    }

    /**
     * Logger that shows the SQL timing, post execution
     */
    private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");

    /**
     * Logger that shows connection open and close events as well as current number
     * of open connections.
     */
    private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");

    // admin/setup logging for log4jdbc.

    /**
     * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
     */
    private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");

    /**
     * Determine if any of the 6 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset |
     * jdbc.sqlonly | jdbc.sqltiming | jdbc.connection)
     *
     * @return true if any of the 6 spy jdbc/sql loggers are enabled at debug info or error level.
     */
    public boolean isJdbcLoggingEnabled()
    {
      return jdbcLogger.isErrorEnabled() || resultSetLogger.isErrorEnabled() || sqlOnlyLogger.isErrorEnabled() ||
        sqlTimingLogger.isErrorEnabled() || connectionLogger.isErrorEnabled() || resultSetTableLogger.isErrorEnabled();
    }
    
    

    /**
     * Called when a jdbc method throws an Exception.
     * 
     * @param spy the Spy wrapping the class that threw an Exception.
     * @param methodCall a description of the name and call parameters of the method generated the Exception.
     * @param e the Exception that was thrown.
     * @param sql optional sql that occured just before the exception occured.
     * @param execTime   optional amount of time that passed before an exception was thrown when sql was being executed.
     *                   caller should pass -1 if not used
     */
    public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime)
    {
        String classType = spy.getClassType();
        Integer spyNo = spy.getConnectionNumber();
        String header = spyNo + ". " + classType + "." + methodCall;
        if (sql == null)
        {
            jdbcLogger.error(header, e);
            sqlOnlyLogger.error(header, e);
            sqlTimingLogger.error(header, e);
        }
        else
        {
            jdbcLogger.error(header + " " + sql, e);

            // if at debug level, display debug info to error log
            if (sqlOnlyLogger.isDebugEnabled())
            {
                sqlOnlyLogger.error(getDebugInfo() + nl + spyNo + ". " + sql, e);
            }
            else
            {
                sqlOnlyLogger.error(header + " " + sql, e);
            }

            // if at debug level, display debug info to error log
            if (sqlTimingLogger.isDebugEnabled())
            {
                sqlTimingLogger.error(getDebugInfo() + nl + spyNo + ". " + sql + " {FAILED after " + execTime + " msec}", e);
            }
            else
            {
                sqlTimingLogger.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
            }
        }
    }

    /**
     * Called when a JDBC method from a Connection, Statement, PreparedStatement,
     * CallableStatement or ResultSet returns.
     * 
     * @param spy        the Spy wrapping the class that called the method that 
     *                   returned.
     * @param methodCall a description of the name and call parameters of the 
     *                   method that returned.
     * @param returnMsg  return value converted to a String for integral types, or
     *                   String representation for Object.  Return types this will
     *                   be null for void return types.
     */
    public void methodReturned(Spy spy, String methodCall, Object returnMsg, Object object, Object... methodParams)
    {
        String classType = spy.getClassType();
        Logger logger = ResultSetSpy.classTypeDescription.equals(classType) ? 
          resultSetLogger : jdbcLogger;
        if (logger.isInfoEnabled())
        {
            String header = spy.getConnectionNumber() + ". " + classType + "." + 
              methodCall + " returned " + returnMsg;
            if (logger.isDebugEnabled())
            {
                logger.debug(header + " " + getDebugInfo());
            }
            else
            {
                logger.info(header);
            }
        }
    }

    /**
     * Called when a spied upon object is constructed.
     * 
     * @param spy the Spy wrapping the class that called the method that returned.
     * @param constructionInfo information about the object construction
     */
    public void constructorReturned(Spy spy, String constructionInfo)
    {
        // not used in this implementation -- yet
    }

    private static String nl = System.getProperty("line.separator");

    /**
   * Determine if the given sql should be logged or not
   * based on the various DumpSqlXXXXXX flags.
     * 
     * @param sql SQL to test.
     * @return true if the SQL should be logged, false if not.
     */
    private boolean shouldSqlBeLogged(String sql)
    {
        if (sql == null)
        {
            return false;
        }
        sql = sql.trim();

        if (sql.length() < 6)
        {
            return false;
        }
        sql = sql.substring(0, 6).toLowerCase();
        return 
          (DriverSpy.DumpSqlSelect && "select".equals(sql)) ||
          (DriverSpy.DumpSqlInsert && "insert".equals(sql)) ||
          (DriverSpy.DumpSqlUpdate && "update".equals(sql)) ||
          (DriverSpy.DumpSqlDelete && "delete".equals(sql)) ||
          (DriverSpy.DumpSqlCreate && "create".equals(sql));
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * 
     * @param spy the Spy wrapping the class where the SQL occured.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql sql that occured.
     */
    public String sqlOccured(Spy spy, String methodCall, String sql)
    {
        if (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql))
        {
            sql = processSql(sql);

            if (sqlOnlyLogger.isDebugEnabled())
            {
                sqlOnlyLogger.debug(getDebugInfo() + nl + spy.getConnectionNumber() + ". " + sql);
            }
            else if (sqlOnlyLogger.isInfoEnabled())
            {
                sqlOnlyLogger.info(sql);
            }
            return sql;
        }
        return "";
    }

    @Override
    public String sqlOccured(Spy spy, String methodCall, String[] sqls)
    {

        StringBuffer batchReport = new StringBuffer("batching " + sqls.length + " statements:");
        int fieldSize = ("" + sqls.length).length();
        String sql;
        for (int i = 0; i < sqls.length; i++)
        {
            sql = sqls[i];
            batchReport.append("\n");
            batchReport.append(Utilities.rightJustify(fieldSize, "" + i));
            batchReport.append(":  ");
            batchReport.append(sql);
        }
        sql = batchReport.toString();
        sqlOccured(spy, methodCall, sql);
        return sql;
    }

    /**
     * Break an SQL statement up into multiple lines in an attempt to make it
     * more readable
     * 
     * @param sql SQL to break up.
     * @return SQL broken up into multiple lines
     */
    private String processSql(String sql)
    {
        if (sql == null)
        {
            return null;
        }

        if (DriverSpy.TrimSql)
        {
            sql = sql.trim();
        }

        StringBuffer output = new StringBuffer();

        if (DriverSpy.DumpSqlMaxLineLength <= 0)
        {
            output.append(sql);
        }
        else
        {
            // insert line breaks into sql to make it more readable
            StringTokenizer st = new StringTokenizer(sql);
            String token;
            int linelength = 0;

            while (st.hasMoreElements())
            {
                token = (String) st.nextElement();

                output.append(token);
                linelength += token.length();
                output.append(" ");
                linelength++;
                if (linelength > DriverSpy.DumpSqlMaxLineLength)
                {
                    output.append("\n");
                    linelength = 0;
                }
            }
        }

        if (DriverSpy.DumpSqlAddSemicolon)
        {
            output.append(";");
        }

        return output.toString();
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * 
     * @param spy the Spy wrapping the class where the SQL occurred.
     * 
     * @param execTime how long it took the SQL to run, in milliseconds.
     * 
     * @param methodCall a description of the name and call parameters of the
     *                   method that generated the SQL.
     * 
     * @param sql SQL that occurred.
     */
    public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql)
    {
        if (sqlTimingLogger.isErrorEnabled() &&
           (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql)))
        {
            if (DriverSpy.SqlTimingErrorThresholdEnabled && 
                execTime >= DriverSpy.SqlTimingErrorThresholdMsec)
            {
                sqlTimingLogger.error(
                  buildSqlTimingDump(spy, execTime, methodCall, sql, true));
            }
            else if (sqlTimingLogger.isWarnEnabled())
            {
                if (DriverSpy.SqlTimingWarnThresholdEnabled && 
                  execTime >= DriverSpy.SqlTimingWarnThresholdMsec)
                {
                    sqlTimingLogger.warn(
                      buildSqlTimingDump(spy, execTime, methodCall, sql, true));
                }
                else if (sqlTimingLogger.isDebugEnabled())
                {
                    sqlTimingLogger.debug(
                      buildSqlTimingDump(spy, execTime, methodCall, sql, true));
                }
                else if (sqlTimingLogger.isInfoEnabled())
                {
                    sqlTimingLogger.info(
                      buildSqlTimingDump(spy, execTime, methodCall, sql, false));
                }
            }
        }
    }

    /**
     * Helper method to quickly build a SQL timing dump output String for
     * logging.
     * 
     * @param spy the Spy wrapping the class where the SQL occurred.
     * 
     * @param execTime how long it took the SQL to run, in milliseconds.
     * 
     * @param methodCall a description of the name and call parameters of the
     *                   method that generated the SQL.
     * 
     * @param sql SQL that occurred.
     * 
     * @param debugInfo if true, include debug info at the front of the output.
     * 
     * @return a SQL timing dump String for logging.
     */
    private String buildSqlTimingDump(Spy spy, long execTime, String methodCall, 
      String sql, boolean debugInfo)
    {
        StringBuffer out = new StringBuffer();

        if (debugInfo)
        {
            out.append(getDebugInfo());
            out.append(nl);
            out.append(spy.getConnectionNumber());
            out.append(". ");
        }

        // NOTE: if both sql dump and sql timing dump are on, the processSql
        // algorithm will run TWICE once at the beginning and once at the end
        // this is not very efficient but usually
        // only one or the other dump should be on and not both.

        sql = processSql(sql);

        out.append(sql);
        out.append(" {executed in ");
        out.append(execTime);
        out.append(" msec}");

        return out.toString();
    }

    /**
     * Get debugging info - the module and line number that called the logger
     * version that prints the stack trace information from the point just before
     * we got it (net.sf.log4jdbc)
     * 
     * if the optional log4jdbc.debug.stack.prefix system property is defined then
     * the last call point from an application is shown in the debug
     * trace output, instead of the last direct caller into log4jdbc
     * 
     * @return debugging info for whoever called into JDBC from within the application.
     */
    private static String getDebugInfo()
    {
        Throwable t = new Throwable();
        t.fillInStackTrace();

        StackTraceElement[] stackTrace = t.getStackTrace();

        if (stackTrace != null)
        {
            String className;

            StringBuffer dump = new StringBuffer();

            /**
             * The DumpFullDebugStackTrace option is useful in some situations when
             * we want to see the full stack trace in the debug info- watch out
             * though as this will make the logs HUGE!
             */
            if (DriverSpy.DumpFullDebugStackTrace)
            {
                boolean first = true;
                for (int i = 0; i < stackTrace.length; i++)
                {
                    className = stackTrace[i].getClassName();
                    if (!className.startsWith("net.sf.log4jdbc"))
                    {
                        if (first)
                        {
                            first = false;
                        }
                        else
                        {
                            dump.append("  ");
                        }
                        dump.append("at ");
                        dump.append(stackTrace[i]);
                        dump.append(nl);
                    }
                }
            }
            else
            {
                dump.append(" ");
                int firstLog4jdbcCall = 0;
                int lastApplicationCall = 0;

                for (int i = 0; i < stackTrace.length; i++)
                {
                    className = stackTrace[i].getClassName();
                    if (className.startsWith("net.sf.log4jdbc"))
                    {
                        firstLog4jdbcCall = i;
                    }
                    else if (DriverSpy.TraceFromApplication && 
                      className.startsWith(DriverSpy.DebugStackPrefix))
                    {
                        lastApplicationCall = i;
                        break;
                    }
                }
                int j = lastApplicationCall;

                if (j == 0) // if app not found, then use whoever was the last guy that called a log4jdbc class.
                {
                    j = 1 + firstLog4jdbcCall;
                }

        dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").
          append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
            }

            return dump.toString();
        }
        else
        {
            return null;
        }
    }

    /**
     * Log a Setup and/or administrative log message for log4jdbc.
     * 
     * @param msg message to log.
     */
    public void debug(String msg)
    {
        debugLogger.debug(msg);
    }

    /**
     * Called whenever a new connection spy is created.
     * 
     * @param spy ConnectionSpy that was created.
     */
    public void connectionOpened(Spy spy)
    {
        if (connectionLogger.isDebugEnabled())
        {
            connectionLogger.info(spy.getConnectionNumber() + ". Connection opened " +
              getDebugInfo());
            connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
        }
        else
        {
            connectionLogger.info(spy.getConnectionNumber() + ". Connection opened");
        }
    }

    /**
     * Called whenever a connection spy is closed.
     * 
     * @param spy ConnectionSpy that was closed.
     */
    public void connectionClosed(Spy spy)
    {
        if (connectionLogger.isDebugEnabled())
        {
            connectionLogger.info(spy.getConnectionNumber() + ". Connection closed " +
              getDebugInfo());
            connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
        }
        else
        {
            connectionLogger.info(spy.getConnectionNumber() + ". Connection closed");
        }
    }

    @Override
    public boolean isResultSetCollectionEnabled() {
        return resultSetTableLogger.isInfoEnabled();
    }

    @Override
    public boolean isResultSetCollectionEnabledWithUnreadValueFillIn() {
        return resultSetTableLogger.isDebugEnabled();
    }

    @Override
    public void resultSetCollected(ResultSetCollector resultSetCollector) {
        new ResultSetCollectorPrinter(resultSetTableLogger).printResultSet(resultSetCollector);
    }

}




© 2015 - 2024 Weber Informatics LLC | Privacy Policy