Exceptions: "javax.jdo.JDOFatalUserException: Persistence Manager has been closed"

[jphalip]

• HiveRunner Version: 6.1.0
• Hive Versions: 3.1.2

Hi,

I'm getting multiple exceptions like the following two stacktraces while running my tests:

2022-05-18 15:04:09 ERROR Error polling for notification events
java.io.IOException: MetaException(message:Persistence Manager has been closed)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$MSClientNotificationFetcher.getCurrentNotificationEventId(EventUtils.java:75)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.init(EventUtils.java:142)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.<init>(EventUtils.java:116)
        at org.apache.hadoop.hive.ql.metadata.events.NotificationEventPoll$Poller.run(NotificationEventPoll.java:139)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: MetaException(message:Persistence Manager has been closed)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:208)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:108)
        at com.sun.proxy.$Proxy23.get_current_notificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getCurrentNotificationEventId(HiveMetaStoreClient.java:2723)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:212)
        at com.sun.proxy.$Proxy24.getCurrentNotificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$MSClientNotificationFetcher.getCurrentNotificationEventId(EventUtils.java:73)
        ... 10 more
Caused by: javax.jdo.JDOFatalUserException: Persistence Manager has been closed
        at org.datanucleus.api.jdo.JDOPersistenceManager.assertIsOpen(JDOPersistenceManager.java:2212)
        at org.datanucleus.api.jdo.JDOPersistenceManager.evictAll(JDOPersistenceManager.java:494)
        at org.apache.hadoop.hive.metastore.ObjectStore.rollbackTransaction(ObjectStore.java:803)
        at org.apache.hadoop.hive.metastore.ObjectStore.rollbackAndCleanup(ObjectStore.java:10835)
        at org.apache.hadoop.hive.metastore.ObjectStore.getCurrentNotificationEventId(ObjectStore.java:9616)
        at sun.reflect.GeneratedMethodAccessor312.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:97)
        at com.sun.proxy.$Proxy21.getCurrentNotificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_current_notificationEventId(HiveMetaStore.java:7485)
        at sun.reflect.GeneratedMethodAccessor311.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
        ... 20 more

And:

2022-05-18 15:06:05 ERROR Retrying HMSHandler after 2000 ms (attempt 9 of 10) with error: javax.jdo.JDOFatalUserException: Persistence Manager has been closed
        at org.datanucleus.api.jdo.JDOPersistenceManager.assertIsOpen(JDOPersistenceManager.java:2212)
        at org.datanucleus.api.jdo.JDOPersistenceManager.evictAll(JDOPersistenceManager.java:494)
        at org.apache.hadoop.hive.metastore.ObjectStore.rollbackTransaction(ObjectStore.java:803)
        at org.apache.hadoop.hive.metastore.ObjectStore.rollbackAndCleanup(ObjectStore.java:10835)
        at org.apache.hadoop.hive.metastore.ObjectStore.getCurrentNotificationEventId(ObjectStore.java:9616)
        at sun.reflect.GeneratedMethodAccessor312.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:97)
        at com.sun.proxy.$Proxy21.getCurrentNotificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_current_notificationEventId(HiveMetaStore.java:7485)
        at sun.reflect.GeneratedMethodAccessor311.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:108)
        at com.sun.proxy.$Proxy23.get_current_notificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getCurrentNotificationEventId(HiveMetaStoreClient.java:2723)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:212)
        at com.sun.proxy.$Proxy24.getCurrentNotificationEventId(Unknown Source)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$MSClientNotificationFetcher.getCurrentNotificationEventId(EventUtils.java:73)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.init(EventUtils.java:142)
        at org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.<init>(EventUtils.java:116)
        at org.apache.hadoop.hive.ql.metadata.events.NotificationEventPoll$Poller.run(NotificationEventPoll.java:139)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

The tests eventually complete successfully. So the main issue is that these exceptions add noise to the output, and I think they also cause the tests to run slower.

I've found that Issue #19 talks about a similar problem. Does something in the above stacktraces jumps at you to explain what might be causing this, and how to fit it?

BTW, thanks a lot for a great project. I've found HiveRunner to be super useful!

[massdosage]

I'm afraid I don't know. It looks like something is closing the persistence manager early, or something is running which expects it to be open but it isn't. Maybe there is some service which is turned on by default in Hive 3 that needs to be disabled? Or the opposite - something that needs to be enabled.

Is there anything else in the log when it starts up that indicates an error or something misconfigured? What is datanucleus.autoStartMechanismMode set to and does that show up in the logs anywhere?

[jphalip]

Thanks for the reply. Where should I look exactly for the logs? Also, how can I look up the value of datanucleus.autoStartMechanismMode? I'm not sure where to look for those in the context of using HiveRunner.

By the way, while searching Github for similar issues, I came across this comment in another project: apache/iceberg#1478 (comment)

That comment mentions something about configuration not being passed correctly to different threads. Does that ring a bell at all?

Thank you.

[massdosage]

By "logs" I just meant the full output you see in the console when you run the test.

To look at the value of the configuration you could try debug the test and put a breakpoint somewhere near where this is happening and then inspect the values, probably in the HiveConf object.

That comment from Iceberg that you linked does look potentially relevant, I'm just not exactly sure where in HiveRunner we'd need to ensure the configuration is passed long if this is indeed the problem.