Getting a new line in the sql timing output which kills output cmd line handling with sed/awk

[adam42a]

In class Slf4jSpyLogDelegator line 313 it looks like there is a bad new line inserted.

This is coming out in the sql timings logging and destroys the command line processing that I do to manipulate and filter the logging output, because the crucial information (duration) appears on the next line.

[brunorozendo]

Can you describe what are you trying to do? I need info to duplicate the scenario

[adam42a]

I'm monitoring the logging output. We pump everything into one log file and then use the command line a bit like this:

tail -f /app/gis/tst/tardis/catalina.out | cut -d ' ' -f 5 | awk '/sqltiming/ {printf("%.4d %s", $1, $4")}'

Basically filtering and formatting the logging output.

This doesn't work with the current version since the duration stats come out on the line below all the other columns in the logging output.

Until I get the chance to clone your repo and produce a local upgrade release, I'm forced to use a different JDBC spy package that is probably a performance downgrade.

[judsona]

@adam66 I think i may have experienced the same issue as you.

I just added a new spy log delegator that removed any sql processing (which adds the new line).

See private String buildSqlTimingDump(long execTime, String sql)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import net.sf.log4jdbc.Properties;
import net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator;
import net.sf.log4jdbc.sql.Spy;

public class GekkoSpyLogDelegator extends Slf4jSpyLogDelegator {

    /**
     * Logger that shows the SQL timing, post execution
     */
    private final Logger sqlTimingLogger =
        LoggerFactory.getLogger("jdbc.sqltiming");

    @Override
    public void sqlTimingOccurred(
        Spy spy, long execTime, String methodCall, String sql)
    {
        if (sqlTimingLogger.isErrorEnabled() &&
            (!Properties.isDumpSqlFilteringOn() || shouldSqlBeLogged(sql)))
        {
            if (Properties.isSqlTimingErrorThresholdEnabled() &&
                execTime >= Properties.getSqlTimingErrorThresholdMsec())
            {
                sqlTimingLogger.error(buildSqlTimingDump(execTime, sql));
            } else if (sqlTimingLogger.isWarnEnabled()) {
                if (Properties.isSqlTimingWarnThresholdEnabled() &&
                    execTime >= Properties.getSqlTimingWarnThresholdMsec())
                {
                    sqlTimingLogger.warn(buildSqlTimingDump(execTime, sql));
                } else if (sqlTimingLogger.isDebugEnabled()) {
                     sqlTimingLogger.debug(buildSqlTimingDump(execTime, sql));
                } else if (sqlTimingLogger.isInfoEnabled()) {
                    sqlTimingLogger.info(buildSqlTimingDump(execTime, sql));
                }
            }

        }
    }

    /**
     * Helper method to quickly build a SQL timing dump output String for
     * logging.
     *
     * @param spy
     *            the Spy wrapping the class where the SQL occurred.
     *
     * @param execTime
     *            how long it took the SQL to run, in milliseconds.
     *
     * @param methodCall
     *            a description of the name and call parameters of the method
     *            that generated the SQL.
     *
     * @param sql
     *            SQL that occurred.
     *
     * @param debugInfo
     *            if true, include debug info at the front of the output.
     *
     * @return a SQL timing dump String for logging.
     */
    private String buildSqlTimingDump(long execTime,
        String sql)
    {       
        return String.format("{}: %s {executed in %s msec}", sql, execTime);
    }

    /**
     * Determine if the given sql should be logged or not based on the various
     * DumpSqlXXXXXX flags.
     *
     * @param sql
     *            SQL to test.
     * @return true if the SQL should be logged, false if not.
     */
    private boolean shouldSqlBeLogged(String sql) {
        if (sql == null) {
            return false;
        }
        sql = sql.trim();

        if (sql.length() < 6) {
            return false;
        }
        sql = sql.substring(0, 6).toLowerCase();
        return (Properties.isDumpSqlSelect() && "select".equals(sql))
            ||
            (Properties.isDumpSqlInsert() && "insert".equals(sql))
            ||
            (Properties.isDumpSqlUpdate() && "update".equals(sql))
            ||
            (Properties.isDumpSqlDelete() && "delete".equals(sql))
            ||
            (Properties.isDumpSqlCreate() && "create".equals(sql));
    }

}