influxdata / influxdata/influxdb

Backedn task executor data race

Open
#16,167 0 comments 0 reactions 0 assignees View on GitHub
team/compute
Dominant language
Rust
Stars
31.7k
Forks
3.7k
Avg merge
13h 37m
Merged PRs (30d)
8

Description

Seeing test fail for data race 3 times in 2 days now, feels like something we should remedy. Here is the output for the test failure:

```
=== RUN TestTaskConcurrency
==================
WARNING: DATA RACE
Read at 0x00c0001c8743 by goroutine 123:
testing.(*common).logDepth()
/usr/local/go/src/testing/testing.go:621 +0x94
testing.(*common).Logf()
/usr/local/go/src/testing/testing.go:614 +0x90
testing.(*T).Logf()
:1 +0x75
go.uber.org/zap/zaptest.testingWriter.Write()
/go/pkg/mod/go.uber.org/zap@v1.9.1/zaptest/logger.go:114 +0x11f
go.uber.org/zap/zaptest.(*testingWriter).Write()
:1 +0xa9
go.uber.org/zap/zapcore.(*ioCore).Write()
/go/pkg/mod/go.uber.org/zap@v1.9.1/zapcore/core.go:90 +0x1c4
go.uber.org/zap/zapcore.(*CheckedEntry).Write()
/go/pkg/mod/go.uber.org/zap@v1.9.1/zapcore/entry.go:215 +0x1e7
go.uber.org/zap.(*Logger).Info()
/go/pkg/mod/go.uber.org/zap@v1.9.1/logger.go:187 +0x95
github.com/influxdata/influxdb/logger.NewOperation.func1()
/go/src/github.com/influxdata/influxdb/logger/fields.go:129 +0x345
github.com/influxdata/influxdb/task/backend/executor.(*asyncRunPromise).finish.func1()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor.go:380 +0x32c
sync.(*Once).Do()
/usr/local/go/src/sync/once.go:44 +0xde
github.com/influxdata/influxdb/task/backend/executor.(*asyncRunPromise).finish()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor.go:367 +0x93
github.com/influxdata/influxdb/task/backend/executor.(*asyncRunPromise).doQuery()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor.go:363 +0x8b1

Previous write at 0x00c0001c8743 by goroutine 47:
testing.tRunner.func1()
/usr/local/go/src/testing/testing.go:856 +0x354
testing.tRunner()
/usr/local/go/src/testing/testing.go:869 +0x17f

Goroutine 123 (running) created at:
github.com/influxdata/influxdb/task/backend/executor.newAsyncRunPromise()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor.go:276 +0x6fb
github.com/influxdata/influxdb/task/backend/executor.(*asyncQueryServiceExecutor).Execute()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor.go:231 +0x262
github.com/influxdata/influxdb/task/backend/executor.testExecutorQuerySuccess.func1()
/go/src/github.com/influxdata/influxdb/task/backend/executor/executor_test.go:346 +0x51f
testing.tRunner()
/usr/local/go/src/testing/testing.go:865 +0x163

Goroutine 47 (finished) created at:
testing.(*T).Run()
/usr/local/go/src/testing/testing.go:916 +0x65a
testing.runTests.func1()
/usr/local/go/src/testing/testing.go:1157 +0xa8
testing.tRunner()
/usr/local/go/src/testing/testing.go:865 +0x163
testing.runTests()
/usr/local/go/src/testing/testing.go:1155 +0x523
testing.(*M).Run()
/usr/local/go/src/testing/testing.go:1072 +0x2eb
main.main()
_testmain.go:46 +0x222
==================
--- PASS: TestTaskConcurrency (0.13s)
logger.go:114: 2019-12-09T09:10:42.843Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
=== RUN TestTaskExecutor
=== RUN TestTaskExecutor/QuerySuccess
=== PAUSE TestTaskExecutor/QuerySuccess
=== RUN TestTaskExecutor/QueryFailure
=== PAUSE TestTaskExecutor/QueryFailure
=== RUN TestTaskExecutor/ManualRun
=== PAUSE TestTaskExecutor/ManualRun
=== RUN TestTaskExecutor/ResumeRun
=== PAUSE TestTaskExecutor/ResumeRun
=== RUN TestTaskExecutor/WorkerLimit
=== PAUSE TestTaskExecutor/WorkerLimit
=== RUN TestTaskExecutor/LimitFunc
=== PAUSE TestTaskExecutor/LimitFunc
=== RUN TestTaskExecutor/Metrics
=== PAUSE TestTaskExecutor/Metrics
=== RUN TestTaskExecutor/IteratorFailure
=== PAUSE TestTaskExecutor/IteratorFailure
=== RUN TestTaskExecutor/ErrorHandling
=== PAUSE TestTaskExecutor/ErrorHandling
=== CONT TestTaskExecutor/QuerySuccess
=== CONT TestTaskExecutor/WorkerLimit
=== CONT TestTaskExecutor/ErrorHandling
=== CONT TestTaskExecutor/IteratorFailure
=== CONT TestTaskExecutor/ResumeRun
=== CONT TestTaskExecutor/ManualRun
=== CONT TestTaskExecutor/Metrics
=== CONT TestTaskExecutor/LimitFunc
=== CONT TestTaskExecutor/QueryFailure
ts=2019-12-09T09:10:43.080472Z lvl=debug msg=Ticked log_id=0JbUPgyl000 svc=taskd/scheduler now=1575882643 tasks_affected=0
--- PASS: TestTaskExecutor (0.00s)
--- PASS: TestTaskExecutor/ErrorHandling (0.06s)
logger.go:114: 2019-12-09T09:10:42.981Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.039Z DEBUG Execution failed {"error": "unexpected error from queryd; Err: could not find bucket: could not find bucket", "taskID": "04e67a8e969d3000"}
--- PASS: TestTaskExecutor/QueryFailure (0.07s)
logger.go:114: 2019-12-09T09:10:42.993Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.056Z DEBUG Execution failed {"error": "Error exhausting result iterator; Err: blargyblargblarg: blargyblargblarg", "taskID": "04e67a8e98458000"}
--- PASS: TestTaskExecutor/IteratorFailure (0.08s)
logger.go:114: 2019-12-09T09:10:42.981Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.058Z INFO Error exhausting result iterator {"error": "something went wrong exhausting iterator", "name": "res"}
logger.go:114: 2019-12-09T09:10:43.062Z DEBUG Execution failed {"error": "could not execute task run; Err: something went wrong exhausting iterator: something went wrong exhausting iterator", "taskID": "04e67a8e98a04000"}
--- PASS: TestTaskExecutor/QuerySuccess (0.09s)
logger.go:114: 2019-12-09T09:10:42.977Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.068Z DEBUG Completed successfully {"taskID": "04e67a8e99a4c000"}
--- PASS: TestTaskExecutor/WorkerLimit (0.09s)
logger.go:114: 2019-12-09T09:10:42.981Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.069Z DEBUG Execution failed {"error": "Error exhausting result iterator; Err: blargyblargblarg: blargyblargblarg", "taskID": "04e67a8e99aa5000"}
--- PASS: TestTaskExecutor/ResumeRun (0.08s)
logger.go:114: 2019-12-09T09:10:42.989Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.070Z DEBUG Completed successfully {"taskID": "04e67a8e996ad000"}
--- PASS: TestTaskExecutor/ManualRun (0.10s)
logger.go:114: 2019-12-09T09:10:42.981Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.068Z DEBUG Completed successfully {"taskID": "04e67a8e98d53000"}
--- PASS: TestTaskExecutor/Metrics (0.13s)
logger.go:114: 2019-12-09T09:10:42.988Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:43.078Z DEBUG Completed successfully {"taskID": "04e67a8e9bbfb000"}
--- PASS: TestTaskExecutor/LimitFunc (1.06s)
logger.go:114: 2019-12-09T09:10:42.990Z INFO Failed to make user owner of organization {"error": "could not find authorizer on context when adding user to resource type orgs"}
logger.go:114: 2019-12-09T09:10:44.050Z DEBUG Execution failed {"error": "unexpected error from queryd; Err: forced: forced", "taskID": "04e67a8e99a1b000"}
FAIL
FAIL github.com/influxdata/influxdb/task/backend/executor 15.640s
```

Contributor guide

Open the contributing guide

Research direction

Start with task/backend/executor/executor_test.go, especially TestTaskConcurrency and the TestTaskExecutor cases, then trace the reported calls into task/backend/executor/executor.go around lines 231, 276, 363, and 380. Run the executor tests with the race detector and identify the concurrent access shown in the report. Done means the race no longer appears while the executor tests continue to pass.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
backend, testing-qa
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
42/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.