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