Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Stellar Quickstart not working #567

Open
dirtydozen1234 opened this issue Feb 14, 2024 · 19 comments
Open

Stellar Quickstart not working #567

dirtydozen1234 opened this issue Feb 14, 2024 · 19 comments
Labels
bug

Comments

@dirtydozen1234
Copy link

dirtydozen1234 commented Feb 14, 2024 •
edited

What version are you using?

"horizon_version": "horizon-v2.28.2-(built-from-source)",
"core_version": "v20.1.0",
"ingest_latest_ledger": 0,
"history_latest_ledger": 0,
"history_latest_ledger_closed_at": "0001-01-01T00:00:00Z",
"history_elder_ledger": 0,
"core_latest_ledger": 50367925,
"network_passphrase": "Public Global Stellar Network ; September 2015",
"current_protocol_version": 19,
"supported_protocol_version": 20,
"core_supported_protocol_version": 20

What did you do?

  • Fresh new VM on Hetzner (8 Cores / 16GB RAM)
  • Debian 11
  • Installed Docked
  • Installed stellar/quickstart using:
  • Started docker container: docker run --rm -it -p "5432:5432" -p "8000:8000" -p "6060:6060" -p "6061:6061" -p "11625:11625" -p "11626:11626" -v "/opt/stellar:/opt/stellar" --name stellar stellar/quickstart --pubnet --> Killed it after it created all necessary folders
  • Changed only one flag in /opt/stellar/horizon/etc/horizon.env --> export PER_HOUR_RATE_LIMIT=0
  • Restarted docker container: docker run --rm -d -p "5432:5432" -p "8000:8000" -p "6060:6060" -p "6061:6061" -p "11625:11625" -p "11626:11626" -v "/opt/stellar:/opt/stellar" --name stellar stellar/quickstart --pubnet
  • When inspecting Horizon logs ingestion breaks at one point and start over an over again:

time="2024-02-14T13:10:49.835Z" level=info msg="Processing ledger entry changes" pid=26610 processed_entries=11650000 progress="55.79%" sequence=50367743 service=ingest source=historyArchive time="2024-02-14T13:10:50.926Z" level=info msg="Processing ledger entry changes" pid=26610 processed_entries=11700000 progress="55.87%" sequence=50367743 service=ingest source=historyArchive time="2024-02-14T13:10:51.398Z" level=info msg="Processing ledger entry changes" pid=26610 processed_entries=11750000 progress="55.95%" sequence=50367743 service=ingest source=historyArchive time="2024-02-14T13:10:53.036Z" level=info msg="Processing ledger entry changes" pid=26610 processed_entries=11800000 progress="56.03%" sequence=50367743 service=ingest source=historyArchive time="2024-02-14T13:10:53.568Z" level=info msg="Processing ledger entry changes" pid=26610 processed_entries=11850000 progress="56.11%" sequence=50367743 service=ingest source=historyArchive time="2024-02-14T13:10:57.363Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.552537392 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:44946" method=GET path=/ pid=26610 referer=undefined req=779a6c970550/nEUgsAq4kx-000110 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:10:59.628Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:10:59.759Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:10:59.850Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:00.018Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:05.212Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:05.362Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:05.486Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:05.593Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:10.717Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:10.988Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:11.142Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:11.261Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:16.378Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:16.504Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:16.568Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:16.597Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:21.675Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:21.684Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:21.721Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:21.749Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:23.136Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.726657983 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:44102" method=GET path=/ pid=26610 referer=undefined req=779a6c970550/nEUgsAq4kx-000111 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:11:26.840Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:26.885Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:26.983Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:27.129Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:32.256Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:32.417Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:32.518Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:32.546Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 time="2024-02-14T13:11:34.663Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.082609845 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:34774" method=GET path=/ pid=26610 referer=undefined req=779a6c970550/nEUgsAq4kx-000112 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:11:41.154Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 time="2024-02-14T13:11:41.290Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=26610 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:41.386Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=26610 time="2024-02-14T13:11:41.442Z" level=warning msg="error ticking app: context deadline exceeded" pid=26610 starting horizon... 2024/02/14 13:11:49 DEPRECATED - The usage of the flag --enable-captive-core-ingestion has been deprecated. Horizon now uses Captive-Core ingestion by default and this flag will soon be removed in the future. 2024/02/14 13:11:49 Checking DB migrations... 2024/02/14 13:11:49 Preparing captive core... time="2024-02-14T13:11:49.441Z" level=info msg="Initializing horizon..." pid=29345 time="2024-02-14T13:11:51.611Z" level=info msg="Initializing database..." pid=29345 time="2024-02-14T13:11:51.611Z" level=info msg="Establishing database session for history" pid=29345 time="2024-02-14T13:11:51.619Z" level=info msg="Establishing database session for ingest" pid=29345 time="2024-02-14T13:11:51.672Z" level=info msg="Starting horizon on :8001 (ingest: true)" pid=29345 time="2024-02-14T13:11:51.672Z" level=info msg="Starting internal server on :6060" pid=29345 time="2024-02-14T13:11:51.673Z" level=info msg="Ingestion system initial state" current_state=start pid=29345 service=ingest time="2024-02-14T13:11:51.674Z" level=info msg="Starting to serve requests" pid=29345 time="2024-02-14T13:11:51.674Z" level=info msg="Starting internal server on :6060" pid=29345 time="2024-02-14T13:11:52.456Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000421683 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:49248" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000001 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:11:52.917Z" level=info msg="Ingestion system state machine transition" current_state=start next_state="buildFromCheckpoint(checkpointLedger=50367871, skipChecks=false)" pid=29345 service=ingest time="2024-02-14T13:11:52.917Z" level=info msg="Preparing range" from=50367871 pid=29345 service=ingest time="2024-02-14T13:11:53.310Z" level=info msg="default: Config from /opt/stellar/horizon/captive-core/captive-core/stellar-core.conf" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="default: Generated QUORUM_SET: {" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 5," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"Blockdaemon_Validator_1\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"Blockdaemon_Validator_2\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"Blockdaemon_Validator_3\"" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [ \"sdf_3\", \"sdf_1\", \"sdf_2\" ]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [ \"coinqvest_finland\", \"coinqvest_hong_kong\", \"coinqvest_germany\" ]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [ \"satoshipay_iowa\", \"satoshipay_singapore\", \"satoshipay_frankfurt\" ]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [ \"FT_SCV_1\", \"FT_SCV_3\", \"FT_SCV_2\" ]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 3," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"lobstr_5_australia\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"lobstr_4_asia\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"lobstr_1_europe\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"lobstr_2_europe\"," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"lobstr_3_north_america\"" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="{" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"t\" : 2," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="\"v\" : [ \"hercules\", \"lyra\", \"bootes\" ]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="}" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="default: Assigning calculated value of 2 to FAILURE_SAFETY" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.311Z" level=info msg="default: Starting stellar-core v20.1.0" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.312Z" level=info msg="Database: Connecting to: sqlite3:///opt/stellar/horizon/captive-core/stellar.db" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.313Z" level=info msg="Ledger: Streaming metadata to file descriptor 3" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.314Z" level=info msg="SCP: LocalNode::LocalNode@ME qSet: b4cccf" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.314Z" level=info msg="Database: DB schema is in current version" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.314Z" level=info msg="default: Dropping accounts" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.314Z" level=info msg="default: Dropping trustlines" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.314Z" level=info msg="default: Dropping accountdata" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping claimablebalances" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping liquiditypools" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping contractdata" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping contractcode" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping configsettings" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.315Z" level=info msg="default: Dropping ttl" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Bucket: BucketListDB enabled: pageSizeExponent: 12 indexCutOff: 20MB, persist indexes: true" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: Connection effective settings:" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: TARGET_PEER_CONNECTIONS: 8" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: MAX_ADDITIONAL_PEER_CONNECTIONS: 64" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: MAX_PENDING_CONNECTIONS: 500" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: MAX_OUTBOUND_PENDING_CONNECTIONS: 56" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="default: MAX_INBOUND_PENDING_CONNECTIONS: 444" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'Blockdaemon_Validator_1' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'Blockdaemon_Validator_2' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'Blockdaemon_Validator_3' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'FT_SCV_1' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'FT_SCV_2' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'FT_SCV_3' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'bootes' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'coinqvest_finland' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'coinqvest_germany' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'coinqvest_hong_kong' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'hercules' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lobstr_1_europe' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lobstr_2_europe' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lobstr_3_north_america' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lobstr_4_asia' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lobstr_5_australia' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'lyra' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'satoshipay_frankfurt' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'satoshipay_iowa' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'satoshipay_singapore' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'sdf_1' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'sdf_2' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="History: Archive 'sdf_3' has 'get' command only, will not be written" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=warning msg="History: No writable archives configured, history will not be written." pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Ledger: Last closed ledger (LCL) hash is ac3c9a0799978670cf4fbe7b03a3df7b36b56be109a1256b093eff6ffe7ff9bb" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Ledger: Loaded LCL header from database: [seq=50367764, hash=ac3c9a]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Ledger: Starting up application" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Ledger: Last closed ledger (LCL) hash is ac3c9a0799978670cf4fbe7b03a3df7b36b56be109a1256b093eff6ffe7ff9bb" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:53.317Z" level=info msg="Ledger: Loaded LCL header from database: [seq=50367764, hash=ac3c9a]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.267Z" level=info msg="Bucket: Restarted merge on BucketList level 1" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.268Z" level=info msg="Ledger: Assumed bucket-state for LCL: [seq=50367764, hash=ac3c9a]" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.268Z" level=info msg="Overlay: Binding to endpoint 0.0.0.0:11725" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.268Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.278Z" level=info msg="Bucket: BucketIndex::createIndex() indexing individual keys in bucket buckets/tmp/bucket-3f50def9bce2b0f5/tmp-bucket-595e13435b62b07f.xdr" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.458Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:54.544Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:55.328Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:55.656Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:55.883Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:56.639Z" level=info msg="Overlay: Connected to 51.222.248.104:11625" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:56.803Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:56.834Z" level=info msg="Overlay: Connected to 65.109.98.186:11625" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:56.889Z" level=info msg="Overlay: Connected to 31.135.8.163:11625" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:56.949Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:57.455Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:57.485Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000242396 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:38520" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000002 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:11:57.883Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.392Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.442Z" level=warning msg="could not load stellar-core info: http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=29345 time="2024-02-14T13:11:58.442Z" level=error msg="failed to load the stellar-core info" err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=29345 stack="[main.go:43 client.go:139 app.go:233 app.go:453 asm_amd64.s:1598]" time="2024-02-14T13:11:58.442Z" level=error msg="could not start repeatable read transaction for txsub tick" error="canceling statement due to lack of response within timeout period" pid=29345 time="2024-02-14T13:11:58.442Z" level=warning msg="error ticking app: context deadline exceeded" pid=29345 time="2024-02-14T13:11:58.811Z" level=info msg="History: Downloading history archive state: .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.901Z" level=warning msg="Process: process 29451 exited 22: curl -sf https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json -o buckets/tmp/history-56c36f98ccaee16c/4ef95fe7d4fd4cb8-stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.901Z" level=error msg="History: Could not download file: archive lobstr_1_europe maybe missing file .well-known/stellar-history.json" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.901Z" level=error msg="History: Could not download .well-known/stellar-history.json file: corrupt archive lobstr_1_europe" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:11:58.901Z" level=error msg="History: Failed to obtain archive information: lobstr_1_europe" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:12:02.511Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000206759 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:38530" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000003 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:07.543Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000221426 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:55584" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000004 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:12.571Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.00038935 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:55600" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000005 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:17.610Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000269346 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:50862" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000006 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:22.639Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000365506 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:50870" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000007 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:27.679Z" level=info msg="Finished request" app_name=undefined app_version=undefined bytes=4106 client_name=undefined client_version=undefined duration=0.000234791 host="localhost:8001" ip=127.0.0.1 ip_port="127.0.0.1:48854" method=GET path=/ pid=29345 referer=undefined req=779a6c970550/e2ePctZ0Op-000008 route=/ status=200 streaming=false x_forwarder_for= time="2024-02-14T13:12:29.268Z" level=warning msg="Herder: Lost track of consensus" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:12:29.268Z" level=warning msg="Herder: Out of sync context: {" pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:12:29.268Z" level=info msg="\"queue\" : null," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:12:29.268Z" level=info msg="\"scp\" : null," pid=29345 service=ingest subservice=stellar-core time="2024-02-14T13:12:29.268Z" level=info msg="\"you\" : \"ME\"" pid=29345 service=ingest subservice=stellar-core

What did you expect to see?

What did you see instead?
@lcgogo
Copy link

lcgogo commented Feb 21, 2024 •
edited

root@ip-10-2-1-1:/data/xlm/log# cat stellar-core-stderr---supervisor-5nlwn3nq.log

2024-02-21T03:36:37.274 GB7AO [History INFO] Downloading history archive state: .well-known/stellar-history.json
2024-02-21T03:36:37.581 GB7AO [Process WARNING] process 425 exited 22: curl -sf https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json -o buckets/tmp/history-b223a3b415611b14/97bbcbe1fa8edc2e-stellar-history.json
2024-02-21T03:36:37.582 GB7AO [History ERROR] Could not download file: archive lobstr_1_europe maybe missing file .well-known/stellar-history.json
2024-02-21T03:36:37.582 GB7AO [History ERROR] Could not download .well-known/stellar-history.json file: corrupt archive lobstr_1_europe
2024-02-21T03:36:37.582 GB7AO [History ERROR] Failed to obtain archive information: lobstr_1_europe
2024-02-21T03:42:30.231 GB7AO [default INFO] Performing maintenance
2024-02-21T03:42:30.232 GB7AO [History INFO] Trimming history <= ledger 0 (rmin=4294967295, qmin=1, lmin=0)
2024-02-21T03:48:29.235 GB7AO [default INFO] Performing maintenance
2024-02-21T03:48:29.236 GB7AO [History INFO] Trimming history <= ledger 0 (rmin=4294967295, qmin=1, lmin=0)
root@ip-10-2-1-1:/data/xlm/log# wget  https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json
--2024-02-21 03:54:06--  https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json
Resolving stellar-archive-1-lobstr.s3.amazonaws.com (stellar-archive-1-lobstr.s3.amazonaws.com)... 52.217.173.73, 3.5.10.23, 52.217.232.97, ...
Connecting to stellar-archive-1-lobstr.s3.amazonaws.com (stellar-archive-1-lobstr.s3.amazonaws.com)|52.217.173.73|:443... connected.
HTTP request sent, awaiting response... 403 Forbidden
2024-02-21 03:54:07 ERROR 403: Forbidden.

seems the stellar-history.json download fail with 403 forbidden

root@ip-10-2-1-1:/data/xlm/log# wget  https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json
--2024-02-21 03:54:06--  https://stellar-archive-1-lobstr.s3.amazonaws.com/.well-known/stellar-history.json
Resolving stellar-archive-1-lobstr.s3.amazonaws.com (stellar-archive-1-lobstr.s3.amazonaws.com)... 52.217.173.73, 3.5.10.23, 52.217.232.97, ...
Connecting to stellar-archive-1-lobstr.s3.amazonaws.com (stellar-archive-1-lobstr.s3.amazonaws.com)|52.217.173.73|:443... connected.
HTTP request sent, awaiting response... 403 Forbidden
2024-02-21 03:54:07 ERROR 403: Forbidden.

@leighmcculloch
Copy link
Member

There appears to be several errors in the logs and it isn't completely obvious which are a problem. They all look like connectivity issues, but do they result in the node not being able to recover? They look recoverable.

@dirtydozen1234
Copy link
Author

dirtydozen1234 commented Feb 21, 2024 •
edited

After 1 day it wasn't synced and ingestion started over and over again. Doesn't look like the VM size is an issue (at least in the phase of ingestion). CPU, RAM and disk size all look good.

@leighmcculloch
Copy link
Member

Was this VM you're running able to run the pubnet quickstart prior to the update?

@dirtydozen1234
Copy link
Author

Yes, but this was ~ 1 year ago.

@airstring
Copy link

Did you solve it

@dirtydozen1234
Copy link
Author

Nope. I have tested it with a 16 Core 32 GB Machine - same behavior.

@dirtydozen1234
Copy link
Author

dirtydozen1234 commented Mar 3, 2024 •
edited

So I have tested it now with the newest Quickstart image and only running --enable horizon - still on a 16 Core 32 GB Machine ingestion will not finish. It stops after ~ 80% because the machine is out of memory. @leighmcculloch - what is the minimum requirement to run a public horizon? Why does it need so much memory for ingestion? Are there any flags that will help to ingest without the need of so much RAM? I think after ingestion is done the VM wouldn't need 32GB RAM anymore, correct? Changed the HISTORY_RETENTION_COUNT=100 but this also didn't help.

@leighmcculloch
Copy link
Member

Could you share some details about the type of machine you're running on? Is the host Windows or Mac or Linux? What's the specs of the host, and the limits of the VM?

@2opremio
Copy link
Contributor

2opremio commented Mar 4, 2024 •
edited

@dirtydozen1234 getting the memory of Horizon/Core inside the container (before it runs out of memory) would be very helpful.

Both for the Quickstart version which works and the one that doesn't.

@dirtydozen1234
Copy link
Author

dirtydozen1234 commented Mar 7, 2024 •
edited

@leighmcculloch 16Core vCPU 32GB RAM 360GB SSD; Host is Linux Ubuntu 20.04 (Tested also on Debian 11 - same).
@2opremio Monitoring RAM usage via htop during ingestion I can see that it continuously increases until there is no memory left ~80% and than it errors out and starts from the beginning. After the error the RAM usage drops as well and than it starts again until it fails again at ~80%. - I have no Quickstart version that works anymore - One year ago I was able to run Quickstart on the same VM with the same specs

@leighmcculloch
Copy link
Member

I'm able to run the latest quickstart image inside 32gb of memory with the --enable horizon option, which runs only horizon in isolation. It took my system about an hour to fully catch up with horizon.

If you're running the default services which will mean a core and horizon are running you might need more memory.

@leighmcculloch
Copy link
Member

leighmcculloch commented Mar 7, 2024 •
edited

@tamirms Are any of the performance improvements you're making recently potentially related to fixing how horizon has become what appears is maybe more hungry to run over the last year?

@dirtydozen1234
Copy link
Author

On the horizon channel on Discord people are reporting the same issue. Not sure if they use Quickstart though.

@github-actions GitHub Actions
Copy link

This issue is stale because it has been open for 30 days with no activity. It will be closed in 30 days unless the stale label is removed.

@github-actions github-actions bot added the stale label Apr 13, 2024
@leighmcculloch
Copy link
Member

Hi! Could you try again with latest QuickStart?

@github-actions github-actions bot removed the stale label Apr 14, 2024
@dirtydozen1234
Copy link
Author

dirtydozen1234 commented Apr 22, 2024 •
edited

Hi! Could you try again with latest QuickStart?

Still not working on the same 32GB machine (16Core vCPU 32GB RAM 360GB SSD; Host is Linux Ubuntu 20.04) - reaching ~80% of Processing ledger entry changes than it is out of memory.

Are there any flags that can be changed so it doesn't require more than 32GB of memory? Something like decreasing the number of ledgers it needs to process for the initial setup?

@dirtydozen1234
Copy link
Author

Do you guys still look into this? Anything wrong with how I start Quickstart?

@tamirms
Copy link
Contributor

tamirms commented May 14, 2024

@dirtydozen1234 the most recent release of horizon https://github.com/stellar/go/releases/tag/horizon-v2.30.0 improves memory consumption when ingesting from an empty db. That release occurred 3 weeks ago. You can try with the latest version of quickstart and double check that the horizon_version field in the root response is is 2.30.0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@leighmcculloch @tamirms @2opremio @lcgogo @airstring @dirtydozen1234 and others