search

hyperledger-archives / caliper

A blockchain benchmark framework to measure performance of multiple blockchain solutions
Apache License 2.0
74 stars 24 forks source link

SSL_read error with Fabric 1.0.5 #44

Closed aklenik closed 6 years ago

aklenik commented 6 years ago

Hi all!

Running the simple benchmark results in the following error since the update to Fabric 1.0.5

***** instantiate chaincode *****

info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org1.example.com","grpc.default_authority":"peer0.org1.example.com"}
ok 4 The chaincode instantiate transaction was valid.
ok 5 Instantiated chaincode simple successfully 
 Sleep 5s...

**** End-to-end flow: testing 'open' ****
----test round 0----
started monitor successfully
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
start client 64984:opening accounts
E1216 14:09:28.516382190   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516482489   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.516543852   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516578931   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.516623617   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516655271   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.516698200   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516729054   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.516770530   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516801077   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.516884760   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.516922654   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.517647763   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.517707686   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR
E1216 14:09:28.517762837   60783 ssl_transport_security.c:439] SSL_read returned 0 unexpectedly.
E1216 14:09:28.517795290   60783 secure_endpoint.c:185]      Decryption error: TSI_INTERNAL_ERROR

So the chaincode invoke part reports the error. Works fine if I pull the 1.0.0 versions of the docker images.

haojun commented 6 years ago

hi, can the test still go on??

aklenik commented 6 years ago

After the previous output the following happens (after some hang time):

info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org1.example.com","grpc.default_authority":"peer1.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org1.example.com","grpc.default_authority":"peer0.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000}
start client 16839:opening accounts
start client 16853:opening accounts
start client 16852:opening accounts
start client 16846:opening accounts
start client 16840:opening accounts
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org1.example.com","grpc.default_authority":"peer1.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org1.example.com","grpc.default_authority":"peer1.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org1.example.com","grpc.default_authority":"peer1.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org1.example.com","grpc.default_authority":"peer1.org1.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer0.org2.example.com","grpc.default_authority":"peer0.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
info: [EventHub.js]: _connect - options {"grpc.ssl_target_name_override":"peer1.org2.example.com","grpc.default_authority":"peer1.org2.example.com","grpc.keepalive_timeout_ms":3000,"grpc.keepalive_time_ms":360000,"grpc.primary_user_agent":"grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4 grpc-node/1.2.4"}
client exited
client exited
Invoke chaincode failed, Error: Failed to get valid event notification
    at channel.sendTransaction.then.then (/home/klenik/test/caliper/src/fabric/e2eUtils.js:615:14)
Invoke chaincode failed, Error: Failed to get valid event notification
    at channel.sendTransaction.then.then (/home/klenik/test/caliper/src/fabric/e2eUtils.js:615:14)
Invoke chaincode failed, Error: Failed to get valid event notification
    at channel.sendTransaction.then.then (/home/klenik/test/caliper/src/fabric/e2eUtils.js:615:14)

After this, every communication attempt results in similar errors.

haojun commented 6 years ago

You can try to remove the old chaincode images, then run the test again to see if the problem can be fixed.

Run 'docker images | grep simple', there should be some images like '...simple..peerx.orgx.example.com...', remove those images using 'docker rmi'

aklenik commented 6 years ago

I think I always removed every image before running a benchmark. So I decided to reproduce the problem in details. But as I was writing this comment, the problem changed, so I provide a detailed step-by-step of what I did. Hopefully, it will be helpful to others.

This is my environment (Ubuntu 16.04 LTS):

klenik@ubuntu:~$ docker --version
Docker version 17.09.1-ce, build 19e2cf6
klenik@ubuntu:~$ docker-compose --version
docker-compose version 1.16.1, build 6d1ac21
klenik@ubuntu:~$ nvm --version
0.33.6
klenik@ubuntu:~$ node --version
v6.12.0
klenik@ubuntu:~$ npm --version
3.10.10

The setup steps I use:

klenik@ubuntu:~$ mkdir caliper_test
klenik@ubuntu:~$ cd caliper_test/

klenik@ubuntu:~/caliper_test$ git clone https://github.com/hyperledger/fabric-sdk-node.git
# commit ID as of now: 1d3facbfd952bac63db4b44c6c6a649c0d8ac9ab
klenik@ubuntu:~/caliper_test$ cd fabric-sdk-node/

klenik@ubuntu:~/caliper_test/fabric-sdk-node$ npm install
klenik@ubuntu:~/caliper_test/fabric-sdk-node$ npm test
# all 623 tests pass

klenik@ubuntu:~/caliper_test/fabric-sdk-node$ cd ..
klenik@ubuntu:~/caliper_test$ git clone https://github.com/Huawei-OSG/caliper.git
# commit ID as of now: 76ed4840719fa6263f0371650867881b6839e39d
klenik@ubuntu:~/caliper_test$ cd caliper/

klenik@ubuntu:~/caliper_test/caliper$ npm install
klenik@ubuntu:~/caliper_test/caliper$ rsync -avq /home/klenik/caliper_test/fabric-sdk-node/node_modules /home/klenik/caliper_test/caliper/ --exclude 'table'
# table package has to be excluded due to version mismatch, this should be mentioned in the docs

klenik@ubuntu:~/caliper_test/caliper$ docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
klenik@ubuntu:~/caliper_test/caliper$ docker images
REPOSITORY          TAG                 IMAGE ID            CREATED             SIZE
# no containers/images present

klenik@ubuntu:~/caliper_test/caliper$ cd benchmark/simple/
klenik@ubuntu:~/caliper_test/caliper/benchmark/simple$ node main.js

# lot of error outputs after round 0, except for the query round:
error: [client-utils.js]: sendPeersProposal - Promise is rejected: Error: Error executing chaincode: Failed to execute transaction (Timeout expired while executing transaction) - make sure the chaincode simple has been successfully instantiated and try again

So I no longer get SSL_read errors, which is good. Although something is wrong after the 1st round. But I can live with that since I only plan to execute one round. So I'm closing this issue now, and thank you for the quick answers!