Blog dedicated to Oracle Applications (E-Business Suite) Technology; covers Apps Architecture, Administration and third party bolt-ons to Apps

Thursday, January 29, 2009

Java.Lang.Noclassdeffounderror: Javax/Jms/Connection When Starting Workflow Mailer

We got this error while starting Workflow Mailer Service in the logs:

Java.Lang.Noclassdeffounderror: Javax/Jms/Connection 

Metalink Note 342700.1 describes the cause of this problem:

The error occurs because JMS jar files ($IAS_OH/rdbms/jlib/jmscommon.jar and
$IAS_OH/rdbms/jlib/aqapi.jar) cannot be found. Normally these are included in
$JAVA_TOP/appsborg2.zip which is not included in the AF_CLASSPATH.

Ensuring that appsborg2.zip is present in your AF_CLASSPATH resolves this problem

Wednesday, January 28, 2009

ORA-01578 block corrupted in jserv.log

Today we had a major issue in Production, and the DBAs ended up restoring everything from RMAN backup.  After the Database was restored, we could not access the AppsLogin page.  After turning on the debug mode, we saw these errors in the jserv.log:

ORA-01578: ORACLE data block corrupted (file # 377, block # 4205) 
ORA-01110: data file 377: '/dev/rac_data2/rapplsysd03.dbf' 
ORA-26040: Data block was loaded using the NOLOGGING option

On seeing this error, Akhilesh said that it is a known issue and ran the WF_LOCAL_SYNCH procedure:

SQL> begin apps.wf_local_synch.BULKSYNCHRONIZATION(P_ORIG_SYSTEM=>'ALL',
2 P_PARALLEL_PROCESSES=>2,
3 P_LOGGING=>'LOGGING', P_RAISEERRORS=>TRUE,
4 P_TEMPTABLESPACE=>'APPS_TS_TX_DATA');
5 END;
6 /

After running the above procedure, we were able to see the AppsLogin page and login to the instance.

Metalink Notes 433280.1 and 435523.1 describe this problem in detail and provide this cause:

During its execution, the Synchronize WF LOCAL tables concurrent program 
executes the following statements: 

ALTER TABLE WF_LOCAL_ROLES 
EXCHANGE PARTITION  
WITH TABLE WF_LOCAL_ROLES_STAGE INCLUDING INDEXES WITHOUT VALIDATION; 
ALTER TABLE WF_LOCAL_USER_ROLES 
EXCHANGE PARTITION  
WITH TABLE WF_LOCAL_USER_ROLES_STAGE INCLUDING INDEXES WITHOUT VALIDATION;
ALTER TABLE WF_USER_ROLE_ASSIGNMENTS 
EXCHANGE PARTITION
WITH TABLE WF_UR_ASSIGNMENTS_STAGE INCLUDING INDEXES WITHOUT VALIDATION; 
  
When an alter table exchange partition takes place, all the segment attributes 
of the two objects (including tablespace and 
logging) are also exchanged. 
So if one of the stage tables is set to logging = 'NO' before the Synchronize WF 
LOCAL tables 
concurrent program is launched, after its completion a partition of 
the corresponding table will be set to LOGGING = 'NO'.           
    
    
    
Example: 


1. WF_LOCAL_ROLES_STAGE are set to LOGGING = 'NO' 
all partitions of WF_LOCAL_ROLES are set to LOGGING = 'YES' 

2. ran 
Synchronize WF LOCAL tables concurrent program for originating system = ENG_LIST. 

3. After completion, 

WF_LOCAL_ROLES_STAGE is set to LOGGING = 'NO' 
ENG_LIST partition of WF_LOCAL_ROLES is set to LOGGING = 'YES'
    
This problem is described in Bug 5942254 RUNNING SYNCHRONIZE WF LOCAL TABLES CHANGES PARTITION TO NOLOGGING. 

I also found this solution on astijf wiki here.

oracle.apps.fnd.sso.SessionMgr.setLang

Abhishek reported this error:

Internal Server Error

The Server encountered an internal error or misconfiguration and was unable to complete your request

Please contact the server administrator, applmgr@justanexample.com and inform them of the time the error occurred, and anything you might have done that may have caused the error.

More information about this error may be available in the server error log.

apache access_log showed HTTP-503 error:

192.168.1.32 - - [28/Jan/2009:09:23:46 -0500] "GET /oa_servlets/AppsSSOServlet/?urlc=v1.2~64B471D0DE31B9ABC28F471BB5DCF74F6583C912573EFBE43AE8001F4F33C31CE4
C01658BEF2F5DE748E13B748BA0CD3EC9B272181AC9A939DB5D75D6C9DA03435445B79EC48BC0B1CCD0764201C93309A2B3C77B1870912D4220B82FF987AF091E9576ABDF0FEA035EC8572556A19B
DB78035965C12BBB63B58E420C3FD37BB86BE2101B5C74879BBF26BEB55C1317BF9FFF6ADB234E480AF57B7156ED45E161D19D36C3D7435BD577E67F96866026C43B3D7AAAD980FDFD9D68576F99A
230B030B435000F61003EEC92225B7FD8DFCB8C34835A41E3CC6EDC7BFD09A9BAF563D7E284A75AD0785AA189D1E21F7BD0A99266AE3DD97EC4FED32AE6A867F81B25F93E5564561A76E348836B54
8F6B06184CBB963A67A28D6 HTTP/1.1" 500 543 0


mod_jserv.log:

[28/01/2009 09:39:24:897] (ERROR) an error returned handling request via protocol "ajpv12"
[28/01/2009 09:39:24:897] (ERROR) balance: 1775 internal servlet error in server dev14.justanexample.com:16220
[28/01/2009 09:39:24:897] (ERROR) an error returned handling request via protocol "balance"
[28/01/2009 09:52:12:600] (ERROR) ajp12: Servlet Error: java.lang.NoSuchMethodError: oracle.apps.fnd.sso.SessionMgr.setLang(Loracle/apps/fnd/common/WebAppsContext;Ljavax/servlet/http/HttpServletRequest;Ljava/lang/String;)V: oracle.apps.fnd.sso.SessionMgr.setLang(Loracle/apps/fnd/common/WebAppsContext;Ljavax/servlet/http/HttpServletRequest;Ljava/lang/String;)V

$IAS_CONFIG_HOME/Apache/Jserv/logs/jvm/OACoreGroup.0.stderr
java.lang.NoSuchMethodError: oracle.apps.fnd.sso.SessionMgr.setLang(Loracle/apps/fnd/common/WebAppsContext;Ljavax/servlet/http/HttpServletRequest;Ljava/lang/String;)V
at org.apache.jserv.JServConnection.processRequest(JServConnection.java:462)
at org.apache.jserv.JServConnection.run(JServConnection.java:294)
at java.lang.Thread.run(Thread.java:534)

Cause: Un-synchronized data in APPLSYS.WF_LOCAL_USER_ROLES:HZ_PARTY

Solution:

For non-OATM instances:

sql>
begin apps.wf_local_synch.BULKSYNCHRONIZATION(P_ORIG_SYSTEM=>'ALL',
P_PARALLEL_PROCESSES=>2,
P_LOGGING=>'LOGGING', P_RAISEERRORS=>TRUE,
P_TEMPTABLESPACE=>'APPLSYSX');
END;
/

For OATM instances:
sql>
begin apps.wf_local_synch.BULKSYNCHRONIZATION(P_ORIG_SYSTEM=>'ALL',
P_PARALLEL_PROCESSES=>2,
P_LOGGING=>'LOGGING', P_RAISEERRORS=>TRUE,
P_TEMPTABLESPACE=>'APPS_TS_TX_DATA'); END; /

Since we were on an OATM instance, we ran this pl/sql block after logging in as apps:

SQL> begin apps.wf_local_synch.BULKSYNCHRONIZATION(P_ORIG_SYSTEM=>'ALL',
2 P_PARALLEL_PROCESSES=>2,
3 P_LOGGING=>'LOGGING', P_RAISEERRORS=>TRUE,
4 P_TEMPTABLESPACE=>'APPS_TS_TX_DATA');
5 END;
6 /

PL/SQL procedure successfully completed.

SQL>

There was no need to bounce Apache. After running the above query, we were able to login without issues.

Tuesday, January 27, 2009

usdsop cannot redirect standard output

Akhilesh reported this error to me today where concurrent managers refused to start with this error in the *.mgr logs:

Cause: usdsop encountered an error redirecting standard output for a child process.

Metalink Note 733901.1 describes this problem and gives the cause as:

The cause of this problem has been identified in Bug 7000874. It is caused by a code bug which causes memory corruption on an internal FILENAME variable. As a result of that the FND Service Manager fails to spawn the service manager processes such as the Output Post Processor and many others.

Solution

Apply a patch that includes the fixed file version of afpsms.oc:
  • Oracle E-Business Suite 11i
    Patch 7244628 1OFF:7235678:11.5.10.2:11.5.10.2:GSM Services Not Running
    --> Controlled release patch on top of patch 4676589 11i.ATG_PF.H.RUP4.
  • Oracle E-Business Suite Release 12
    Patch 7000874 GSM Services Not Running
    --> Controlled release patch on top of the 12.0.3 code level.
Note: Both patches are released under the terms of 'By Support' which implies that the patch is queryable on Metalink, but downloads of these patches requires a password. Please contact Global Customer Support to receive a password to download the patch.

Workaround

In case the issue is encountered on a lower code level and thus a patch is not available, one may consider to implement the following workaround:
  1. Stop the concurrent managers.
  2. Decreased the sequence value of FND_CONCURRENT_PROCESSES_S to 500000 (decrease from 8 to 6 digits).

    • Determine the current sequence value:
      SELECT applsys.fnd_concurrent_processes_s.NEXTVAL
      FROM DUAL;

    • Set the INCREMENT BY value of the sequence to the value of (fnd_concurrent_processes_s.NEXTVAL - 500000) * -1). For example, if the current value is 10019473 then the INCREMENT value will be -9519473 (= (10019473 - 500000) * -1).
      ALTER SEQUENCE applsys.fnd_concurrent_processes_s INCREMENT BY -9519473;

    • Decrease the current sequence value by requesting a next value from the sequence:
      SELECT fnd_concurrent_processes_s.NEXTVAL
      FROM DUAL;

      This will return a value of 500000.

    • Reset the INCREMENT BY value to 1:
      ALTER SEQUENCE fnd_concurrent_processes_s INCREMENT BY 1;

  3. Determine the concurrent manager log files that will need to be removed manually from the Concurrent Processing tier. The easiest way is to spool the output to a spool file so that it can be execute afterwards from the command line (or to be archived if needed).
    SELECT 'rm ' || logfile_name
    FROM fnd_concurrent_processes
    WHERE concurrent_process_id >= 500000;

  4. Delete the rows from the FND_CONCURRENT_PROCESSES table:
    DELETE FROM fnd_concurrent_processes
    WHERE concurrent_process_id >= 500000;

  5. Delete the rows from the FND_ENV_CONTEXT table:
    DELETE FROM fnd_env_context
    WHERE concurrent_process_id >= 500000;

  6. Start the concurrent managers.
Once these actions are completed, the service managers such as the Workflow related ones as well as the Output Post Processor will start up successfully.

Note: The impact of the workaround affects only the Concurrent Processing log files. If preferred, these can be kept for a temporary time in case it may be of interest. The existing concurrent requests which ran in the past are not affected meaning that report data will not be lost by completing this workaround.


ASCP plan uses lot of temp tablespace after OATM

After converting to OATM, we got complaints of ASCP Plan not completing and erroing out with errors of unable to extend TEMP tablespace.

This was traced to materialized view: INV.MTL_SYS_ITEMS_SN

SELECT /*+ OPAQUE_TRANSFORM */
"INVENTORY_ITEM_ID", "ORGANIZATION_ID", "USING_ORGANIZATION_ID",
"ASL_ID", "PROCESSING_LEAD_TIME", "MINIMUM_ORDER_QUANTITY",
"FIXED_LOT_MULTIPLE", "DELIVERY_CALENDAR_CODE",
"PURCHASING_UNIT_OF_MEASURE", "VENDOR_ID", "VENDOR_SITE_ID",
"ENABLE_VMI_FLAG", "VMI_MIN_QTY", "VMI_MAX_QTY",
"ENABLE_VMI_AUTO_REPLENISH_FLAG", "VMI_REPLENISHMENT_APPROVAL",
"ATTRIBUTE1", "ATTRIBUTE2", "ATTRIBUTE3", "ATTRIBUTE4", "ATTRIBUTE5",
"ATTRIBUTE6", "ATTRIBUTE7", "ATTRIBUTE8", "ATTRIBUTE9", "ATTRIBUTE10",
"ATTRIBUTE11", "ATTRIBUTE12", "ATTRIBUTE13", "ATTRIBUTE14",
"ATTRIBUTE15", "ITEM_PRICE", "PRIMARY_VENDOR_ITEM",
"REPLENISHMENT_METHOD", "MIN_MINMAX_DAYS", "MAX_MINMAX_DAYS",
"FORECAST_HORIZON", "FIXED_ORDER_QUANTITY"
FROM "MRP_AP_PO_SUPPLIERS_V" "X"
WHERE "ORGANIZATION_ID" = 1234
OR "ORGANIZATION_ID" = 2341
OR "ORGANIZATION_ID" = 2929
OR "ORGANIZATION_ID" = 2382

The query when traced showed a lot of wait events on 'direct path write temp' and filled up the temp tablespace.

WAIT #35: nam='direct path write temp' ela= 5078 file number=4017 first dba=18341
WAIT #35: nam='direct path write temp' ela= 2611 file number=4017 first dba=18354
WAIT #35: nam='direct path write temp' ela= 2617 file number=4017 first dba=18353
WAIT #35: nam='direct path write temp' ela= 1880 file number=4017 first dba=18360
WAIT #35: nam='direct path write temp' ela= 26 file number=4017 first dba=183641
WAIT #35: nam='direct path write temp' ela= 1721 file number=4017 first dba=18363
WAIT #35: nam='direct path write temp' ela= 24 file number=4017 first dba=183721
WAIT #35: nam='direct path write temp' ela= 1922 file number=4017 first dba=18378
WAIT #35: nam='direct path write temp' ela= 6247 file number=4017 first dba=18377
WAIT #35: nam='direct path write temp' ela= 1887 file number=4017 first dba=18383
WAIT #35: nam='direct path write temp' ela= 5088 file number=4017 first dba=18383
WAIT #35: nam='direct path write temp' ela= 4958 file number=4017 first dba=18396


/8: lwp_park(0x00000000, 0) = 0
/8: pwrite(423, "\bA2\0\0\f03 M YA9 b P _".., 122880, 0x69AB2000) = 122880
/1: kaio(AIOWAIT, 0xFFFFFFFFFFFFFFFF) Err#22 EINVAL
/1: write(5, " W A I T # 3 5 : n a".., 127) = 127
/1: write(5, "\n", 1) = 1
/1: times(0xFFFFFFFF7FFF8F70) = 1994720337
/1: semctl(469762093, 12, SETVAL, 1) = 0
/1: semtimedop(570425393, 0xFFFFFFFF7FFF7E04, 1, 0xFFFFFFFF7FFF7DF0) = 0
/1: write(5, " W A I T # 3 5 : n a".., 99) = 99
/1: write(5, "\n", 1) = 1
/1: semctl(469762093, 12, SETVAL, 1) = 0
/1: semtimedop(570425393, 0xFFFFFFFF7FFF7E04, 1, 0xFFFFFFFF7FFF7DF0) = 0
/1: write(5, " W A I T # 3 5 : n a".., 99) = 99
/1: write(5, "\n", 1) = 1
/1: semctl(469762093, 12, SETVAL, 1) = 0
/1: semtimedop(570425393, 0xFFFFFFFF7FFF7E04, 1, 0xFFFFFFFF7FFF7DF0) = 0
/1: write(5, " W A I T # 3 5 : n a".., 99) = 99
/1: write(5, "\n", 1) = 1
/1: times(0xFFFFFFFF7FFF8D50) = 1994720339
/1: lwp_unpark(9) = 0
/9: lwp_park(0x00000000, 0) = 0
/1: kaio(AIOWAIT, 0xFFFFFFFFFFFFFFFF) Err#22 EINVAL
/9: pwrite(422, "\bA2\0\0\vC3E3D9A9 b P _".., 122880, 0x7C7B2000) = 122880
/9: kaio(AIONOTIFY, 0) = 0
/1: kaio(AIOWAIT, 0xFFFFFFFF7FFF8E30) = 1
/1: write(5, " W A I T # 3 5 : n a".., 127) = 127
/1: write(5, "\n", 1) = 1
/1: times(0xFFFFFFFF7FFF8F70) = 1994720340
/1: times(0xFFFFFFFF7FFF8D50) = 1994720340
/1: lwp_unpark(10) = 0
/10: lwp_park(0x00000000, 0) = 0
/1: kaio(AIOWAIT, 0xFFFFFFFFFFFFFFFF) Err#22 EINVAL
/10: pwrite(423, "\bA2\0\0\f03 M iA9 b P _".., 122880, 0x69AD2000) = 122880
/10: kaio(AIONOTIFY, 0) = 0
/1: kaio(AIOWAIT, 0xFFFFFFFF7FFF8E30) = 1
/1: write(5, " W A I T # 3 5 : n a".., 128) = 128
/1: write(5, "\n", 1) = 1
/1: times(0xFFFFFFFF7FFF8F70) = 1994720342
/1: semctl(469762093, 12, SETVAL, 1) = 0
/1: semtimedop(570425393, 0xFFFFFFFF7FFF7E04, 1, 0xFFFFFFFF7FFF7DF0) = 0
/1: write(5, " W A I T # 3 5 : n a".., 99) = 99
/1: write(5, "\n", 1) = 1
/1: semctl(469762093, 12, SETVAL, 1) = 0
/1: semtimedop(570425393, 0xFFFFFFFF7FFF7E04, 1, 0xFFFFFFFF7FFF7DF0) = 0
/1: write(5, " W A I T # 3 5 : n a".., 99) = 99

Solved by following these steps:

execute dbms_stats.gather_fixed_objects_stats;
execute dbms_stats.gather_dictionary_stats();
execute dbms_stats.gather_schema_stats('APPS',cascade=>TRUE,degree=>48);
execute dbms_stats.gather_schema_stats('APPLSYS',cascade=>TRUE,degree=>48);
execute dbms_stats.gather_schema_stats('INV',cascade=>TRUE,degree=>48);
execute dbms_stats.gather_schema_stats('PO',cascade=>TRUE,degree=>48);
execute dbms_stats.gather_schema_stats('MSC',cascade=>TRUE,degree=>48);
execute dbms_stats.gather_schema_stats('ASO',cascade=>TRUE,degree=>48);

Query to check temp tablespace usage

This query is courtesy www.dbspecialists.com from their excellent article here.

SELECT A.tablespace_name tablespace, D.mb_total,
SUM (A.used_blocks * D.block_size) / 1024 / 1024 mb_used,
D.mb_total - SUM (A.used_blocks * D.block_size) / 1024 / 1024 mb_free
FROM v$sort_segment A,
(
SELECT B.name, C.block_size, SUM (C.bytes) / 1024 / 1024 mb_total
FROM v$tablespace B, v$tempfile C
WHERE B.ts#= C.ts#
GROUP BY B.name, C.block_size
) D
WHERE A.tablespace_name = D.name
GROUP by A.tablespace_name, D.mb_total;