search

microsoft / CCF

Confidential Consortium Framework
https://microsoft.github.io/CCF/
Apache License 2.0
766 stars 207 forks source link

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

Closed chantong-ubs closed 4 years ago

chantong-ubs commented 4 years ago

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 commented 4 years ago

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

chantong-ubs commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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:

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:

chantong-ubs commented 4 years ago

I believed short inactivity time, you will not see the problem. I believed to reproduce the problem, please increase time 

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:

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:

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

olgavrou commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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

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 commented 4 years ago

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

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 commented 4 years ago

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]

[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 commented 4 years ago

@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?

chantong-ubs commented 4 years ago

It’s been working all the time for all previous versions. It’s not the problem the identity file that I used. I suspected it’s something to do with all pem files to add members users in CCF. This process has been changed in this version. Please look into this direction. I tried several times to start new CCF network from scratch, same problem

Sent from my iPhone

On Nov 1, 2019, at 3:42 AM, Amaury Chamayou notifications@github.com wrote:

@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?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

olgavrou commented 4 years ago

Hi @chantong-ubs

The way we add users and members last changed here: https://github.com/microsoft/CCF/pull/371

We also have our tests consistently passing and verifying that users and members have been added correctly and can access the network afterwards.

For example e2e_logging.py test which runs on every CI build:

Can you please provide us with more details and a reproducible example?

Thank you!

chantong-ubs commented 4 years ago

Read all documents, but it did not help to resolve the issue. In previous email, it had all commands (which I followed from github document (https://microsoft.github.io/CCF). Anyone read and verify all CCF commands from my previous email? It had start, join, adduser, add lua, open network. You can reproduce with the same command as below (from previous email)

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}

achamayou commented 4 years ago

@chantong-ubs we have reviewed your commands, but it is not possible for us to reproduce your issue because:

  1. we do not have a copy of gov.lua or madrec_app.lua
  2. we do not know what the p12 files are or how they are used, the step you show failing is a java stack trace, and we do not have a java client

As @olgavrou pointed out, all our end to end test start by adding users, and they all pass. We have reviewed the user checking logic (https://github.com/microsoft/CCF/blob/master/src/node/rpc/frontend.h#L687), which is a table lookup, and we have no reason to believe it is broken.

The automated test we have that is closest to what you describe is the lua_end_to_end_logging test, which you can run with: ./tests.sh -VV -R lua_end_to_end_logging.

Please find inline below the relevant output section to be compared to your commands, and feel free to reproduce it in your environment. If you would like to provide more information, we'll be happy to investigate further, but as it stands we've done all we can. I can only suggest making sure that all the certs are in sync, and that you aren't trying to connect with newer/outdated certs.

41: 2019-11-04 17:13:11.989 | INFO     | infra.path:working_dir:78 - cd .
41: 2019-11-04 17:13:11.989 | INFO     | infra.proc:ccall:11 - rm -f
41: 2019-11-04 17:13:11.991 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=member1
41: 2019-11-04 17:13:11.997 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=member2
41: 2019-11-04 17:13:12.003 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=member3
41: 2019-11-04 17:13:12.010 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=user1
41: 2019-11-04 17:13:12.017 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=user2
41: 2019-11-04 17:13:12.023 | INFO     | infra.proc:ccall:11 - ./keygenerator --name=user3
41: 2019-11-04 17:13:12.030 | INFO     | infra.proc:ccall:11 - cp /data/src/CCF/src/runtime_config/gov.lua .
41: 2019-11-04 17:13:12.032 | INFO     | infra.ccf:start_and_join:210 - Lua scripts copied
41: 2019-11-04 17:13:12.032 | INFO     | infra.ccf:_start_all_nodes:153 - Opening CCF service on ['localhost', 'localhost']
41: 2019-11-04 17:13:12.033 | INFO     | infra.remote:_rc:347 - [127.179.219.152] rm -rf /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.034 | INFO     | infra.remote:_rc:347 - [127.179.219.152] mkdir -p /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.036 | INFO     | infra.remote:_rc:347 - [127.179.219.152] ln -s /data/src/CCF/build/cchost /data/src/CCF/build/workspace/lua_end_to_end_logging_0/cchost
41: 2019-11-04 17:13:12.038 | INFO     | infra.remote:_rc:347 - [127.179.219.152] ln -s /data/src/CCF/build/./libluagenericenc.so.signed /data/src/CCF/build/workspace/lua_end_to_end_logging_0/libluagenericenc.so.signed
41: 2019-11-04 17:13:12.039 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/member1_cert.pem /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.041 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/member2_cert.pem /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.043 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/member3_cert.pem /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.045 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/gov.lua /data/src/CCF/build/workspace/lua_end_to_end_logging_0
41: 2019-11-04 17:13:12.047 | INFO     | infra.remote:start:384 - [127.179.219.152] cd /data/src/CCF/build/workspace/lua_end_to_end_logging_0 && ./cchost --enclave-file=./libluagenericenc.so.signed --enclave-type=debug --node-address=127.179.219.152:35927 --rpc-address=127.179.219.152:36763 --public-rpc-address=127.179.219.152:36763 --ledger-file=0.ledger --node-cert-file=0.pem --host-log-level=info --raft-election-timeout-ms=100000 --notify-server-address=localhost:58857 --quote-file=quote0.bin start --network-cert-file=networkcert.pem --gov-script=gov.lua --member-cert=member1_cert.pem --member-cert=member2_cert.pem --member-cert=member3_cert.pem 1>/data/src/CCF/build/workspace/lua_end_to_end_logging_0/out 2>/data/src/CCF/build/workspace/lua_end_to_end_logging_0/err (env: {'HOME': '/home/amchamay', 'OE_LOG_LEVEL': 'WARNING'})
41: 2019-11-04 17:13:14.052 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/workspace/lua_end_to_end_logging_0/0.pem 0.pem
41: 2019-11-04 17:13:14.054 | INFO     | infra.remote:_rc:347 - [127.179.219.152] cp /data/src/CCF/build/workspace/lua_end_to_end_logging_0/networkcert.pem networkcert.pem
41: 2019-11-04 17:13:14.056 | INFO     | infra.ccf:_start:911 - Remote 0 started
41: 2019-11-04 17:13:14.112 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/getPrimaryInfo {} (node 0 (node))
41: 2019-11-04 17:13:14.112 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'primary_host': b'127.179.219.152', 'primary_id': 0, 'primary_port': b'36763'}, 'error': None, 'jsonrpc': b'2.0', 'commit': 2, 'term': 2, 'global_commit': 2}
41: 2019-11-04 17:13:14.113 | INFO     | infra.remote:_rc:347 - [127.83.53.188] rm -rf /data/src/CCF/build/workspace/lua_end_to_end_logging_1
41: 2019-11-04 17:13:14.115 | INFO     | infra.remote:_rc:347 - [127.83.53.188] mkdir -p /data/src/CCF/build/workspace/lua_end_to_end_logging_1
41: 2019-11-04 17:13:14.116 | INFO     | infra.remote:_rc:347 - [127.83.53.188] ln -s /data/src/CCF/build/cchost /data/src/CCF/build/workspace/lua_end_to_end_logging_1/cchost
41: 2019-11-04 17:13:14.118 | INFO     | infra.remote:_rc:347 - [127.83.53.188] ln -s /data/src/CCF/build/./libluagenericenc.so.signed /data/src/CCF/build/workspace/lua_end_to_end_logging_1/libluagenericenc.so.signed
41: 2019-11-04 17:13:14.120 | INFO     | infra.remote:_rc:347 - [127.83.53.188] cp /data/src/CCF/build/networkcert.pem /data/src/CCF/build/workspace/lua_end_to_end_logging_1
41: 2019-11-04 17:13:14.122 | INFO     | infra.remote:start:384 - [127.83.53.188] cd /data/src/CCF/build/workspace/lua_end_to_end_logging_1 && ./cchost --enclave-file=./libluagenericenc.so.signed --enclave-type=debug --node-address=127.83.53.188:41735 --rpc-address=127.83.53.188:37063 --public-rpc-address=127.83.53.188:37063 --ledger-file=1.ledger --node-cert-file=1.pem --host-log-level=info --raft-election-timeout-ms=100000 --notify-server-address=localhost:58857 --quote-file=quote1.bin join --network-cert-file=networkcert.pem --target-rpc-address=127.179.219.152:36763 1>/data/src/CCF/build/workspace/lua_end_to_end_logging_1/out 2>/data/src/CCF/build/workspace/lua_end_to_end_logging_1/err (env: {'HOME': '/home/amchamay', 'OE_LOG_LEVEL': 'WARNING'})
41: 2019-11-04 17:13:15.125 | INFO     | infra.remote:_rc:347 - [127.83.53.188] cp /data/src/CCF/build/workspace/lua_end_to_end_logging_1/1.pem 1.pem
41: 2019-11-04 17:13:15.128 | INFO     | infra.ccf:_start:911 - Remote 1 started
41: 2019-11-04 17:13:16.008 | INFO     | infra.jsonrpc:log_request:228 - [127.83.53.188:37063] #0 nodes/getCommit {} (node 1 (node))
41: 2019-11-04 17:13:16.008 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'commit': 0, 'term': 0}, 'error': None, 'jsonrpc': b'2.0', 'commit': 0, 'term': 2, 'global_commit': 0}
41: 2019-11-04 17:13:16.008 | INFO     | infra.ccf:_start_all_nodes:188 - All remotes started
41: 2019-11-04 17:13:16.064 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/getPrimaryInfo {} (node 0 (node))
41: 2019-11-04 17:13:16.074 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'primary_host': b'127.179.219.152', 'primary_id': 0, 'primary_port': b'36763'}, 'error': None, 'jsonrpc': b'2.0', 'commit': 4, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.132 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 members/query {'text': 'tables = ...\n                    return tables["ccf.service"]:get(0)'} (node 0 (member))
41: 2019-11-04 17:13:16.142 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'cert': [45, 45, 45, 45, 45, 66, 69, 71, 73, 78, 32, 67, 69, 82, 84, 73, 70, 73, 67, 65, 84, 69, 45, 45, 45, 45, 45, 10, 77, 73, 73, 66, 116, 106, 67, 67, 65, 84, 117, 103, 65, 119, 73, 66, 65, 103, 73, 82, 65, 75, 76, 122, 118, ...
41: 2019-11-04 17:13:16.196 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/getCommit {} (node 0 (node))
41: 2019-11-04 17:13:16.206 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'commit': 4, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 4, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.260 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/getCommit {} (node 0 (node))
41: 2019-11-04 17:13:16.270 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'commit': 4, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 4, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.328 | INFO     | infra.jsonrpc:log_request:228 - [127.83.53.188:37063] #0 nodes/getCommit {} (node 1 (node))
41: 2019-11-04 17:13:16.338 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'commit': 4, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 4, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.338 | SUCCESS  | infra.ccf:start_and_join:219 - All nodes joined network
41: 2019-11-04 17:13:16.338 | INFO     | infra.proc:ccall:11 - cp /data/src/CCF/src/apps/logging/logging.lua .
41: 2019-11-04 17:13:16.357 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem set_lua_app --lua-app-file=/data/src/CCF/src/apps/logging/logging.lua
41: 2019-11-04 17:13:16.483 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":5,"global_commit":4,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":0},"term":2}
41: 2019-11-04 17:13:16.483 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=0 --accept 
41: 2019-11-04 17:13:16.620 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":6,"global_commit":4,"id":0,"jsonrpc":"2.0","result":false,"term":2}
41: 2019-11-04 17:13:16.621 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member2_cert.pem --privk=member2_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=0 --accept 
41: 2019-11-04 17:13:16.755 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":7,"global_commit":4,"id":0,"jsonrpc":"2.0","result":true,"term":2}
41: 2019-11-04 17:13:16.812 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/mkSign {} (node 0 (node))
41: 2019-11-04 17:13:16.822 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': True, 'error': None, 'jsonrpc': b'2.0', 'commit': 8, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.822 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #1 nodes/getCommit {'commit': 7} (node 0 (node))
41: 2019-11-04 17:13:16.833 | DEBUG    | infra.jsonrpc:log_response:239 - #1 {'id': 1, 'result': {'commit': 7, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 8, 'term': 2, 'global_commit': 4}
41: 2019-11-04 17:13:16.933 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #2 nodes/getCommit {'commit': 7} (node 0 (node))
41: 2019-11-04 17:13:16.943 | DEBUG    | infra.jsonrpc:log_response:239 - #2 {'id': 2, 'result': {'commit': 7, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 8, 'term': 2, 'global_commit': 8}
41: 2019-11-04 17:13:16.944 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem add_user --user-cert=user1_cert.pem
41: 2019-11-04 17:13:17.067 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":9,"global_commit":8,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":1},"term":2}
41: 2019-11-04 17:13:17.068 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=1 --accept 
41: 2019-11-04 17:13:17.199 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":10,"global_commit":8,"id":0,"jsonrpc":"2.0","result":false,"term":2}
41: 2019-11-04 17:13:17.199 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member2_cert.pem --privk=member2_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=1 --accept 
41: 2019-11-04 17:13:17.332 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":11,"global_commit":8,"id":0,"jsonrpc":"2.0","result":true,"term":2}
41: 2019-11-04 17:13:17.384 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/mkSign {} (node 0 (node))
41: 2019-11-04 17:13:17.394 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': True, 'error': None, 'jsonrpc': b'2.0', 'commit': 12, 'term': 2, 'global_commit': 8}
41: 2019-11-04 17:13:17.394 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #1 nodes/getCommit {'commit': 11} (node 0 (node))
41: 2019-11-04 17:13:17.404 | DEBUG    | infra.jsonrpc:log_response:239 - #1 {'id': 1, 'result': {'commit': 11, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 12, 'term': 2, 'global_commit': 8}
41: 2019-11-04 17:13:17.505 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #2 nodes/getCommit {'commit': 11} (node 0 (node))
41: 2019-11-04 17:13:17.515 | DEBUG    | infra.jsonrpc:log_response:239 - #2 {'id': 2, 'result': {'commit': 11, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 12, 'term': 2, 'global_commit': 12}
41: 2019-11-04 17:13:17.515 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem add_user --user-cert=user2_cert.pem
41: 2019-11-04 17:13:17.647 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":13,"global_commit":12,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":2},"term":2}
41: 2019-11-04 17:13:17.647 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=2 --accept 
41: 2019-11-04 17:13:17.775 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":14,"global_commit":12,"id":0,"jsonrpc":"2.0","result":false,"term":2}
41: 2019-11-04 17:13:17.775 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member2_cert.pem --privk=member2_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=2 --accept 
41: 2019-11-04 17:13:17.907 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":15,"global_commit":12,"id":0,"jsonrpc":"2.0","result":true,"term":2}
41: 2019-11-04 17:13:17.964 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/mkSign {} (node 0 (node))
41: 2019-11-04 17:13:17.974 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': True, 'error': None, 'jsonrpc': b'2.0', 'commit': 16, 'term': 2, 'global_commit': 12}
41: 2019-11-04 17:13:17.974 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #1 nodes/getCommit {'commit': 15} (node 0 (node))
41: 2019-11-04 17:13:17.984 | DEBUG    | infra.jsonrpc:log_response:239 - #1 {'id': 1, 'result': {'commit': 15, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 16, 'term': 2, 'global_commit': 12}
41: 2019-11-04 17:13:18.085 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #2 nodes/getCommit {'commit': 15} (node 0 (node))
41: 2019-11-04 17:13:18.095 | DEBUG    | infra.jsonrpc:log_response:239 - #2 {'id': 2, 'result': {'commit': 15, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 16, 'term': 2, 'global_commit': 16}
41: 2019-11-04 17:13:18.095 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem add_user --user-cert=user3_cert.pem
41: 2019-11-04 17:13:18.223 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":17,"global_commit":16,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":3},"term":2}
41: 2019-11-04 17:13:18.223 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=3 --accept 
41: 2019-11-04 17:13:18.363 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":18,"global_commit":16,"id":0,"jsonrpc":"2.0","result":false,"term":2}
41: 2019-11-04 17:13:18.364 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member2_cert.pem --privk=member2_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=3 --accept 
41: 2019-11-04 17:13:18.491 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":19,"global_commit":16,"id":0,"jsonrpc":"2.0","result":true,"term":2}
41: 2019-11-04 17:13:18.548 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/mkSign {} (node 0 (node))
41: 2019-11-04 17:13:18.558 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': True, 'error': None, 'jsonrpc': b'2.0', 'commit': 20, 'term': 2, 'global_commit': 16}
41: 2019-11-04 17:13:18.564 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #1 nodes/getCommit {'commit': 19} (node 0 (node))
41: 2019-11-04 17:13:18.564 | DEBUG    | infra.jsonrpc:log_response:239 - #1 {'id': 1, 'result': {'commit': 19, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 20, 'term': 2, 'global_commit': 16}
41: 2019-11-04 17:13:18.664 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #2 nodes/getCommit {'commit': 19} (node 0 (node))
41: 2019-11-04 17:13:18.664 | DEBUG    | infra.jsonrpc:log_response:239 - #2 {'id': 2, 'result': {'commit': 19, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 20, 'term': 2, 'global_commit': 20}
41: 2019-11-04 17:13:18.665 | INFO     | infra.ccf:start_and_join:226 - Initial set of users added
41: 2019-11-04 17:13:18.665 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem open_network
41: 2019-11-04 17:13:18.799 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":21,"global_commit":20,"id":0,"jsonrpc":"2.0","result":{"completed":false,"id":4},"term":2}
41: 2019-11-04 17:13:18.800 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member1_cert.pem --privk=member1_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=4 --accept 
41: 2019-11-04 17:13:18.935 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":22,"global_commit":20,"id":0,"jsonrpc":"2.0","result":false,"term":2}
41: 2019-11-04 17:13:18.935 | INFO     | infra.proc:ccall:11 - ./memberclient --cert=member2_cert.pem --privk=member2_privk.pem --rpc-address=127.179.219.152:36763 --ca=networkcert.pem vote --proposal-id=4 --accept 
41: 2019-11-04 17:13:19.065 | DEBUG    | infra.proc:ccall:14 - stdout: {"commit":23,"global_commit":20,"id":0,"jsonrpc":"2.0","result":true,"term":2}
41: 2019-11-04 17:13:19.120 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 nodes/mkSign {} (node 0 (node))
41: 2019-11-04 17:13:19.130 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': True, 'error': None, 'jsonrpc': b'2.0', 'commit': 25, 'term': 2, 'global_commit': 20}
41: 2019-11-04 17:13:19.130 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #1 nodes/getCommit {'commit': 23} (node 0 (node))
41: 2019-11-04 17:13:19.130 | DEBUG    | infra.jsonrpc:log_response:239 - #1 {'id': 1, 'result': {'commit': 23, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 25, 'term': 2, 'global_commit': 20}
41: 2019-11-04 17:13:19.231 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #2 nodes/getCommit {'commit': 23} (node 0 (node))
41: 2019-11-04 17:13:19.231 | DEBUG    | infra.jsonrpc:log_response:239 - #2 {'id': 2, 'result': {'commit': 23, 'term': 2}, 'error': None, 'jsonrpc': b'2.0', 'commit': 25, 'term': 2, 'global_commit': 25}
41: 2019-11-04 17:13:19.288 | INFO     | infra.jsonrpc:log_request:228 - [127.179.219.152:36763] #0 members/query {'text': 'tables = ...\n                    return tables["ccf.service"]:get(0)'} (node 0 (member))
41: 2019-11-04 17:13:19.298 | DEBUG    | infra.jsonrpc:log_response:239 - #0 {'id': 0, 'result': {'cert': [45, 45, 45, 45, 45, 66, 69, 71, 73, 78, 32, 67, 69, 82, 84, 73, 70, 73, 67, 65, 84, 69, 45, 45, 45, 45, 45, 10, 77, 73, 73, 66, 116, 106, 67, 67, 65, 84, 117, 103, 65, 119, 73, 66, 65, 103, 73, 82, 65, 75, 76, 122, 118, ...
41: 2019-11-04 17:13:19.299 | SUCCESS  | infra.ccf:start_and_join:229 - ***** Network is now open *****
chantong-ubs commented 4 years ago

Same argument was I can not use Python to verify my problem (my problem happened on the command/sequence that gave you). I want to make sure all CCF command requests and responses were good from your point of view. I attached Lua codes (please rename/remove .xtx) to see if it helps on your side.

gov.lua.txt madrec_app.lua.txt

For p12 file, you will use member pem and cert and export into keystore (see below command) openssl pkcs12 -export -in member2_cert.pem -inkey member2_privk.pem -out member2.p12 -name member2 -passout pass:password

chantong-ubs commented 4 years ago

To make it more clear, all CCF lua codes did not change, all Java client codes did not change. I am using the same codes with different CCF version/command. I have done more than 30 times with previous CCF version with no problem. The version that I had problem was different and I am not sure I did everything right from the document. That's reason I suspected new CCF version

olgavrou commented 4 years ago

Hi @chantong-ubs

Since we do not have the Java client that you are using, the simplest thing to do now would be for you to run ./tests.sh -VV -R lua_end_to_end_logging on your environment. That way we will easily verify if there is a problem with CCF adding users or if it is an issue on the Java client side and/or the p12 files that you are using.

Thank you, Olga

achamayou commented 4 years ago

@chantong-ubs I can only think of two things:

  1. Your client is connecting to a follower, which hasn't replicated the new user entry yet. That should be easy to rule out by waiting a bit before trying, which I imagine you have already. This isn't new behaviour though.
  2. There is a discrepancy in the cert, and the easiest way to confirm it is to write the client cert to the log on every new connection. I'm happy to add that on a branch, which you can then try to compare the client cert CCF sees with what's been uploaded to the KV via the add_user member voter.
chantong-ubs commented 4 years ago

About the follower, I had 3 nodes. As you can see from the command/response, member 1 proposed and member 2 accepted. I tried member 3 to accept, but the response returned already accepted with enough quorum. This should not be an issue.

2, yes, needs more debugging to verify the cert

achamayou commented 4 years ago

@chantong-ubs I've pushed a branch called log_client_certs (https://github.com/microsoft/CCF/tree/log_client_certs). Please build with -DVERBOSE_LOGGING=ON, and you will get the full client cert as PEM logged on every RPC. I hope this helps.

chantong-ubs commented 4 years ago

K, I will use the below commands to get source codes. Please verify this is correct.

git clone -b log_client_certs --recursive https://github.com/microsoft/CCF.git git fetch --tags git tag -l git checkout tags/tcp_keepalives

achamayou commented 4 years ago

@chantong-ubs just the first command please (—recursive is no longer needed but won’t cause problems either).

achamayou commented 4 years ago

@chantong-ubs #501 (https://microsoft.github.io/CCF/users/issue_commands.html) changed RPCs to use a prefix, so you will need to add "users/" in front of your user rpcs ("members/" for members RPC).

This is to remove the need for SNI to be used and part of our move towards REST.

chantong-ubs commented 4 years ago

I'm not familiar with the code to change. Can you be more specific about the change? Add prefix is easy, but where exactly?

achamayou commented 4 years ago

To all methods in jsonrpc messages, as per https://microsoft.github.io/CCF/users/issue_commands.html

$ cat request.json
{
  "id": 0,
  "method": "users/LOG_record",
  "jsonrpc": "2.0",
  "params":
  {
    "id": 42,
    "msg": "Hello There"
  }
}

which before would have been:

$ cat request.json
{
  "id": 0,
  "method": "LOG_record",
  "jsonrpc": "2.0",
  "params":
  {
    "id": 42,
    "msg": "Hello There"
  }
}
chantong-ubs commented 4 years ago

After changed method, still getting the same error, see JSON request:

TlsClient startConnection: Socket[addr=/52.234.133.170,port=25000,localport=49206] callR REQ:com.ubs.madrec.ccbf.clients.MemberImpl$Proposal@719a6f6c RpcTlsClient call REQ:{"jsonrpc":"2.0","id":1,"method":"users/propose","params":{"script":{"text":"tables, user_cert = ...\nreturn Calls:call(\"new_user\", user_cert)"},"parameter":[48,-126,1,-75,48,-126,1,57,-96,3,2,1,2,2,17,0,-26,-73,-111,49,-59,82,-75,49,43,-14,-118,-79,-110,-33,4,-111,48,12,6,8,42,-122,72,-50,61,4,3,3,5,0,48,16,49,14,48,12,6,3,85,4,3,12,5,117,115,101,114,49,48,32,23,13,48,49,48,49,48,49,48,48,48,48,48,48,90,24,15,50,49,48,48,49,50,51,49,50,51,53,57,53,57,90,48,16,49,14,48,12,6,3,85,4,3,12,5,117,115,101,114,49,48,118,48,16,6,7,42,-122,72,-50,61,2,1,6,5,43,-127,4,0,34,3,98,0,4,-124,-44,64,-122,-109,55,19,12,-26,-23,-2,-74,-61,-21,78,-52,-58,-56,64,60,91,28,79,-47,-3,115,45,-60,94,37,-113,-33,-43,47,-45,-22,56,76,55,99,-90,-2,-99,-34,70,0,-30,65,105,-7,-75,-69,-124,-71,-40,125,-39,-40,-39,27,-54,99,122,-84,-29,89,-117,-72,14,-115,3,-56,-13,40,-37,-46,4,44,-9,74,-90,41,-94,-68,8,118,-27,90,37,60,-45,-89,95,-28,102,97,-93,83,48,81,48,15,6,3,85,29,19,4,8,48,6,1,1,-1,2,1,0,48,29,6,3,85,29,14,4,22,4,20,40,-123,-2,-80,33,-25,83,-112,-17,109,-70,-125,-6,119,114,93,9,125,-40,127,48,31,6,3,85,29,35,4,24,48,22,-128,20,40,-123,-2,-80,33,-25,83,-112,-17,109,-70,-125,-6,119,114,93,9,125,-40,127,48,12,6,8,42,-122,72,-50,61,4,3,3,5,0,3,104,0,48,101,2,49,0,-85,-91,-54,8,-95,-125,109,51,-83,-18,-57,-110,-96,77,79,-112,5,67,103,69,-127,-26,12,74,-73,9,-71,66,9,-28,46,-120,-99,-124,47,-31,-36,51,-97,-40,-112,123,-43,127,-18,49,-47,74,2,48,117,-85,0,0,22,2,42,-56,16,60,123,81,111,126,-70,-41,-45,5,-74,-76,-11,-81,-38,20,116,32,75,94,-104,-113,53,-100,-90,7,-43,-73,-6,40,-21,20,29,-60,-115,-61,-3,-94,-103,-62]}}

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�@[METHOD_NOT_FOUND]: No handler script found for method 'propose'�id^A�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:66) 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) at com.ubs.madrec.coco.controller.CredentialsRestController.getCertificate(CredentialsRestController.java:130)

achamayou commented 4 years ago

propose is a members method, so that should be "members/propose". Only RPCs on the user frontend (ie. madrec specific code) are "users/".

achamayou commented 4 years ago

@chantong-ubs solved offline.