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.

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

Horizon: context deadline exceeded #4446

Closed
orosstefan opened this issue Jul 5, 2022 · 2 comments · Fixed by #4860
Closed

Horizon: context deadline exceeded #4446

orosstefan opened this issue Jul 5, 2022 · 2 comments · Fixed by #4860
Assignees

Comments

@orosstefan
Copy link

What version are you using?

horizon: 2.18.0
stellar-core: 19.1.0
go: 1.17.9

What did you do?

I ran stellar-horizon with captive-core following the configuration from the official documentation. After catching up with the history and applying all the checkpoints, when ingesting live data horizon tries to get info from http://localhost:11626/info and it times out.

What did you expect to see?

I expect live ingestion to work properly.

What did you see instead?

Because of the timeout the live ingestion lags behind

INFO[2022-07-05T15:17:16.644+01:00] Ledger: Got consensus: [seq=41625941, prev=a0d052, txs=430, ops=953, sv: [ SIGNED@lobstr_2_europe txH: f81623, ct: 1657030634, upgrades: [ ] ]]  pid=306990 service=ingest subservice=stellar-core
INFO[2022-07-05T15:17:16.644+01:00] Tx: applying ledger 41625941 (txs:430, ops:953, base_fee:100)  pid=306990 service=ingest subservice=stellar-core
INFO[2022-07-05T15:17:16.664+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:18.664+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:20.664+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
ERRO[2022-07-05T15:17:21.645+01:00] failed to load the stellar-core info          err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=306990 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1581]"
WARN[2022-07-05T15:17:21.645+01:00] could not load stellar-core info: http request errored: Get "http://localhost:11626/info": context deadline exceeded  pid=306990
WARN[2022-07-05T15:17:21.646+01:00] error ticking app: context deadline exceeded  pid=306990
INFO[2022-07-05T15:17:22.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:23.340+01:00] Processing ledger entry changes               pid=306990 processed_entries=600000 progress="2.20%" sequence=41625919 service=ingest source=historyArchive
INFO[2022-07-05T15:17:24.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:25.174+01:00] Processing ledger entry changes               pid=306990 processed_entries=650000 progress="2.42%" sequence=41625919 service=ingest source=historyArchive
ERRO[2022-07-05T15:17:26.646+01:00] failed to load the stellar-core info          err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=306990 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1581]"
WARN[2022-07-05T15:17:26.646+01:00] could not load stellar-core info: http request errored: Get "http://localhost:11626/info": context deadline exceeded  pid=306990
WARN[2022-07-05T15:17:26.647+01:00] error ticking app: context deadline exceeded  pid=306990
INFO[2022-07-05T15:17:26.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:28.664+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:30.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:31.543+01:00] Processing ledger entry changes               pid=306990 processed_entries=700000 progress="2.65%" sequence=41625919 service=ingest source=historyArchive
WARN[2022-07-05T15:17:31.647+01:00] could not load stellar-core info: http request errored: Get "http://localhost:11626/info": context deadline exceeded  pid=306990
ERRO[2022-07-05T15:17:31.647+01:00] failed to load the stellar-core info          err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=306990 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1581]"
WARN[2022-07-05T15:17:31.648+01:00] error ticking app: context deadline exceeded  pid=306990
INFO[2022-07-05T15:17:32.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
INFO[2022-07-05T15:17:33.367+01:00] Processing ledger entry changes               pid=306990 processed_entries=750000 progress="2.87%" sequence=41625919 service=ingest source=historyArchive
INFO[2022-07-05T15:17:34.663+01:00] waiting for ingestion system catchup          pid=306990 service=ingest status="{false false 0 41457386 41457386}"
WARN[2022-07-05T15:17:36.648+01:00] could not load stellar-core info: http request errored: Get "http://localhost:11626/info": context deadline exceeded  pid=306990
ERRO[2022-07-05T15:17:36.648+01:00] failed to load the stellar-core info          err="http request errored: Get \"http://localhost:11626/info\": context deadline exceeded" pid=306990 stack="[main.go:43 client.go:67 app.go:230 app.go:442 asm_amd64.s:1581]"
@orosstefan orosstefan added the bug label Jul 5, 2022
@bartekn bartekn moved this to Backlog in Platform Scrum Nov 29, 2022
@bartekn bartekn moved this from Backlog to Next Sprint Proposal in Platform Scrum Nov 29, 2022
@bartekn bartekn moved this from Next Sprint Proposal to Current Sprint in Platform Scrum Dec 8, 2022
@jcx120 jcx120 added the horizon label Dec 8, 2022
@bartekn
Copy link
Contributor

bartekn commented Dec 8, 2022

INFO[2022-07-05T15:17:31.543+01:00] Processing ledger entry changes               pid=306990 processed_entries=700000 progress="2.65%" sequence=41625919 service=ingest source=historyArchive

indicates that error appear while state is being rebuilt. While this happens the buffer for storing ledgers sent from Captive-Core becomes full as it's only storing 20 ledgers at max. We should check if the current state of ingestion state machine is buildState and in such case suppress could not load stellar-core info: http request errored errors.

@mollykarcher mollykarcher moved this from Current Sprint to Next Sprint Proposal in Platform Scrum Jan 5, 2023
@mollykarcher mollykarcher moved this from Next Sprint Proposal to Backlog in Platform Scrum Jan 5, 2023
@jun0tpyrc
Copy link

jun0tpyrc commented Jan 19, 2023

seem seeing this one latest v19.6.0 as well , block head not moving
stellar/quickstart:latest@sha256:51a1ba72cd5d162835b6359aea588f385085cf1fdbba7f5cb3d410ae878fba21

so seem need to be patient and wait for

curl http://localhost:11626/info
{
   "info" : {
      "build" : "v19.6.0",
      "ledger" : {
         "age" : 1674105765,
         "baseFee" : 100,
         "baseReserve" : 100000000,
         "closeTime" : 0,
         "hash" : "39c2a3cd4141b2853e70d84601faa44744660334b48f3228e0309342e3f4eb48",
         "maxTxSetSize" : 100,
         "num" : 1,
         "version" : 0
      },
      "network" : "Public Global Stellar Network ; September 2015",
      "peers" : {
         "authenticated_count" : 8,
         "pending_count" : 16
      },
      "protocol_version" : 19,
      "quorum" : {
         "node" : "GBSEF",
         "qset" : {
            "agree" : 20,
            "cost" : 51713768,
            "delayed" : 0,
            "disagree" : 0,
            "fail_at" : 4,
            "hash" : "b68a69",
            "lag_ms" : 602,
            "ledger" : 44550672,
            "missing" : 3,
            "phase" : "EXTERNALIZE"
         },
         "transitive" : {
            "critical" : null,
            "intersection" : true,
            "last_check_ledger" : 44550623,
            "node_count" : 27
         }
      },
      "startedOn" : "2023-01-19T05:18:31Z",
      "state" : "Catching up",
      "status" : [
         "Catching up to ledger 44550655: downloading and verifying buckets: 16/21 (76%)" <=====
      ]
   }
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: Done
Development

Successfully merging a pull request may close this issue.

5 participants