Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Crash] ClassNotFound when running with DEBUG environment variable set to false #1714

Closed
Nek-12 opened this issue Mar 29, 2023 · 4 comments
Closed

[Crash] ClassNotFound when running with DEBUG environment variable set to false #1714

Nek-12 opened this issue Mar 29, 2023 · 4 comments

Comments

@Nek-12
Copy link

Nek-12 commented Mar 29, 2023 •
edited
Loading

I have faced a ridiculously strange error just now.
I'm using Exposed as my database driver.
I have not set up any logging or other handling.
I have a DEBUG environment variable set in my docker container image.
That environment variable is used throughout the application to mostly configure logging and set Ktor's development mode to true.
The DEBUG environment variable is not used in any way by the Exposed code.
When I build a jar and run it with DEBUG=true, everything works correctly.
As soon as I try to run the app with DEBUG=false, the application crashes when executing a query that tries to fetch a specific entity via a foreign key relation.

The stacktrace is not helpful at all. At first it points to a reflection issue, but then begins to point at a nullpointer exception, and finally, says that my companion object extending UUIDEntityClass is for some reason not found in the bytecode.

java.lang.reflect.InvocationTargetException: null
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:79)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:484)
	at kotlin.reflect.jvm.internal.calls.CallerImpl$Constructor.call(CallerImpl.kt:41)
	at kotlin.reflect.jvm.internal.KCallableImpl.call(KCallableImpl.kt:108)
	at org.jetbrains.exposed.dao.EntityClass$entityCtor$1.invoke(EntityClass.kt:32)
	at org.jetbrains.exposed.dao.EntityClass$entityCtor$1.invoke(EntityClass.kt:32)
	at org.jetbrains.exposed.dao.EntityClass.createInstance(EntityClass.kt:229)
	at org.jetbrains.exposed.dao.EntityClass.wrap(EntityClass.kt:233)
	at org.jetbrains.exposed.dao.EntityClass.wrapRow(EntityClass.kt:138)
	at org.jetbrains.exposed.dao.EntityClass$wrapRows$1.invoke(EntityClass.kt:125)
	at org.jetbrains.exposed.dao.EntityClass$wrapRows$1.invoke(EntityClass.kt:124)
	at org.jetbrains.exposed.sql.IterableExKt$mapLazy$1$iterator$1.next(IterableEx.kt:138)
	at kotlin.collections.CollectionsKt___CollectionsKt.single(_Collections.kt:595)
	at com.app.database.entity.UserEntityKt.findByEmail(UserEntity.kt:49)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invokeSuspend(Ext.kt:60)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invoke(Ext.kt)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invoke(Ext.kt)
	at org.jetbrains.exposed.sql.transactions.experimental.SuspendedKt$suspendedTransactionAsyncInternal$1.invokeSuspend(Suspended.kt:129)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at java.base/java.lang.VirtualThread.run(VirtualThread.java:287)
	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:174)
	at java.base/jdk.internal.vm.Continuation.enter0(Continuation.java:327)
	at java.base/jdk.internal.vm.Continuation.enter(Continuation.java:320)
Caused by: java.lang.ExceptionInInitializerError: null
	at com.app.database.entity.habit.EntryEntity$Companion.<init>(EntryEntity.kt:52)
	at com.app.database.entity.habit.EntryEntity$Companion.<init>(EntryEntity.kt)
	at com.app.database.entity.habit.EntryEntity.<clinit>(EntryEntity.kt:63)
	at com.app.database.entity.UserEntity.<init>(UserEntity.kt:45)
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:67)
	... 24 common frames omitted
Caused by: java.lang.NullPointerException: Parameter specified as non-null is null: method com.app.database.entity.base.SyncedTable.updateHook, parameter entity // <- entity is of type EntityClass<UUID, EntryEntity>(EntryTable)
	at com.app.database.entity.base.SyncedTable.updateHook(SyncedEntity.kt)
	at com.app.database.entity.habit.EntryTable.<clinit>(EntryEntity.kt:47)
	... 29 common frames omitted
ERROR Application - Unhandled: POST - /api/auth/email/login
java.lang.reflect.InvocationTargetException: null
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:79)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:484)
	at kotlin.reflect.jvm.internal.calls.CallerImpl$Constructor.call(CallerImpl.kt:41)
	at kotlin.reflect.jvm.internal.KCallableImpl.call(KCallableImpl.kt:108)
	at org.jetbrains.exposed.dao.EntityClass$entityCtor$1.invoke(EntityClass.kt:32)
	at org.jetbrains.exposed.dao.EntityClass$entityCtor$1.invoke(EntityClass.kt:32)
	at org.jetbrains.exposed.dao.EntityClass.createInstance(EntityClass.kt:229)
	at org.jetbrains.exposed.dao.EntityClass.wrap(EntityClass.kt:233)
	at org.jetbrains.exposed.dao.EntityClass.wrapRow(EntityClass.kt:138)
	at org.jetbrains.exposed.dao.EntityClass$wrapRows$1.invoke(EntityClass.kt:125)
	at org.jetbrains.exposed.dao.EntityClass$wrapRows$1.invoke(EntityClass.kt:124)
	at org.jetbrains.exposed.sql.IterableExKt$mapLazy$1$iterator$1.next(IterableEx.kt:138)
	at kotlin.collections.CollectionsKt___CollectionsKt.single(_Collections.kt:595)
	at com.app.database.entity.UserEntityKt.findByEmail(UserEntity.kt:49)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invokeSuspend(Ext.kt:60)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invoke(Ext.kt)
	at com.app.controller.UserController$findUser$$inlined$db$default$1.invoke(Ext.kt)
	at org.jetbrains.exposed.sql.transactions.experimental.SuspendedKt$suspendedTransactionAsyncInternal$1.invokeSuspend(Suspended.kt:129)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at java.base/java.lang.VirtualThread.run(VirtualThread.java:287)
	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:174)
	at java.base/jdk.internal.vm.Continuation.enter0(Continuation.java:327)
	at java.base/jdk.internal.vm.Continuation.enter(Continuation.java:320)
Caused by: java.lang.ExceptionInInitializerError: null
	at com.app.database.entity.habit.EntryEntity$Companion.<init>(EntryEntity.kt:52)
	at com.app.database.entity.habit.EntryEntity$Companion.<init>(EntryEntity.kt)
	at com.app.database.entity.habit.EntryEntity.<clinit>(EntryEntity.kt:63)
	at com.app.database.entity.UserEntity.<init>(UserEntity.kt:45)
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:67)
	... 24 common frames omitted
Caused by: java.lang.NullPointerException: Parameter specified as non-null is null: method com.app.database.entity.base.SyncedTable.updateHook, parameter entity
	at com.app.database.entity.base.SyncedTable.updateHook(SyncedEntity.kt)
	at com.app.database.entity.habit.EntryTable.<clinit>(EntryEntity.kt:47)
	... 29 common frames omitted
INFO  Application - 500 Internal Server Error: POST - /api/auth/email/login in 560ms

The updateHook is a function that is being called in EntryTable.init() block. Here's the content:

fun updateHook(entity: UUIDEntityClass<SyncedEntity>) {
        EntityHook.subscribe { action ->
            try {
                if (action.entityClass != entity) return@subscribe
                when (action.changeType) {
                    EntityChangeType.Updated -> {
                        val e = requireNotNull(action.toEntity(entity))
                        e.updatedAt = Clock.System.now()
                    }
                    EntityChangeType.Removed -> {
                        val id = action.entityId.value as UUID
                        DeletedRecordEntity.new(id, action.entityClass.table.nameInDatabaseCase(), null)
                    }
                    EntityChangeType.Created -> Unit
                }
            } catch (expected: Exception) {
                exposedLogger.error(expected)
            }
        }
    }

The exception arises because the companion object is null or not found for some reason.

I'm using:

  • gradle 8.0.2
  • JDK 19
  • K2 Compiler
  • Exposed 0.41.1

I've investigated into what may be causing the bug already.
This bug is NOT related to the usage of gradle version, JDK version and K2 compiler version.
It can be reproduced on my local environment as soon as I set the DEBUG env variable to false, so the docker image is not at fault too.

The jar is being built by the shadow plugin which is used by Ktor internally. The shadow plugin may be at fault here.
The only somewhat related issue I could find is GradleUp/shadow#843

What in the world is going on?

Who is changing what when the DEBUG variable is present so that the bug stops reproducing itself?
@AlexeySoshin
Copy link
Contributor

From your stack trace, the issue is not with how your updateHook is defined, but with how it is called.

My guess is that you're calling it from an init block of some entity?

@Nek-12
Copy link
Author

Nek-12 commented Mar 31, 2023

As I've explained in the issue body, I'm calling it from an EntryTable.init() block

@Nek-12
Copy link
Author

Nek-12 commented Apr 2, 2023 •
edited
Loading

After an investigation, I discovered that the following was the issue:

  1. There was an inheritance relationship involved for that particular entity and table. The code was declared in a parent table definition
  2. The code was invoked in a constructor of the Table, which is an object.
  3. The EntityClass is an object too, it is declared after the Table in the same file
  4. The table was accessed before the EntityClass object when DEBUG was off (in the first query) internally by Exposed.
  5. When DEBUG was TRUE, the EntityClass was accessed before the table definition

As a result, when the table was accessed for a query by Exposed for the first time, the child object was accessed first, which was trying to access the EntityClass, but the EntityClass tried to access the table which was not initialized yet. As a result, null was simply passed as an argument to the parent class's updateHook, due to a race/circular dependency.
This did not happen for tables where inheritance was not involved (for some reason?).

The method of declaring the updateHook was taken from one of the Github issues in the app and was actually used widely in the project before, and we did not notice the catch there.
So the issue is partially with the lacking documentation (#1703) and partially our fault, but regardless, I'm sorry for blaming everything on the library.

@Nek-12 Nek-12 closed this as completed Apr 2, 2023
@AlexeySoshin
Copy link
Contributor

Appreciate the investigation done, @Nek-12 !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@AlexeySoshin @Nek-12