search

helidon-io / helidon

Java libraries for writing microservices
https://helidon.io
Apache License 2.0
3.51k stars 566 forks source link

eclipselink JPA cache issue with @Transactional #1174

Closed nagaraja0yellapu closed 4 years ago

nagaraja0yellapu commented 4 years ago

Environment Details

1) eclipselink L1 cache on PersistenceContext is not cleared. The JPA query returning data from the L1 cache (that to stale cache) instead of from database 2) It seems L1 cache is not cleared or entitymanager is not closed after completion of transaction with container managed transaction 3) Expected Behavior: L1 cache shall be cleared on end of request. The JPA query from the subsequent requests shall return data from database instead of from L1 cache 4) Console Output, for reference. The initial data in the database is description1122335 and later changed to description1122335566. But in some subsequent requests, old data from cache is returned which is description1122335. We can see this from below log.

[EL Config]: 2019-11-27 23:38:28.892--ServerSession(800374351)--Connection(1443737297)--Thread(Thread[helidon-2,5,server])--Connected: jdbc:postgresql://localhost:5432/test?prepareThreshold=5&preparedStatementCacheQueries=256&preparedStatementCacheSizeMiB=5&databaseMetadataCacheFields=65536&databaseMetadataCacheFieldsMiB=5&defaultRowFetchSize=0&binaryTransfer=true&readOnly=false&binaryTransferEnable=&binaryTransferDisable=&unknownLength=2147483647&logUnclosedConnections=false&disableColumnSanitiser=false&tcpKeepAlive=false&loginTimeout=30&connectTimeout=10&socketTimeout=0&cancelSignalTimeout=10&receiveBufferSize=-1&sendBufferSize=-1&ApplicationName=PostgreSQL+JDBC+Driver&jaasLogin=true&useSpnego=false&gsslib=auto&sspiServiceClass=POSTGRES&allowEncodingChanges=false&targetServerType=any&loadBalanceHosts=false&hostRecheckSeconds=10&preferQueryMode=extended&autosave=never&cleanupSavepoints=false&reWriteBatchedInserts=false
        User: postgres
        Database: PostgreSQL  Version: 9.3.25
        Driver: PostgreSQL JDBC Driver  Version: 42.2.8
[EL Finest]: 2019-11-27 23:38:28.918--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--sequencing connected, state is NoPreallocation_State
[EL Finest]: 2019-11-27 23:38:28.918--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--sequence SEQ_GEN_IDENTITY: preallocation size 1
[EL Info]: 2019-11-27 23:38:29.033--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--/jar:file:/D:/Innorium/iWater-2.0/trunk/app-server-helidon1/target/iWater.jar!/_greeting login successful
[EL Finer]: 2019-11-27 23:38:29.106--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--Canonical Metamodel class [com.innorium.SampleData_] found and instantiated during initialization.
[EL Finest]: 2019-11-27 23:38:29.11--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--End deploying Persistence Unit greeting; session /jar:file:/D:/Innorium/iWater-2.0/trunk/app-server-helidon1/target/iWater.jar!/_greeting; state Deployed; factoryCount 1
[EL Finer]: 2019-11-27 23:38:29.164--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--client acquired: 1384620218
[EL Finer]: 2019-11-27 23:38:29.191--ClientSession(1384620218)--Thread(Thread[helidon-2,5,server])--acquire unit of work: 1729046662
[EL Finest]: 2019-11-27 23:38:29.212--UnitOfWork(1729046662)--Thread(Thread[helidon-2,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
[EL Finest]: 2019-11-27 23:38:29.22--ServerSession(800374351)--Connection(1339695066)--Thread(Thread[helidon-2,5,server])--Connection acquired from connection pool [read].
[EL Finest]: 2019-11-27 23:38:29.221--ServerSession(800374351)--Thread(Thread[helidon-2,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:29.223--ServerSession(800374351)--Connection(158558425)--Thread(Thread[helidon-2,5,server])--SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)
        bind => [1]
[EL Finest]: 2019-11-27 23:38:29.23--ServerSession(800374351)--Connection(1339695066)--Thread(Thread[helidon-2,5,server])--Connection released to connection pool [read].
==>getDefaultMessage**description1122335**
[EL Finer]: 2019-11-27 23:38:47.156--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--TX beforeCompletion callback, status=STATUS_ACTIVE
[EL Finer]: 2019-11-27 23:38:47.158--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--begin unit of work commit
[EL Finer]: 2019-11-27 23:38:47.185--ClientSession(848484835)--Thread(Thread[helidon-1,5,server])--TX beginTransaction, status=STATUS_ACTIVE
[EL Finest]: 2019-11-27 23:38:47.19--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--Execute query UpdateObjectQuery(com.innorium.SampleData@61466018)
[EL Finest]: 2019-11-27 23:38:47.215--ServerSession(800374351)--Connection(2075904664)--Thread(Thread[helidon-1,5,server])--Connection acquired from connection pool [default].
[EL Finest]: 2019-11-27 23:38:47.229--ClientSession(848484835)--Thread(Thread[helidon-1,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:47.262--ClientSession(848484835)--Connection(174439720)--Thread(Thread[helidon-1,5,server])--UPDATE SAMPLEDATA SET DESCRIPTION = ? WHERE (ID = ?)
        bind => [**description1122335566**, 1]
[EL Finest]: 2019-11-27 23:38:47.275--ServerSession(800374351)--Connection(2075904664)--Thread(Thread[helidon-1,5,server])--Connection released to connection pool [default].
[EL Finer]: 2019-11-27 23:38:47.282--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--TX afterCompletion callback, status=COMMITTED
[EL Finer]: 2019-11-27 23:38:47.297--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--end unit of work commit
[EL Finer]: 2019-11-27 23:38:47.301--UnitOfWork(1941623526)--Thread(Thread[helidon-1,5,server])--release unit of work
[EL Finer]: 2019-11-27 23:38:47.312--ClientSession(848484835)--Thread(Thread[helidon-1,5,server])--client released
[EL Finer]: 2019-11-27 23:38:54.081--ServerSession(800374351)--Thread(Thread[helidon-3,5,server])--client acquired: 1872402127
[EL Finer]: 2019-11-27 23:38:54.084--ClientSession(1872402127)--Thread(Thread[helidon-3,5,server])--acquire unit of work: 1805979620
[EL Finest]: 2019-11-27 23:38:54.086--UnitOfWork(1805979620)--Thread(Thread[helidon-3,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
[EL Finest]: 2019-11-27 23:38:54.099--ServerSession(800374351)--Connection(782736628)--Thread(Thread[helidon-3,5,server])--Connection acquired from connection pool [read].
[EL Finest]: 2019-11-27 23:38:54.1--ServerSession(800374351)--Thread(Thread[helidon-3,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:54.112--ServerSession(800374351)--Connection(609498224)--Thread(Thread[helidon-3,5,server])--SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)
        bind => [1]
[EL Finest]: 2019-11-27 23:38:54.116--ServerSession(800374351)--Connection(782736628)--Thread(Thread[helidon-3,5,server])--Connection released to connection pool [read].
==>getDefaultMessage**description1122335566**
[EL Finest]: 2019-11-27 23:38:54.099--ServerSession(800374351)--Connection(782736628)--Thread(Thread[helidon-3,5,server])--Connection acquired from connection pool [read].
[EL Finest]: 2019-11-27 23:38:54.1--ServerSession(800374351)--Thread(Thread[helidon-3,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:54.112--ServerSession(800374351)--Connection(609498224)--Thread(Thread[helidon-3,5,server])--SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)
        bind => [1]
[EL Finest]: 2019-11-27 23:38:54.116--ServerSession(800374351)--Connection(782736628)--Thread(Thread[helidon-3,5,server])--Connection released to connection pool [read].
==>getDefaultMessagedescription1122335566
[EL Finer]: 2019-11-27 23:38:55.069--ServerSession(800374351)--Thread(Thread[helidon-4,5,server])--client acquired: 1497165426
[EL Finer]: 2019-11-27 23:38:55.08--ClientSession(1497165426)--Thread(Thread[helidon-4,5,server])--acquire unit of work: 1560506765
[EL Finest]: 2019-11-27 23:38:55.083--UnitOfWork(1560506765)--Thread(Thread[helidon-4,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
[EL Finest]: 2019-11-27 23:38:55.09--ServerSession(800374351)--Connection(402777161)--Thread(Thread[helidon-4,5,server])--Connection acquired from connection pool [read].
[EL Finest]: 2019-11-27 23:38:55.097--ServerSession(800374351)--Thread(Thread[helidon-4,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:55.105--ServerSession(800374351)--Connection(396503366)--Thread(Thread[helidon-4,5,server])--SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)
        bind => [1]
[EL Finest]: 2019-11-27 23:38:55.113--ServerSession(800374351)--Connection(402777161)--Thread(Thread[helidon-4,5,server])--Connection released to connection pool [read].
==>getDefaultMessage**description1122335566**
[EL Finest]: 2019-11-27 23:38:55.309--UnitOfWork(**1729046662**)--Thread(Thread[helidon-2,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
==>getDefaultMessage**description1122335**
[EL Finer]: 2019-11-27 23:38:55.517--ServerSession(800374351)--Thread(Thread[helidon-1,5,server])--client acquired: 490870928
[EL Finer]: 2019-11-27 23:38:55.523--ClientSession(490870928)--Thread(Thread[helidon-1,5,server])--acquire unit of work: 826383480
[EL Finest]: 2019-11-27 23:38:55.536--UnitOfWork(826383480)--Thread(Thread[helidon-1,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
[EL Finest]: 2019-11-27 23:38:55.538--ServerSession(800374351)--Connection(1635019524)--Thread(Thread[helidon-1,5,server])--Connection acquired from connection pool [read].
[EL Finest]: 2019-11-27 23:38:55.539--ServerSession(800374351)--Thread(Thread[helidon-1,5,server])--reconnecting to external connection pool
[EL Fine]: 2019-11-27 23:38:55.543--ServerSession(800374351)--Connection(1508572716)--Thread(Thread[helidon-1,5,server])--SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)
        bind => [1]
[EL Finest]: 2019-11-27 23:38:55.546--ServerSession(800374351)--Connection(1635019524)--Thread(Thread[helidon-1,5,server])--Connection released to connection pool [read].
==>getDefaultMessage**description1122335566**
[EL Finest]: 2019-11-27 23:39:01.374--UnitOfWork(**1729046662**)--Thread(Thread[helidon-2,5,server])--Execute query ReadObjectQuery(name="readSampleData" referenceClass=SampleData sql="SELECT ID, DESCRIPTION, NAME FROM SAMPLEDATA WHERE (ID = ?)")
==>getDefaultMessage**description1122335**

Steps to reproduce

persistence.xml : disabled L2 cache (even tried by enabling L2 cache and still same issue)

<persistence-unit name="greeting" transaction-type="JTA">
        <description>A persistence unit for the greeting example.</description>
        <jta-data-source>greetingDataSource</jta-data-source>
        <class>com.innorium.SampleData</class>

        <shared-cache-mode>NONE</shared-cache-mode>
        <properties>
            <property name="javax.persistence.schema-generation.database.action" value="create"/>
            <property name="javax.persistence.schema-generation.create-source" value="metadata"/>
            <property name="javax.persistence.schema-generation.drop-source" value="metadata"/>

            <property name="eclipselink.deploy-on-startup" value="true"/>
            <property name="eclipselink.jdbc.native-sql" value="true"/>
            <!--<property name="eclipselink.logging.logger" value="JavaLogger"/>-->
            <property name="eclipselink.logging.level" value="ALL"/>
            <property name="eclipselink.logging.parameters" value="true"/>

            <property name="eclipselink.target-database" value="org.eclipse.persistence.platform.database.PostgreSQLPlatform"/>
            <property name="eclipselink.target-server" value="io.helidon.integrations.cdi.eclipselink.CDISEPlatform"/>

            <property name="eclipselink.weaving" value="false"/>
        </properties>
    </persistence-unit>

resource

@Path("/testData")
@RequestScoped
public class TestDataResource {

    @PersistenceContext //(unitName = "greeting")
    private EntityManager entityManager;

    @GET
    @Consumes(MediaType.APPLICATION_JSON)
    @Produces(MediaType.APPLICATION_JSON)
    @Transactional(value = Transactional.TxType.NOT_SUPPORTED)
    public Response getDefaultMessage() {
        //entityManager.clear();
        SampleData testData = entityManager.find(SampleData.class, 1L);
        System.out.println("==>getDefaultMessage" + testData.getDescription());
        return Response.status(Response.Status.OK).entity(testData).build();
    }

    @POST
    @Consumes(MediaType.APPLICATION_JSON)
    @Produces(MediaType.APPLICATION_JSON)
    @Transactional(value = Transactional.TxType.REQUIRED)
    public Response saveData(SampleData data) {
        //entityManager.clear();
        SampleData origData = entityManager.find(SampleData.class, data.getId());
        origData.setDescription(data.getDescription());
        origData.setName(data.getName());
        System.out.println("==>getDefaultMessage");
        return Response.status(Response.Status.OK).entity(data).build();
    }
}

SampleData entity class

@Entity
public class SampleData {
    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private long id;

    @Column(length = 10, nullable = true)
    private String name;

    @Column(length = 100, nullable = true)
    private String description;

    public long getId() {
        return id;
    }

    public void setId(long id) {
        this.id = id;
    }

    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }

    public String getDescription() {
        return description;
    }

    public void setDescription(String description) {
        this.description = description;
    }
}

DataSource configuration

  sql:
    DataSource:
      greetingDataSource:
        dataSourceClassName: org.postgresql.ds.PGSimpleDataSource
        dataSource:
          url: jdbc:postgresql://localhost:5432/test
          user: postgres
          password: XXXXX
ljnelson commented 4 years ago

@nagaraja0yellapu you may want to keep an eye on #1146 which may ultimately help with this. I'll look at this in detail shortly.

ljnelson commented 4 years ago

Fixed with https://github.com/oracle/helidon/commit/f5e1cc51e360e80d103b59d0528d1239950e3cfa.