CCF icon indicating copy to clipboard operation
CCF copied to clipboard

Published 20 hours ago • verified publisher icon microsoft

2.0.4-sgx: sandbox.sh: PrimaryNotFound

Open divneil-intel opened this issue 3 years ago • 4 comments

Describe the bug I am trying to setup base 2.0.4 CCF to work upon. So, as a basic test I am running sandbox.sh and it is throwing PrimaryNotFound error.

To Reproduce Dockerfile

FROM mcr.microsoft.com/ccf/app/dev:2.0.4-sgx
CMD /opt/ccf/bin/sandbox.sh -v

docker build -t ccf-base - < Dockerfile docker run -ti ccf-base

Expected behavior Per CCF documentation, I should have the JS logging app running.

Environment information Ubuntu 18.04 - No SGX

Logs

Setting up Python environment...
No package/app specified. Defaulting to installed JS logging app
Python environment successfully setup
00:47:27.910 | WARNING  | __main__:run:42 - Virtual mode enabled
00:47:27.910 | INFO     | __main__:run:43 - Starting 1 CCF node...
00:47:27.910 | INFO     | infra.network:_setup_common_folder:395 - Creating common folder: /workspace/sandbox_common
00:47:27.911 | INFO     | infra.proc:ccall:11 - rm -rf /workspace/sandbox_common
00:47:27.914 | INFO     | infra.proc:ccall:11 - mkdir -p /workspace/sandbox_common
00:47:27.917 | INFO     | infra.proc:ccall:11 - cp /opt/ccf/bin/actions.js /workspace/sandbox_common
00:47:27.920 | INFO     | infra.proc:ccall:11 - cp /opt/ccf/bin/validate.js /workspace/sandbox_common
00:47:27.923 | INFO     | infra.proc:ccall:11 - cp /opt/ccf/bin/resolve.js /workspace/sandbox_common
00:47:27.926 | INFO     | infra.proc:ccall:11 - cp /opt/ccf/bin/apply.js /workspace/sandbox_common
00:47:27.928 | INFO     | infra.proc:ccall:11 - ln -s /keygenerator.sh /workspace/sandbox_common
00:47:27.931 | INFO     | infra.proc:ccall:11 - /opt/ccf/bin/keygenerator.sh --name member0 --curve secp384r1 --gen-enc-key [cwd: /workspace/sandbox_common]
00:47:28.051 | INFO     | infra.member:__init__:112 - Member member0 created: bdaf80a2a77b63b0aa1437432252bc5f0e867843c3e892abe41fc687be10c59c
00:47:28.052 | DEBUG    | infra.network:_start_all_nodes:325 - Opening CCF service on [HostSpec(rpc_interfaces={'primary_rpc_interface': RPCInterface(host='127.0.0.1', port=8000, protocol='local', public_host=None, public_port=None, max_open_sessions_soft=1000, max_open_sessions_hard=1010, max_http_body_size=1048576, max_http_header_size=16384, max_http_headers_count=256, endorsement=Endorsement(authority=<EndorsementAuthority.Service: 1>))})]
00:47:28.062 | INFO     | infra.remote:_rc:434 - [127.0.0.1] rm -rf /workspace/sandbox_0
00:47:28.066 | INFO     | infra.remote:_rc:434 - [127.0.0.1] mkdir -p /workspace/sandbox_0
00:47:28.070 | INFO     | infra.remote:_rc:434 - [127.0.0.1] ln -s /workspace/sandbox_common/0.config.json /workspace/sandbox_0/0.config.json
00:47:28.073 | INFO     | infra.remote:_rc:434 - [127.0.0.1] ln -s /opt/ccf/bin/cchost /workspace/sandbox_0/cchost
00:47:28.076 | INFO     | infra.remote:_rc:434 - [127.0.0.1] ln -s /opt/ccf/lib/libjs_generic.virtual.so /workspace/sandbox_0/libjs_generic.virtual.so
00:47:28.080 | INFO     | infra.remote:start:484 - [127.0.0.1] cd /workspace/sandbox_0 && ./cchost --config /workspace/sandbox_common/0.config.json 1> /workspace/sandbox_0/out 2> /workspace/sandbox_0/err (env: {'UBSAN_OPTIONS': 'print_stacktrace=1'})
00:47:28.284 | INFO     | infra.remote:_rc:434 - [127.0.0.1] cp /workspace/sandbox_0/0.pem /workspace/sandbox_common/0.pem
00:47:28.288 | INFO     | infra.remote:_rc:434 - [127.0.0.1] cp /workspace/sandbox_0/0.node_address /workspace/sandbox_common/0.node_address
00:47:28.292 | INFO     | infra.remote:_rc:434 - [127.0.0.1] cp /workspace/sandbox_0/0.rpc_addresses /workspace/sandbox_common/0.rpc_addresses
00:47:28.295 | INFO     | infra.remote:_rc:434 - [127.0.0.1] cp /workspace/sandbox_0/service_cert.pem /workspace/sandbox_common/service_cert.pem
00:47:28.299 | INFO     | infra.node:_start:345 - Node 0 started: c62b2244553f7b9658dd3cce7b8ad99a778e968a387cc8b26e97bf9c88e318ec
00:47:28.300 | INFO     | infra.network:_start_all_nodes:385 - All nodes started
00:47:28.301 | DEBUG    | infra.clients:request:369 - Running: curl https://127.0.0.1:8000/node/network -X GET -i -m 1 -L --cacert /workspace/sandbox_common/service_cert.pem
00:47:29.408 | DEBUG    | infra.clients:request:369 - Running: curl https://127.0.0.1:8000/node/network -X GET -i -m 1 -L --cacert /workspace/sandbox_common/service_cert.pem
00:47:30.518 | DEBUG    | infra.clients:request:369 - Running: curl https://127.0.0.1:8000/node/network -X GET -i -m 1 -L --cacert /workspace/sandbox_common/service_cert.pem
00:47:31.526 | WARNING  | infra.network:find_primary:898 - Could not successfully connect to node 0. Retrying...
00:47:31.627 | INFO     | infra.network:find_primary:907 - [0||] GET /node/network
00:47:31.627 | INFO     | infra.network:network:1395 - Stopping network
00:47:31.627 | INFO     | infra.node:stop:430 - Stopping node 0
00:47:31.627 | INFO     | infra.remote:stop:515 - [127.0.0.1] closing
00:47:31.631 | INFO     | infra.network:stop_all_nodes:701 - All nodes stopped
Traceback (most recent call last):
  File "/opt/ccf/bin/start_network.py", line 190, in <module>
    run(args)
  File "/opt/ccf/bin/start_network.py", line 87, in run
    network.start_and_open(args)
  File "/opt/ccf/bin/infra/network.py", line 492, in start_and_open
    self.start(args, **kwargs)
  File "/opt/ccf/bin/infra/network.py", line 453, in start
    primary = self._start_all_nodes(args, **kwargs)
  File "/opt/ccf/bin/infra/network.py", line 389, in _start_all_nodes
    primary, _ = self.find_primary(
  File "/opt/ccf/bin/infra/network.py", line 908, in find_primary
    raise PrimaryNotFound
infra.network.PrimaryNotFound

divneil-intel avatar Aug 04 '22 17:08 divneil-intel

Hi @divneil-intel and thanks for reporting this. Could you attach the out and err files in the workspace/sandbox_0 folder? It looks like the first node (node 0) did not start successfully and the logs files will help us understand the issue.

Edit: I've run the steps you've described above to try to reproduce the issue but the sandbox starts up fine in my case:

13:40:27.979 | SUCCESS  | infra.network:open:487 - ***** Network is now open *****
13:40:27.980 | DEBUG    | infra.clients:request:369 - Running: curl https://127.0.0.1:8000/app/commit -X GET -i -m 10 -L --cacert /workspace/sandbox_common/service_cert.pem
13:40:27.994 | INFO     | __main__:run:96 - [0||] GET /app/commit
13:40:27.994 | INFO     | __main__:run:96 - 200 @2.10 {"transaction_id":"2.9"}
13:40:27.994 | INFO     | __main__:run:104 - Started CCF network with the following nodes:
13:40:27.994 | INFO     | __main__:run:106 -   Node [0] = https://127.0.0.1:8000
13:40:27.994 | INFO     | __main__:run:114 - You can now issue business transactions to the /opt/ccf/bin/../lib/libjs_generic application
13:40:27.994 | INFO     | __main__:run:118 - Loaded JS application: /opt/ccf/bin/../samples/logging/js
13:40:27.995 | INFO     | __main__:run:119 - Keys and certificates have been copied to the common folder: /workspace/sandbox_common
13:40:27.995 | INFO     | __main__:run:122 - See https://microsoft.github.io/CCF/main/use_apps/issue_commands.html for more information
13:40:27.995 | WARNING  | __main__:run:125 - Press Ctrl+C to shutdown the network

Note that my host VM is Ubuntu 20.04:

$ uname -a
Linux jumaffre2 5.15.0-1014-azure #17~20.04.1-Ubuntu SMP Thu Jun 23 20:01:51 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

jumaffre avatar Aug 05 '22 10:08 jumaffre

out.txt Pls find attached the out file, err file is turning out to empty. I have already tried the same on Windows 10 WSL2 Ubuntu 20.04 and end up with the same result. :(

Edit1: Since, the container is started without SGX parameters, so, I believe sandbox.sh is taking care of it. However, there's an interesting log in out.txt

2022-08-06T01:38:25.151732Z        100 [info ] ../src/host/sig_term.h:24            | SIGTERM: Shutting down enclave gracefully...
2022-08-06T01:38:25.152842Z -0.002 0   [info ] ../src/enclave/enclave.h:462         | Enclave stopped successfully. Stopping host...

divneil-intel avatar Aug 05 '22 18:08 divneil-intel

@divneil-intel The out.txt doesn't show any errors - that's the expected logging for a healthy shutdown flow. Could you confirm that the curl .../node/network ... lines happen while the node is alive (ie - between the timestamps where the node output prints Network TLS connections now accepted and SIGTERM: Shutting down enclave gracefully...)? If that's the case, then it looks like the CCF node is being started successfully, but the sandbox infra is unable to communicate with it (and then shuts it down gracefully while cleaning up).

I've also got a local repro which launched successfully, so need to pin down what's different in your setup. Potentially something about the networking setup available to Docker containers? Rather than trying to launch sandbox.sh, could you test that from this base image you can successfully curl from a public web server, and from a simple web server running within the same container?

eddyashton avatar Sep 01 '22 13:09 eddyashton

@eddyashton thanks for the pointers. The network was working well in the docker as the python environment was being setup successfully. However, I followed the docker notation for noProxy from here: https://docs.docker.com/network/proxy/. It's not very apparent why 127.0.0.1 works well with sandbox.sh and not 127.0.0.0/8.

divneil-intel avatar Sep 02 '22 05:09 divneil-intel

@divneil-intel sandbox takes an interface, which it then binds to. Taking a mask and binding to every IP it includes would be very surprising to most users, and unlikely to be a valid use case.

achamayou avatar Feb 27 '23 23:02 achamayou