BUG #11119: JDBC Driver misreports failing query/statement in executeBatch - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      11119
Logged by:          Luke Henry
Email address:      luke.henry@sanmina.com
PostgreSQL version: 9.2.1
Operating system:   Windows 7
Description:

The various JDBC driver versions, from 9.2X until the latest appear to
always report batch record 0 as the offending record when a
BatchUpdateException is thrown.

Initial analysis of the driver code seems to show that the handlers
(BatchResultHandler and CallableBatchResultHandler) only update their
internal "result arrays" when handleCommandStatus is invoked.
Unfortunately, it appears that method does not get called when one of the
batch queries throws an exception.

Therefore, the driver always reports the first query as the failing query
(as it remains in its default initial state), making it extremely difficult
to identify which statement caused the problem.

This also means that when an executeBatch fails the updateCounts option on
the BatchExecutionException is always empty, even if some number of
statements succeeded.

The performance benefits of batch calls appear to be substantial, but with
such poor diagnostic capabilities it is difficult to use it in production
code.

Note: the BatchExecutionException does contain the original exception in its
getNextException property but it misreports which batch statement caused the
exception.

Log Details:

14:45:02.999 (3) PostgreSQL 9.3 JDBC4.1 (build 1102)
14:45:02.999 (3) Trying to establish a protocol version 3 connection to
localhost:5432
14:45:03.001 (3) Receive Buffer Size is 8192
14:45:03.002 (3) Send Buffer Size is 8192
14:45:03.002 (3)  FE=> StartupPacket(user=****, database=batch_mesr,
client_encoding=UTF8, DateStyle=ISO, extra_float_digits=2,
TimeZone=America/Chicago)
14:45:03.020 (3)  <=BE AuthenticationOk
14:45:03.020 (3)  <=BE ParameterStatus(application_name = )
14:45:03.020 (3)  <=BE ParameterStatus(client_encoding = UTF8)
14:45:03.021 (3)  <=BE ParameterStatus(DateStyle = ISO, MDY)
14:45:03.021 (3)  <=BE ParameterStatus(integer_datetimes = on)
14:45:03.021 (3)  <=BE ParameterStatus(IntervalStyle = postgres)
14:45:03.021 (3)  <=BE ParameterStatus(is_superuser = off)
14:45:03.021 (3)  <=BE ParameterStatus(server_encoding = UTF8)
14:45:03.021 (3)  <=BE ParameterStatus(server_version = 9.2.1)
14:45:03.021 (3)  <=BE ParameterStatus(session_authorization = ****)
14:45:03.021 (3)  <=BE ParameterStatus(standard_conforming_strings = on)
14:45:03.021 (3)  <=BE ParameterStatus(TimeZone = America/Chicago)
14:45:03.021 (3)  <=BE BackendKeyData(pid=3572,ckey=341046590)
14:45:03.021 (3)  <=BE ReadyForQuery(I)
14:45:03.021 (3) simple execute,
handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@89ec211,
maxRows=0, fetchSize=0, flags=23
14:45:03.021 (3)  FE=> Parse(stmt=null,query="SET extra_float_digits =
3",oids={})
14:45:03.021 (3)  FE=> Bind(stmt=null,portal=null)
14:45:03.021 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.021 (3)  FE=> Sync
14:45:03.022 (3)  <=BE ParseComplete [null]
14:45:03.022 (3)  <=BE BindComplete [null]
14:45:03.022 (3)  <=BE CommandStatus(SET)
14:45:03.022 (3)  <=BE ReadyForQuery(I)
14:45:03.022 (3)     compatible = 9.3
14:45:03.022 (3)     loglevel = 2
14:45:03.022 (3)     prepare threshold = 5
14:45:03.023 (3)     types using binary send =

INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
14:45:03.023 (3)     types using binary receive =

INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
14:45:03.023 (3)     integer date/time = true
getConnection returning org.postgresql.Driver
14:45:03.028 (3) batch execute 6 queries,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$CallableBatchResultHandler@5ee76547,
maxRows=0, fetchSize=0, flags=4
14:45:03.028 (3)  FE=> Parse(stmt=S_1,query="BEGIN",oids={})
14:45:03.029 (3)  FE=> Bind(stmt=S_1,portal=null)
14:45:03.029 (3)  FE=> Execute(portal=null,limit=0)
14:45:03.030 (3)  FE=> Parse(stmt=S_2,query="select * from
mesr.test_insert_or_update($1)  as result",oids={1043})
14:45:03.030 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text0'>)
14:45:03.031 (3)  FE=> Describe(portal=null)
14:45:03.031 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.031 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text1'>)
14:45:03.031 (3)  FE=> Describe(portal=null)
14:45:03.031 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.031 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text2'>)
14:45:03.031 (3)  FE=> Describe(portal=null)
14:45:03.031 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.032 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text3'>)
14:45:03.032 (3)  FE=> Describe(portal=null)
14:45:03.032 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.032 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text4'>)
14:45:03.032 (3)  FE=> Describe(portal=null)
14:45:03.032 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.032 (3)  FE=> Bind(stmt=S_2,portal=null,$1=<'some_text5'>)
14:45:03.032 (3)  FE=> Describe(portal=null)
14:45:03.032 (3)  FE=> Execute(portal=null,limit=1)
14:45:03.032 (3)  FE=> Sync
14:45:03.037 (3)  <=BE ParseComplete [S_1]
14:45:03.037 (3)  <=BE BindComplete [null]
14:45:03.037 (3)  <=BE CommandStatus(BEGIN)
14:45:03.037 (3)  <=BE ParseComplete [S_2]
14:45:03.037 (3)  <=BE BindComplete [null]
14:45:03.039 (3)  <=BE RowDescription(1)
14:45:03.039 (3)         Field(,INT4,4,T)
14:45:03.039 (3)  <=BE DataRow(len=1)
14:45:03.039 (3)  <=BE PortalSuspended
14:45:03.040 (3)  <=BE BindComplete [null]
14:45:03.040 (3)  <=BE RowDescription(1)
14:45:03.040 (3)         Field(,INT4,4,T)
14:45:03.040 (3)  <=BE DataRow(len=1)
14:45:03.040 (3)  <=BE PortalSuspended
14:45:03.040 (3)  <=BE BindComplete [null]
14:45:03.040 (3)  <=BE RowDescription(1)
14:45:03.040 (3)         Field(,INT4,4,T)
14:45:03.040 (3)  <=BE DataRow(len=1)
14:45:03.040 (3)  <=BE PortalSuspended
14:45:03.040 (3)  <=BE BindComplete [null]
14:45:03.040 (3)  <=BE RowDescription(1)
14:45:03.040 (3)         Field(,INT4,4,T)
14:45:03.040 (3)  <=BE DataRow(len=1)
14:45:03.040 (3)  <=BE PortalSuspended
14:45:03.040 (3)  <=BE BindComplete [null]
14:45:03.040 (3)  <=BE RowDescription(1)
14:45:03.041 (3)         Field(,INT4,4,T)
14:45:03.041 (3)  <=BE DataRow(len=1)
14:45:03.041 (3)  <=BE PortalSuspended
14:45:03.041 (3)  <=BE BindComplete [null]
14:45:03.041 (3)  <=BE RowDescription(1)
14:45:03.041 (3)         Field(,INT4,4,T)
14:45:03.043 (3)  <=BE ErrorMessage(ERROR: bad things irl)
org.postgresql.util.PSQLException: ERROR: bad things irl
    at
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2198)
    at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1927)
    at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405)
    at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2892)
    at

com.sanmina.mds.services.mesreplication.replicator.PersistentBatchReplicatorTest.testBatch(PersistentBatchReplicatorTest.java:85)
    at

com.sanmina.mds.services.mesreplication.replicator.PersistentBatchReplicatorTest.testBatchUpdates(PersistentBatchReplicatorTest.java:59)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:601)
    at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
    at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
    at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
    at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
    at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
    at
org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
    at
org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
    at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
    at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
    at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
    at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
SQLException: SQLState(P0001)
SQLState(P0001) vendor code(0)
java.sql.BatchUpdateException: Batch entry 0 select * from
mesr.test_insert_or_update('some_text0')  as result was aborted.  Call
getNextException to see the cause.
    at
org.postgresql.jdbc2.AbstractJdbc2Statement$CallableBatchResultHandler.handleError(AbstractJdbc2Statement.java:2813)
    at
org.postgresql.core.v3.QueryExecutorImpl$1.handleError(QueryExecutorImpl.java:461)
    at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1928)
    at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405)
    at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2892)