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.

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

Race condition using redcon v1.6.0 #61

Closed
darkweak opened this issue Dec 8, 2022 · 5 comments
Closed

Race condition using redcon v1.6.0 #61

darkweak opened this issue Dec 8, 2022 · 5 comments

Comments

@darkweak
Copy link

darkweak commented Dec 8, 2022

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/[email protected]/redcon.go:651 +0x3e
  github.com/tidwall/redcon.(*conn).Close()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:459 +0x47
  github.com/tidwall/redcon.serve.func1.1()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:338 +0x119
  github.com/tidwall/redcon.serve.func1()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/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/[email protected]/redcon.go:311 +0x155
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x784
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x47
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/sylvain/go/pkg/mod/golang.org/x/[email protected]/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/[email protected]/redcon.go:654 +0xbe
  github.com/tidwall/redcon.handle.func2()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:438 +0x237
  github.com/tidwall/redcon.handle()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:442 +0xb8
  github.com/tidwall/redcon.serve.func2()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:378 +0x47

Goroutine 19 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/sylvain/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0x12e
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/[email protected]/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/[email protected]/redcon.go:378 +0x89b
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/sylvain/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:311 +0x155
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x784
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/sylvain/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x47
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/sylvain/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x86
@tidwall
Copy link
Owner

tidwall commented Dec 14, 2022

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
Copy link

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/[email protected]/redcon.go:651 +0x34
  github.com/tidwall/redcon.(*conn).Close()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:459 +0x3c
  github.com/tidwall/redcon.serve.func1.1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:338 +0xcc
  github.com/tidwall/redcon.serve.func1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/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/[email protected]/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/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/[email protected]/redcon.go:654 +0xa0
  github.com/tidwall/redcon.handle.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:438 +0x17c
  github.com/tidwall/redcon.handle()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:442 +0x7c
  github.com/tidwall/redcon.serve.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:378 +0x40

Goroutine 17 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0xd8
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/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/[email protected]/redcon.go:378 +0x690
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/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/[email protected]/redcon.go:654 +0x4c
  github.com/tidwall/redcon.(*conn).Close()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:459 +0x3c
  github.com/tidwall/redcon.serve.func1.1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:338 +0xcc
  github.com/tidwall/redcon.serve.func1()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/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/[email protected]/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/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/[email protected]/redcon.go:658 +0x15c
  github.com/tidwall/redcon.handle.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:438 +0x17c
  github.com/tidwall/redcon.handle()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:442 +0x7c
  github.com/tidwall/redcon.serve.func2()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:378 +0x40

Goroutine 17 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0xd8
  github.com/buraksezer/olric.(*Olric).Start()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/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/[email protected]/redcon.go:378 +0x690
  github.com/tidwall/redcon.(*Server).Serve()
      /Users/buraksezer/go/pkg/mod/github.com/tidwall/[email protected]/redcon.go:311 +0x14c
  github.com/buraksezer/olric/internal/server.(*Server).ListenAndServe()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/internal/server/server.go:189 +0x5a8
  github.com/buraksezer/olric.(*Olric).Start.func1()
      /Users/buraksezer/go/pkg/mod/github.com/buraksezer/[email protected]/olric.go:324 +0x40
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/buraksezer/go/pkg/mod/golang.org/x/[email protected]/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
Copy link
Owner

tidwall commented Jan 12, 2023

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
Copy link

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

@tidwall
Copy link
Owner

tidwall commented Jan 17, 2023

My pleasure

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants