studio/flamenco
studio/flamenco
12
30
Fork 38
Code Issues 63 Pull Requests 5 Releases Wiki Activity

Flamenco Manager race condition #98264

New Issue
Closed
opened 2022-05-19 18:22:57 +02:00 by Sybren A. Stüvel · 3 comments
Sybren A. Stüvel commented 2022-05-19 18:22:57 +02:00
Owner
Copy Link

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
Author
Owner
Copy Link

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

Changed status from 'Needs Triage' to: 'Confirmed'
Sybren A. Stüvel commented 2022-05-19 18:22:57 +02:00
Author
Owner
Copy Link

Added subscriber: @dr.sybren

Added subscriber: @dr.sybren
Sybren A. Stüvel commented 2022-07-04 14:32:57 +02:00
Author
Owner
Copy Link

Changed status from 'Confirmed' to: 'Resolved'

Changed status from 'Confirmed' to: 'Resolved'
Sybren A. Stüvel self-assigned this 2022-07-04 14:32:57 +02:00
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels   
Good First Issue
  
Priority
High

  
Priority
Low

  
Priority
Normal

  
Status
Archived

  
Status
Confirmed

  
Status
Needs Info from Developers

  
Status
Needs Information from User

  
Status
Needs Triage

  
Status
Resolved

  
Type
Bug

  
Type
Design

  
Type
Job Type
Custom Flamenco job type

  
Type
Known Issue

  
Type
Patch

  
Type
Report

  
Type
To Do

No Label
Good First Issue
Priority
High
Priority
Low
Priority
Normal
Status
Archived
Status
Confirmed
Status
Needs Info from Developers
Status
Needs Information from User
Status
Needs Triage
Status
Resolved
Type
Bug
Type
Design
Type
Job Type
Type
Known Issue
Type
Patch
Type
Report
Type
To Do
Milestone
Clear milestone
No items
No Milestone
Assignees
Clear assignees
No Assignees
Sybren A. Stüvel
1 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: studio/flamenco#98264
No description provided.
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?