jOOQ doesn't log the SQL queries it executes, despite enabling DEBUG logging

Question

My application uses Logback and I've enabled DEBUG logging for org.jooq in my Logback configuration. Despite this, jOOQ doesn't log the SQL queries (as it ought to). What can be causing this?

Answer 1

I'm assuming you mean logging with the org.jooq.tools.LoggerListener, which by default DEBUG logs all your queries and their results.

There's a flag to turn that off completely. It's enabled by default. You may have turned it off with Settings.executeLogging.

Another reason may be that jOOQ's org.jooq.tools.JooqLogger tries to classload org.slf4j.Logger and logs through that if available, falling back to java.util.logging otherwise. Do check that you make slf4j available to jOOQ on the classpath or modulepath, and that you have it backed by logback.

Answer 2

I looked at this a bit more (it was a problem I ran into last week), and it turned out I was wrong. jOOQ did indeed log the queries, using the o.j.t.L.o.j.t.LoggerListener. The problem was just this:

• I was running different queries on multiple threads.

• Other queries were being logged after this query.

• This particular query returned 21 million records, leading to the following:

  java.lang.OutOfMemoryError: Java heap space
  Dumping heap to /tmp/java_pid104782.hprof ...
  
  Exception: java.lang.OutOfMemoryError thrown from the  UncaughtExceptionHandler in thread "Thread-0 (ActiveMQ-scheduled-threads)"
  
  Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "I/O dispatcher 14"
  Heap dump file created [6088668813 bytes in 48.331 secs]
  
  Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "req-rsp-timeout-task"
  
  Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "I/O dispatcher 5"
  
  Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "lettuce-eventExecutorLoop-1-3"
  
  Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "I/O dispatcher 11"
  

• Because of the above, the Fetched result and Fetched row(s) messages were never logged. And in general, it was hard to understand that it was that specific query that failed, because it wasn't the "last" query to be logged, so to speak (because of the queries from the other threads).

What I did to mitigate this was to add an onRenderEnd handler for the particular query that was failing (I stepped through the code with the debugger to roughly see which jOOQ query this was). Using this, I was able to pin-point the logging for my particular query more easily.

Posting all these details in the help that it might help others and/or my future self.

diff --git a/path/to/MyClass.java b/path/to/MyClass.java
index 92beaa9a91..fcddf9c134 100644
--- a/path/to/MyClass.java
+++ b/path/to/MyClass.java
@@ -30,6 +30,7 @@ import java.util.stream.Stream;
 
 import org.jooq.DSLContext;
 import org.jooq.DatePart;
+import org.jooq.ExecuteListener;
 import org.jooq.Field;
 import org.jooq.Name;
 import org.jooq.Record1;
@@ -417,6 +418,10 @@ public class MyClass {
             // arithmetics on `Field<Instant>` https://stackoverflow.com/a/71508599
             Field<Instant> upperRelatedLimit = field( "(" + seriesTimeFieldName.first() + " + INTERVAL '1 hour')", Instant.class );
 
+            create.configuration().set( ExecuteListener.onRenderEnd( ctx -> {
+                System.out.println( ctx.sql() );
+            } ) );
+
             try ( Stream<AssignedDeviceConnectionState> connectionStates = auditDsl.select(
                     field( "series." + seriesTimeFieldName.first(), Instant.class ).as( "time" ),
                     field( "d.id", Integer.class ).as( "device_id" ),