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

Buffered struct channel corrupting string field.....? #47714

Closed
HeCorr opened this issue Aug 16, 2021 · 7 comments
Closed

Buffered struct channel corrupting string field.....? #47714

HeCorr opened this issue Aug 16, 2021 · 7 comments

Comments

@HeCorr
Copy link

HeCorr commented Aug 16, 2021

What version of Go are you using (go version)?

$ go version
go version go1.16.7 windows/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Henrique\AppData\Local\go-build
set GOENV=C:\Users\Henrique\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\Henrique\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\Henrique\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.16.7
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Users\Henrique\Documents\.dev\github.com\HeCorr\tokenizer\go.mod
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\Henrique\AppData\Local\Temp\go-build2151051964=/tmp/go-build -gno-record-gcc-switches

What did you do?

I'm writing a ticketing system with websockets. When the websocket client is connected, everything works as expected:

ws client connected
calling ticket {Window:1 Ticket:{ID:23 Prefix:AAA Code:12}} <- ticket created and sent to the channel
writing ticket {Window:1 Ticket:{ID:23 Prefix:AAA Code:12}} <- ticket received from channel and sent to the client
calling ticket {Window:1 Ticket:{ID:24 Prefix:BB Code:12}}
writing ticket {Window:1 Ticket:{ID:24 Prefix:BB Code:12}}

However, when the client is offline, ticket call requests are stored in the buffered channel to then be read upon reconnection, but it seems that the "AAA" prefixes are partially overwritten by the "BB" prefixes, which makes absolutely no sense:

calling ticket {Window:1 Ticket:{ID:25 Prefix:AAA Code:13}}
calling ticket {Window:1 Ticket:{ID:26 Prefix:BB Code:13}}
ws client connected
writing ticket {Window:1 Ticket:{ID:25 Prefix:BBA Code:13}} <- ??????
writing ticket {Window:1 Ticket:{ID:26 Prefix:BB Code:13}}

Unfortunately, I couldn't reproduce the issue on the Playground and don't know what else to try.

Here's the relevant parts of the code:

type CallRequest struct {
	Window string
	Ticket Ticket
}

type Ticket struct {
	ID     uint64
	Prefix string
	Code   uint8
}

var callChan = make(chan CallRequest, 10)

func callTicket(cr CallRequest) {
	fmt.Printf("calling ticket %+v\n", cr)
	callChan <- cr
}

// init web server, etc

app.Post("/tickets", func(c *fiber.Ctx) error {
        // createTicket() stores the ticket in the database and returns a copy of it with it's id and code set
        tk, err := createTicket(&Ticket{Prefix: c.FormValue("prefix")})
        if err != nil {
	        return err
        }
        callTicket(CallRequest{Ticket: tk, Window: "1"})
        return c.SendString(tk.String())
})

app.Get("/ws/monitor", websocket.New(func(c *websocket.Conn) {
	fmt.Println("ws client connected")

	// logic to break the loop if client disconnects (exitChan)

outer:
	for {
		select {
		case <-exitChan:
			break outer
		case call := <-callChan:
			fmt.Printf("writing ticket %+v\n", call)
			// err = c.WriteMessage(websocket.TextMessage, []byte(call.Ticket.String()+"@"+call.Window))
			// if err != nil {
			// 	fmt.Println(err)
			// }
		}
	}
}))

As of writing this, I ran more tests with the -race flag and it actually (inconsistently) triggered pointing to the fmt.Printf() line above, which still doesn't make sense to me:

==================
WARNING: DATA RACE
Write at 0x00c00017a390 by goroutine 11:
  runtime.slicecopy()
      C:/Program Files/Go/src/runtime/slice.go:247 +0x0
  github.com/valyala/fasthttp.decodeArgAppend()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/args.go:539 +0x659
  github.com/valyala/fasthttp.(*argsScanner).next()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/args.go:530 +0x8b6
  github.com/valyala/fasthttp.(*Args).ParseBytes()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/args.go:98 +0x186
  github.com/valyala/fasthttp.(*Request).parsePostArgs()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/http.go:797 +0x16e
  github.com/valyala/fasthttp.(*Request).PostArgs()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/http.go:784 +0x18e
  github.com/valyala/fasthttp.(*RequestCtx).PostArgs()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:907 +0x17c
  github.com/valyala/fasthttp.(*RequestCtx).FormValue()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:1025 +0x445
  github.com/gofiber/fiber/v2.(*Ctx).FormValue()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/fiber/v2@v2.14.0/ctx.go:466 +0x78
  main.main.func1()
      C:/Users/Henrique/Documents/.dev/github.com/HeCorr/tokenizer/server/src/main.go:35 +0x7d
  github.com/gofiber/fiber/v2.(*App).next()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/fiber/v2@v2.14.0/router.go:127 +0x441
  github.com/gofiber/fiber/v2.(*App).handler()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/fiber/v2@v2.14.0/router.go:155 +0x1e4
  github.com/gofiber/fiber/v2.(*App).handler-fm()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/fiber/v2@v2.14.0/router.go:143 +0x64
  github.com/valyala/fasthttp.(*Server).serveConn()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:2239 +0x1dd6
  github.com/valyala/fasthttp.(*Server).serveConn-fm()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:1996 +0x6a
  github.com/valyala/fasthttp.(*workerPool).workerFunc()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:223 +0x10b
  github.com/valyala/fasthttp.(*workerPool).getCh.func1()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:195 +0x49

Previous read at 0x00c00017a390 by goroutine 34:
  runtime.slicecopy()
      C:/Program Files/Go/src/runtime/slice.go:247 +0x0
  fmt.(*buffer).writeString()
      C:/Program Files/Go/src/fmt/print.go:82 +0x115
  fmt.(*fmt).padString()
      C:/Program Files/Go/src/fmt/format.go:110 +0x73
  fmt.(*fmt).fmtS()
      C:/Program Files/Go/src/fmt/format.go:359 +0x75
  fmt.(*pp).fmtString()
      C:/Program Files/Go/src/fmt/print.go:443 +0x1c5
  fmt.(*pp).printValue()
      C:/Program Files/Go/src/fmt/print.go:757 +0x32bd
  fmt.(*pp).printValue()
      C:/Program Files/Go/src/fmt/print.go:806 +0x291a
  fmt.(*pp).printValue()
      C:/Program Files/Go/src/fmt/print.go:806 +0x291a
  fmt.(*pp).printArg()
      C:/Program Files/Go/src/fmt/print.go:712 +0x284
  fmt.(*pp).doPrintln()
      C:/Program Files/Go/src/fmt/print.go:1169 +0xb4
  fmt.Fprintln()
      C:/Program Files/Go/src/fmt/print.go:264 +0x6f
  fmt.Println()
      C:/Program Files/Go/src/fmt/print.go:274 +0x21c
  main.main.func3()
      C:/Users/Henrique/Documents/.dev/github.com/HeCorr/tokenizer/server/src/main.go:75 +0x13f  <------------- right here
  github.com/gofiber/websocket/v2.New.func2.4()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/websocket/v2@v2.0.7/websocket.go:109 +0xb6
  github.com/fasthttp/websocket.(*FastHTTPUpgrader).Upgrade.func1()
      C:/Users/Henrique/go/pkg/mod/github.com/fasthttp/websocket@v1.4.3/server_fasthttp.go:201 +0x24b
  github.com/valyala/fasthttp.hijackConnHandler()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:2384 +0x8f

Goroutine 11 (running) created at:
  github.com/valyala/fasthttp.(*workerPool).getCh()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:194 +0x1c4
  github.com/valyala/fasthttp.(*workerPool).Serve()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:147 +0x6a6
  github.com/valyala/fasthttp.(*Server).Serve()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:1749 +0x6b5
  github.com/gofiber/fiber/v2.(*App).Listen()
      C:/Users/Henrique/go/pkg/mod/github.com/gofiber/fiber/v2@v2.14.0/app.go:646 +0x13c
  main.main()
      C:/Users/Henrique/Documents/.dev/github.com/HeCorr/tokenizer/server/src/main.go:86 +0x458

Goroutine 34 (finished) created at:
  github.com/valyala/fasthttp.(*Server).serveConn()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:2338 +0x12c4
  github.com/valyala/fasthttp.(*Server).serveConn-fm()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/server.go:1996 +0x6a
  github.com/valyala/fasthttp.(*workerPool).workerFunc()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:223 +0x10b
  github.com/valyala/fasthttp.(*workerPool).getCh.func1()
      C:/Users/Henrique/go/pkg/mod/github.com/valyala/fasthttp@v1.28.0/workerpool.go:195 +0x49
==================

What did you expect to see?

I expected to see the original contents of the struct, as they were when written to the channel:

calling ticket {Window:1 Ticket:{ID:25 Prefix:AAA Code:13}}
calling ticket {Window:1 Ticket:{ID:26 Prefix:BB Code:13}}
ws client connected
writing ticket {Window:1 Ticket:{ID:25 Prefix:AAA Code:13}}
writing ticket {Window:1 Ticket:{ID:26 Prefix:BB Code:13}}
@bradfitz
Copy link
Contributor

If you have data races, you first have to eliminate all your data races.

I'm going to close this for now, but feel free to reopen if you still have problems after all the races are gone.

@HeCorr
Copy link
Author

HeCorr commented Aug 16, 2021

But I have no idea of what's causing the race in this code..

How can receiving from a channel and printing the value be a race condition..?

@ianlancetaylor
Copy link
Member

For questions about using Go, you will get better and faster answers using a forum. Please see https://golang.org/wiki/Questions.

@HeCorr
Copy link
Author

HeCorr commented Aug 17, 2021

Using strings.Copy(c.FormValue("prefix")) (from this repo) solved the issue. It seems that FormValue modifies string references on each request:

... Returned value is only valid within the handler. Do not store any references. Make copies or use the Immutable setting instead.

@ianlancetaylor
Copy link
Member

Strings in Go are normally immutable and do not need to be copied.

The Fiber package must be doing something unsafe.

@HeCorr
Copy link
Author

HeCorr commented Aug 17, 2021

@ianlancetaylor Fiber is focused on high performance, so it kinda makes sense why they would do that.

@davecheney
Copy link
Contributor

As @rsc said “I can make something really fast if it doesn’t have to be correct”

@golang golang locked and limited conversation to collaborators Aug 17, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants