Thursday, August 20, 2009

FND Debug Log - Debugging Oracle Apps code

Refernce : http://oracle.anilpassi.com


There was a time when every individual Oracle Applications module used its own debugging technique.

But this is changing now, thanks to FND Logging. I have been using FND Logging for over one year now, ever since 11.5.10 was released, hence I would like to share knowledge on this topic.

What is the use of FND Debug Log?
1. It helps you pinpoint the cause of error in standard Oracle Code, by making debug messages to appear in a centralized table named FND_LOG_MESSAGES.
2. You can design and build your custom extensions in a manner that can easily be debugged. This can be done by calling Oracle delivered API’s in your custom code.

Where is the debug message stored, once the logging is turned on?
Debug messages are stored in a table called FND_LOG_MESSAGES
A program written in any technology, either form, or report, or pl/sql or java concurrent program or OAF…all their debug messages will be stored in fnd_log_messages.
All debug messages spooled to fnd_log_messages

How to debug the issue being faced in Oracle Application?
Step 1 Set the following profile options at your user level(your fnd_user)
FND: Debug Log Level
Following possible values are available, but I suggest you set this to "Statement" level when debugging code.
LEVEL_UNEXPECTED : Internal Level Id is 6
LEVEL_ERROR : Internal Level Id is 5
LEVEL_EXCEPTION : Internal Level Id is 4
LEVEL_EVENT : Internal Level Id is 3
LEVEL_PROCEDURE : Internal Level Id is 2
LEVEL_STATEMENT : Internal Level Id is 1

FND: Debug Log Enabled
Set this profile to Yes

FND: Debug Log Module
Set this to %


Step 2
Login to the application and reproduce the problem.

Step 3
SELECT *
FROM fnd_log_messages
WHERE user_id = 209122 /*your FND_USER user_id here*/
AND TIMESTAMP > SYSDATE - .3
ORDER BY log_sequence DESC /*note the order by clause here*/

The result of this select statement will provide the list of all the debug messages, on top will appear the most recent debug messages..


Why should I setup the module name to %, in profile option?
You can set this to po%, if you know for sure that the error was caused by code written in po module. However po code might be internally calling hr code which might inturn be calling fnd code.
Hence it’s best to set this profile value as %.
You may also use comma delimited values i.e po%,hr%,fnd%


Why must I bother debugging Oracle's Standard code when I can quickly raise a tar.
If the issue is with Standard Oracle Code, first thing you must do is to search into Metalink. However having the debug information on error helps your searching ability further. Uploading the debug messages upfront during Tar creation will also help Oracle speedily understand and fix your issues.


Why to set the profile option to statement level?
This profile option has following main levels.-
Error
Warning
Procedure
Statement

I like setting this to "Statement" level as it extracts debug messages at all levels, in one glance. You can latter filter those debug messages by using below SQL for example
select * from fnd_log_messages where user_id = 111 and LOG_LEVEL =5


What if the piece of code causing the error is not appearing in fnd_log_messages?
This is very much possible. The fnd_log_messages might have helped you get close to the culprit piece of code , but may not be able to pinpoint the error as there may not be enough debug messages implanted by Oracle.

You can do one of the below:-
A. Run the database sql trace for the session with bind variables and see the last meaningful SQL statement in the raw trace file.
Please note that PL/SQL statements will not appear in trace, only the SQL Statements will appear, hence you may consider option (b) below
B. Add your own debug messages to the pl/sql code that was delivered by oracle, which you suspect is causing problem. This is a temporary change, and must only be done on development environment, NEVER DO THIS CHANGE ON PRODUCTION.


The size of table FND_LOG_MESSAGES will keep on increasing?
You can run concurrent program “Purge Debug Log and System Alerts”.


I have written a pl/sql concurrent process to interface Purchase Orders from 3rd Party System. How will add debug messages?
fnd_log.STRING(log_level => fnd_log.level_statement
,module => 'xxpo.packagename.procedurename'
,message => 'debug message here');


Will the above debug command create an entry into fnd_log_messages ?
Debug records will be created in fnd_log_messages if and only if you run the interface program after setting the profile options as suggested above.


What if a rollback occurs due to unhandled exception. Will the inserts done to fnd_log_messages be lost?
fnd_log.string eventually calls procedure FND_LOG.STRING_UNCHECKED_INTERNAL2. This procedure uses pragma AUTONOMOUS_TRANSACTION with a commit.
Hence your debug messages will not be lost despite a rollback in parent session.


What if an exception is incurred within the Debug Logging API itself?
Oracle takes well care of this by handling the WHEN OTHERS exception.
It is evident from below Oracle Code for debug API
PROCEDURE STRING(LOG_LEVEL IN NUMBER,
MODULE IN VARCHAR2,
MESSAGE IN VARCHAR2) is

begin
/* Short circuit if logging not turned on at this level */
if (LOG_LEVEL < log_level =""> LOG_LEVEL,
MODULE => MODULE,
MESSAGE_TEXT => MESSAGE);
end if;

exception
when others then
NULL; /* supress the exception */
end;

Monday, August 10, 2009

Error :

===========================================================

RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ============

RMAN-00571: ===========================================================

RMAN-03002: failure of configure command at 05/12/2008 18:21:50

RMAN-06004: ORACLE error from recovery catalog database:
RMAN-20011: target database incarnation is not current in recovery catalog

Cause :

The database incarnation that matches the resetlogs change# and time of the mounted target database control file is not the current incarnation of the database .

In our case we cloned our database LGEIL as CRM and thus used “ reset database “ to reset the incarnation as per the new cloned CRM database . But after moving back to old database LGEIL , backup getting errored out with the error mentioned above ..

Details :

The above error occurs when the Database target Incarnation is not current in the Recovery Catalog.

The incarnation of a database is a number that is used to identify a version of the database.A database incarnation is created whenever you open the database with the RESETLOGS.

V$DATABASE_INCARNATION displays information about all database incarnations. Oracle creates
a new incarnation whenever a database is opened with the RESETLOGS option. Records about the
current and immediately previous incarnation are also contained in the V$DATABASE view.

To Reference the corresponding Incarnation information in the recovery catalog review the RC_DATABASE_INCARNATION and RC_DATABASE views.


à RC_DATABASE_INCARNATION lists information about all database incarnations registered in the recovery catalog.

àRC_DATABASE lists information about the databases registered in the recovery catalog. It corresponds to the V$DATABASE view in your target database.

Solution :

Connect to the RMAN schema as rman user e.g.

sqlplus rman/rman@EMREP

SQL> SELECT dbid, name, dbinc_key, resetlogs_change#, resetlogs_time FROM rc_database_incarnation WHERE dbid=1243244440 ORDER BY resetlogs_time;

DBID NAME DBINC_KEY RESETLOGS_CHANGE# RESETLOGS_TIME

---------- -------- ---------- ----------------- --------------------

1243244440 LGEIL 2812522 1 08-JUL-2007 06:09:28

1243244440 LGEIL 2812503 9.6778E+12 08-JUL-2007 07:11:27

1243244440 CRM 5026006 1.1191E+13 08-AUG-2009 21:02:00

Now , here our current incarnation is 5026006 (CRM ) and we have to change it to 2812503 ( LGEIL ) .

Incarnation time of your database ( LGEIL in our case ) can be confirmed from v$database ..

SQL> select RESETLOGS_TIME , RESETLOGS_CHANGE# , PRIOR_RESETLOGS_CHANGE# , PRIOR_RESETLOGS_TIME from v$database;

RESETLOGS_TIME RESETLOGS_CHANGE# PRIOR_RESETLOGS_CHANGE# PRIOR_RESETLOGS_TIME

-------------------- ------------------------ ---------------------------- --------------------

08-JUL-2007 07:11:27 9677807775711 1 08-JUL-2007 06:09:28

Here it’s “08-JUL-2007 07:11:27

Now , reset the incarnation …..

[csnetnorthdb:oracle] /northact/LGEIL/rman/scripts> rman target / catalog rman/rman@EMREP

Recovery Manager: Release 9.2.0.8.0 - 64bit Production

Copyright (c) 1995, 2002, Oracle Corporation. All rights reserved.

connected to target database: LGEIL (DBID=1243244440)

connected to recovery catalog database

RMAN> list incarnation;

No rows will be selected here ..

RMAN>

RMAN> RESET DATABASE TO INCARNATION 2812503;

database reset to incarnation 2812503 in recovery catalog

RMAN> resync catalog;

starting full resync of recovery catalog

full resync complete

RMAN> list incarnation;

List of Database Incarnations

DB Key Inc Key DB Name DB ID CUR Reset SCN Reset Time

------- ------- -------- ---------------- --- ---------- ----------

2812502 2812522 LGEIL 1243244440 NO 1 08-JUL-07

2812502 2812503 LGEIL 1243244440 YES 9677807775711 08-JUL-07

2812502 5026006 CRM 1243244440 NO 11190641794400 08-AUG-09

Now ..you can take the backup

RMAN-20011: target database incarnation is not current in recovery catalog

Error :

===========================================================

RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ============

RMAN-00571: ===========================================================

RMAN-03002: failure of configure command at 05/12/2008 18:21:50

RMAN-06004: ORACLE error from recovery catalog database:
RMAN-20011: target database incarnation is not current in recovery catalog

Cause :

The database incarnation that matches the resetlogs change# and time of the mounted target database control file is not the current incarnation of the database .

In our case we cloned our database LGEIL as CRM and thus used “ reset database “ to reset the incarnation as per the new cloned CRM database . But after moving back to old database LGEIL , backup getting errored out with the error mentioned above ..

Details :

The above error occurs when the Database target Incarnation is not current in the Recovery Catalog.

The incarnation of a database is a number that is used to identify a version of the database.A database incarnation is created whenever you open the database with the RESETLOGS.

V$DATABASE_INCARNATION displays information about all database incarnations. Oracle creates
a new incarnation whenever a database is opened with the RESETLOGS option. Records about the
current and immediately previous incarnation are also contained in the V$DATABASE view.

To Reference the corresponding Incarnation information in the recovery catalog review the RC_DATABASE_INCARNATION and RC_DATABASE views.


à RC_DATABASE_INCARNATION lists information about all database incarnations registered in the recovery catalog.

àRC_DATABASE lists information about the databases registered in the recovery catalog. It corresponds to the V$DATABASE view in your target database.

Solution :

Connect to the RMAN schema as rman user e.g.

sqlplus rman/rman@EMREP

SQL> SELECT dbid, name, dbinc_key, resetlogs_change#, resetlogs_time FROM rc_database_incarnation WHERE dbid=1243244440 ORDER BY resetlogs_time;

DBID NAME DBINC_KEY RESETLOGS_CHANGE# RESETLOGS_TIME

---------- -------- ---------- ----------------- --------------------

1243244440 LGEIL 2812522 1 08-JUL-2007 06:09:28

1243244440 LGEIL 2812503 9.6778E+12 08-JUL-2007 07:11:27

1243244440 CRM 5026006 1.1191E+13 08-AUG-2009 21:02:00

Now , here our current incarnation is 5026006 (CRM ) and we have to change it to 2812503 ( LGEIL ) .

Incarnation time of your database ( LGEIL in our case ) can be confirmed from v$database ..

SQL> select RESETLOGS_TIME , RESETLOGS_CHANGE# , PRIOR_RESETLOGS_CHANGE# , PRIOR_RESETLOGS_TIME from v$database;

RESETLOGS_TIME RESETLOGS_CHANGE# PRIOR_RESETLOGS_CHANGE# PRIOR_RESETLOGS_TIME

-------------------- ------------------------ ---------------------------- --------------------

08-JUL-2007 07:11:27 9677807775711 1 08-JUL-2007 06:09:28

Here it’s “08-JUL-2007 07:11:27

Now , reset the incarnation …..

[csnetnorthdb:oracle] /northact/LGEIL/rman/scripts> rman target / catalog rman/rman@EMREP

Recovery Manager: Release 9.2.0.8.0 - 64bit Production

Copyright (c) 1995, 2002, Oracle Corporation. All rights reserved.

connected to target database: LGEIL (DBID=1243244440)

connected to recovery catalog database

RMAN> list incarnation;

No rows will be selected here ..

RMAN>

RMAN> RESET DATABASE TO INCARNATION 2812503;

database reset to incarnation 2812503 in recovery catalog

RMAN> resync catalog;

starting full resync of recovery catalog

full resync complete

RMAN> list incarnation;

List of Database Incarnations

DB Key Inc Key DB Name DB ID CUR Reset SCN Reset Time

------- ------- -------- ---------------- --- ---------- ----------

2812502 2812522 LGEIL 1243244440 NO 1 08-JUL-07

2812502 2812503 LGEIL 1243244440 YES 9677807775711 08-JUL-07

2812502 5026006 CRM 1243244440 NO 11190641794400 08-AUG-09

Now ..you can take the backup