Issue: POTENTIAL DEADLOCK with Postgres Node

[StarGeezerPhil]

Receiving an backend exit most days at the same time (~04:30 UTC) with the following error:

(I should note this example is taken from this afternoon after a restart and subsequent exit)

2023-05-15 15:58:57 POTENTIAL DEADLOCK:
2023-05-15 15:58:57 Previous place where the lock was grabbed
2023-05-15 15:58:57 goroutine 1473 lock 0xc1fe542054
2023-05-15 15:58:57 deso/src/core/lib/blockchain.go:1787 lib.(*Blockchain).ProcessBlock ??? <<<<<
2023-05-15 15:58:57 deso/src/core/lib/server.go:1823 lib.(*Server)._handleBlock ???
2023-05-15 15:58:57 deso/src/core/lib/server.go:2142 lib.(*Server)._handlePeerMessages ???
2023-05-15 15:58:57 deso/src/core/lib/server.go:2187 lib.(*Server).messageHandler ???
2023-05-15 15:58:57 
2023-05-15 15:58:57 Have been trying to lock it again for more than 10m0s
2023-05-15 15:58:57 goroutine 2294 lock 0xc1fe542054
2023-05-15 15:58:57 
2023-05-15 15:58:57 Here is what goroutine 1473 doing now
2023-05-15 15:58:57 goroutine 1473 [IO wait]:
2023-05-15 15:58:57 internal/poll.runtime_pollWait(0x7f6e7d06ffd8, 0x72)
2023-05-15 15:58:57     /usr/lib/go/src/runtime/netpoll.go:305 +0x89
2023-05-15 15:58:57 internal/poll.(*pollDesc).wait(0xc0006e0080?, 0xc001660000?, 0x0)
2023-05-15 15:58:57     /usr/lib/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
2023-05-15 15:58:57 internal/poll.(*pollDesc).waitRead(...)
2023-05-15 15:58:57     /usr/lib/go/src/internal/poll/fd_poll_runtime.go:89
2023-05-15 15:58:57 internal/poll.(*FD).Read(0xc0006e0080, {0xc001660000, 0x100000, 0x100000})
2023-05-15 15:58:57     /usr/lib/go/src/internal/poll/fd_unix.go:167 +0x25a
2023-05-15 15:58:57 net.(*netFD).Read(0xc0006e0080, {0xc001660000?, 0xc001969950?, 0x41c2b9?})
2023-05-15 15:58:57     /usr/lib/go/src/net/fd_posix.go:55 +0x29
2023-05-15 15:58:57 net.(*conn).Read(0xc0006b2028, {0xc001660000?, 0x7f6ea59bed28?, 0x20?})
2023-05-15 15:58:57     /usr/lib/go/src/net/net.go:183 +0x45
2023-05-15 15:58:57 github.com/go-pg/pg/v10/internal/pool.(*BufReader).read(...)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/internal/pool/reader_buf.go:428
2023-05-15 15:58:57 github.com/go-pg/pg/v10/internal/pool.(*BufReader).fill(0xc21ab18200)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/internal/pool/reader_buf.go:120 +0x13c
2023-05-15 15:58:57 github.com/go-pg/pg/v10/internal/pool.(*BufReader).ReadByte(0xc21ab18200)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/internal/pool/reader_buf.go:297 +0x46
2023-05-15 15:58:57 github.com/go-pg/pg/v10.readMessageType(0xc000290390)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/messages.go:1381 +0x25
2023-05-15 15:58:57 github.com/go-pg/pg/v10.readSimpleQueryData({0x1a41fc8, 0xc000040290}, 0xc000290390, {0x13a22a0, 0xc1fda4c600})
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/messages.go:904 +0xc5
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).simpleQueryData.func1(0x21cdba0?)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:561 +0x38
2023-05-15 15:58:57 github.com/go-pg/pg/v10/internal/pool.(*Conn).WithReader(0xc0006d00f0, {0x1a41fc8?, 0xc000040290?}, 0xc001969b78?, 0xc001969b48)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/internal/pool/conn.go:90 +0x186
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).simpleQueryData(0xc001296000, {0x1a41fc8, 0xc000040290}, 0x132af80?, {0x13a22a0, 0xc1fda4c600}, 0x6400426473?)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:559 +0xed
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).query.func1({0x1a41fc8?, 0xc000040290?}, 0xc000040290?)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:311 +0x55
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).withConn(0xc001296000, {0x1a41fc8?, 0xc000040290}, 0xc001969d90)
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:168 +0x1fe
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).query(0xc001296000, {0x1a41fc8, 0xc000040290}, {0x13a22a0, 0xc1fda4c600}, {0x132af80, 0xc005fe40c0}, {0xc0032e24e0, 0x1, 0x1})
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:310 +0x44e
2023-05-15 15:58:57 github.com/go-pg/pg/v10.(*baseDB).QueryContext(0xc00053c800?, {0x1a41fc8?, 0xc000040290?}, {0x13a22a0?, 0xc1fda4c600?}, {0x132af80?, 0xc005fe40c0?}, {0xc0032e24e0, 0x1, 0x1})
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/base.go:285 +0x66
2023-05-15 15:58:57 github.com/go-pg/pg/v10/orm.(*Query).query(0xc005852000, {0x1a41fc8, 0xc000040290}, {0x1a48600?, 0xc1fda4c600}, {0x132af80, 0xc005fe40c0})
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/orm/query.go:870 +0x1c9
2023-05-15 15:58:57 github.com/go-pg/pg/v10/orm.(*Query).Select(0xc005852000, {0x0?, 0x20?, 0xc0032e24d0?})
2023-05-15 15:58:57     /root/go/pkg/mod/github.com/go-pg/pg/[email protected]/orm/query.go:839 +0xd8
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*Postgres).GetBlockRewardsForPublicKey(0xc000d7c998, 0xc00297c990, 0x0?, 0x0?)
2023-05-15 15:58:57     /deso/src/core/lib/postgres.go:3287 +0x4f5
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView).GetSpendableDeSoBalanceNanosForPublicKey(0xc21ab34500, {0xc2133332c0, 0x21, 0x21}, 0x38ce9)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:3897 +0x132
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView)._spendBalance(0xc21ab34500, 0xd7, {0xc2133332c0, 0x21, 0x21}, 0x9b52f2?)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:829 +0x67
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView)._connectBasicTransferWithExtraSpend(0xc21ab34500, 0xc0004746c0, 0xc1ff4fa2c0, 0x38cea, 0x0, 0x1)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:1812 +0x102c
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView)._connectBasicTransfer(0x7f6e7c06ffff?, 0x15e13a0b8?, 0xc00?, 0x196a8a0?, 0xc0?)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:1609 +0x1e
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView).HelpConnectCoinTransfer(0xc21ab34500, 0xc0004746c0, 0x700000000000003?, 0x38cea, 0xff?, 0x1)
2023-05-15 15:58:57     /deso/src/core/lib/block_view_balance_entry.go:283 +0x1ab
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView)._connectDAOCoinTransfer(0xc21ab34500, 0xc0004746c0, 0xc00196b190?, 0x38cea, 0x0?)
2023-05-15 15:58:57     /deso/src/core/lib/block_view_dao_coin.go:650 +0xed
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView)._connectTransaction(0xc21ab34500, 0xc0004746c0, 0x200?, 0x0, 0x38cea, 0x0?, 0x0?)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:3119 +0x10c5
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView).ConnectTransaction(0x11cf8a0?, 0xc004fc7000?, 0xc00117ff80?, 0xc00117ff50?, 0xff6cd540?, 0xc1?, 0x0?)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:2966 +0x19
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*UtxoView).ConnectBlock(0xc21ab34500, 0xc2c19631d0, {0xc001288000, 0x2a5, 0xc20b0201e0?}, 0x20?, 0x0, 0x38cea)
2023-05-15 15:58:57     /deso/src/core/lib/block_view.go:3371 +0x246
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*Blockchain).ProcessBlock(0xc1fe542000, 0xc2c19631d0, 0xd0?)
2023-05-15 15:58:57     /deso/src/core/lib/blockchain.go:2119 +0x1d27
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*Server)._handleBlock(0xc1fe5226c0, 0xc219474900, 0xc2c19631d0)
2023-05-15 15:58:57     /deso/src/core/lib/server.go:1823 +0x768
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*Server)._handlePeerMessages(0xc1fe5226c0?, 0xc219474900?)
2023-05-15 15:58:57     /deso/src/core/lib/server.go:2142 +0x1dc
2023-05-15 15:58:57 github.com/deso-protocol/core/lib.(*Server).messageHandler(0xc1fe5226c0)
2023-05-15 15:58:57     /deso/src/core/lib/server.go:2187 +0x1ad
2023-05-15 15:58:57 created by github.com/deso-protocol/core/lib.(*Server).Start
2023-05-15 15:58:57     /deso/src/core/lib/server.go:2375 +0xaf
2023-05-15 15:58:57

It appears that go routines 1473 and 2294 are attempting to grab the same lock - with 1473 holding the lock for more than 10 minutes whilst 2294 is waiting to access it (and presumably after 10 minutes is giving up and exiting).

Seems strange that this seems to happen at the same time each day - at around 4:30am UTC.

@lazynina - not sure if this is only affecting me or if it is a local issue (please advise if you can)

[lazynina]

not sure - currently syncing a postgres node from scratch w/ a commit to address #526 , so will update you if I can reproduce.

[lazynina]

@StarGeezerPhil - I haven't been able to reproduce this issue unfortunately.

[StarGeezerPhil]

Thanks @lazynina, I'll investigate further. This is a new docker container arrangement. Previously archival w/ pg was consuming >38gb ram continually (just syncing), but this time it's down in the 20s and was thinking it was running ok.

Seems to run fine other than these deadlocks, but maybe I've inadvertently limited resources somewhere.. I'll take another look.