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