Tag Archives: adop

R12.2 adop phase fs_clone fails because it can’t copy a file.

Complexity leading to fragility
Complex Systems Integration (Courtesy of: https://www.mulesoft.com/resources/esb/business-process-integration)

Oracle…sometimes blinding in complexity, and a foreshadowing of what happens when a system becomes so complex that it becomes fragile.

This is what the screen session looks like:

adnodemgrctl.sh: check the logfile /u01/oradev/fs1/inst/apps/DEV2_itsrv33m/logs/appl/admin/log/adnodemgrctl.txt for more information …
[UNEXPECTED]fs_clone has failed.
[STATEMENT] Please run adopscanlog utility, using the command
“adopscanlog -latest=yes”
to get the list of the log files along with snippet of the error message corresponding to each log file.
adop exiting with status = 2 (Fail)

Here is what it looks like in the adop.log

[EVENT]     Performing CLONE steps.
[PROCEDURE] [START 2016/11/08 08:20:19] CLONE Patch File System from Run File System
[PROCEDURE] Calling: /u01/oradev/fs2/EBSapps/appl/ad/12.0.0/patch/115/bin/txkADOPPreparePhaseSynchronize.pl
[EVENT]     Log: /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m
[UNEXPECTED]Error occurred running “perl /u01/oradev/fs2/EBSapps/appl/ad/12.0.0/patch/115/bin/txkADOPPreparePhaseSynchronize.pl -contextfile=/u01/oradev/fs2/inst/apps/DEV2_itsrv33m/appl/admin/DEV2_itsrv33m.xml -patchcontextfile=/u01/oradev/fs1/inst/apps/DEV2_itsrv33m/appl/admin/DEV2_itsrv33m.xml -promptmsg=hide -console=off -mode=create -sync_mode=copy -sessionid=25 -timestamp=20161108_081645 -outdir=/u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m”
[UNEXPECTED]occurred during CLONE Patch File System from Run File System, running command: “perl /u01/oradev/fs2/EBSapps/appl/ad/12.0.0/patch/115/bin/txkADOPPreparePhaseSynchronize.pl -contextfile=/u01/oradev/fs2/inst/apps/DEV2_itsrv33m/appl/admin/DEV2_itsrv33m.xml -patchcontextfile=/u01/oradev/fs1/inst/apps/DEV2_itsrv33m/appl/admin/DEV2_itsrv33m.xml -promptmsg=hide -console=off -mode=create -sync_mode=copy -sessionid=25 -timestamp=20161108_081645 -outdir=/u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m”.
[EVENT]     Releasing managed server ports.
[PROCEDURE] [START 2016/11/08 08:30:55] Releasing ports
[STATEMENT] Calling task: “Releasing ports on itsrv33m”; script: “/u01/oradev/fs2/inst/apps/DEV2_itsrv33m/admin/install/txkCloneAcquirePort.pl”; args: ” -option=close -server=itsrv33m.mwd.h2o -ports=5570,7015,7615,7415,7215,7216,7217,7815,6114,6214,10013 -log=/u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/txkCloneAcquirePort.log”
[PROCEDURE] [START 2016/11/08 08:30:56] Releasing ports on itsrv33m
[PROCEDURE] Calling: /u01/oradev/fs2/inst/apps/DEV2_itsrv33m/admin/install/txkCloneAcquirePort.pl
[EVENT]     Log: /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/txkCloneAcquirePort.log
[PROCEDURE] [END   2016/11/08 08:30:57] Releasing ports on itsrv33m
[PROCEDURE] [END   2016/11/08 08:30:57] Releasing ports

How cryptic!  Looks complicated.  This system happens to have AD/TXK.Delta.8, so the logs related to adop are all being centralized under the session # (in this case “25”.)

Diving deep into the log subdirectories:

/u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/txkADOPPreparePhaseSynchronize.log

================================
Inside copyComnUtil()…
================================

Directory /u01/oradev/fs1/EBSapps/comn already exists.
Removing the directory: /u01/oradev/fs1/EBSapps/comn/util

Copying the directory
———————
SOURCE : /u01/oradev/fs2/EBSapps/comn/util
TARGET : /u01/oradev/fs1/EBSapps/comn/util

Execute SYSTEM command : cp -rH  /u01/oradev/fs2/EBSapps/comn/util /u01/oradev/fs1/EBSapps/comn/util
EXIT STATUS: 1
Copied /u01/oradev/fs2/EBSapps/comn/util into /u01/oradev/fs1/EBSapps/comn/utilLOG FILE: /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/cp_rH.out

<snip>
======================================
Inside copyCloneLogsToFSNE()…
======================================

Creating the directory: /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/fsclone_apply

Copying the directory
———————
SOURCE : /u01/oradev/fs2/inst/apps/DEV2_itsrv33m/admin/log/clone
TARGET : /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/fsclone_apply

/u01/oradev/fs2/EBSapps/comn/adopclone_itsrv33m/bin/adclone.pl did not go through successfully.
LOG DIRECTORY: /u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/fsclone_apply.
*******FATAL ERROR*******
PROGRAM : (/u01/oradev/fs2/EBSapps/appl/ad/12.0.0/patch/115/bin/txkADOPPreparePhaseSynchronize.pl)
TIME    : Tue Nov  8 08:30:55 2016
FUNCTION: main::runFSCloneApply [ Level 1 ]
ERRORMSG: /u01/oradev/fs2/EBSapps/comn/adopclone_itsrv33m/bin/adclone.pl did not go through successfully.

/u01/oradev/fs_ne/EBSapps/log/adop/25/20161108_081645/fs_clone/itsrv33m/TXK_SYNC_create/fsclone_apply/FSCloneApplyAppsTier_11080821.log

(One innocuous, but annoying file, owned by someone other than applmgr, and happened to be 600 (user read/write only):)

Done copying /u01/oradev/fs2/EBSapps/appl/wms to /u01/oradev/fs1/EBSapps/appl/wms/
Copying /u01/oradev/fs2/EBSapps/appl/gmf to /u01/oradev/fs1/EBSapps/appl/gmf/
WARNING:
.end std out.
cp: cannot open /u01/oradev/fs2/EBSapps/appl/mwd/12.0.0/sql/MWDPOLPO.xsl: Permission denied

.end err out.
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/mwd failed
ERROR: Copying failed, so stopping all the parallel threads
Done copying /u01/oradev/fs2/EBSapps/appl/okc to /u01/oradev/fs1/EBSapps/appl/okc/
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/okc failed
Done copying /u01/oradev/fs2/EBSapps/comn/java/classes/oracle/apps/pqh to /u01/oradev/fs1/EBSapps/comn/java/classes/oracle/apps/pqh/
WARNING: Copying of /u01/oradev/fs2/EBSapps/comn/java/classes/oracle/apps/pqh failed
Done copying /u01/oradev/fs2/EBSapps/appl/gmf to /u01/oradev/fs1/EBSapps/appl/gmf/
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/gmf failed
Done copying /u01/oradev/fs2/EBSapps/comn/java/classes/oracle/apps/ies to /u01/oradev/fs1/EBSapps/comn/java/classes/oracle/apps/ies/
WARNING: Copying of /u01/oradev/fs2/EBSapps/comn/java/classes/oracle/apps/ies failed
Done copying /u01/oradev/fs2/EBSapps/appl/msc to /u01/oradev/fs1/EBSapps/appl/msc/
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/msc failed
Done copying /u01/oradev/fs2/EBSapps/appl/ams to /u01/oradev/fs1/EBSapps/appl/ams/
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/ams failed
Done copying /u01/oradev/fs2/EBSapps/appl/cs to /u01/oradev/fs1/EBSapps/appl/cs/
WARNING: Copying of /u01/oradev/fs2/EBSapps/appl/cs failed
START: Inside exitClone….
Updating status INCOMPLETE for ApplyApplTop
START: Updating status INCOMPLETE for action ApplyApplTop
END: Updated status INCOMPLETE for action ApplyApplTop

One file.  A single file.  Could have been a hidden file. Could have been anywhere in the entire AppsTier filesystem.  This one file stopped ADOP cold from performing.  This happened to be phase=fs_clone, but could have been a patching session, or a post-clone config (adcfgclone.pl) session.

Remove the file, and:

The fs_clone phase completed successfully.
adop exiting with status = 0 (Success)

Complexity leads to unintentional fragility.