[BUG and possible FIX]: Indexer: txindex.go panics

[kiok46]

Details:

bchd version 0.18.0
macOS version 11.3.1
go version go1.16.3 darwin/amd64

Error:

2021-05-21 16:05:53.655 [INF] GRPC: Unary method /pb.bchrpc/GetTransaction invoked by [::1]:50046
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x58 pc=0x1472216]

goroutine 771 [running]:
github.com/gcash/bchd/database/ffldb.rollbackOnPanic(0xc000b59ae0)
	<my_bchd_clone_path>/bchd/database/ffldb/db.go:1903 +0x7d
panic(0x191db20, 0x2192ca0)
	/usr/local/go/src/runtime/panic.go:965 +0x1b9
github.com/gcash/bchd/blockchain/indexers.dbFetchTxIndexEntry(0x1ca2080, 0xc000b59ae0, 0xc00dc4f900, 0x1, 0x31465b8, 0x2c8ab740)
	<my_bchd_clone_path>/bchd/blockchain/indexers/txindex.go:204 +0x96
github.com/gcash/bchd/blockchain/indexers.(*TxIndex).TxBlockRegion.func1(0x1ca2080, 0xc000b59ae0, 0xc000b59ae0, 0x0)
	<my_bchd_clone_path>/bchd/blockchain/indexers/txindex.go:480 +0x47
github.com/gcash/bchd/database/ffldb.(*db).View(0xc0000e0200, 0xc00d1acf60, 0x0, 0x0)
	<my_bchd_clone_path>/bchd/database/ffldb/db.go:1926 +0x9e
github.com/gcash/bchd/blockchain/indexers.(*TxIndex).TxBlockRegion(0xc0006a2048, 0xc00dc4f900, 0x1a5cdf5, 0x1e, 0x0)
	<my_bchd_clone_path>/bchd/blockchain/indexers/txindex.go:478 +0x90
github.com/gcash/bchd/bchrpc.(*GrpcServer).fetchTransactionFromBlock(0xc0000bea00, 0xc00dc4f900, 0x0, 0x1c84ae0, 0xc00df4c000, 0x0, 0xc0001160c0, 0xc000174000, 0x62)
	<my_bchd_clone_path>/bchd/bchrpc/server.go:2584 +0x3d
github.com/gcash/bchd/bchrpc.(*GrpcServer).GetTransaction(0xc0000bea00, 0x1c969d8, 0xc0074ce2d0, 0xc00734a8c0, 0xc0000bea00, 0xc0074ce1b0, 0x2)
	<my_bchd_clone_path>/bchd/bchrpc/server.go:719 +0x185
github.com/gcash/bchd/bchrpc/pb._Bchrpc_GetTransaction_Handler.func1(0x1c969d8, 0xc0074ce2d0, 0x19a2600, 0xc00734a8c0, 0x2, 0x2, 0x0, 0x203001)
	<my_bchd_clone_path>/bchd/bchrpc/pb/bchrpc.pb.go:8780 +0x8b
main.interceptUnary(0x1c969d8, 0xc0074ce2d0, 0x19a2600, 0xc00734a8c0, 0xc00d9891c0, 0xc00d1acf48, 0xc0021d9ba0, 0x10fa206, 0x19bc140, 0xc0074ce2d0)
	<my_bchd_clone_path>/bchd/grpcserver.go:165 +0x19b
github.com/gcash/bchd/bchrpc/pb._Bchrpc_GetTransaction_Handler(0x1a32820, 0xc0000bea00, 0x1c969d8, 0xc0074ce2d0, 0xc007334e40, 0x1bb4d88, 0x1c969d8, 0xc0074ce2d0, 0xc00dc71f50, 0x22)
	<my_bchd_clone_path>/bchd/bchrpc/pb/bchrpc.pb.go:8782 +0x150
google.golang.org/grpc.(*Server).processUnaryRPC(0xc000628380, 0x1c9fc38, 0xc002b07ef0, 0xc002de8200, 0xc00ca326f0, 0x21a1ca0, 0x0, 0x0, 0x0)
	<my_user_path>/go/pkg/mod/google.golang.org/grpc@v1.34.0/server.go:1210 +0x52b
google.golang.org/grpc.(*Server).handleStream(0xc000628380, 0x1c9fc38, 0xc002b07ef0, 0xc002de8200, 0x0)
	<my_user_path>/go/pkg/mod/google.golang.org/grpc@v1.34.0/server.go:1533 +0xd0c
google.golang.org/grpc.(*Server).serveStreams.func1.2(0xc00ce78c10, 0xc000628380, 0x1c9fc38, 0xc002b07ef0, 0xc002de8200)
	<my_user_path>/go/pkg/mod/google.golang.org/grpc@v1.34.0/server.go:871 +0xab
created by google.golang.org/grpc.(*Server).serveStreams.func1
	<my_user_path>/go/pkg/mod/google.golang.org/grpc@v1.34.0/server.go:869 +0x1fd

Situation:

This occurs on at least 2 calls. GetTransactionRequest and SubscribeTransactionsRequest stream.

After diving into the codebase I got to know that txIndex is nil sometimes and that leads to a panic when getting the serialisedData serializedData := txIndex.Get(txHash[:]) https://github.com/gcash/bchd/blob/master/blockchain/indexers/txindex.go#L191

Solution?

Add a check for it.

txIndex := dbTx.Metadata().Bucket(txIndexKey)
if txIndex == nil {
	return nil, nil
}
serializedData := txIndex.Get(txHash[:])

After adding the check, I am able to stream and fetch the transactions.

Note: I am still not very comfortable with the codebase and doing this fix might break something elsewhere.

[zquestz]

A txindex is required for this functionality. Those methods should just error if a txindex is not present.

[zquestz]

Can you provide an example GetTransaction call that shows this behavior? I make thousands a day from https://explore.cash with no issues... can you also provide the flags you started bchd with?

[kiok46]

The GetTransaction is a regular gRPC call, I feed in the hashHex and usually get the expected response.

I have observed that this panic occurs in the following three situations:

1. Fetching a transaction that my node has not seen yet(This can happen when I restarted the node and it has missed some of the transactions while it was away from the network).
2. Fetching a transaction from an older block(Even previous block). [utxo cache not loaded yet? Not sure.]
3. It might seem like from point 1-2 that the problem is only related to the startup process. (Assuming that loading db and reindexing actually happens and that takes a considerable about of time) I have observed this panic even after 20 min of running of node.

Config file flags.

rpcuser=mFocdsi8q+IsUOkc= // Changed it to post here.
rpcpass=xaGocDES=CK+Drc= // Changed it to post here.
rpclisten=:8334
rpccert=./rpc.crt
rpckey=./rpc.key
grpclisten=[::]:8335
txindex=1
addrindex=1
debuglevel=info

[kiok46]

#473 Seems to have fixed the original issue. @zquestz

[kiok46]

Resyncing and #473 fixed it. I am closing the issue.