# Delving into the unknown This write-up summarises how to debug what appears to be a mischievous Lotus instance during our Testground tests. It also goes enumerates which assets are useful to report suspicious behaviours upstream, in a way that they are actionable. ## Querying the Lotus RPC API The `local:docker` and `cluster:k8s` map ports that you specify in the composition.toml, so you can access them externally. All our compositions should carry this fragment: ```toml [global.run_config] exposed_ports = { pprof = "6060", node_rpc = "1234", miner_rpc = "2345" } ``` This tells Testground to expose the following ports: * `6060` => Go pprof. * `1234` => Lotus full node RPC. * `2345` => Lotus storage miner RPC. ### `local:docker` 1. Install the `lotus` binary on your host. 2. Find the container that you want to connect to in `docker ps`. * Note that our _container names_ are slightly long, and they're the last field on every line, so if your terminal is wrapping text, the port numbers will end up ABOVE the friendly/recognizable container name (e.g. `tg-lotus-soup-deals-e2e-acfc60bc1727-miners-1`). * The testground output displays the _container ID_ inside coloured angle brackets, so if you spot something spurious in a particular node, you can hone in on that one, e.g. `<< 54dd5ad916b2 >>`. ``` ⟩ docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 54dd5ad916b2 be3c18d7f0d4 "/testplan" 10 seconds ago Up 8 seconds 0.0.0.0:32788->1234/tcp, 0.0.0.0:32783->2345/tcp, 0.0.0.0:32773->6060/tcp, 0.0.0.0:32777->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-clients-2 53757489ce71 be3c18d7f0d4 "/testplan" 10 seconds ago Up 8 seconds 0.0.0.0:32792->1234/tcp, 0.0.0.0:32790->2345/tcp, 0.0.0.0:32781->6060/tcp, 0.0.0.0:32786->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-clients-1 9d3e83b71087 be3c18d7f0d4 "/testplan" 10 seconds ago Up 8 seconds 0.0.0.0:32791->1234/tcp, 0.0.0.0:32789->2345/tcp, 0.0.0.0:32779->6060/tcp, 0.0.0.0:32784->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-clients-0 7bd60e75ed0e be3c18d7f0d4 "/testplan" 10 seconds ago Up 8 seconds 0.0.0.0:32787->1234/tcp, 0.0.0.0:32782->2345/tcp, 0.0.0.0:32772->6060/tcp, 0.0.0.0:32776->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-miners-1 dff229d7b342 be3c18d7f0d4 "/testplan" 10 seconds ago Up 9 seconds 0.0.0.0:32778->1234/tcp, 0.0.0.0:32774->2345/tcp, 0.0.0.0:32769->6060/tcp, 0.0.0.0:32770->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-miners-0 4cd67690e3b8 be3c18d7f0d4 "/testplan" 11 seconds ago Up 8 seconds 0.0.0.0:32785->1234/tcp, 0.0.0.0:32780->2345/tcp, 0.0.0.0:32771->6060/tcp, 0.0.0.0:32775->6060/tcp tg-lotus-soup-deals-e2e-acfc60bc1727-bootstrapper-0 aeb334adf88d iptestground/sidecar:edge "testground sidecar …" 43 hours ago Up About an hour 0.0.0.0:32768->6060/tcp testground-sidecar c1157500282b influxdb:1.8 "/entrypoint.sh infl…" 43 hours ago Up 25 seconds 0.0.0.0:8086->8086/tcp testground-influxdb 99ca4c07fecc redis "docker-entrypoint.s…" 43 hours ago Up About an hour 0.0.0.0:6379->6379/tcp testground-redis bf25c87488a5 bitnami/grafana "/run.sh" 43 hours ago Up 26 seconds 0.0.0.0:3000->3000/tcp testground-grafana cd1d6383eff7 goproxy/goproxy "/goproxy" 45 hours ago Up About a minute 8081/tcp testground-goproxy ``` 3. Take note of the port mapping. Imagine in the output above, we want to query `54dd5ad916b2`. We'd use `localhost:32788`, as it forwards to the container's 1234 port (Lotus Full Node RPC). 4. Run your Lotus CLI command setting the `FULLNODE_API_INFO` env variable, which is a multiaddr: ```sh $ FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/$port/http" lotus chain list [...] ``` --- Alternatively, you could download gawk and setup a script in you .bashrc or .zshrc similar to: ``` lprt() { NAME=$1 PORT=$2 docker ps --format "table {{.Names}}" | grep $NAME | xargs -I {} docker port {} $PORT | gawk --field-separator=":" '{print $2}' } envs() { NAME=$1 local REMOTE_PORT_1234=$(lprt $NAME 1234) local REMOTE_PORT_2345=$(lprt $NAME 2345) export FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/$REMOTE_PORT_1234/http" export STORAGE_API_INFO=":/ip4/127.0.0.1/tcp/$REMOTE_PORT_2345/http" echo "Setting \$FULLNODE_API_INFO to $FULLNODE_API_INFO" echo "Setting \$STORAGE_API_INFO to $STORAGE_API_INFO" } ``` Then call commands like: ``` envs miners-0 lotus chain list ``` ### `cluster:k8s` Similar to `local:docker`, you pick a pod that you want to connect to and port-forward 1234 and 2345 to that specific pod, such as: ``` export PODNAME="tg-lotus-soup-ae620dfb2e19-miners-0" kubectl port-forward pods/$PODNAME 1234:1234 2345:2345 export FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/1234/http" export STORAGE_API_INFO=":/ip4/127.0.0.1/tcp/2345/http" lotus-storage-miner storage-deals list lotus-storage-miner storage-deals get-ask ``` ### Useful commands / checks * **Making sure miners are on the same chain:** compare outputs of `lotus chain list`. * **Checking deals:** `lotus client list-deals`. * **Sector queries:** `lotus-storage-miner info` , `lotus-storage-miner proving info` * **Sector sealing errors:** * `STORAGE_API_INFO=":/ip4/127.0.0.1/tcp/53624/http" FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/53623/http" lotus-storage-miner sector info` * `STORAGE_API_INFO=":/ip4/127.0.0.1/tcp/53624/http" FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/53623/http" lotus-storage-miner sector status <sector_no>` * `STORAGE_API_INFO=":/ip4/127.0.0.1/tcp/53624/http" FULLNODE_API_INFO=":/ip4/127.0.0.1/tcp/53623/http" lotus-storage-miner sector status --log <sector_no>` ## Viewing logs of a particular container `local:docker` This works for both started and stopped containers. Just get the container ID (in double angle brackets in Testground output, on every log line), and do a: ```shell script $ docker logs $container_id ``` ## Accessing the golang instrumentation Testground exposes a pprof endpoint under local port 6060, which both `local:docker` and `cluster:k8s` map. For `local:docker`, see above to figure out which host port maps to the container's 6060 port. ## Acquiring a goroutine dump When things appear to be stuck, get a goroutine dump. ```shell script $ wget -o goroutine.out http://localhost:${pprof_port}/debug/pprof/goroutine?debug=2 ``` You can use whyrusleeping/stackparse to extract a summary: ```shell script $ go get https://github.com/whyrusleeping/stackparse $ stackparse --summary goroutine.out ``` ## Acquiring a CPU profile When the CPU appears to be spiking/rallying, grab a CPU profile. ```shell script $ wget -o profile.out http://localhost:${pprof_port}/debug/pprof/profile ``` Analyse it using `go tool pprof`. Usually, generating a `png` graph is useful: ```shell script $ go tool pprof profile.out File: testground Type: cpu Time: Jul 3, 2020 at 12:00am (WEST) Duration: 30.07s, Total samples = 2.81s ( 9.34%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) png Generating report in profile003.png ``` ## Submitting actionable reports / findings This is useful both internally (within the Oni team, so that peers can help) and externally (when submitting a finding upstream). We don't need to play the full bug-hunting game on Lotus, but it's tremendously useful to provide the necessary data so that any reports are actionable. These include: * test outputs (use `testground collect`). * stack traces that appear in logs (whether panics or not). * output of relevant Lotus CLI commands. * if this is some kind of blockage / deadlock, goroutine dumps. * if this is a CPU hotspot, a CPU profile would be useful. * if this is a memory issue, a heap dump would be useful. **When submitting bugs upstream (Lotus), make sure to indicate:** * Lotus commit. * FFI commit.