Random "Unable to extract field value" when using Auto Upgrade

• Type: Bug
• Status: Closed
• Resolution: Fixed
• Affects Version/s: Master
• Fix Version/s: 7.3.10 DXP GA1, Master
• Component/s: Database Upgrade Framework
• Labels:
  • 7.3-known-issues
  • QA-AUTOMATION
  • liferay-ga2-ce-731
• Fix Priority: 3
• Git Pull Request: https://github.com/brianchandotcom/liferay-portal/pull/86931
• QA Test Name:
  • LocalFile.PortalSmokeUpgrade#ViewPortalSmokeArchiveAutoUpgrade730
• QA Test Score: 4

'Steps to Reproduce:

1. Import attached database (7.3 GA1) into MySQL
2. Set portal property: "upgrade.database.auto.run=true"
3. Start portal to execute upgrade
4. Repeat test multiple times with fresh import since this is not a consistent failure.

Expected Result:
Portal upgrades database and starts without error during startup

Actual Result:
Upgrade sometimes throws errors like:

     [exec] 15:43:40,530 INFO  [main][LoggingTimer:83] Starting com.liferay.portal.upgrade.internal.index.updater.IndexUpdaterUtil#updateIndexes#Updating database indexes for com.liferay.document.library.service
     [exec] 15:43:40,545 INFO  [main][BaseDB:695] Dropping stale indexes
     [exec] 15:43:40,547 INFO  [main][BaseDB:75] Adding indexes
     [exec] 15:43:40,547 INFO  [main][LoggingTimer:44] Completed com.liferay.portal.upgrade.internal.index.updater.IndexUpdaterUtil#updateIndexes#Updating database indexes for com.liferay.document.library.service in 17 ms
     [exec] 15:43:41,834 ERROR [liferay/background_task-10][Field:189] Unable to extract field value
     [exec] java.lang.NullPointerException
     [exec] 	at com.liferay.dynamic.data.mapping.service.DDMStructureLocalServiceUtil.fetchStructure(DDMStructureLocalServiceUtil.java:442)
     [exec] 	at com.liferay.dynamic.data.mapping.storage.Field.getDDMStructure(Field.java:129)
     [exec] 	at com.liferay.dynamic.data.mapping.storage.Field.getValue(Field.java:176)
     [exec] 	at com.liferay.dynamic.data.mapping.storage.Field.getValue(Field.java:165)
     [exec] 	at com.liferay.journal.internal.util.JournalConverterImpl.updateFieldsDisplay(JournalConverterImpl.java:1036)
     [exec] 	at com.liferay.journal.internal.util.JournalConverterImpl.addDDMFields(JournalConverterImpl.java:352)
     [exec] 	at com.liferay.journal.internal.util.JournalConverterImpl.getDDMFields(JournalConverterImpl.java:227)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.extractDDMContent(JournalArticleIndexer.java:627)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.doGetDocument(JournalArticleIndexer.java:433)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.doGetDocument(JournalArticleIndexer.java:119)
     [exec] 	at com.liferay.portal.kernel.search.BaseIndexer.getDocument(BaseIndexer.java:139)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.lambda$reindexArticles$0(JournalArticleIndexer.java:800)
     [exec] 	at com.liferay.portal.kernel.dao.orm.DefaultActionableDynamicQuery.performAction(DefaultActionableDynamicQuery.java:394)
     [exec] 	at com.liferay.portal.kernel.dao.orm.DefaultActionableDynamicQuery$1.call(DefaultActionableDynamicQuery.java:306)
     [exec] 	at com.liferay.portal.kernel.dao.orm.DefaultActionableDynamicQuery$1.call(DefaultActionableDynamicQuery.java:268)
     [exec] 	at com.liferay.portal.kernel.dao.orm.DefaultActionableDynamicQuery.doPerformActions(DefaultActionableDynamicQuery.java:326)
     [exec] 	at com.liferay.portal.kernel.dao.orm.IndexableActionableDynamicQuery.doPerformActions(IndexableActionableDynamicQuery.java:107)
     [exec] 	at com.liferay.portal.kernel.dao.orm.DefaultActionableDynamicQuery.performActions(DefaultActionableDynamicQuery.java:86)
     [exec] 	at com.liferay.portal.kernel.dao.orm.IndexableActionableDynamicQuery.performActions(IndexableActionableDynamicQuery.java:65)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.reindexArticles(JournalArticleIndexer.java:849)
     [exec] 	at com.liferay.journal.internal.search.JournalArticleIndexer.doReindex(JournalArticleIndexer.java:608)
     [exec] 	at com.liferay.portal.kernel.search.BaseIndexer.reindex(BaseIndexer.java:506)
     [exec] 	at com.liferay.portal.search.internal.background.task.ReindexSingleIndexerBackgroundTaskExecutor.reindex(ReindexSingleIndexerBackgroundTaskExecutor.java:81)
     [exec] 	at com.liferay.portal.search.internal.background.task.ReindexBackgroundTaskExecutor.execute(ReindexBackgroundTaskExecutor.java:54)
     [exec] 	at com.liferay.portal.background.task.internal.SerialBackgroundTaskExecutor.execute(SerialBackgroundTaskExecutor.java:62)
     [exec] 	at com.liferay.portal.kernel.backgroundtask.DelegatingBackgroundTaskExecutor.execute(DelegatingBackgroundTaskExecutor.java:41)
     [exec] 	at com.liferay.portal.background.task.internal.ThreadLocalAwareBackgroundTaskExecutor.execute(ThreadLocalAwareBackgroundTaskExecutor.java:72)
     [exec] 	at com.liferay.portal.background.task.internal.messaging.BackgroundTaskMessageListener.doReceive(BackgroundTaskMessageListener.java:136)
     [exec] 	at com.liferay.portal.kernel.messaging.BaseMessageListener.receive(BaseMessageListener.java:26)
     [exec] 	at com.liferay.portal.kernel.messaging.InvokerMessageListener.receive(InvokerMessageListener.java:74)
     [exec] 	at com.liferay.portal.messaging.internal.ParallelDestination$1.run(ParallelDestination.java:56)
     [exec] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
     [exec] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
     [exec] 	at java.lang.Thread.run(Thread.java:745)

No functional impact observed.

Full log https://testray.liferay.com/reports/production/logs/test-1-1/1584366702416/test-portal-upstream(master)/948/functional-tomcat90-mysql57-jdk8/752/0/jenkins-console.txt.gz

Test history of this failure: https://testray.liferay.com/home/-/testray/cases/1012027172/view?p_p_state=normal&orderByCol=createDate_sortable&orderByType=desc&statuses=3&errors=extract