Tukukkk

Persist works differently in dev and production environments. In dev, a signle sql insert is issued:

insert into mytable (field1, field2) values (?, ?)

In prod, there is select currval('mytable_mykeyfield_seq') query immediately after insert:

23-11-2018;16:57:04,255 TRACE org.hibernate.event.internal.AbstractSaveEventListener Transient instance of: com.odin.approvalengineapp.application.domain.ApprovalRequest

23-11-2018;16:57:04,255 TRACE org.hibernate.event.internal.DefaultPersistEventListener Saving transient instance

23-11-2018;16:57:04,256 TRACE org.hibernate.event.internal.AbstractSaveEventListener Saving com.odin.approvalengineapp.application.domain.ApprovalRequest#<null>

23-11-2018;16:57:04,257 TRACE org.hibernate.engine.internal.Cascade Processing cascade ACTION_PERSIST_SKIPLAZY for: com.odin.approvalengineapp.application.domain.ApprovalRequest

23-11-2018;16:57:04,257 TRACE org.hibernate.engine.internal.Cascade Done processing cascade ACTION_PERSIST_SKIPLAZY for: com.odin.approvalengineapp.application.domain.ApprovalRequest

23-11-2018;16:57:04,258 TRACE org.hibernate.event.internal.WrapVisitor Wrapped collection in role: com.odin.approvalengineapp.application.domain.ApprovalRequest.approvalActionHistories

23-11-2018;16:57:04,259 TRACE org.hibernate.engine.spi.ActionQueue Adding an EntityIdentityInsertAction for [com.odin.approvalengineapp.application.domain.ApprovalRequest] object

23-11-2018;16:57:04,259 TRACE org.hibernate.engine.spi.ActionQueue Executing inserts before finding non-nullable transient entities for early insert: [EntityIdentityInsertActioncom.odin.approvalengineapp.application.domain.ApprovalRequest#<null>]

23-11-2018;16:57:04,260 TRACE org.hibernate.engine.spi.ActionQueue Adding insert with no non-nullable, transient entities: [EntityIdentityInsertActioncom.odin.approvalengineapp.application.domain.ApprovalRequest#<null>]

23-11-2018;16:57:04,261 TRACE org.hibernate.engine.spi.ActionQueue Executing insertions before resolved early-insert

23-11-2018;16:57:04,261 DEBUG org.hibernate.engine.spi.ActionQueue Executing identity-insert immediately

23-11-2018;16:57:04,262 TRACE org.hibernate.persister.entity.AbstractEntityPersister Inserting entity: com.odin.approvalengineapp.application.domain.ApprovalRequest (native id)

23-11-2018;16:57:04,263 DEBUG org.hibernate.engine.jdbc.spi.SqlStatementLogger insert into approval_request (action_id, status, creation_date, initiator_id, is_response_send, last_edit_date, request_body, request_id, retry_times) values (?, ?, ?, ?, ?, ?, ?, ?, ?)

23-11-2018;16:57:04,264 TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl Registering statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@6e270417]

23-11-2018;16:57:04,264 TRACE org.hibernate.persister.entity.AbstractEntityPersister Dehydrating entity: com.odin.approvalengineapp.application.domain.ApprovalRequest#<null>

23-11-2018;16:57:04,265 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [1] as [INTEGER] - [0]

23-11-2018;16:57:04,266 DEBUG org.hibernate.type.descriptor.converter.AttributeConverterSqlTypeDescriptorAdapter$1 Converted value on binding : REQUEST_ACCEPTED -> 0

23-11-2018;16:57:04,266 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [2] as [INTEGER] - [0]

23-11-2018;16:57:04,267 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [3] as [TIMESTAMP] - [Fri Nov 23 16:57:04 UTC 2018]

23-11-2018;16:57:04,268 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [4] as [VARCHAR] - [a63e2cb7-d5a0-4eca-adf5-982c64874bd5]

23-11-2018;16:57:04,269 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [5] as [INTEGER] - [0]

23-11-2018;16:57:04,269 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [6] as [TIMESTAMP] - [Fri Nov 23 16:57:04 UTC 2018]

23-11-2018;16:57:04,270 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [7] as [VARCHAR] - [{"performingApplication":"Order Management","actionName":"Create New Order","initiator":"a63e2cb7-d5a0-4eca-adf5-982c64874bd5","entity":{"id":"SO000504","name":"Order","fields":[



{"name":"orderCustomer","value":"50123493-40ed-49da-8ad8-022041f179f5"}

,{"name":"orderDate","value":"22-Nov-2018"},{"name":"orderValidUntil","value":"22-Dec-2018"},{"name":"orderSubTotal","value":"36.0"},{"name":"orderTaxTotal","value":"9.0"},{"name":"orderTotal","value":"45.0"},{"name":"orderComment","value":"Order for the "Symantec Endpoint Protection Cloud for Users (Monthly)" Plan for 1 Month(s). "},{"name":"orderPromoCode"},{"name":"orderDetailDiscountPercent","value":"0.0","number":1,"description":"Symantec Endpoint Protection Cloud UserProduct Recurring"},{"name":"orderDetailDiscountAmount","value":"0.0","number":1,"description":"Symantec Endpoint Protection Cloud UserProduct Recurring"},{"name":"costDiscountPercent","value":"0.0","number":1,"description":"Symantec Endpoint Protection Cloud UserProduct Recurring"},{"name":"costDiscountAmount","value":"0.0","number":1,"description":"Symantec Endpoint Protection Cloud UserProduct Recurring"}]},"moduleAPSIdentifier":"f1165975-c686-40ea-863d-781ad0484007"}]

23-11-2018;16:57:04,271 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [8] as [VARCHAR] - [951c0893-82be-4661-a5ae-1c42ba874734]

23-11-2018;16:57:04,271 TRACE org.hibernate.type.descriptor.sql.BasicBinder binding parameter [9] as [INTEGER] - [0]

23-11-2018;16:57:04,274 TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl Releasing statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@6e270417]

23-11-2018;16:57:04,274 TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl Closing prepared statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@6e270417]

23-11-2018;16:57:04,275 TRACE org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl Starting after statement execution processing [AFTER_STATEMENT]

23-11-2018;16:57:04,276 TRACE org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor LogicalConnection#afterStatement

23-11-2018;16:57:04,276 DEBUG org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl Initiating JDBC connection release from afterStatement

23-11-2018;16:57:04,277 TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl Releasing JDBC resources

23-11-2018;16:57:04,277 DEBUG org.hibernate.engine.jdbc.spi.SqlStatementLogger select currval('approval_request_id_seq')

23-11-2018;16:57:04,278 TRACE org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl Registering statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@6307d039]

23-11-2018;16:57:04,280 DEBUG org.hibernate.engine.jdbc.spi.SqlExceptionHelper could not extract ResultSet [n/a]: org.postgresql.util.PSQLException: ERROR: relation "approval_request_id_seq" does not exist

The problem is I cannot understand why Hibernate behaves differently. Dev and prod uses the same wildfly, application and configs (all consumed via docker image), same Postgresql version.

persistence.xml:

<?xml version="1.0" encoding="UTF-8"?>

<persistence xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://java.sun.com/xml/ns/persistence"

             xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd"

             version="2.0">

    <persistence-unit name="appdb" transaction-type="JTA">

        <jta-data-source>java:jboss/datasources/appdb</jta-data-source>

        <properties>

            <property name="hibernate.dialect" value="org.hibernate.dialect.PostgreSQL94Dialect"/>

            <property name="hibernate.connection.autocommit" value="true"/>

            <property name="hibernate.jta.track_by_thread" value="false"/>

            <property name="jboss.entity.manager.jndi.name" value="java:/appdb"/>

            <property name="jboss.entity.manager.factory.jndi.name" value="java:/appDSFactory"/>

        </properties>

    </persistence-unit>

</persistence>

entity:

@Entity

@Table(name = "approval_request")

public class ApprovalRequest {



    @Id

    @GeneratedValue(strategy = GenerationType.IDENTITY)

    @Column(name = "id", nullable = false)

    private Integer id;



    @Column(name = "request_id", nullable = false, length = 255)

    private String requestId;

...

table structure (also the same in dev and prod):

a8n_approvalengineapp=> d approval_request

Table "public.approval_request"

      Column      |            Type             |                             Modifiers

------------------+-----------------------------+--------------------------------------------------------------------

 id               | integer                     | not null default nextval('approval_request_id_sequence'::regclass)

 request_id       | character varying(256)      | not null

...

Indexes:

    "pk_approval_request" PRIMARY KEY, btree (id)

    "uk_approval_request_request_id" UNIQUE CONSTRAINT, btree (request_id)

    "ix_approval_request_request_id" btree (request_id)

Referenced by:

    TABLE "approval_action_history" CONSTRAINT "fk_approval_action_history_request_id" FOREIGN KEY (request_id) REFERENCES approval_request(id)

I use following components:

WildFly Full 11.0.0.Final

Hibernate Core 5.1.10.Final (bundled with Wildfly)

org.postgresql.Driver 42.2

Postgresql 9.6

CentOS 7

OpenJDK 1.8

From http://docs.jboss.org/hibernate/orm/5.1/userguide/html_single/Hibernate_User_Guide.html chapter 2.6.9 I can suggest java.sql.Statement#getGeneratedKeys was used in dev environment but not used in prod. Why?