Web Client Exception in P4210 after upgrading Tools Release
Purpose of Document
The purpose of this document is to guide possible issue in Sales Order Entry (P4210) application through Case Study. However this document is not to encompass commonly reported issue in this application.
Table of Contents:
Case Study 1 - All users are not able to add/update Sales Order after upgrading tools release
Case Study 1 - All users are not able to add/update Sales Order after upgrading tools release
Symptom
After upgrading tools release from 8.98.3.2 to 9.1.3.1, all users are not able to enter Sales Order. Web Client Exception error message appears on HTML client but it does not show Transaction Failure or Asynchronous business function error message in it.
For example,
Error message on Web/HTML Client:-
WEB CLIENT EXCEPTION An exception has been caught by the Web client. Please contact your system administrator. See log for details. Exception id = Exception 2013-09-22 16:41:41.022_USERID There was a problem with the server while running the business function F4211FSEndDoc. The sever may still be available, but because of state information, the entire unit of work must be resubmitted. Please exit the application and restart it. Post Button clicked Line number 87 P4210_W4210A
Note: Message represented in HTML/Web Client has to be repeated in e1root_mmddyy.log (mmddyy is the date when JAS Service started) so get/review e1root_*.log
Mesage in e1root_*.log:-
22 Sep 2013 16:38:11,018 [WARN ] - [RUNTIME] *ERROR* CallObject@179b0cd7: COSE#1000 Request timeout: timeout after 90000ms host EnterprisServerMachineID:6015(51643) SocID:58369 PID:4576 BSFN:F4211FSEndDoc user:USERID Env:JPD900 22 Sep 2013 16:38:11,019 [WARN ] - [RUNTIME] *ERROR* CallObject@179b0cd7: Server problem. The server may still be available, but because of state information, the entire unit-of-work must be resubmitted user:USERID Env:JPD900 22 Sep 2013 16:38:29,440 [WARN ] - [RUNTIME] HTMLClientHandler:doService: Abnormal error: Silent post request can not be processed due to busy status
22 Sep 2013 16:38:39,001 [SEVERE] - [RUNTIME] FormEngine.doEvent(): BSFN failed and need roll back!! | Form Name : P4210_W4210A com.jdedwards.runtime.base.SystemException: There was a problem with the server while running the business function F4211FSEndDoc.\nThe server may still be available, but because of state information, the entire unit of work must be resubmitted.\nPlease exit the application and restart it.\nPost Button Clicked Line number 87\nP4210_W4210A
Note: Refer to
<Document 1094464.1> - E1: JAS: Exception/Error Code in JAS when Call Object Kernel Fails on Logic Server
<Document 1307451.1> - E1: BSFN: Troubleshooting Tips and Techniques on Asynchronous Business Function Commit Fail Error in EnterpriseOne
For this example, above error COSE#1000 may come earlier than JDB_RollbackUser() in Call Object Kernel log (namely, JDEDEBUG.log)
JDEDEBUG_*.log (namely Call Object Kernel log):-
This log does not contain any error message and F4211FSEndDoc returns 0 but after F4211FSEndDoc is returned it calls "Entering JDB_RollbackUser (UserHandle 05284580)" and this user handle (pointer) is same with user handle initialized in calling F4211FSEndDoc.
Sep 22 16:36:42.440295 - 4576/3268 WRK:Init Remote User Entering JDB_InitUser with (MANUAL commit mode) Sep 22 16:36:42.440296 - 4576/3268 WRK:Init Remote User Entering JDB_BeginTransaction (UserHandle 05284580) Sep 22 16:36:42.440297 - 4576/3268 WRK:Init Remote User Starting Commit Point No : 1 for Transaction ID : 419434668_4576_3268_422634946 Sep 22 16:36:42.440298 - 4576/3268 WRK:Init Remote User Exiting JDB_BeginTransaction with Success (UserHandle 05284580) Sep 22 16:36:42.440330 - 4576/3268 WRK:Starting jdeCallObject Calling Business function F4211FSEndDoc from Level 1 for USERID. Application Name [P4210], Version [ZJDE0001] (BSFNLevel = 1) ... Sep 22 16:39:25.398959 - 4576/3268 WRK:Starting jdeCallObject Return value is 0 for F4211FSEndDoc. (BSFNLevel = 1) Sep 22 16:39:25.398969 - 4576/3268 WRK:Call Object Error count: Sent back - Server new #Error[0], #Warning[0]: Both Server&Client #Error[0] #Warning[0] Sep 22 16:39:25.398997 - 4576/3268 WRK:Rollback Remote User Entering JDB_RollbackUser (UserHandle 05284580) Sep 22 16:39:25.398998 - 4576/3268 WRK:Rollback Remote User Rolling back commit point 1 of the transaction : 419434668_4576_3268_422634946 Sep 22 16:39:25.398999 - 4576/3268 WRK:Rollback Remote User ORACLE DBRollbackCon envr=05459718 conn=07BAC5F0
Note:
Refer to <Document 1513147.1> E1: DB: JDEDB_COMMIT_MANUAL, JDEDB_COMMIT_AUTO, Transaction Processing Boundaries and Deadlock
JDB_InitUser with (MANUAL commit mode) is issued by system level (connection level) code
Check time flag from calling to return business function for problematic business function
INI settings:
JDE.INI
[NETWORK QUEUE SETTINGS] JDENETTimeout=60
JAS.INI
[JDENET] enterpriseServerTimeout=90000
Note:
JDENETTimeout is allowed time between Logic Server and Database Server when MANUAL commit is issued by ODBC. Currently 60 seconds (1 minute is default value). Unless it is requested by Oracle, do not modify this parameter because there is high chance of Database blocking by setting Transaction Processing boundaries till it receive message JDB_CommitUser() or JDB_RollbackUser() APIs.
enterprisServerTimeout is permitted time between JAS server to logic server. So any request by JAS is expected to receive message from logic server within 90 seconds. This value can be increased up to 720000 milliseconds in case user receive timeout error message in viewing data from, for instance, P4021, P09200 and so on.
Timeout settings are described at document <Document 1307451.1> - E1: BSFN: Troubleshooting Tips and Techniques on Asynchronous Business Function Commit Fail Error in EnterpriseOne
Change
Tools release upgrade from 8.98.4.5 to 9.1.4.2
Note: This case study shows that the only change made in system is upgrade of tools release and full package deployment for followup action, but actual cause is not related with this change made. Refer cause section
Cause
Probable cause is Index file for the table F42199 (Sales Order Detail Ledger) file is corrupted. Because it takes 2 minute 40 seconds in inserting a single record into F42199 as below,
Note: Overall time take is computed from Entering JDB_InsertTable (Table F42199) (hRequest 07BCEFE8) through Exiting JDB_InsertTable with Success (Table F42199)
Try
Possibly,
Run it in Windows Client (strictly testing purpose only): It does not issue any error but it takes long time to see data created
Issue above query through query tool (e.g., SQLPlus), it takes 2minutes 40 seconds. So we can conclude that issue is coming from database.
Note:
The first try is made to isolate possible problem in JAS or Local HTML server so we can avoid COSE#1000 error
The second try shows that issue is coming from database server.
Solution
Since we determined issue is coming from database level. Interestingly INSERT takes long time to commit. So probable cause can be corrupted index for data files. Then only option we have is drop table and create it again with index information.
Capture jdedebug.log
Check any DML statement which takes longer time
In case time is taking long time against INSERT most probable cause is corrupted index file
Try to generate index
If 4 does not fix issue, then generate table through OMW
Considerations
Before take any Table Operation through OMW, make it sure you have backed up as-is data using query tool.
Currently, a few option is available for this type of issue and general routine can be:-
Entering JDB_TableExists (Table F42199 ) Exiting JDB_TableExists with Failure(Table F42199) Entering JDB_CreateTable for (Table F42199) Entering JDB_CreateTableX (Table F42199) sql> CREATE TABLE PRODDTA.F42199 (...with data size and type...) sql> GRANT ALL ON PRODDTA.F42199 TO PUBLIC Entering JDB_CreateIndex (Table = F42199) Entering JDB_AddPrimaryKeyX (Table F42199) sql> ALTER TABLE PRODDTA.F42199 ALTER COLUMN SLKCOO nchar(5) NOT NULL sql> ALTER TABLE PRODDTA.F42199 ALTER COLUMN SLDOCO float NOT NULL ... (repeat for all columns in Primary Key) sql> ALTER TABLE PRODDTA.F42199 ADD CONSTRAINT F42199_PK PRIMARY KEY (SLKCOO, SLDOCO, ...) for primary key sql> ALTER TABLE PRODDTA.F42199 ADD CONSTRAINT F42199_2 PRIMARY KEY (SLKCOO, SLDOCO, ...) for secondary key
B. Copy Table
1. CopyTable
Entering JDB_TableExists (Table F42199) sql> SELECT COUNT(*) FROM CRPDTA.F42199 Entering JDB_DropIndex (Table = F42199) sql> DROP INDEX CRPDTA.F42199.F42199_1 sql> DROP INDEX CRPDTA.F42199.F42199_2 sql> ALTER TABLE CRPDTA.F42199 DROP CONSTRAINT F42199_PK Entering JDB_DropTable( Table = F41001 ) sql> DROP TABLE CRPDTA.F42199 Entering JDB_GetTableProperties sql> CREATE TABLE PRODDTA.F42199 (...with data size and type...) sql> GRANT ALL ON PRODDTA.F42199 TO PUBLIC sql> SELECT * FROM PRODDTA.F42199 Entering JDB_InsertTable (Table F42199) sql> INSERT INTO CRPDTA.F42199 VALUES (...) ... (repeat this for all data from PRODDTA.F42199 (source) to CRPDTA.F42199 (target) Entering JDB_CreateIndex (Table = F42199) Entering JDB_AddPrimaryKeyX (Table F42199) sql> ALTER TABLE PRODDTA.F42199 ALTER COLUMN SLKCOO nchar(5) NOT NULL sql> ALTER TABLE PRODDTA.F42199 ALTER COLUMN SLDOCO float NOT NULL ... (repeat for all columns in Primary Key) sql> ALTER TABLE PRODDTA.F42199 ADD CONSTRAINT F42199_PK PRIMARY KEY (SLKCOO, SLDOCO, ...) for primary key sql> ALTER TABLE PRODDTA.F42199 ADD CONSTRAINT F42199_2 PRIMARY KEY (SLKCOO, SLDOCO, ...) for secondary key
C. Create Index: Drop Index and Create Index
Below case study is to be added in the future.
Case Study 2 - Intermittently P42101 issues "Transaction Failure Message"
Symptom: Intermittently users are getting Transaction Failure error in running P42101 with error in e1root_*.log as below,
26 9 2013 12:59:16,834 [WARN ] USERID - [RUNTIME] *ERROR* CallObject@5eab5eab: CallObject.executeRequest(): Problem executing function [SalesOrderApplCtrlEX] lib [CSALES] TM_TRAN_CANCELLED was received from CallObject user:USERID Env:JPD910 26 9 2013 12:59:17,519 [SEVERE] USERID - [RUNTIME] AsynFormState.executeAsync(): async BSFN failed and need roll back!! .There was a problem with the sever while running the business function SalesOrderApplCtrlEX.\nThe server may still be available, but because of state information, the entire unit of work must be resubmitted.\nPlease exit the application and restart it. Post Button Click - Asynch Line number 0 | Form Name : P42101_W42101D
Change Through customer query they have implemented purging of Sales Order Files including related tables.
Cause Orphaned records from F49211 (Sales Order Detail File - Tag File) and F49219 (Sales Order Detail - Tag History). Commonly owing to table naming convention, you may miss out to handle this table from your custom routine. Make it sure all data from F4211 vs F49211 are a pair and F42119 vs F49219 are a pair.
If possible, try to simulate issue by adding same order number. For this case study, jdedebug.log (namely, Call Object Kernel log) reads as below,
INSERT INTO PRODDTA.F49211 VALUES (13000033.000000,'SO','00016',1000.000000,' ',0.000000,0,' ','P',0.000000,' ',' ',0.000000,0.000000,0.000000,0.000000,0.000000,0,' ',0,0.000000,0,0.000000,' ',0.000000,' ',0.000000,' ',0.000000,' ',0.000000,'A',' ',0.000000,0.000000,' ',0.000000,' ',0.000000,' ',' ',' ',0.000000,0.000000,' ',' ',' ',' ',' ',' ',' ',0.000000,0.000000,364753.000000,' ',0.000000,' ',' ',-1.000000,' ','PPN ','V',' ',' ',' ',' ',' ',' ',' ',0.000000,0.000000,' ',0.000000,0.000000,' ',0.000000,0.000000,0,0.000000,0,0.000000,0,0.000000,0,0.000000,' ',' ',' ',' ',' ',' ',0.000000,0,' ','USERID','EP42101','jasmachineID',113270,175832.000000,' ',' ',' ',' ',0,0,0,' ',' ',' ',' ',' ',' ','Y',' ',' ',' ',' ',0.000000,' ',' ',0.000000,' ',' ',' ',0.000000,' ',' ',' ',0.000000,' ',' ',0.000000,'Y','Y','Y','Y',' ',' ',' ','N',' ',' ',' ',' ',' ') Entering DBPerformRequest ODBC:W DBPerformRequest req=33b340b8 con=34954da8 env=00000001 dbc=00000004 spid=0 jddv-db1 M (JDE@JDE_PY16) ODBC[jdbodbc.c,4023] wSQLExecute failure. rc = -1 ODBC[jdbodbc.c,4023] STMT:00 [23505][-803] [IBM][CLI Driver][DB2/AIX64] SQL0803N One or more values in the INSERT statement, UPDATE statement, or foreign key update caused by a DELETE statement are not valid because the primary key, unique constraint or unique index identified by "1" constrains t ODB0000163 - wSQLExecute failure. rc=-1 ODB0000164 - STMT:00 [23505][-803][2] [IBM][CLI Driver][DB2/AIX64] SQL0803N One or more values in the INSERT statement, UPDATE statement, or foreign key update caused by a DELETE statement are not valid because the primary key, unique constraint or unique index identified by "1" constrains t Exiting DBPerformRequest JDB9900401 - Failed to execute db request JDB3400009 - Failed to perform Insert for F49211 JDB9901232 - Canceling transaction because: TC052 InsertTable: Insert failed Cancelling Transaction : 2886801884_15925452_423015921 Exiting JDB_InsertTable with Failure(Table F49211)
Try The reason it appears to be intermittent is that at once order number is retrieved next number is to get updated. So by chance, same order does not exist from F49211 user shall not hit same error.
For this type of issue,
1. Get e1root_*.log from JAS (this will give you PID for Call Object Kernel) 2. Get JDE_PID.log from log folder in your logic server. In case error message in e1root_*.log does not contain any PID (Process Identifier) then get all JDE_*.logs in your logic server 3. (if you know how to simulate) capture/trace jdedebug.log
Solution Delete orphaned data from F49211 and F49219.
Considerations In case you need to implement your custom Purge/Archive routine, refer to <Document 625602.1> E1: 42: Data File Purges in Sales (R42119P / R42199P / R4201P / R4211P / R42800). If possible, analyze how purge is working in R42800 and make it sure all tables related with Sales Order are handled correctly