New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Received resultset tuples, but no field structure for them" when executing "drop constraint" on db #811

Closed
mgornikov opened this Issue Apr 11, 2017 · 15 comments

Comments

Projects
None yet
7 participants
@mgornikov

mgornikov commented Apr 11, 2017

We got error in application executing SELECT query, when executing, assumedly, DROP CONSTRAINT on database.

application log:

java.lang.IllegalStateException: Received resultset tuples, but no field structure for them
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2089)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:291)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:432)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:358)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:171)
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:119)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:1009)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:560)
	at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2056)
	at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:306)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:299)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:694)
	at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2740)
	at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2693)
	at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:559)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1175)
	at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:904)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1134)
	at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:460)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1222)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2896)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1857)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1839)
	at org.eclipse.persistence.mappings.OneToOneMapping.executeBatchQuery(OneToOneMapping.java:806)
	at org.eclipse.persistence.mappings.ForeignReferenceMapping.extractResultFromBatchQuery(ForeignReferenceMapping.java:640)
	at org.eclipse.persistence.internal.indirection.BatchValueHolder.instantiateForUnitOfWorkValueHolder(BatchValueHolder.java:81)
	at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:160)
	at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:234)
	at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:89)
	at ru.citc.yodha.core.domain.CustomerDevice._persistence_get_customerProfile(CustomerDevice.java)
	at ru.citc.yodha.core.domain.CustomerDevice.getCustomerProfile(CustomerDevice.java:233)
	at ru.citc.aproject.webservice.v1.impl.UpdatesServiceImpl.getUpdate(UpdatesServiceImpl.java:335)
	at sun.reflect.GeneratedMethodAccessor470.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at com.sun.proxy.$Proxy133.getUpdate(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor470.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at ru.citc.aproject.webservice.validation.MethodValidationInterceptor.invoke(MethodValidationInterceptor.java:47)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:69)
	at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:255)
	at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:148)
	at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:90)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at com.sun.proxy.$Proxy134.getUpdate(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor470.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180)
	at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:189)
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:99)
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59)
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:254)
	at org.apache.cxf.transport.http_jetty.JettyHTTPDestination.doService(JettyHTTPDestination.java:234)
	at org.apache.cxf.transport.http_jetty.JettyHTTPHandler.handle(JettyHTTPHandler.java:70)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1129)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1065)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)

database log:

postgres@db STATEMENT:  CREATE UNIQUE INDEX CONCURRENTLY pgcompact_index_16989 ON customerprofile USING btree (id);
postgres@db LOG:  duration: 58687.181 ms  statement: CREATE UNIQUE INDEX CONCURRENTLY pgcompact_index_16989 ON customerprofile USING btree (id);
postgres@db ERROR:  canceling statement due to statement timeout
postgres@db STATEMENT:  ALTER TABLE public.customerprofile DROP CONSTRAINT customerprofile_pkey;
@davecramer

This comment has been minimized.

Member

davecramer commented Apr 11, 2017

Is there any way to recreate this in a small test case

@mgornikov

This comment has been minimized.

mgornikov commented Apr 11, 2017

We don't know. This case from production.

Version driver:
9.4.1211 PostgreSQL JDBC Driver JDBC42

@davecramer

This comment has been minimized.

Member

davecramer commented Apr 11, 2017

So I think I know what is happening here. This is a create index concurrently which can take an indeterminate amount of time. Someone cancels it, which I suspect is the driver and the results that come back can't be handled. I'll try to replicate this and figure it out

@axelfontaine

This comment has been minimized.

axelfontaine commented May 15, 2017

We are seeing the same issue, not during a create index concurrently though. Just regular DML transactions. (also only happened in our prod environment)

@davecramer

This comment has been minimized.

Member

davecramer commented May 15, 2017

Can anyone provide us with a self contained test ?

@cen1

This comment has been minimized.

cen1 commented Oct 20, 2017

Just got this error today but unfortunately I also cannot provide a minimal test case. It dissapeared after service/db restart.

Received resultset tuples, but no field structure for them
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2120)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:117)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
...

Exception was thrown when getting a resultset for simple select query.

@kristwaa

This comment has been minimized.

kristwaa commented Dec 15, 2017

We're getting this as well.
Based on our system architecture, I think I'm able to state that:

  • only one out of two application server nodes experienced the problem
  • it appears only one, or a few, of the connections in the connection pool suffers from the problem
  • we can see that the code in question is both succeeding and failing during the relevant period, which in this case is visible through rows inserted in the relevant tables
  • the error went away without touching the database or the application after approximately 26 minutes, which could correlate with the maxAge setting in the connection pool (30 minutes)
  • we've observed one incident earlier with the same behavior

Version driver:
42.1.4 (August 1st 2017)

Version server:
PostgreSQL 9.6.1 on x86_64-pc-linux-gnu

Stacktrace:

Caused by: java.lang.IllegalStateException: Received resultset tuples, but no field structure for them
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2121)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
        at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:136)
        at org.springframework.jdbc.core.JdbcTemplate$3.doInPreparedStatement(JdbcTemplate.java:851)
        at org.springframework.jdbc.core.JdbcTemplate$3.doInPreparedStatement(JdbcTemplate.java:849)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:589)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:849)
        at org.springframework.jdbc.core.simple.AbstractJdbcInsert.executeInsertAndReturnKeyHolderInternal(AbstractJdbcInsert.java:436)
        at org.springframework.jdbc.core.simple.AbstractJdbcInsert.executeInsertAndReturnKeyInternal(AbstractJdbcInsert.java:417)
        at org.springframework.jdbc.core.simple.AbstractJdbcInsert.doExecuteAndReturnKey(AbstractJdbcInsert.java:374)
        at org.springframework.jdbc.core.simple.SimpleJdbcInsert.executeAndReturnKey(SimpleJdbcInsert.java:121)```
@davecramer

This comment has been minimized.

Member

davecramer commented Dec 15, 2017

Thanks for the information. I'm still at a loss as to how to figure this out though. Without a repeatable test case and the fact that it is not even repeatable in production the only thing I can think of is that somehow the connection is being shared across threads.

@kristwaa

This comment has been minimized.

kristwaa commented Dec 15, 2017

Unfortunately, I'm also at a loss on how to create a repeatable test case. We don't do anything funky in terms of sharing connections across threads; a thread pool and standard Spring constructs (this doesn't disprove your theory though). The relevant part of the code does use @ Transactional annotations.

I see HikariCP in stacktraces above, but this case was observed with the Tomcat connection pool. Based on comments, seen on both SELECT, UPDATE and DDL / admin commands.

If we don't get anywhere and the problem persists, I consider adding logic to flush the pool if this error is detected to see if that can reduce the impact. The error happens far too seldom to add custom debug code for the time being.

@cen1

This comment has been minimized.

cen1 commented Dec 15, 2017

We also use Hikari and all our EntityManagers are RequestScoped. So in theory, all should be fine. Is it perhaps possible that under load two EntityManagers would get a handle to the same connection from the Hikari pool thus using it in a different thread? Pretty sure it should block on pool exhaustion..

That being said, I only noticed this once in several months while working on a project so it might have been a fluke. Or maybe I had a bug in the code that caused connection sharing.

If I ever encounter again I'll make sure to branch the code and try to figure it out.

@kristwaa

This comment has been minimized.

kristwaa commented Dec 18, 2017

Got it again today, this time on both our nodes but at different times. Lasted for ~10 and ~26 minutes (connection eviction / aging still my only theory on this).
No new debugging information, unfortunately. We will review our code, so far we have only experienced this error in one [broad] code path.

@sethduda

This comment has been minimized.

sethduda commented Dec 18, 2017

Just submitted a bug report to the postgres dl and then found this issue on github - very likely the same issue. Issue appears to have been introduced starting in JDBC driver v9.4.1210

The JDBC driver is throwing an "IllegalStateException: Received resultset tuples, but no field structure for them" exception in the following scenario:

Execute the same query 5 times and cause an exception to be thrown the 5th time (e.g. value too long error). Prepare Threshold must be set to 5. When you execute the same query the 6th time, you'll receive an IllegalStateException.

Below is an example of how to reproduce the error. Tested using JDBC driver v9.4.1210 to v42.1.4 and PostgreSQL 9.4.7. Cannot reproduce the issue in driver versions before v9.4.1210


import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;

import org.postgresql.util.PSQLException;

public class IllegalStateExceptionTest {

	public static void main(String[] args) throws Exception {

		/*
		 * CREATE TABLE test ( val varchar(10) )
		 */

		Class.forName("org.postgresql.Driver");
		String url = "jdbc:postgresql://localhost:5432/XXX?user=XXXX&password=XXXX";
		Connection conn = DriverManager.getConnection(url);
		conn.setAutoCommit(false);
		PreparedStatement ps = conn.prepareStatement("insert into test (val) values (?)", new String[] { "val" });
		ps.setString(1, "TEST");

		System.out.println("Execution #1 (OK)");
		ps.executeUpdate();
		conn.rollback();
		System.out.println("Execution #2 (OK)");
		ps.executeUpdate();
		conn.rollback();
		System.out.println("Execution #3 (OK)");
		ps.executeUpdate();
		conn.rollback();
		System.out.println("Execution #4 (OK)");
		ps.executeUpdate();
		conn.rollback();
		System.out.println("Execution #5 (OK)");
		try {
			// Send a value that's too long on the 5th request
			ps.setString(1, "TESTTESTTEST");
			ps.executeUpdate();
		} catch (PSQLException e) {
			// Expected error: org.postgresql.util.PSQLException: ERROR: value
			// too long for type character varying(10)
			conn.rollback();
		}
		// Send a valid value on the 6th request
		ps.setString(1, "TEST");
		System.out.println("Execution #6 (java.lang.IllegalStateException: Received resultset tuples, but no field structure for them)");
		ps.executeUpdate();
		conn.rollback();
	}

}

Here is the stack trace of the error (using driver v42.1.4)

Exception in thread "main" java.lang.IllegalStateException: Received resultset tuples, but no field structure for them
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2121)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:136)
at IllegalStateExceptionTest.main(IllegalStateExceptionTest.java:53)

@kristwaa

This comment has been minimized.

kristwaa commented Jan 2, 2018

Great with a repeatable test case, @sethduda 👍

The defect demonstrated by the test case is feasible in our production case, although we currently have no way to actually verify it. The case has been reproduced manually in a development environment.

@vlsi vlsi closed this in 082d009 Jan 2, 2018

@vlsi

This comment has been minimized.

Member

vlsi commented Jan 2, 2018

@sethduda thanks for the test

@sethduda

This comment has been minimized.

sethduda commented Jan 2, 2018

Thanks for the quick fix!

rhavermans added a commit to bolcom/pgjdbc that referenced this issue Jul 13, 2018

fix: "Received resultset tuples, but no field structure for them" whe…
…n bind failure happens on 5th execution of a statement

Current "describe" approach is to set "statement/portal described" flags at "send describe" phase.
It turns out the describe might be skipped (e.g. if bind fails), then query is marked as "described"
however no field information is known.

The fix is to reset "described" flags in "Ready For Query" for the queries in
pendingDescribeStatementQueue / pendingDescribePortalQueue

fixes pgjdbc#811

rhavermans added a commit to bolcom/pgjdbc that referenced this issue Jul 13, 2018

fix: "Received resultset tuples, but no field structure for them" whe…
…n bind failure happens on 5th execution of a statement

Current "describe" approach is to set "statement/portal described" flags at "send describe" phase.
It turns out the describe might be skipped (e.g. if bind fails), then query is marked as "described"
however no field information is known.

The fix is to reset "described" flags in "Ready For Query" for the queries in
pendingDescribeStatementQueue / pendingDescribePortalQueue

fixes pgjdbc#811
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment