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

services/horizon: Data race during expingest shutdown #2046

Closed
bartekn opened this issue Dec 12, 2019 · 1 comment
Closed

services/horizon: Data race during expingest shutdown #2046

bartekn opened this issue Dec 12, 2019 · 1 comment
Labels
horizon
Milestone
Horizon 1.0-alpha

Comments

@bartekn
Copy link
Contributor

bartekn commented Dec 12, 2019

What version are you using?

Horizon 0.24.0 RC

What did you do?

  1. Run Horizon with race detector (-race).
  2. Send SIGTERM signal.

What did you expect to see?

No data races.

What did you see instead?

First occurrence:

INFO[2019-12-11T15:29:52.344+01:00] Reading new ledger                            ledger=27212116 pid=1997 service=expingest
INFO[2019-12-11T15:29:52.345+01:00] Processing ledger                             ledger=27212116 pid=1997 service=expingest type=ledger_pipeline updating_database=true
INFO[2019-12-11T15:29:55.556+01:00] Processed ledger                              ledger=27212116 pid=1997 service=expingest type=ledger_pipeline
INFO[2019-12-11T15:29:55.557+01:00] Finished processing ledger                    duration=3.212663749 ledger=27212116 pid=1997 service=expingest transactions=54
^CINFO[2019-12-11T15:29:56.283+01:00] received signal, gracefully stopping          pid=1997
INFO[2019-12-11T15:29:56.283+01:00] Shutting down ingestion system...             pid=1997 service=expingest
INFO[2019-12-11T15:29:57.267+01:00] finished background ticker                    pid=1997
INFO[2019-12-11T15:29:57.352+01:00] Reading new ledger                            ledger=27212117 pid=1997 service=expingest
INFO[2019-12-11T15:29:57.354+01:00] Processing ledger                             ledger=27212117 pid=1997 service=expingest type=ledger_pipeline updating_database=true
INFO[2019-12-11T15:29:57.355+01:00] Processing ledger shutdown                    duration=0.002914144 ledger=27212117 pid=1997 service=expingest
INFO[2019-12-11T15:29:57.356+01:00] Session shut down                             pid=1997 service=expingest
INFO[2019-12-11T15:29:57.358+01:00] stopped                                       pid=1997
WARNING: DATA RACE
Read at 0x00c0003996f8 by goroutine 87:
  github.com/stellar/go/support/db.(*Session).ExecRaw()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:362 +0xe1
  github.com/stellar/go/support/db.(*Session).Exec()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:170 +0x100
  github.com/stellar/go/services/horizon/internal/db2/history.(*Q).UpdateAccount()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/db2/history/accounts.go:108 +0x38f
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).processLedgerAccounts()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:490 +0x2e9
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).processLedgerAccounts-fm()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:454 +0x61
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).ProcessLedger()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:244 +0x91a
  github.com/stellar/go/exp/ingest/pipeline.(*ledgerProcessorWrapper).Process()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/ingest/pipeline/wrappers.go:24 +0x280
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode.func1()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:177 +0x10b

Previous write at 0x00c0003996f8 by goroutine 54:
  github.com/stellar/go/support/db.(*Session).Rollback()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:285 +0xc4
  github.com/stellar/go/services/horizon/internal/db2/history.(*Q).Rollback()
      <autogenerated>:1 +0x5d
  github.com/stellar/go/services/horizon/internal/expingest.(*System).Run.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:310 +0x374
  github.com/stellar/go/services/horizon/internal/expingest.alwaysRetry.onError()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:119 +0x86
  github.com/stellar/go/services/horizon/internal/expingest.(*alwaysRetry).onError()
      <autogenerated>:1 +0x66
  github.com/stellar/go/services/horizon/internal/expingest.(*System).Run()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:233 +0x14f
  github.com/stellar/go/services/horizon/internal.(*App).Serve.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/app.go:109 +0x56

Goroutine 87 (running) created at:
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:174 +0x43f
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:201 +0x12c

Goroutine 54 (finished) created at:
  github.com/stellar/go/services/horizon/internal.(*App).Serve()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/app.go:108 +0x75b
  github.com/stellar/go/services/horizon/cmd.glob..func11()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/cmd/root.go:31 +0x34
  github.com/spf13/cobra.(*Command).execute()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:603 +0x7b8
  github.com/spf13/cobra.(*Command).ExecuteC()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:689 +0x36a
  github.com/stellar/go/services/horizon/cmd.Execute()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:648 +0x4e
  main.main()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/main.go:6 +0x2f
==================
Found 1 data race(s)

Second occurrence:

==================
WARNING: DATA RACE
Read at 0x00c00016fa58 by goroutine 36:
  github.com/stellar/go/support/db.(*Session).ExecRaw()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:362 +0xe1
  github.com/stellar/go/support/db.(*Session).Exec()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:170 +0x100
  github.com/stellar/go/services/horizon/internal/db2/history.(*Q).UpdateTrustLine()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/db2/history/trust_lines.go:89 +0x400
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).processLedgerTrustLines()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:765 +0x40b
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).processLedgerTrustLines-fm()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:715 +0x61
  github.com/stellar/go/services/horizon/internal/expingest/processors.(*DatabaseProcessor).ProcessLedger()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/processors/database_processor.go:246 +0x91a
  github.com/stellar/go/exp/ingest/pipeline.(*ledgerProcessorWrapper).Process()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/ingest/pipeline/wrappers.go:24 +0x280
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode.func1()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:177 +0x10b

Previous write at 0x00c00016fa58 by goroutine 54:
  github.com/stellar/go/support/db.(*Session).Rollback()
      /Users/bartek/gocode/src/github.com/stellar/go/support/db/session.go:285 +0xc4
  github.com/stellar/go/services/horizon/internal/db2/history.(*Q).Rollback()
      <autogenerated>:1 +0x5d
  github.com/stellar/go/services/horizon/internal/expingest.(*System).Run.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:311 +0x3e2
  github.com/stellar/go/services/horizon/internal/expingest.alwaysRetry.onError()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:119 +0x86
  github.com/stellar/go/services/horizon/internal/expingest.(*alwaysRetry).onError()
      <autogenerated>:1 +0x66
  github.com/stellar/go/services/horizon/internal/expingest.(*System).Run()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/expingest/main.go:233 +0x14f
  github.com/stellar/go/services/horizon/internal.(*App).Serve.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/app.go:109 +0x56

Goroutine 36 (running) created at:
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:174 +0x43f
  github.com/stellar/go/exp/support/pipeline.(*Pipeline).processStateNode.func2()
      /Users/bartek/gocode/src/github.com/stellar/go/exp/support/pipeline/pipeline.go:201 +0x12c

INFO[2019-12-11T16:04:40.724+01:00] stopped                                       pid=5074
Goroutine 54 (finished) created at:
  github.com/stellar/go/services/horizon/internal.(*App).Serve()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/internal/app.go:108 +0x75b
  github.com/stellar/go/services/horizon/cmd.glob..func11()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/cmd/root.go:31 +0x34
  github.com/spf13/cobra.(*Command).execute()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:603 +0x7b8
  github.com/spf13/cobra.(*Command).ExecuteC()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:689 +0x36a
  github.com/stellar/go/services/horizon/cmd.Execute()
      /Users/bartek/gocode/pkg/mod/github.com/spf13/[email protected]/command.go:648 +0x4e
  main.main()
      /Users/bartek/gocode/src/github.com/stellar/go/services/horizon/main.go:6 +0x2f
==================
Found 1 data race(s)
@bartekn bartekn added this to the Horizon 0.25.0 milestone Dec 12, 2019
@bartekn bartekn added the P2 label Dec 12, 2019
This was referenced Dec 12, 2019
Closed
Merged
Merged
@bartekn
Copy link
Contributor Author

bartekn commented Dec 17, 2019

Fixed in #2058.

@bartekn bartekn closed this as completed Dec 17, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
horizon
Projects
None yet
Milestone
Horizon 1.0-alpha
Development

No branches or pull requests
1 participant
@bartekn