Unexpected LCL in Stellar-Core DB

[gitmewai]

What version are you using?

stellar-horizon: 2.21.0-298
stellar-core: 19.4.0-1075.39bee1a2b.focal

What did you do?

We are running the docker-compose image from https://github.com/stellar/go/tree/master/services/horizon/docker and after we restart with docker-compose up, we found that the stellar.db cannot be reused and a new one is generated which definitely takes much longer time before the node is fully bootstrapped.

What did you expect to see?

We expect the node can make good use of the stellar.db with consistency.

What did you see instead?

Oct 10 08:20:16 stellar-1 systemd[1]: Started stellar-docker.service.
Oct 10 08:20:17 stellar-1 stellar[1899]: Creating network "docker_default" with the default driver
Oct 10 08:20:17 stellar-1 stellar[1899]: Creating docker_horizon_1 ...
Oct 10 08:20:18 stellar-1 stellar[1899]: Creating docker_horizon_1 ... done
Oct 10 08:20:18 stellar-1 stellar[1899]: Attaching to docker_horizon_1
Oct 10 08:20:18 stellar-1 stellar[1899]: horizon_1  | 2022/10/10 08:20:18 Applying DB migrations...
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | 2022/10/10 08:24:04 successfully applied 3 horizon migrations
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | 2022/10/10 08:24:04 Checking DB migrations...
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | 2022/10/10 08:24:04 Preparing captive core...
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.902Z" level=info msg="Initializing horizon..." pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.903Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.903Z" level=info msg="Initializing database..." pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.903Z" level=info msg="Establishing database session for history" pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.906Z" level=info msg="Establishing database session for ingest" pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.910Z" level=info msg="Starting horizon on :8000 (ingest: true)" pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.910Z" level=info msg="Ingestion system initial state" current_state=start pid=1 service=ingest
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.910Z" level=info msg="Starting to serve requests" pid=1
Oct 10 08:24:04 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:04.929Z" level=info msg="Resuming ingestion system from last processed ledger..." last_ledger=43047229 pid=1 service=ingest
Oct 10 08:24:05 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:05.903Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1
Oct 10 08:24:05 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:05.903Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1594]"
Oct 10 08:24:05 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:05.930Z" level=info msg="Ingestion system state machine transition" current_state=start next_state="resume(latestSuccessfullyProcessedLedger=43047229)" pid=1 service=ingest
Oct 10 08:24:05 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:05.930Z" level=info msg="Preparing range" from=43047230 pid=1 service=ingest
Oct 10 08:24:07 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:07.864Z" level=info msg="Unexpected LCL in Stellar-Core DB: 43047230 (want: 43047229), removing existing storage-dir contents" pid=1 service=ingest subservice=stellar-core
Oct 10 08:24:09 stellar-1 stellar[1899]: horizon_1  | time="2022-10-10T08:24:09.735Z" level=info msg="default: Config from /var/lib/stellar/captive-core/stellar-core.conf" pid=1 service=ingest subservice=stellar-core

Oct 14 09:10:14 stellar-2 systemd[1]: Started stellar-docker.service.
Oct 14 09:10:17 stellar-2 stellar[801]: Creating network "docker_default" with the default driver
Oct 14 09:10:17 stellar-2 stellar[801]: Creating docker_horizon_1 ...
Oct 14 09:10:18 stellar-2 stellar[801]: Creating docker_horizon_1 ... done
Oct 14 09:10:18 stellar-2 stellar[801]: Attaching to docker_horizon_1
Oct 14 09:10:18 stellar-2 stellar[801]: horizon_1  | 2022/10/14 09:10:18 Applying DB migrations...
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | 2022/10/14 09:10:19 Checking DB migrations...
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | 2022/10/14 09:10:19 Preparing captive core...
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.108Z" level=info msg="Initializing horizon..." pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.109Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.109Z" level=info msg="Initializing database..." pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.109Z" level=info msg="Establishing database session for history" pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.111Z" level=info msg="Establishing database session for ingest" pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.116Z" level=info msg="Starting horizon on :8000 (ingest: true)" pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.116Z" level=info msg="Ingestion system initial state" current_state=start pid=1 service=ingest
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.116Z" level=info msg="Starting to serve requests" pid=1
Oct 14 09:10:19 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:19.289Z" level=info msg="Resuming ingestion system from last processed ledger..." last_ledger=43107147 pid=1 service=ingest
Oct 14 09:10:20 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:20.110Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1
Oct 14 09:10:20 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:20.110Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1594]"
Oct 14 09:10:20 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:20.290Z" level=info msg="Ingestion system state machine transition" current_state=start next_state="resume(latestSuccessfullyProcessedLedger=43107147)" pid=1 service=ingest
Oct 14 09:10:20 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:20.290Z" level=info msg="Preparing range" from=43107148 pid=1 service=ingest
Oct 14 09:10:23 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:23.380Z" level=info msg="Unexpected LCL in Stellar-Core DB: 43107148 (want: 43107147), removing existing storage-dir contents" pid=1 service=ingest subservice=stellar-core
Oct 14 09:10:25 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:25.112Z" level=error msg="failed to load ledger capacity usage stats" err="canceling statement due to lack of response within timeout period" pid=1 stack="[main.go:36 main.go:39 proc.go:6321 proc.go:6298 proc.go:6298 proc.go:6298 proc.go:233 asm_amd64.s:1594]"
Oct 14 09:10:25 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:25.112Z" level=warning msg="error ticking app: context deadline exceeded" pid=1
Oct 14 09:10:25 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:25.112Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1
Oct 14 09:10:25 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:25.112Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": dial tcp 127.0.0.1:11626: connect: connection refused" pid=1 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1594]"
Oct 14 09:10:25 stellar-2 stellar[801]: horizon_1  | time="2022-10-14T09:10:25.182Z" level=info msg="default: Config from /var/lib/stellar/captive-core/stellar-core.conf" pid=1 service=ingest subservice=stellar-core