Flamenco Manager race condition #98264

New Issue

Sybren A. Stüvel · 2022-05-19T18:22:57+02:00

Sybren A. Stüvel commented

2022-05-19 18:22:57 +02:00

A race condition occurs in internal/manager/api_impl/worker_auth.go, function requestWorkerStore(), and can be reproduced as follows:

Build Manager and Worker with the race condition checker enabled. The Worker probably doesn't need this, but this will reproduce my configuration. make flamenco-manager_race flamenco-worker_race
Run ./flamenco-manager_race -debug
Submit a video render job that renders PNGs, for example via ./debug-job-render.sh
Run ./flamenco-worker_race -debug to start the Worker
While the Worker is running a task (I tested with the preview-video task), press Ctrl+C to shut it down.
The Manager should now log a race condition.

==================
WARNING: DATA RACE
Write at 0x00c000179801 by goroutine 38:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/string.go:46 +0xa5
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/base.go:18 +0x14a
  github.com/rs/zerolog.Context.Str()
      C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/context.go:77 +0x73
  git.blender.org/flamenco/internal/manager/api_impl.requestWorkerStore.func1()
      C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:77 +0xd3
  github.com/rs/zerolog.(*Logger).UpdateContext()
      C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/log.go:272 +0x29d
  git.blender.org/flamenco/internal/manager/api_impl.requestWorkerStore()
      C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:75 +0x324
  git.blender.org/flamenco/internal/manager/api_impl.WorkerAuth()
      C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:60 +0x397
  git.blender.org/flamenco/internal/manager/api_impl.authenticator()
      C:/workspace/flamenco/internal/manager/api_impl/openapi_auth.go:50 +0x9d
  git.blender.org/flamenco/internal/manager/api_impl.SwaggerValidator.func1()
      C:/workspace/flamenco/internal/manager/api_impl/openapi_auth.go:26 +0x5c
  github.com/getkin/kin-openapi/openapi3filter.validateSecurityRequirement()
      C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:313 +0x5ef
  github.com/getkin/kin-openapi/openapi3filter.ValidateSecurityRequirements()
      C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:261 +0x113
  github.com/getkin/kin-openapi/openapi3filter.ValidateRequest()
      C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:92 +0x834
  github.com/deepmap/oapi-codegen/pkg/middleware.ValidateRequestFromContext()
      C:/workspace/go/pkg/mod/github.com/deepmap/oapi-codegen@v1.9.0/pkg/middleware/oapi_validate.go:128 +0x804
  github.com/deepmap/oapi-codegen/pkg/middleware.OapiRequestValidatorWithOptions.func1.1()
      C:/workspace/go/pkg/mod/github.com/deepmap/oapi-codegen@v1.9.0/pkg/middleware/oapi_validate.go:82 +0xab
  github.com/labstack/echo/v4/middleware.CORSWithConfig.func1.1()
      C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/middleware/cors.go:118 +0x573
  github.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1()
      C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/middleware/recover.go:98 +0x12d
  github.com/ziflex/lecho/v3.Middleware.func1.1()
      C:/workspace/go/pkg/mod/github.com/ziflex/lecho/v3@v3.1.0/middleware.go:84 +0x8b4
  github.com/labstack/echo/v4.(*Echo).ServeHTTP()
      C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:662 +0x844
  net/http.serverHandler.ServeHTTP()
      c:/go/src/net/http/server.go:2916 +0x896
  net/http.(*conn).serve()
      c:/go/src/net/http/server.go:1966 +0xbaa
  net/http.(*Server).Serve.func3()
      c:/go/src/net/http/server.go:3071 +0x58

Previous read at 0x00c000179800 by goroutine 68:
  [failed to restore the stack]

Goroutine 38 (running) created at:
  net/http.(*Server).Serve()
      c:/go/src/net/http/server.go:3071 +0x80c
  github.com/labstack/echo/v4.(*Echo).Start()
      C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:679 +0x135
  main.runWebService.func1()
      C:/workspace/flamenco/cmd/flamenco-manager/main.go:279 +0xc4

Goroutine 68 (running) created at:
  net/http.(*Server).Serve()
      c:/go/src/net/http/server.go:3071 +0x80c
  github.com/labstack/echo/v4.(*Echo).Start()
      C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:679 +0x135
  main.runWebService.func1()
      C:/workspace/flamenco/cmd/flamenco-manager/main.go:279 +0xc4
==================

This was with 247903444f, Go 1.18.2, on an Intel(R) Core(TM) i7-10700K CPU @ 3.80GHz.

A race condition occurs in `internal/manager/api_impl/worker_auth.go`, function `requestWorkerStore()`, and can be reproduced as follows: - Build Manager and Worker with the race condition checker enabled. The Worker probably doesn't need this, but this will reproduce my configuration. `make flamenco-manager_race flamenco-worker_race` - Run `./flamenco-manager_race -debug` - Submit a video render job that renders PNGs, for example via `./debug-job-render.sh` - Run `./flamenco-worker_race -debug` to start the Worker - While the Worker is running a task (I tested with the `preview-video` task), press Ctrl+C to shut it down. - The Manager should now log a race condition. ``` ================== WARNING: DATA RACE Write at 0x00c000179801 by goroutine 38: github.com/rs/zerolog/internal/json.Encoder.AppendString() C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/string.go:46 +0xa5 github.com/rs/zerolog/internal/json.Encoder.AppendKey() C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/internal/json/base.go:18 +0x14a github.com/rs/zerolog.Context.Str() C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/context.go:77 +0x73 git.blender.org/flamenco/internal/manager/api_impl.requestWorkerStore.func1() C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:77 +0xd3 github.com/rs/zerolog.(*Logger).UpdateContext() C:/workspace/go/pkg/mod/github.com/rs/zerolog@v1.26.1/log.go:272 +0x29d git.blender.org/flamenco/internal/manager/api_impl.requestWorkerStore() C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:75 +0x324 git.blender.org/flamenco/internal/manager/api_impl.WorkerAuth() C:/workspace/flamenco/internal/manager/api_impl/worker_auth.go:60 +0x397 git.blender.org/flamenco/internal/manager/api_impl.authenticator() C:/workspace/flamenco/internal/manager/api_impl/openapi_auth.go:50 +0x9d git.blender.org/flamenco/internal/manager/api_impl.SwaggerValidator.func1() C:/workspace/flamenco/internal/manager/api_impl/openapi_auth.go:26 +0x5c github.com/getkin/kin-openapi/openapi3filter.validateSecurityRequirement() C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:313 +0x5ef github.com/getkin/kin-openapi/openapi3filter.ValidateSecurityRequirements() C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:261 +0x113 github.com/getkin/kin-openapi/openapi3filter.ValidateRequest() C:/workspace/go/pkg/mod/github.com/getkin/kin-openapi@v0.88.0/openapi3filter/validate_request.go:92 +0x834 github.com/deepmap/oapi-codegen/pkg/middleware.ValidateRequestFromContext() C:/workspace/go/pkg/mod/github.com/deepmap/oapi-codegen@v1.9.0/pkg/middleware/oapi_validate.go:128 +0x804 github.com/deepmap/oapi-codegen/pkg/middleware.OapiRequestValidatorWithOptions.func1.1() C:/workspace/go/pkg/mod/github.com/deepmap/oapi-codegen@v1.9.0/pkg/middleware/oapi_validate.go:82 +0xab github.com/labstack/echo/v4/middleware.CORSWithConfig.func1.1() C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/middleware/cors.go:118 +0x573 github.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1() C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/middleware/recover.go:98 +0x12d github.com/ziflex/lecho/v3.Middleware.func1.1() C:/workspace/go/pkg/mod/github.com/ziflex/lecho/v3@v3.1.0/middleware.go:84 +0x8b4 github.com/labstack/echo/v4.(*Echo).ServeHTTP() C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:662 +0x844 net/http.serverHandler.ServeHTTP() c:/go/src/net/http/server.go:2916 +0x896 net/http.(*conn).serve() c:/go/src/net/http/server.go:1966 +0xbaa net/http.(*Server).Serve.func3() c:/go/src/net/http/server.go:3071 +0x58 Previous read at 0x00c000179800 by goroutine 68: [failed to restore the stack] Goroutine 38 (running) created at: net/http.(*Server).Serve() c:/go/src/net/http/server.go:3071 +0x80c github.com/labstack/echo/v4.(*Echo).Start() C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:679 +0x135 main.runWebService.func1() C:/workspace/flamenco/cmd/flamenco-manager/main.go:279 +0xc4 Goroutine 68 (running) created at: net/http.(*Server).Serve() c:/go/src/net/http/server.go:3071 +0x80c github.com/labstack/echo/v4.(*Echo).Start() C:/workspace/go/pkg/mod/github.com/labstack/echo/v4@v4.6.1/echo.go:679 +0x135 main.runWebService.func1() C:/workspace/flamenco/cmd/flamenco-manager/main.go:279 +0xc4 ================== ``` This was with 247903444f, Go 1.18.2, on an Intel(R) Core(TM) i7-10700K CPU @ 3.80GHz.

Sybren A. Stüvel commented

2022-05-19 18:22:57 +02:00

Changed status from 'Needs Triage' to: 'Confirmed'