LoggerListener does not apply to R2DBC execution

[nickman]

This logging configuration does not appear to work when using R2DBC.
At least, that what's I am attributing it to.
I was able to get some [much less useful] info using these logger configs:

       <Logger name="io.r2dbc.postgresql.QUERY" level="debug" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        <Logger name="io.r2dbc.postgresql.PARAM" level="debug" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>

I get that the R2DBC code is pretty new, but just looking for a confirm on my diagnosis.
Thanks.

[lukaseder]

Thanks a lot for your feedback.

A side effect of the R2DBC execution not going through the ExecuteListener lifecycle yet (see #11717), is that the LoggerListener (which implements ExecuteListener) is not called either.

Given that the documentation here: https://www.jooq.org/doc/latest/manual/sql-execution/logging suggests that such logging should be automatic on DEBUG level, I can see how this can be seen as a bug.

The logging won't be the same, because when streaming results (both push and pull style), we don't have the entire result set available, so we can't debug-log the results. But there's certainly room for debug logging the SQL statements.

I'll see what can be done here.

[lukaseder]

It won't make sense to look at this independently from looking at ExecuteListener lifecycle support for R2DBC executions as well: #12221

However, it might be possible to achieve logging the SQL string by implementing only renderStart() / renderEnd() events for now. To be further investigated.

[davinkevin]

One of the most important feature I've lost after migration to R2DBC 😢

It's harder than ever to debug/implement/reason about queries… I feel like I'm using hibernate again 😅.

[lukaseder]

I feel like I'm using hibernate again 😅.

Maybe a bit exaggerated? It's a useful feature in jOOQ, sure, but by no means a necessary one. JDBC and R2DBC are both SPIs that can be proxied very easily to log every SQL query that is passing through, as well as result sets.

E.g. look at this: https://github.com/r2dbc/r2dbc-proxy

[davinkevin]

You are not the only one able to troll 😇.

It's mainly about developer experience, especially when I write tests. In my case, this is a really helpful to see the query, well formatted and with result in ascii table. Losing that make me totally blind, and the feature provided natively by R2DBC are not as efficient as the JOOQ one.

I'll give a try to the proxy, thank you for the link/idea.

[lukaseder]

I understand the value of this feature, but with a roadmap as full as jOOQ's, the prioritisation hasn't favoured this issue here (yet).

This issue here isn't just about the LoggerListener, but about ExecuteListener lifecycles in general, which can't be adapted to R2DBC as easily as it may seem at first: #12221

this is a really helpful to see the query, well formatted

Sure, the formatting option is a great one. Using that r2dbc-proxy, you could parse and re-format the jOOQ query to get a similar result

and with result in ascii table

Well, it's hard to say if this will work in the reactive world. We already worked around the fact that in a pull stream, there's no such thing as a "result" by buffering a few records in the LoggerListener (see #10019). I can't say yet, whether this also works in the reactive world, where the individual records may be streamed by different threads. It's kinda lame for the LoggerListener to synchronize (and thus block) just to be able to buffer things, no?

[davinkevin]

I totally understand and thank you for all details !

If this has to be the downside of reactive, I'm ok with that. If you have in mind some solutions to provide a great DX in this context, it's welcomed.

My usage (and maybe only mine) is to use it only in test phase. I don't need this feature in "production". If we can set something "different" in this context to have this feature back only in this context, this would be wonderful for me.

With reactor, we have access to the .log(…) operator, maybe it can be useful to use it to provide a similar experience for developer as with JDBC, like this:

From.Flux(query.select().from(table)…)
  .log(query.reactorLog()) 
  …

It's maybe a possibility 🤷

[lukaseder]

If you have in mind some solutions to provide a great DX in this context, it's welcomed.

Much more important than the immediate itch to scratch here (logging) is to implement something sound that fits well with all the other different SPIs. If the big questions aren't resolved (ExecuteListener), then the smaller ones can't be, either (LoggerListener).

An alternative solution for logging reactive queries doesn't make sense, as it would just increase the complexity of jOOQ overall, including the documentation.

So, the roadmap is clear, once time permits, #12221 is implemented thoroughly, and then this issue here will work OOTB.

My usage (and maybe only mine) is to use it only in test phase. I don't need this feature in "production".

I think this is what everyone does. Hardly anyone will log sensitive information about customers, etc. in their ordinary technical log files in production, so no results, no bind variables should be logged. It's a pure test/dev/debug feature.

If we can set something "different" in this context to have this feature back only in this context, this would be wonderful for me.

If you're using Spring, then @Profile will be the solution for you for now: https://www.baeldung.com/spring-profiles. With a test profile, you can inject that r2dbc-proxy into your ConnectionFactory.

There are many other ways to "ease the immediate pain" while this feature here isn't available yet.

[lukaseder]

Please note that jOOQ 3.18.0, 3.17.7, and 3.16.13 now have a LoggingConnection, an R2DBC Connection proxy that logs all events including SQL statements: #14499. It works independently of jOOQ.

We should still eventually support the ExecuteListener lifecycle, but at least, the logging aspect can be addressed simply.

See also: https://blog.jooq.org/jooqs-r2dbc-loggingconnection-to-log-all-sql-statements/