Hyperledger Fabric v1.2 - Failed to invoke chaincode name:"qscc" , error: timeout expired while executing transaction

Hyperledger Fabric v1.2 - Failed to invoke chaincode name:"qscc" , error: timeout expired while executing transaction

我有 3 个 VM 的 Fabric 网络设置,其中包含 4 个组织,每个组织有 2 个对等点以及各自的 CouchDB 实例、1 个专用 CA 和单个订购者。我正在使用 Hyperledger Java SDK 以公开剩余 API 供消费。

我们在查询时经常遇到问题,无论是富文本查询还是有时会出现下面提到的历史查询异常。根据日志,我能够看到用户 Chaincode 已成功检索查询结果,但在执行 "qscc" Chaincode 调用时失败。

2018-08-29 02:43:33.749 UTC [lockbasedtxmgr] Next -> DEBU 26591 queryResultsItr.Next() returned a record:{"availableDate":"","refTxId":"3b9c439f918a4c4ff558ab803611877d5cd990255f57c5b0b2a1944866982384","userId":"ABC0002","updatedBy":"system"}
2018-08-29 02:43:33.749 UTC [chaincode] HandleGetQueryResult -> DEBU 26592 Got keys and values. Sending RESPONSE
2018-08-29 02:43:33.749 UTC [chaincode] HandleTransaction -> DEBU 26593 [4e6c0cc5] Completed GET_QUERY_RESULT. Sending RESPONSE
2018-08-29 02:43:33.750 UTC [chaincode] handleMessage -> DEBU 26594 [4e6c0cc5] Fabric side handling ChaincodeMessage of type: QUERY_STATE_CLOSE in state ready
2018-08-29 02:43:33.750 UTC [chaincode] HandleTransaction -> DEBU 26595 [4e6c0cc5] handling QUERY_STATE_CLOSE from chaincode
2018-08-29 02:43:33.750 UTC [chaincode] HandleTransaction -> DEBU 26596 [4e6c0cc5] Completed QUERY_STATE_CLOSE. Sending RESPONSE
2018-08-29 02:43:33.751 UTC [chaincode] handleMessage -> DEBU 26597 [4e6c0cc5] Fabric side handling ChaincodeMessage of type: COMPLETED in state ready
2018-08-29 02:43:33.751 UTC [chaincode] Notify -> DEBU 26598 [4e6c0cc5] notifying Txid:4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79, channelID:mychannel
2018-08-29 02:43:33.751 UTC [chaincode] Execute -> DEBU 26599 Exit
2018-08-29 02:43:33.751 UTC [endorser] callChaincode -> DEBU 2659a [mychannel][4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79] Exit
2018-08-29 02:43:33.751 UTC [lockbasedtxmgr] GetTxSimulationResults -> DEBU 2659b Simulation completed, getting simulation results
2018-08-29 02:43:33.751 UTC [lockbasedtxmgr] Done -> DEBU 2659c Done with transaction simulation / query execution [4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79]
2018-08-29 02:43:33.751 UTC [endorser] SimulateProposal -> DEBU 2659d [mychannel][4e6c0cc5] Exit
2018-08-29 02:43:33.751 UTC [endorser] endorseProposal -> DEBU 2659e [mychannel][4e6c0cc5] Entry chaincode: name:"mychaincode"
2018-08-29 02:43:33.751 UTC [endorser] endorseProposal -> DEBU 2659f [mychannel][4e6c0cc5] escc for chaincode name:"mychaincode"  is escc
2018-08-29 02:43:33.751 UTC [endorser] EndorseWithPlugin -> DEBU 265a0 Entering endorsement for {plugin: escc, channel: mychannel, tx: 4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79, chaincode: mychaincode}
2018-08-29 02:43:33.751 UTC [endorser] EndorseWithPlugin -> DEBU 265a1 Exiting {plugin: escc, channel: mychannel, tx: 4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79, chaincode: mychaincode}
2018-08-29 02:43:33.751 UTC [endorser] endorseProposal -> DEBU 265a2 [mychannel][4e6c0cc5] Exit
2018-08-29 02:43:33.751 UTC [lockbasedtxmgr] Done -> DEBU 265a3 Done with transaction simulation / query execution [4e6c0cc5d95c5686c20d33d6bafa2cf850b1d1615f240c56831c44cf5bb69c79]
2018-08-29 02:43:33.751 UTC [endorser] ProcessProposal -> DEBU 265a4 Exit: request from 10.255.0.4:47828
2018-08-29 02:43:33.977 UTC [gossip/discovery] periodicalSendAlive -> DEBU 265a5 Sleeping 5s
2018-08-29 02:43:34.198 UTC [gossip/discovery] periodicalReconnectToDead -> DEBU 265a6 Sleeping 25s
2018-08-29 02:43:34.711 UTC [gossip/election] waitForInterrupt -> DEBU 265a7 [40 227 139 114 173 5 75 157 49 97 134 49 223 250 188 122 25 48 140 50 245 198 39 79 233 243 124 193 89 118 85 88] : Exiting
2018-08-29 02:43:34.711 UTC [gossip/election] IsLeader -> DEBU 265a8 [40 227 139 114 173 5 75 157 49 97 134 49 223 250 188 122 25 48 140 50 245 198 39 79 233 243 124 193 89 118 85 88] : Returning true
2018-08-29 02:43:34.711 UTC [gossip/election] waitForInterrupt -> DEBU 265a9 [40 227 139 114 173 5 75 157 49 97 134 49 223 250 188 122 25 48 140 50 245 198 39 79 233 243 124 193 89 118 85 88] : Entering
2018-08-29 02:43:35.075 UTC [chaincode] Execute -> DEBU 265aa Exit
2018-08-29 02:43:35.075 UTC [endorser] callChaincode -> DEBU 265ab [mychannel][8fb2e3710e44df19e8255177885c5ce29a940ea5239b20e7a94791fe2e4faee9] Exit
2018-08-29 02:43:35.077 UTC [endorser] SimulateProposal -> ERRO 265ac [mychannel][8fb2e371] failed to invoke chaincode name:"qscc" , error: timeout expired while executing transaction
github.com/hyperledger/fabric/core/chaincode.(*Handler).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/handler.go:919
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:253
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Invoke
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:239
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:179
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:141
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:136
github.com/hyperledger/fabric/core/endorser.(*Endorser).SimulateProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:287
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:501
github.com/hyperledger/fabric/core/handlers/auth/filter.(*expirationCheckFilter).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/expiration.go:61
github.com/hyperledger/fabric/core/handlers/auth/filter.(*filter).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/filter.go:31
github.com/hyperledger/fabric/protos/peer._Endorser_ProcessProposal_Handler
        /opt/gopath/src/github.com/hyperledger/fabric/protos/peer/peer.pb.go:112
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).processUnaryRPC
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:923
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).handleStream
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:1148
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:637
runtime.goexit
        /opt/go/src/runtime/asm_amd64.s:2361
error sending
failed to execute transaction 8fb2e3710e44df19e8255177885c5ce29a940ea5239b20e7a94791fe2e4faee9
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:181
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:141
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:136
github.com/hyperledger/fabric/core/endorser.(*Endorser).SimulateProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:287
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:501
github.com/hyperledger/fabric/core/handlers/auth/filter.(*expirationCheckFilter).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/expiration.go:61
github.com/hyperledger/fabric/core/handlers/auth/filter.(*filter).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/filter.go:31
github.com/hyperledger/fabric/protos/peer._Endorser_ProcessProposal_Handler
        /opt/gopath/src/github.com/hyperledger/fabric/protos/peer/peer.pb.go:112
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).processUnaryRPC
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:923
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).handleStream
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:1148
github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1
        /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:637
runtime.goexit
        /opt/go/src/runtime/asm_amd64.s:2361
2018-08-29 02:43:35.077 UTC [endorser] SimulateProposal -> DEBU 265ad [mychannel][8fb2e371] Exit
2018-08-29 02:43:35.077 UTC [endorser] ProcessProposal -> DEBU 265ae Exit: request from 10.255.0.4:47818

我最近也遇到了这个问题。在检查了一些相关问题和文档之后,我的临时解决方案是重新启动您在其日志中找到 Failed to invoke chaincode name "qscc" 的对等方:

docker restart <peer container's id>

但是,这个方案并不能彻底解决问题。但是你可以查看this issues to get more information( the issues is duplicated by this,它仍然没有解决)。

这是 Manish Sethi 的相关评论,用于解释查询分类账背后发生的事情:

Ledger exposes two set of APIs one set of APIs relate to state reads and manipulation and the other set of APIs relate to querying the blockchain status (such as GetBlockByNumber and GetTransactionByID). The first set of APIs are exposed via transaction simulator and (are meant for a chaincode to use during transaction simulation) and the second set of API are exposed as a direct APIs in the ledger interface (and are meant for clients to know the ledger status).

Keeping the above in mind, a tacit assumption in the ledger design has been that a single gorouting limits it's usage to one of the above set of APIs exclusively. A chaincode limits itself to state related APIs and a ledger status querying client would not need to create a simulator.

However, on the higher layers, since the ledger status related APIs are exposed via chaincode (qscc, to be specific), the above assumption is broken. The execution path for answering the ledger status queries obtains a transaction simulator before it reaches the qscc code (which has no use in fact, of the transaction simulator).

More specifically, an additional constraint on these two sets of APIs relates to the fact that two independent external calls to any of the ledger API should give a perceived notion of atomic commit to the block storage and the state. For instance, this should not happen that a client queries the API GetBlockchainInfo and finds out that block number 10 is committed but when he submits a subsequent state query, the query returns the state as of block 9 (because, the state update for block 10 are still pending). This is implemented by a pair of locks One lock syncs the state between simulation and statedb commit and another syncs the ledger status related calls with the overall commit. This is done for achieving better performance by halting the simulation to a minimum (only when the updates are actually been dumped to the disk) at the cost of ledger status related queries. Because, the qscc takes a transaction simulator, the above mentioned interaction leads to the reported deadlock. I believe that going forward, one of the suggestions was to expose these ledger status related APIs via grpc interface which will fix this issue. However, I list below three options for completeness...

qscc path not to take hold of a transaction simulator (which is desired otherwise also, as the transaction simulator is an expensive resource as it takes a read lock on the statedb to sync with commit and hence should be taken only for transaction simulations).

An alternate fix could be to implement the above mentioned perceived notion of atomic commit to the block storage and the state by a coarser level single lock but that will impact the throughput an not a desired solution.

Implement the perceived notion of atomic commit yet differently.. which requires some significant work in the interaction between ledger storage and the statedb. In nut shell, exposing the ledger storage a two phase commit. In first step, we append the block and then in the second step, update the BlockchainInfo and blockindexes sunchronized with statedb updates. Given, the above, since the first one is anyway desired, my suggestion would be fix that for 1.1 and 1.2.