Hi,

While trying to get data from hyperledger fabric, we are getting following error at client side

 

"Error While Query\nERROR:Error: error getting results for query response \nerror: QUERY_STATE_NEXT failed: transaction ID: cda38a1c382867183db359d129ac7a9ea81ed4c60088a2dc03a0bd77fc9c2c59: error reading response body: net/http: request canceled (Client.Timeout exceeded while reading body)"

and observing following error on peer node:

←[33m2021-01-08 08:57:17.005 UTC [couchdb] handleRequest -> WARN 3da←[0m Retrying couchdb request in 125ms. Attempt:1  Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:57:52.131 UTC [couchdb] handleRequest -> WARN 3db←[0m Retrying couchdb request in 250ms. Attempt:2  Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:58:27.383 UTC [couchdb] handleRequest -> WARN 3dc←[0m Retrying couchdb request in 500ms. Attempt:3  Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:59:02.883 UTC [couchdb] handleRequest -> WARN 3dd←[0m Retrying couchdb request in 1s. Attempt:4  Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[31m2021-01-08 08:59:03.883 UTC [chaincode] HandleTransaction -> ERRO 3de←[0m [274987ba] Failed to handle GET_QUERY_RESULT. error: Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleGetQueryResult

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:905

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:276

runtime.goexit

        /opt/go/src/runtime/asm_amd64.s:1337

GET_QUERY_RESULT failed: transaction ID: 274987ba0d1fbec4fc9ae92df024caa9f069e2d5732672f18b0b45b98d05624f

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:280

runtime.goexit

        /opt/go/src/runtime/asm_amd64.s:1337

Need help in understanding root cause of why this could be happening.

The query appears to be a JSON find query. These queries will be slow or time out if they do not utilize a well designed index against the JSON data. See the CouchDB tutorial for more details:
https://hyperledger-fabric.readthedocs.io/en/latest/couchdb_tutorial.html


Dave Enyeart

hiteshdutt05---01/08/2021 04:03:52 AM---Hi, While trying to get data from hyperledger fabric, we are getting following error at client side

From: hiteshdutt05@...
To: fabric@...
Date: 01/08/2021 04:03 AM
Subject: [EXTERNAL] [Hyperledger Fabric] Unable to Query data from Hyperledger Fabric #couchdb #fabric-chaincode #hyperledger-fabric
Sent by: fabric@...

---

Hi,

While trying to get data from hyperledger fabric, we are getting following error at client side

"Error While Query\nERROR:Error: error getting results for query response \nerror: QUERY_STATE_NEXT failed: transaction ID: cda38a1c382867183db359d129ac7a9ea81ed4c60088a2dc03a0bd77fc9c2c59: error reading response body: net/http: request canceled (Client.Timeout exceeded while reading body)"

and observing following error on peer node:

←[33m2021-01-08 08:57:17.005 UTC [couchdb] handleRequest -> WARN 3da←[0m Retrying couchdb request in 125ms. Attempt:1 Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:57:52.131 UTC [couchdb] handleRequest -> WARN 3db←[0m Retrying couchdb request in 250ms. Attempt:2 Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:58:27.383 UTC [couchdb] handleRequest -> WARN 3dc←[0m Retrying couchdb request in 500ms. Attempt:3 Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[33m2021-01-08 08:59:02.883 UTC [couchdb] handleRequest -> WARN 3dd←[0m Retrying couchdb request in 1s. Attempt:4 Error:Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

←[31m2021-01-08 08:59:03.883 UTC [chaincode] HandleTransaction -> ERRO 3de←[0m [274987ba] Failed to handle GET_QUERY_RESULT. error: Post http://localhost:5984/prod-nld_new$c$c/_find: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleGetQueryResult

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:905

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:276

runtime.goexit

/opt/go/src/runtime/asm_amd64.s:1337

GET_QUERY_RESULT failed: transaction ID: 274987ba0d1fbec4fc9ae92df024caa9f069e2d5732672f18b0b45b98d05624f

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:280

runtime.goexit

/opt/go/src/runtime/asm_amd64.s:1337

Need help in understanding root cause of why this could be happening.

Hi David,

The chaincode is performing a select query on the CouchDB documents, and the fields set for filtering the results are indexed while installing and instantiating the chaincode. The single query using the Fabric Node SDK client might be reading around 20K-30K records. 

We tried by overriding the peer configuration for following default values with the new values: "CORE_CHAINCODE_EXECUTETIMEOUT=300s" and CORE_PEER_KEEPALIVE_CLIENT_TIMEOUT=300s". We also tried with the SDK connection profile using a property:  "grpc.keepalive_timeout_ms": "300000"

So I am not understanding, what we could be missing here. Because the other chaincodes in same channel are able to query the maximum limit of 100K records!

Adding workarounds such as longer timeouts will only prolong your pain. You must address the root cause of the slow query in CouchDB. Troubleshoot it in a separate CouchDB environment until you have figured it out why the query/index are slow in CouchDB.
But honestly, if you expect to get back 20,000 records, you should consider the pattern of querying a downstream data store built from block events. Chaincode is optimized for transactions, not large queries.


Dave Enyeart

chintanr97---01/11/2021 11:50:53 PM---Hi David, The chaincode is performing a select query on the CouchDB documents, and the fields set fo

From: chintanr97@...
To: fabric@...
Date: 01/11/2021 11:50 PM
Subject: [EXTERNAL] Re: [Hyperledger Fabric] Unable to Query data from Hyperledger Fabric #couchdb #fabric-chaincode #hyperledger-fabric
Sent by: fabric@...

---

Hi David,

The chaincode is performing a select query on the CouchDB documents, and the fields set for filtering the results are indexed while installing and instantiating the chaincode. The single query using the Fabric Node SDK client might be reading around 20K-30K records.

We tried by overriding the peer configuration for following default values with the new values: "CORE_CHAINCODE_EXECUTETIMEOUT=300s" and CORE_PEER_KEEPALIVE_CLIENT_TIMEOUT=300s". We also tried with the SDK connection profile using a property: "grpc.keepalive_timeout_ms": "300000"

So I am not understanding, what we could be missing here. Because the other chaincodes in same channel are able to query the maximum limit of 100K records!

Thanks a lot David for your response. So digging deeper into the logs, we found that peer was returning below error:
[chaincode] BuildQueryResponse -> ERRO Failed to get query result from iterator [chaincode] HandleTransaction -> ERRO Failed to handle QUERY_STATE_NEXT. error: net/http: request canceled (Client.Timeout exceeded while reading body) error reading response body

I wanted to understand the "Client.Timeout" meaning here. I am understanding that the "Client" could be either the peer to Couch DB connection or it could be the Fabric SDK client to peer connection.

IMO, this looks like the peer to Couch DB connection, where the error is getting logged in peer logs within <60s (from the timeout query request comes to the time it errors out), even when CORE_CHAINCODE_EXECUTETIMEOUT is set to 300s. So, this does not look like a timeout issue. Couch DB is returning error much before the set timeout config on the peer. Health of Couch DB and peer containers seem to be good as well. 

Your first log snippet showed CouchDB queries timing out after 35 seconds each. This is the core.yaml ledger.state.couchDBConfig.requestTimeout of 35s. It means that CouchDB is still processing the query when the peer client gives up on it.


Dave Enyeart

chintanr97---01/12/2021 09:31:22 AM---Thanks a lot David for your response. So digging deeper into the logs, we found that peer was return

From: chintanr97@...
To: fabric@...
Date: 01/12/2021 09:31 AM
Subject: [EXTERNAL] Re: [Hyperledger Fabric] Unable to Query data from Hyperledger Fabric #couchdb #fabric-chaincode #hyperledger-fabric
Sent by: fabric@...

---

Thanks a lot David for your response. So digging deeper into the logs, we found that peer was returning below error:
[chaincode] BuildQueryResponse -> ERRO Failed to get query result from iterator [chaincode] HandleTransaction -> ERRO Failed to handle QUERY_STATE_NEXT. error: net/http: request canceled (Client.Timeout exceeded while reading body) error reading response body

I wanted to understand the "Client.Timeout" meaning here. I am understanding that the "Client" could be either the peer to Couch DB connection or it could be the Fabric SDK client to peer connection.

IMO, this looks like the peer to Couch DB connection, where the error is getting logged in peer logs within <60s (from the timeout query request comes to the time it errors out), even when CORE_CHAINCODE_EXECUTETIMEOUT is set to 300s. So, this does not look like a timeout issue. Couch DB is returning error much before the set timeout config on the peer. Health of Couch DB and peer containers seem to be good as well.

Hi David, That's correct! However, we found a minor fix in the chaincode and post that the latest error logs give following stack trace:

```

[34m2021-01-12 09:22:03.362 UTC [endorser] callChaincode -> INFO 10f7b [][] Entry chaincode: name:"<ccName>" 

[31m2021-01-12 09:22:41.290 UTC [chaincode] BuildQueryResponse -> ERRO [0m Failed to get query result from iterator

[31m2021-01-12 09:22:41.290 UTC [chaincode] HandleTransaction -> ERRO [0m [] Failed to handle QUERY_STATE_NEXT. error: net/http: request canceled (Client.Timeout exceeded while reading body)

error reading response body

github.com/hyperledger/fabric/core/ledger/util/couchdb.(*CouchDatabase).QueryDocuments

/opt/gopath/src/github.com/hyperledger/fabric/core/ledger/util/couchdb/couchdb.go:1072

github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/statedb/statecouchdb.(*queryScanner).executeQueryWithBookmark

/opt/gopath/src/github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go:483

github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/statedb/statecouchdb.(*queryScanner).Next

/opt/gopath/src/github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go:731

github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr.(*queryResultsItr).Next

/opt/gopath/src/github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/helper.go:433

github.com/hyperledger/fabric/core/chaincode.(*QueryResponseGenerator).BuildQueryResponse

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/query_response_generator.go:32

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleQueryStateNext

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:824

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:276

runtime.goexit

/opt/go/src/runtime/asm_amd64.s:1337

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleQueryStateNext

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:827

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:276

runtime.goexit

/opt/go/src/runtime/asm_amd64.s:1337

QUERY_STATE_NEXT failed: transaction ID: <tid>

github.com/hyperledger/fabric/core/chaincode.(*Handler).HandleTransaction

/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:280

runtime.goexit

/opt/go/src/runtime/asm_amd64.s:1337

[34m2021-01-12 09:22:41.291 UTC [<cc>] func2 -> INFO [0m 2021/01/12 09:22:41 error getting results for query response 

[34m2021-01-12 09:22:41.291 UTC [<cc>] func2 -> INFO [0m error: QUERY_STATE_NEXT failed: transaction ID: <tid>: error reading response body: net/http: request canceled (Client.Timeout exceeded while reading body)

[34m2021-01-12 09:22:41.291 UTC [endorser] callChaincode -> INFO [0m [<channel>][] Exit chaincode: name:"<ccName>"  (37928ms)
[31m2021-01-12 09:22:41.300 UTC [endorser] ProcessProposal -> ERRO [0m [<channel>][] simulateProposal() resulted in chaincode name:"<ccName>"  response status 500 for txid: <tid>
```

In the total 4 iterations of query we did, the timestamp in the second last log line, "Exit chaincode: name: ..." was: 49695ms, 55657ms, 37928ms (above) snippet, and 38826ms.

So, I am not sure now if it is "ledger.state.couchDBConfig.requestTimeout" (which has been set to 35 s), or if it is "CORE_CHAINCODE_EXECUTETIMEOUT" (updated to 300s).

I had a similar error and ended up being an issue with the high number of records (400k+) processed by the query. I am not sure whether this could be related to your case, but using indexes (and even better with partial_filter_selector) solved it for me.

I had a similar error and ended up being an issue with the high number of records (400k+) processed by the query. I am not sure whether this could be related to your case, but using indexes (and even better with partial_filter_selector) solved it for me.