    001    /**
    002     * Copyright 2007-2008 Arthur Blake
    003     *
    004     * Licensed under the Apache License, Version 2.0 (the "License");
    005     * you may not use this file except in compliance with the License.
    006     * You may obtain a copy of the License at
    007     *
    008     *    http://www.apache.org/licenses/LICENSE-2.0
    009     *
    010     * Unless required by applicable law or agreed to in writing, software
    011     * distributed under the License is distributed on an "AS IS" BASIS,
    012     * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    013     * See the License for the specific language governing permissions and
    014     * limitations under the License.
    015     */
    016    package net.sf.log4jdbc;
    017
    018    import org.slf4j.LoggerFactory;
    019    import org.slf4j.Logger;
    020
    021    /**
    022     * Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
    023     *
    024     * @author Arthur Blake
    025     */
    026    public class Slf4jSpyLogDelegator implements SpyLogDelegator
    027    {
    028      /**
    029       * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
    030       */
    031      public Slf4jSpyLogDelegator()
    032      {
    033      }
    034
    035      // logs for sql and jdbc
    036
    037      /**
    038       * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
    039       */
    040      private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");
    041
    042      /**
    043       * Logger that shows JDBC calls for ResultSet operations
    044       */
    045      private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");
    046
    047      /**
    048       * Logger that shows only the SQL that is occuring
    049       */
    050      private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");
    051
    052      /**
    053       * Logger that shows the SQL timing, post execution
    054       */
    055      private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");
    056
    057      // admin/setup logging for log4jdbc.
    058
    059      /**
    060       * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
    061       */
    062      private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");
    063
    064      /**
    065       * Determine if any of the 4 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset |
    066       * jdbc.sqlonly | jdbc.sqltiming.)
    067       *
    068       * @return true if any of the 4 spy jdbc/sql loggers are enabled at debug info or error level.
    069       */
    070      public boolean isJdbcLoggingEnabled()
    071      {
    072        return jdbcLogger.isErrorEnabled() || resultSetLogger.isErrorEnabled() || sqlOnlyLogger.isErrorEnabled() ||
    073          sqlTimingLogger.isErrorEnabled();
    074      }
    075
    076      /**
    077       * Called when a jdbc method throws an Exception.
    078       *
    079       * @param spy        the Spy wrapping the class that threw an Exception.
    080       * @param methodCall a description of the name and call parameters of the method generated the Exception.
    081       * @param e          the Exception that was thrown.
    082       * @param sql        optional sql that occured just before the exception occured.
    083       * @param execTime   optional amount of time that passed before an exception was thrown when sql was being executed.
    084       *                   caller should pass -1 if not used
    085       */
    086      public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime)
    087      {
    088        String classType = spy.getClassType();
    089        int spyNo = spy.getConnectionNumber();
    090        String header = spyNo + ". " + classType + "." + methodCall;
    091        if (sql == null)
    092        {
    093          jdbcLogger.error(header, e);
    094          sqlOnlyLogger.error(header, e);
    095          sqlTimingLogger.error(header, e);
    096        }
    097        else
    098        {
    099          jdbcLogger.error(header + " " + sql, e);
    100
    101          // if at debug level, display debug info to error log
    102          if (sqlOnlyLogger.isDebugEnabled())
    103          {
    104            sqlOnlyLogger.error(getDebugInfo() + nl + spyNo + ". " + sql, e);
    105          }
    106          else
    107          {
    108            sqlOnlyLogger.error(header + " " + sql, e);
    109          }
    110
    111          // if at debug level, display debug info to error log
    112          if (sqlTimingLogger.isDebugEnabled())
    113          {
    114            sqlTimingLogger.error(getDebugInfo() + nl + spyNo + ". " + sql + " {FAILED after " + execTime + " msec}", e);
    115          }
    116          else
    117          {
    118            sqlTimingLogger.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
    119          }
    120        }
    121      }
    122
    123      /**
    124       * Called when a jdbc method from a Connection, Statement, PreparedStatement, CallableStatement or ResultSet
    125       * returns.
    126       *
    127       * @param spy        the Spy wrapping the class that called the method that returned.
    128       * @param methodCall a description of the name and call parameters of the method that returned.
    129       * @param returnMsg  return value converted to a String for integral types, or String representation for Object
    130       *                   return types this will be null for void return types.
    131       */
    132      public void methodReturned(Spy spy, String methodCall, String returnMsg)
    133      {
    134        String classType = spy.getClassType();
    135        int spyNo = spy.getConnectionNumber();
    136        String header = spyNo + ". " + classType + "." + methodCall + " returned " + returnMsg;
    137        if (ResultSetSpy.classTypeDescription.equals(classType))
    138        {
    139          if (resultSetLogger.isDebugEnabled())
    140          {
    141            resultSetLogger.debug(header + " " + getDebugInfo());
    142          }
    143          else if (resultSetLogger.isInfoEnabled())
    144          {
    145            resultSetLogger.info(header);
    146          }
    147        }
    148        else
    149        {
    150          if (jdbcLogger.isDebugEnabled())
    151          {
    152            jdbcLogger.debug(header + " " + getDebugInfo());
    153          }
    154          else if (jdbcLogger.isInfoEnabled())
    155          {
    156            jdbcLogger.info(header);
    157          }
    158        }
    159      }
    160
    161      /**
    162       * Called when a spied upon object is constructed.
    163       *
    164       * @param spy              the Spy wrapping the class that called the method that returned.
    165       * @param constructionInfo information about the object construction
    166       */
    167      public void constructorReturned(Spy spy, String constructionInfo)
    168      {
    169        // not used in this implementation -- yet
    170      }
    171
    172      private static String nl = System.getProperty("line.separator");
    173
    174      /**
    175       * Special call that is called only for JDBC method calls that contain SQL.
    176       *
    177       * @param spy        the Spy wrapping the class where the SQL occured.
    178       * @param methodCall a description of the name and call parameters of the method that generated the SQL.
    179       * @param sql        sql that occured.
    180       */
    181      public void sqlOccured(Spy spy, String methodCall, String sql)
    182      {
    183        int spyNo = spy.getConnectionNumber();
    184
    185        if (sqlOnlyLogger.isDebugEnabled())
    186        {
    187          sqlOnlyLogger.debug(getDebugInfo() + nl + spyNo + ". " + sql);
    188        }
    189        else if (sqlOnlyLogger.isInfoEnabled())
    190        {
    191          sqlOnlyLogger.info(sql);
    192        }
    193      }
    194
    195      /**
    196       * Special call that is called only for JDBC method calls that contain SQL.
    197       *
    198       * @param spy        the Spy wrapping the class where the SQL occurred.
    199       *
    200       * @param execTime   how long it took the SQL to run, in milliseconds.
    201       *
    202       * @param methodCall a description of the name and call parameters of the
    203       *                   method that generated the SQL.
    204       *
    205       * @param sql        SQL that occurred.
    206       */
    207      public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql)
    208      {
    209        // un-comment to simulate random delay to make testing easier
    210        //execTime = execTime + (long)(Math.random() * 5000);
    211
    212        if (sqlTimingLogger.isErrorEnabled())
    213        {
    214          if (DriverSpy.SqlTimingErrorThresholdEnabled &&
    215              execTime >= DriverSpy.SqlTimingErrorThresholdMsec)
    216          {
    217            sqlTimingLogger.error(
    218              buildSqlTimingDump(spy, execTime, methodCall, sql, true));
    219          }
    220          else if (sqlTimingLogger.isWarnEnabled())
    221          {
    222            if (DriverSpy.SqlTimingWarnThresholdEnabled &&
    223              execTime >= DriverSpy.SqlTimingWarnThresholdMsec)
    224            {
    225              sqlTimingLogger.warn(
    226                buildSqlTimingDump(spy, execTime, methodCall, sql, true));
    227            }
    228            else if (sqlTimingLogger.isDebugEnabled())
    229            {
    230              sqlTimingLogger.debug(
    231                buildSqlTimingDump(spy, execTime, methodCall, sql, true));
    232            }
    233            else if (sqlTimingLogger.isInfoEnabled())
    234            {
    235              sqlTimingLogger.info(
    236                buildSqlTimingDump(spy, execTime, methodCall, sql, false));
    237            }
    238          }
    239        }
    240      }
    241
    242      /**
    243       * Helper method to quickly build a SQL timing dump output String for
    244       * logging.
    245       *
    246       * @param spy        the Spy wrapping the class where the SQL occurred.
    247       *
    248       * @param execTime   how long it took the SQL to run, in milliseconds.
    249       *
    250       * @param methodCall a description of the name and call parameters of the
    251       *                   method that generated the SQL.
    252       *
    253       * @param sql        SQL that occurred.
    254       *
    255       * @param debugInfo  if true, include debug info at the front of the output.
    256       *
    257       * @return a SQL timing dump String for logging.
    258       */
    259      private String buildSqlTimingDump(Spy spy, long execTime, String methodCall,
    260        String sql, boolean debugInfo)
    261      {
    262        StringBuffer out = new StringBuffer();
    263
    264        if (debugInfo)
    265        {
    266          out.append(getDebugInfo());
    267          out.append(nl);
    268          out.append(spy.getConnectionNumber());
    269          out.append(". ");
    270        }
    271
    272        out.append(sql);
    273        out.append(" {executed in ");
    274        out.append(execTime);
    275        out.append(" msec}");
    276
    277        return out.toString();
    278      }
    279
    280      /**
    281       * Get debugging info - the module and line number that called the logger
    282       * version that prints the stack trace information from the point just before
    283       * we got it (net.sf.log4jdbc)
    284       *
    285       * if the optional log4jdbc.debug.stack.prefix system property is defined then
    286       * the last call point from an application is shown in the debug
    287       * trace output, instead of the last direct caller into log4jdbc
    288       *
    289       * @return debugging info for whoever called into JDBC from within the application.
    290       */
    291      private static String getDebugInfo()
    292      {
    293        Throwable t = new Throwable();
    294        t.fillInStackTrace();
    295        StackTraceElement[] stackTrace = t.getStackTrace();
    296
    297        if (stackTrace != null)
    298        {
    299          int firstLog4jdbcCall = 0;
    300          int lastApplicationCall = 0;
    301
    302          String className;
    303          for (int i = 0; i < stackTrace.length; i++)
    304          {
    305            className = stackTrace[i].getClassName();
    306            if (className.startsWith("net.sf.log4jdbc"))
    307            {
    308              firstLog4jdbcCall = i;
    309            }
    310            else if (DriverSpy.TraceFromApplication &&
    311              className.startsWith(DriverSpy.DebugStackPrefix))
    312            {
    313              lastApplicationCall = i;
    314              break;
    315            }
    316          }
    317
    318          StringBuffer dump = new StringBuffer(" ");
    319          int j = lastApplicationCall;
    320
    321          if (j == 0)  // if app not found, then use whoever was the last guy that called a log4jdbc class.
    322          {
    323            j = 1 + firstLog4jdbcCall;
    324          }
    325
    326          dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").
    327            append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
    328
    329          return dump.toString();
    330        }
    331        else
    332        {
    333          return null;
    334        }
    335      }
    336
    337      /**
    338       * Log a Setup and/or administrative log message for log4jdbc.
    339       *
    340       * @param msg message to log.
    341       */
    342      public void debug(String msg)
    343      {
    344        debugLogger.debug(msg);
    345      }
    346    }
    347