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 java.util.StringTokenizer;
019
020 import org.slf4j.LoggerFactory;
021 import org.slf4j.Logger;
022
023 /**
024 * Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
025 *
026 * @author Arthur Blake
027 */
028 public class Slf4jSpyLogDelegator implements SpyLogDelegator
029 {
030 /**
031 * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
032 */
033 public Slf4jSpyLogDelegator()
034 {
035 }
036
037 // logs for sql and jdbc
038
039 /**
040 * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
041 */
042 private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");
043
044 /**
045 * Logger that shows JDBC calls for ResultSet operations
046 */
047 private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");
048
049 /**
050 * Logger that shows only the SQL that is occuring
051 */
052 private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");
053
054 /**
055 * Logger that shows the SQL timing, post execution
056 */
057 private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");
058
059 /**
060 * Logger that shows connection open and close events as well as current number
061 * of open connections.
062 */
063 private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");
064
065 // admin/setup logging for log4jdbc.
066
067 /**
068 * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
069 */
070 private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");
071
072 /**
073 * Determine if any of the 4 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset |
074 * jdbc.sqlonly | jdbc.sqltiming.)
075 *
076 * @return true if any of the 4 spy jdbc/sql loggers are enabled at debug info or error level.
077 */
078 public boolean isJdbcLoggingEnabled()
079 {
080 return jdbcLogger.isErrorEnabled() || resultSetLogger.isErrorEnabled() || sqlOnlyLogger.isErrorEnabled() ||
081 sqlTimingLogger.isErrorEnabled() || connectionLogger.isErrorEnabled();
082 }
083
084 /**
085 * Called when a jdbc method throws an Exception.
086 *
087 * @param spy the Spy wrapping the class that threw an Exception.
088 * @param methodCall a description of the name and call parameters of the method generated the Exception.
089 * @param e the Exception that was thrown.
090 * @param sql optional sql that occured just before the exception occured.
091 * @param execTime optional amount of time that passed before an exception was thrown when sql was being executed.
092 * caller should pass -1 if not used
093 */
094 public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime)
095 {
096 String classType = spy.getClassType();
097 Integer spyNo = spy.getConnectionNumber();
098 String header = spyNo + ". " + classType + "." + methodCall;
099 if (sql == null)
100 {
101 jdbcLogger.error(header, e);
102 sqlOnlyLogger.error(header, e);
103 sqlTimingLogger.error(header, e);
104 }
105 else
106 {
107 jdbcLogger.error(header + " " + sql, e);
108
109 // if at debug level, display debug info to error log
110 if (sqlOnlyLogger.isDebugEnabled())
111 {
112 sqlOnlyLogger.error(getDebugInfo() + nl + spyNo + ". " + sql, e);
113 }
114 else
115 {
116 sqlOnlyLogger.error(header + " " + sql, e);
117 }
118
119 // if at debug level, display debug info to error log
120 if (sqlTimingLogger.isDebugEnabled())
121 {
122 sqlTimingLogger.error(getDebugInfo() + nl + spyNo + ". " + sql + " {FAILED after " + execTime + " msec}", e);
123 }
124 else
125 {
126 sqlTimingLogger.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
127 }
128 }
129 }
130
131 /**
132 * Called when a jdbc method from a Connection, Statement, PreparedStatement, CallableStatement or ResultSet
133 * returns.
134 *
135 * @param spy the Spy wrapping the class that called the method that returned.
136 * @param methodCall a description of the name and call parameters of the method that returned.
137 * @param returnMsg return value converted to a String for integral types, or String representation for Object
138 * return types this will be null for void return types.
139 */
140 public void methodReturned(Spy spy, String methodCall, String returnMsg)
141 {
142 String classType = spy.getClassType();
143 Integer spyNo = spy.getConnectionNumber();
144 String header = spyNo + ". " + classType + "." + methodCall + " returned " + returnMsg;
145 if (ResultSetSpy.classTypeDescription.equals(classType))
146 {
147 if (resultSetLogger.isDebugEnabled())
148 {
149 resultSetLogger.debug(header + " " + getDebugInfo());
150 }
151 else if (resultSetLogger.isInfoEnabled())
152 {
153 resultSetLogger.info(header);
154 }
155 }
156 else
157 {
158 if (jdbcLogger.isDebugEnabled())
159 {
160 jdbcLogger.debug(header + " " + getDebugInfo());
161 }
162 else if (jdbcLogger.isInfoEnabled())
163 {
164 jdbcLogger.info(header);
165 }
166 }
167 }
168
169 /**
170 * Called when a spied upon object is constructed.
171 *
172 * @param spy the Spy wrapping the class that called the method that returned.
173 * @param constructionInfo information about the object construction
174 */
175 public void constructorReturned(Spy spy, String constructionInfo)
176 {
177 // not used in this implementation -- yet
178 }
179
180 private static String nl = System.getProperty("line.separator");
181
182 /**
183 * Determine if the given sql should be logged or not
184 * based on the various DumpSqlXXXXXX flags.
185 *
186 * @param sql SQL to test.
187 * @return true if the SQL should be logged, false if not.
188 */
189 private boolean shouldSqlBeLogged(String sql)
190 {
191 if (sql == null)
192 {
193 return false;
194 }
195 sql = sql.trim();
196
197 if (sql.length()<6)
198 {
199 return false;
200 }
201 sql = sql.substring(0,6).toLowerCase();
202 return
203 (DriverSpy.DumpSqlSelect && "select".equals(sql)) ||
204 (DriverSpy.DumpSqlInsert && "insert".equals(sql)) ||
205 (DriverSpy.DumpSqlUpdate && "update".equals(sql)) ||
206 (DriverSpy.DumpSqlDelete && "delete".equals(sql)) ||
207 (DriverSpy.DumpSqlCreate && "create".equals(sql));
208 }
209
210 /**
211 * Special call that is called only for JDBC method calls that contain SQL.
212 *
213 * @param spy the Spy wrapping the class where the SQL occured.
214 * @param methodCall a description of the name and call parameters of the method that generated the SQL.
215 * @param sql sql that occured.
216 */
217 public void sqlOccured(Spy spy, String methodCall, String sql)
218 {
219 if (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql))
220 {
221 sql = processSql(sql);
222
223 if (sqlOnlyLogger.isDebugEnabled())
224 {
225 sqlOnlyLogger.debug(getDebugInfo() + nl + spy.getConnectionNumber() + ". " + sql);
226 }
227 else if (sqlOnlyLogger.isInfoEnabled())
228 {
229 sqlOnlyLogger.info(sql);
230 }
231 }
232 }
233
234 /**
235 * Break an SQL statement up into multiple lines in an attempt to make it
236 * more readable
237 *
238 * @param sql SQL to break up.
239 * @return SQL broken up into multiple lines
240 */
241 private String processSql(String sql)
242 {
243 if (sql==null)
244 {
245 return null;
246 }
247
248 sql = sql.trim();
249
250 StringBuffer output = new StringBuffer();
251
252 if (DriverSpy.DumpSqlMaxLineLength <= 0)
253 {
254 output.append(sql);
255 }
256 else
257 {
258 // insert line breaks into sql to make it more readable
259 StringTokenizer st = new StringTokenizer(sql);
260 String token;
261 int linelength = 0;
262
263 while (st.hasMoreElements())
264 {
265 token = (String) st.nextElement();
266
267 output.append(token);
268 linelength += token.length();
269 output.append(" ");
270 linelength++;
271 if (linelength > 90)
272 {
273 output.append("\n");
274 linelength = 0;
275 }
276 }
277 }
278
279 if (DriverSpy.DumpSqlAddSemicolon)
280 {
281 output.append(";");
282 }
283
284 return output.toString();
285 }
286
287 /**
288 * Special call that is called only for JDBC method calls that contain SQL.
289 *
290 * @param spy the Spy wrapping the class where the SQL occurred.
291 *
292 * @param execTime how long it took the SQL to run, in milliseconds.
293 *
294 * @param methodCall a description of the name and call parameters of the
295 * method that generated the SQL.
296 *
297 * @param sql SQL that occurred.
298 */
299 public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql)
300 {
301 if (sqlTimingLogger.isErrorEnabled() &&
302 (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql)))
303 {
304 if (DriverSpy.SqlTimingErrorThresholdEnabled &&
305 execTime >= DriverSpy.SqlTimingErrorThresholdMsec)
306 {
307 sqlTimingLogger.error(
308 buildSqlTimingDump(spy, execTime, methodCall, sql, true));
309 }
310 else if (sqlTimingLogger.isWarnEnabled())
311 {
312 if (DriverSpy.SqlTimingWarnThresholdEnabled &&
313 execTime >= DriverSpy.SqlTimingWarnThresholdMsec)
314 {
315 sqlTimingLogger.warn(
316 buildSqlTimingDump(spy, execTime, methodCall, sql, true));
317 }
318 else if (sqlTimingLogger.isDebugEnabled())
319 {
320 sqlTimingLogger.debug(
321 buildSqlTimingDump(spy, execTime, methodCall, sql, true));
322 }
323 else if (sqlTimingLogger.isInfoEnabled())
324 {
325 sqlTimingLogger.info(
326 buildSqlTimingDump(spy, execTime, methodCall, sql, false));
327 }
328 }
329 }
330 }
331
332 /**
333 * Helper method to quickly build a SQL timing dump output String for
334 * logging.
335 *
336 * @param spy the Spy wrapping the class where the SQL occurred.
337 *
338 * @param execTime how long it took the SQL to run, in milliseconds.
339 *
340 * @param methodCall a description of the name and call parameters of the
341 * method that generated the SQL.
342 *
343 * @param sql SQL that occurred.
344 *
345 * @param debugInfo if true, include debug info at the front of the output.
346 *
347 * @return a SQL timing dump String for logging.
348 */
349 private String buildSqlTimingDump(Spy spy, long execTime, String methodCall,
350 String sql, boolean debugInfo)
351 {
352 StringBuffer out = new StringBuffer();
353
354 if (debugInfo)
355 {
356 out.append(getDebugInfo());
357 out.append(nl);
358 out.append(spy.getConnectionNumber());
359 out.append(". ");
360 }
361
362 // NOTE: if both sql dump and sql timing dump are on, the processSql
363 // algorithm will run TWICE once at the beginning and once at the end
364 // this is not very efficient but usually
365 // only one or the other dump should be on and not both.
366
367 sql = processSql(sql);
368
369 out.append(sql);
370 out.append(" {executed in ");
371 out.append(execTime);
372 out.append(" msec}");
373
374 return out.toString();
375 }
376
377 /**
378 * Get debugging info - the module and line number that called the logger
379 * version that prints the stack trace information from the point just before
380 * we got it (net.sf.log4jdbc)
381 *
382 * if the optional log4jdbc.debug.stack.prefix system property is defined then
383 * the last call point from an application is shown in the debug
384 * trace output, instead of the last direct caller into log4jdbc
385 *
386 * @return debugging info for whoever called into JDBC from within the application.
387 */
388 private static String getDebugInfo()
389 {
390 Throwable t = new Throwable();
391 t.fillInStackTrace();
392
393 StackTraceElement[] stackTrace = t.getStackTrace();
394
395 if (stackTrace != null)
396 {
397 String className;
398
399 StringBuffer dump = new StringBuffer();
400
401 /**
402 * The DumpFullDebugStackTrace option is useful in some situations when
403 * we want to see the full stack trace in the debug info- watch out
404 * though as this will make the logs HUGE!
405 */
406 if (DriverSpy.DumpFullDebugStackTrace)
407 {
408 boolean first=true;
409 for (int i = 0; i < stackTrace.length; i++)
410 {
411 className = stackTrace[i].getClassName();
412 if (!className.startsWith("net.sf.log4jdbc"))
413 {
414 if (first)
415 {
416 first = false;
417 }
418 else
419 {
420 dump.append(" ");
421 }
422 dump.append("at ");
423 dump.append(stackTrace[i]);
424 dump.append(nl);
425 }
426 }
427 }
428 else
429 {
430 dump.append(" ");
431 int firstLog4jdbcCall = 0;
432 int lastApplicationCall = 0;
433
434 for (int i = 0; i < stackTrace.length; i++)
435 {
436 className = stackTrace[i].getClassName();
437 if (className.startsWith("net.sf.log4jdbc"))
438 {
439 firstLog4jdbcCall = i;
440 }
441 else if (DriverSpy.TraceFromApplication &&
442 className.startsWith(DriverSpy.DebugStackPrefix))
443 {
444 lastApplicationCall = i;
445 break;
446 }
447 }
448 int j = lastApplicationCall;
449
450 if (j == 0) // if app not found, then use whoever was the last guy that called a log4jdbc class.
451 {
452 j = 1 + firstLog4jdbcCall;
453 }
454
455 dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").
456 append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
457 }
458
459 return dump.toString();
460 }
461 else
462 {
463 return null;
464 }
465 }
466
467 /**
468 * Log a Setup and/or administrative log message for log4jdbc.
469 *
470 * @param msg message to log.
471 */
472 public void debug(String msg)
473 {
474 debugLogger.debug(msg);
475 }
476
477 /**
478 * Called whenever a new connection spy is created.
479 *
480 * @param spy ConnectionSpy that was created.
481 */
482 public void connectionOpened(Spy spy)
483 {
484 if (connectionLogger.isDebugEnabled())
485 {
486 connectionLogger.info(spy.getConnectionNumber() + ". Connection opened " +
487 getDebugInfo());
488 connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
489 }
490 else
491 {
492 connectionLogger.info(spy.getConnectionNumber() + ". Connection opened");
493 }
494 }
495
496 /**
497 * Called whenever a connection spy is closed.
498 *
499 * @param spy ConnectionSpy that was closed.
500 */
501 public void connectionClosed(Spy spy)
502 {
503 if (connectionLogger.isDebugEnabled())
504 {
505 connectionLogger.info(spy.getConnectionNumber() + ". Connection closed " +
506 getDebugInfo());
507 connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
508 }
509 else
510 {
511 connectionLogger.info(spy.getConnectionNumber() + ". Connection closed");
512 }
513 }
514 }