search

Samourai-Wallet / samourai-dojo

End-to-end bitcoin wallet backing server for powering Samourai Wallet and other light wallets
https://samouraiwallet.com/dojo
Other
170 stars 79 forks source link

External bticoind not tracking new blocks #105

Closed dmp1ce closed 4 years ago

dmp1ce commented 4 years ago

Describe the issue Using an external bitcoind I am getting the following output almost all the time, after the dojo catches up to the head block.

$ ./dojo.sh logs tracker
[20191215 16:09:15.977 071 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:09:25.981 071 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:09:34.448 072 MiB] Processing unconfirmed transactions
[20191215 16:09:34.451 072 MiB]  Finished processing unconfirmed transactions 0.0s, 0 tx, 0ms/tx
[20191215 16:09:35.979 072 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:09:45.982 072 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:09:55.979 072 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:10:05.983 072 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:10:15.984 072 MiB] Processing inactive Mempool (0 transactions)
[20191215 16:10:25.980 072 MiB] Processing inactive Mempool (0 transactions)

My Whirlpool is up-to-date initially but then gets further and further out of date because the dojo doesn't find any new blocks! I would expect that the dojo would track the new blocks coming in, even if using and external bitcoind.

Screenshots My settings in the .conf file are:

#
# INSTALL AND RUN BITCOIND INSIDE DOCKER
#

# Install and run bitcoind inside Docker
# Set this option to 'off' for using a bitcoind hosted outside of Docker (not recommended)
# Value: on | off
BITCOIND_INSTALL=off

# IP address of bitcoind used by Dojo
# Set value to 172.28.1.5 if BITCOIND_INSTALL is set to 'on'
# Type: string
BITCOIND_IP=172.17.0.1

# Port of the RPC API
# Set value to 28256 if BITCOIND_INSTALL is set to 'on'
# Type: integer
BITCOIND_RPC_PORT=8332

# Port exposing ZMQ notifications for raw transactions
# Set value to 9501 if BITCOIND_INSTALL is set to 'on'
# Type: integer
BITCOIND_ZMQ_RAWTXS=18502

# Port exposing ZMQ notifications for block hashes
# Set value to 9502 if BITCOIND_INSTALL is set to 'on'
# Type: integer
BITCOIND_ZMQ_BLK_HASH=18501

These are the logs I get when restarting the dojo.

$ ./dojo.sh restart                                                                                                                                                              
Stopping nginx  ... done                                                                                                                                                                                                                      
Stopping nodejs ... done                                                                                                                                                                                                                      
Stopping tor    ... done                                                                                                                                                                                                                      
Stopping db     ... done                                                                                                                                                                                                                      
Removing nginx  ... done                                                                                                                                                                                                                      
Removing nodejs ... done                                                                                                                                                                                                                      
Removing tor    ... done                                                                                                                                                                                                                      
Removing db     ... done                                                                                                                                                                                                                      
Removing network my-dojo_dojonet                                                                                                                                                                                                              
Removing network my-dojo_dmznet                                                                                                                                                                                                               
Creating network "my-dojo_dojonet" with driver "bridge"                                                                                                                                                                                       
Creating network "my-dojo_dmznet" with driver "bridge"                                                                                                                                                                                        
Creating tor    ... done                                                                                                                                                                                                                      
Creating db  ... done                                                                                                                                                                                                                         
Creating nodejs ... done                                                                                                                                                                                                                      
Creating nginx  ... done                                                                                                                                                                                                                      
$ ./dojo.sh logs tracker                                                                                                                                                         
[20191215 16:22:06.041 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:22:16.041 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:22:26.044 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:22:36.042 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:22:46.045 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:22:56.045 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:23:06.046 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:23:16.046 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:23:26.047 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:23:36.047 072 MiB] Processing inactive Mempool (0 transactions)                                                                                                                                                                  
[20191215 16:24:05.719 045 MiB] Process ID: 140                                                                                                                                                                                               
[20191215 16:24:05.723 045 MiB] Preparing the tracker                                                                                                                                                                                         
[20191215 16:24:05.826 044 MiB] Created a database pool of 10 connections                                                                                                                                                                     
[20191215 16:24:05.856 044 MiB] HTTP server listening on port 8082                                                                                                                                                                            
[20191215 16:24:07.388 044 MiB] Tracker Startup (normal mode)                                                                                                                                                                                 
[20191215 16:24:07.397 044 MiB] Sync 24 blocks                                                                                                                                                                                                
[20191215 16:24:07.459 047 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:08.664 086 MiB]  Added block 608214 (id=608232)                                                                                                                                                                               
[20191215 16:24:08.740 088 MiB]  Finished block 608214, 1.2s, 1028 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:08.855 090 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:10.017 101 MiB]  Added block 608215 (id=608234)                                                                                                                                                                               
[20191215 16:24:10.091 101 MiB]  Finished block 608215, 1.2s, 1214 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:10.228 105 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:12.821 121 MiB]  Added block 608216 (id=608235)                                                                                                                                                                               
[20191215 16:24:12.944 122 MiB]  Finished block 608216, 2.6s, 2704 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:13.056 125 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:14.966 133 MiB]  Added block 608217 (id=608236)                                                                                                                                                                               
[20191215 16:24:15.061 134 MiB]  Finished block 608217, 2.0s, 1845 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:15.195 138 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:17.303 128 MiB]  Added block 608218 (id=608237)                                                                                                                                                                               
[20191215 16:24:17.410 128 MiB]  Finished block 608218, 2.2s, 2175 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:17.595 132 MiB] Beginning to process new block.                                                                                                                                                                               
[20191215 16:24:19.298 130 MiB]  Added block 608219 (id=608238)                                                                                                                                                                               
[20191215 16:24:19.403 130 MiB]  Finished block 608219, 1.7s, 1721 tx, 1ms/tx                                                                                                                                                                 
[20191215 16:24:19.554 135 MiB] Beginning to process new block.                               
.
.
.
[20191215 16:24:47.325 151 MiB]  Finished block 608230, 2.6s, 2805 tx, 1ms/tx
[20191215 16:24:47.405 153 MiB] Beginning to process new block.
[20191215 16:24:48.138 131 MiB]  Added block 608231 (id=608250)
[20191215 16:24:48.222 131 MiB]  Finished block 608231, 0.8s, 651 tx, 1ms/tx
[20191215 16:24:48.478 140 MiB] Beginning to process new block.
[20191215 16:24:49.705 126 MiB]  Added block 608232 (id=608251)
[20191215 16:24:49.741 126 MiB]  Finished block 608232, 1.2s, 111 tx, 11ms/tx
[20191215 16:24:49.952 133 MiB] Beginning to process new block.
[20191215 16:24:51.480 140 MiB]  Added block 608233 (id=608252)
[20191215 16:24:51.531 140 MiB]  Finished block 608233, 1.5s, 1115 tx, 1ms/tx
[20191215 16:24:51.723 147 MiB] Beginning to process new block.
[20191215 16:24:53.843 150 MiB]  Added block 608234 (id=608253)
[20191215 16:24:53.907 150 MiB]  Finished block 608234, 2.1s, 1821 tx, 1ms/tx
[20191215 16:24:54.093 157 MiB] Beginning to process new block.
[20191215 16:24:56.173 152 MiB]  Added block 608235 (id=608254)
[20191215 16:24:56.319 140 MiB]  Finished block 608235, 2.2s, 1667 tx, 1ms/tx
[20191215 16:24:56.493 146 MiB] Beginning to process new block.
[20191215 16:24:58.670 154 MiB]  Added block 608236 (id=608255)
[20191215 16:24:58.743 154 MiB]  Finished block 608236, 2.2s, 2115 tx, 1ms/tx
[20191215 16:24:58.908 160 MiB] Beginning to process new block.
[20191215 16:25:01.869 156 MiB]  Added block 608237 (id=608256)
[20191215 16:25:02.047 136 MiB]  Finished block 608237, 3.1s, 3226 tx, 1ms/tx
[20191215 16:25:02.050 136 MiB] Listening for blocks
[20191215 16:25:02.053 136 MiB] Processing unconfirmed transactions
[20191215 16:25:02.055 136 MiB]  Finished processing unconfirmed transactions 0.0s, 0 tx, 0ms/tx
[20191215 16:25:02.058 136 MiB] Listening for pushTx
[20191215 16:25:02.060 136 MiB] Listening for pushTx orchestrator
[20191215 16:25:02.061 136 MiB] Listening for mempool transactions
[20191215 16:25:02.068 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:25:12.070 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:25:22.078 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:25:32.081 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:25:42.083 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:25:52.084 136 MiB] Processing active Mempool (0 transactions)
[20191215 16:26:02.085 070 MiB] Processing active Mempool (0 transactions)
[20191215 16:26:12.086 070 MiB] Processing active Mempool (0 transactions)
[20191215 16:26:22.086 070 MiB] Processing active Mempool (0 transactions)
[20191215 16:26:32.088 070 MiB] Processing active Mempool (0 transactions)

Desktop (please complete the following information):

Additional context I'm using my docker-compose setup for the full node here: https://github.com/dmp1ce/lnd-tor-docker-compose

LaurentMT commented 4 years ago

The fact that Dojo doesn't seem able to process the mempool while being able to sync the blocks when it's launched suggests an issue with the configuration of ZeroMQ notifications, either in your bitcoin.conf or in your docker-bitcoind.conf.

Can you check the values set for these 2 properties in your bitcoin.conf file?

If I'm correct, you should have something like this:

Another possible cause is a firewall blocking the port 18502.

dmp1ce commented 4 years ago

This is what I thought, but I've double checked bitcoind and it looks like the ports are right. I don't think there is a firewall or routing issue because RPC port 8332 is accessible.

Here is what bitcoin-cli gives me:

$ bitcoin-cli getzmqnotifications
[
  {
    "type": "pubrawblock",
    "address": "tcp://127.0.0.1:18501",
    "hwm": 1000
  },
  {
    "type": "pubrawtx",
    "address": "tcp://127.0.0.1:18502",
    "hwm": 1000
  }
]

Is there a way I can test the ZMQ ports are working?

dmp1ce commented 4 years ago

In my bitcoin.conf I had

zmqpubrawblock=tcp://127.0.0.1:18501
zmqpubrawtx=tcp://127.0.0.1:18502

but I needed

zmqpubrawblock=tcp://0.0.0.0:18501
zmqpubrawtx=tcp://0.0.0.0:18502

because I'm exposing the ports outside of my docker container. Networking issues get me every time! I'm surprised Whirlpool and Samourai worked as well as they did without any new transaction or block information!

dmp1ce commented 4 years ago

After about 1 hour of processing I again got Processing inactive Mempool (0 transactions)! Why would this happen? Here is what my logs looked like.

[20191217 20:59:36.383 091 MiB] Processing active Mempool (41 transactions)
[20191217 20:59:46.384 096 MiB] Processing active Mempool (33 transactions)
[20191217 20:59:56.388 084 MiB] Processing active Mempool (38 transactions)
[20191217 21:00:06.389 086 MiB] Processing active Mempool (32 transactions)
[20191217 21:00:16.387 083 MiB] Processing active Mempool (74 transactions)
[20191217 21:00:26.388 084 MiB] Processing active Mempool (41 transactions)
[20191217 21:00:36.393 088 MiB] Processing active Mempool (39 transactions)
[20191217 21:00:46.397 092 MiB] Processing active Mempool (41 transactions)
[20191217 21:00:56.398 094 MiB] Processing active Mempool (29 transactions)
[20191217 21:01:06.403 084 MiB] Processing active Mempool (36 transactions)
[20191217 21:01:16.405 084 MiB] Processing active Mempool (30 transactions)
[20191217 21:01:26.406 084 MiB] Processing active Mempool (42 transactions)
[20191217 21:01:36.407 084 MiB] Processing active Mempool (20 transactions)
[20191217 21:01:46.407 084 MiB] Processing active Mempool (35 transactions)
[20191217 21:01:56.409 084 MiB] Processing active Mempool (29 transactions)
[20191217 21:02:05.672 086 MiB] Processing unconfirmed transactions
[20191217 21:02:05.696 087 MiB]  Finished processing unconfirmed transactions 0.0s, 4 tx, 6ms/tx
[20191217 21:02:06.409 087 MiB] Processing active Mempool (31 transactions)
[20191217 21:02:16.407 089 MiB] Processing active Mempool (43 transactions)
[20191217 21:02:26.409 091 MiB] Processing active Mempool (32 transactions)
[20191217 21:02:36.408 093 MiB] Processing active Mempool (30 transactions)
[20191217 21:02:46.417 095 MiB] Processing active Mempool (24 transactions)
[20191217 21:02:56.421 085 MiB] Processing active Mempool (23 transactions)
[20191217 21:03:06.422 085 MiB] Processing active Mempool (42 transactions)
[20191217 21:03:16.424 085 MiB] Processing active Mempool (43 transactions)
[20191217 21:03:26.422 085 MiB] Processing active Mempool (41 transactions)
[20191217 21:03:36.429 085 MiB] Processing active Mempool (29 transactions)
[20191217 21:03:46.430 086 MiB] Processing active Mempool (38 transactions)
[20191217 21:03:56.430 089 MiB] Processing active Mempool (30 transactions)
[20191217 21:04:06.431 092 MiB] Processing inactive Mempool (2935 transactions)
[20191217 21:04:16.435 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:04:26.435 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:04:36.433 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:04:46.439 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:04:56.439 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:06.441 154 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:16.450 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:26.449 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:36.449 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:46.450 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:05:56.448 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:06:06.451 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:06:16.451 076 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:06:26.454 077 MiB] Processing inactive Mempool (0 transactions)
[20191217 21:06:36.457 076 MiB] Processing inactive Mempool (0 transactions)

What should I do to try and debug this?

dmp1ce commented 4 years ago

It ran for about one and a half hours last night and then back to inactive mempool. I'm going to restart again now.

dmp1ce commented 4 years ago

After restarting this morning, I got inactive mempool after only about 40 minutes of processing transactions. I would like to know why this is happening. I'm happy to debug further on my setup if you can give me some advice.

dmp1ce commented 4 years ago

I think I finally figured you my issue. I was missing zmqpubhashblock! I had zmqpubrawblock instead.

Make sure the logs show Processing active Mempool (xx transactions) and Block #xxxxxx 0000000xxxxxxxxxxx from time to time, or the dojo is probably are not listening to the correct ZMQ ports.

4NobleTruths commented 3 years ago

Thanks for these tips @dmp1ce ! What should the rpcbind in bitcoin.conf be for this to work, if there are already other rpc clients using rpcbind=127.0.0.1? Did you put rpcbind=172.17.0.1 also?

Is the docker0 ip not supposed to work for the zmq also, and has to be set 0.0.0.0?

dmp1ce commented 3 years ago

@4NobleTruths In my external bitcoind I have rpcbind=0.0.0.0 set in bitcoin.conf. I couldn't find a way around that, but my bitcoind RPC port is only exposed on my LAN so I don't think it is a problem.

I also have internal processes from a Docker Compose connecting to bitcoind using the IP 127.0.0.1.

Oberfeldwedler commented 2 years ago

I ran into the same Issue. FULL NODE and INDEXER stay synced while TRACKER and DOJO DB fall behind. My Issue was that I had

BITCOIND_ZMQ_RAWTXS=<IP>:18502
BITCOIND_ZMQ_BLK_HASH=<IP>:18501

instead of 

BITCOIND_ZMQ_RAWTXS=18502
BITCOIND_ZMQ_BLK_HASH=18501

Also in my bitcoin.conf i had

zmqpubrawblock=<IP>:18501

instead of 

zmqpubrawblock=tcp://<IP>:18501

Just wanted to leave this here in case somebody has the same issue.