jdbi3 SQLLog equivalent?

[leaumar]

I've been going through the entire javadoc and site doc but I can't seem to find a replacement mechanism for SQLLog. I can see StatementContext has some get*Sql methods, but there's no replacement for DBI.setSQLLog. TimingCollector receives the statementcontext so it could technically be done in there, but that feels like a workaround given the interface's name.

[arteam]

I think we have removed this logging abstraction in JDBI3. If you want to enable SQL logging, you need to that in the configuration of your SLF4J implementation.

[leaumar]

in SqlStatement
LOG.trace("Execute SQL \"{}\" in {}ms", sql, elapsedTime / 1000000L);

Problem is this doesn't leave me free to decide how I want my queries to be logged: level, phrasing, raw/rendered/parsed sql, conditions...

The doc site says TimingCollector isn't entirely fleshed out yet anyway so ideas are welcome, so I guess I hereby suggest to either make a sister interface for logging queries rather than passed time, or to generify TimingCollector to also be intended for logging queries.

[stevenschlansker]

Yes, we do not have a great interface for this right now. The old SQLLog left a lot to be desired so we removed it while we had the chance, in favor of building something better.

[leaumar]

Having spent some hours updating my project to jdbi3 now, I'm finding TimingCollector a not-half-bad solution in my project, with just 3 minor gripes: it's semantically wrong, it's executed after the query instead of before (so if the query causes an exception there will be no logging of it), and I'm not able to get the named/positional arguments from the statementcontext's binding.

--

Completely unrelated to this issue but on the topic of having spent time updating to jdbi3, I just wanna say I freaking love it. The way the Jdbi class acts as a configuration repository that holds plugins is brilliant. My project was until now built on using jdbi in a very specific, typically-me way that worked but wasn't really jdbi working the jdbi way. Since jdbi3 forced me to do everything the jdbi3 way by removing some freedoms, I've learned some of the alternative mechanisms like Arguments, building on column rather than row mapping, and the improved fluent api, and it's just a whole new world of convenience once you've got everything set up. I didn't even realize how much sense your paradigm technically and functionally makes until now. Awesome work guys, thanks for making this :)

[stevenschlansker]

Thanks for the kind feedback! Would you mind maybe assembling the ways you want to use SqlLog / TimingCollector into this ticket as the start of a design document? It'd be good to get some actual use cases outlined, so we can make sure we solve actual problems.

[leaumar]

Quick pseudo-java-code sketch:

public interface Jdbi {
	void registerSqlLogger(SqlLogger logger);

	void registerSqlLoggerFactory(SqlLoggerFactory factory);
}

public interface SqlLogger {
	void logBeforeExecution(StatementContext context);

	void logAfterExecution(StatementContext context, long nanos);

	void logException(StatementContext context, Exception ex);
}

public interface SqlLoggerFactory {
	// the sqlObject, if any
	Optional<SqlLogger> build(@Nullable SqlObject extension, @Nullable Class extensionClass);
}

public interface StatementContext {
	// "select * from x where foo = 'bar'"
	String getNormalizedSql();

	// "select * from x where foo = ?"
	// "select * from x where foo = :bar"
	String getParamaterizedSql();

	List<Object> getPositionalArgs();

	Map<String, Object> getNamedArgs();

	ParamsType getParamsType();

	enum ParamsType {
		NONE, POSITIONAL, NAMED
	}
}

public class Main {
	public static void main(String[] args) {
		Jdbi jdbi = Jdbi.create();
		jdbi.registerSqlLoggerFactory((sqlObject, sqlObjectClass) -> new SqlLogger() {
			private final Logger logger = LoggerFactory.getLogger(sqlObject != null? sqlObjectClass: MyApp.class);

			@Override
			void before(StatementContext context) {
				String params;
				switch (context.getParamsType()) {
					case NONE:
						params = "N/A";
					case POSITIONAL:
						params = context.getPositionalArgs().toString();
					case NAMED:
						params = toKeyValueString(context.getNamedArgs());
				}
				logger.debug(Markers.SQL, "query: {}, params: {}", context.getParameterizedSql(), params);
			}

			@Override
			void after(StatementContext context, long nanos) {
				logger.trace(Markers.SQL, "query {} took {}ns", context.getNormalizedSql, nanos);
			}

			@Override
			void exception(StatementContext context, Exception ex) {
				logger.error(Markers.SQL, context.getNormalizedSql(), e);
			}
		});
	}
}

[pikzen]

For what it's worth, a simple SqlStatementCustomizerFactory allows you to implement this through annotations, placed either on individual methods or entire interfaces. Yes, it's prone to being forgotten, which is an issue. I currently do not need extremely precise logging for queries as they are mostly for debugging, and turned on when I need to, but you can override beforeExecution and afterExecution for the timing too. It isn't too hard to extend it to take a class to instantiate instead.

@NameBinding
@Retention(AnnotationRetention.RUNTIME)
@Target(AnnotationTarget.CLASS)
@SqlStatementCustomizingAnnotation(WriteQueryToLogFactory::class)
annotation class WriteQueryToLog


class WriteQueryToLogFactory : SqlStatementCustomizerFactory {
    val log: Logger = LoggerFactory.getLogger("api.sql-statements")
    override fun createForType(annotation: Annotation?, sqlObjectType: Class<*>?): SqlStatementCustomizer {
        return SqlStatementCustomizer( { q -> q.addCustomizer(object: StatementCustomizer {
            override fun beforeExecution(stmt: PreparedStatement, ctx: StatementContext) {
                log.trace("Context: ${ctx.extensionMethod.type}.${ctx.extensionMethod.method.name}")
                log.trace("Statement: ${stmt.toString()}")
            }
        })})
    }
}

Yes, it means you have access to the entire statement and can screw it up, but is it really an issue?

[leaumar]

@pikzen That gets the brunt of it done, but my suggestion was about making the query data more accessible and adding the onException method as well. I tried one of those customizing annotations at first too but found it too limited for what I wanted to do, which is why I suggested all of this.

[leaumar]

I just had another look and it seems ParsedParameters and ParsedSql are halfway to what I'd like to see. ParsedParameters is just missing a way to get a parameter value from the provided name/index. I think that would make the picture largely complete.

[pikzen]

Have you given a look at the StatementContext object passed to the customizer? It gives you access to parsedSql rawSql and renderedSql for the SQL, as well as attributes containing the query params.

I do agree that getting something on an exception would be practical, but isn't that better served by simply improving the current StatementCustomizer interface and adapting core?

[leaumar]

as well as attributes containing the query params

Hmmm, no?

The only place to get query param values AFAIK is through reflection on the Binding:

Reflect.on(context.getBinding()).<HashMap<Integer, Argument>>get("named")

[pikzen]

Indeed, my bad, I meant binding, I was only looking at it through the debugger and didn't realize it was not available from the outside.

There's a few places where they are available yes, binding.positionals/named, statement.parameterValues/parameterTypes (although that one is not exactly the most practical) and they are indeed only available through reflection. I

[qualidafial]

Bound parameters are in getBinding(). attributes contains attributes defined through define()--these are the ones inlined into <attr> markers in the SQL.