BUG #2686: 8.2beta1 restarts given query - Mailing list pgsql-bugs

The following bug has been logged online:

Bug reference:      2686
Logged by:          Per Jensen
Email address:      per2jensen@gmail.com
PostgreSQL version: 8.2beta1
Operating system:   SuSE 8.0
Description:        8.2beta1 restarts given query
Details:

Have tried to send bugreport to pgsql-bugs@postgresql.org with no success,
if they get through I am sorry to spam the list.

---

Bughunters,

I am testing the 8.2beta1 server with a pg_dump/restore from a debian
production sarge-PG74 instance.

When the dump is restored to a test PG-8.1.3 my application works nicely
(have not upgraded the production server though).

When the same dump is restored to a PG-8.2beta1 some queries succeed and
others fail. The server *restarts* as can be seen from the server
logfile below.

The database is accessed through iBatis version 1.3.1 --> jakarta DBCP
1.2.1

JDBC driver used: postgresql-8.2dev-503.jdbc3.jar' downloaded from
'jdbc.postgresql.org'.

JVM: java full version "1.5.0-b64"

PG-8.2beta1 is built from source with this configure command:
 '$ ./configure --prefix=/srv/pg-8.2.0.beta1 --with-zlib' (from config.log)

 Version from version():
 ------------------------------
 Welcome to psql 8.2beta1, the PostgreSQL interactive terminal.

 Type:  \copyright for distribution terms
       \h for help with SQL commands
       \? for help with psql commands
       \g or terminate with semicolon to execute query
       \q to quit

 XXXX=> select version();
 LOG:  statement: BEGIN
 LOG:  statement: select version();
                                 version
 -------------------------------------------------------------------------
 PostgreSQL 8.2beta1 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 3.2
 (1 row)




 Locales:
 -----------
Locale used in initdb command on 8.2.beta1: LATIN1
Locale used in createdb command on test db: LATIN1
Locale used in production db: LATIN1

 Table description:
 -----------------------
                                              Table "booking.booking"
       Column       |           Type           |
      Modifiers
 --------------------+--------------------------+---------------------------
----------------------------------------
 id                 | integer                  | not null default
nextval(('booking.booking_seq'::text)::regclass)
 customer_id        | integer                  | not null
 type               | integer                  | not null
 fromtime           | timestamp with time zone | not null
 totime             | timestamp with time zone | not null
 contact            | character varying(255)   |
 comment            | character varying(2000)  |
 driver             | character varying(255)   |
 last_updated       | timestamp with time zone | not null
 sms_last_sent      | timestamp with time zone |
 location           | character varying(255)   |
 sms_sent           | boolean                  | not null
 deleted            | boolean                  | not null
 regular            | boolean                  | not null
 express_booking_id | integer                  |
 Indexes:
    "booking_pkey" PRIMARY KEY, btree (id)
    "booking_customer_id_idx" btree (customer_id)
    "booking_express_booking_id_idx" btree (express_booking_id)
    "booking_fromtime_idx" btree (fromtime)
    "booking_totime_idx" btree (totime)
 Foreign-key constraints:
    "fk_booking_customer_id" FOREIGN KEY (customer_id) REFERENCES
customer(id)
    "fk_booking_pickup_type" FOREIGN KEY ("type") REFERENCES enum_value(id)
 Triggers:
    tr_after_update AFTER UPDATE ON booking.booking FOR EACH ROW
EXECUTE PROCEDURE tr_maintain_pickup_status()


 Query as logged on client:
 ---------------------------------
 DEBUG 2006-10-10 13:31:56,481 PreparedStatement - {pstm-101012}
PreparedStatement:    select distinct id, customer_id,
express_booking_id, type, fromtime, totime, contact, comment, driver,
sms_sent, regular, deleted, last_updated, sms_last_sent, location
from   (     select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location     from booking.booking, public.customer
 WHERE     booking.booking.customer_id = public.customer.id
AND               fromtime >= ?             AND               totime
<= ?             AND                     customer.zip < '5000'
                  UNION     select public.customer.name,
booking.booking.id as id, customer_id, express_booking_id, type,
fromtime, totime, contact, comment, driver, sms_sent, regular,
deleted, last_updated, sms_last_sent, location     from
booking.booking, public.customer        WHERE
booking.booking.customer_id = public.customer.id         AND
   fromtime >= ?             AND               totime <= ?
 AND                     customer.zip >= '5000'
    ) as subselect
 DEBUG 2006-10-10 13:31:56,481 PreparedStatement - {pstm-101012}
Parameters: [2006-10-10 00:00:00.0, 2006-10-10 23:59:59.0, 2006-10-10
00:00:00.0, 2006-10-10 23:59:59.0]
 DEBUG 2006-10-10 13:31:56,482 PreparedStatement - {pstm-101012}
Types: [java.sql.Timestamp, java.sql.Timestamp, java.sql.Timestamp,
java.sql.Timestamp]



 Query as logged on server:
 -----------------------------------
 This logsnip is from the working 8.1.3 instance because the 8.2beta1 does
not log the query before crash.

 <snip>
 LOG:  statement: PREPARE <unnamed> AS SET SESSION CHARACTERISTICS AS
TRANSACTION ISOLATION LEVEL SERIALIZABLE
 LOG:  statement: <BIND>
 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SET SESSION
CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE]
 LOG:  statement: <BIND>
 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
 LOG:  statement: PREPARE <unnamed> AS
                select distinct id, customer_id, express_booking_id,
type, fromtime, totime, contact, comment, driver, sms_sent, regular,
deleted, last_updated, sms_last_sent, location
                from
                (
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= $1
                 AND
                   totime <= $2
                 AND

                          customer.zip < '5000'



        UNION
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= $3
                 AND
                   totime <= $4
                 AND

                          customer.zip >= '5000'



                ) as subselect

 LOG:  statement: <BIND>
 LOG:  statement: EXECUTE <unnamed>  [PREPARE:
                select distinct id, customer_id, express_booking_id,
type, fromtime, totime, contact, comment, driver, sms_sent, regular,
deleted, last_updated, sms_last_sent, location
                from
                (
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= $1
                 AND
                   totime <= $2
                 AND

                          customer.zip < '5000'



        UNION
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= $3
                 AND
                   totime <= $4
                 AND

                          customer.zip >= '5000'



                ) as subselect
           ]
 LOG:  statement: <BIND>
 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  ROLLBACK]

 </snip>

 It seems the queries are sent twice, must look into that later.


 Same query in psql:
 --------------------------
The query is successfull in psql and returns 63 rows

         select distinct id, customer_id, express_booking_id, type,
fromtime, totime, contact, comment, driver, sms_sent, regular,
deleted, last_updated, sms_last_sent, location
                from
                (
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= '2006-10-10 00:00:00'
                 AND
                   totime <= '2006-10-10 23:59:59'
                 AND

                          customer.zip < '5000'

        UNION
            select public.customer.name, booking.booking.id as id,
customer_id, express_booking_id, type, fromtime, totime, contact,
comment, driver, sms_sent, regular, deleted, last_updated,
sms_last_sent, location
            from booking.booking, public.customer
               WHERE
                        booking.booking.customer_id = public.customer.id
                AND
                   fromtime >= '2006-10-10 00:00:00'
                 AND
                   totime <= '2006-10-10 23:59:59'
                 AND

                          customer.zip >= '5000'
                ) as subselect





 The error in the client log is:
 --------------------------------------
 Caused by: java.io.EOFException
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:258)
        at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.ja
va:1164)
        at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:190)

        at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.j
ava:452)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2St
atement.java:354)
        at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statem
ent.java:258)
        at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingP
reparedStatement.java:92)
        at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at
com.ibatis.db.jdbc.logging.PreparedStatementLogProxy.invoke(Unknown
Source)
        at $Proxy1.executeQuery(Unknown Source)
        ... 56 more



 The error in server log is:
 --------------------------------
 LOG:  execute <unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION
ISOLATION LEVEL SERIALIZABLE
 LOG:  execute S_1: BEGIN
 LOG:  server process (PID 23573) was terminated by signal 11
 LOG:  terminating any other active server processes
 WARNING:  terminating connection because of crash of another server
process
 DETAIL:  The postmaster has commanded this server process to roll
back the current transaction and exit, because another server process
exited abnormally and possibly corrupted shared memory.
 HINT:  In a moment you should be able to reconnect to the database
and repeat your command.
 LOG:  all server processes terminated; reinitializing
 LOG:  database system was interrupted at 2006-10-10 13:42:34 CEST
 LOG:  checkpoint record is at 0/5240B8CC
 LOG:  redo record is at 0/5240B8CC; undo record is at 0/0; shutdown TRUE
 LOG:  next transaction ID: 0/143146; next OID: 6644019
 LOG:  next MultiXactId: 1; next MultiXactOffset: 0
 LOG:  database system was not properly shut down; automatic recovery
in progress
 LOG:  connection received: host=::ffff:127.0.0.1 port=33904
 FATAL:  the database system is starting up
 LOG:  redo starts at 0/5240B914
 LOG:  record with zero length at 0/5240F9FC
 LOG:  redo done at 0/5240F9D4
 LOG:  database system is ready
 LOG:  transaction ID wrap limit is 2147484172, limited by database
"postgres"

 The 8.2beta1 server does not log the query before it crashes




 Feel free to ask more information if this bugreport is useful to you.

 Thank you for a great database !

 Regards
 Per Jensen