Upgrade xwiki 9.11.4 to 10.11.1 issues: database upgrade failed due to migration because store.attachment.hint=file cause

Help / Discuss
#1

Hello

I failed to upgrade my xwiki 9.11.4 to 10.11.1 (linux + tomcat-8.5.11+ jdk1.8.0_121+ postgresql via JNDI).
I used attachment storage = filesystem
I could not know the way I can debug this because I have some file issue and database issue too.
I managed one upgrade on another xwiki anyways (same xwiki version but older tomcat 8.0.33+ older java 1.8.0.71 version and xwiki content)
Any helps?
Thxs
Here, my catalina displayed these strange logs:

2019-01-22 14:04:56,162 [XWiki initialization] INFO  .HibernateDataMigrationManager - Starting data migration [R1001000XWIKI14758] with version [1001000] on database [xwiki] 
2019-01-22 14:04:56,199 [XWiki initialization] INFO  1001000XWIKI14758DataMigration - Renaming folder [/xxxxxxx/storage/xwiki/%45ncyclop%C3%A9die/SMQ-M2+%3A+Pr%C3%A9sentation+du+syst%C3%A8me+de+management+de+la+quait%C3%A9+du+CP2I] into [/xxxxxxx/storage/xwiki/%45ncyclop%C3%A9die/%53%4D%51-%4D2 %3A %50r%C3%A9sentation du syst%C3%A8me de management de la quait%C3%A9 du %43%502%49] 
2019-01-22 14:04:56,200 [XWiki initialization] INFO  1001000XWIKI14758DataMigration - Renaming folder [/xxxxxxx/storage/xwiki/%45ncyclop%C3%A9die/%53%4D%51-%4D2 %3A %50r%C3%A9sentation du syst%C3%A8me de management de la quait%C3%A9 du %43%502%49/~this/deleted-attachments/Proc%C3%A9dures+processus+management.svg-1443716440514] into [/xxxxxxx/storage/xwiki/%45ncyclop%C3%A9die/%53%4D%51-%4D2 %3A %50r%C3%A9sentation du syst%C3%A8me de management de la quait%C3%A9 du %43%502%49/~this/deleted-attachments/Proc%C3%A9dures processus management.svg-1443716440514] 
...
...
2019-01-22 14:04:56,468 [XWiki initialization] ERROR .HibernateDataMigrationManager - Failed to migrate database [xwiki]... 
com.xpn.xwiki.store.migration.DataMigrationException: Data migration R1001000XWIKI14758 failed
	at com.xpn.xwiki.store.migration.hibernate.AbstractHibernateDataMigration.migrate(AbstractHibernateDataMigration.java:114)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrations(AbstractDataMigrationManager.java:848)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.migrateDatabase(AbstractDataMigrationManager.java:743)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrations(AbstractDataMigrationManager.java:664)
	at com.xpn.xwiki.store.migration.hibernate.HibernateDataMigrationManager.startMigrations(HibernateDataMigrationManager.java:346)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrationsOnlyOnce(AbstractDataMigrationManager.java:644)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.tryToProcceedToMigration(AbstractDataMigrationManager.java:621)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.checkDatabase(AbstractDataMigrationManager.java:538)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:339)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:302)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.beginTransaction(HibernateStore.java:472)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.beginTransaction(XWikiHibernateBaseStore.java:682)
	at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(XWikiHibernateStore.java:894)
	at com.xpn.xwiki.store.XWikiCacheStore.loadXWikiDoc(XWikiCacheStore.java:353)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1916)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1978)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocument(XWiki.java:1333)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocuments(XWiki.java:1307)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1225)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1167)
	at com.xpn.xwiki.XWiki.<init>(XWiki.java:1140)
	at com.xpn.xwiki.internal.XWikiInitializerJob.runInternal(XWikiInitializerJob.java:117)
	at org.xwiki.job.AbstractJob.runInContext(AbstractJob.java:236)
	at org.xwiki.job.AbstractJob.run(AbstractJob.java:213)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.xpn.xwiki.XWikiException: Error number 0 in 3: Exception while hibernate execute
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:927)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.executeWrite(XWikiHibernateBaseStore.java:1036)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.hibernateMigrate(R1001000XWIKI14758DataMigration.java:84)
	at com.xpn.xwiki.store.migration.hibernate.AbstractHibernateDataMigration.migrate(AbstractHibernateDataMigration.java:112)
	... 24 common frames omitted
Caused by: org.hibernate.HibernateException: Failed to refactor filesystem store paths
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.lambda$hibernateMigrate$0(R1001000XWIKI14758DataMigration.java:88)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:921)
	... 27 common frames omitted
Caused by: java.io.IOException: Destination '/xxxxxxx/storage/xwiki/%45ncyclop%C3%A9die/%4Darch%C3%A9 de %54ierces %50restations %47%C3%A9omatiques (%54%50%47) 2018 (%45%4E %43%4F%55%52%53 %44%45 %52%45%44%41%43%54%49%4F%4E)/%4Darch%C3%A9 de %54%50%47 - %4C%4F%54 2 %44%45%56%45%4C%4F%50%50%45%4D%45%4E%54 %45%54 %53%55%50%50%4F%52%54 %44%45%53 %4C%4F%47%49%43%49%45%4C%53 %4C%49%42%52%45%53 %51%47%49%53 %45%54 %50%4F%53%54%47%49%53 (%45%4E %43%4F%55%52%53 %44%45 %52%45%44%41%43%54%49%4F%4E)' directory cannot be created
	at org.apache.commons.io.FileUtils.doCopyDirectory(FileUtils.java:1412)
	at org.apache.commons.io.FileUtils.copyDirectory(FileUtils.java:1366)
	at org.apache.commons.io.FileUtils.copyDirectory(FileUtils.java:1246)
	at org.apache.commons.io.FileUtils.copyDirectory(FileUtils.java:1215)
	at org.apache.commons.io.FileUtils.moveDirectory(FileUtils.java:2930)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.migrate(R1001000XWIKI14758DataMigration.java:186)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.migrateDocument(R1001000XWIKI14758DataMigration.java:102)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.migrateDocument(R1001000XWIKI14758DataMigration.java:113)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.migrateDocument(R1001000XWIKI14758DataMigration.java:113)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.migrateDocument(R1001000XWIKI14758DataMigration.java:113)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.lambda$hibernateMigrate$0(R1001000XWIKI14758DataMigration.java:86)
	... 28 common frames omitted
2019-01-22 14:04:56,469 [XWiki initialization] ERROR .HibernateDataMigrationManager - Main wiki database migration failed, it is not safe to continue! 
2019-01-22 14:04:56,470 [XWiki initialization] ERROR c.x.x.XWiki                    - Failed to initialize mandatory document 
com.xpn.xwiki.XWikiException: Error number 3202 in 3: Exception while reading document [xwiki:XWiki.Notifications.Code.NotificationFilterDisplayerClass]
	at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(XWikiHibernateStore.java:1022)
	at com.xpn.xwiki.store.XWikiCacheStore.loadXWikiDoc(XWikiCacheStore.java:353)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1916)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1978)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocument(XWiki.java:1333)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocuments(XWiki.java:1307)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1225)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1167)
	at com.xpn.xwiki.XWiki.<init>(XWiki.java:1140)
	at com.xpn.xwiki.internal.XWikiInitializerJob.runInternal(XWikiInitializerJob.java:117)
	at org.xwiki.job.AbstractJob.runInContext(AbstractJob.java:236)
	at org.xwiki.job.AbstractJob.run(AbstractJob.java:213)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.xpn.xwiki.XWikiException: Error number 3301 in 3: Exception while switching to database xwiki
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:345)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:302)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.beginTransaction(HibernateStore.java:472)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.beginTransaction(XWikiHibernateBaseStore.java:682)
	at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(XWikiHibernateStore.java:894)
	... 12 common frames omitted
Caused by: com.xpn.xwiki.store.migration.DataMigrationException: Main wiki database migration failed, it is not safe to continue!
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrations(AbstractDataMigrationManager.java:667)
	at com.xpn.xwiki.store.migration.hibernate.HibernateDataMigrationManager.startMigrations(HibernateDataMigrationManager.java:346)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrationsOnlyOnce(AbstractDataMigrationManager.java:644)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.tryToProcceedToMigration(AbstractDataMigrationManager.java:621)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.checkDatabase(AbstractDataMigrationManager.java:538)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:339)
	... 16 common frames omitted
2019-01-22 14:04:56,479 [XWiki initialization] ERROR c.x.x.XWiki                    - Failed to initialize mandatory document 
com.xpn.xwiki.XWikiException: Error number 3202 in 3: Exception while reading document [xwiki:XWiki.WikiMacroParameterClass]
	at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(XWikiHibernateStore.java:1022)
	at com.xpn.xwiki.store.XWikiCacheStore.loadXWikiDoc(XWikiCacheStore.java:353)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1916)
	at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1978)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocument(XWiki.java:1333)
	at com.xpn.xwiki.XWiki.initializeMandatoryDocuments(XWiki.java:1307)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1225)
	at com.xpn.xwiki.XWiki.initXWiki(XWiki.java:1167)
	at com.xpn.xwiki.XWiki.<init>(XWiki.java:1140)
	at com.xpn.xwiki.internal.XWikiInitializerJob.runInternal(XWikiInitializerJob.java:117)
	at org.xwiki.job.AbstractJob.runInContext(AbstractJob.java:236)
	at org.xwiki.job.AbstractJob.run(AbstractJob.java:213)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.xpn.xwiki.XWikiException: Error number 3301 in 3: Exception while switching to database xwiki
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:345)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:302)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.beginTransaction(HibernateStore.java:472)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.beginTransaction(XWikiHibernateBaseStore.java:682)
	at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(XWikiHibernateStore.java:894)
	... 12 common frames omitted
Caused by: com.xpn.xwiki.store.migration.DataMigrationException: Migration of database [xwiki] has failed, it could not be safely used! Database is currently in version [911001] while the required version is [1008010].
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.preventAccessToOutdatedDb(AbstractDataMigrationManager.java:594)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.checkDatabase(AbstractDataMigrationManager.java:541)
	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.setWiki(HibernateStore.java:339)
	... 16 common frames omitted
Caused by: com.xpn.xwiki.store.migration.DataMigrationException: Data migration R1001000XWIKI14758 failed
	at com.xpn.xwiki.store.migration.hibernate.AbstractHibernateDataMigration.migrate(AbstractHibernateDataMigration.java:114)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrations(AbstractDataMigrationManager.java:848)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.migrateDatabase(AbstractDataMigrationManager.java:743)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrations(AbstractDataMigrationManager.java:664)
	at com.xpn.xwiki.store.migration.hibernate.HibernateDataMigrationManager.startMigrations(HibernateDataMigrationManager.java:346)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.startMigrationsOnlyOnce(AbstractDataMigrationManager.java:644)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.tryToProcceedToMigration(AbstractDataMigrationManager.java:621)
	at com.xpn.xwiki.store.migration.AbstractDataMigrationManager.checkDatabase(AbstractDataMigrationManager.java:538)
	... 17 common frames omitted
Caused by: com.xpn.xwiki.XWikiException: Error number 0 in 3: Exception while hibernate execute
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:927)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.executeWrite(XWikiHibernateBaseStore.java:1036)
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.hibernateMigrate(R1001000XWIKI14758DataMigration.java:84)
	at com.xpn.xwiki.store.migration.hibernate.AbstractHibernateDataMigration.migrate(AbstractHibernateDataMigration.java:112)
	... 24 common frames omitted
Caused by: org.hibernate.HibernateException: Failed to refactor filesystem store paths
	at org.xwiki.store.filesystem.internal.migration.R1001000XWIKI14758DataMigration.lambda$hibernateMigrate$0(R1001000XWIKI14758DataMigration.java:88)
	at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:921)
	... 27 common frames omitted
#2

It seems I have issues with ’ characters in document name:
ie
Encyclopédie.TPG 2018 - 2022 > Présentation générale du Marché de Tierces Prestations Géomatiques.TPG 2018-2022 > Lot 3 Développement et maintenance d'applications et de composants géomatiques.WebHome
because xwiki 'insert a ’ character during his move command. Her the logs

java.io.IOException: Destination '/xxxxxx/storage/xwiki/%45ncyclop%C3%A9die/%54%50%47 2018 - 2022 %3E %50r%C3%A9sentation g%C3%A9n%C3%A9rale du %4Darch%C3%A9
 de %54ierces %50restations %47%C3%A9omatiques/%54%50%47 2018-2022 %4C%4F%54 3 %44%45%56%45%4C%4F%50%50%45%4D%45%4E%54 %45%54 %4D%41%49%4E%54%45%4E%41%4E%43%45 %44'%41%50%50
%4C%49%43%41%54%49%4F%4E%53 %45%54 %44%45 %43%4F%4D%50%4F%53%41%4E%54%53 %47%45%4F%4D%41%54%49%51%55%45%53 (%45%4E %43%4F%55%52%53 %44%45 %52%45%44%41%43%54%49%4F%4E)' direc
tory cannot be created

(not same document but I can see the ’ character)

#3

My test, I remove my data xwiki directory ( /xxxxxx/) and restart tomcat.
It seems that database upgraded successfully and DW is displayed:

2019-01-22 17:17:18,540 [XWiki initialization] INFO  .HibernateDataMigrationManager - Data migration [R1004001XWIKI15249] applied successfully, database [xwiki] upgraded to version [1004001]
#4

Anyways, I don’t know if it is related about my issue but I have a strange directory “Encyclop%C3%83%C2%A9die” there:

avril 11  2018 Encyclop%C3%83%C2%A9die
nov.  23 14:22 Encyclop%C3%A9die

I have a space name “Encyclopédie” and “Encyclop%C3%83%C2%A9die” directory contains only multiple empty subdirectory. I didn’t managed to remove it from xwiki 9.11.4 version (with deleted doc on Main.AllDocs)
(I deleted it and start another upgrade but same issue)

#5

Hello
Do you have an idea of some tests I could do to fix my issue and/or debug this?
ty

#6

The stack trace you pasted in the first message is incomplete. Would be great if you could extract the whole thing (everything between two lines starting with a date basically).

#7

Sure!
Here you are: https://pastebin.com/t1xK2VLy
Thxs

#8

Thanks.

Caused by: java.io.IOException: Destination ‘/MyAttachmentDataPath/storage/xwiki/%45ncyclop%C3%A9die/%4Darch%C3%A9 de %54ierces %50restations %47%C3%A9omatiques (%54%50%47) 2018 (%45%4E %43%4F%55%52%53 %44%45 %52%45%44%41%43%54%49%4F%4E)/%4Darch%C3%A9 de %54%50%47 - %4C%4F%54 2 %44%45%56%45%4C%4F%50%50%45%4D%45%4E%54 %45%54 %53%55%50%50%4F%52%54 %44%45%53 %4C%4F%47%49%43%49%45%4C%53 %4C%49%42%52%45%53 %51%47%49%53 %45%54 %50%4F%53%54%47%49%53 (%45%4E %43%4F%55%52%53 %44%45 %52%45%44%41%43%54%49%4F%4E)’ directory cannot be created

The reason is that in 10.1 a new format was introduce to support case insensitive FS (the migration which is failing is about that) and that new format encode upper case characters making this specific document store path much longer (because it contains a lot of upper case characters).

Modern filesystem like ext4 do support very big paths, unfortunately it’s not true for a single path element which in your case is 269 (because of upper case encoding).

This issue general long path issue has been fixed in https://jira.xwiki.org/browse/XWIKI-15620 but this is too big of a change for what is supposed to become the new LTS branch very shortly.

#9

ok thxs now I have DW displayed.

  • On xwiki, I permanently delete all entries of deleted documents named “Marché de TPG - LOT 2 DEVELOPPEMENT ET SUPPORT DES LOGICIELS LIBRES QGIS ET POSTGIS (EN COURS DE REDACTION)”
  • On my hard drive, I delete my wrong duplicate subdirectory /home/opera/data_xwiki/storage/xwiki/Encyclop%C3%83%C2%A9die/ (empty)
  • I restarted xwiki 9.11.4 and stop it
  • I upgraded xwiki application to 10.11.1
#10

I will create a jira issue to explain the problem with this use case.

#11

https://jira.xwiki.org/browse/XWIKI-16061