CCF Node socket connection not close even client close it after connection idle for 10-20 minutes or so

[chantong-ubs]

Built CCF source codes from Oct 4, 2019.

After client established SSL connection with CCF node, client performed some activities and idle for 10-20 minutes or so (roughly, did not count exact minutes). Then, client used the same connection sent request to CCF Node and waited for response, but read time out. Then, client terminated the process, CCF node connection still exist. I observed the file descriptor on CCF Node was increasing from /proc/$pid/fd. Because of this behavior, the CCF Node reached file description limitation (see issue #414).

Attached standard output from CCF Node with command "cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --host-log-level debug --node-address $host_ip:$raft_port --rpc-address $host_ip:$tls_port --public-rpc-address $pub_host_ip:$tls_port --ledger-file $node_id.log --node-cert-file $node_id.pem --quote-file quote$node_id.bin start --network-cert-file network_cert.pem --gov-script gov.lua --app-script madrec_app.lua --member-certs member1_cert.pem "

out.txt

[achamayou]

@chantong-ubs thank you for reporting this issue, we will investigate.

[chantong-ubs]

Any progress? On Wednesday, October 9, 2019, 04:24:47 PM EDT, Amaury Chamayou <notifications@github.com> wrote: @chantong-ubs thank you for reporting this issue, we will investigate. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[chantong-ubs]

Any status update? On Tuesday, October 15, 2019, 10:09:14 AM EDT, Chan Tong <chantong00@yahoo.com> wrote: Any progress? On Wednesday, October 9, 2019, 04:24:47 PM EDT, Amaury Chamayou <notifications@github.com> wrote: @chantong-ubs thank you for reporting this issue, we will investigate. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[olgavrou]

Hi @chantong-ubs

I can't seem to reproduce the issue. I am performing the below steps (albeit in python instead of Java), please let me know if this is similar to what you are doing:

• creating a tls client connection with the primary node and use that connection for all the transactions sent
• send ~60 transactions and then sleep for 10 seconds
• after 10 seconds another ~60 transactions are sent and we keep looping this way, sleeping and sending transactions every 10 seconds
• every 10 cycles of the above, sleep for 14 minutes and after 14 minutes of inactivity, continue the transaction/sleep cycle described above

I am querying for the file descriptors every 30 seconds and I can see that they are not increasing

Does this issue persist for you? Can you please provide us with some more details so that we can investigate further? It would be helpful if you could reproduce the issue again and send the below information:

• How many transactions you are issuing over the connection each time
• How many nodes are in the network?
• Which node you are connecting to and sending the transactions to (if you know)
• The out and err files that all the nodes produce

[chantong-ubs]

I believed short inactivity time, you will not see the problem. I believed to reproduce the problem, please increase time  - creating a tls client connection with the primary node and use that connection for all the transactions sent - send ~60 transactions and then sleep for 360 seconds ( > 5 minutes) - after 360 seconds another ~60 transactions are sent and we keep looping this way, sleeping and sending transactions every 360 seconds - every 10 cycles of the above, sleep for 32 minutes (>30 minutes) and after 32 minutes of inactivity, continue the transaction/sleep cycle described above On Monday, October 21, 2019, 10:40:23 AM EDT, olgavrou <notifications@github.com> wrote: Hi @chantong-ubs I can't seem to reproduce the issue. I am performing the below steps (albeit in python instead of Java), please let me know if this is similar to what you are doing: - creating a tls client connection with the primary node and use that connection for all the transactions sent - send ~60 transactions and then sleep for 10 seconds - after 10 seconds another ~60 transactions are sent and we keep looping this way, sleeping and sending transactions every 10 seconds - every 10 cycles of the above, sleep for 14 minutes and after 14 minutes of inactivity, continue the transaction/sleep cycle described above I am querying for the file descriptors every 30 seconds and I can see that they are not increasing Does this issue persist for you? Can you please provide us with some more details so that we can investigate further? It would be helpful if you could reproduce the issue again and send the below information: - How many transactions you are issuing over the connection each time - How many nodes are in the network? - Which node you are connecting to and sending the transactions to (if you know) - The out and err files that all the nodes produce — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[olgavrou]

@chantong-ubs

We believe we have found what was causing the reported issue (plase see #474 )

I have created a temporary tag here: https://github.com/microsoft/CCF/releases/tag/tcp_keepalives

Could please check to see if the change has resolved your issue?

Thank you,
Olga

[chantong-ubs]

From the issue #474, that was the root cause. I will test in the next few days when I free up. Thanks On Wednesday, October 23, 2019, 12:56:53 PM EDT, olgavrou <notifications@github.com> wrote: @chantong-ubs We believe we have found what was causing the reported issue (plase see #474 ) I have created a temporary tag here: https://github.com/microsoft/CCF/releases/tag/tcp_keepalives Could please check to see if the change has resolved your issue? Thank you, Olga — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[chantong-ubs]

Download the zip and ran setup.sh. It failed. Seems the zip file was small and did not have all dependencies.

ccf@ccf-dev:~/CCF-tcp_keepalives/getting_started/setup_vm$ ./setup.sh

• sudo add-apt-repository ppa:ansible/ansible -y
  Hit:1 http://azure.archive.ubuntu.com/ubuntu bionic InRelease
  Hit:2 http://azure.archive.ubuntu.com/ubuntu bionic-updates InRelease
  Hit:3 http://azure.archive.ubuntu.com/ubuntu bionic-backports InRelease
  Hit:4 https://packages.microsoft.com/ubuntu/18.04/prod bionic InRelease
  Hit:5 http://apt.llvm.org/bionic llvm-toolchain-bionic-7 InRelease
  Hit:6 http://security.ubuntu.com/ubuntu bionic-security InRelease
  Hit:7 http://ppa.launchpad.net/ansible/ansible/ubuntu bionic InRelease
  Hit:8 http://ppa.launchpad.net/deadsnakes/ppa/ubuntu bionic InRelease
  Hit:9 https://download.01.org/intel-sgx/sgx_repo/ubuntu bionic InRelease
  Reading package lists... Done
• sudo apt-get update
  Hit:1 http://apt.llvm.org/bionic llvm-toolchain-bionic-7 InRelease
  Hit:2 http://azure.archive.ubuntu.com/ubuntu bionic InRelease
  Hit:3 http://azure.archive.ubuntu.com/ubuntu bionic-updates InRelease
  Hit:4 http://azure.archive.ubuntu.com/ubuntu bionic-backports InRelease
  Hit:5 https://packages.microsoft.com/ubuntu/18.04/prod bionic InRelease
  Hit:6 https://download.01.org/intel-sgx/sgx_repo/ubuntu bionic InRelease
  Hit:7 http://security.ubuntu.com/ubuntu bionic-security InRelease
  Hit:8 http://ppa.launchpad.net/ansible/ansible/ubuntu bionic InRelease
  Hit:9 http://ppa.launchpad.net/deadsnakes/ppa/ubuntu bionic InRelease
  Reading package lists... Done
• sudo apt install ansible -y
  Reading package lists... Done
  Building dependency tree
  Reading state information... Done
  The following packages were automatically installed and are no longer required:
  linux-azure-cloud-tools-5.0.0-1018 linux-azure-cloud-tools-5.0.0-1020 linux-azure-headers-5.0.0-1018 linux-azure-headers-5.0.0-1020
  linux-azure-tools-5.0.0-1018 linux-azure-tools-5.0.0-1020 linux-cloud-tools-5.0.0-1020-azure linux-headers-5.0.0-1020-azure
  linux-image-5.0.0-1020-azure linux-modules-5.0.0-1020-azure linux-tools-5.0.0-1020-azure
  Use 'sudo apt autoremove' to remove them.
  The following packages will be upgraded:
  ansible
  1 upgraded, 0 newly installed, 0 to remove and 32 not upgraded.
  Need to get 5156 kB of archives.
  After this operation, 18.4 kB of additional disk space will be used.
  Get:1 http://ppa.launchpad.net/ansible/ansible/ubuntu bionic/main amd64 ansible all 2.8.6-1ppabionic [5156 kB]
  Fetched 5156 kB in 1s (5921 kB/s)
  (Reading database ... 143661 files and directories currently installed.)
  Preparing to unpack .../ansible_2.8.6-1ppabionic_all.deb ...
  Unpacking ansible (2.8.6-1ppabionic) over (2.8.5-1ppabionic) ...
  Setting up ansible (2.8.6-1ppa~bionic) ...
  Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
• ansible-playbook ccf-dependencies.yml
  [WARNING]: provided hosts list is empty, only localhost is available. Note that the implicit localhost does not match 'all'

PLAY [localhost] ********************************************************************************************************************************

TASK [Gathering Facts] **************************************************************************************************************************
ok: [localhost]

TASK [openenclave : Include vars] ***************************************************************************************************************
ok: [localhost]

TASK [openenclave : Download OpenEnclave source] ************************************************************************************************
changed: [localhost]

TASK [openenclave : Remove Pre-existing OpenEnclave source on the remote] ***********************************************************************
ok: [localhost]

TASK [openenclave : Create directory for OpenEnclave source] ************************************************************************************
changed: [localhost]

TASK [openenclave : Expand OpenEnclave] *********************************************************************************************************
changed: [localhost]

TASK [openenclave : Make OpenEnclave build dir] *************************************************************************************************
changed: [localhost]

TASK [openenclave : Disable Compiler-level Spectre mitigations] *********************************************************************************
changed: [localhost]

TASK [openenclave : Install OpenEnclave dependencies] *******************************************************************************************
[WARNING]: Reset is not implemented for this connection

changed: [localhost]

TASK [openenclave : Install ninja] **************************************************************************************************************
fatal: [localhost]: FAILED! => {"msg": "fragment_class is None"}
to retry, use: --limit @/home/ccf/CCF-tcp_keepalives/getting_started/setup_vm/ccf-dependencies.retry

PLAY RECAP **************************************************************************************************************************************
localhost : ok=9 changed=6 unreachable=0 failed=1

[olgavrou]

@chantong-ubs

Could you please try and checkout the tag via git. Either from a clean repository (git clone <url> --recursive) or from the repository that you have already cloned run:

• git fetch --tags
• git tag -l
• you should be able to see the tcp_keepalive tag
• git checkout tags/tcp_keepalive [-b <branch name>]

and try again. If the setup.sh fails again could you please try to run the ansible step with verbose and let me know about the results, i.e. just run ansible-playbook ccf-dependencies.yml --verbose from the getting_started/setup_vm directory, so we can get more detail on what fails.

If you are short on time you could try to build the new code without running setup.sh. You should be able to build the code from the tcp_keepalive tag by going into CCF/build and running ninja.

Let me know.

Thank you!

[chantong-ubs]

Use Oct 29 source codes + tcp_keepalive, build OK. When running, the new CCF did not recognized CALLER_ID for new memory/user key stores. There was no change on Client Side, only use new member/user key store files.

Attached first node output file.
node0.zip

See detail info on running 3 nodes on the same server:::
[Start Up Commands]

• ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44180 --rpc-address 10.0.0.4:25000 --public-rpc-address 40.85.174.87:25000 --ledger-file 0.log --node-cert-file 0.pem --quote-file quote0.bin start --network-cert-file network_cert.pem --gov-script gov.lua --member-cert member1_cert.pem --member-cert member2_cert.pem --member-cert member3_cert.pem

• ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44181 --rpc-address 10.0.0.4:25001 --public-rpc-address 40.85.174.87:25001 --ledger-file 1.log --node-cert-file 1.pem --quote-file quote1.bin join --network-cert-file network_cert.pem --target-rpc-address 40.85.174.87:25000

• ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44182 --rpc-address 10.0.0.4:25002 --public-rpc-address 40.85.174.87:25002 --ledger-file 2.log --node-cert-file 2.pem --quote-file quote2.bin join --network-cert-file network_cert.pem --target-rpc-address 40.85.174.87:25000

• ./memberclient --cert member1_cert.pem --privk member1_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem add_user --user-cert user1_cert.pem
  {"commit":7,"global_commit":6,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":0},"term":2}

• ./memberclient --cert member2_cert.pem --privk member2_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem vote --proposal-id 0 --accept
  {"commit":9,"global_commit":8,"id":0,"jsonrpc":"2.0","result":true,"term":2}

• ./memberclient --cert member1_cert.pem --privk member1_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem set_lua_app --lua-app-file madrec_app.lua
  {"commit":11,"global_commit":10,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":1},"term":2}

• ./memberclient --cert member2_cert.pem --privk member2_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem vote --proposal-id 1 --accept
  {"commit":13,"global_commit":12,"id":0,"jsonrpc":"2.0","result":true,"term":2}

• ./memberclient --cert member1_cert.pem --privk member1_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem open_network
  {"commit":15,"global_commit":14,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":2},"term":2}

• ./memberclient --cert member2_cert.pem --privk member2_privk.pem --rpc-address 10.0.0.4:25000 --ca network_cert.pem vote --proposal-id 2 --accept
  {"commit":17,"global_commit":16,"id":0,"jsonrpc":"2.0","result":true,"term":2}

[Process Running]
ccf 19602 1 99 17:05 pts/1 00:09:54 ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44180 --rpc-address 10.0.0.4:25000 --public-rpc-address 40.85.174.87:25000 --ledger-file 0.log --node-cert-file 0.pem --quote-file quote0.bin start --network-cert-file network_cert.pem --gov-script gov.lua --member-cert member1_cert.pem --member-cert member2_cert.pem --member-cert member3_cert.pem
ccf 19641 1 99 17:06 pts/1 00:09:00 ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44181 --rpc-address 10.0.0.4:25001 --public-rpc-address 40.85.174.87:25001 --ledger-file 1.log --node-cert-file 1.pem --quote-file quote1.bin join --network-cert-file network_cert.pem --target-rpc-address 40.85.174.87:25000
ccf 19692 1 99 17:06 pts/1 00:07:28 ./cchost --enclave-file libluagenericenc.so.signed --enclave-type debug --node-address 10.0.0.4:44182 --rpc-address 10.0.0.4:25002 --public-rpc-address 40.85.174.87:25002 --ledger-file 2.log --node-cert-file 2.pem --quote-file quote2.bin join --network-cert-file network_cert.pem --target-rpc-address 40.85.174.87:25000

[Runtime Directory]
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 member1_privk.pem
-rw-rw-r-- 1 ccf ccf 661 Oct 31 17:05 member1_cert.pem
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 member2_privk.pem
-rw-rw-r-- 1 ccf ccf 657 Oct 31 17:05 member2_cert.pem
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 member3_privk.pem
-rw-rw-r-- 1 ccf ccf 657 Oct 31 17:05 member3_cert.pem
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 user1_privk.pem
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:05 user1_cert.pem
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 user2_privk.pem
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:05 user2_cert.pem
-rw-rw-r-- 1 ccf ccf 288 Oct 31 17:05 user3_privk.pem
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:05 user3_cert.pem
-rw------- 1 ccf ccf 1073 Oct 31 17:05 member2.p12
-rw------- 1 ccf ccf 1073 Oct 31 17:05 member1.p12
-rw------- 1 ccf ccf 1073 Oct 31 17:05 member3.p12
-rw------- 1 ccf ccf 1061 Oct 31 17:05 user1.p12
-rw------- 1 ccf ccf 1061 Oct 31 17:05 user2.p12
-rw------- 1 ccf ccf 1061 Oct 31 17:05 user3.p12
-rw-rw-r-- 1 ccf ccf 0 Oct 31 17:05 0.err
-rw-rw-r-- 1 ccf ccf 4596 Oct 31 17:05 quote0.bin
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:05 network_cert.pem
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:05 0.pem
-rw-rw-r-- 1 ccf ccf 4686 Oct 31 17:05 sealed_secrets.20191031170552.19602
-rw-rw-r-- 1 ccf ccf 0 Oct 31 17:06 1.err
-rw-rw-r-- 1 ccf ccf 4596 Oct 31 17:06 quote1.bin
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:06 1.pem
-rw-rw-r-- 1 ccf ccf 4634 Oct 31 17:06 sealed_secrets.20191031170625.19641
-rw-rw-r-- 1 ccf ccf 0 Oct 31 17:06 2.err
-rw-rw-r-- 1 ccf ccf 4596 Oct 31 17:06 quote2.bin
-rw-rw-r-- 1 ccf ccf 653 Oct 31 17:06 2.pem
-rw-rw-r-- 1 ccf ccf 4665 Oct 31 17:07 sealed_secrets.20191031170700.19692
-rw-rw-r-- 1 ccf ccf 12325 Oct 31 17:16 madrec.out
-rw-rw-r-- 1 ccf ccf 25132 Oct 31 17:16 madrec.err
-rw-rw-r-- 1 ccf ccf 76395 Oct 31 17:16 0.log
-rw-rw-r-- 1 ccf ccf 76214 Oct 31 17:16 1.log
-rw-rw-r-- 1 ccf ccf 76214 Oct 31 17:16 2.log
-rw-rw-r-- 1 ccf ccf 3433342 Oct 31 17:16 2.out
-rw-rw-r-- 1 ccf ccf 3636185 Oct 31 17:16 1.out
-rw-rw-r-- 1 ccf ccf 4567001 Oct 31 17:16 0.out

[Error Log - when used member1.p12 or user1.p12]

com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field "error" (class com.ubs.madrec.ccbf.rpc.Rpc$Response), not marked as ignorable (6 known properties: "global_commit", "commit", "id", "term", "jsonrpc", "result"])
at [Source: (byte[])"��error��codeт��message�:[INVALID_CALLER_ID]: No corresponding caller entry exists.�id^@�jsonrpc�2.0"; line: -1, column: 8] (through reference chain: com.ubs.madrec.ccbf.rpc.Rpc$Response["error"])
at com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:60)
at com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:823)
at com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:1153)
at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1589)
at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1567)
at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:294)
at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:151)
at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4013)
at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3091)
at com.ubs.madrec.ccbf.rpc.RpcTlsClient.call(RpcTlsClient.java:44)
at com.ubs.madrec.ccbf.rpc.RpcTlsClient.callR(RpcTlsClient.java:65)
at com.ubs.madrec.ccbf.clients.MemberImpl.addClient(MemberImpl.java:41)
at com.ubs.madrec.ccbf.clients.MemberImpl.addUser(MemberImpl.java:53)
at com.ubs.madrec.coco.ServiceContainer.init(ServiceContainer.java:33

[achamayou]

@chantong-ubs I'm not sure what the p12 files are, but the identities you have voted in as users are the .pem files, so those ought to work. Can you make sure you are using identities that have been voted in as users to connect?