Adobe Experience Manager Sites & More

homerfv · 5/14/18

Hi Folks,

I am upgrading AEM 5.6 to 6.3 and encountered some this issue along the way.

Below is the command I used to initiate the upgrade.

java -server -Xmx4096m -XX:MaxPermSize=512M -Djava.awt.headless=true -Dsling.run.modes=author,crx3,crx3tar,nosamplecontent -Doak.queryLimitInMemory=1000000 -Doak.queryLimitReads=500000 -jar crx-quickstart/app/cq-quickstart-6.3.0-standalone-quickstart.jar start -c crx-quickstart -i launchpad -p 4502 -Dsling.properties=conf/sling.properties

Below is the log error

14.05.2018 22:07:39.001 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode /var/upgrade/status/Cq60SocialContentUpgrade does not exist, upgrade needed

14.05.2018 22:07:39.001 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK STARTING: Cq60SocialContentUpgrade

14.05.2018 22:07:39.002 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Comment nodetype upgrade started.

14.05.2018 22:07:39.003 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Upgrading node type cq:Comment

14.05.2018 22:07:39.005 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Unregistering cq:Comment's subtypes.

14.05.2018 22:07:39.089 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider cq:Rating was removed

14.05.2018 22:07:39.089 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider Node type changes: [cq:Rating] appear not to be trivial, starting repository scan

14.05.2018 22:07:39.838 *INFO* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.IndexUpdate Reindexing Traversed #210000 /content/dam/great-eastern/bn/homepage/about-us/company-profile/great-eastern-milestones/small/heritage-2012-small-great-eastern.jpg/jcr:content/metadata/photoshop:TextLayers/19

14.05.2018 22:07:39.839 *INFO* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.IndexUpdate /oak:index/lucene => Indexed 210000 nodes in 2.857 s ...

14.05.2018 22:07:40.000 *INFO* [CommitStats] CommitStats 1231 commits by 2 users [99% sling-event, 0% compat-codeupgrade-service] from 5 locations [52% jobs-task:jobs.tasks.CheckTopologyTask, 30% jobmanager:job-startJobs, 16% jobmanager:job.reschedule, 2 others] (3 types [52% jobs-task, 47% jobmanager, 1 other]) [CommitStats overhead was 334ms = 271.0us / commit]

14.05.2018 22:07:44.146 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider Node type changes: [cq:Rating]; repository scan took 5057ms

14.05.2018 22:07:44.293 *WARN* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Exception in Cq60SocialContentUpgrade.run()

javax.jcr.AccessDeniedException: Failed to unregister node type cq:Rating

at org.apache.jackrabbit.oak.api.CommitFailedException.asRepositoryException(CommitFailedException.java:231)

at org.apache.jackrabbit.oak.plugins.nodetype.write.ReadWriteNodeTypeManager.unregisterNodeType(ReadWriteNodeTypeManager.java:186)

at com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade.addMixinTo(Cq60SocialContentUpgrade.java:167)

at com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade.doUpgrade(Cq60SocialContentUpgrade.java:94)

at com.day.cq.compat.codeupgrade.impl.AbstractCodeUpgradeTask.run(AbstractCodeUpgradeTask.java:64)

at com.adobe.cq.upgradesexecutor.Activator.runUpgradeTasks(Activator.java:350)

at com.adobe.cq.upgradesexecutor.Activator.finishUpgradeExecution(Activator.java:220)

at com.adobe.cq.upgradesexecutor.Activator.start(Activator.java:170)

at org.apache.felix.framework.util.SecureAction.startActivator(SecureAction.java:697)

at org.apache.felix.framework.Felix.activateBundle(Felix.java:2227)

at org.apache.felix.framework.Felix.startBundle(Felix.java:2145)

at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1372)

at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)

at java.lang.Thread.run(Unknown Source)

Caused by: org.apache.jackrabbit.oak.api.CommitFailedException: OakAccess0000: Access denied

at org.apache.jackrabbit.oak.security.authorization.permission.PermissionValidator.checkPermissions(PermissionValidator.java:242)

at org.apache.jackrabbit.oak.security.authorization.permission.PermissionValidator.propertyChanged(PermissionValidator.java:128)

at org.apache.jackrabbit.oak.spi.commit.VisibleValidator.propertyChanged(VisibleValidator.java:90)

at org.apache.jackrabbit.oak.spi.commit.CompositeEditor.propertyChanged(CompositeEditor.java:91)

at org.apache.jackrabbit.oak.spi.commit.EditorDiff.propertyChanged(EditorDiff.java:93)

at org.apache.jackrabbit.oak.segment.SegmentNodeState.compareProperties(SegmentNodeState.java:621)

at org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:515)

at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148)

at org.apache.jackrabbit.oak.segment.MapRecord.compare(MapRecord.java:489)

at org.apache.jackrabbit.oak.segment.MapRecord.compareBranch(MapRecord.java:568)

at org.apache.jackrabbit.oak.segment.MapRecord.compare(MapRecord.java:467)

at org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:608)

at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148)

at org.apache.jackrabbit.oak.segment.MapRecord.compare(MapRecord.java:415)

at org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:608)

at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148)

at org.apache.jackrabbit.oak.segment.MapRecord$3.childNodeChanged(MapRecord.java:441)

at org.apache.jackrabbit.oak.segment.MapRecord.compare(MapRecord.java:489)

at org.apache.jackrabbit.oak.segment.MapRecord.compare(MapRecord.java:433)

at org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:608)

at org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:52)

at org.apache.jackrabbit.oak.spi.commit.EditorHook.processCommit(EditorHook.java:54)

at org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:61)

at org.apache.jackrabbit.oak.segment.SegmentNodeStore$Commit.prepare(SegmentNodeStore.java:611)

at org.apache.jackrabbit.oak.segment.SegmentNodeStore$Commit.optimisticMerge(SegmentNodeStore.java:634)

at org.apache.jackrabbit.oak.segment.SegmentNodeStore$Commit.execute(SegmentNodeStore.java:690)

at org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:334)

at org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:249)

at org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:260)

at org.apache.jackrabbit.oak.plugins.nodetype.write.ReadWriteNodeTypeManager.unregisterNodeType(ReadWriteNodeTypeManager.java:182)

... 12 common frames omitted

14.05.2018 22:07:44.294 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK FAILED: Cq60SocialContentUpgrade

14.05.2018 22:07:44.295 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode /var/upgrade/status/Cq60MSMContentUpgrade does not exist, upgrade needed

14.05.2018 22:19:18.116 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE FINISHED: 24 CodeUpgradeTasks executed , 1 CodeUpgradeTasks failed (out of 25), total time about 699 seconds

I have done a smoke test after the upgrade and so far the upgraded instance is working fine though the instance i have upgraded is not using the features related to this social thing.

I am not sure what exactly the root cause of the issue, would be great if any one has encounter the same issue and can share thoughts or perhaps solution if there is any.

Sincerely,

Homer

kautuk_sahni · 5/16/18

It is know bug, please create a support ticket for this. Refer them NPR-22352

// Workaround:-

Right now there is a timing problem as the reindexing is taking place while the CodeUpgradeTask is already running. A manual way to get there would be to change org.osgi.framework.startlevel.beginning to 24 in crx-quickstart/conf/sling.properties as the codeupgrade-excutor triggers the tasks in startlevel 25, wait for the corresponding index to build up (please indicate the message in the logs to wait for!), then go to http://<host>:<port>/system/console/vmstat - change startlevel back to 30 (which will unblock the intercepted switch to higher startlevels) and revert the change in the properties file.

-Kautuk

Kautuk Sahni

View solution in original post

kautuk_sahni · 5/16/18

It is know bug, please create a support ticket for this. Refer them NPR-22352

// Workaround:-

Right now there is a timing problem as the reindexing is taking place while the CodeUpgradeTask is already running. A manual way to get there would be to change org.osgi.framework.startlevel.beginning to 24 in crx-quickstart/conf/sling.properties as the codeupgrade-excutor triggers the tasks in startlevel 25, wait for the corresponding index to build up (please indicate the message in the logs to wait for!), then go to http://<host>:<port>/system/console/vmstat - change startlevel back to 30 (which will unblock the intercepted switch to higher startlevels) and revert the change in the properties file.

-Kautuk

Kautuk Sahni

homerfv · 5/16/18

Hi Kautuk,

Thanks for the information that you have provided. I have raised a Daycare ticket for this and still waiting for advice.

I was thinking about your statement "wait for the corresponding index to build up (please indicate the message in the logs to wait for!)" what exactly it means. I'm not sure whether i got your point correctly but i gave it a try.

1) In sling.properties, I added org.osgi.framework.startlevel.beginning=24 at the bottom of the file.

2) Then initiated the upgrade using the same command i posted above.

3) I assume when you mean "wait for the corresponding index to build up" is wait for the re-index to complete hence i waited and monitored the log for a while until i spotted "17.05.2018 13:05:39.672 *INFO* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate [async] Reindexing completed for indexes: [/oak:index/slingeventJob*(1070), /oak:index/versionStoreIndex*(133935), /oak:index/cqTagLucene*(32), /oak:index/counter*(7710), /oak:index/workflowDataLucene*(85540), /oak:index/socialLucene*(0), /content/oak:index/enablementResourceName*(0), /oak:index/authorizables*(534), /oak:index/ntBaseLucene*(289967), /oak:index/commerceLucene*(3), /oak:index/cqProjectLucene*(0), /oak:index/cqMobileAppLucene*(0), /oak:index/damAssetLucene*(15283), /oak:index/cqPageLucene*(11463)] in 5.685 min". I noticed also that the cpu usage has gone down after it hence i thought it was the right time to put back the start level to 30 hence i did.

4) After i set back the start level to 30, i noticed the cpu usage suddenly increased again denoting that upgrade has continued spotting "17.05.2018 13:22:54.611 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE STARTS - StartupMode is UPDATE" in the log.

I waited until the final report is shown in the log and unfortunately the same error occur.

Below is the remaining of the error log.

17.05.2018 13:23:56.327 *ERROR* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator OSGI installer finished and the upgrade task condition was not satisfied. Executing installed upgrade tasks but most likely one of the mandatory upgrade tasks was not executed. Please check the log file.

17.05.2018 13:23:56.333 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator Collecting CodeUpgradeTasks

17.05.2018 13:23:56.336 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK FILTERS - 2 com.day.cq.compat.codeupgrade.CodeUpgradeTaskFilter services found

17.05.2018 13:23:56.338 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator Checking 25 candidate CodeUpgradeTasks: [Cq561SocialContentUpgrade, Cq561ProjectContentUpgrade, Cq60SocialContentUpgrade, Cq60MSMContentUpgrade, Cq61CloudServicesContentUpgrade, Cq61CloudSettingsContentUpgrade, Cq62WorkflowContentUpgrade, CQ63ProcessingProfileConfigUpdate, Cq62TargetContentUpgrade, CQ63MetadataSchemaConfigUpdate, CQ63InboxItemsUpgrade, Cq62TargetCampaignsContentUpgrade, Cq62MediaContentUpgrade, Cq62MobileContentUpgrade, Cq62PrimaryComponentsUpgrade, CQ62Html5SmartFileUpgrade, Cq62ProjectsCodeUpgrade, CQ63MonitoringDashboardsConfigUpdate, CQ63AssetsMetadataFormsUpdate, CQ63MobileAppsContentUpgrade, CQ63ToolsMenuEntriesContentUpgrade, Cq62ConfContentUpgrade, Cq62FormsContentUpgrade, CQ63AssetsSearchFacetsUpdate, CqMergeBackupUpgrade]

17.05.2018 13:23:56.344 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode /var/upgrade/status/Cq561SocialContentUpgrade does not exist, upgrade needed

17.05.2018 13:23:56.344 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK STARTING: Cq561SocialContentUpgrade

17.05.2018 13:23:56.346 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561SocialContentUpgrade Start upgrade.

17.05.2018 13:23:56.358 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561SocialContentUpgrade Upgrading comments.

17.05.2018 13:23:56.359 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561SocialContentUpgrade Upgrading attachments.

17.05.2018 13:23:56.359 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561SocialContentUpgrade Upgrading tally nodes.

17.05.2018 13:23:56.359 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561SocialContentUpgrade All done.

17.05.2018 13:23:56.370 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode Upgrade recorded, /var/upgrade/status/Cq561SocialContentUpgrade set to Thu May 17 13:23:56 SGT 2018

17.05.2018 13:23:56.371 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK DONE: Cq561SocialContentUpgrade

17.05.2018 13:23:56.371 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode /var/upgrade/status/Cq561ProjectContentUpgrade does not exist, upgrade needed

17.05.2018 13:23:56.371 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK STARTING: Cq561ProjectContentUpgrade

17.05.2018 13:23:56.372 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561ProjectContentUpgrade Start Project Content upgrade.

17.05.2018 13:23:56.373 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq561.Cq561ProjectContentUpgrade All done.

17.05.2018 13:23:56.377 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode Upgrade recorded, /var/upgrade/status/Cq561ProjectContentUpgrade set to Thu May 17 13:23:56 SGT 2018

17.05.2018 13:23:56.378 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK DONE: Cq561ProjectContentUpgrade

17.05.2018 13:23:56.378 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.StatusNode /var/upgrade/status/Cq60SocialContentUpgrade does not exist, upgrade needed

17.05.2018 13:23:56.378 *INFO* [FelixStartLevel] com.adobe.cq.upgradesexecutor.Activator UPGRADE TASK STARTING: Cq60SocialContentUpgrade

17.05.2018 13:23:56.379 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Comment nodetype upgrade started.

17.05.2018 13:23:56.380 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Upgrading node type cq:Comment

17.05.2018 13:23:56.383 *INFO* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Unregistering cq:Comment's subtypes.

17.05.2018 13:23:56.450 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider cq:Rating was removed

17.05.2018 13:23:56.450 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider Node type changes: [cq:Rating] appear not to be trivial, starting repository scan

17.05.2018 13:23:57.195 *INFO* [Apache Sling Resource Resolver Finalizer Thread] com.adobe.granite.repository Service [7656, [org.apache.jackrabbit.oak.api.jmx.SessionMBean]] ServiceEvent UNREGISTERING

17.05.2018 13:23:57.199 *INFO* [Apache Sling Resource Resolver Finalizer Thread] com.adobe.granite.repository Service [7642, [org.apache.jackrabbit.oak.api.jmx.SessionMBean]] ServiceEvent UNREGISTERING

17.05.2018 13:24:02.597 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.nodetype.TypeEditorProvider Node type changes: [cq:Rating]; repository scan took 6147ms

17.05.2018 13:24:02.653 *WARN* [FelixStartLevel] com.day.cq.compat.codeupgrade.impl.cq60.Cq60SocialContentUpgrade Exception in Cq60SocialContentUpgrade.run()