search

setavenger / blindbit-oracle

A GO implementation for a BIP0352 Silent Payments Indexing Server
6 stars 6 forks source link

Errors with initial sync #4

Closed Sjors closed 3 months ago

Sjors commented 3 months ago

I was trying the latest main branch commit, with a fresh data directory.

2024/05/10 14:07:58.881452 sync.go:261: [INFO] Getting next batch of headers from: 840000
2024/05/10 14:07:58.999529 sync.go:13: [INFO] starting sync
2024/05/10 14:07:58.999727 sync.go:20: [INFO] blockchain info: &{Chain:main Blocks:842853 Headers:842853 BestBlockHash:000000000000000000003ba411102ec4330c7bb0956029b3b2387371086e488a}
2024/05/10 14:07:58.999746 sync.go:36: [INFO] Getting next batch of headers from: 709632
2024/05/10 14:07:59.280364 sync.go:110: [INFO] Processing 10000 headers
2024/05/10 14:07:59.281438 /home/sjors/dev/BlindBit-Backend/src/core/rpc.go:75: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281462 /home/sjors/dev/BlindBit-Backend/src/core/routine.go:80: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281469 /home/sjors/dev/BlindBit-Backend/src/core/sync.go:145: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281437 /home/sjors/dev/BlindBit-Backend/src/core/rpc.go:75: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281493 /home/sjors/dev/BlindBit-Backend/src/core/rpc.go:75: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281504 /home/sjors/dev/BlindBit-Backend/src/core/routine.go:80: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281509 /home/sjors/dev/BlindBit-Backend/src/core/sync.go:145: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281489 /home/sjors/dev/BlindBit-Backend/src/core/routine.go:80: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281520 /home/sjors/dev/BlindBit-Backend/src/core/sync.go:145: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
setavenger commented 3 months ago

Could you please add the debug logs? Those should show the actual response from core

Sjors commented 3 months ago

How do I get those? In the log file I see the same:

024/05/10 14:07:58.636399 sync.go:261: [INFO] Getting next batch of headers from: 830000
2024/05/10 14:07:58.881452 sync.go:261: [INFO] Getting next batch of headers from: 840000
2024/05/10 14:07:58.999529 sync.go:13: [INFO] starting sync
2024/05/10 14:07:58.999727 sync.go:20: [INFO] blockchain info: &{Chain:main Blocks:842853 Headers:842853 BestBlockHash:000000000000000000003ba411102ec4330c7bb0956029b3b2387371086e488a}
2024/05/10 14:07:58.999746 sync.go:36: [INFO] Getting next batch of headers from: 709632
2024/05/10 14:07:59.280364 sync.go:110: [INFO] Processing 10000 headers
2024/05/10 14:07:59.281438 /home/sjors/dev/BlindBit-Backend/src/core/rpc.go:75: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281462 /home/sjors/dev/BlindBit-Backend/src/core/routine.go:80: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
2024/05/10 14:07:59.281469 /home/sjors/dev/BlindBit-Backend/src/core/sync.go:145: [ERROR] error unmarshaling response: invalid character 'W' looking for beginning of value
setavenger commented 3 months ago

there should be a log file with the following signature in the same folder as the normal logs /logs/logs-debug-{time_at_start_up}

Sjors commented 3 months ago 
2024/05/10 14:07:58.635862 blockheaderinv.go:41: [DEBUG] Inserted 10000 headers-inv
2024/05/10 14:07:58.877148 blockheaderinv.go:22: [DEBUG] Inserting headers-inv...
2024/05/10 14:07:58.880972 blockheaderinv.go:41: [DEBUG] Inserted 10000 headers-inv
2024/05/10 14:07:58.998082 blockheaderinv.go:22: [DEBUG] Inserting headers-inv...
2024/05/10 14:07:58.999250 blockheaderinv.go:41: [DEBUG] Inserted 2854 headers-inv
2024/05/10 14:07:59.281394 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281406 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281413 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281416 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281424 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281433 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281449 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281452 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281465 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281466 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281470 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281483 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281489 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281477 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281483 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281472 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281496 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281539 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281582 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281585 rpc.go:56: [DEBUG] data: Work queue depth exceeded
2024/05/10 14:07:59.281630 rpc.go:55: [DEBUG] status code: 503 Service Unavailable
2024/05/10 14:07:59.281632 rpc.go:56: [DEBUG] data: Work queue depth exceeded
Sjors commented 3 months ago

Oh interesting, on the Bitcoin Core side I get:

024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
2024-05-10T12:07:59Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting

I forgot to set --rpcthreads= it seems

setavenger commented 3 months ago

Did you set max_parallel_requests in the config (blindbit-oracle)? I just saw that the default is at 24 parallel requests to Bitcoin core. Very likely that this is exceeding the limit. Will adjust those defaults.

Sjors commented 3 months ago

I set it to 30 :-)

It seems fine once I set -rpcthreads to 32.

setavenger commented 3 months ago

Makes sense, I'll add a little context to the config variables. It's easy to miss that the node needs to be adjusted accordingly.

With your settings how long does it take for you to sync up from taproot activation to chaintip? I believe it should be rather fast.

Sjors commented 3 months ago

Trying that now... Not entirely fair because the node is also reconstructing the index, though that only uses 1 thread.

Sjors commented 3 months ago

I get a ton of these:

2024/05/10 15:22:57.475334 /home/sjors/dev/BlindBit-Backend/src/db/dblevel/utxo.go:58: [ERROR] [no entry found]

Should I worry?

setavenger commented 3 months ago

I don't think that you do. I believe that originates from a check where I assert that a utxo does/does not exist. I should probably remove the log there. This error is frequently ignored anyways as it's supposed to not find entries a lot of the times.

Sjors commented 3 months ago

(running it again with 24, to leave more room for Bitcoin Core to handle these requests)

I should probably remove the log there

That would make the log a lot less noisy.

setavenger commented 3 months ago

I can push that change in a couple mins.

(running it again with 24, to leave more room for Bitcoin Core to handle these requests)

If both the node and the indexer are on the same machine it's a balancing act to get the numbers right and efficient.

setavenger commented 3 months ago

@Sjors main is updated

Sjors commented 3 months ago

It took a little over 6 hours, but the machine was pretty distracted.

setavenger commented 3 months ago

Thanks! I think this can/must be optimised. Most people will probably not be able to run this with 24 threads. Ideally this should not take days to sync up.