Combining c3p0 with Sqlite - table exists after being dropped

[rdehuyss]

Dear,

I'm the maintainer of JobRunr, an open-source distributed background processing framework for Java.

We try to support all major databases and connection pooling framework, including Sqlite and c3p0. We do encounter a bug when combining c3p0 with Sqlite in our tests: for each test, we drop all tables and recreate them to have a blank slate.

When doing so, the dropping of the table succeeds but when we try to recreate the table, it fails complaining that the table is still there. Any idea why this is and what goes wrong?

All code is available in our GitHub repo: https://github.com/jobrunr/jobrunr.
The test in question is: C3p0SqLiteStorageProviderTest

Attached the exception log:

C3p0SqLiteStorageProviderTest > testJobStats() STANDARD_OUT | 539s
-- | --
6179 | Dropped view jobrunr_jobs_stats | 539s
6180 | Dropped table jobrunr_recurring_jobs | 539s
6181 | Dropped table jobrunr_job_counters | 539s
6182 | Dropped table jobrunr_jobs | 539s
6183 | Dropped table jobrunr_backgroundjobservers | 539s
6184 | Dropped table jobrunr_migrations | 539s
6185 |   | 539s
6186 | C3p0SqLiteStorageProviderTest > testJobStats() STANDARD_ERROR | 539s
6187 | [Test worker] INFO org.jobrunr.storage.sql.common.DatabaseCreator - Running migration /org/jobrunr/storage/sql/common/migrations/v0__create_migrations_table.sql | 539s
6188 |   | 540s
6189 | C3p0SqLiteStorageProviderTest > testJobStats() FAILED | 540s
6190 | org.jobrunr.JobRunrException: JobRunr encounterd a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) | 540s
6191 | at org.jobrunr.JobRunrException.shouldNotHappenException(JobRunrException.java:22) | 540s
6192 | at org.jobrunr.storage.sql.common.DatabaseCreator.runMigration(DatabaseCreator.java:75) | 540s
6193 | at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183) | 540s
6194 | at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177) | 540s
6195 | at java.base/java.util.ArrayList.forEach(ArrayList.java:1540) | 540s
6196 | at java.base/java.util.stream.SortedOps$RefSortingSink.end(SortedOps.java:395) | 540s
6197 | at java.base/java.util.stream.Sink$ChainedReference.end(Sink.java:258) | 540s
6198 | at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:485) | 540s
6199 | at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) | 540s
6200 | at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150) | 540s
6201 | at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173) | 540s
6202 | at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) | 540s
6203 | at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497) | 540s
6204 | at org.jobrunr.storage.sql.common.DatabaseCreator.runMigrations(DatabaseCreator.java:48) | 540s
6205 | at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.createDBIfNecessary(DefaultSqlStorageProvider.java:46) | 540s
6206 | at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.<init>(DefaultSqlStorageProvider.java:41) | 540s
6207 | at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.<init>(DefaultSqlStorageProvider.java:35) | 540s
6208 | at org.jobrunr.storage.sql.sqlite.SqLiteStorageProvider.<init>(SqLiteStorageProvider.java:10) | 540s
6209 | at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) | 540s
6210 | at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) | 540s
6211 | at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) | 540s
6212 | at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490) | 540s
6213 | at org.jobrunr.storage.sql.common.SqlStorageProviderFactory.getStorageProvider(SqlStorageProviderFactory.java:105) | 540s
6214 | at org.jobrunr.storage.sql.common.SqlStorageProviderFactory.getSqliteStorageProvider(SqlStorageProviderFactory.java:67) | 540s
6215 | at org.jobrunr.storage.sql.common.SqlStorageProviderFactory.getStorageProviderByJdbcUrl(SqlStorageProviderFactory.java:88) | 540s
6216 | at org.jobrunr.storage.sql.common.SqlStorageProviderFactory.using(SqlStorageProviderFactory.java:24) | 540s
6217 | at org.jobrunr.storage.sql.SqlStorageProviderTest.getStorageProvider(SqlStorageProviderTest.java:26) | 540s
6218 | at org.jobrunr.storage.StorageProviderTest.cleanUpAndSetupBackgroundJobServer(StorageProviderTest.java:66) | 540s
6219 | at jdk.internal.reflect.GeneratedMethodAccessor75.invoke(Unknown Source) | 540s
6220 | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) | 540s
6221 | at java.base/java.lang.reflect.Method.invoke(Method.java:566) | 540s
6222 | at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:686) | 540s
6223 | at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60) | 540s
6224 | at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131) | 540s
6225 | at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149) | 540s
6226 | at org.junit.jupiter.engine.extension.TimeoutExtension.interceptLifecycleMethod(TimeoutExtension.java:126) | 540s
6227 | at org.junit.jupiter.engine.extension.TimeoutExtension.interceptBeforeEachMethod(TimeoutExtension.java:76) | 540s
6228 | at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115) | 540s
6229 | at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105) | 540s
6230 | at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106) | 540s
6231 | at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64) | 540s
6232 | at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45) | 540s
6233 | at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37) | 540s
6234 | at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104) | 540s
6235 | at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98) | 540s
6236 | at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeMethodInExtensionContext(ClassBasedTestDescriptor.java:481) | 540s
6237 | at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$synthesizeBeforeEachMethodAdapter$18(ClassBasedTestDescriptor.java:466) | 540s
6238 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeBeforeEachMethods$2(TestMethodTestDescriptor.java:169) | 540s
6239 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeBeforeMethodsOrCallbacksUntilExceptionOccurs$5(TestMethodTestDescriptor.java:197) | 540s
6240 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6241 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeBeforeMethodsOrCallbacksUntilExceptionOccurs(TestMethodTestDescriptor.java:197) | 540s
6242 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeBeforeEachMethods(TestMethodTestDescriptor.java:166) | 540s
6243 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:133) | 540s
6244 | at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:71) | 540s
6245 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:135) | 540s
6246 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6247 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125) | 540s
6248 | at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135) | 540s
6249 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123) | 540s
6250 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6251 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122) | 540s
6252 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80) | 540s
6253 | at java.base/java.util.ArrayList.forEach(ArrayList.java:1540) | 540s
6254 | at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38) | 540s
6255 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139) | 540s
6256 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6257 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125) | 540s
6258 | at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135) | 540s
6259 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123) | 540s
6260 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6261 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122) | 540s
6262 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80) | 540s
6263 | at java.base/java.util.ArrayList.forEach(ArrayList.java:1540) | 540s
6264 | at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38) | 540s
6265 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139) | 540s
6266 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6267 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125) | 540s
6268 | at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135) | 540s
6269 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123) | 540s
6270 | at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) | 540s
6271 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122) | 540s
6272 | at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80) | 540s
6273 | at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32) | 540s
6274 | at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57) | 540s
6275 | at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51) | 540s
6276 | at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:220) | 540s
6277 | at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:188) | 540s
6278 | at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:202) | 540s
6279 | at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:181) | 540s
6280 | at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128) | 540s
6281 | at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99) | 540s
6282 | at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79) | 540s
6283 | at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75) | 540s
6284 | at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61) | 540s
6285 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) | 540s
6286 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) | 540s
6287 | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) | 540s
6288 | at java.base/java.lang.reflect.Method.invoke(Method.java:566) | 540s
6289 | at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36) | 540s
6290 | at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) | 540s
6291 | at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33) | 540s
6292 | at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94) | 540s
6293 | at com.sun.proxy.$Proxy5.stop(Unknown Source) | 540s
6294 | at org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:132) | 540s
6295 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) | 540s
6296 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) | 540s
6297 | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) | 540s
6298 | at java.base/java.lang.reflect.Method.invoke(Method.java:566) | 540s
6299 | at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36) | 540s
6300 | at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) | 540s
6301 | at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182) | 540s
6302 | at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164) | 540s
6303 | at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:412) | 540s
6304 | at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64) | 540s
6305 | at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48) | 540s
6306 | at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) | 540s
6307 | at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) | 540s
6308 | at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56) | 540s
6309 | at java.base/java.lang.Thread.run(Thread.java:834) | 540s
6310 |   | 540s
6311 | Caused by: | 540s
6312 | java.lang.IllegalStateException: Error running database migration v0__create_migrations_table.sql | 540s
6313 | at org.jobrunr.storage.sql.common.DatabaseCreator.runMigration(DatabaseCreator.java:75) | 540s
6314 | ... 117 more | 540s
6315 |   | 540s
6316 | Caused by: | 540s
6317 | java.sql.BatchUpdateException: batch entry 0: [SQLITE_ERROR] SQL error or missing database (table jobrunr_migrations already exists) | 540s
6318 | at org.sqlite.jdbc3.JDBC3Statement.executeBatch(JDBC3Statement.java:205) | 540s
6319 | at com.mchange.v2.c3p0.impl.NewProxyStatement.executeBatch(NewProxyStatement.java:1013) | 540s
6320 | at org.jobrunr.storage.sql.common.DatabaseCreator.runMigrationStatement(DatabaseCreator.java:85) | 540s
6321 | at org.jobrunr.storage.sql.common.DatabaseCreator.runMigration(DatabaseCreator.java:72) | 540s
6322 | ... 117 more

[swaldman]

Is the work transactional? You might be missing an explicit commit. c3p0 rollsback uncommitted work by default, but that behavior is undefined, perhaps others autocommit?

You might try setting c3p0 config param autoCommitOnClose.