LoggerListener logs some batch queries twice, when using BatchMultiple

[pedegie]

Expected behavior

JOOQ displays the logging output only once for each insert during batch queries

Actual behavior

This sample code will result in receiving duplicated logging output of inserts:

List<InsertOnDuplicateSetMoreStep<?>> queries = List.of(createExampleQuery(id1, name1), createExampleQuery(id2, name2);
dslContext.batch(queries ).execute();

private InsertOnDuplicateSetMoreStep<?> createExampleQuery(id, name) {
 return dslContext.insertInto(SOME_TABLE)
                .set(SOME_TABLE.ID, id)
                .set(SOME_TABLE.NAME, name)
                .onDuplicateKeyUpdate()
                .set(SOME_TABLE.NAME, name);
}

Output:

 10:29:20.131 [main] DEBUG org.jooq.tools.LoggerListener [requestId: trackingId: businessCtx: sessionId:] - Executing batch query: insert into SOME_TABLE(id, name) values ('ID1', 'name1') on conflict (ID) do update set name= 'name1'
 10:29:20.131 [main] DEBUG org.jooq.tools.LoggerListener [requestId: trackingId: businessCtx: sessionId:] - Executing batch query: insert into SOME_TABLE(id, name) values ('ID1', 'name1') on conflict (ID) do update set name= 'name1'
  10:29:20.131 [main] DEBUG org.jooq.tools.LoggerListener [requestId: trackingId: businessCtx: sessionId:] - Executing batch query: insert into SOME_TABLE(id, name) values ('ID2', 'name2') on conflict (ID) do update set name= 'name2'
 10:29:20.131 [main] DEBUG org.jooq.tools.LoggerListener [requestId: trackingId: businessCtx: sessionId:] - Executing batch query: insert into SOME_TABLE(id, name) values ('ID2', 'name2') on conflict (ID) do update set name= 'name2'

The logging output is duplicated because of LoggerListener code:

  else if (ctx.type() == ExecuteType.BATCH
                    && batchSQL.length > 0
                    && batchSQL[batchSQL.length - 1] != null) {
                for (String sql : batchSQL)
                    log.debug("Executing batch query", newline + sql);
            }

            else if (!StringUtils.isBlank(ctx.sql())) {

                // [#1529] Batch queries should be logged specially
                if (ctx.type() == ExecuteType.BATCH)
                    log.debug("Executing batch query", newline + ctx.sql());
                else
                    log.debug("Executing query", newline + ctx.sql());
            }

During the table batchSql[] population, this condition is met:

       if (ctx.type() == ExecuteType.BATCH)
                    log.debug("Executing batch query", newline + ctx.sql());

and later, when the table is full, this:

  else if (ctx.type() == ExecuteType.BATCH
                    && batchSQL.length > 0
                    && batchSQL[batchSQL.length - 1] != null) {
                for (String sql : batchSQL)
                    log.debug("Executing batch query", newline + sql);
            }

resulting in the duplication of the logging output

Steps to reproduce the problem

As mentioned above in the example

jOOQ Version

3.18.4

Database product and version

PostgreSQL 11.15

Java Version

openjdk 17

OS Version

Windows

JDBC driver name and version (include name if unofficial driver)

org.postgresql.postgresql:42.6.0

[lukaseder]

Thanks a lot for your report. I will investigate this more in detail, soon.

[lukaseder]

I can reproduce this with the following two respective call stacks:

Thread [main] (Suspended (breakpoint at line 126 in LoggerListener))	
	LoggerListener.renderEnd(ExecuteContext) line: 126	
	ExecuteListeners.renderEnd(ExecuteContext) line: 188	
	BatchMultiple.execute(Configuration, Query[]) line: 127	
	BatchMultiple.lambda$1(List) line: 93	
	0x0000000800636eb0.apply(Object) line: not available	
	ReferencePipeline$3$1.accept(P_OUT) line: 197	
	Spliterators$ArraySpliterator<T>.forEachRemaining(Consumer<? super T>) line: 992	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).copyInto(Sink<P_IN>, Spliterator<P_IN>) line: 509	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).wrapAndCopyInto(S, Spliterator<P_IN>) line: 499	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).evaluate(Spliterator<P_IN>, boolean, IntFunction<E_OUT[]>) line: 575	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).evaluateToArrayNode(IntFunction<E_OUT[]>) line: 260	
	ReferencePipeline$8(IntPipeline<E_IN>).toArray() line: 562	
	BatchMultiple.execute() line: 95	
	BatchTests<A,B,S,B2S,BS>.testBatchMultiple() line: 446	

And

Thread [main] (Suspended (breakpoint at line 119 in LoggerListener))	
	LoggerListener.renderEnd(ExecuteContext) line: 119	
	ExecuteListeners.renderEnd(ExecuteContext) line: 188	
	BatchMultiple.execute(Configuration, Query[]) line: 127	
	BatchMultiple.lambda$1(List) line: 93	
	0x0000000800636eb0.apply(Object) line: not available	
	ReferencePipeline$3$1.accept(P_OUT) line: 197	
	Spliterators$ArraySpliterator<T>.forEachRemaining(Consumer<? super T>) line: 992	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).copyInto(Sink<P_IN>, Spliterator<P_IN>) line: 509	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).wrapAndCopyInto(S, Spliterator<P_IN>) line: 499	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).evaluate(Spliterator<P_IN>, boolean, IntFunction<E_OUT[]>) line: 575	
	ReferencePipeline$8(AbstractPipeline<E_IN,E_OUT,S>).evaluateToArrayNode(IntFunction<E_OUT[]>) line: 260	
	ReferencePipeline$8(IntPipeline<E_IN>).toArray() line: 562	
	BatchMultiple.execute() line: 95	
	BatchTests<A,B,S,B2S,BS>.testBatchMultiple() line: 446	

I think something around the (very old) fixes below is now obsolete:

• Let batch executions debug-log executed queries #2532
• Combining renderFormatted with inlined bind variables will change bind values when they contain newlines #2528

Since individual statements are already logged, we don't need to log the entire batch anymore.

[lukaseder]

Fixed in versions

• 3.19.0
• 3.18.5 (LoggerListener logs some batch queries twice, when using BatchMultiple - Merge [#15250] #15267)
• 3.17.14 (LoggerListener logs some batch queries twice, when using BatchMultiple - Merge [#15250] #15268)
• 3.16.20 (LoggerListener logs some batch queries twice, when using BatchMultiple - Merge [#15250] #15269)