Upstream on port 3000 not listening

[Kexkey]

Hi, I've been running Esplora for 2 weeks with Docker. Bitcoin Core sync'ed quickly since I already had the data. Electrs then started working hard but has been using only around 1% of the CPU for several days.

I'm having a look at nginx logs in the container and I can see it's trying to connect to the upstream but the connection is refused when I hit the server. Port 3000 is indeed not a listening port in the container, nor is it on the host.

2019/03/02 03:55:18 [error] 199#199: *224 connect() failed (111: Connection refused) while connecting to upstream, client: 139.28.218.30, server: , request: "GET /api/blocks/tip/height HTTP/1.1", upstream: "http://127.0.0.1:3000/blocks/tip/height", host: "esplora-mainnet:8080", referrer: "http://esplora-mainnet:8080/"

Around 750GB of disk space is used on a total of 1TB.

I haven't changed anything to the configs, except adding -vvv to the supervisord config to know what was going on.

...
2019-03-01T21:42:12.850+00:00 - DEBUG - Starting pre-cache for scripthash 26/10692
2019-03-01T22:48:43.007+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-02T00:39:57.217+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-02T02:15:11.364+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-02T02:15:11.373+00:00 - DEBUG - Starting pre-cache for scripthash 31/10692
2019-03-02T03:25:11.233+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable

It looks fine, I don't see errors anywhere. When is electrs going to listen to port 3000?

Thanks.

[greenaddress]

Hi @Kexkey

How are you running the docker instance? Did you tell docker to open the ports?

If you followed the example for mainnet in the README.md then the port open wouldn't be 3000 but 8080

docker run -p 8080:80 \
           --volume $PWD/data_bitcoin_mainnet:/data \
           --rm -i -t esplora \
           bash -c "/srv/explorer/run.sh bitcoin-mainnet explorer"

This has docker forward the port 8080 outside the container to port 80 on the container where nginx serves the static content and proxy passes to electrs, see https://github.com/Blockstream/esplora/blob/master/contrib/nginx.conf.in#L2

As far as I know port 3000 is only opened on localhost and only within the docker instance.

You could try to enter the docker instance with

docker exec -it $CONTAINER_ID bash where $CONTAINER_ID is the ID provided by docker ps (first column)

Hope this helps! let us know if you have any question!

[Kexkey]

Hi! Yes I used that exact docker command to start it. The port 8080 answers with a 502 Bad Gateway. I got in the container to see what was the problem. The connect() failed (111: Connection refused) while connecting to upstream, client: 139.28.218.30, server: , request: "GET /api/blocks/ HTTP/1.1", upstream: "http://127.0.0.1:3000/blocks/" error comes from /var/log/nginx/error.log inside the container.

From inside the container, port 3000 is not listening (can see with ss -l) and of course curl 127.0.0.1:3000 gives curl: (7) Failed to connect to 127.0.0.1 port 3000: Connection refused.

electrs is running though, I can see it with top and see a new line once in a while in data_bitcoin_mainnet/logs/electrs-bitcoin.log.

So is there a special configuration I have to add somewhere so that electrs will start listening on port 3000, or does it open the port only when finished indexing? It seems like it's finished indexing though, from what I see in the logs and the low CPU it uses, compared to the first few days of running.

Thanks for your help!

[greenaddress]

It opens the port after IDB + indexing.

Maybe check electrs uptime, if it's shorter than the other processes it may be running out of ram and crashing

[Kexkey]

No OOM crash:

debian@esplora-mainnet-06:~$ docker logs 0ff
...
2019-03-01 01:53:05,074 INFO success: electrs entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-03-01 01:53:05,075 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-03-01 01:53:05,075 INFO success: bitcoind entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-03-01 01:53:05,174 INFO success: prerenderer entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

I'd like to know, is the writing to RocksDB pace normal:

debian@esplora-mainnet-06:~/data_bitcoin_mainnet$ tail logs/electrs-bitcoin.log
...
2019-03-03T17:17:36.159+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-03T18:35:07.584+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-03T19:39:15.338+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable
2019-03-03T20:44:29.163+00:00 - DEBUG - writing 1 rows to RocksDB { path: "/data/electrs_bitcoin_db/mainnet/mainnet/newindex/cache" }, flush=Enable

Writing 1 row every 1 hour is not a lot, I would have expected more.

[shesek]

It looks like its writing to the cache DB. This probably means its still in the process of pre-caching history stats for popular addresses (something done once initially for the 10k addresses with the most history). However, this should be heavily parallelized and use up considerably more CPU than what you're describing, so I'm not quite sure why that's happening there exactly.

If you're running with -vvvv, you should also be seeing DEBUG lines with Starting pre-cache for scripthash N/M every once in awhile. Can you try finding one of these to check the progress made so far?

If you don't plan to query the super popular addresses or don't mind the first user to request them to have to wait for a little while, you can disable pre-caching by removing --precache-scripts /srv/explorer/popular-scripts.txt from contrib/supervisord.conf.in.

[Kexkey]

Ok, I restarted from scratch with a brand new beast VM (the most powerful one on lunanode) and it's now all good! Here are some stats (mainnet) for the record:

Bitcoin Core syncing whole chain: 7 hours
Electrs indexing: 9 hours
RocksDB compaction: 1.5 hours
Electrs pre-caching: 2 hours

Total cost to be up and running: around 10 CAD.

Now I'll quickly copy the data on a reusable volume, destroy that monster VM and use data on a more reasonable VM. :-)

Thanks!

[greenaddress]

@Kexkey thank you a lot for the stats! very useful! maybe we should add them to the README (updated as of timestamp)

Thoughts?

[Kexkey]

Yes. Of course the problem is it varies so much depending on hardware. But it's definitely useful to have some reference. It took a little over a week on Jimmy's machine and 2 weeks passed on my other VM before I gave up.

I think having a small table with typical hardware and time it took would be nice. Also, being able to enable/disable the debug level live would be useful, instead of having to add -vvvv to the supervisor's file, rebuild and rerun. Or just add some progression info in the logs, even if not in debug level.

And btw, good job guys!

[greenaddress]

thanks @Kexkey !

I agree, it should be possible to add logging/debugging - what are you thinking? a parameter to run.sh?

What do you think about #57 ? Want to try it out and let me know?

[greenaddress]

@Kexkey debug mode is merged, you just need to pass to run.sh the word verbose as the last parameter

[Kexkey]

Sorry I didn't see your comment until now. The PR looks good! I'll put it online on my instance today. Thumbs up!!

[benwilliams]

Does anyone know the total disk space required for compaction to finish? A couple of times my volume space was exhausted and it seems on every interruption compaction restarts from the beginning. It was using 300G before compaction started and now grown to 783G and it is still compacting.

[shesek]

It should peak at a little less than 1TB of storage.

[benwilliams]

The compaction finished, total size now 554G. However nothing is listening on port 3000 yet. Should the container be stopped and started to make the port begin listening? Now that compaction is finished can the container be restarted without causing another compaction to occur?

[benwilliams]

I'm about 4 weeks into this install and about to give up on it. I assumed compaction was done but who knows? Database went to about 900G then back down to 563G and now staying steady at that size.
No port 3000 is open. Stopped and started the container, again no listener on port 3000. Great fucking job you guys, really nice work.