Re: [HACKERS] server process (PID 1188) exited with exit code

Hi,

I have a query that throws "org.postgresql.util.PSQLException: An I/O error
occured while sending to the backend". Here is a simplified version of it
where I used pg_database, but any table or view do the same.

PreparedStatement pstmt = connection.prepareStatement("select ? from (select
* from pg_database) t");
pstmt.setObject(1, 1);
ResultSet rs = pstmt.executeQuery();

It restarts PostgreSQL with this in the Log
2006-10-24 15:35:38 LOG: server process (PID 1188) exited with exit code
-1073741819
2006-10-24 15:35:38 LOG: terminating any other active server processes
2006-10-24 15:35:38 LOG: all server processes terminated; reinitializing
2006-10-24 15:35:39 LOG: database system was interrupted at 2006-10-24
15:34:54 Eastern Standard Time
2006-10-24 15:35:39 LOG: Windows fopen("recovery.conf","r") failed: code 2,
errno 2
2006-10-24 15:35:39 LOG: Windows fopen("pg_xlog/00000001.history","r")
failed: code 2, errno 2
2006-10-24 15:35:39 LOG: Windows fopen("backup_label","r") failed: code 2,
errno 2
2006-10-24 15:35:39 LOG: checkpoint record is at 0/31FDF0A0
2006-10-24 15:35:39 LOG: redo record is at 0/31FDF0A0; undo record is at
0/0; shutdown TRUE
2006-10-24 15:35:39 LOG: next transaction ID: 0/22535; next OID: 101011
2006-10-24 15:35:39 LOG: next MultiXactId: 1; next MultiXactOffset: 0
2006-10-24 15:35:39 LOG: database system was not properly shut down;
automatic recovery in progress
2006-10-24 15:35:39 LOG: record with zero length at 0/31FDF0F0
2006-10-24 15:35:39 LOG: redo is not required
2006-10-24 15:35:40 LOG: database system is ready
2006-10-24 15:35:40 LOG: Windows fopen("global/pg_fsm.cache","rb") failed:
code 2, errno 2
2006-10-24 15:35:40 LOG: transaction ID wrap limit is 2147484172, limited
by database "postgres"
2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb") failed:
code 2, errno 2
2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb") failed:
code 2, errno 2

I am using PostgreSQL 8.2 beta1 on Windows XP, Service Pack 2
Both JDBC3 driver 8.1 build 407 and 8.2 build 503 do the same.

Thanks,
Jean-Pierre Pelletier
e-djuster

This is a server bug, I will post to hackers for you, it has little
to do with JDBC, however the ? can't be a column in a prepared statement

DAVE
On 24-Oct-06, at 4:45 PM, JEAN-PIERRE PELLETIER wrote:

> Hi,
>
> I have a query that throws "org.postgresql.util.PSQLException: An I/
> O error occured while sending to the backend". Here is a simplified
> version of it where I used pg_database, but any table or view do
> the same.
>
> PreparedStatement pstmt = connection.prepareStatement("select ?
> from (select * from pg_database) t");
> pstmt.setObject(1, 1);
> ResultSet rs = pstmt.executeQuery();
>
> It restarts PostgreSQL with this in the Log
> 2006-10-24 15:35:38 LOG: server process (PID 1188) exited with
> exit code -1073741819
> 2006-10-24 15:35:38 LOG: terminating any other active server
> processes
> 2006-10-24 15:35:38 LOG: all server processes terminated;
> reinitializing
> 2006-10-24 15:35:39 LOG: database system was interrupted at
> 2006-10-24 15:34:54 Eastern Standard Time
> 2006-10-24 15:35:39 LOG: Windows fopen("recovery.conf","r")
> failed: code 2, errno 2
> 2006-10-24 15:35:39 LOG: Windows fopen("pg_xlog/
> 00000001.history","r") failed: code 2, errno 2
> 2006-10-24 15:35:39 LOG: Windows fopen("backup_label","r") failed:
> code 2, errno 2
> 2006-10-24 15:35:39 LOG: checkpoint record is at 0/31FDF0A0
> 2006-10-24 15:35:39 LOG: redo record is at 0/31FDF0A0; undo record
> is at 0/0; shutdown TRUE
> 2006-10-24 15:35:39 LOG: next transaction ID: 0/22535; next OID:
> 101011
> 2006-10-24 15:35:39 LOG: next MultiXactId: 1; next MultiXactOffset: 0
> 2006-10-24 15:35:39 LOG: database system was not properly shut
> down; automatic recovery in progress
> 2006-10-24 15:35:39 LOG: record with zero length at 0/31FDF0F0
> 2006-10-24 15:35:39 LOG: redo is not required
> 2006-10-24 15:35:40 LOG: database system is ready
> 2006-10-24 15:35:40 LOG: Windows fopen("global/pg_fsm.cache","rb")
> failed: code 2, errno 2
> 2006-10-24 15:35:40 LOG: transaction ID wrap limit is 2147484172,
> limited by database "postgres"
> 2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb")
> failed: code 2, errno 2
> 2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb")
> failed: code 2, errno 2
>
> I am using PostgreSQL 8.2 beta1 on Windows XP, Service Pack 2
> Both JDBC3 driver 8.1 build 407 and 8.2 build 503 do the same.
>
> Thanks,
> Jean-Pierre Pelletier
> e-djuster
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

In my real query the ? was used in the where clause,
I moved it to the select while trying to come with a simplified test case.

>From: Dave Cramer <pg(at)fastcrypt(dot)com>
>To: JEAN-PIERRE PELLETIER <pelletier_32(at)sympatico(dot)ca>
>CC: List <pgsql-jdbc(at)postgresql(dot)org>, PostgreSQL-development
><pgsql-hackers(at)postgreSQL(dot)org>
>Subject: Re: [JDBC] server process (PID 1188) exited with exit code
>-1073741819, 8.2 beta1
>Date: Tue, 24 Oct 2006 18:11:18 -0400
>
>This is a server bug, I will post to hackers for you, it has little to do
>with JDBC, however the ? can't be a column in a prepared statement
>
>DAVE
>On 24-Oct-06, at 4:45 PM, JEAN-PIERRE PELLETIER wrote:
>
>>Hi,
>>
>>I have a query that throws "org.postgresql.util.PSQLException: An I/ O
>>error occured while sending to the backend". Here is a simplified version
>>of it where I used pg_database, but any table or view do the same.
>>
>>PreparedStatement pstmt = connection.prepareStatement("select ? from
>>(select * from pg_database) t");
>>pstmt.setObject(1, 1);
>>ResultSet rs = pstmt.executeQuery();
>>
>>It restarts PostgreSQL with this in the Log
>>2006-10-24 15:35:38 LOG: server process (PID 1188) exited with exit code
>>-1073741819
>>2006-10-24 15:35:38 LOG: terminating any other active server processes
>>2006-10-24 15:35:38 LOG: all server processes terminated; reinitializing
>>2006-10-24 15:35:39 LOG: database system was interrupted at 2006-10-24
>>15:34:54 Eastern Standard Time
>>2006-10-24 15:35:39 LOG: Windows fopen("recovery.conf","r") failed: code
>>2, errno 2
>>2006-10-24 15:35:39 LOG: Windows fopen("pg_xlog/ 00000001.history","r")
>>failed: code 2, errno 2
>>2006-10-24 15:35:39 LOG: Windows fopen("backup_label","r") failed: code
>>2, errno 2
>>2006-10-24 15:35:39 LOG: checkpoint record is at 0/31FDF0A0
>>2006-10-24 15:35:39 LOG: redo record is at 0/31FDF0A0; undo record is at
>>0/0; shutdown TRUE
>>2006-10-24 15:35:39 LOG: next transaction ID: 0/22535; next OID: 101011
>>2006-10-24 15:35:39 LOG: next MultiXactId: 1; next MultiXactOffset: 0
>>2006-10-24 15:35:39 LOG: database system was not properly shut down;
>>automatic recovery in progress
>>2006-10-24 15:35:39 LOG: record with zero length at 0/31FDF0F0
>>2006-10-24 15:35:39 LOG: redo is not required
>>2006-10-24 15:35:40 LOG: database system is ready
>>2006-10-24 15:35:40 LOG: Windows fopen("global/pg_fsm.cache","rb")
>>failed: code 2, errno 2
>>2006-10-24 15:35:40 LOG: transaction ID wrap limit is 2147484172,
>>limited by database "postgres"
>>2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb")
>>failed: code 2, errno 2
>>2006-10-24 15:36:40 LOG: Windows fopen("global/pgstat.stat","rb")
>>failed: code 2, errno 2
>>
>>I am using PostgreSQL 8.2 beta1 on Windows XP, Service Pack 2
>>Both JDBC3 driver 8.1 build 407 and 8.2 build 503 do the same.
>>
>>Thanks,
>>Jean-Pierre Pelletier
>>e-djuster
>>
>>
>>
>>---------------------------(end of broadcast)---------------------------
>>TIP 6: explain analyze is your friend
>>
>
>
>---------------------------(end of broadcast)---------------------------
>TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match

Dave Cramer <pg(at)fastcrypt(dot)com> writes:
> This is a server bug, I will post to hackers for you,

Please provide a complete test case. I tried to reproduce the failure
in libpq, with

/* Here is our out-of-line parameter value */
paramValues[0] = "joe's place";

res = PQexecParams(conn,
"SELECT $1 FROM (select * from pg_database) t",
1, /* one param */
NULL, /* let the backend deduce param type */
paramValues,
NULL, /* don't need param lengths since text */
NULL, /* default to all text params */
0); /* ask for text results */

and got nothing worse than

SELECT failed: ERROR: could not determine data type of parameter $1

regards, tom lane

Tom Lane wrote:

> NULL, /* let the backend deduce param type */

I think the JDBC driver will be passing the int4 OID for the param type
in this case.

Best thing is probably for the OP to run with loglevel=2 and see exactly
what's being sent, though.

-O

Here is what I get with loglevel=2

08:47:18.718 (1) PostgreSQL 8.2devel JDBC3 with SSL (build 503)
08:47:18.718 (1) Trying to establish a protocol version 3 connection to
localhost:5432
08:47:18.859 (1) FE=> StartupPacket(user=postgres, database=main,
client_encoding=UNICODE, DateStyle=ISO)
08:47:19.218 (1) <=BE AuthenticationOk
08:47:19.234 (1) <=BE ParameterStatus(client_encoding = UNICODE)
08:47:19.234 (1) <=BE ParameterStatus(DateStyle = ISO, MDY)
08:47:19.234 (1) <=BE ParameterStatus(integer_datetimes = off)
08:47:19.234 (1) <=BE ParameterStatus(is_superuser = on)
08:47:19.234 (1) <=BE ParameterStatus(server_encoding = LATIN1)
08:47:19.234 (1) <=BE ParameterStatus(server_version = 8.2beta1)
08:47:19.234 (1) <=BE ParameterStatus(session_authorization = postgres)
08:47:19.234 (1) <=BE ParameterStatus(standard_conforming_strings = off)
08:47:19.234 (1) <=BE ParameterStatus(TimeZone = US/Eastern)
08:47:19.234 (1) <=BE BackendKeyData(pid=3248,ckey=166035706)
08:47:19.234 (1) <=BE ReadyForQuery(I)
08:47:19.234 (1) compatible = 8.2
08:47:19.234 (1) loglevel = 2
08:47:19.234 (1) prepare threshold = 5
getConnection returning
driver[className=org.postgresql.Driver,org(dot)postgresql(dot)Driver(at)747fa2]
08:47:19.296 (1) simple execute,
handler=org(dot)postgresql(dot)jdbc2(dot)AbstractJdbc2Statement$StatementResultHandler(at)18352d8,
maxRows=0, fetchSize=0, flags=17
08:47:19.296 (1) FE=> Parse(stmt=null,query="select $1 from (select * from
pg_database) t",oids={23})
08:47:19.296 (1) FE=> Bind(stmt=null,portal=null,$1=<1>)
08:47:19.296 (1) FE=> Describe(portal=null)
08:47:19.296 (1) FE=> Execute(portal=null,limit=0)
08:47:19.296 (1) FE=> Sync
08:47:19.718 (1) FE=> Terminate
08:47:19.718 (1) Discarding IOException on close:
java.net.SocketException: Connection reset by peer: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(Unknown Source)
at java.net.SocketOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.flush(Unknown Source)
at org.postgresql.core.PGStream.flush(PGStream.java:532)
at
org.postgresql.core.v3.ProtocolConnectionImpl.close(ProtocolConnectionImpl.java:131)
at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:215)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:452)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:354)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:258)
at org.apache.jsp.Test_jsp._jspService(Test_jsp.java:104)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:332)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at
org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:831)
at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1196)
at java.lang.Thread.run(Unknown Source)
org.postgresql.util.PSQLException: An I/O error occured while sending to the
backend.
at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:216)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:452)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:354)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:258)
at org.apache.jsp.Test_jsp._jspService(Test_jsp.java:104)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:332)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:314)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:264)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at
org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:831)
at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1196)
at java.lang.Thread.run(Unknown Source)
SQLException: SQLState(08006)

>From: Oliver Jowett <oliver(at)opencloud(dot)com>
>To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
>CC: Dave Cramer <pg(at)fastcrypt(dot)com>, JEAN-PIERRE PELLETIER
><pelletier_32(at)sympatico(dot)ca>, List <pgsql-jdbc(at)postgresql(dot)org>,
>PostgreSQL-development <pgsql-hackers(at)postgresql(dot)org>
>Subject: Re: [HACKERS] [JDBC] server process (PID 1188) exited with exit
>code
>Date: Wed, 25 Oct 2006 03:26:07 +0000
>
>Tom Lane wrote:
>
>> NULL, /* let the backend deduce param type */
>
>I think the JDBC driver will be passing the int4 OID for the param type in
>this case.
>
>Best thing is probably for the OP to run with loglevel=2 and see exactly
>what's being sent, though.
>
>-O
>
>---------------------------(end of broadcast)---------------------------
>TIP 1: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo(at)postgresql(dot)org so that your
> message can get through to the mailing list cleanly

"JEAN-PIERRE PELLETIER" <pelletier_32(at)sympatico(dot)ca> writes:
> 08:47:19.296 (1) FE=> Parse(stmt=null,query="select $1 from (select * from
> pg_database) t",oids={23})

Actually, now that I look closely, this command is almost certainly
triggering this beta1 bug:
http://archives.postgresql.org/pgsql-committers/2006-10/msg00107.php

Please try beta2 and see if it isn't fixed.

regards, tom lane

Yes, the problem is gone in 8.2 beta2.

Thanks all for an outstanding product and support,

Jean-Pierre Pelletier

>From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
>To: "JEAN-PIERRE PELLETIER" <pelletier_32(at)sympatico(dot)ca>
>CC: pgsql-hackers(at)postgresql(dot)org, pg(at)fastcrypt(dot)com, oliver(at)opencloud(dot)com
>Subject: Re: [HACKERS] [JDBC] server process (PID 1188) exited with exit
>code Date: Wed, 25 Oct 2006 10:15:03 -0400
>
>"JEAN-PIERRE PELLETIER" <pelletier_32(at)sympatico(dot)ca> writes:
> > 08:47:19.296 (1) FE=> Parse(stmt=null,query="select $1 from (select *
>from
> > pg_database) t",oids={23})
>
>Actually, now that I look closely, this command is almost certainly
>triggering this beta1 bug:
>http://archives.postgresql.org/pgsql-committers/2006-10/msg00107.php
>
>Please try beta2 and see if it isn't fixed.
>
> regards, tom lane

>> This is a server bug, I will post to hackers for you,
>
> Please provide a complete test case. I tried to reproduce the failure
> in libpq, with

tom, i've just noticed this is the exact same error message & errorcode as i
get when updating a table that contains a tsearch2 vector column

2006-10-25 20:08:42 [3420] LOG: 00000: server process (PID 2332) exited
with exit code -1073741819
2006-10-25 20:08:42 [3420] LOCATION: LogChildExit, postmaster.c:2385

(test case provided, see "Re: [BUGS] 8.2beta1 (w32): server process crash
(tsvector)" from oct. 17th)

maybe dave is also using tsearch2 in the involved tables, or is this a
general error code?

regards,
thomas

Dave Cramer <pg(at)fastcrypt(dot)com> writes:
> This is a server bug, I will post to hackers for you, it has little
> to do with JDBC, however the ? can't be a column in a prepared statement

I cannot reproduce any problem using what I think is equivalent in libpq:

/* Here is our out-of-line parameter value */
paramValues[0] = "1";

res = PQexecParams(conn,
"select $1 from (select * from pg_database) t",
1, /* one param */
NULL, /* let the backend deduce param type */
paramValues,
NULL, /* don't need param lengths since text */
NULL, /* default to all text params */
0); /* ask for text results */

This comes back with
ERROR: could not determine data type of parameter $1
but no crash. Is the JDBC driver doing anything interesting as a result
of the
pstmt.setObject(1, 1);
and if so what?

regards, tom lane

Tom Lane wrote:
> Dave Cramer <pg(at)fastcrypt(dot)com> writes:
>
>>This is a server bug, I will post to hackers for you, it has little
>>to do with JDBC, however the ? can't be a column in a prepared statement
>
> I cannot reproduce any problem using what I think is equivalent in libpq:

I thought we got this one sorted out already, it was a server bug fixed
in beta2? At the time you said:

> "JEAN-PIERRE PELLETIER" <pelletier_32(at)sympatico(dot)ca> writes:
>
>>> 08:47:19.296 (1) FE=> Parse(stmt=null,query="select $1 from (select * from
>>> pg_database) t",oids={23})
>
>
> Actually, now that I look closely, this command is almost certainly
> triggering this beta1 bug:
> http://archives.postgresql.org/pgsql-committers/2006-10/msg00107.php
>
> Please try beta2 and see if it isn't fixed.
>
> regards, tom lane

(and the problem went away in beta2)

-O