Thread: Batch INSERT failing with error 22P02

I recently upgraded from PG 8.1.8 to 8.2.4.  I made a corresponding move
in JDBC driver versions from postgresql-8.1-408.jdbc3.jar to
postgresql-8.2-506.jdbc4.jar (binary distributions in both cases).
During a lengthy import using Hibernate (yes, I realize it's not the
most efficient mechanism for bulk import), I hit the following error:

Sep 4, 2007 3:39:10 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
WARNING: SQL Error: 0, SQLState: null
Sep 4, 2007 3:39:10 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
SEVERE: Batch entry 0 insert into turnaround (turn_number, site, item,
purchase_order_number, purchase_order_line, lot, serial_number,
quantity_issued, expiration_date, id) values (0000XBJG, GSO, 0A0001H9L,
427190, 15, , , -14000.00000, NULL, 59657893) was aborted.  Call
getNextException to see the cause.
Sep 4, 2007 3:39:10 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
WARNING: SQL Error: 0, SQLState: 22P02
Sep 4, 2007 3:39:10 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
SEVERE: ERROR: invalid input syntax for type oid: ""
Sep 4, 2007 3:39:10 AM
org.hibernate.event.def.AbstractFlushingEventListener performExecutions
SEVERE: Could not synchronize database state with session

... <Hibernate stack trace clutter omitted> ...

Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into
turnaround (turn_number, site, item, purchase_order_number,
purchase_order_line, lot, serial_number, quantity_issued,
expiration_date, id) values (0000XBJG, GSO, 0A0001H9L, 427190, 15, , ,
-14000.00000, NULL, 59657893) was aborted.  Call getNextException to see
the cause.
        at
org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2534)
        at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1317)
        at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:350)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2596)
        at
com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
        at
org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:57)
        at
org.hibernate.jdbc.BatchingBatcher.addToBatch(BatchingBatcher.java:33)
        at
org.hibernate.persister.entity.BasicEntityPersister.insert(BasicEntityPersister.java:1853)
        ... 11 more
Sep 4, 2007 3:39:10 AM com.goldencode.p2j.schema.ImportWorker$Library
removeFailingRecord
SEVERE: Dropped record #1225351 in turnarnd.d due to error:  ERROR:
invalid input syntax for type oid: ""
Sep 4, 2007 3:40:26 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
WARNING: SQL Error: 0, SQLState: null
Sep 4, 2007 3:40:26 AM org.hibernate.util.JDBCExceptionReporter
logExceptions
SEVERE: An SQLException was provoked by the following failure:
java.lang.IllegalArgumentException: Can't change resolved type for
param: 7 from 1043 to 26
...

The table schema looks like so at the time of the failure:

          Table "public.turnaround"
        Column         |  Type   | Modifiers
-----------------------+---------+-----------
 id                    | integer | not null
 turn_number           | text    |
 site                  | text    |
 item                  | text    |
 purchase_order_number | integer |
 purchase_order_line   | integer |
 lot                   | text    |
 serial_number         | text    |
 quantity_issued       | numeric |
 expiration_date       | date    |
Indexes:
    "turnaround_pkey" PRIMARY KEY, btree (id)
    "idx__turnaround_pi_turnarnd" UNIQUE, btree (upper(rtrim(turn_number, '
'::text)))

I hit this error 1,225,351 rows into a ~1.7 million row table.
Unfortunately, I have not been able to recreate this problem with a
smaller testcase.  If I try cutting down my import data set to just the
failing row, or to that row and nearby rows, the import is clean.  I
should note there was no such error using the identical data set with
the 8.1.8 back-end/8.1-408 JDBC driver combination.

I tried using the development driver (postgresql-8.3dev-601.jdbc4.jar),
but the same problem occurs.  Interestingly, if I drop back to the older
driver I was using with the 8.1.8 back-end
(postgresql-8.1-408.jdbc3.jar), but run it against the 8.2.4 back-end,
the import completes without error!

So, my questions:

A) Can anyone think what might have changed between the 8.1-408 and
8.2-506 versions of the JDBC driver which might result in an INVALID
TEXT REPRESENTATION (22P02) error?

B) While the JDBC drivers are documented to be backward compatible with
older back-ends, is there anything that would make it obviously unsafe
for me to go the other way round, using the 8.1 JDBC driver with the
8.2.4 back-end?  Although this doesn't seem to be a viable permanent
solution, for the time being I have no working alternative for PG 8.2.4.

Thanks in advance,
Eric Faulhaber

>
> So, my questions:
>
> A) Can anyone think what might have changed between the 8.1-408 and
> 8.2-506 versions of the JDBC driver which might result in an
> INVALID TEXT REPRESENTATION (22P02) error?
I seem to recall the backend becoming more restrictive on valid UTF
sequences. However that doesn't make sense if an 8.1 driver does
work. Any chance we can get the server logs ?
>
> B) While the JDBC drivers are documented to be backward compatible
> with older back-ends, is there anything that would make it
> obviously unsafe for me to go the other way round, using the 8.1
> JDBC driver with the 8.2.4 back-end?  Although this doesn't seem to
> be a viable permanent solution, for the time being I have no
> working alternative for PG 8.2.4.
>
Iyou can do this if the code is just doing select/insert/update/
delete in other words nothing fancy.
> Thanks in advance,
> Eric Faulhaber
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
>               http://archives.postgresql.org

On Mon, 17 Sep 2007, Eric Faulhaber wrote:

> I recently upgraded from PG 8.1.8 to 8.2.4.  I made a corresponding move in
> JDBC driver versions from postgresql-8.1-408.jdbc3.jar to
> postgresql-8.2-506.jdbc4.jar (binary distributions in both cases).  During a
> lengthy import using Hibernate (yes, I realize it's not the most efficient
> mechanism for bulk import), I hit the following error:
>
> SEVERE: ERROR: invalid input syntax for type oid: ""
>
> Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into
> turnaround (turn_number, site, item, purchase_order_number,
> purchase_order_line, lot, serial_number, quantity_issued, expiration_date,
> id) values (0000XBJG, GSO, 0A0001H9L, 427190, 15, , , -14000.00000, NULL,
> 59657893) was aborted.  Call getNextException to see the cause.
> SEVERE: An SQLException was provoked by the following failure:
> java.lang.IllegalArgumentException: Can't change resolved type for param: 7
> from 1043 to 26
> ....

We've seen this report once before, but weren't able to get to the bottom
of it because it also occurred on a large dataset.

http://archives.postgresql.org/pgsql-jdbc/2007-06/threads.php#00041

In his case int4 and int8 were getting mixed up which is a little more
understandable, in your case it's confusing varchar and oid which seems
less likely.  Is there any chance you can run this with the URL parameter
loglevel=2, which will produce tons of logging information, or can you
make this test case available to me?

Kris Jurka

Kris Jurka wrote:
>
>
> On Mon, 17 Sep 2007, Eric Faulhaber wrote:
>
>> I recently upgraded from PG 8.1.8 to 8.2.4.  I made a corresponding
>> move in JDBC driver versions from postgresql-8.1-408.jdbc3.jar to
>> postgresql-8.2-506.jdbc4.jar (binary distributions in both cases).
>> During a lengthy import using Hibernate (yes, I realize it's not the
>> most efficient mechanism for bulk import), I hit the following error:
>>
>> SEVERE: ERROR: invalid input syntax for type oid: ""
>>
>> Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into
>> turnaround (turn_number, site, item, purchase_order_number,
>> purchase_order_line, lot, serial_number, quantity_issued,
>> expiration_date, id) values (0000XBJG, GSO, 0A0001H9L, 427190, 15, ,
>> , -14000.00000, NULL, 59657893) was aborted.  Call getNextException
>> to see the cause.
>> SEVERE: An SQLException was provoked by the following failure:
>> java.lang.IllegalArgumentException: Can't change resolved type for
>> param: 7 from 1043 to 26
>> ....
>
> We've seen this report once before, but weren't able to get to the
> bottom of it because it also occurred on a large dataset.
>
> http://archives.postgresql.org/pgsql-jdbc/2007-06/threads.php#00041

Yes, before posting I googled the error message and found part of this
discussion, as well as the resulting change to the error message in
SimpleParameterList.java.

>
> In his case int4 and int8 were getting mixed up which is a little more
> understandable, in your case it's confusing varchar and oid which
> seems less likely.

Any idea what component is mixing up these types?  As I understand it
from setting a breakpoint at the point the exception is thrown and
tracking back through the stack, the OID type (26) is reported by the
back-end and is compared with the type the driver expects for the given
parameter.  But then I wonder why we would not see this error with the
same back-end and the older JDBC driver...

>   Is there any chance you can run this with the URL parameter
> loglevel=2, which will produce tons of logging information, or can you
> make this test case available to me?

OK, I generated the debug log file (>1.4GB).  How do I get this to you?
Even the relevant portions alone are probably too long to inline in a
message to the list.

>
> Kris Jurka
>
>

Thanks,
Eric Faulhaber

Dave Cramer wrote:
>>
>> So, my questions:
>>
>> A) Can anyone think what might have changed between the 8.1-408 and
>> 8.2-506 versions of the JDBC driver which might result in an INVALID
>> TEXT REPRESENTATION (22P02) error?
> I seem to recall the backend becoming more restrictive on valid UTF
> sequences.

The particular parameter on which the error is being reported is an
empty string, going into a column of type text.  BTW, the database is
encoded as LATIN1.

> However that doesn't make sense if an 8.1 driver does work.

Agreed.

> Any chance we can get the server logs ?

I am sending a client log (debug=2) to Kris Jurka.  What level of
debugging would you need to see in the server logs?

Thanks,
Eric Faulhaber

On Tue, 18 Sep 2007, Eric Faulhaber wrote:

> Any idea what component is mixing up these types?  As I understand it from
> setting a breakpoint at the point the exception is thrown and tracking back
> through the stack, the OID type (26) is reported by the back-end and is
> compared with the type the driver expects for the given parameter.  But then
> I wonder why we would not see this error with the same back-end and the older
> JDBC driver...

Basically you have two text columns in your table (lot and serial_number)
that alternate between backend type oids 1043 (varchar) and 26 (oid).
This is most likely because hibernate sometimes calls setClob and
sometimes it calls setString for these columns.  Additionally you have
something that is setting an unknown type in the driver that the server
must resolve.  This could be something like setNull(x, Types.OTHER),
setObject(x, null), or by using the URL parameter stringtype=unspecified.
An unspecified type is common when using timestamps, but you aren't using
any in this table.

So what's going on is, as you work through the rows you want to insert the
types of these columns occasionally changes and a the driver must reparse
a new server side prepared statement to handle the new type.  Some time
after the new server side statement has been setup we get an unspecified
type and we ask the server to tell us what type we should really use.  The
server responds with a new type for something we don't think should have
changed and we get an error.

Consider this set of events:

Server Has    Current Data    Action
nothing yet    1043, 26    No server statement yet, parse
1043, 26    1043, 26    server matches, execute away
1043, 26    1043, 1043    server doesn't match, reparse
1043, 1043    1043, 0        0 matches, so don't reparse, but describe

So we are passed an unknown type and we ask the server to resolve it.
When we get the describe answer back we set it on the data, overwriting
the 0 with the returned 1043.  So that's all legal and expected behavior,
but for some reason in your case.

So one potential solution (and optimization) is to avoid the describe if
we already have a prepared statement with type information filled in.  We
expect the backend to just echo back what the statement was prepared with,
but what's the point when we have that already have that information in
the driver?  So this would likely avoid your problem, but it doesn't
explain what's going on...

I diffed the 8.1-408 release with 8.3dev for the core/v3 directory and the
only relevant change is SimpleParameterList#bind.  When deciding to
overwrite an existing type we now add a check for NULL_OBJECT that 8.1
does not have:

if (oid == Oid.UNSPECIFIED && paramTypes[index] != Oid.UNSPECIFIED &&
value == NULL_OBJECT)
             return;

I know I haven't described this well, especially for people who aren't
versed in the frontend/backend protocol and how the driver issues queries,
but I must admit I have no idea why this is failing.  There is a potential
workaround, but it doesn't explain the root cause.  I'll keep
investigating though...

1) Are you using stringtype=unspecified in your URL?

2) Any idea why these two columns are sometimes interpreted as strings and
sometimes as Clobs?  It doesn't look to be the case with the other text
fields in your table.

3) The log file you sent me says: "Using 2 threads for import".  Could you
elaborate on what the different threads are doing?  Any chance they're
using the same Connection and somehow interfering with each other?

Kris Jurka

Kris Jurka wrote:
>
>
> On Tue, 18 Sep 2007, Eric Faulhaber wrote:
>
>> Any idea what component is mixing up these types?  As I understand it
>> from setting a breakpoint at the point the exception is thrown and
>> tracking back through the stack, the OID type (26) is reported by the
>> back-end and is compared with the type the driver expects for the
>> given parameter.  But then I wonder why we would not see this error
>> with the same back-end and the older JDBC driver...
>
> Basically you have two text columns in your table (lot and
> serial_number) that alternate between backend type oids 1043 (varchar)
> and 26 (oid). This is most likely because hibernate sometimes calls
> setClob and sometimes it calls setString for these columns.
> Additionally you have something that is setting an unknown type in the
> driver that the server must resolve.  This could be something like
> setNull(x, Types.OTHER), setObject(x, null), or by using the URL
> parameter stringtype=unspecified. An unspecified type is common when
> using timestamps, but you aren't using any in this table.

What in the log file is indicating the use of an unspecified type to
you?  I'd like to investigate this further.

>
> So what's going on is, as you work through the rows you want to insert
> the types of these columns occasionally changes and a the driver must
> reparse a new server side prepared statement to handle the new type.
> Some time after the new server side statement has been setup we get an
> unspecified type and we ask the server to tell us what type we should
> really use.  The server responds with a new type for something we
> don't think should have changed and we get an error.
>
> Consider this set of events:
>
> Server Has    Current Data    Action
> nothing yet    1043, 26    No server statement yet, parse
> 1043, 26    1043, 26    server matches, execute away
> 1043, 26    1043, 1043    server doesn't match, reparse
> 1043, 1043    1043, 0        0 matches, so don't reparse, but describe
>
> So we are passed an unknown type and we ask the server to resolve it.
> When we get the describe answer back we set it on the data,
> overwriting the 0 with the returned 1043.  So that's all legal and
> expected behavior, but for some reason in your case.
>
> So one potential solution (and optimization) is to avoid the describe
> if we already have a prepared statement with type information filled
> in.  We expect the backend to just echo back what the statement was
> prepared with, but what's the point when we have that already have
> that information in the driver?  So this would likely avoid your
> problem, but it doesn't explain what's going on...
>
> I diffed the 8.1-408 release with 8.3dev for the core/v3 directory and
> the only relevant change is SimpleParameterList#bind.  When deciding
> to overwrite an existing type we now add a check for NULL_OBJECT that
> 8.1 does not have:
>
> if (oid == Oid.UNSPECIFIED && paramTypes[index] != Oid.UNSPECIFIED &&
> value == NULL_OBJECT)
>             return;
>
> I know I haven't described this well, especially for people who aren't
> versed in the frontend/backend protocol and how the driver issues
> queries, but I must admit I have no idea why this is failing.  There
> is a potential workaround, but it doesn't explain the root cause.
> I'll keep investigating though...

Many thanks for a deep look into the log file and for a detailed
description of what is going on.  Your analysis has given me some great
insight which has led to a possible solution (see below).  Nevertheless,
I'd still be interested to find out what triggered this change in
behavior from version to version given my use case.

>
> 1) Are you using stringtype=unspecified in your URL?

No.

>
> 2) Any idea why these two columns are sometimes interpreted as strings
> and sometimes as Clobs?  It doesn't look to be the case with the other
> text fields in your table.

Yes, this is caused by our implementation of custom Hibernate types.  We
map standard SQL types to custom Java data type wrappers due to specific
runtime requirements.  We leverage Hibernate's UserType facility for
this, which requires that we implement the code to serialize Java data
objects to and from JDBC via an instance of either PreparedStatement
(to) or ResultSet (from) handed to us by Hibernate at the appropriate times.

Note that our string columns are defined as text rather than character
varying(n).  This is because we don't know how wide the string data we
will be expected to handle can be.  Because the PG docs claim there is
no performance disadvantage to using text vs. character varying, we go
with text in all cases, thereby avoiding the headache of determining a
max width for varchar columns.

As a result, our custom user type for string data publishes its
corresponding JDBC type as Types.CLOB.  This was a somewhat arbitrary
(and in retrospect, probably bad) decision, intended to match
Hibernate's PostgreSQLDialect's mapping of Types.CLOB to PG's text
type.  In the code which serializes data to JDBC, we need to handle the
possibility of the data being unknown at runtime.  If the data is known,
we use PreparedStatement.setString(index, "data"), which evidently uses
Types.VARCHAR.  If unknown, we instead use
PreparedStatement.setNull(index, Types.CLOB).

This explains why we sometimes get strings and sometimes Clobs, but
where the unspecified type comes from, I have no idea.  The only way
data is imported is via the mechanism described above:  a
PreparedStatement INSERT which Hibernate generates, into which we set
positional parameters.  For this table, we would use only the following
PreparedStatement methods:

setString(int, java.lang.String) --> for text data
setInt(int, int) --> for integer data
setBigDecimal(int, java.lang.BigDecimal) --> for numeric data
setDate(int, java.sql.Date) --> for date data
setNull(int, int) --> for unknown value, where the second parm is
Types.CLOB, Types.INTEGER, Types.NUMERIC, or Types.DATE, as appropriate

We never use setNull(x, Types.OTHER) nor setObject(x, null).

Interestingly, if I publish either VARCHAR or LONGVARCHAR as the JDBC
type associated with my custom user type for text, the problem no longer
occurs.  This effectively changes the second parameter in the
PreparedStatement.setNull(int, int) call from CLOB to
VARCHAR/LONGVARCHAR.  I'll have to re-run the full import over the
weekend to see if this has any repercussions with other tables.  Also,
I'll have to do a lot of regression testing of our runtime to see if
this impacts anything else, as I'm not familiar enough with all the
places Hibernate may use this information.

>
> 3) The log file you sent me says: "Using 2 threads for import".  Could
> you elaborate on what the different threads are doing?  Any chance
> they're using the same Connection and somehow interfering with each
> other?

Each table is imported on a dedicated thread.  So, despite the log
message, only one thread was running in this case, since only one table
was being imported.  The second thread was never dispatched.  Normally,
we import a large number of tables, so the distribution of work is more
efficient than in this case.  So, no, Connection instances are never
shared across threads.

Thanks,
Eric Faulhaber

On Thu, 20 Sep 2007, Eric Faulhaber wrote:

> What in the log file is indicating the use of an unspecified type to you?
> I'd like to investigate this further.

Whenever you see a DescribeStatement message that means the parameters
you've supplied for that row have at least one unresolved type.

21:29:08.469 (3)  FE=> Describe(statement=S_19)

The normal describe message is for describing a portal, meaning just the
resultset info while a statement describe will return information on what
parameter types the server side statement expects.

> Many thanks for a deep look into the log file and for a detailed description
> of what is going on.  Your analysis has given me some great insight which has
> led to a possible solution (see below).  Nevertheless, I'd still be
> interested to find out what triggered this change in behavior from version to
> version given my use case.
>

OK, I've got two approaches to figure out what's going on:

1) More type logging information.  This tries to figure our why we're
sending DescribeStatement and shows all the type info that goes into that
decision.  It also logs the results of DescribeStatement and when there is
a conflict the error now contains all the type info from before and after
the conflict.

2) Where's the unspecified type coming from?  I've put in a hack to the
driver to throw an exception when the first unspecified type is set which
should hopefully provide enough information to track it back to your
application.  Unspecified types are perfectly legal, so this isn't a real
problem, but it may be informational.


I've put up jar files and associated patches here:

http://www.ejurka.com/pgsql/jars/ecf/

For the unspecified type, the stacktrace alone should be fine.  For the
logging information, please rerun with loglevel=2 and upload just the last
10k lines of the file.

Kris Jurka

Kris Jurka wrote:
> 2) Where's the unspecified type coming from?  I've put in a hack to
> the driver to throw an exception when the first unspecified type is
> set which should hopefully provide enough information to track it back
> to your application.  Unspecified types are perfectly legal, so this
> isn't a real problem, but it may be informational.

I turned on some additional logging in our code to see what data is
being bound to each parameter in our UserType implementation.  It seems
the unspecified type is coming from a Date object bound with
PreparedStatement.setDate(int, java.sql.Date).  At least, this is the
first parameter that triggers the test.

...
Sep 20, 2007 2:30:04 PM
com.goldencode.p2j.persist.AbstractWrapperUserType nullSafeSet
FINEST: binding '11/30/04' to parameter: 9
Sep 20, 2007 2:30:04 PM com.goldencode.p2j.schema.ImportWorker$Library
importTable
SEVERE: Error processing import data from
/home/ecf/dump/export/gso/turnarnd.d;  100 of ? record(s) successfully
processed;  0 record(s) uncommitted due to this error;  0 record(s) dropped
java.lang.IllegalArgumentException: Unspecified type comes from here,
parameter: 9
        at
org.postgresql.core.v3.SimpleParameterList.bind(SimpleParameterList.java:68)
        at
org.postgresql.core.v3.SimpleParameterList.setStringParameter(SimpleParameterList.java:120)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.bindString(AbstractJdbc2Statement.java:2119)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.setDate(AbstractJdbc2Statement.java:3015)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.setDate(AbstractJdbc2Statement.java:1296)
        at
com.goldencode.p2j.persist.DateUserType.bindNonNull(DateUserType.java:159)
        at
com.goldencode.p2j.persist.AbstractWrapperUserType.nullSafeSet(AbstractWrapperUserType.java:263)
        at
com.goldencode.p2j.persist.DateUserType.nullSafeSet(DateUserType.java:39)
        at org.hibernate.type.CustomType.nullSafeSet(CustomType.java:141)
        at
org.hibernate.persister.entity.BasicEntityPersister.dehydrate(BasicEntityPersister.java:1617)
        at
org.hibernate.persister.entity.BasicEntityPersister.dehydrate(BasicEntityPersister.java:1594)
        at
org.hibernate.persister.entity.BasicEntityPersister.insert(BasicEntityPersister.java:1850)
        at
org.hibernate.persister.entity.BasicEntityPersister.insert(BasicEntityPersister.java:2200)
        at
org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:46)
        at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:239)
        at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:223)
        at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:136)
        at
org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:274)
        at
org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:730)
        at
com.goldencode.p2j.schema.ImportWorker$Library.importTable(ImportWorker.java:710)
        at
com.goldencode.p2j.schema.ImportWorker$Library$1.run(ImportWorker.java:1020)
        at java.lang.Thread.run(Thread.java:619)
...

A number of previous inserts contained "unknown" dates.  These were
bound with PreparedStatement.setNull(index, Types.DATE) before the test
was tripped by the PreparedStatement.setDate(index, date) in the stack
trace above.

I will run with the enhanced logging patch and upload results shortly.

Thanks,
Eric Faulhaber

Eric Faulhaber wrote:
> Kris Jurka wrote:
>> 2) Where's the unspecified type coming from?  I've put in a hack to
>> the driver to throw an exception when the first unspecified type is
>> set which should hopefully provide enough information to track it
>> back to your application.  Unspecified types are perfectly legal, so
>> this isn't a real problem, but it may be informational.
>
> I turned on some additional logging in our code to see what data is
> being bound to each parameter in our UserType implementation.  It
> seems the unspecified type is coming from a Date object bound with
> PreparedStatement.setDate(int, java.sql.Date).  At least, this is the
> first parameter that triggers the test.

How relevant is the following change to this mystery?  This is an
excerpt from a diff of AbstractJdbc2Statement between the versions we've
been discussing, specifically, the internals of the setDate(int, Date,
Calendar) method:

---
postgresql-jdbc-8.1-408.src/org/postgresql/jdbc2/AbstractJdbc2Statement.java
2006-11-05 00:44:44.000000000 -0500
+++
postgresql-jdbc-8.2-506.src/org/postgresql/jdbc2/AbstractJdbc2Statement.java
2007-07-27 05:01:53.000000000 -0400

...

@@ -2897,7 +2919,7 @@
        if (cal != null)
            cal = (Calendar)cal.clone();

-        // We must use INVALID here, or inserting a Date-with-timezone
into a
+        // We must use UNSPECIFIED here, or inserting a
Date-with-timezone into a
        // timestamptz field does an unexpected rotation by the server's
TimeZone:
        //
        // We want to interpret 2005/01/01 with calendar +0100 as
@@ -2916,7 +2938,7 @@
        //  2005-01-01 00:00:00+03
        // (1 row)

-        bindString(i, connection.getTimestampUtils().toString(cal, d),
Oid.INVALID);
+        bindString(i, connection.getTimestampUtils().toString(cal, d),
Oid.UNSPECIFIED);
    }

    public void setTime(int i, Time t, java.util.Calendar cal) throws
SQLException
...

I mean, it obviously explains where the unspecified type is coming from,
but how likely is that to trigger the FE/BE type mismatch we're seeing
many records later?

Thanks,
Eric Faulhaber

On Thu, 20 Sep 2007, Eric Faulhaber wrote:

> Eric Faulhaber wrote:
>> Kris Jurka wrote:
>>> 2) Where's the unspecified type coming from?  I've put in a hack to the
>>> driver to throw an exception when the first unspecified type is set which
>>> should hopefully provide enough information to track it back to your
>>> application.  Unspecified types are perfectly legal, so this isn't a real
>>> problem, but it may be informational.
>>
>> I turned on some additional logging in our code to see what data is being
>> bound to each parameter in our UserType implementation.  It seems the
>> unspecified type is coming from a Date object bound with
>> PreparedStatement.setDate(int, java.sql.Date).  At least, this is the first
>> parameter that triggers the test.

I had forgotten that we treated dates like timestamps, so this is the
cause.  We can't be sure what the underlying type for a java.sql.Timestamp
object is because on the server side we have timestamps with and without
timezones and if you pick the wrong type you can get an incorrect timezone
shift, so we've got to use unspecified to let the server determine the
correct type.  I'm not sure if Date needs the same treatment because you
would expect a date column on the server, but mismatching these is
something people do frequently, so I'm hesitant to make any changes here
without a lot more thought about how date works.  But again this can't be
the real problem/fix because this has to work like this if your column was
a timestamp type.

> How relevant is the following change to this mystery?  This is an excerpt
> from a diff of AbstractJdbc2Statement between the versions we've been
> discussing, specifically, the internals of the setDate(int, Date, Calendar)
> method:

That's just a rename.  See here:

http://gborg.postgresql.org/cgi-bin/cvsweb.cgi/pgjdbc/org/postgresql/core/Oid.java.diff?r1=1.9;r2=1.10;cvsroot=pgjdbc

> I mean, it obviously explains where the unspecified type is coming from, but
> how likely is that to trigger the FE/BE type mismatch we're seeing many
> records later?
>

It shouldn't cause a mismatch.  The fact that we have an unspecified type
causes the describe statement which then triggers the verification that we
got the same types back from the server that we have in our parameters, so
it triggers the failure, but it is not the real problem.  The verification
check specifically skips unspecified types (oid=0) and if you'll recall
your error message was a conflict between 1043 and 26, so no oid=0 there
at all.

Kris Jurka

On Thu, 20 Sep 2007, Kris Jurka wrote:

> For the logging information, please rerun with loglevel=2 and upload
> just the last 10k lines of the file.
>

OK, with that info I'v finally managed to generate a reproducible test
case (attached).  What happens is the driver sends:

Parse S_1
Describe S_1
Parse S_2
Sync

and when we get the results of S_1's describe we assign it to S_2
because there's only one active query at any time.  So we've prepared
S_2 with one set of parameters, but now it thinks it was prepared with
S_1's.  So next time we do:

Describe S_2
Sync

We get describe results which come from the server and have what S_2 was
parsed with and that doesn't match up with what the driver has for S_2 and
it bails out.

So the fix is probably to check that we aren't setting type information
from stale results, but this is a pretty complicated area, so I'd like to
study it a little more.

In any case, thanks for your help in tracking this one down.

Kris Jurka

Kris Jurka wrote:
> So the fix is probably to check that we aren't setting type
> information from stale results, but this is a pretty complicated area,
> so I'd like to study it a little more.
>
> In any case, thanks for your help in tracking this one down.

No problem, thanks to you for your responsiveness and for your
commitment to this project.  Let me know if there's anything more I can
do to assist;  testing a patch, more logging, etc.

Regards,
Eric Faulhaber

On Fri, 21 Sep 2007, Kris Jurka wrote:

> So the fix is probably to check that we aren't setting type information from
> stale results, but this is a pretty complicated area, so I'd like to study it
> a little more.
>

OK, I've committed a fix for 8.1, 8.2, and 8.3-dev to the CVS repository.
It simply checks that the describe results match the currently parsed
query before applying them.  There is still an optimization to be made
here, in that we don't need to describe at all if the Query has all the
needed type informtion already, but I'll leave that for later.

Kris Jurka

Kris Jurka wrote:
> OK, I've committed a fix for 8.1, 8.2, and 8.3-dev to the CVS
> repository. It simply checks that the describe results match the
> currently parsed query before applying them.  There is still an
> optimization to be made here, in that we don't need to describe at all
> if the Query has all the needed type informtion already, but I'll
> leave that for later.

I checked out the code from CVS and rebuilt with the following
build.local.properties:

major=8
minor=2
fullversion=8.2
def_pgport=5432
enable_debug=yes

Assuming the above is OK, this fix resolves the issue in my use case.
Thanks, Kris!

Any idea when this might make it into an official build?

Regards,
Eric Faulhaber

On Mon, 24 Sep 2007, Eric Faulhaber wrote:

> I checked out the code from CVS and rebuilt with the following
> build.local.properties:
>
> major=8
> minor=2
> fullversion=8.2
> def_pgport=5432
> enable_debug=yes
>
> Assuming the above is OK, this fix resolves the issue in my use case.
>

Overriding the version numbers isn't all that wise.  If you want a 8.2
driver version you should check out the REL8_2_STABLE branch and you'll
get a 8.2 driver, not a 8.3-dev relabled to 8.2.

> Any idea when this might make it into an official build?
>

There are no immediate plans for a release.  I'll probably put out new
versions after making some headway against our patch backlog, but I don't
dare speculate when I'll get to that.

Kris Jurka