search

hyperledger / caliper

A blockchain benchmark framework to measure performance of multiple blockchain solutions https://wiki.hyperledger.org/display/caliper
https://hyperledger.github.io/caliper/
Apache License 2.0
650 stars 402 forks source link

error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: REQUEST_TIMEOUT #214

Closed Priyanshi52 closed 5 years ago

Priyanshi52 commented 5 years ago

As default image hyperledger/fabric-peer:x86_64-1.1.0 does not support armv71 so using talium/fabric-peer:armv7l-1.0.0-beta instead same for ca and orderer. Using this image I am able to run fabric first-network successfully on Raspberry Pi 3 but getting an error while running caliper-

root@raspberrypi:/home/caliper-master# node benchmark/simple/main.js -c config.json -n fabric.json TAP version 13

Caliper Test

docker-compose -f network/fabric/simplenetwork/docker-compose.yaml up -d Creating network "simplenetwork_default" with the default driver Creating ca_peerOrg2 Creating simplenetwork_peer_1 Creating simplenetwork_ca_1 Creating orderer.example.com Creating ca_peerOrg1 Creating peer0.org1.example.com Creating peer1.org1.example.com Creating peer0.org2.example.com Creating peer1.org2.example.com

create mychannel......

ok 1 created mychannel successfully

Sleep 5s......

Join channel......

join mychannel

ok 2 Successfully joined mychannel

install all chaincodes......

info: [packager/Golang.js]: packaging GOLANG from contract/fabric/simple/go info: [packager/Golang.js]: packaging GOLANG from contract/fabric/simple/go ok 3 Installed chaincode simple successfully in all peers

Instantiate chaincode......

error: [Peer.js]: sendProposal - timed out after:120000 error: [Peer.js]: sendProposal - timed out after:120000 error: [Peer.js]: sendProposal - timed out after:120000 error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: REQUEST_TIMEOUT at Timeout._onTimeout (/home/caliper-master/node_modules/fabric-client/lib/Peer.js:124:19) at ontimeout (timers.js:498:11) at tryOnTimeout (timers.js:323:5) at Timer.listOnTimeout (timers.js:290:5) error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: REQUEST_TIMEOUT at Timeout._onTimeout (/home/caliper-master/node_modules/fabric-client/lib/Peer.js:124:19) at ontimeout (timers.js:498:11) at tryOnTimeout (timers.js:323:5) at Timer.listOnTimeout (timers.js:290:5) error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: REQUEST_TIMEOUT at Timeout._onTimeout (/home/caliper-master/node_modules/fabric-client/lib/Peer.js:124:19) at ontimeout (timers.js:498:11) at tryOnTimeout (timers.js:323:5) at Timer.listOnTimeout (timers.js:290:5) error: [Peer.js]: sendProposal - timed out after:120000 error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: REQUEST_TIMEOUT at Timeout._onTimeout (/home/caliper-master/node_modules/fabric-client/lib/Peer.js:124:19) at ontimeout (timers.js:498:11) at tryOnTimeout (timers.js:323:5) at Timer.listOnTimeout (timers.js:290:5) not ok 4 Failed to instantiate chaincodes, Error: Failed to send instantiate due to error: Error: Failed to send instantiate Proposal or receive valid response. Response null or status is not 200. exiting... at Client.newDefaultKeyValueStore.then.then.then.then (/home/caliper-master/src/fabric/e2eUtils.js:372:19) at at process._tickCallback (internal/process/next_tick.js:189:7) at Client.newDefaultKeyValueStore.then.then.then.then.then (/home/caliper-master/src/fabric/e2eUtils.js:385:15) at at process._tickCallback (internal/process/next_tick.js:189:7)

operator: fail
at: chaincodes.reduce.then.catch (/home/caliper-master/src/fabric/instantiate-chaincode.js:60:19)
stack: |-
  Error: Failed to instantiate chaincodes, Error: Failed to send instantiate due to error: Error: Failed to send instantiate Proposal or receive valid response. Response null or status is not 200. exiting...
      at Client.newDefaultKeyValueStore.then.then.then.then (/home/caliper-master/src/fabric/e2eUtils.js:372:19)
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:189:7)
      at Client.newDefaultKeyValueStore.then.then.then.then.then (/home/caliper-master/src/fabric/e2eUtils.js:385:15)
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:189:7)
      at Test.assert [as _assert] (/home/caliper-master/node_modules/tape/lib/test.js:224:54)
      at Test.bound [as _assert] (/home/caliper-master/node_modules/tape/lib/test.js:76:32)
      at Test.fail (/home/caliper-master/node_modules/tape/lib/test.js:317:10)
      at Test.bound [as fail] (/home/caliper-master/node_modules/tape/lib/test.js:76:32)
      at chaincodes.reduce.then.catch (/home/caliper-master/src/fabric/instantiate-chaincode.js:60:19)
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:189:7)

... fabric.installSmartContract() failed, Error: Fabric: instantiate chaincodes failed at chaincodes.reduce.then.catch (/home/caliper-master/src/fabric/instantiate-chaincode.js:61:31) at at process._tickCallback (internal/process/next_tick.js:189:7) [Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0 unexpected error, Error: Fabric: instantiate chaincodes failed at chaincodes.reduce.then.catch (/home/caliper-master/src/fabric/instantiate-chaincode.js:61:31) at at process._tickCallback (internal/process/next_tick.js:189:7) docker-compose -f network/fabric/simplenetwork/docker-compose.yaml down;docker rm $(docker ps -aq);docker rmi $(docker images dev* -q) Stopping peer0.org2.example.com ... done Stopping peer1.org2.example.com ... done Stopping peer1.org1.example.com ... done Stopping peer0.org1.example.com ... done Stopping simplenetwork_ca_1 ... done Stopping ca_peerOrg1 ... done Stopping orderer.example.com ... done Stopping ca_peerOrg2 ... done Removing peer0.org2.example.com ... done Removing peer1.org2.example.com ... done Removing peer1.org1.example.com ... done Removing peer0.org1.example.com ... done Removing simplenetwork_ca_1 ... done Removing ca_peerOrg1 ... done Removing orderer.example.com ... done Removing ca_peerOrg2 ... done Removing simplenetwork_peer_1 ... done Removing network simplenetwork_default Error response from daemon: You cannot remove a running container a724154af83911c36b80ce8737f25d049915bb314856ecc0de8ac709f45d32e6. Stop the container before attempting removal or force remove Error response from daemon: You cannot remove a running container 8e62f5870abf169ed3248ed8c68e094eebc0db53f4a2996081e0060d5d60230a. Stop the container before attempting removal or force remove Error response from daemon: You cannot remove a running container deb4c95dfdc4740e296c843562b721e8c9e6ae8613926c7a288010080ecac9ea. Stop the container before attempting removal or force remove Error response from daemon: You cannot remove a running container ba62b00c331a134bd6f32bb54bae775eb0ff6de564ed2085073866460449fa0a. Stop the container before attempting removal or force remove "docker rmi" requires at least 1 argument. See 'docker rmi --help'.

Usage: docker rmi [OPTIONS] IMAGE [IMAGE...]

Remove one or more images

1..4

tests 4

pass 3

fail 1

aklenik commented 5 years ago

@Priyanshi52 The following is from my comment in RocketChat:

Timeout during a chaincode instantiation is a tricky thing. You would expect that it is an actual timeout, but in my experience, it is an error during executing (or trying to execute) the chaincode Init function.

The confusing part is, that this error appears/logged in the dev*** chaincode container that is created by the peer (and not the peer container itself). But since the peer doesn't receive an OK from the CC init in time (because of the error), it will report a timeout, and delete the container, and yessss, the error message with it 🙂

So to observe the actual error, you have to follow the logs of the dev*** container once it is created ( docker logs --follow dev***), but before the peer deletes it. For this, you should increase the timeout on the client/Caliper side AND on the peer side with the CORE_CHAINCODE_STARTUPTIMEOUT=300s env setting for example.

Priyanshi52 commented 5 years ago

@aklenik I got this -

2018-11-08 17:22:20.749 UTC [msp] getMspConfig -> INFO 001 intermediate certs folder not found at [/etc/hyperledger/msp/peer/msp/intermediatecerts]. Skipping.: [stat /etc/hyperledger/msp/peer/msp/intermediatecerts: no such file or directory] 2018-11-08 17:22:20.750 UTC [msp] getMspConfig -> INFO 002 crls folder not found at [/etc/hyperledger/msp/peer/msp/intermediatecerts]. Skipping.: [stat /etc/hyperledger/msp/peer/msp/crls: no such file or directory] 2018-11-08 17:22:20.750 UTC [msp] getMspConfig -> INFO 003 MSP configuration file not found at [/etc/hyperledger/msp/peer/msp/config.yaml]: [stat /etc/hyperledger/msp/peer/msp/config.yaml: no such file or directory] 2018-11-08 17:22:20.977 UTC [nodeCmd] serve -> INFO 004 Starting peer: Version: 1.0.0-beta Go version: go1.7.5 OS/Arch: linux/arm Chaincode: Base Image Version: 0.3.1 Base Docker Namespace: talium Base Docker Label: org.talium.fabric Docker Namepace: talium

2018-11-08 17:22:20.977 UTC [ledgermgmt] initialize -> INFO 005 Initializing ledger mgmt 2018-11-08 17:22:20.977 UTC [kvledger] NewProvider -> INFO 006 Initializing ledger provider 2018-11-08 17:22:24.897 UTC [kvledger] NewProvider -> INFO 007 ledger provider Initialized 2018-11-08 17:22:24.898 UTC [ledgermgmt] initialize -> INFO 008 ledger mgmt initialized 2018-11-08 17:22:24.915 UTC [nodeCmd] serve -> INFO 009 Starting peer with TLS enabled 2018-11-08 17:22:24.928 UTC [eventhub_producer] start -> INFO 00a Event processor started 2018-11-08 17:22:24.932 UTC [chaincode] NewChaincodeSupport -> INFO 00b Chaincode support using peerAddress: peer0.org2.example.com:7051 2018-11-08 17:22:24.937 UTC [sccapi] RegisterSysCC -> INFO 00c system chaincode cscc(github.com/hyperledger/fabric/core/scc/cscc) registered 2018-11-08 17:22:24.938 UTC [sccapi] RegisterSysCC -> INFO 00d system chaincode lscc(github.com/hyperledger/fabric/core/scc/lscc) registered 2018-11-08 17:22:24.939 UTC [sccapi] RegisterSysCC -> INFO 00e system chaincode escc(github.com/hyperledger/fabric/core/scc/escc) registered 2018-11-08 17:22:24.940 UTC [sccapi] RegisterSysCC -> INFO 00f system chaincode vscc(github.com/hyperledger/fabric/core/scc/vscc) registered 2018-11-08 17:22:24.941 UTC [sccapi] RegisterSysCC -> INFO 010 system chaincode qscc(github.com/hyperledger/fabric/core/chaincode/qscc) registered 2018-11-08 17:22:24.945 UTC [gossip/service] func1 -> INFO 011 Initialize gossip with endpoint peer0.org2.example.com:7051 and bootstrap set [127.0.0.1:7051] 2018-11-08 17:22:24.946 UTC [msp] DeserializeIdentity -> INFO 012 Obtaining identity 2018-11-08 17:22:25.056 UTC [msp] DeserializeIdentity -> INFO 013 Obtaining identity 2018-11-08 17:22:25.108 UTC [gossip/discovery] NewDiscoveryService -> INFO 014 Started {peer0.org2.example.com:7051 [] [23 3 141 140 92 60 43 136 186 32 94 164 8 215 61 180 84 156 91 71 138 94 173 44 140 205 249 1 125 91 102 112] peer0.org2.example.com:7051} incTime is 1541697745105002356 2018-11-08 17:22:25.109 UTC [gossip/gossip] NewGossipService -> INFO 015 Creating gossip service with self membership of {peer0.org2.example.com:7051 [] [23 3 141 140 92 60 43 136 186 32 94 164 8 215 61 180 84 156 91 71 138 94 173 44 140 205 249 1 125 91 102 112] peer0.org2.example.com:7051} 2018-11-08 17:22:25.109 UTC [msp] DeserializeIdentity -> INFO 016 Obtaining identity 2018-11-08 17:22:25.199 UTC [gossip/gossip] start -> INFO 017 Gossip instance peer0.org2.example.com:7051 started 2018-11-08 17:22:25.202 UTC [cscc] Init -> INFO 018 Init CSCC 2018-11-08 17:22:25.203 UTC [sccapi] deploySysCC -> INFO 019 system chaincode cscc/(github.com/hyperledger/fabric/core/scc/cscc) deployed 2018-11-08 17:22:25.206 UTC [sccapi] deploySysCC -> INFO 01a system chaincode lscc/(github.com/hyperledger/fabric/core/scc/lscc) deployed 2018-11-08 17:22:25.209 UTC [escc] Init -> INFO 01b Successfully initialized ESCC 2018-11-08 17:22:25.210 UTC [sccapi] deploySysCC -> INFO 01c system chaincode escc/(github.com/hyperledger/fabric/core/scc/escc) deployed 2018-11-08 17:22:25.212 UTC [sccapi] deploySysCC -> INFO 01d system chaincode vscc/(github.com/hyperledger/fabric/core/scc/vscc) deployed 2018-11-08 17:22:25.215 UTC [qscc] Init -> INFO 01e Init QSCC 2018-11-08 17:22:25.216 UTC [sccapi] deploySysCC -> INFO 01f system chaincode qscc/(github.com/hyperledger/fabric/core/chaincode/qscc) deployed 2018-11-08 17:22:25.216 UTC [nodeCmd] initSysCCs -> INFO 020 Deployed system chaincodess 2018-11-08 17:22:25.218 UTC [nodeCmd] serve -> INFO 021 Starting peer with ID=[name:"peer0.org2.example.com" ], network ID=[dev], address=[peer0.org2.example.com:7051] 2018-11-08 17:22:25.236 UTC [nodeCmd] serve -> INFO 022 Started peer with ID=[name:"peer0.org2.example.com" ], network ID=[dev], address=[peer0.org2.example.com:7051] 2018-11-08 17:22:37.394 UTC [ledgermgmt] CreateLedger -> INFO 023 Creating ledger [mychannel] with genesis block 2018-11-08 17:22:38.674 UTC [kvledger] Commit -> INFO 024 Channel [mychannel]: Created block [0] with 1 transaction(s) 2018-11-08 17:22:38.701 UTC [ledgermgmt] CreateLedger -> INFO 025 Created ledger [mychannel] with genesis block 2018-11-08 17:22:39.172 UTC [cscc] Init -> INFO 026 Init CSCC 2018-11-08 17:22:39.173 UTC [sccapi] deploySysCC -> INFO 027 system chaincode cscc/mychannel(github.com/hyperledger/fabric/core/scc/cscc) deployed 2018-11-08 17:22:39.176 UTC [sccapi] deploySysCC -> INFO 028 system chaincode lscc/mychannel(github.com/hyperledger/fabric/core/scc/lscc) deployed 2018-11-08 17:22:39.179 UTC [escc] Init -> INFO 029 Successfully initialized ESCC 2018-11-08 17:22:39.179 UTC [sccapi] deploySysCC -> INFO 02a system chaincode escc/mychannel(github.com/hyperledger/fabric/core/scc/escc) deployed 2018-11-08 17:22:39.182 UTC [sccapi] deploySysCC -> INFO 02b system chaincode vscc/mychannel(github.com/hyperledger/fabric/core/scc/vscc) deployed 2018-11-08 17:22:39.184 UTC [qscc] Init -> INFO 02c Init QSCC 2018-11-08 17:22:39.184 UTC [sccapi] deploySysCC -> INFO 02d system chaincode qscc/mychannel(github.com/hyperledger/fabric/core/chaincode/qscc) deployed 2018-11-08 17:22:39.185 UTC [eventhub_producer] SendProducerBlockEvent -> INFO 02e Channel [mychannel]: Sending event for block number [0] 2018-11-08 17:22:45.439 UTC [ConnProducer] NewConnection -> ERRO 02f Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:22:45.440 UTC [deliveryClient] connect -> ERRO 030 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:22:46.468 UTC [ConnProducer] NewConnection -> ERRO 031 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:22:46.468 UTC [deliveryClient] connect -> ERRO 032 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:22:48.533 UTC [ConnProducer] NewConnection -> ERRO 033 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:22:48.533 UTC [deliveryClient] connect -> ERRO 034 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:22:52.574 UTC [ConnProducer] NewConnection -> ERRO 035 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:22:52.575 UTC [deliveryClient] connect -> ERRO 036 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:23:00.619 UTC [ConnProducer] NewConnection -> ERRO 037 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:23:00.619 UTC [deliveryClient] connect -> ERRO 038 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:23:16.669 UTC [ConnProducer] NewConnection -> ERRO 039 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:23:16.670 UTC [deliveryClient] connect -> ERRO 03a Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:23:48.720 UTC [ConnProducer] NewConnection -> ERRO 03b Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:23:48.720 UTC [deliveryClient] connect -> ERRO 03c Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:24:52.783 UTC [ConnProducer] NewConnection -> ERRO 03d Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:24:52.784 UTC [deliveryClient] connect -> ERRO 03e Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050] 2018-11-08 17:26:59.271 UTC [chaincode-platform] func1 -> ERRO 03f Failed to generate platform-specific docker build: Error returned from build: 2 "# contract/fabric/simple/go /opt/go/pkg/tool/linux_arm/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

" 2018-11-08 17:26:59.275 UTC [dockercontroller] deployImage -> ERRO 040 Error building images: Failed to generate platform-specific docker build: Error returned from build: 2 "# contract/fabric/simple/go /opt/go/pkg/tool/linux_arm/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

" 2018-11-08 17:26:59.276 UTC [dockercontroller] deployImage -> ERRO 041 Image Output:

2018-11-08 17:26:59.276 UTC [chaincode] Launch -> ERRO 042 launchAndWaitForRegister failed Error starting container: Failed to generate platform-specific docker build: Error returned from build: 2 "# contract/fabric/simple/go /opt/go/pkg/tool/linux_arm/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

" 2018-11-08 17:26:59.276 UTC [endorser] simulateProposal -> ERRO 043 failed to invoke chaincode name:"lscc" on transaction 9734873d304930c2aced6d72bdf7b186356892efcd6dbe1272d6ebfc3c9a3cf3, error: Error starting container: Failed to generate platform-specific docker build: Error returned from build: 2 "# contract/fabric/simple/go /opt/go/pkg/tool/linux_arm/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

" 2018-11-08 17:27:01.462 UTC [ConnProducer] NewConnection -> ERRO 044 Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority 2018-11-08 17:27:01.463 UTC [deliveryClient] connect -> ERRO 045 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050]

aklenik commented 5 years ago

The following errors all seem Fabric-related (orderer cert setup, build CC image):

[ConnProducer] NewConnection -> ERRO 02f Failed connecting to orderer.example.com:7050 , error: x509: certificate signed by unknown authority
[deliveryClient] connect -> ERRO 030 Failed obtaining connection: Could not connect to any of the endpoints: [orderer.example.com:7050]
[chaincode-platform] func1 -> ERRO 03f Failed to generate platform-specific docker build: Error returned from build: 2 "# contract/fabric/simple/go
/opt/go/pkg/tool/linux_arm/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

So you should ask around Fabric channels (or the creators of the docker images), because it doesn't seem like a Caliper-related issue.

Smy0521 commented 5 years ago

vi src/fabric/e2eUtils.js

211行 Client.setConfigSetting('request-timeout', 120000);

改为：Client.setConfigSetting('request-timeout', 720000);

aklenik commented 5 years ago

@Priyanshi52 Since the error occurs in the backend network, I'm closing the issue. If you run into Caliper-related errors with your network, feel free to reopen the issue.