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