Config: electrum on a client computer cannot reach electrs on the server, electrs itself seems to be running fine

[marimes]

Have you read the documentation?
YES

How did you configure electrs?

electrs@mlbb2:~/.electrs$ cat electrs.conf
network = "bitcoin"
daemon_dir= "/home/bitcoin/.bitcoin"
daemon_rpc_addr = "127.0.0.1:8332"
daemon_p2p_addr = "127.0.0.1:8333"

electrum_rpc_addr = "127.0.0.1:50001"

db_dir = "/home/electrs/.electrs/db"
index_lookup_limit = 1000

log_filters = "INFO"
timestamp = true

The issue is that electrum running on another computer cannot reach electrs. I use nginx as a reverse proxy. The log below shows (I believe) that electrum can reach the server OK, the request seems to be passed on to electrs but no response is received.

electrs itself is running fine.

Environment variables: ELECTRS_X=Y;...
Arguments: --foo

Debug output of configuration

Below I describe my nginx configuration. My actual domain has been replaced by MY_SITE.COM and my true IP by 99.99.99.99. I also describe how nginx was configured and how I have tried to trace network traffic using lsof, curl, and tcpdump.

I have compiled nginx with these arguments:

marius@mlbb2:~$ nginx -V
nginx version: nginx/1.25.3
built by gcc 11.4.0 (Ubuntu 11.4.0-1ubuntu1~22.04) 
built with OpenSSL 3.0.2 15 Mar 2022
TLS SNI support enabled
configure arguments: --sbin-path=/usr/local/bin/nginx --conf-path=/etc/nginx/nginx.conf --modules-path=/etc/nginx/modules --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --with-pcre --with-http_ssl_module --with-http_gzip_static_module --with-http_gunzip_module --with-http_v2_module --with-http_xslt_module=dynamic --with-http_image_filter_module=dynamic --with-http_geoip_module=dynamic --with-stream=dynamic --with-stream_ssl_preread_module --with-stream_ssl_module --with-stream_geoip_module=dynamic

nginx.conf and the included electrs.conf:

marius@mlbb2:~$ cat /etc/nginx/nginx.conf
user www-data;
worker_processes auto;
pid /run/nginx.pid;

events {
    worker_connections 1024;
}

http { ... details removed ... }

stream {
    ssl_certificate /etc/letsencrypt/live/MY_SITE.COM/fullchain.pem; # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/MY_SITE.COM/privkey.pem; # managed by Certbot
    ssl_session_timeout 4h;
    ssl_protocols TLSv1 TLSv1.1 TLSv1.2 TLSv1.3;
    ssl_prefer_server_ciphers on;

    include streams-enabled/*.conf;
}

marius@mlbb2:~$ cat /etc/nginx/streams-enabled/electrs.conf
upstream electrs {
    server 127.0.0.1:50001;
}

server {
    listen 50002 ssl;
    proxy_pass electrs;
}

below we see that electrs is listening on ports 50001 and nginx is listening on port 50002:

marius@mlbb2:~$ sudo lsof -i -n -P | grep LISTEN
[sudo] password for marius: 
systemd        1            root  147u  IPv4    20186      0t0  TCP *:111 (LISTEN)
systemd        1            root  149u  IPv6    20187      0t0  TCP *:111 (LISTEN)
rpcbind      539            _rpc    4u  IPv4    20186      0t0  TCP *:111 (LISTEN)
rpcbind      539            _rpc    6u  IPv6    20187      0t0  TCP *:111 (LISTEN)
systemd-r    661 systemd-resolve   14u  IPv4    21687      0t0  TCP 127.0.0.53:53 (LISTEN)
node         676             rtl   25u  IPv6    21166      0t0  TCP *:7000 (LISTEN)
sshd         716            root    3u  IPv4    23719      0t0  TCP *:22 (LISTEN)
sshd         716            root    4u  IPv6    23730      0t0  TCP *:22 (LISTEN)
rpc.statd    771           statd    9u  IPv4    25254      0t0  TCP *:41613 (LISTEN)
rpc.statd    771           statd   11u  IPv6    25260      0t0  TCP *:38191 (LISTEN)
bitcoind     867         bitcoin   11u  IPv6    21150      0t0  TCP [::1]:8332 (LISTEN)
bitcoind     867         bitcoin   12u  IPv4    21152      0t0  TCP 127.0.0.1:8332 (LISTEN)
bitcoind     867         bitcoin   28u  IPv4    21341      0t0  TCP 127.0.0.1:8334 (LISTEN)
bitcoind     867         bitcoin   29u  IPv6    21342      0t0  TCP *:8333 (LISTEN)
bitcoind     867         bitcoin   31u  IPv4    21343      0t0  TCP *:8333 (LISTEN)
tor          879      debian-tor    6u  IPv4    24237      0t0  TCP 127.0.0.1:9050 (LISTEN)
tor          879      debian-tor    7u  IPv4    24238      0t0  TCP 127.0.0.1:9051 (LISTEN)
electrs     1158         electrs    3u  IPv4    25702      0t0  TCP 127.0.0.1:4224 (LISTEN)
electrs     1158         electrs    4u  IPv4    25703      0t0  TCP 127.0.0.1:50001 (LISTEN)
python      1747          lnbits   19u  IPv4    30823      0t0  TCP 127.0.0.1:5000 (LISTEN)
lightning  56323       lightning    5u  IPv4   624561      0t0  TCP 127.0.0.1:9736 (LISTEN)
lightning  56323       lightning    6u  IPv4   624562      0t0  TCP *:9735 (LISTEN)
node       56610       lightning   26u  IPv6   628171      0t0  TCP *:3001 (LISTEN)
node       56610       lightning   27u  IPv6   628172      0t0  TCP *:4001 (LISTEN)
nginx     975705            root    6u  IPv4 11787171      0t0  TCP *:443 (LISTEN)
nginx     975705            root    7u  IPv4 11787172      0t0  TCP *:80 (LISTEN)
nginx     975705            root    8u  IPv4 11787173      0t0  TCP *:50002 (LISTEN)
(the last three lines repeated 3 times as I have 4 workers)

I have compiled nginx with these arguments:

marius@mlbb2:~$ nginx -V
nginx version: nginx/1.25.3
built by gcc 11.4.0 (Ubuntu 11.4.0-1ubuntu1~22.04) 
built with OpenSSL 3.0.2 15 Mar 2022
TLS SNI support enabled
configure arguments: --sbin-path=/usr/local/bin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --modules-path=/etc/nginx/modules --with-pcre --with-http_ssl_module --with-stream --with-stream_ssl_preread_module --with-stream_ssl_module --with-http_gzip_static_module --with-http_gunzip_module

Electrum client: (getinfo(): "auto_connect": false, "blockchain_height": 818697,"connected": false,"default_wallet": "/Users/marius/.electrum/wallets/default_wallet", "fee_per_kb": null,"network": "mainnet","path": "/Users/marius/.electrum","server": "MY_SITE.COM","server_height": 0,"spv_nodes": 9,"version": "4.4.6")

as soon as I start the above client I see the following with tcpdump:

marius@mlbb2:~$ sudo tcpdump port 50002 and '(tcp-syn|tcp-ack)!=0'
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on ens18, link-type EN10MB (Ethernet), snapshot length 262144 bytes
12:03:28.828861 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [S], seq 1543470894, win 65535, options [mss 1452,nop,wscale 6,nop,nop,TS val 4107815640 ecr 0,sackOK,eol], length 0
12:03:28.828880 IP mlbb2.fritz.box.50002 > 99.99.99.99.58811: Flags [S.], seq 1035971693, ack 1543470895, win 65160, options [mss 1460,sackOK,TS val 4124502244 ecr 4107815640,nop,wscale 7], length 0
12:03:28.832589 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [.], ack 1, win 2070, options [nop,nop,TS val 4107815646 ecr 4124502244], length 0
12:03:28.835365 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [P.], seq 1:518, ack 1, win 2070, options [nop,nop,TS val 4107815649 ecr 4124502244], length 517
12:03:28.835372 IP mlbb2.fritz.box.50002 > 99.99.99.99.58811: Flags [.], ack 518, win 506, options [nop,nop,TS val 4124502251 ecr 4107815649], length 0
12:03:28.835675 IP mlbb2.fritz.box.50002 > 99.99.99.99.58811: Flags [P.], seq 1:4097, ack 518, win 506, options [nop,nop,TS val 4124502251 ecr 4107815649], length 4096
12:03:28.836354 IP mlbb2.fritz.box.50002 > 99.99.99.99.58811: Flags [P.], seq 4097:4527, ack 518, win 506, options [nop,nop,TS val 4124502252 ecr 4107815649], length 430
12:03:28.838573 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [.], ack 2881, win 2025, options [nop,nop,TS val 4107815653 ecr 4124502251], length 0
12:03:28.839609 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [.], ack 4527, win 1999, options [nop,nop,TS val 4107815653 ecr 4124502252], length 0
12:03:28.839978 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [.], ack 4527, win 2048, options [nop,nop,TS val 4107815653 ecr 4124502252], length 0
12:03:28.841339 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [F.], seq 518, ack 4527, win 2048, options [nop,nop,TS val 4107815655 ecr 4124502252], length 0
12:03:28.841371 IP mlbb2.fritz.box.50002 > 99.99.99.99.58811: Flags [F.], seq 4527, ack 519, win 506, options [nop,nop,TS val 4124502257 ecr 4107815655], length 0
12:03:28.846843 IP 99.99.99.99.58811 > mlbb2.fritz.box.50002: Flags [.], ack 4528, win 2048, options [nop,nop,TS val 4107815659 ecr 4124502257], length 0
12:03:30.757673 IP 99.99.99.99.58823 > mlbb2.fritz.box.50002: Flags [S], seq 3684983692, win 65535, options [mss 1452,nop,wscale 6,nop,nop,TS val 1578602325 ecr 0,sackOK,eol], length 0

I assume therefore that the request reaches the server on port 50002.

This is the output of a request to 50002 with the result "* Received HTTP/0.9 when not allowed".

marius@mlbb2:~$ curl -I --verbose https://MY_SITE.COM:50002
*   Trying 99.99.99.99:50002...
* Connected to MY_SITE.COM (99.99.99.99) port 50002 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.0 (OUT), TLS header, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS header, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS header, Finished (20):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.2 (OUT), TLS header, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server did not agree to a protocol
* Server certificate:
*  subject: CN=MY_SITE.COM
*  start date: Nov 25 11:03:06 2023 GMT
*  expire date: Feb 23 11:03:05 2024 GMT
*  subjectAltName: host "MY_SITE.COM" matched cert's "MY_SITE.COM"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
> HEAD / HTTP/1.1
> Host: MY_SITE.COM:50002
> User-Agent: curl/7.81.0
> Accept: */*
> 
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* TLSv1.2 (IN), TLS header, Supplemental data (23):
* Received HTTP/0.9 when not allowed
* Closing connection 0
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
* TLSv1.3 (OUT), TLS alert, close notify (256):
curl: (1) Received HTTP/0.9 when not allowed

Expected behavior
the electrs instance running on the server can be reached from the electrum client running on the laptop

Actual behavior
No response reaches electrum client on another computer.

[romanz]

Could you please try to send the following command to your server (using netcat):

$ echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | netcat MY_SITE.COM 50002

and attach the logs?

[marimes]

The above command (issued on the client) produces no output at all as shown here:

marius@eb4m:~$ echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | netcat MY_SITE:COM 50002
marius@eb4m:~$ 

When I trace traffic on 50002 on the server I see this while I issue the above command:

20:40:29.626046 IP 99.99.99.99.16416 > mlbb2.fritz.box.50002: Flags [S], seq 3439253556, win 64240, options [mss 1452,sackOK,TS val 1157031007 ecr 0,nop,wscale 7], length 0
20:40:29.626059 IP mlbb2.fritz.box.50002 > 99.99.99.99.16416: Flags [S.], seq 3973764396, ack 3439253557, win 65160, options [mss 1460,sackOK,TS val 292542902 ecr 1157031007,nop,wscale 7], length 0
20:40:29.632373 IP 99.99.99.99.16416 > mlbb2.fritz.box.50002: Flags [.], ack 1, win 502, options [nop,nop,TS val 1157031011 ecr 292542902], length 0
20:40:29.632564 IP 99.99.99.99.16416 > mlbb2.fritz.box.50002: Flags [P.], seq 1:80, ack 1, win 502, options [nop,nop,TS val 1157031012 ecr 292542902], length 79
20:40:29.632577 IP mlbb2.fritz.box.50002 > 99.99.99.99.16416: Flags [.], ack 80, win 509, options [nop,nop,TS val 292542909 ecr 1157031012], length 0
20:40:29.632614 IP mlbb2.fritz.box.50002 > 99.99.99.99.16416: Flags [F.], seq 1, ack 80, win 509, options [nop,nop,TS val 292542909 ecr 1157031012], length 0
20:40:29.635108 IP 99.99.99.99.16416 > mlbb2.fritz.box.50002: Flags [F.], seq 80, ack 2, win 502, options [nop,nop,TS val 1157031016 ecr 292542909], length 0
20:40:29.635114 IP mlbb2.fritz.box.50002 > 99.99.99.99.16416: Flags [.], ack 81, win 509, options [nop,nop,TS val 292542911 ecr 1157031016], length 0

[Kixunil]

First of all big thanks for very detailed report! I wish more people were doing it like this!

Could you please check if there's communication between nginx and electrs? Port 50001 in tcp dump should do it. Also I think @romanz made a mistake not noticing TLS, you need to use openssl s_client -connect MYSITE.COM:50002 instead of nc ....

Possible issues:

• electrs may be synchronizing, so it's not bound
• electrs may be broken by some kind of DoS attack - it's not designed to be publicly accessible and your setup makes it accessible. I'd recommend using a tunnel or check if client certificates can be used (I never tried).
• There's a bug that makes electrs stuck after some time, try restarting it (IIRC I observed this in older versions of electrs but not in new ones. Are you running an up-to-date version?)

[marimes]

marius@eb4m:~$ echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | openssl s_client -connect MY_SITE.COM:50002
CONNECTED(00000003)
depth=2 C = US, O = Internet Security Research Group, CN = ISRG Root X1
verify return:1
depth=1 C = US, O = Let's Encrypt, CN = R3
verify return:1
depth=0 CN = MY_SITE.COM
verify return:1
---
Certificate chain
 0 s:CN = MY_SITE.COM
   i:C = US, O = Let's Encrypt, CN = R3
 1 s:C = US, O = Let's Encrypt, CN = R3
   i:C = US, O = Internet Security Research Group, CN = ISRG Root X1
 2 s:C = US, O = Internet Security Research Group, CN = ISRG Root X1
   i:O = Digital Signature Trust Co., CN = DST Root CA X3
---
Server certificate
-----BEGIN CERTIFICATE-----
(... certificate content removed here ...)
-----END CERTIFICATE-----
subject=CN = MY_SITE.COM

issuer=C = US, O = Let's Encrypt, CN = R3

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 4526 bytes and written 390 bytes
Verification: OK
---
New, TLSv1.3, Cipher is TLS_AES_256_GCM_SHA384
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---
DONE

[marimes]

electrs version is v0.10.0

Synch status seems OK:

marius@mlbb2:~$ systemctl status electrs.service 
● electrs.service - Electrs daemon
     Loaded: loaded (/etc/systemd/system/electrs.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2023-11-01 13:11:21 UTC; 1 month 1 day ago
   Main PID: 1158 (electrs)
      Tasks: 19 (limit: 38268)
     Memory: 1.7G
        CPU: 1d 4h 52min 52.415s
     CGroup: /system.slice/electrs.service
             └─1158 /usr/local/bin/electrs --conf /home/electrs/.electrs/electrs.conf

Dec 03 11:21:21 mlbb2 electrs[1158]: [2023-12-03T11:21:21.595Z INFO  electrs::index] indexing 1 blocks: [819550..819550]
Dec 03 11:21:21 mlbb2 electrs[1158]: [2023-12-03T11:21:21.638Z INFO  electrs::chain] chain updated: tip=00000000000000000002a53f3b2db160378adf4baf9>
Dec 03 11:28:24 mlbb2 electrs[1158]: [2023-12-03T11:28:24.725Z INFO  electrs::index] indexing 1 blocks: [819551..819551]
Dec 03 11:28:24 mlbb2 electrs[1158]: [2023-12-03T11:28:24.776Z INFO  electrs::chain] chain updated: tip=00000000000000000001b2c54c2f9d97ded38366701>
Dec 03 11:28:37 mlbb2 electrs[1158]: [2023-12-03T11:28:37.003Z INFO  electrs::index] indexing 1 blocks: [819552..819552]
Dec 03 11:28:37 mlbb2 electrs[1158]: [2023-12-03T11:28:37.049Z INFO  electrs::chain] chain updated: tip=0000000000000000000362588e136eac368b25a774a>
Dec 03 11:38:55 mlbb2 electrs[1158]: [2023-12-03T11:38:55.489Z INFO  electrs::index] indexing 1 blocks: [819553..819553]
Dec 03 11:38:55 mlbb2 electrs[1158]: [2023-12-03T11:38:55.535Z INFO  electrs::chain] chain updated: tip=00000000000000000003ddbd87d6298ca1ba320cebc>
Dec 03 11:44:56 mlbb2 electrs[1158]: [2023-12-03T11:44:56.986Z INFO  electrs::index] indexing 1 blocks: [819554..819554]
Dec 03 11:44:57 mlbb2 electrs[1158]: [2023-12-03T11:44:57.032Z INFO  electrs::chain] chain updated: tip=000000000000000000016ddcce88455c56405533da2

[onlineapps-cloud]

hi, i have same problem (some times), i use mynodebtc , as i understand electrs is used as electrum server, so it's happens some time that i cannot reach electrs server in my local network, i tried to restart from mynodebtc dashboard, but this not help, i need to restart entire mynodebtc to connect. when i will have connection stuck, i will post systemctl status, i had problem few minutes ago, and i started to search where to write about this bug, and found oppened topic. best wishes.

[Kixunil]

Could you try the nc one but from the server, using localhost and port 50001?

[onlineapps-cloud]

Could you try the nc one but from the server, using localhost and port 50001?

nothing happens

admin@myNode:~$ systemctl status electrs.service
● electrs.service - myNode Electrum Server
     Loaded: loaded (/etc/systemd/system/electrs.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2023-12-03 12:57:29 EST; 5h 22min ago
    Process: 12583 ExecStartPre=/usr/bin/is_not_shutting_down.sh (code=exited, status=0/SUCCESS)
    Process: 12584 ExecStartPre=/usr/bin/wait_on_bitcoin.sh (code=exited, status=0/SUCCESS)
    Process: 12586 ExecStartPre=/usr/bin/service_scripts/pre_electrs.sh (code=exited, status=0/SUCCESS)
   Main PID: 12619 (electrs)
      Tasks: 23
     Memory: 1.0G
        CPU: 8min 17.227s
     CGroup: /system.slice/electrs.service
             └─12619 /usr/bin/electrs --conf=/mnt/hdd/mynode/electrs/electrs.toml

admin@myNode:~$ echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | netcat 127.0.0.1 50002
admin@myNode:~$ echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | netcat 127.0.0.1 50001
{"id":0,"jsonrpc":"2.0","result":["electrs/0.9.9","1.4"]}

/mnt/hdd/mynode/electrs/electrs.toml

# --timestamp --db-dir /mnt/hdd/mynode/electrs --electrum-rpc-addr 0.0.0.0:50001 --jsonrpc-import --bulk-index-threads 3 --index-batch-size 12 --daemon-rpc-addr 127.0.0.1:8332 --txid-limit 100 --tx-cache-size-mb 10.0 --wait-duration-secs 15 

log_filters = "INFO"
timestamp = true
#jsonrpc_import = true
jsonrpc_timeout_secs = 30
daemon_rpc_addr = "127.0.0.1:8332"
db_dir = "/mnt/hdd/mynode/electrs"
electrum_rpc_addr = "0.0.0.0:50001"
monitoring_addr = "127.0.0.1:4224"
bulk_index_threads = 3
index_lookup_limit = 1001
tx_cache_size_mb = 10.0
wait_duration_secs = 15
network = "bitcoin"

Right now electrs stucked, if you need additional information, let me know, if tomorrow system will be stucked, i will extract additional information.

[Kixunil]

Could it be a hardware issue with HDD? Check dmesg maybe?

[onlineapps-cloud]

problem is not in HDD, because i use inside in Proxmox, i don't have dedicated hdd to mynodebtc, but i get the dmesg log: https://pastebin.com/yj710VpF
maybe it will be helpful. Also glitch dissapear today.

[romanz]

@marimes Could you please also run:

echo '{"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}' | netcat 127.0.0.1 50001

on the same machine running electrs?

If possible, please also increase electrs log verbosity to log_filters = "DEBUG".

[marimes]

The result is: {"id":0,"jsonrpc":"2.0","result":["electrs/0.10.0","1.4"]}

I have restarted electrs with the DEBUG flag set in the config file and the output looks like this:

2023/12/04-23:43:27.311968 1465250 EVENT_LOG_v1 {"time_micros": 1701733407311949, "cf_name": "spending", "job": 23, "event": "table_file_creation", "file_number": 47119, "file_size": 57955627, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 5842009502, "largest_seqno": 5901805142, "table_properties": {"data_size": 57538000, "index_size": 490562, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 120367220, "raw_average_key_size": 20, "raw_value_size": 0, "raw_average_value_size": 0, "num_data_blocks": 27022, "num_entries": 6018361, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "spending", "column_family_id": 5, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "rocksdb.FixedPrefix.8", "property_collectors": "[]", "compression": "ZSTD", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1700002339, "oldest_key_time": 0, "file_creation_time": 1701733403, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "92eee7af-8417-4e10-9058-5086d26219eb", "db_session_id": "M2116IE67VI0KQMR9YVJ", "orig_file_number": 47119, "seqno_to_time_mapping": "N/A"}}
2023/12/04-23:43:31.160562 1465250 [db/compaction/compaction_job.cc:1587] [spending] [JOB 23] Generated table #47120: 6002799 keys, 57880686 bytes, temperature: kUnknown
2023/12/04-23:43:31.160599 1465250 EVENT_LOG_v1 {"time_micros": 1701733411160580, "cf_name": "spending", "job": 23, "event": "table_file_creation", "file_number": 47120, "file_size": 57880686, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 5852754270, "largest_seqno": 5901811081, "table_properties": {"data_size": 57464643, "index_size": 489024, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 120055980, "raw_average_key_size": 20, "raw_value_size": 0, "raw_average_value_size": 0, "num_data_blocks": 26960, "num_entries": 6002799, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "spending", "column_family_id": 5, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "rocksdb.FixedPrefix.8", "property_collectors": "[]", "compression": "ZSTD", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1700002339, "oldest_key_time": 0, "file_creation_time": 1701733407, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "92eee7af-8417-4e10-9058-5086d26219eb", "db_session_id": "M2116IE67VI0KQMR9YVJ", "orig_file_number": 47120, "seqno_to_time_mapping": "N/A"}}
2023/12/04-23:43:33.951494 1465250 [db/compaction/compaction_job.cc:1587] [spending] [JOB 23] Generated table #47121: 4400165 keys, 42424105 bytes, temperature: kUnknown
2023/12/04-23:43:33.951536 1465250 EVENT_LOG_v1 {"time_micros": 1701733413951516, "cf_name": "spending", "job": 23, "event": "table_file_creation", "file_number": 47121, "file_size": 42424105, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 5852757007, "largest_seqno": 5901815544, "table_properties": {"data_size": 42120611, "index_size": 358239, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 88003300, "raw_average_key_size": 20, "raw_value_size": 0, "raw_average_value_size": 0, "num_data_blocks": 19762, "num_entries": 4400165, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "spending", "column_family_id": 5, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "rocksdb.FixedPrefix.8", "property_collectors": "[]", "compression": "ZSTD", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1700002339, "oldest_key_time": 0, "file_creation_time": 1701733411, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "92eee7af-8417-4e10-9058-5086d26219eb", "db_session_id": "M2116IE67VI0KQMR9YVJ", "orig_file_number": 47121, "seqno_to_time_mapping": "N/A"}}
2023/12/04-23:43:33.956096 1465250 (Original Log Time 2023/12/04-23:43:33.955063) [db/compaction/compaction_job.cc:1662] [spending] [JOB 23] Compacted 4@0 + 3@1 files to L1 => 158260418 bytes
2023/12/04-23:43:33.956098 1465250 (Original Log Time 2023/12/04-23:43:33.956044) [db/compaction/compaction_job.cc:864] [spending] compacted to: files[0 3 0 68 0 0 0] max score 0.67, MB/sec: 15.1 rd, 15.1 wr, level 1, files in(4, 3) out(3 +0 blob) MB in(0.4, 150.6 +0.0 blob) out(150.9 +0.0 blob), read-write-amplify(843.7) write-amplify(421.9) OK, records in: 16421325, records dropped: 0 output_compression: ZSTD
2023/12/04-23:43:33.956102 1465250 (Original Log Time 2023/12/04-23:43:33.956061) EVENT_LOG_v1 {"time_micros": 1701733413956052, "job": 23, "event": "compaction_finished", "compaction_time_micros": 10481085, "compaction_time_cpu_micros": 10430541, "output_level": 1, "num_output_files": 3, "total_output_size": 158260418, "num_input_records": 16421325, "num_output_records": 16421325, "num_subcompactions": 1, "output_compression": "ZSTD", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 3, 0, 68, 0, 0, 0]}
2023/12/04-23:43:33.956191 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047118.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.956197 1465250 EVENT_LOG_v1 {"time_micros": 1701733413956195, "job": 23, "event": "table_file_deletion", "file_number": 47118}
2023/12/04-23:43:33.956244 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047093.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.956247 1465250 EVENT_LOG_v1 {"time_micros": 1701733413956246, "job": 23, "event": "table_file_deletion", "file_number": 47093}
2023/12/04-23:43:33.956285 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047084.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.956288 1465250 EVENT_LOG_v1 {"time_micros": 1701733413956287, "job": 23, "event": "table_file_deletion", "file_number": 47084}
2023/12/04-23:43:33.956324 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047078.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.956327 1465250 EVENT_LOG_v1 {"time_micros": 1701733413956326, "job": 23, "event": "table_file_deletion", "file_number": 47078}
2023/12/04-23:43:33.961863 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047073.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.961868 1465250 EVENT_LOG_v1 {"time_micros": 1701733413961867, "job": 23, "event": "table_file_deletion", "file_number": 47073}
2023/12/04-23:43:33.970884 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047072.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.970892 1465250 EVENT_LOG_v1 {"time_micros": 1701733413970890, "job": 23, "event": "table_file_deletion", "file_number": 47072}
2023/12/04-23:43:33.978983 1465250 [file/delete_scheduler.cc:73] Deleted file /home/electrs/.electrs/db/bitcoin/047071.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2023/12/04-23:43:33.978989 1465250 EVENT_LOG_v1 {"time_micros": 1701733413978987, "job": 23, "event": "table_file_deletion", "file_number": 47071}
2023/12/04-23:43:33.979066 1465250 (Original Log Time 2023/12/04-23:43:33.979059) [db/db_impl/db_impl_compaction_flush.cc:3275] Compaction nothing to do
2023/12/04-23:43:34.110115 1465242 [db/db_impl/db_impl_compaction_flush.cc:1746] [config] Manual flush start.
2023/12/04-23:43:34.110123 1465242 [db/db_impl/db_impl_compaction_flush.cc:1756] [config] Manual flush finished, status: OK
2023/12/04-23:43:34.110126 1465242 [db/db_impl/db_impl_compaction_flush.cc:1746] [headers] Manual flush start.
2023/12/04-23:43:34.110128 1465242 [db/db_impl/db_impl_compaction_flush.cc:1756] [headers] Manual flush finished, status: OK

[conduition]

I'm also experiencing this bug, on a locally running Electrs server connected to a bitcoin node over LAN. Here's what I see from simply launching electrs. Early on, i managed to send a quick server.version request which was handled correctly.

$ electrs 
Starting electrs 0.10.1 on x86_64 linux with Config { network: Bitcoin, db_path: "/mnt/electrs/bitcoin", daemon_dir: "/home/user/.bitcoin", daemon_auth: UserPass("<sensitive>", "<sensitive>"), daemon_rpc_addr: 10.xxx.xxx.xxx:8332, daemon_p2p_addr: 10.xxx.xxx.xxx:8333, electrum_rpc_addr: 127.0.0.1:50001, monitoring_addr: 127.0.0.1:4224, wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: None, reindex_last_blocks: 0, auto_reindex: true, ignore_mempool: false, sync_once: false, skip_block_download_wait: false, disable_electrum_rpc: false, server_banner: "Welcome to electrs 0.10.1 (Electrum Rust Server)!", signet_magic: f9beb4d9, args: [] }
[2023-12-05T22:07:47.922Z DEBUG electrs::metrics::metrics_fake] metrics collection is disabled
[2023-12-05T22:07:47.922Z INFO  electrs::server] serving Electrum RPC on 127.0.0.1:50001
[2023-12-05T22:07:47.953Z INFO  electrs::db] "/mnt/electrs/bitcoin": 188 SST files, 44.605034211 GB, 5.566030569 Grows
[2023-12-05T22:07:47.953Z DEBUG electrs::db] DB Some(Config { compacted: true, format: 0 })
[2023-12-05T22:07:47.994Z DEBUG electrs::db] auto-compactions enabled
[2023-12-05T22:07:49.516Z INFO  electrs::chain] loading 819935 headers, tip=00000000000000000001b7a27f012ceb96493cade08d23adeadf61d373fc31be
[2023-12-05T22:07:52.414Z DEBUG electrs::server] 0: recv {"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}
[2023-12-05T22:07:52.648Z INFO  electrs::chain] chain updated: tip=00000000000000000001b7a27f012ceb96493cade08d23adeadf61d373fc31be, height=819935
[2023-12-05T22:07:52.673Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
[2023-12-05T22:07:52.681Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2023-12-05T22:07:52.683Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2023-12-05T22:07:52.685Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
[2023-12-05T22:07:52.687Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2023-12-05T22:07:52.693Z DEBUG electrs::p2p] peer version: VersionMessage { version: 70016, services: ServiceFlags(1037), timestamp: 1701814073, receiver: Address {services: ServiceFlags(NONE), address: 0.0.0.0, port: 0}, sender: Address {services: ServiceFlags(NETWORK|BLOOM|WITNESS|NETWORK_LIMITED), address: 0.0.0.0, port: 0}, nonce: 4166182828414797083, user_agent: "/Satoshi:25.0.0/", start_height: 819935, relay: true }
[2023-12-05T22:07:52.693Z DEBUG electrs::server] 0: connected
[2023-12-05T22:07:52.693Z DEBUG electrs::server] 0: send {"id":0,"jsonrpc":"2.0","result":["electrs/0.10.1","1.4"]}
[2023-12-05T22:07:52.695Z DEBUG electrs::p2p] got 0 new headers
[2023-12-05T22:07:52.707Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawmempool []
[2023-12-05T22:07:59.814Z DEBUG electrs::mempool] loading 133608 mempool transactions
[2023-12-05T22:07:59.841Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawtransaction ["ef15a09a06cc36a84eddc78c4196727535f4bc1c8c948b1ef69b0ae567ed9ff1",false]
[2023-12-05T22:07:59.841Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawtransaction ["74d27ae4a132dcc8a3bc5a1c043b0ecfe8c2fcb0d39407c04b1b2ad53d440a4e",false]
[2023-12-05T22:07:59.861Z DEBUG bitcoincore_rpc] JSON-RPC request: getmempoolentry ["ef15a09a06cc36a84eddc78c4196727535f4bc1c8c948b1ef69b0ae567ed9ff1"]
[2023-12-05T22:07:59.863Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawtransaction ["12a82ea5e8ca86e00bacb5e71439a6fd7c1dc2976beeff1e7ff88ce983a86dac",false]
[2023-12-05T22:07:59.866Z DEBUG bitcoincore_rpc] JSON-RPC request: getmempoolentry ["74d27ae4a132dcc8a3bc5a1c043b0ecfe8c2fcb0d39407c04b1b2ad53d440a4e"]
[2023-12-05T22:07:59.869Z DEBUG bitcoincore_rpc] JSON-RPC request: getmempoolentry ["12a82ea5e8ca86e00bacb5e71439a6fd7c1dc2976beeff1e7ff88ce983a86dac"]
[2023-12-05T22:07:59.871Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawtransaction ["66308b912ee0dfbaf5239d18bc2a44097f906565caf453aa5d37b4149b406bec",false]
[2023-12-05T22:07:59.876Z DEBUG bitcoincore_rpc] JSON-RPC request: getmempoolentry ["66308b912ee0dfbaf5239d18bc2a44097f906565caf453aa5d37b4149b406bec"]
[2023-12-05T22:07:59.880Z DEBUG bitcoincore_rpc] JSON-RPC request: getrawtransaction ["1ff0091d2b4b2f6100f57bc5fc3872ed815f4c1536161fdacbd20e365c598722",false]
[2023-12-05T22:07:59.882Z DEBUG bitcoincore_rpc] JSON-RPC request: getmempoolentry ["1ff0091d2b4b2f6100f57bc5fc3872ed815f4c1536161fdacbd20e365c59872
...

After that, it's an endless stream of getrawtransaction and getmempoolentry log lines like the last few lines above. While these lines are still being printed, I am unable to execute any JSON-RPC calls successfully. The server keeps the socket open but simply does not reply.

I suspect the problem may be related to the mempool scanning functionality. If i launch electrs with

electrs --ignore-mempool

... then the bug goes away, and the server becomes responsive again.

Once the mempool scan is complete, I am briefly able to access the server at intervals, but then a new mepool scan begins and I am locked out again until that scan completes, which is often several seconds at a time.

It appears that while the mempool scan is ongoing, the electrs server isn't able to reply to incoming client requests. Perhaps as a consequence of my LAN connection to my BTC core node, the mempool scanning takes much longer, long enough that intermittent scanning causes client requests to simply time out.

[conduition]

While unresponsive, the electrs server will still print log lines that it receives incoming JSON-RPC requests.

[2023-12-05T22:19:42.393Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "server.version", "params": ["", "1.4"], "id": 0}

However, these requests are not handled.

All the above is strongly suggesting to me that the rpc.sync() call on this line is blocking for too long, probably because the mempool.sync() call on this line is blocking. This results in JSON-RPC client calls not being handled because the electrs code relies on syncing being paused before handling incoming client requests.

That hypothesis would also explain why i can't kill the electrum server without using kill -9.

I'm not sure if my case is the same as OP, because OP's bitcoin node is on the same machine as electrs, and so mempool scanning would take much less time. @marimes do you think this might be your issue? To confirm try launching electrs --ignore-mempool and let me know if this fixes the unresponsiveness