Topics

Timeout expired while executing transaction a heavy chaincode function #fabric #fabric-sdk-java


Joao Antunes
 

Hi to all,

Currently I have a chaincode that takes a bit of time to execute (it's expected).

The problem is that when I run the call I receive the following error:

Caused by: io.grpc.StatusRuntimeException: UNKNOWN: error executing chaincode: failed to execute transaction: timeout expired while executing transaction


I'm using java sdk and yes, I have my proposal.waitTime=60000.

Can the transaction timeout be changed? Where, sdk or network config?

Thank you and regards,
João Antunes


Joao Antunes
 

Just a quick update:

The peer1-org1 logs:

 

2019-02-14 17:42:03.360 UTC [endorser] simulateProposal -> ERRO 1e5b6 [project1][d90dbe85] failed to invoke chaincode name:"project1" version:"1.0" , error: timeout expired while executing transaction

github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:813

github.com/hyperledger/fabric/core/chaincode.Execute

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/exectransaction.go:58

github.com/hyperledger/fabric/core/chaincode.ExecuteChaincode

        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincodeexec.go:85

github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute

        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:93

github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode

        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:132

github.com/hyperledger/fabric/core/endorser.(*Endorser).simulateProposal

        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:265

github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal

        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:491

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:781

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:981

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:551

runtime.goexit

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

failed to execute transaction

error executing chaincode

 
 
 


Joao Antunes
 

New update:

 

Changed the following variables on docker-compose:

- CORE_CHAINCODE_EXECUTETIMEOUT=60S
- CORE_PEER_KEEPALIVE_CLIENT_TIMEOUT=60S
- CORE_PEER_KEEPALIVE_DELIVERYCLIENT_TIMEOUT=60S

Still no change on the outcome.


Joao Antunes
 

New update:

This was expected not to work since no information arrives at the ordering service, but the following property has been changed:

- ORDERER_GENERAL_KEEPALIVE_SERVERTIMEOUT=60s

 Still with no change on the error.


Gari Singh
 

How long does it actually take for the chaincode to execute?
Try setting CORE_CHAINCODE_EXECUTETIMEOUT to something like 300s (overkill but let's see if this gets you past the error).

Also ... any errors coming out of the chaincode logs?


-----------------------------------------
Gari Singh
Distinguished Engineer, CTO - IBM Blockchain
IBM Middleware
550 King St
Littleton, MA 01460
Cell: 978-846-7499
garis@us.ibm.com
-----------------------------------------

-----fabric@lists.hyperledger.org wrote: -----
To: fabric@lists.hyperledger.org
From: "Joao Antunes"
Sent by: fabric@lists.hyperledger.org
Date: 02/19/2019 05:00AM
Subject: Re: [Hyperledger Fabric] Timeout expired while executing transaction a heavy chaincode function #fabric #fabric-sdk-java

New update:

Changed the following variables on docker-compose:

- CORE_CHAINCODE_EXECUTETIMEOUT=60S
- CORE_PEER_KEEPALIVE_CLIENT_TIMEOUT=60S
- CORE_PEER_KEEPALIVE_DELIVERYCLIENT_TIMEOUT=60S
Still no change on the outcome.


Joao Antunes
 

The chaincode executes in around 30 sec. 
On chaincode logs, I only receive the following errors:

2019-02-19 10:24:21.020 UTC [shim] handleGetQueryResult -> ERRO 011 [653f0d11]Received ERROR
2019-02-19 10:24:21.020 UTC [smartcycling] Infof -> INFO 012. Number 10000, id1 for the transactionID 653f0d1120a1604c5cf64c6855ab4f824be67eca0ad9235fc74d4140a90c704d
2019-02-19 10:24:48.998 UTC [shim] handlePutState -> ERRO 013 [653f0d11]Received ERROR. Payload: [[653f0d11 PUT_STATE ERROR]]No ledger context for %!s(MISSING). Sending %!s(MISSING)


On the Peer logs:

2019-02-19 10:24:48.996 UTC [chaincode] processStream -> DEBU 129ad [653f0d11]Received message PUT_STATE from shim
2019-02-19 10:24:48.996 UTC [chaincode] ExecuteChaincode -> ERRO 129ae timeout expired while executing transaction
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:813
github.com/hyperledger/fabric/core/chaincode.Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/exectransaction.go:58
github.com/hyperledger/fabric/core/chaincode.ExecuteChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincodeexec.go:85
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:93
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:132
github.com/hyperledger/fabric/core/endorser.(*Endorser).simulateProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:265
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:491
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:781
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:981
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:551
runtime.goexit
        /opt/go/src/runtime/asm_amd64.s:2337
failed to execute transaction
error executing chaincode
2019-02-19 10:24:48.996 UTC [chaincode] handleMessage -> DEBU 129af [653f0d11]Fabric side Handling ChaincodeMessage of type: PUT_STATE in state ready
2019-02-19 10:24:48.996 UTC [endorser] callChaincode -> DEBU 129b0 [code1][653f0d11] Exit
2019-02-19 10:24:48.996 UTC [chaincode] filterError -> DEBU 129b1 Ignoring NoTransitionError: no transition
2019-02-19 10:24:48.996 UTC [endorser] simulateProposal -> ERRO 129b2 [code1][653f0d11] failed to invoke chaincode name:"code1" version:"1.0" , error: timeout expired while executing transaction
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:813
github.com/hyperledger/fabric/core/chaincode.Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/exectransaction.go:58
github.com/hyperledger/fabric/core/chaincode.ExecuteChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincodeexec.go:85
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:93
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:132
github.com/hyperledger/fabric/core/endorser.(*Endorser).simulateProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:265
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
        /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:491
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:781
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:981
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:551
runtime.goexit
        /opt/go/src/runtime/asm_amd64.s:2337
failed to execute transaction
error executing chaincode
2019-02-19 10:24:48.996 UTC [endorser] simulateProposal -> DEBU 129b3 [code1][653f0d11] Exit
2019-02-19 10:24:48.996 UTC [lockbasedtxmgr] Done -> DEBU 129b4 Done with transaction simulation / query execution [653f0d1120a1604c5cf64c6855ab4f824be67eca0ad9235fc74d4140a90c704d]
2019-02-19 10:24:48.996 UTC [chaincode] func1 -> DEBU 129b5 [653f0d11]state is ready
2019-02-19 10:24:48.996 UTC [endorser] ProcessProposal -> DEBU 129b6 Exit: request from%!(EXTRA string=172.31.0.1:40862)
2019-02-19 10:24:48.996 UTC [chaincode] isValidTxSim -> ERRO 129b7 [[653f0d11 PUT_STATE ERROR]]No ledger context for %!!(MISSING)s(MISSING). Sending %!!(MISSING)s(MISSING)
 
 


Gari Singh
 

Looks like there are actually errors executing the chaincode itself ... which version of Fabric are you using again?


-----------------------------------------
Gari Singh
Distinguished Engineer, CTO - IBM Blockchain
IBM Middleware
550 King St
Littleton, MA 01460
Cell: 978-846-7499
garis@us.ibm.com
-----------------------------------------

-----fabric@lists.hyperledger.org wrote: -----
To: fabric@lists.hyperledger.org
From: "Joao Antunes"
Sent by: fabric@lists.hyperledger.org
Date: 02/19/2019 06:16AM
Subject: Re: [Hyperledger Fabric] Timeout expired while executing transaction a heavy chaincode function #fabric #fabric-sdk-java

The chaincode executes in around 30 sec.
On chaincode logs, I only receive the following errors:
2019-02-19 10:24:21.020 UTC [shim] handleGetQueryResult -> ERRO 011 [653f0d11]Received ERROR
2019-02-19 10:24:21.020 UTC [smartcycling] Infof -> INFO 012. Number 10000, id1 for the transactionID 653f0d1120a1604c5cf64c6855ab4f824be67eca0ad9235fc74d4140a90c704d
2019-02-19 10:24:48.998 UTC [shim] handlePutState -> ERRO 013 [653f0d11]Received ERROR. Payload: [[653f0d11 PUT_STATE ERROR]]No ledger context for %!s(MISSING). Sending %!s(MISSING)

On the Peer logs:


2019-02-19 10:24:48.996 UTC [chaincode] processStream -> DEBU 129ad [653f0d11]Received message PUT_STATE from shim
2019-02-19 10:24:48.996 UTC [chaincode] ExecuteChaincode -> ERRO 129ae timeout expired while executing transaction
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:813
github.com/hyperledger/fabric/core/chaincode.Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/exectransaction.go:58
github.com/hyperledger/fabric/core/chaincode.ExecuteChaincode
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincodeexec.go:85
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:93
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:132
github.com/hyperledger/fabric/core/endorser.(*Endorser).simulateProposal
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:265
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:491
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:781
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:981
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:551
runtime.goexit
/opt/go/src/runtime/asm_amd64.s:2337
failed to execute transaction
error executing chaincode
2019-02-19 10:24:48.996 UTC [chaincode] handleMessage -> DEBU 129af [653f0d11]Fabric side Handling ChaincodeMessage of type: PUT_STATE in state ready
2019-02-19 10:24:48.996 UTC [endorser] callChaincode -> DEBU 129b0 [code1][653f0d11] Exit
2019-02-19 10:24:48.996 UTC [chaincode] filterError -> DEBU 129b1 Ignoring NoTransitionError: no transition
2019-02-19 10:24:48.996 UTC [endorser] simulateProposal -> ERRO 129b2 [code1][653f0d11] failed to invoke chaincode name:"code1" version:"1.0" , error: timeout expired while executing transaction
github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:813
github.com/hyperledger/fabric/core/chaincode.Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/exectransaction.go:58
github.com/hyperledger/fabric/core/chaincode.ExecuteChaincode
/opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincodeexec.go:85
github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:93
github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:132
github.com/hyperledger/fabric/core/endorser.(*Endorser).simulateProposal
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:265
github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
/opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:491
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:781
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:981
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:551
runtime.goexit
/opt/go/src/runtime/asm_amd64.s:2337
failed to execute transaction
error executing chaincode
2019-02-19 10:24:48.996 UTC [endorser] simulateProposal -> DEBU 129b3 [code1][653f0d11] Exit
2019-02-19 10:24:48.996 UTC [lockbasedtxmgr] Done -> DEBU 129b4 Done with transaction simulation / query execution [653f0d1120a1604c5cf64c6855ab4f824be67eca0ad9235fc74d4140a90c704d]
2019-02-19 10:24:48.996 UTC [chaincode] func1 -> DEBU 129b5 [653f0d11]state is ready
2019-02-19 10:24:48.996 UTC [endorser] ProcessProposal -> DEBU 129b6 Exit: request from%!(EXTRA string=172.31.0.1:40862)
2019-02-19 10:24:48.996 UTC [chaincode] isValidTxSim -> ERRO 129b7 [[653f0d11 PUT_STATE ERROR]]No ledger context for %!!(MISSING)s(MISSING). Sending %!!(MISSING)s(MISSING)


Joao Antunes
 

I know that my chaincode is correct because, with less actions to execute, there are no running errors or timeouts.

I'm currently running version 1.1 of fabric (I can't change the version to the latest one)