search

tidwall / redcon

Redis compatible server framework for Go
MIT License
2.19k stars 158 forks source link

Race condition using redcon v1.6.0 #61

Closed darkweak closed 1 year ago

darkweak commented 1 year ago

Hello, there is a race condition in the redcon library used by olric v0.5.0. I was testing my code using go test -race and this warning appeared.

Sample

    olricInstance = config.New("local")
    db, err := olric.New(olricInstance)
    if err != nil {
        return nil, err
    }

    go func() {
        _ = db.Start()
    }()

Output

WARNING: DATA RACE
Read at 0x00c0000360a8 by goroutine 19:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:651 +0x3e
  github.com/tidwall/redcon.(*conn).Close()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:459 +0x47
  github.com/tidwall/redcon.serve.func1.1()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:338 +0x119
  github.com/tidwall/redcon.serve.func1()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:341 +0x56
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:476 +0x32
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x155
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x784
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x47
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/sylvain/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 +0x86

Previous write at 0x00c0000360a8 by goroutine 37:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:654 +0xbe
  github.com/tidwall/redcon.handle.func2()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:438 +0x237
  github.com/tidwall/redcon.handle()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:442 +0xb8
  github.com/tidwall/redcon.serve.func2()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x47

Goroutine 19 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/sylvain/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:72 +0x12e
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:323 +0x2a4
  command-line-arguments.EmbeddedOlricConnectionFactory.func3()
      /Users/sylvain/go/src/github.com/darkweak/souin/cache/providers/embeddedOlricProvider.go:86 +0x39

Goroutine 37 (running) created at:
  github.com/tidwall/redcon.serve()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x89b
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x155
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x784
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x47
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/sylvain/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 +0x86
tidwall commented 1 year ago

I'm unable to reproduce.

I wrapped your example in this program:

package main

import (
    "github.com/buraksezer/olric"
    "github.com/buraksezer/olric/config"
)

func main() {
    olricInstance := config.New("local")
    db, err := olric.New(olricInstance)
    if err != nil {
        panic(err)
    }

    go func() {
        _ = db.Start()
    }()
}

And I did go run -race main.go.

The program printing and ended successfully.

2022/12/14 11:04:42 [INFO] Olric 0.5.0 on darwin/arm64 go1.19.4 => olric.go:319
buraksezer commented 1 year ago

Hey, @tidwall I have prepared a sample for you. If you run the following code snippet by enabling the race detector, you will see the problem. I would greatly appreciate any help.

package main

import (
    "context"
    "fmt"
    "log"
    "time"

    "github.com/buraksezer/olric"
    "github.com/buraksezer/olric/config"
)

func main() {
    // Sample for Olric v0.5.x

    // Deployment scenario: embedded-member
    // This creates a single-node Olric cluster. It's good enough for experimenting.

    // config.New returns a new config.Config with sane defaults. Available values for env:
    // local, lan, wan
    c := config.New("local")

    // Callback function. It's called when this node is ready to accept connections.
    ctx, cancel := context.WithCancel(context.Background())
    c.Started = func() {
        defer cancel()
        log.Println("[INFO] Olric is ready to accept connections")
    }

    // Create a new Olric instance.
    db, err := olric.New(c)
    if err != nil {
        log.Fatalf("Failed to create Olric instance: %v", err)
    }

    // Start the instance. It will form a single-node cluster.
    go func() {
        // Call Start at background. It's a blocker call.
        err = db.Start()
        if err != nil {
            log.Fatalf("olric.Start returned an error: %v", err)
        }
    }()

    <-ctx.Done()

    // In embedded-member scenario, you can use the EmbeddedClient. It implements
    // the Client interface.
    e := db.NewEmbeddedClient()

    dm, err := e.NewDMap("bucket-of-arbitrary-items")
    if err != nil {
        log.Fatalf("olric.NewDMap returned an error: %v", err)
    }

    ctx, cancel = context.WithCancel(context.Background())

    // Magic starts here!
    fmt.Println("##")
    fmt.Println("Simple Put/Get on a DMap instance:")
    err = dm.Put(ctx, "my-key", "Olric Rocks!")
    if err != nil {
        log.Fatalf("Failed to call Put: %v", err)
    }

    gr, err := dm.Get(ctx, "my-key")
    if err != nil {
        log.Fatalf("Failed to call Get: %v", err)
    }

    // Olric uses the Redis serialization format.
    value, err := gr.String()
    if err != nil {
        log.Fatalf("Failed to read Get response: %v", err)
    }

    fmt.Println("Response for my-key:", value)
    fmt.Println("##")

    // Don't forget the call Shutdown when you want to leave the cluster.
    ctx, cancel = context.WithTimeout(context.Background(), 10*time.Second)
    defer cancel()

    err = db.Shutdown(ctx)
    if err != nil {
        log.Printf("Failed to shutdown Olric: %v", err)
    }
}
2023/01/11 23:45:39 [INFO] Olric 0.5.0 on darwin/arm64 go1.19.4 => olric.go:319
2023/01/11 23:45:39 [INFO] Join completed. Synced with 0 initial nodes => discovery.go:59
2023/01/11 23:45:39 [INFO] Routing table has been pushed by 192.168.1.45:3320 => operations.go:86
2023/01/11 23:45:39 [INFO] The cluster coordinator has been bootstrapped => discovery.go:42
2023/01/11 23:45:39 [INFO] Memberlist bindAddr: 192.168.1.45, bindPort: 3322 => routingtable.go:413
2023/01/11 23:45:39 [INFO] Cluster coordinator: 192.168.1.45:3320 => routingtable.go:414
2023/01/11 23:45:39 [INFO] Node name in the cluster: 192.168.1.45:3320 => olric.go:380
2023/01/11 23:45:39 [INFO] Olric bindAddr: 192.168.1.45, bindPort: 3320 => olric.go:386
2023/01/11 23:45:39 [INFO] Replication count is 1 => olric.go:388
2023/01/11 23:45:39 [INFO] Olric is ready to accept connections
##
Simple Put/Get on a DMap instance:
Response for my-key: Olric Rocks!
##
2023/01/11 23:45:39 [INFO] Broadcasting a leave message => discovery.go:295
==================
WARNING: DATA RACE
Read at 0x00c00056e028 by goroutine 17:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:651 +0x34
  github.com/tidwall/redcon.(*conn).Close()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:459 +0x3c
  github.com/tidwall/redcon.serve.func1.1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:338 +0xcc
  github.com/tidwall/redcon.serve.func1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:341 +0x50
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:476 +0x30
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x74

Previous write at 0x00c00056e028 by goroutine 34:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:654 +0xa0
  github.com/tidwall/redcon.handle.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:438 +0x17c
  github.com/tidwall/redcon.handle()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:442 +0x7c
  github.com/tidwall/redcon.serve.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x40

Goroutine 17 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0xd8
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:323 +0x20c
  main.main.func2()
      /Users/buraksezer/GolandProjects/redcon61/main.go:39 +0x34

Goroutine 34 (running) created at:
  github.com/tidwall/redcon.serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x690
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x74
==================
==================
WARNING: DATA RACE
Read at 0x00c00056e010 by goroutine 17:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:654 +0x4c
  github.com/tidwall/redcon.(*conn).Close()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:459 +0x3c
  github.com/tidwall/redcon.serve.func1.1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:338 +0xcc
  github.com/tidwall/redcon.serve.func1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:341 +0x50
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:476 +0x30
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x74

Previous write at 0x00c00056e010 by goroutine 34:
  github.com/tidwall/redcon.(*Writer).Flush()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:658 +0x15c
  github.com/tidwall/redcon.handle.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:438 +0x17c
  github.com/tidwall/redcon.handle()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:442 +0x7c
  github.com/tidwall/redcon.serve.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x40

Goroutine 17 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0xd8
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:323 +0x20c
  main.main.func2()
      /Users/buraksezer/GolandProjects/redcon61/main.go:39 +0x34

Goroutine 34 (running) created at:
  github.com/tidwall/redcon.serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:378 +0x690
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/redcon@v1.6.0/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/olric@v0.5.0/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x74
==================
2023/01/11 23:45:39 [INFO] 192.168.1.45:3320 is gone => olric.go:448
==================
WARNING: DATA RACE
Write at 0x00c000120470 by main goroutine:
  main.main()
      /Users/buraksezer/GolandProjects/redcon61/main.go:84 +0x92c

Previous write at 0x00c000120470 by goroutine 16:
  main.main.func2()
      /Users/buraksezer/GolandProjects/redcon61/main.go:39 +0x44

Goroutine 16 (finished) created at:
  main.main()
      /Users/buraksezer/GolandProjects/redcon61/main.go:37 +0x2c8
==================
Found 3 data race(s)
tidwall commented 1 year ago

Thanks for detailed example. I pushed a fix moments ago.

Also, in your example code, you have a minor race condition at:

    // Start the instance. It will form a single-node cluster.
    go func() {
        // Call Start at background. It's a blocker call.
        err = db.Start()
        if err != nil {
            log.Fatalf("olric.Start returned an error: %v", err)
        }
    }()

The line err = db.Start() may need to be err := db.Start()

buraksezer commented 1 year ago

Thank you @tidwall, I'll update the documentation.

tidwall commented 1 year ago

My pleasure