[bug]: lncli getinfo and LND in general, getting stuck at COMMIT when using Postgres

[FeatureSpitter]

There are no errors in the logs, other commands like walletbalance and getnetworkinfo return (they take a few seconds tho), but getinfo and listpeers and maybe others take forever to return... no error in the logs. I am using 0.17 RC3 on raspberry pi 4 8GB. The CPU is at 1% or less most of the time, with some spikes at 40-70% either from LND or Bitcoind...

Logs: https://pastebin.com/W10vaKgF

LND: lncli version 0.17.0-beta.rc3 commit=v0.17.0-beta.rc3-19-g9f4a8836d

OS: Linux raspberrypi 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux

Examples:

pi@raspberrypi:~ $ time ll walletbalance
{
    "total_balance": "33268",
    "confirmed_balance": "33268",
    "unconfirmed_balance": "0",
    "locked_balance": "0",
    "reserved_balance_anchor_chan": "0",
    "account_balance": {
        "default": {
            "confirmed_balance": "33268",
            "unconfirmed_balance": "0"
        }
    }
}

real	0m0.678s
user	0m0.102s
sys	0m0.073s

$ time ll getinfo
^C[lncli] rpc error: code = Canceled desc = context canceled

real	3m5.953s
user	0m0.087s
sys	0m0.095s

(I ctrl+c to make it stop)

$ time ll listchannels
^C[lncli] rpc error: code = Canceled desc = context canceled

real	3m28.391s
user	0m0.083s
sys	0m0.159s

(I ctrl+c to make it stop)

LND.CONF:

[Application Options]
debuglevel=info
maxpendingchannels=10
alias=*******************
color=#ffffff

rpclisten=0.0.0.0:10009
listen=0.0.0.0:9735
restlisten=0.0.0.0:8001

[Bitcoin]
bitcoin.active=1
bitcoin.testnet=0
bitcoin.mainnet=1
bitcoin.node=bitcoind

; The base fee in millisatoshi we will charge for forwarding payments on our
; channels.
bitcoin.basefee=5

; The fee rate used when forwarding payments on our channels. The total fee
; charged is basefee + (amount * feerate / 1000000), where amount is the
; forwarded amount.
bitcoin.feerate=1

[Bitcoind]
bitcoind.rpchost=bitcoind:8332
bitcoind.rpcuser=*****************************
bitcoind.rpcpass=***********************
bitcoind.zmqpubrawblock=tcp://bitcoind:28332
bitcoind.zmqpubrawtx=tcp://bitcoind:28333

; Fee estimate mode for bitcoind. It must be either "ECONOMICAL" or "CONSERVATIVE".
; If unset, the default value is "CONSERVATIVE".
bitcoind.estimatemode=CONSERVATIVE

[tor]
tor.active=true
tor.v3=true
tor.streamisolation=false
tor.skip-proxy-for-clearnet-targets=false
tor.socks=tor:9050
tor.control=tor:9051
tor.password=*********************
tor.targetipaddress=10.5.0.6

[wtclient]

; Activate Watchtower Client. To get more information or configure watchtowers
; run `lncli wtclient -h`.
wtclient.active=true

; Specify the fee rate with which justice transactions will be signed. This fee
; rate should be chosen as a maximum fee rate one is willing to pay in order to
; sweep funds if a breach occurs while being offline. The fee rate should be
; specified in sat/vbyte.
wtclient.sweep-fee-rate=30

[db]
db.backend=postgres

[postgres]
; Postgres connection string.
; Default:
;   db.postgres.dsn=
; Example:
db.postgres.dsn=postgres://postgres:********************************************@pgsql:5432/lnd?sslmode=disable

; Postgres connection timeout. Valid time units are {s, m, h}. Set to zero to
; disable.
db.postgres.timeout=3m

; Postgres maximum number of connections. Set to zero for unlimited. It is
; recommended to set a limit that is below the server connection limit.
; Otherwise errors may occur in lnd under high-load conditions.
; Default:
db.postgres.maxconnections=10

Bitcoind seems ok:

$ btc getblockchaininfo
{
  "chain": "main",
  "blocks": 808403,
  "headers": 808403,
  "bestblockhash": "0000000000000000000314d5ce9e52d2677c08d3dc8a617690a13897203f53fa",
  "difficulty": 54150142369480,
  "time": 1695107587,
  "mediantime": 1695104573,
  "verificationprogress": 0.9999999672514687,
  "initialblockdownload": false,
  "chainwork": "000000000000000000000000000000000000000056098a6c3da24d6620caa504",
  "size_on_disk": 581069847788,
  "pruned": false,
  "warnings": ""
}

[guggero]

It's hard to say, we've heard a similar report from someone else. So it would be really helpful if you could help us debug this.

Since you're already on commit 9f4a883, can you please add the following to your config and restart:

profile=1234
blockingprofile=1
mutexprofile=1

And then while such a blocking request is going on (e.g. you're waiting for the response, but before aborting the command), please run the following three commands and upload the output (shouldn't contain any sensitive info, just some memory addresses):

curl http://localhost:1234/debug/pprof/goroutine?debug=2
curl http://localhost:1234/debug/pprof/block
curl http://localhost:1234/debug/pprof/mutex

Thanks!

[FeatureSpitter]

Ok, I'll come back to you in a moment

[FeatureSpitter]

Now when I restarted it (the 4th time this morning), started working perfectly... Before even after restarting for the 3rd time it wasn't responding.
LND is just to messing with me...

It will eventually start to bug again, it always does, and by then I'll run those command and post here.

[FeatureSpitter]

@guggero here it is: https://www.dropbox.com/scl/fo/0v3wo0pmctw4g6m8dcgvp/h?rlkey=2aeljel9l500tp9ihl1ezhtu6&dl=0

[guggero]

@FeatureSpitter thanks for the goroutine dump, that's very helpful indeed.

@Roasbeef I think we might have another mutext locking issue here, possibly amplified by the single write lock of Postgres.

Here's the full dump: goroutinedump.txt

What looks suspicious:

--> 8 peers seem to be stuck here:

goroutine 714932 [semacquire, 61 minutes]:
sync.runtime_Semacquire(0x4232f90)
	runtime/sema.go:62 +0x3c
sync.(*WaitGroup).Wait(0x4232f88)
	sync/waitgroup.go:116 +0x68
github.com/lightningnetwork/lnd/peer.(*Brontide).WaitForDisconnect(0x4232d80, 0x5122e80)
	github.com/lightningnetwork/lnd/peer/brontide.go:1102 +0xd8
github.com/lightningnetwork/lnd.(*server).peerTerminationWatcher(0x4372b60, 0x4232d80, 0x5122e80)
	github.com/lightningnetwork/lnd/server.go:4017 +0x74
created by github.com/lightningnetwork/lnd.(*server).peerInitializer in goroutine 714931
	github.com/lightningnetwork/lnd/server.go:3973 +0x114

--> 19 goroutines seem to be stuck here:

goroutine 2264025 [sync.RWMutex.RLock, 30 minutes]:
sync.runtime_SemacquireRWMutexR(0x4372bcc, 0x0, 0x0)
	runtime/sema.go:82 +0x3c
sync.(*RWMutex).RLock(0x4372bc0)
	sync/rwmutex.go:71 +0x58
github.com/lightningnetwork/lnd.(*server).BroadcastMessage(0x4372b60, 0x0, {0x1fe16f8, 0x0, 0x0})
	github.com/lightningnetwork/lnd/server.go:3287 +0x2c
github.com/lightningnetwork/lnd/discovery.(*AuthenticatedGossiper).sendLocalBatch(0xcf32310, {0x54e4000, 0x0, 0x6e})
	github.com/lightningnetwork/lnd/discovery/gossiper.go:1286 +0x70
github.com/lightningnetwork/lnd/discovery.(*AuthenticatedGossiper).splitAndSendAnnBatch.func2()
	github.com/lightningnetwork/lnd/discovery/gossiper.go:1260 +0x198
created by github.com/lightningnetwork/lnd/discovery.(*AuthenticatedGossiper).splitAndSendAnnBatch in goroutine 50911
	github.com/lightningnetwork/lnd/discovery/gossiper.go:1251 +0x200


--> Waiting for `p.startReady`:

goroutine 2262974 [select, 30 minutes]:
github.com/lightningnetwork/lnd/peer.(*Brontide).Disconnect(0xeeb6b40, {0x1575da0, 0xdb130c0})
	github.com/lightningnetwork/lnd/peer/brontide.go:1115 +0x94
github.com/lightningnetwork/lnd.(*server).removePeer(0x4372b60, 0xeeb6b40)
	github.com/lightningnetwork/lnd/server.go:4309 +0x100
github.com/lightningnetwork/lnd.(*server).InboundPeerConnected(0x4372b60, {0x1583294, 0x15632960})
	github.com/lightningnetwork/lnd/server.go:3586 +0x6f0
created by github.com/btcsuite/btcd/connmgr.(*ConnManager).listenHandler in goroutine 714406
	github.com/btcsuite/btcd@v0.23.5-0.20230905170901-80f5a0ffdf36/connmgr/connmanager.go:507 +0x250

Looking closer, I think this might actually be because goroutine 714108 is holding the unique Postgres write lock but is waiting for an answer:

goroutine 714108 [runnable]:
syscall.Syscall(0x4, 0x3b, 0x810e800, 0x43)
	syscall/syscall_linux.go:69 +0x8
syscall.write(0x3b, {0x810e800, 0x43, 0x400})
	syscall/zsyscall_linux_arm.go:949 +0x48
syscall.Write(...)
	syscall/syscall_unix.go:209
internal/poll.ignoringEINTRIO(...)
	internal/poll/fd_unix.go:736
internal/poll.(*FD).Write(0x11648780, {0x810e800, 0x43, 0x400})
	internal/poll/fd_unix.go:380 +0x304
net.(*netFD).Write(0x11648780, {0x810e800, 0x43, 0x400})
	net/fd_posix.go:96 +0x38
net.(*conn).Write(0x1eb5aa98, {0x810e800, 0x43, 0x400})
	net/net.go:191 +0x48
github.com/jackc/pgconn.(*PgConn).execExtendedSuffix(0x7bd0000, {0x810e800, 0x2d, 0x400}, 0x7bd0054)
	github.com/jackc/pgconn@v1.14.0/pgconn.go:1153 +0x138
github.com/jackc/pgconn.(*PgConn).ExecPrepared(0x7bd0000, {0x1580210, 0x12f3dea0}, {0x11a29240, 0xe}, {0x154a2840, 0x1, 0x4}, {0x115a11a0, 0x1, ...}, ...)
	github.com/jackc/pgconn@v1.14.0/pgconn.go:1108 +0x118
github.com/jackc/pgx/v4.(*Conn).Query(0x114e8580, {0x1580210, 0x12f3dea0}, {0x64218c0, 0x56}, {0x479fa70, 0x2, 0x2})
	github.com/jackc/pgx/v4@v4.18.1/conn.go:655 +0xc38
github.com/jackc/pgx/v4/stdlib.(*Conn).QueryContext(0xb19bcc0, {0x1580210, 0x12f3dea0}, {0x64218c0, 0x56}, {0x21152870, 0x1, 0x1})
	github.com/jackc/pgx/v4@v4.18.1/stdlib/sql.go:436 +0x330
database/sql.ctxDriverQuery({0x1580210, 0x12f3dea0}, {0xef3c0cb8, 0xb19bcc0}, {0x0, 0x0}, {0x64218c0, 0x56}, {0x21152870, 0x1, ...})
	database/sql/ctxutil.go:48 +0x94
database/sql.(*DB).queryDC.func1()
	database/sql/sql.go:1748 +0x178
database/sql.withLock({0x157ce68, 0x7d725a0}, 0x6db5a1c)
	database/sql/sql.go:3502 +0x84
database/sql.(*DB).queryDC(0x42b0bd0, {0x1580210, 0x12f3dea0}, {0x15801d0, 0x82d30b0}, 0x7d725a0, 0xaec03e0, {0x64218c0, 0x56}, {0x6db5b40, ...})
	database/sql/sql.go:1743 +0x174
database/sql.(*Tx).QueryContext(0xdba5bc0, {0x1580210, 0x12f3dea0}, {0x64218c0, 0x56}, {0x6db5b40, 0x1, 0x1})
	database/sql/sql.go:2497 +0xbc
database/sql.(*Tx).QueryRowContext(...)
	database/sql/sql.go:2515
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*readWriteTx).QueryRow(0x15ace3a8, {0x64218c0, 0x56}, {0x6db5b40, 0x1, 0x1})
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/readwrite_tx.go:180 +0x60
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*readWriteCursor).Next(0x6db5b80)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/readwrite_cursor.go:93 +0x1f8
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*readWriteBucket).ForEach(0x5130c10, 0x1fe64c60)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/readwrite_bucket.go:62 +0x7c
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).pruneGraphNodes(0x448bf80, {0x158597c, 0x5130b20}, {0x158597c, 0x5130c10})
	github.com/lightningnetwork/lnd/channeldb/graph.go:1458 +0x194
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).PruneGraphNodes.func1({0x15844f4, 0x15ace3a8})
	github.com/lightningnetwork/lnd/channeldb/graph.go:1410 +0x11c
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*db).executeTransaction.func2()
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/db.go:311 +0x30
github.com/lightningnetwork/lnd/kvdb/sqlbase.catchPanic(0x6db5cb0)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/db.go:196 +0x68
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*db).executeTransaction(0x439a5c0, 0x14ce83e0, 0x13dcd34, 0x0)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/db.go:311 +0x144
github.com/lightningnetwork/lnd/kvdb/sqlbase.(*db).Update(0x439a5c0, 0x14ce83e0, 0x13dcd34)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/sqlbase/db.go:227 +0x34
github.com/lightningnetwork/lnd/kvdb.Update(...)
	github.com/lightningnetwork/lnd/kvdb@v1.4.4/interface.go:16
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).PruneGraphNodes(0x448bf80)
	github.com/lightningnetwork/lnd/channeldb/graph.go:1396 +0x84
github.com/lightningnetwork/lnd/routing.(*ChannelRouter).pruneZombieChans(0x5622840)
	github.com/lightningnetwork/lnd/routing/router.go:990 +0x76c
github.com/lightningnetwork/lnd/routing.(*ChannelRouter).networkHandler(0x5622840)
	github.com/lightningnetwork/lnd/routing/router.go:1232 +0xbc4
created by github.com/lightningnetwork/lnd/routing.(*ChannelRouter).Start in goroutine 1
	github.com/lightningnetwork/lnd/routing/router.go:689 +0x944

So not sure if things being locked on the server's main mutex is a problem in itself or only really possible if there is only a single DB writer possible.

@FeatureSpitter can you please do the following:

• Check the postgres log if you see anything suspicious that would explain why a single query is taking so long?
• Try reducing the db.postgres.timeout=3m value to something smaller, e.g. 1m
• Try increasing the db.postgres.maxconnections=10 value (but check the actually configured value in Postgres first, that must be at least as large as the number you're using in lnd)

[FeatureSpitter]

I'll try that.

The next time it hangs (shouldn't be taking too much time) I'll fetch the curls again and the postgres logs.

[FeatureSpitter]

@guggero here it goes.

I increased the postgres max connection limit to 200 (both in LND and postgres configs).
I reduced the timeout to 30s.
Here are the postgres logs since it started until the moment getinfo got stuck again:

pgsql       | 
pgsql       | PostgreSQL Database directory appears to contain a database; Skipping initialization
pgsql       | 
pgsql       | 2023-09-19 11:31:00.704 UTC [1] LOG:  starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 12.2.0-14) 12.2.0, 32-bit
pgsql       | 2023-09-19 11:31:00.705 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
pgsql       | 2023-09-19 11:31:00.705 UTC [1] LOG:  listening on IPv6 address "::", port 5432
pgsql       | 2023-09-19 11:31:00.857 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
pgsql       | 2023-09-19 11:31:00.877 UTC [30] LOG:  database system was shut down at 2023-09-19 11:28:58 UTC
pgsql       | 2023-09-19 11:31:00.907 UTC [1] LOG:  database system is ready to accept connections
pgsql       | 2023-09-19 11:36:00.979 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 11:36:42.366 UTC [28] LOG:  checkpoint complete: wrote 414 buffers (2.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=41.286 s, sync=0.063 s, total=41.388 s; sync files=17, longest=0.005 s, average=0.004 s; distance=1623 kB, estimate=1623 kB
pgsql       | 2023-09-19 11:41:00.463 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 11:41:06.929 UTC [28] LOG:  checkpoint complete: wrote 64 buffers (0.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=6.356 s, sync=0.053 s, total=6.467 s; sync files=11, longest=0.015 s, average=0.005 s; distance=366 kB, estimate=1497 kB
pgsql       | 2023-09-19 11:46:01.027 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 11:47:15.293 UTC [28] LOG:  checkpoint complete: wrote 694 buffers (4.2%); 0 WAL file(s) added, 0 removed, 0 recycled; write=74.147 s, sync=0.073 s, total=74.266 s; sync files=18, longest=0.009 s, average=0.005 s; distance=5666 kB, estimate=5666 kB
pgsql       | 2023-09-19 11:51:01.391 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 11:51:41.717 UTC [28] LOG:  checkpoint complete: wrote 397 buffers (2.4%); 0 WAL file(s) added, 0 removed, 1 recycled; write=40.183 s, sync=0.078 s, total=40.327 s; sync files=17, longest=0.020 s, average=0.005 s; distance=4033 kB, estimate=5502 kB
pgsql       | 2023-09-19 11:56:01.774 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 11:59:04.401 UTC [28] LOG:  checkpoint complete: wrote 1810 buffers (11.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=182.531 s, sync=0.038 s, total=182.628 s; sync files=9, longest=0.010 s, average=0.005 s; distance=13725 kB, estimate=13725 kB
pgsql       | 2023-09-19 12:01:01.499 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 12:02:55.945 UTC [28] LOG:  checkpoint complete: wrote 941 buffers (5.7%); 0 WAL file(s) added, 0 removed, 1 recycled; write=114.329 s, sync=0.050 s, total=114.447 s; sync files=15, longest=0.007 s, average=0.004 s; distance=11368 kB, estimate=13489 kB
pgsql       | 2023-09-19 12:11:02.129 UTC [28] LOG:  checkpoint starting: time
pgsql       | 2023-09-19 12:11:44.533 UTC [28] LOG:  checkpoint complete: wrote 423 buffers (2.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=42.321 s, sync=0.041 s, total=42.404 s; sync files=12, longest=0.007 s, average=0.004 s; distance=4030 kB, estimate=12543 kB

And here are the new debug files: https://www.dropbox.com/scl/fo/h9xfa3k2yt08xr2lwygd5/h?rlkey=bbd6f3fh70674v4kxazza9trs&dl=0

As a curiosity, here is the database size (per table):

[FeatureSpitter]

I just did another test:

After waiting for getinfo to return for 25 mins (it didn't return), I sigterm postgres and started it again.

While it was down, lnd complained, as expected, and as soon as postgres was up it stopped complaining and went back to the normal logs:

lnd         | 2023-09-19 12:30:00.003 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:30:00.011 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:31:00.003 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:31:00.011 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:31:41.042 [ERR] CRTR: Failed to update mission control store: unknown postgres error: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)
lnd         | 2023-09-19 12:31:42.043 [ERR] CRTR: Failed to update mission control store: unknown postgres error: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)
lnd         | 2023-09-19 12:31:43.046 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:44.046 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:45.046 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:46.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:47.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:48.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:49.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:50.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:51.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:52.046 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:53.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:54.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:55.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:31:56.045 [ERR] CRTR: Failed to update mission control store: failed to connect to `host=pgsql user=postgres database=lnd`: hostname resolving error (lookup pgsql on 127.0.0.11:53: no such host)
lnd         | 2023-09-19 12:32:00.003 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:32:00.011 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:32:13.037 [INF] DISC: GossipSyncer(02d419c9af624d0e7a7c90a60b9ffa35f4934973a9d7d3b4175cc3cc28b7ffcde1): applying gossipFilter(start=0001-01-01 00:00:00 +0000 UTC, end=0001-01-01 00:00:00 +0000 UTC)
lnd         | 2023-09-19 12:32:13.038 [INF] DISC: GossipSyncer(0390cc12f782259427bdc45a283705f4c20ccbdff064ed43f6b74fefcafe9eb1f7): applying gossipFilter(start=2023-09-19 12:32:13.038208524 +0000 UTC m=+3669.907464421, end=2159-10-26 19:00:28.038208524 +0000 UTC)
lnd         | 2023-09-19 12:33:00.002 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
lnd         | 2023-09-19 12:33:00.011 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)

However, getinfo is still stuck.
With postgres being terminated gracefully, I would expect any "hanging" connection on postgres to be terminated, thus un-clogging my getinfo command (returning some error). But that was not the case, the command is still hanging, and if I cancel and ask getinfo again, it still hangs.

So whatever is clogging this seems to be isolated to the lnd process only. Rebooting postgres didn't make any difference besides these log messages. Only rebooting lnd (without rebooting postgres) unclogs it, until it clogs again after like ~10-20 minutes of runtime.

This test probably rules out postgres as the potential point of failure in this issue.

[FeatureSpitter]

Meanwhile I measure the query statistics on postgres while it is clogged and I learned this:

Look at that commit operation going...!

[FeatureSpitter]

The commit is still going strong.

[guggero]

This does look like something's not properly working with Postgres... Why would a commit take that long? Is there a way to find out all queries of that transaction? So basically, what it is committing?

[FeatureSpitter]

It now finished the commit and started a new one, but the other SHOW TRANSACTION ISOLATION LEVEL is still there: