added parameter bind logging

[62mkv]

closes #278

Make sure that:

• You have read the contribution guidelines.
• You have created a feature request first to discuss your contribution intent. Please reference the feature request ticket number in the pull request.
• You use the code formatters provided here and have them applied to your changes. Don't submit any formatting related changes.
• You submit test cases (unit or integration tests) that back your changes.

Not sure what tests should I provide along with this?

Issue description

#278

New Public APIs

none

Additional context

Query Parameter values are now visible in the logs

[mp911de]

Thanks for submitting a pull request. Care to attach a snippet as comment how the logs would look like?

I'm considering to slightly tweak the logging behavior. Since we have already a query logger, we might want to keep the actual SQL and the parameters somewhat close together so one can reason about the query and its parameters.

Let's see how the log output would look like before we continue here.

[62mkv]

Hi. This is how the output looks like for me:

Started
2020-08-11 17:04:06.741 DEBUG 8288 --- [  restartedMain] io.r2dbc.postgresql.PARAM                : Parameter 0 value bound: %a%
2020-08-11 17:04:06.744 DEBUG 8288 --- [  restartedMain] io.r2dbc.postgresql.PARAM                : Parameter 1 value bound: 1
2020-08-11 17:04:06.744 DEBUG 8288 --- [  restartedMain] io.r2dbc.postgresql.PARAM                : Parameter 2 value bound: 2020-01-01
2020-08-11 17:04:06.773 DEBUG 8288 --- [actor-tcp-nio-1] io.r2dbc.postgresql.QUERY                : Executing query: SELECT TEMPDATA.id, TEMPDATA.textdata, TEMPDATA.tzdata FROM TEMPDATA WHERE TEMPDATA.textdata LIKE $1 AND (TEMPDATA.id > $2) AND (TEMPDATA.tzdata > $3)
Finished

I'm considering to slightly tweak the logging behavior. Since we have already a query logger, we might want to keep the actual SQL and the parameters somewhat close together so one can reason about the query and its parameters.

Could you please provide a little bit more details, on how you see it accomplished?

Thanks!

[62mkv]

where I see a problem with the above (apart from off-by-one numbering) is what might happen in mass-parallel scenarios. So arguably, if we could put some unique query execution id into both QUERY and PARAM logger output so user could correlate those together, would be great. However at the moment I have no idea how to achieve this..

[Squiry]

I believe we need some connection id in log, in every log, not only bindings, that would help a lot.

[ttddyy]

FYI, If you want to log bindings and query all together(also connection id), r2dbc-proxy provides such capability.
Here is sample log.
(It is multilined for display purpose but actual logging is single line, and configurable to own format)

[mp911de]

The log output looks good already. I second @Squiry's view, that we need to add context. Single-process logs are easy to understand, but in production environments we get way more log output than that.

In the SQL Server driver, we've introduced ConnectionContext that is a factory for log messages holding the connection/channel Id for easier tracing. We could do here the same.

I'll be off for around two weeks, I can have a look afterward. Alternatively, feel free to check out the SQL server driver and introduce the contextual log message factory.

[Squiry]

We have a processId that can be used as a connection id provided by backend, but we have it only after connection succeed.

[mp911de]

I filed #339 to capture more context so we can correlate bind calls to the actual connection.

[mp911de]

Thank you for your contribution. That's merged, polished, and backported now.

[62mkv]

Thanks @mp911de !