OPATCHAUTO-72043 and JCE

I was applying Grid Infrastructure Jan 2021 Release Update (GI RU) 18.13.0.0.210119 to an 18c cluster the other day.
opatchauto failed with the errors as follows:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 20:40:45 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_08-40-48PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log
The id for this session is 56VW
OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
OPatchAuto failed.

OPatchauto session completed at Wed Jan 27 20:40:53 2021
Time taken to complete the session 0 minute, 8 seconds

 opatchauto failed with error code 42

The session log file:

2021-01-27 20:40:51,664 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto version: 13.9.4.5.0
2021-01-27 20:40:51,666 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log'}
2021-01-27 20:40:51,733 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - crsType: SOFTWARE_INSTALLATION_ONLY
2021-01-27 20:40:51,733 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - running: false
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - OPatchAutoOptions configured options:
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.location:patch-location Value:/u01/swtmp/32226219/
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: home:-oh Value:/u01/app/18.3.0/grid/
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log:-log Value:/u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log_priority:-logLevel Value:INFO
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customLogDir:-customLogDir Value:/u01/app/18.3.0/grid/cfgtoollogs
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: analyze:-analyze Value:true
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: inventory.pointer.location:-invPtrLoc Value:/u01/app/18.3.0/grid//oraInst.loc
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: host:-host Value:rac1.example.com
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.plan:-plan Value:crs-rolling
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: format:-format Value:xml
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: output:-output Value:console
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customconfigdir:-customConfigDir Value:/u01/app/18.3.0/grid/opatchautocfg/db
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: nonrolling:-nonrolling Value:false
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: session:-session Value:56VW
2021-01-27 20:40:52,545 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - The id for this session is 56VW
2021-01-27 20:40:52,545 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='The id for this session is 56VW'}
2021-01-27 20:40:52,549 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:40:52,584 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome]
2021-01-27 20:40:52,602 INFO  [1] com.oracle.helper.util.HelperUtility - Orabasehome Output :
/u01/app/18.3.0/grid

2021-01-27 20:40:52,602 INFO  [1] com.oracle.helper.util.HelperUtility - Oracle Base Home for /u01/app/18.3.0/grid is /u01/app/18.3.0/grid
2021-01-27 20:40:52,603 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:40:52,616 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Entering getPatchPackageFromDir, getting patch object for the given patch location /u01/swtmp/32226219
2021-01-27 20:40:53,135 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator - Bundle.xml does not exist
2021-01-27 20:40:53,135 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator - inventory.xml found at /u01/swtmp/32226219/32216973/etc/config/inventory.xml which implies it is an OPatch Singleton patch
2021-01-27 20:40:53,137 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Command for patch metadata::/u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser
2021-01-27 20:40:53,741 INFO  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Is retry required=false
2021-01-27 20:40:53,742 WARNING [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Patch Collection failed: 
2021-01-27 20:40:53,743 INFO  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Space available after session: 32874 MB
2021-01-27 20:40:53,766 SEVERE [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto failed.
com.oracle.glcm.patch.auto.OPatchAutoException: OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:97)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
	at com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
	at com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
	at com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
Caused by: com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchCollectionException: 
	at com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
	at oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
	at com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
	... 11 more
2021-01-27 20:40:53,767 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.'}
2021-01-27 20:40:53,767 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPatchAuto failed.'}

There are several common scenarios when I see such errors:

• Wrong permissions on patch files
• A wrong folder passed to opatchauto
• Wrong opatch version

None of these was the case:

[grid@rac1 ~]$ /u01/app/18.3.0/grid/OPatch/opatch version
OPatch Version: 12.2.0.1.23

OPatch succeeded.

After checking the usual suspects, I had to enable logging:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -logLevel FINEST -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 20:52:04 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_08-52-07PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log
The id for this session is 7NBB
OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
OPatchAuto failed.

OPatchauto session completed at Wed Jan 27 20:52:12 2021
Time taken to complete the session 0 minute, 8 seconds

 opatchauto failed with error code 42

This time around I got something new:

2021-01-27 20:52:10,508 FINEST [1] com.oracle.cie.common.util.reporting.Reporting - Adding reporter com.oracle.cie.common.util.reporting.console.ConsoleReporter@4445629
2021-01-27 20:52:10,510 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto version: 13.9.4.5.0
2021-01-27 20:52:10,511 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log'}
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardedDatabase set as false
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  DataGuard primary set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardGroup set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardSpace set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  productSupport initialize: com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport@48fa0f47
2021-01-27 20:52:10,517 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:10,577 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - crsType: SOFTWARE_INSTALLATION_ONLY
2021-01-27 20:52:10,577 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - running: false
2021-01-27 20:52:10,577 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - ENTRY
2021-01-27 20:52:10,577 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - CRS stack is down. Now getting crs version by OUI.
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Added Component:oracle.crs
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Added OUI Info to:OraGI18Home1
2021-01-27 20:52:10,660 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ENTRY
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Executing OPatch/opatch version for OracleHome at /u01/app/18.3.0/grid
2021-01-27 20:52:10,968 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - /u01/app/18.3.0/grid has OPatch Version 12.2.0.1.23
2021-01-27 20:52:10,968 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - RETURN
2021-01-27 20:52:10,969 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ENTRY
2021-01-27 20:52:10,969 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ORACLE_BASE for /u01/app/18.3.0/grid is /u01/app/grid
2021-01-27 20:52:10,969 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - RETURN
2021-01-27 20:52:10,969 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Found Local Home:/u01/app/18.3.0/grid
2021-01-27 20:52:10,969 CONFIG [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - Found local home at /u01/app/18.3.0/grid
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - isSingleSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - prepareSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - oopEnabled: false
2021-01-27 20:52:11,112 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.CRSTopologyBuilder - SIDBonly is set to false
2021-01-27 20:52:11,113 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property LocalHost
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property logDir
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SessionID
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property OracleHome
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property LogFileLevel
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConsoleLogLevel
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property OPlanLocation
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConfigXML
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property invPtrLoc
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property UserInvokingOplan
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property RootUser
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property TmpFilesDir
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ExecutionMode
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerURL
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerUser
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerPassword
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property BundlePatchLocation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property RACPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property GIPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AllPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property PatchIDs
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property Operation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SkipConfigValidation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ProductFamily
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property NodeNumberPerReadme
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property MoveConfigToOH
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SelectivePatchingEnabled
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConfigurationSnapshot
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property MinimumOPatchVersion
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property IntgFactoryClass
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property customLogPath
2021-01-27 20:52:11,154 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.CRSTopologyBuilder - Creating config graph from instance
2021-01-27 20:52:11,179 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Actions loaded...
2021-01-27 20:52:11,182 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.SDBProductSupport - Actions loaded...
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - isSingleSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - prepareSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - oopEnabled: false
2021-01-27 20:52:11,211 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - OPatchAutoOptions configured options:
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.location:patch-location Value:/u01/swtmp/32226219/
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: home:-oh Value:/u01/app/18.3.0/grid/
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log:-log Value:/u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log_priority:-logLevel Value:FINEST
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customLogDir:-customLogDir Value:/u01/app/18.3.0/grid/cfgtoollogs
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: analyze:-analyze Value:true
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: inventory.pointer.location:-invPtrLoc Value:/u01/app/18.3.0/grid//oraInst.loc
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: host:-host Value:rac1.example.com
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.plan:-plan Value:crs-rolling
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: format:-format Value:xml
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: output:-output Value:console
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customconfigdir:-customConfigDir Value:/u01/app/18.3.0/grid/opatchautocfg/db
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: nonrolling:-nonrolling Value:false
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: session:-session Value:7NBB
2021-01-27 20:52:11,215 FINE  [1] com.oracle.glcm.patch.auto.tracking.PatchTracking - Adding new execution with id 1 to patch tracking session 7NBB
2021-01-27 20:52:11,222 FINE  [1] com.oracle.glcm.patch.auto.tracking.PatchTracking - Saving patch tracking session to /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/7NBB.json
2021-01-27 20:52:11,421 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - The id for this session is 7NBB
2021-01-27 20:52:11,422 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='The id for this session is 7NBB'}
2021-01-27 20:52:11,424 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - requestedHostName: rac1.example.com
2021-01-27 20:52:11,425 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - formattedHostName: rac1
2021-01-27 20:52:11,425 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:52:11,425 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - Permissions: 700
2021-01-27 20:52:11,428 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, chmod 700 /u01/app/18.3.0/grid/.patch_storage]
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Operation type:apply
2021-01-27 20:52:11,453 FINER [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Unrecognized property "autoDeploymentSubType"
2021-01-27 20:52:11,460 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome]
2021-01-27 20:52:11,461 FINE  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome] in dir null with env null
2021-01-27 20:52:11,477 INFO  [1] com.oracle.helper.util.HelperUtility - Orabasehome Output :
/u01/app/18.3.0/grid

2021-01-27 20:52:11,477 INFO  [1] com.oracle.helper.util.HelperUtility - Oracle Base Home for /u01/app/18.3.0/grid is /u01/app/18.3.0/grid
2021-01-27 20:52:11,478 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:52:11,478 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.oplan.IOUtils - Change the permission of the file /u01/app/18.3.0/grid/cfgtoollogs/opatchautodbto 775
2021-01-27 20:52:11,478 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, grid, -m, -c, chmod 775 /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb]
2021-01-27 20:52:11,492 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:11,492 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:11,494 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Entering getPatchPackageFromDir, getting patch object for the given patch location /u01/swtmp/32226219
2021-01-27 20:52:11,495 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding to the patch factory all supported PatchValidatorsAndGenerators. 
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator
2021-01-27 20:52:11,499 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator
2021-01-27 20:52:11,499 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.CompositePatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.ExapatchPatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.DefaultPatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - patchLocation /u01/swtmp/32226219
2021-01-27 20:52:12,036 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Patch represented by the given patch location /u01/swtmp/32226219 is an Engineered System Patch.
2021-01-27 20:52:12,078 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Trying to create sub patch with the PatchValidatorAndGenerator com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator
2021-01-27 20:52:12,078 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator - Bundle.xml does not exist
2021-01-27 20:52:12,079 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Trying to create sub patch with the PatchValidatorAndGenerator com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator
2021-01-27 20:52:12,079 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator - inventory.xml found at /u01/swtmp/32226219/32216973/etc/config/inventory.xml which implies it is an OPatch Singleton patch
2021-01-27 20:52:12,081 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Command for patch metadata::/u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser
2021-01-27 20:52:12,081 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, grid, -m, -c, /u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser]
2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Error message:Exception in thread "main" java.util.ServiceConfigurationError: java.nio.file.spi.FileSystemProvider: Provider org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider could not be instantiated
	at java.util.ServiceLoader.fail(ServiceLoader.java:232)
	at java.util.ServiceLoader.access$100(ServiceLoader.java:185)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:384)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at java.nio.file.spi.FileSystemProvider.loadInstalledProviders(FileSystemProvider.java:119)
	at java.nio.file.spi.FileSystemProvider.access$000(FileSystemProvider.java:77)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:169)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:166)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.spi.FileSystemProvider.installedProviders(FileSystemProvider.java:166)
	at java.nio.file.FileSystems.newFileSystem(FileSystems.java:388)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:144)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:103)
	at oracle.opatch.wrappers.WrapperFactory.getNioServiceWrapper(WrapperFactory.java:71)
	at oracle.opatch.opatchutil.OUSession.phbasedir(OUSession.java:2594)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatches(OPatchPatch.java:486)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatchesNoSymbolResolve(OPatchPatch.java:456)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.getPatchInfo(PatchMetadataQueryOperation.java:45)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.execute(PatchMetadataQueryOperation.java:26)
	at oracle.opatchauto.core.OpatchAutoCoreUtility.main(OpatchAutoCoreUtility.java:41)
Caused by: java.lang.ExceptionInInitializerError
	at javax.crypto.JceSecurityManager.<clinit>(JceSecurityManager.java:65)
	at javax.crypto.Cipher.getConfiguredPermission(Cipher.java:2590)
	at javax.crypto.Cipher.getMaxAllowedKeyLength(Cipher.java:2614)
	at org.apache.sshd.common.cipher.Cipher.checkSupported(Cipher.java:80)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<init>(BuiltinCiphers.java:104)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<clinit>(BuiltinCiphers.java:55)
	at org.apache.sshd.common.BaseBuilder.<clinit>(BaseBuilder.java:70)
	at org.apache.sshd.client.SshClient.setUpDefaultClient(SshClient.java:778)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:170)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:161)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:157)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:144)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
	... 18 more
Caused by: java.lang.SecurityException: Can not initialize cryptographic mechanism
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:93)
	... 36 more
Caused by: java.lang.SecurityException: The jurisdiction policy files are not signed by the expected signer! (Policy files are specific per major JDK release.Ensure the correct version is installed.)
	at javax.crypto.JarVerifier.verifyPolicySigned(JarVerifier.java:336)
	at javax.crypto.JceSecurity.loadPolicies(JceSecurity.java:378)
	at javax.crypto.JceSecurity.setupJurisdictionPolicies(JceSecurity.java:323)
	at javax.crypto.JceSecurity.access$000(JceSecurity.java:50)
	at javax.crypto.JceSecurity$1.run(JceSecurity.java:85)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:82)
	... 36 more

2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 1
2021-01-27 20:52:12,657 INFO  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Is retry required=false
2021-01-27 20:52:12,657 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Query output::
2021-01-27 20:52:12,657 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Query err::Exception in thread "main" java.util.ServiceConfigurationError: java.nio.file.spi.FileSystemProvider: Provider org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider could not be instantiated
	at java.util.ServiceLoader.fail(ServiceLoader.java:232)
	at java.util.ServiceLoader.access$100(ServiceLoader.java:185)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:384)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at java.nio.file.spi.FileSystemProvider.loadInstalledProviders(FileSystemProvider.java:119)
	at java.nio.file.spi.FileSystemProvider.access$000(FileSystemProvider.java:77)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:169)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:166)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.spi.FileSystemProvider.installedProviders(FileSystemProvider.java:166)
	at java.nio.file.FileSystems.newFileSystem(FileSystems.java:388)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:144)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:103)
	at oracle.opatch.wrappers.WrapperFactory.getNioServiceWrapper(WrapperFactory.java:71)
	at oracle.opatch.opatchutil.OUSession.phbasedir(OUSession.java:2594)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatches(OPatchPatch.java:486)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatchesNoSymbolResolve(OPatchPatch.java:456)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.getPatchInfo(PatchMetadataQueryOperation.java:45)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.execute(PatchMetadataQueryOperation.java:26)
	at oracle.opatchauto.core.OpatchAutoCoreUtility.main(OpatchAutoCoreUtility.java:41)
Caused by: java.lang.ExceptionInInitializerError
	at javax.crypto.JceSecurityManager.<clinit>(JceSecurityManager.java:65)
	at javax.crypto.Cipher.getConfiguredPermission(Cipher.java:2590)
	at javax.crypto.Cipher.getMaxAllowedKeyLength(Cipher.java:2614)
	at org.apache.sshd.common.cipher.Cipher.checkSupported(Cipher.java:80)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<init>(BuiltinCiphers.java:104)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<clinit>(BuiltinCiphers.java:55)
	at org.apache.sshd.common.BaseBuilder.<clinit>(BaseBuilder.java:70)
	at org.apache.sshd.client.SshClient.setUpDefaultClient(SshClient.java:778)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:170)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:161)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:157)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:144)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
	... 18 more
Caused by: java.lang.SecurityException: Can not initialize cryptographic mechanism
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:93)
	... 36 more
Caused by: java.lang.SecurityException: The jurisdiction policy files are not signed by the expected signer! (Policy files are specific per major JDK release.Ensure the correct version is installed.)
	at javax.crypto.JarVerifier.verifyPolicySigned(JarVerifier.java:336)
	at javax.crypto.JceSecurity.loadPolicies(JceSecurity.java:378)
	at javax.crypto.JceSecurity.setupJurisdictionPolicies(JceSecurity.java:323)
	at javax.crypto.JceSecurity.access$000(JceSecurity.java:50)
	at javax.crypto.JceSecurity$1.run(JceSecurity.java:85)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:82)
	... 36 more

2021-01-27 20:52:12,658 FINE  [1] com.oracle.cie.common.util.ResourceBundleManager - The code () is null or not an integer.
2021-01-27 20:52:12,658 WARNING [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Patch Collection failed: 
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.cie.common.util.ResourceBundleManager - The code (OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.) is null or not an integer.
2021-01-27 20:52:12,660 INFO  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Space available after session: 32877 MB
2021-01-27 20:52:12,662 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, cp /tmp/patchingsummary.xml /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/]
2021-01-27 20:52:12,673 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,673 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:12,674 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.oplan.IOUtils - Change the permission of the file /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/patchingsummary.xmlto 775
2021-01-27 20:52:12,674 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, chmod 775 /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/patchingsummary.xml]
2021-01-27 20:52:12,683 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,684 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:12,684 SEVERE [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto failed.
com.oracle.glcm.patch.auto.OPatchAutoException: OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:97)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
	at com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
	at com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
	at com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
Caused by: com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchCollectionException: 
	at com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
	at oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
	at com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
	... 11 more
2021-01-27 20:52:12,685 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.'}
2021-01-27 20:52:12,685 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPatchAuto failed.'}

The errors pointed out to Java: Bug 31997805 - Exception In Thread "root thread" java.lang.exceptionininitializererror in 12.2 Database (Doc ID 31997805.8). To verify that hypothesis, I downloaded Java Cryptography Extension (JCE) Unlimited Strength Jurisdiction Policy Files 8. I copied both local_policy.jar and US_export_policy.jar to /u01/app/18.3.0/grid/OPatch/jre/lib/security, and reran opatchauto.
Sure enough, the analyze command was successful:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/  
OPatchauto session is initiated at Wed Jan 27 21:02:05 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_09-02-08PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_09-02-10PM.log
The id for this session is D2B1

Executing OPatch prereq operations to verify patch applicability on home /u01/app/18.3.0/grid
Patch applicability verified successfully on home /u01/app/18.3.0/grid


Executing patch validation checks on home /u01/app/18.3.0/grid
Patch validation checks successfully completed on home /u01/app/18.3.0/grid

OPatchAuto successful.

--------------------------------Summary--------------------------------

Analysis for applying patches has completed successfully:

Host:rac1
CRS Home:/u01/app/18.3.0/grid
Version:18.0.0.0.0


==Following patches were SUCCESSFULLY analyzed to be applied:

Patch: /u01/swtmp/32226219/32216973
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32216944
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/28655963
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32240606
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32204699
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log



OPatchauto session completed at Wed Jan 27 21:02:38 2021
Time taken to complete the session 0 minute, 33 seconds

The policy files themselves should not be needed since Java 8 Update 161: Unlimited cryptography enabled by default.
The Java version that comes with OPatch 12.2.0.1.23 is newer, so that it should contain the fix:

[grid@rac1 bin]$ /u01/app/18.3.0/grid/OPatch/jre/bin/java -version
java version "1.8.0_271"
Java(TM) SE Runtime Environment (build 1.8.0_271-b03)
Java HotSpot(TM) 64-Bit Server VM (build 25.271-b03, mixed mode)

I also checked with several 19c clusters that these policy files were not there. How come if the OPatch version was the same?

Turns out that when the OPatch was updated, the proper update procedure was not followed: How To Download And Install The Latest OPatch(6880880) Version (Doc ID 274526.1):

• Policy files are present in a vanilla 18c home:

  [grid@rac1 grid]$ unzip -l /u01/swtmp/LINUX.X64_180000_grid_home.zip | grep "OPatch/jre/lib/security/.*.jar"
       3026  06-04-2018 00:52   OPatch/jre/lib/security/US_export_policy.jar
       3527  06-04-2018 00:52   OPatch/jre/lib/security/local_policy.jar
  

• The old OPatch directory was not removed. Instead a newer OPatch version was copied over the existing OPatch folder.
• Since the old OPatch directory was not removed, the policy files were kept after the newer OPatch version was deployed

I just moved the existing OPatch folder and did a clean OPatch deployment:

[grid@rac1 grid]$ mv OPatch/ OPatch_$(date +%Y%m%d)/
[grid@rac1 grid]$ unzip /u01/swtmp/p6880880_190000_Linux-x86-64.zip

The apply analyze command ran without errors and I applied the release update later on:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 21:12:01 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_09-12-04PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_09-12-07PM.log
The id for this session is 3IKL

Executing OPatch prereq operations to verify patch applicability on home /u01/app/18.3.0/grid
Patch applicability verified successfully on home /u01/app/18.3.0/grid


Executing patch validation checks on home /u01/app/18.3.0/grid
Patch validation checks successfully completed on home /u01/app/18.3.0/grid

OPatchAuto successful.

--------------------------------Summary--------------------------------

Analysis for applying patches has completed successfully:

Host:rac1
CRS Home:/u01/app/18.3.0/grid
Version:18.0.0.0.0


==Following patches were SUCCESSFULLY analyzed to be applied:

Patch: /u01/swtmp/32226219/32216973
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32216944
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/28655963
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32240606
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32204699
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log



OPatchauto session completed at Wed Jan 27 21:12:36 2021
Time taken to complete the session 0 minute, 35 seconds

It is crucial to follow Oracle instructions to the letter when it makes sense.
Otherwise, it can lead to such uncommon errors. It is also disappointing that opatchauto did not give any clue what was going on with the default logging level. Thankfully, the logging level can be easily changed. It is a bit verbose but it usually does the job and gives enough information about the cause of an issue.

SYS and Extended Data Types

It is a widely known fact that Oracle supports a maximum size of 32,767 bytes for the VARCHAR2, NVARCHAR2, and RAW data types (Extended Data Types) provided that MAX_STRING_SIZE = EXTENDED. What I recently discovered is that SYS can create such columns even when MAX_STRING_SIZE = STANDARD. It is possible in 12.2, 18c, 19c. I am unsure about 12.1 since I do not have any of those.

Firstly, let us try to create a table with a VARCHAR2(32767) column as non-SYS user:

SQL> conn tc/tc@localhost/pdb2
Connected.
SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> select banner_full from v$version;

BANNER_FULL
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0


SQL> create table t(c varchar2(32767));
create table t(c varchar2(32767))
                          *
ERROR at line 1:
ORA-00910: specified length too long for its datatype

It fails as expected.

Now I try the same as SYS - I also switch to my root container to verify that MAX_STRING_SIZE = STANDARD everywhere:

SQL> conn sys/Oracle123@localhost/orcl2 as sysdba
Connected.
SQL> alter session set container=cdb$root;

Session altered.

SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> alter session set container=pdb2;

Session altered.

SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> select banner_full from v$version;

BANNER_FULL
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0


SQL> create table t(c varchar2(32767));

Table created.

SQL> desc t
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 C                                                  VARCHAR2(32767)

Let us try to run a DML command:

SQL> insert into t values (lpad('x',32767,'x'));

1 row created.

SQL> select length(c) from t;

 LENGTH(C)
----------
      4000

Although it was possible to create a 32K column, somewhere between LPAD and the data layer I still got 4,000 bytes only.
But is it limited to 4,000 bytes? Not really as the example below demonstrates:

SQL> update t
  2     set c=c||'y';

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
      4001

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
      8002

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     16004

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     32008

SQL>
SQL> update t
  2     set c=c||c;
update t
*
ERROR at line 1:
ORA-01489: result of string concatenation is too long


SQL> select length(c) from t;

 LENGTH(C)
----------
     32008

SQL>
SQL> update t
  2     set c=c||lpad('x',759,'x');

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     32767

SQL>
SQL> update t
  2     set c=c||'x';
update t
       *
ERROR at line 1:
ORA-01489: result of string concatenation is too long


SQL> select length(c) from t;

 LENGTH(C)
----------
     32767

As expected Oracle stores the column as LOB under the hood:

SQL> select dbms_metadata.get_ddl('TABLE', 'T') from dual;

DBMS_METADATA.GET_DDL('TABLE','T')
--------------------------------------------------------------------------------

  CREATE TABLE "SYS"."T"
   (    "C" VARCHAR2(32767)
   ) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255
 NOCOMPRESS LOGGING
  STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "SYSTEM"


SQL>
SQL> select column_name, segment_name, index_name, securefile
  2    from user_lobs
  3   where table_name='T';

COLUMN_NAME SEGMENT_NAME              INDEX_NAME                SECUREFILE
----------- ------------------------- ------------------------- ----------
C           SYS_LOB0000023954C00001$$ SYS_IL0000023954C00001$$  NO

Turns out that Oracle uses that internally:

SQL> drop table t;

Table dropped.

SQL>
SQL> select table_name, column_name, data_length
  2    from user_tab_cols
  3   where data_type = 'VARCHAR2'
  4     and data_length > 4000;

TABLE_NAME                COLUMN_NAME          DATA_LENGTH
------------------------- -------------------- -----------
OPATCH_SQL_PATCHES        NODE_NAMES                 32000
SYSDBIMFS_METADATA$       VALUE                       4096
SCHEDULER$_CREDENTIAL     KEY                        32767
V_$DIAG_LOG_EXT           SUPPLEMENTAL_DETAILS        4003

Originally I discovered that Oracle uses VARCHAR2(32767) in its scripts which threw me into a tizzy since the scripts were running without errors in MAX_STRING_SIZE = STANDARD databases.
It is yet another confirmation that it is not a good idea to use SYS to do things. SYS is a "special" user.

Creating a Table for Exchange and Copying Indexes

It is something Oracle added in one of the latest Release Updates of 19c. I believe I discovered it either in 19.7 or 19.8 originally. I used 19.10 in this post.

SQL> select banner_full from v$version;

BANNER_FULL
----------------------------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0

Creating a partitioned table with some local indexes:

SQL> create table t (
  2    created date,
  3    c1 int,
  4    c2 int
  5  )
  6  partition by range(created) interval(numtoyminterval(1, 'year')) (
  7    partition values less than(date'2019-01-01')
  8  );

Table created.

SQL>
SQL> create index t_c1_i on t(c2) local;

Index created.

SQL> create index t_c1_c2_i on t(c1, c2) local;

Index created.

SQL> create index t_created_c1_i on t(trunc(created), c1) local;

Index created.

SQL> create index t_desc_i on t(c1 desc, c2) local;

Index created.

Populating it with some data:

SQL> insert into t values (date'2018-01-01', 1, 10);

1 row created.

SQL> insert into t values (date'2019-01-01', 2, 20);

1 row created.

SQL> insert into t values (date'2020-01-01', 3, 30);

1 row created.

Now is the actual enhancement - the CLONE INDEXES clause:

SQL> alter session set events 'trace[sql_ddl]';

Session altered.

SQL> create table tex for exchange with table t clone indexes;

Table created.

SQL> alter session set events 'trace[sql_ddl] off';

Session altered.

I enabled the SQL_DDL trace event to see the actual DDL statements executed under the hood.
Let us see what indexes are actually created:

SQL> exec dbms_metadata.set_transform_param( -
>   dbms_metadata.session_transform, -
>   'SQLTERMINATOR', true)

PL/SQL procedure successfully completed.

SQL>
SQL> select dbms_metadata.get_ddl('INDEX', index_name) from ind where table_name='TEX';

DBMS_METADATA.GET_DDL('INDEX',INDEX_NAME)
----------------------------------------------------------------------------------------------------

  CREATE INDEX "TC"."I_SYS_23689_T_C1_I" ON "TC"."TEX" ("C2")
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
  TABLESPACE "USERS" ;


  CREATE INDEX "TC"."I_SYS_23689_T_C1_C2_I" ON "TC"."TEX" ("C1", "C2")
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
  TABLESPACE "USERS" ;


  CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX" (TRUNC("CREATED"), "C1")
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
  TABLESPACE "USERS" ;


  CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX" ("C1" DESC, "C2")
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
  TABLESPACE "USERS" ;

Looks good. Let us try to exchange a partition with that table:

SQL> alter table t
  2    exchange partition for (date'2018-01-01')
  3    with table tex
  4    including indexes;

Table altered.

SQL>
SQL> select * from t;

CREATED           C1         C2
--------- ---------- ----------
01-JAN-19          2         20
01-JAN-20          3         30

SQL> select * from tex;

CREATED           C1         C2
--------- ---------- ----------
01-JAN-18          1         10

The entries in the trace file:

*** 2021-01-22T17:45:20.340547+00:00 (PDB2(3))
*** SESSION ID:(5.40211) 2021-01-22T17:45:20.340569+00:00
*** CLIENT ID:() 2021-01-22T17:45:20.340573+00:00
*** SERVICE NAME:(pdb2) 2021-01-22T17:45:20.340576+00:00
*** MODULE NAME:(SQL*Plus) 2021-01-22T17:45:20.340579+00:00
*** ACTION NAME:() 2021-01-22T17:45:20.340583+00:00
*** CLIENT DRIVER:(SQL*PLUS) 2021-01-22T17:45:20.340585+00:00
*** CONTAINER ID:(3) 2021-01-22T17:45:20.340588+00:00

DDL begin in opiprs
session id 5 inc 40211 pgadep 0 sqlid fabsxw9ass76q oct 1 txn 0xaed56ac8 autocommit 1
----- Current SQL Statement for this session (sql_id=fabsxw9ass76q) -----
create table tex for exchange with table t clone indexes

DCSTRC: Deferred Segment Creation Enabled for objn 0.
ctcdrv
session id 5 inc 40211 pgadep 0 sqlid fabsxw9ass76q DDL on 23689 op-alter_table 0
DCSTRC: Inserting into deferred_stg$ objn:23689
stg:0x95fbff70 ts: objno:23689 dobjno:23689 pctfree:127 pctused:127 size:32767 initrans:2147483647 maxtrans:2147483647 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x8 imcflag: 0x0----- Current SQL Statement for this session (sql_id=fabsxw9ass76q) -----
create table tex for exchange with table t clone indexes
----- Abridged Call Stack Trace -----
ksedsts<-kkpoids_insert_deferred_stg<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x753b1c2f5bde975f
DCSTRC: Data Segment for ObjNo: 23689 Not Created
DDL begin in opiprs
session id 17 inc 56060 pgadep 1 sqlid gpda0upp7xs4x oct 9 txn 0xaed56ac8 autocommit 0
----- Current SQL Statement for this session (sql_id=gpda0upp7xs4x) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_I" ON "TC"."TEX"("C2") NOPARALLEL

DCSTRC: Selecting from deferred_stg$ objn:23689
----- Current SQL Statement for this session (sql_id=gpda0upp7xs4x) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_I" ON "TC"."TEX"("C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kkdlgstd<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock
<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr
<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x41a77ef85a8b5b0f
stg:0x7fff61c4c838 ts: objno:0 dobjno:0 pctfree:127 pctused:127 size:32767 initrans:2147483647 maxtrans:2147483647 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x8 imcflag: 0x0ktagetg_ddl sessionid 17 inc 56060 pgadep 1 txn 0xaed56ac8 table 23689 mode 4
DCSTRC: Inserting into deferred_stg$ objn:23690
stg:0x98722108 ts: objno:23690 dobjno:23690 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0----- Current SQL Statement for this session (sql_id=gpda0upp7xs4x) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_I" ON "TC"."TEX"("C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkpoids_insert_deferred_stg<-kdicrws<-kdicdrv<-opiexe<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip
<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x67b767b3ee346cb2
DCSTRC: Index Segment for ObjNo:23690 Not Created
DDL end in opiexe
session id 17 inc 56060 pgadep 1 sqlid gpda0upp7xs4x txn 0xaed56ac8 autocommit 0 commited 0
DDL begin in opiprs
session id 17 inc 56060 pgadep 1 sqlid 890bc4g127vkt oct 9 txn 0xaed56ac8 autocommit 0
----- Current SQL Statement for this session (sql_id=890bc4g127vkt) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_C2_I" ON "TC"."TEX"("C1" , "C2") NOPARALLEL

DCSTRC: Selecting from deferred_stg$ objn:23689
----- Current SQL Statement for this session (sql_id=890bc4g127vkt) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_C2_I" ON "TC"."TEX"("C1" , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kkdlgstd<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock
<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr
<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x41a77ef85a8b5b0f
stg:0x7fff61c4c838 ts: objno:0 dobjno:0 pctfree:127 pctused:127 size:32767 initrans:2147483647 maxtrans:2147483647 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x8 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23690
----- Current SQL Statement for this session (sql_id=890bc4g127vkt) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_C2_I" ON "TC"."TEX"("C1" , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0ktagetg_ddl sessionid 17 inc 56060 pgadep 1 txn 0xaed56ac8 table 23689 mode 4
DCSTRC: Inserting into deferred_stg$ objn:23691
stg:0x98701d48 ts: objno:23691 dobjno:23691 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0----- Current SQL Statement for this session (sql_id=890bc4g127vkt) -----
CREATE INDEX "TC"."I_SYS_23689_T_C1_C2_I" ON "TC"."TEX"("C1" , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkpoids_insert_deferred_stg<-kdicrws<-kdicdrv<-opiexe<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip
<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x67b767b3ee346cb2
DCSTRC: Index Segment for ObjNo:23691 Not Created
DDL end in opiexe
session id 17 inc 56060 pgadep 1 sqlid 890bc4g127vkt txn 0xaed56ac8 autocommit 0 commited 0
DDL begin in opiprs
session id 17 inc 56060 pgadep 1 sqlid dv4r3pvxwh4az oct 9 txn 0xaed56ac8 autocommit 0
----- Current SQL Statement for this session (sql_id=dv4r3pvxwh4az) -----
CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX"(TRUNC("CREATED") , "C1") NOPARALLEL

DCSTRC: Selecting from deferred_stg$ objn:23689
----- Current SQL Statement for this session (sql_id=dv4r3pvxwh4az) -----
CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX"(TRUNC("CREATED") , "C1") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kkdlgstd<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock
<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr
<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x41a77ef85a8b5b0f
stg:0x7fff61c4c838 ts: objno:0 dobjno:0 pctfree:127 pctused:127 size:32767 initrans:2147483647 maxtrans:2147483647 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x8 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23691
----- Current SQL Statement for this session (sql_id=dv4r3pvxwh4az) -----
CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX"(TRUNC("CREATED") , "C1") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23690
----- Current SQL Statement for this session (sql_id=dv4r3pvxwh4az) -----
CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX"(TRUNC("CREATED") , "C1") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0ktagetg_ddl sessionid 17 inc 56060 pgadep 1 txn 0xaed56ac8 table 23689 mode 4
DCSTRC: Inserting into deferred_stg$ objn:23692
stg:0x986e5b68 ts: objno:23692 dobjno:23692 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0----- Current SQL Statement for this session (sql_id=dv4r3pvxwh4az) -----
CREATE INDEX "TC"."I_SYS_23689_T_CREATED_C1_I" ON "TC"."TEX"(TRUNC("CREATED") , "C1") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkpoids_insert_deferred_stg<-kdicrws<-kdicdrv<-opiexe<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip
<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x67b767b3ee346cb2
DCSTRC: Index Segment for ObjNo:23692 Not Created
DDL end in opiexe
session id 17 inc 56060 pgadep 1 sqlid dv4r3pvxwh4az txn 0xaed56ac8 autocommit 0 commited 0
DDL begin in opiprs
session id 17 inc 56060 pgadep 1 sqlid cukauv41bbw51 oct 9 txn 0xaed56ac8 autocommit 0
----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL

DCSTRC: Selecting from deferred_stg$ objn:23689
----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kkdlgstd<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock
<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr
<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x41a77ef85a8b5b0f
stg:0x7fff61c4c838 ts: objno:0 dobjno:0 pctfree:127 pctused:127 size:32767 initrans:2147483647 maxtrans:2147483647 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x8 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23692
----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23691
----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0DCSTRC: Selecting from deferred_stg$ objn:23690
----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkposds_select_deferred_stg<-kkpo_rcinfo_defstg<-ktsircinfo<-kdigetspace2<-kdigetspace<-kkdl1ck<-kkdlack<-kkmfcbbt<-kkmfcbloCbk<-kkmpfcbk<-qcsprfro<-qcsprfro_tree<-qcsprfro_tree<-qcspafq<-qcspqbDescendents<-qcspqb<-kkmdrv<-opiSem<-opiprs<-kksParseChildCursor
<-rpiswu2<-kksLoadChild<-kxsGetRuntimeLock<-kksfbc<-kkspsc0<-kksParseCursor<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8
<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x2e48dfa364bfeef0
stg:0x7fff61c4cd98 ts: objno:0 dobjno:0 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0ktagetg_ddl sessionid 17 inc 56060 pgadep 1 txn 0xaed56ac8 table 23689 mode 4
DCSTRC: Inserting into deferred_stg$ objn:23693
stg:0x986caa78 ts: objno:23693 dobjno:23693 pctfree:10 pctused:127 size:32767 initrans:2 maxtrans:255 initial:4294967295 next:4294967295 optimal:4294967295 minextents:2147483647 maxextents:2147483647 pctinc:2147483647 maxins:0 frlins:65535 tabno:0 NOCOMPRESS/NO ROW LEVEL LOCKING/
flags: 0x0 imcflag: 0x0----- Current SQL Statement for this session (sql_id=cukauv41bbw51) -----
CREATE INDEX "TC"."I_SYS_23689_T_DESC_I" ON "TC"."TEX"("C1" DESC , "C2") NOPARALLEL
----- Abridged Call Stack Trace -----
ksedsts<-kkpoids_insert_deferred_stg<-kdicrws<-kdicdrv<-opiexe<-opiosq0<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkpofmc_form_msq_cix<-kglsscn<-kkpocim_create_indexes_modpart<-ctcdrv<-opiexe<-opiosq0<-kpooprx<-kpoal8<-opiodr<-ttcpip
<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x67b767b3ee346cb2
DCSTRC: Index Segment for ObjNo:23693 Not Created
DDL end in opiexe
session id 17 inc 56060 pgadep 1 sqlid cukauv41bbw51 txn 0xaed56ac8 autocommit 0 commited 0
DDL end in opiexe
session id 5 inc 40211 pgadep 0 sqlid fabsxw9ass76q txn 0xaed56ac8 autocommit 1 commited 1

Probably we will see this improvement documented one day. Not sure whether it is stable or not. I have tested it for some simple examples and it was working well.

Pluggable Database not Opened on all RAC Instances Following Switchover

Environment

• GI and DB version: 19.9

Site A

• Hostnames: raca1.example.com, raca2.example.com
• db_unique_name: racdba
• Instance Names: racdba1, racdba2
• Configuration Type: RAC

Site B

• Hostnames: racb1.example.com, racb2.example.com
• db_unique_name: racdbb
• Instance Names: racdbb1, racdbb2
• Configuration Type: RAC

Initial State

Data Guard Configuration

DGMGRL> show configuration;

Configuration - racdb

  Protection Mode: MaxPerformance
  Members:
  racdba - Primary database
    racdbb - Physical standby database

Fast-Start Failover:  Disabled

Configuration Status:
SUCCESS   (status updated 116 seconds ago)

RACDBA: primary

SYS@RACDBA> select database_role from v$database;

DATABASE_ROLE
----------------
PRIMARY

SYS@RACDBA>
SYS@RACDBA> select *
  2    from dba_pdb_saved_states
  3   order by con_id, instance_name;

 CON_ID CON_NAME INSTANCE_NAME    CON_UID GUID                             STATE          RESTRICTED
------- -------- ------------- ---------- -------------------------------- -------------- ----------
      3 PDB      racdba1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdba2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO

SYS@RACDBA>
SYS@RACDBA>
SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

RACDBB: standby

SYS@RACDBB> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SYS@RACDBB>
SYS@RACDBB> select *
  2    from dba_pdb_saved_states
  3   order by con_id, instance_name;

 CON_ID CON_NAME INSTANCE_NAME    CON_UID GUID                             STATE          RESTRICTED
------- -------- ------------- ---------- -------------------------------- -------------- ----------
      3 PDB      racdba1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdba2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO

SYS@RACDBB>
SYS@RACDBB>
SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        READ ONLY
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

Switchover

dgmgrl

DGMGRL> switchover to racdbb;
Performing switchover NOW, please wait...
Operation requires a connection to database "racdbb"
Connecting ...
Connected to "racdbb"
Connected as SYSDBA.
New primary database "racdbb" is opening...
Oracle Clusterware is restarting database "racdba" ...
Connected to "racdba"
Connected to "racdba"
Switchover succeeded, new primary is "racdbb"

RACDBA: new standby, old primary

SYS@RACDBA> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SYS@RACDBA>
SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        MOUNTED
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

The upshot of that is that PDB is not opened on all instances.

RACDBB: new primary, old standby

SYS@RACDBB> select database_role from v$database;

DATABASE_ROLE
----------------
PRIMARY

SYS@RACDBB>
SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

alert_racdba1.log

2021-01-14T11:06:34.301193+00:00
PDB$SEED(2):This instance was first to open pluggable database PDB$SEED (container=2)
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:2456242 end:2456242 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
PDB$SEED(2):Opening pdb with no Resource Manager plan active
2021-01-14T11:06:34.854870+00:00
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:06:34.855107+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba1/trace/racdba1_ora_15488.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
2021-01-14T11:06:34.999598+00:00
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {1:39212:957} */

racdba1_ora_15488.trc

*** 2021-01-14T11:06:33.488203+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode

*** 2021-01-14T11:06:34.082190+00:00 (CDB$ROOT(1))
* Set mstr_rdy 1, lmon_pnpchk 1 
<error barrier> at 0x7fffb4489030 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba1.log

2021-01-14T11:05:21.783+00:00
Initiating a healthcheck...
2021-01-14T11:05:23.298+00:00
SWITCHOVER TO racdbb
Switchover to physical standby database cannot be initiated from the primary database
redirecting connection to switchover target database racdbb...
...using connect identifier: //myracb-scan/racdbb
SWITCHOVER TO racdbb
2021-01-14T11:05:26.004+00:00
Notifying Oracle Clusterware to prepare primary database for switchover
Switchover in progress...
2021-01-14T11:05:27.263+00:00
Executing SQL: [ALTER DATABASE SWITCHOVER TO 'racdbb']
2021-01-14T11:05:57.144+00:00
SQL [ALTER DATABASE SWITCHOVER TO 'racdbb'] executed successfully
2021-01-14T11:05:58.295+00:00
Switchover successful
2021-01-14T11:06:03.892+00:00
Notifying Clusterware to restart this instance for Switchover
2021-01-14T11:06:06.080+00:00
Shutting down instance after Switchover
2021-01-14T11:06:26.438+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:26.438+00:00                      DMON: Attach state object
2021-01-14T11:06:26.440+00:00                      DMON: Initialization of broker state requires reconciliation
2021-01-14T11:06:26.440+00:00                      DMON: Broker state reconciled, version = 0, state = 00000000
2021-01-14T11:06:26.440+00:00                      DMON: Broker State Initialized
2021-01-14T11:06:26.440+00:00                            Version = 1
2021-01-14T11:06:26.440+00:00                            State = 00000000
2021-01-14T11:06:26.440+00:00                      DMON: Creating INSV process
2021-01-14T11:06:29.458+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:06:29.461+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:06:29.474+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=12.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:29.474+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:29.476+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:29.480+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=13.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:29.480+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=13.0)
2021-01-14T11:06:29.480+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:29.483+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:29.485+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:06:29.485+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:29.485+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:29.485+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:06:29.485+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:06:29.486+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:06:29.486+00:00                      INSV: INSV is ready
2021-01-14T11:06:30.455+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:06:30.455+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:06:30.455+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:30.465+00:00                      DMON: My instance_name is racdba1 (SID racdba1), broker profile found at (1.2)
2021-01-14T11:06:30.465+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:06:30.465+00:00                      DMON: Configuration service not registered
2021-01-14T11:06:30.465+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:06:30.465+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:06:30.465+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:06:30.466+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:06:30.466+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca1.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba1)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=13.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:06:30.495+00:00
Physical standby restart after broker operation requires Oracle Clusterware buildup
Notifying Oracle Clusterware to buildup
2021-01-14T11:06:33.484+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:06:47.143+00:00
Starting redo apply services...
2021-01-14T11:06:52.764+00:00
instance 2 requested FSFO state reconciliation

alert_racdba2.log

2021-01-14T11:06:55.357652+00:00
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:2478578 end:2478578 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:06:55.996836+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:06:56.094252+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba2/trace/racdba2_ora_20683.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {1:39212:1040} */

racdba2_ora_20683.trc

*** 2021-01-14T11:06:54.338847+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode

*** 2021-01-14T11:06:55.135200+00:00 (CDB$ROOT(1))
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:06:56.094148+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffe4296eeb0 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba2.log

2021-01-14T11:05:25.005+00:00
Updated broker configuration file available, loading from "+DATA/RACDBA/dr1racdba"
2021-01-14T11:06:49.513+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:49.513+00:00                      DMON: Attach state object
2021-01-14T11:06:49.521+00:00                      DMON: Broker State Initialized
2021-01-14T11:06:49.521+00:00                            Version = 3
2021-01-14T11:06:49.521+00:00                            State = 00000000
2021-01-14T11:06:49.521+00:00                      DMON: Creating INSV process
2021-01-14T11:06:52.746+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:06:52.749+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:06:52.752+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=12.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:52.753+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:52.755+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:52.757+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=13.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:52.757+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=13.0)
2021-01-14T11:06:52.757+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:52.758+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:52.763+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:06:52.763+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:52.763+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:52.763+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:06:52.763+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:06:52.764+00:00                      INSV: Received reconcile FSFO state from instance #1
2021-01-14T11:06:52.764+00:00                      INSV:        flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:52.764+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:52.764+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:06:52.765+00:00                      INSV: INSV is ready
2021-01-14T11:06:53.534+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:06:53.539+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:06:53.539+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:53.553+00:00                      DMON: My instance_name is racdba2 (SID racdba2), broker profile found at (1.1)
2021-01-14T11:06:53.553+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:06:53.553+00:00                      DMON: Configuration service not registered
2021-01-14T11:06:53.553+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:06:53.554+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:06:53.554+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:06:53.555+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:06:53.555+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca2.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba2)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=13.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:06:56.334+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:07:00.357+00:00
Starting redo apply services...

Thoughts and Fix

The problem is that a new standby database does not open a non-seed pluggable database on all instances.
The exact cause is still unclear, but there are certain references in the Oracle documentation that explain how Switchover works when RAC is involved:

SWITCHOVER

If an Oracle RAC primary database is becoming a physical standby database, all but one instance of the primary database will be shut down before performing the switchover. See Switchover for details.

How the Broker Performs a Switchover

Restarts the new standby (former primary) database if the switchover occurs to a physical standby database, and Redo Apply begins applying redo data from the new primary database. If this is an Oracle RAC physical standby database managed by Oracle Clusterware, then the broker directs Oracle Clusterware to restart the new standby database.
The new primary database is opened in read/write mode and redo transport services are started.
If the former physical standby database was running with real-time query enabled, the new physical standby database will run with real-time query enabled.

I tend to think that the current behaviour is not quite consistent. Either all standby instances should open PDB or neither should open it.
There are several workarounds possible to achieve the desired effect.
Oracle itself recommends using user-defined services:
Default and User-Defined Services

Always use user-defined services for applications. The reason is that you can customize user-defined services to fit the requirements of your applications. Oracle recommends that you not use the default PDB service for applications.

I am quite fond of that approach, albeit I do not see it is widely used in the field.
Let us create one PDB service for both primary and standby roles:

# RACDBA
srvctl add service -db racdba -service pdb_svc -pdb pdb -preferred racdba1,racdba2 -role primary,physical_standby
srvctl start service -db racdba -service pdb_svc

# RACDBB
srvctl add service -db racdbb -service pdb_svc -pdb pdb -preferred racdbb1,racdbb2 -role primary,physical_standby
srvctl start service -db racdbb -service pdb_svc

Another Switchover

dgmgrl

DGMGRL> switchover to racdbb;
Performing switchover NOW, please wait...
Operation requires a connection to database "racdbb"
Connecting ...
Connected to "racdbb"
Connected as SYSDBA.
New primary database "racdbb" is opening...
Oracle Clusterware is restarting database "racdba" ...
Connected to "racdba"
Connected to "racdba"
Switchover succeeded, new primary is "racdbb"

RACDBA: new standby, old primary

SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        READ ONLY
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

PDB is opened on all instances this time around.

RACDBB: new primary, old standby

SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

alert_racdba1.log

2021-01-14T11:27:31.788825+00:00
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:3713780 end:3713780 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:27:31.988785+00:00
Set LMHB to elevated priority
2021-01-14T11:27:32.638396+00:00
Starting background process RSM0
2021-01-14T11:27:32.660794+00:00
RSM0 started with pid=75, OS id=2007 
2021-01-14T11:27:32.986896+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:27:33.111145+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba1/trace/racdba1_ora_1534.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {2:24204:2659} */
2021-01-14T11:27:33.820334+00:00
ALTER PLUGGABLE DATABASE pdb OPEN   /* svc agent *//* {2:24204:2659} */
2021-01-14T11:27:34.048502+00:00
ALTER SYSTEM SET remote_listener=' myraca-scan.example.com:1521' SCOPE=MEMORY SID='racdba1';
2021-01-14T11:27:34.050341+00:00
ALTER SYSTEM SET listener_networks='' SCOPE=MEMORY SID='racdba1';
PDB(3):Autotune of undo retention is turned on. 
2021-01-14T11:27:34.073923+00:00
PDB(3):Endian type of dictionary set to little
PDB(3):Undo initialization finished serial:0 start:3716088 end:3716088 diff:0 ms (0.0 seconds)
PDB(3):Database Characterset for PDB is AL32UTF8
2021-01-14T11:27:35.152791+00:00
PDB(3):Opening pdb with no Resource Manager plan active
Pluggable database PDB opened read only
Completed: ALTER PLUGGABLE DATABASE pdb OPEN   /* svc agent *//* {2:24204:2659} */
2021-01-14T11:27:35.703268+00:00
PDB(3):Started service pdb_svc/pdb_svc/pdb_svc

Although the ORA-65054 error is still there, the pluggable database is opened shortly afterwards by the Clusterware.

racdba1_ora_1534.trc

*** 2021-01-14T11:27:20.529675+00:00 (CDB$ROOT(1))
*** SESSION ID:(377.9495) 2021-01-14T11:27:20.529708+00:00
*** CLIENT ID:() 2021-01-14T11:27:20.529717+00:00
*** SERVICE NAME:() 2021-01-14T11:27:20.529724+00:00
*** MODULE NAME:(oraagent.bin@raca1.example.com (TNS V1-V3)) 2021-01-14T11:27:20.529731+00:00
*** ACTION NAME:() 2021-01-14T11:27:20.529739+00:00
*** CLIENT DRIVER:() 2021-01-14T11:27:20.529745+00:00
*** CONTAINER ID:(1) 2021-01-14T11:27:20.529753+00:00
 
kcrrmnt: RT: Role transition work is not done

*** 2021-01-14T11:27:20.865334+00:00 (CDB$ROOT(1))
*** 2021-01-14 11:27:20.865323 [krsn.c:548]
krsn_dbrole_change: Database role set to PHYSICAL STANDBY [kcvfdb.c:9212]
krsd_cb_role_change: role 2
*** 2021-01-14 11:27:20.993319 [krsh.c:6348]
Archiving previously deferred ORLs
*** 2021-01-14 11:27:20.993982 [krsq.c:3772]
krsq_arch_all_complete: Finished archiving all complete, unarchived ORLs

*** 2021-01-14T11:27:30.695367+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable

*** 2021-01-14T11:27:30.999497+00:00 (CDB$ROOT(1))
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:27:32.249955+00:00 (PDB$SEED(2))
IPCLW:[0.0]{-}[WAIT]:PROTO: [1610623652249736]ipclw_data_chunk_process:1165 Discarding msg with seq # 2043340599, expecting 2043340603

*** 2021-01-14T11:27:33.111040+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffc3992e030 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba1.log

2021-01-14T11:27:25.254+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:25.254+00:00                      DMON: Attach state object
2021-01-14T11:27:25.261+00:00                      DMON: Broker State Initialized
2021-01-14T11:27:25.261+00:00                            Version = 3
2021-01-14T11:27:25.261+00:00                            State = 00000000
2021-01-14T11:27:25.261+00:00                      DMON: Creating INSV process
2021-01-14T11:27:28.282+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:27:28.292+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:27:28.296+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=14.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:28.297+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:28.300+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:28.301+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=15.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:28.301+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=15.0)
2021-01-14T11:27:28.301+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:28.303+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:28.305+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:27:28.305+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:28.305+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:28.305+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:27:28.305+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:27:28.306+00:00                      INSV: Received reconcile FSFO state from instance #2
2021-01-14T11:27:28.306+00:00                      INSV:        flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:28.306+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:28.307+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:27:28.307+00:00                      INSV: INSV is ready
2021-01-14T11:27:29.278+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:27:29.284+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:27:29.284+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:29.301+00:00                      DMON: My instance_name is racdba1 (SID racdba1), broker profile found at (1.2)
2021-01-14T11:27:29.301+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:27:29.301+00:00                      DMON: Configuration service not registered
2021-01-14T11:27:29.301+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:27:29.303+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:27:29.303+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:27:29.303+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:27:29.303+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca1.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba1)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=15.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:27:32.638+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:27:46.120+00:00
Starting redo apply services...

alert_racdba2.log

2021-01-14T11:27:10.590468+00:00
PDB$SEED(2):This instance was first to open pluggable database PDB$SEED (container=2)
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:3693763 end:3693763 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:27:10.879141+00:00
db_recovery_file_dest_size of 18000 MB is 15.64% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
2021-01-14T11:27:11.038141+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:27:11.103829+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba2/trace/racdba2_ora_6677.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
2021-01-14T11:27:11.217024+00:00
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {2:24204:2565} */
2021-01-14T11:27:11.849329+00:00
ALTER PLUGGABLE DATABASE pdb OPEN READ ONLY  /* svc agent *//* {2:24204:2565} */

racdb2_ora_6677.trc

*** 2021-01-14T11:27:09.794332+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:27:11.103734+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffdf766e730 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba2.log

2021-01-14T11:26:06.494+00:00
Initiating a healthcheck...
2021-01-14T11:26:08.044+00:00
SWITCHOVER TO racdbb
Switchover to physical standby database cannot be initiated from the primary database
redirecting connection to switchover target database racdbb...
...using connect identifier: //myracb-scan/racdbb
SWITCHOVER TO racdbb
2021-01-14T11:26:10.771+00:00
Notifying Oracle Clusterware to prepare primary database for switchover
Switchover in progress...
2021-01-14T11:26:12.048+00:00
Executing SQL: [ALTER DATABASE SWITCHOVER TO 'racdbb']
2021-01-14T11:26:33.855+00:00
SQL [ALTER DATABASE SWITCHOVER TO 'racdbb'] executed successfully
2021-01-14T11:26:35.031+00:00
Switchover successful
2021-01-14T11:26:40.618+00:00
Notifying Clusterware to restart this instance for Switchover
2021-01-14T11:26:42.824+00:00
Shutting down instance after Switchover
2021-01-14T11:27:02.925+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:02.925+00:00                      DMON: Attach state object
2021-01-14T11:27:02.927+00:00                      DMON: Initialization of broker state requires reconciliation
2021-01-14T11:27:02.927+00:00                      DMON: Broker state reconciled, version = 0, state = 00000000
2021-01-14T11:27:02.927+00:00                      DMON: Broker State Initialized
2021-01-14T11:27:02.927+00:00                            Version = 1
2021-01-14T11:27:02.927+00:00                            State = 00000000
2021-01-14T11:27:02.927+00:00                      DMON: Creating INSV process
2021-01-14T11:27:05.944+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:27:05.946+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:27:05.950+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=14.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:05.951+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:05.952+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:05.954+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=15.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:05.954+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=15.0)
2021-01-14T11:27:05.954+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:05.956+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:05.958+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:27:05.958+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:05.958+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:05.958+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:27:05.958+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:27:05.959+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:27:05.959+00:00                      INSV: INSV is ready
2021-01-14T11:27:06.940+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:27:06.941+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:27:06.941+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:06.951+00:00                      DMON: My instance_name is racdba2 (SID racdba2), broker profile found at (1.1)
2021-01-14T11:27:06.951+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:27:06.951+00:00                      DMON: Configuration service not registered
2021-01-14T11:27:06.951+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:27:06.951+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:27:06.951+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:27:06.952+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:27:06.952+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca2.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba2)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=15.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:27:06.981+00:00
Physical standby restart after broker operation requires Oracle Clusterware buildup
Notifying Oracle Clusterware to buildup
2021-01-14T11:27:09.788+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:27:21.950+00:00
Starting redo apply services...

Conclusion

User PDB's may not open on all instances following DataGuard Switchover. This behaviour is quite inconsistent since PDB's are opened just on some instances. Thankfully, the workaround is pretty straightforward - we just need to create a dedicated service for these PDB's.