Bug when updating to Metadata Mapping 1.2

Hello all–

fyi, I think we’ve encountered a bug when upgrading to the latest version of the Metadata Mapping module.

It’s not a blocker, because I believe the fix is to simply restart tomcat (and potentially restart all modules manually), but I wanted to note it in case anyone else runs into it.

I believe the issue is caused by the changeset introduced as part of https://issues.openmrs.org/browse/MAP-7

This changeset removes the (deprecated) “Metadata Mapping” privilege from all Roles, and then removes the privilege itself.

However, looking at the logs during startup, we see the following error soon after the that privilege is deleted.

I    NFO 9/28/16 9:13 PM:liquibase: ChangeSet liquibase.xml::metadatamapping-2016-02-12-1646::kosmik ran successfully in 16ms
    INFO 9/28/16 9:13 PM:liquibase: Successfully released change log lock
    INFO - LoggingAdvice.invoke(113) |2016-09-28 21:13:44,362| In method AdministrationService.saveGlobalProperty. Arguments: GlobalProperty=property: metadatam
    apping.started value: true,
    INFO - LoggingAdvice.invoke(150) |2016-09-28 21:13:44,365| Exiting method saveGlobalProperty
    INFO - LoggingAdvice.invoke(113) |2016-09-28 21:13:44,369| In method AdministrationService.saveGlobalProperty. Arguments: GlobalProperty=property: metadatam
    apping.mandatory value: false,
    INFO - LoggingAdvice.invoke(150) |2016-09-28 21:13:44,371| Exiting method saveGlobalProperty
    ERROR - Context.checkCoreDataset(1011) |2016-09-28 21:13:44,415| Error while setting core roles for openmrs system
    org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [org.openmrs.Privilege#Metadata Mapping]
        at org.hibernate.impl.SessionFactoryImpl$2.handleEntityNotFound(SessionFactoryImpl.java:435)
        at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:233)
        at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
        at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
        at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
        at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038)
        at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630)
        at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:236)
        at org.hibernate.collection.PersistentSet.initializeFromCache(PersistentSet.java:147)
        at org.hibernate.cache.entry.CollectionCacheEntry.assemble(CollectionCacheEntry.java:58)
        at org.hibernate.event.def.DefaultInitializeCollectionEventListener.initializeCollectionFromCache(DefaultInitializeCollectionEventListener.java:159)
        at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:71)
        at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1863)
        at org.hibernate.collection.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:479)
        at org.hibernate.engine.StatefulPersistenceContext.initializeNonLazyCollections(StatefulPersistenceContext.java:900)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:279)
        at org.hibernate.loader.Loader.doList(Loader.java:2533)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
        at org.hibernate.loader.Loader.list(Loader.java:2271)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
        at org.openmrs.api.db.hibernate.HibernateUserDAO.getAllRoles(HibernateUserDAO.java:232)
        at org.openmrs.api.impl.UserServiceImpl.getAllRoles(UserServiceImpl.java:268)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at com.sun.proxy.$Proxy29.getAllRoles(Unknown Source)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.openmrs.aop.LoggingAdvice.invoke(LoggingAdvice.java:118)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at com.sun.proxy.$Proxy30.getAllRoles(Unknown Source)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at com.sun.proxy.$Proxy30.getAllRoles(Unknown Source)
        at org.openmrs.api.context.Context.checkCoreDataset(Context.java:997)
        at org.openmrs.module.ModuleFactory.startModuleInternal(ModuleFactory.java:556)
        at org.openmrs.api.context.Daemon$1.run(Daemon.java:57)

It looks like this is happening when the ensureCoreDataset method is iterating through all Users and Roles to make sure all the relevant roles exist, and then comes across the “Metadata Mappiung” privilege. My guess is that one user (assumedly the admin user) is loaded into Hibernate before the liquibase changesets are run, and then the change deletes the privilege from the database, out from underneath Hibernate, and so then when Hibernate tries to access it further, it bombs.

There are chain of errors after this, and then, in our case, our distro module doesn’t start, resulting in an error when trying to load the home page.

Not sure what the fix is here–and it’s not crucial, because restarting tomcat and restarting all modules resolves the issue–but wanted other to be aware of it in case they run into it.

Take care, Mark

@raff did you happen to see this? :slight_smile:

A quick fix is to move dropping of the privilege from liquibase changeset to module’s activator, see MAP-31.

The proper fix is to clean Hibernate session after applying liquibase changesets, but that will be in openmrs-core, see TRUNK-4959

FYI, I’ve just released Metadata Mapping 1.2.1 with the fix.