Logged SQL Statements are not visible in dev ui log.

Postremus commented 2 years ago

Describe the bug

I activated quarkus.hibernate-orm.log.sql=true. The sql statements are logged to the console, but not visible in dev ui.

Expected behavior

The log in dev ui also prints out the executed sql statements.

Actual behavior

No sql statements are logged in dev ui. Parameters for the statements are logged however.

How to Reproduce?

Download the reproducer: self-invocation.zip
mvn quarkus:dev, open dev ui
http://localhost:8080/hello
The terminal now prints out some sql statements.
They are not visible in dev ui however

Output of `uname -a` or `ver`

MSYS_NT-10.0-19043 NANB7NLNVP2 3.1.7-340.x86_64 2021-03-26 22:17 UTC x86_64 Msys

Output of `java -version`

OpenJDK Runtime Environment Zulu11.39+15-CA (build 11.0.7+10-LTS) OpenJDK 64-Bit Server VM Zulu11.39+15-CA (build 11.0.7+10-LTS, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.3.0.Final

Build tool (ie. output of `mvnw --version` or `gradlew --version`)

Apache Maven 3.8.3 (ff8e977a158738155dc465c6a97ffaf31982d739) Maven home: C:\eclipse\tools\apache-maven Java version: 11.0.7, vendor: Azul Systems, Inc., runtime: C:\eclipse\tools\java\11 Default locale: de_DE, platform encoding: Cp1252 OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

No response

geoand commented 2 years ago

cc @phillip-kruger

phillip-kruger commented 2 years ago

I'll investigate. I know that System.out is not reflecting in the Dev UI, @geoand do you know how the sql are being logged ? Hopefully not System.out ?

geoand commented 2 years ago

I don't know, but it's possible (because looking at the output, there is no logging information).

@yrodiere or @Sanne would however have the definittive answer.

phillip-kruger commented 2 years ago

Thanks ! Waiting for their answer. I am not sure how to get System.out in the log...

yrodiere commented 2 years ago

The implementation of this logging is there: https://github.com/hibernate/hibernate-orm/blob/cf995a15717caafe65a8aa60f3750e23fbe72a69/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java#L135-L149

As you can see, statements are logged, and also (optionally) sent to stdout.

The configuration option that enables logging (hibernate.show_sql), however, only affects stdout: https://github.com/hibernate/hibernate-orm/blob/cf995a15717caafe65a8aa60f3750e23fbe72a69/hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcServicesImpl.java#L56-L61

As it turn outs, the Quarkus setting affects only stdout: https://github.com/quarkusio/quarkus/blob/28330b13b457ada58fa78e00edeb2e61034febc2/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/FastBootHibernatePersistenceProvider.java#L363-L369

I suppose debug logs are either suppressed by default in Quarkus, or explicitly suppressed by the Hibernate ORM extension.

I don't know if there was a specific reason to rely primarily on stdout rather than logs in Quarkus. But that seems odd, and I can see how it could cause problems in the dev UI.

@Sanne Maybe we should have quarkus.hibernate-orm.log.sql = true enable logging at the debug level for the org.hibernate.SQL logger, instead of forwarding the setting to Hibernate ORM through hibernate.show_sql?

EDIT: That would probably change the output format, though.

Sanne commented 2 years ago

I don't see why it's odd to output to system out, that's what people normally want :)

If you're all expecting to see output in the dev console, shouldn't we tee the std output to the console? It's an open question, as I suppose there might be many other things it's missing to show.

We could also have Hibernate emit the SQL logs to a different stream in addition to the existing one.

phillip-kruger commented 2 years ago

@Sanne - I am not sure how to get the System.out in the log.... any tips ?

yrodiere commented 2 years ago

I don't see why it's odd to output to system out, that's what people normally want :)

I mean, asking Hibernate to display SQL statements is awfully close to tracing. Which is traditionally something you do through logs. (Obviously, I'm not talking about observability, just local dev)

Must be just me, but:

In a webapp, ~~I simply wouldn't expect to use stdout at all. All I need is logs, and logs normally go to stderr.~~ Okay, right, it's reasonable to output INFO-WARN to stdout and ERROR to stderr. But still, I'd expect logs to go through... the logging framework. With formatting, prefixes with the date and time, and all that.
In a CLI application, sending SQL statements to stdout could actually mess up the application's output.

Regardless, sure, if we can write stdout to the console, that would be a better option, since it would potentially capture user-generated output as well.

Sanne commented 2 years ago

@Sanne - I am not sure how to get the System.out in the log.... any tips ?

honestly I've never done this before, I just know it's possible and several tools do so in such cases. Sorry :)

@yrodiere sure I find it generally odd as well specifically when developing a traditional webapp, but we're not limited to those. I'd be cautious to change such things as it's hard to predict all consequences and all uses, but I would support some more radical changes in Hibernate ORM 6.

For example we could have an "output stream service" within the ORM registry; thinking loudly, that might be OK to have in ORM 5.6: it could default to System.out but Quarkus (and others) could reimplement it, making it easier to specify where one wants output to go - specifically from the ORM engine.

For Quarkus I suppose we could do both; I still maintain that it might be useful to capture all system.out so to have it printed on the dev-console, but we could defer that.

gsmet commented 2 years ago

FWIW it has always bugged me that the SQL output was sent to stdout and I would have preferred a logger.

If enabling DEBUG for org.hibernate.SQL has the same behavior as the current setting, I would lean towards switching to it in Quarkus given it's a relatively new project and I don't think people would rely on it (and in any case, they can tweak the logger to have the equivalent behavior).

cescoffier commented 1 month ago

This issue is still relevant (I reproduced it Today).

yrodiere commented 1 month ago

Created https://hibernate.atlassian.net/browse/HHH-18426 for consideration in ORM.

Not sure this will fly, but we might at least get a pluggable SPI to redefine how SQL logging is done in Quarkus specifically. We might even get a hint that this SPI already exists, who knows :)

quarkusio / quarkus