upgrading database from 4.5 to 4.6 - type def not in sequence

[Malte]

Question:
Is this a critical error cause the DB seemed to be fine after a restart. I did not investigate any details though.

Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.TypeCache removeTopicType
INFO: ### Removing topic type "dm4.contacts.address_entry" from type cache
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.TypeCache loadTopicType
INFO: Loading topic type "dm4.contacts.person"
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl installPluginInDB
WARNING: ROLLBACK! (plugin "DeepaMehta 4 Contacts")
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl activate
INFO: ----- Activating plugin "DeepaMehta 4 Files" -----
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl handleEvent
SEVERE: Handling PLUGIN_ACTIVATED event from "de.deepamehta.webbrowser" for plugin "DeepaMehta 4 Contacts" failed
java.lang.RuntimeException: Activation of plugin "DeepaMehta 4 Contacts" failed
	at de.deepamehta.core.impl.PluginImpl.activate(PluginImpl.java:515)
	at de.deepamehta.core.impl.PluginManager.activatePlugin(PluginManager.java:64)
	at de.deepamehta.core.impl.PluginImpl.checkRequirementsForActivation(PluginImpl.java:481)
	at de.deepamehta.core.impl.PluginImpl.handleEvent(PluginImpl.java:913)
	at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415)
	at org.apache.felix.eventadmin.impl.tasks.SyncDeliverTasks$1.run(SyncDeliverTasks.java:145)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Installing plugin "DeepaMehta 4 Contacts" in the database failed
	at de.deepamehta.core.impl.PluginImpl.installPluginInDB(PluginImpl.java:551)
	at de.deepamehta.core.impl.PluginImpl.activate(PluginImpl.java:502)
	... 10 more
Caused by: java.lang.RuntimeException: Running migration 2 of plugin "DeepaMehta 4 Contacts" failed
	at de.deepamehta.core.impl.MigrationManager.runMigration(MigrationManager.java:145)
	at de.deepamehta.core.impl.MigrationManager.runPluginMigration(MigrationManager.java:100)
	at de.deepamehta.core.impl.MigrationManager.runPluginMigrations(MigrationManager.java:68)
	at de.deepamehta.core.impl.PluginImpl.installPluginInDB(PluginImpl.java:540)
	... 11 more
Caused by: java.lang.RuntimeException: Fetching topic type "dm4.contacts.person" failed
	at de.deepamehta.core.impl.EmbeddedService.getTopicType(EmbeddedService.java:324)
	at de.deepamehta.plugins.contacts.migrations.Migration2.run(Migration2.java:50)
	at de.deepamehta.core.impl.MigrationManager.runMigration(MigrationManager.java:137)
	... 14 more
Caused by: java.lang.RuntimeException: DB inconsistency: type "dm4.contacts.person" has 4 association definitions but in sequence are 1
	at de.deepamehta.core.impl.TypeStorageImpl.fetchAssociationDefinitions(TypeStorageImpl.java:286)
	at de.deepamehta.core.impl.TypeStorageImpl.fetchTopicType(TypeStorageImpl.java:108)
	at de.deepamehta.core.impl.TypeStorageImpl.getTopicType(TypeStorageImpl.java:72)
	at de.deepamehta.core.impl.TypeCache.loadTopicType(TypeCache.java:97)
	at de.deepamehta.core.impl.TypeCache.getTopicType(TypeCache.java:47)
	at de.deepamehta.core.impl.EmbeddedService.getTopicType(EmbeddedService.java:322)
	... 16 more

Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl createPluginTopicIfNotExists
INFO: Installing plugin "DeepaMehta 4 Files" in the database ABORTED -- already installed
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.MigrationManager runPluginMigrations
INFO: Running migrations for plugin "DeepaMehta 4 Files" ABORTED -- everything up-to-date (migrationNr=1)
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl publishDirectory
INFO: ### Publishing directory "" at URI namespace "/filerepo"
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl registerListeners
INFO: Registering event listeners of plugin "DeepaMehta 4 Files" ABORTED -- no event listeners implemented
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl registerPluginService
INFO: Registering service "de.deepamehta.plugins.files.service.FilesService" at OSGi framework
Nov 23, 2015 9:53:00 PM de.deepamehta.core.impl.PluginImpl activate
INFO: ----- Activation of plugin "DeepaMehta 4 Files" complete -----

[jri]

Oh, that's interesting!

After investigating this I learned there is indeterminism involved here.
This error occurs if the Contacts migration 2 (part of DM 4.6) runs before the Type Editor plugin is activated.

When updating to 4.6 fails shutdown and start again. The next time Type Editor might be activated before Contacts. Retry this until all plugins are activated. The Contacts migration will finally run properly.

The proper solution is to remove that indeterminism by adding importModels=de.deepmehta.typeeditor to the Contacts plugin. I will do so for the next release.

Background: Contacts migration no. 2 replaces the Phone/Address? "Entry" topic types by corresponding association types and deletes the topic types. When deleting a topic type which is involved in an Assoc Def as a child type the Type Editor plugin hooks in and rebuilds the "sequence". (The sequence is the internal data structure that defines the order of the child types.) If the rebuild doesn't happen (because the Type Editor plugin is not yet activated) the sequence will be broken, resulting in a corrupt parent type.

Note: the DB rollback will remove that corruption. The memory (type cache) however is not rolled back. That is why you need to actually restart the server (in contrast to e.g. refreshing the Contacts plugin).

Lesson learned for plugin developers:
if your plugin uses a migration to delete a topic type which is involved in an Assoc Def as a child type your plugin MUST declare de.deepmehta.typeeditor in its importModels property.

(This apparently is not a comfortable situation for the plugin developer. The Core should care about the type definitions automatically.)

BTW: now it becomes clear that importModels should actually be renamed to waitFor. See #840, in particular ticket:840#comment:2.

That you very much for revealing this undetermined problem!

[Malte]

Ok, thanks! That would also explains why, in another try i just performed, the migration just ran through fine (without such an exception).

Also for the explanation about my question: In this case of an exception the necessary Migration is rolled back, which equals to not performed and the database upgrade can not be regarded as complete.

[Jörg Richter <jri@…>]

In 22eca4cfb8c48e09e45da0e2b140bdaa514adcde/deepamehta:

Contacts: fix 4.5 -> 4.6 upgrade (#900).

The Contacts plugin now waits for the Type Editor plugin.

Note: Contacts migration no. 2 (as of DM 4.6) deletes the "Entry" child topic types.
At that time the Type Editor must be in place in order to maintain the assoc def sequence.

Thank you very much, Malte, for reporting!

See #900.

[Malte]

Could it be that this dependency is also need if my plugin just adds a new assocDef to an existing "Type Definition". I ask because i had the same error in another context but there the migration just uses addAssocDef and nothing more.

[Malte]

Thanks for the clarification on the phone!

[jri]

Replying to jri:

if your plugin uses a migration to delete a topic type which is involved in an Assoc Def as a child type your plugin MUST declare de.deepmehta.typeeditor in its importModels property.

(This apparently is not a comfortable situation for the plugin developer. The Core should care about the type definitions automatically.)

This is now addressed in the follow-up #942.