hibernate-reactive NullpointException in case Quarkus log in set to debug

[hy-good]

Describe the bug

hibernate-reactive NullpointException
When I set the log level to debug and run it, a nullpointexception occurs and the application does not work properly.

Configuration

quarkus:
  log:
    level: DEBUG
  datasource:
    db-kind: postgresql
    username: postgres
    password: 1234
    reactive:
      url: postgresql://localhost:5432/postgres

Screenshots

16:35:55 ERROR [io.qu.ru.Application] (Quarkus Main Thread) Failed to start application (with profile dev): java.lang.NullPointerException
at org.hibernate.reactive.persister.collection.impl.ReactiveOneToManyPersister.getSQLInsertRowString(ReactiveOneToManyPersister.java:144)
at org.hibernate.persister.collection.AbstractCollectionPersister.logStaticSQL(AbstractCollectionPersister.java:693)
at org.hibernate.persister.collection.AbstractCollectionPersister.(AbstractCollectionPersister.java:529)
at org.hibernate.persister.collection.OneToManyPersister.(OneToManyPersister.java:69)
at org.hibernate.reactive.persister.collection.impl.ReactiveOneToManyPersister.(ReactiveOneToManyPersister.java:52)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
at org.hibernate.persister.internal.PersisterFactoryImpl.createCollectionPersister(PersisterFactoryImpl.java:152)
at org.hibernate.persister.internal.PersisterFactoryImpl.createCollectionPersister(PersisterFactoryImpl.java:140)
at org.hibernate.metamodel.internal.MetamodelImpl.initialize(MetamodelImpl.java:225)
at org.hibernate.internal.SessionFactoryImpl.(SessionFactoryImpl.java:303)
at org.hibernate.reactive.session.impl.ReactiveSessionFactoryImpl.(ReactiveSessionFactoryImpl.java:33)
at io.quarkus.hibernate.reactive.runtime.boot.FastBootReactiveEntityManagerFactoryBuilder.build(FastBootReactiveEntityManagerFactoryBuilder.java:34)
at io.quarkus.hibernate.reactive.runtime.FastBootHibernateReactivePersistenceProvider.createEntityManagerFactory(FastBootHibernateReactivePersistenceProvider.java:83)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:118)
at io.quarkus.hibernate.orm.runtime.JPAConfig.startAll(JPAConfig.java:42)
at io.quarkus.hibernate.orm.runtime.JPAConfig_Subclass.startAll$$superaccessor4(JPAConfig_Subclass.zig:650)
at io.quarkus.hibernate.orm.runtime.JPAConfig_Subclass$$function$$4.apply(JPAConfig_Subclass$$function$$4.zig:29)
at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:63)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:51)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(InvocationInterceptor_Bean.zig:521)
at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
at io.quarkus.hibernate.orm.runtime.JPAConfig_Subclass.startAll(JPAConfig_Subclass.zig:608)
at io.quarkus.hibernate.orm.runtime.HibernateOrmRecorder.startAllPersistenceUnits(HibernateOrmRecorder.java:88)
at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits951856026.deploy_0(HibernateOrmProcessor$startPersistenceUnits951856026.zig:74)
at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits951856026.deploy(HibernateOrmProcessor$startPersistenceUnits951856026.zig:40)
at io.quarkus.runner.ApplicationImpl.doStart(ApplicationImpl.zig:762)
at io.quarkus.runtime.Application.start(Application.java:90)
at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:100)
at io.quarkus.runtime.Quarkus.run(Quarkus.java:66)
at io.quarkus.runtime.Quarkus.run(Quarkus.java:42)
at io.quarkus.runtime.Quarkus.run(Quarkus.java:119)
at io.quarkus.runner.GeneratedMain.main(GeneratedMain.zig:29)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at io.quarkus.runner.bootstrap.StartupActionImpl$3.run(StartupActionImpl.java:134)
at java.base/java.lang.Thread.run(Thread.java:836)

Output of java -version

jdk 11

Quarkus version or git rev

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

Apache Maven 3.6.3

[quarkus-bot]

/cc @DavideD, @Sanne, @gavinking

[DavideD]

Which version of quarkus are you using?

[DavideD]

It seems the issue is related to a @OneToMany association mapping, could you show me how you've mapped some of the entities or create a small test case I can run?

[DavideD]

Maybe when you set the log to debug level, you are trying to print an association that's not initialized yet?
Hibernate Reactive doesn't support lazy fetching of associations, you need to fetch them explicitly.

For example:

session.find(Author.class, author.id)
       .chain( author -> Mutiny.fetch(author.books) )
       .invoke( books -> ... )

Where author.books is a one-to-many association.

You can find more details about this in the Hibernate Reactive documentation: 1.2.11. Fetching lazy associations

[DavideD]

Anyway, I need more information about this to be able to help you.

[DavideD]

Mmmh... maybe not... it seems that the issue happens when the persister is created

[DavideD]

Never mind, I think I've found the problem: https://github.com/hibernate/hibernate-reactive/blob/main/hibernate-reactive-core/src/main/java/org/hibernate/reactive/persister/collection/impl/ReactiveOneToManyPersister.java#L52

The log is called in the superclass before the variable this.parameters is initialized. This causes NullPointerException when getSQLInsertRow() is called for logging: https://github.com/hibernate/hibernate-reactive/blob/f283b6e8e4e0cb59add668ea70620af860924962/hibernate-reactive-core/src/main/java/org/hibernate/reactive/persister/collection/impl/ReactiveOneToManyPersister.java#L144

I will create an issue on Hibernate Reactive for this.

[DavideD]

I've created this issue in Hibernate Reactive: hibernate/hibernate-reactive#726

[hy-good]

Which version of quarkus are you using?

used 1.13.1

[hy-good]

It seems the issue is related to a @OneToMany association mapping, could you show me how you've mapped some of the entities or create a small test case I can run?

The entity I created is as follows

public class RoutingInfo extends PanacheEntityBase {
    @Id
    @GeneratedValue
    @JsonIgnore
    private Long id;

    // sequence no
    private int seq;

    // service definition
    private String name;
    private String description;

    // Route Topic
    private String topic;

    // limit
    private Long timeout;
    @Enumerated
    @Column(name = "time_units")
    @Builder.Default
    private TimeUnits timeUnits = TimeUnits.SECONDS;

    // mandatory / optional
    @Builder.Default
    private boolean mandatory = true;

    // update time
    @UpdateTimestamp
    @Column(name = "update_time")
    private OffsetDateTime updateTime;

}

@Getter
@Setter
@Builder
@AllArgsConstructor
@NoArgsConstructor
@ToString
@Entity
@Cacheable
public class Routing extends PanacheEntityBase {
    @Id
    private String id;

    // service definition
    private String name;
    private String description;

    // common compensation handler
    private String compensation;

    // performance type (topic 구조가 다름,  하위 서비스별 토픽을 모두 만드는 구조 HIGH, 하나의 라우팅테이블 기준 service/complete/compensation 3개로 통합하는 구조 NORMAL)
    @Column(name = "performance_type", length = 6, columnDefinition = "varchar(6) default 'NORMAL'")
    @Enumerated(value = EnumType.STRING)
    @Builder.Default
    private PerformanceType performanceType = PerformanceType.NORMAL;

    // limit
    private Long timeout;
    @Enumerated
    @Column(name = "time_units")
    @Builder.Default
    private TimeUnits timeUnits = TimeUnits.SECONDS;

    // update time
    @UpdateTimestamp
    @Column(name = "update_time")
    private OffsetDateTime updateTime;

    @NotNull
    @OneToMany(cascade = CascadeType.ALL, orphanRemoval = true, fetch = FetchType.EAGER)
    @JoinColumn(name = "routing_id")
    private Collection<RoutingInfo> routingInfos;

}

[DavideD]

Thank you @KIMHYEONGJUN! I've already found the problem and I'm now thinking about how to solve it.
It's a bug in Hibernate Reactive. Thanks for finding it :-)