Saturday, June 2, 2012

SQLIntegrityConstraintViolationException while the LeaseManager updates the ACTIVE table



####<May 31, 2012 11:14:06 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '32' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008622> <1338455646674> <BEA-000000> <Query: UPDATE ACTIVE SET TIMEOUT = ( (SYSDATE + (30/86400))) WHERE SERVER IN ('wlsserver.osbpp1ms1') AND INSTANCE ='-5605988896686436333/osbpp1ms1' AND DOMAINNAME='osbpp1do' AND CLUSTERNAME='osbpp1cl'>

####<May 31, 2012 11:14:07 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008626> <1338455647328> <BEA-000000> <<DatabaseLeasingBasis>: tryAcquire(service.SINGLETON_MASTER, 30000)>

####<May 31, 2012 11:14:07 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008626> <1338455647329> <BEA-000000> <Query: DELETE FROM ACTIVE WHERE (SYSDATE > TIMEOUT) AND SERVER = 'service.SINGLETON_MASTER' AND DOMAINNAME='osbpp1do' AND CLUSTERNAME='osbpp1cl'>

####<May 31, 2012 11:14:07 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008626> <1338455647331> <BEA-000000> <Query: INSERT INTO ACTIVE ( SERVER, INSTANCE, DOMAINNAME, CLUSTERNAME, TIMEOUT ) VALUES ( 'service.SINGLETON_MASTER' , '-5605988896686436333/osbpp1ms1' , 'osbpp1do' , 'osbpp1cl' , (SYSDATE + (30/86400)) )>

####<May 31, 2012 11:14:07 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008626> <1338455647333> <BEA-000000> <Attempted Query: INSERT INTO ACTIVE ( SERVER, INSTANCE, DOMAINNAME, CLUSTERNAME, TIMEOUT ) VALUES ( 'service.SINGLETON_MASTER' , '-5605988896686436333/osbpp1ms1' , 'osbpp1do' , 'osbpp1cl' , (SYSDATE + (30/86400)) )>

####<May 31, 2012 11:14:07 AM CEST> <Debug> <ServerMigration> <hqchacme105> <osbpp1ms1> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <553e43a3c186ec6d:58114d2:1379f528b89:-7ffd-0000000000008626> <1338455647334> <BEA-000000> <Unexpected exception

java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (PP1_SOAINFRA.SYS_C0013550) violated
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:457)
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:405)
at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:889)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:476)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:204)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:540)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:217)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:1079)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1466)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3752)
at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3887)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeUpdate(OraclePreparedStatementWrapper.java:1508)
at weblogic.jdbc.wrapper.PreparedStatement.executeUpdate(PreparedStatement.java:172)
at weblogic.cluster.singleton.DatabaseLeasingBasis.assumeLease(DatabaseLeasingBasis.java:253)
at weblogic.cluster.singleton.DatabaseLeasingBasis.acquire(DatabaseLeasingBasis.java:88)
at weblogic.cluster.singleton.LeaseManager.timerExpired(LeaseManager.java:408)
at weblogic.timers.internal.TimerImpl.run(TimerImpl.java:273)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:178)




this is the content of the ACTIVE table




"SERVER" "INSTANCE" "DOMAINNAME" "CLUSTERNAME" "TIMEOUT"

"service.SINGLETON_MASTER" "2372471525479840300/osbpp1ms2" "osbpp1do" "osbpp1cl" 31-MAY-12

"wlsserver.osbpp1ms1" "-5605988896686436333/osbpp1ms1" "osbpp1do" "osbpp1cl" 31-MAY-12

"service.CLUSTER_MASTER" "2372471525479840300/osbpp1ms2" "osbpp1do" "osbpp1cl" 31-MAY-12

"wlsserver.osbpp1ms4" "2967680027205630303/osbpp1ms4" "osbpp1do" "osbpp1cl" 31-MAY-12

"wlsserver.osbpp1ms2" "2372471525479840300/osbpp1ms2" "osbpp1do" "osbpp1cl" 31-MAY-12

"wlsserver.osbpp1ms3" "1002143801186479830/osbpp1ms3" "osbpp1do" "osbpp1cl" 31-MAY-12





and the constraint is:



"CONSTRAINT_NAME" "CONSTRAINT_TYPE" "SEARCH_CONDITION" "R_OWNER" "R_TABLE_NAME" "R_CONSTRAINT_NAME" "DELETE_RULE" "STATUS" "DEFERRABLE" "VALIDATED" "GENERATED" "BAD" "RELY" "LAST_CHANGE" "INDEX_OWNER" "INDEX_NAME" "INVALID" "VIEW_RELATED"


"SYS_C0013550" "Primary_Key" "" "" "" "" "" "ENABLED" "NOT DEFERRABLE" "VALIDATED" "GENERATED NAME" "" "" 26-APR-12 "PP1_SOAINFRA" "SYS_C0013550" "" ""





and the DDL is:



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

-- DDL for Table ACTIVE

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



CREATE TABLE "PP1_SOAINFRA"."ACTIVE"

( "SERVER" VARCHAR2(150 BYTE),

"INSTANCE" VARCHAR2(100 BYTE),

"DOMAINNAME" VARCHAR2(50 BYTE),

"CLUSTERNAME" VARCHAR2(50 BYTE),

"TIMEOUT" DATE

)


CREATE UNIQUE INDEX "PP1_SOAINFRA"."SYS_C0013550" ON "PP1_SOAINFRA"."ACTIVE" ("SERVER", "DOMAINNAME", "CLUSTERNAME")



ALTER TABLE "PP1_SOAINFRA"."ACTIVE" ADD PRIMARY KEY ("SERVER", "DOMAINNAME", "CLUSTERNAME");



probably the DELETE doesn’t delete the row....


This is what the official documentation says:


http://docs.oracle.com/cd/E23549_01/relnotes.1111/e10133/ha.htm#CIHEJAHC




6.1.14 Harmless SQLIntegrityConstraintViolationException Can be Received in a SOA Cluster

The following SQLIntegrityConstraintViolationException can be received in a SOA cluster:

[TopLink Warning]: 2010.04.11 14:26:53.941--UnitOfWork(275924841)--Exception

[TOPLINK-4002] (Oracle TopLink - 11g Release 1 (11.1.1.3.0):

Internal Exception: java.sql.SQLIntegrityConstraintViolationException:

ORA-00001: unique constraint (JYIPS2RC4B49_SOAINFRA.SYS_C0035333) violated

.

.

.

This is not a bug. In a cluster environment, when the messages for the same group arrive on both the nodes, one node is bound to experience this exception for the first message. The application is aware of this exception and handles it properly. It does not break any functionality.

This exception can also come on a single node after you restart the server and send the message for the existing group. Again, this exception will be experienced on the very first message.

In summary, this exception is within the application design and does not impact any functionality. It is for this reason that you do not see this exception logged as severe in the soa-diagnostic logs.

Toplink does, however, log it in its server logs.



I hope this is our case... harmless....

No comments: