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.

Sign up for GitHub

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

Jump to bottom

WrapHandleFunc: Data race when running HTTP server in a goroutine #957

Closed
bentcoder opened this issue Aug 31, 2024 · 8 comments
Closed

WrapHandleFunc: Data race when running HTTP server in a goroutine #957

bentcoder opened this issue Aug 31, 2024 · 8 comments
Labels
bug

Comments

@bentcoder
Copy link

bentcoder commented Aug 31, 2024 •
edited
Loading

Hi,

When starting the HTTP server in a goroutine (ListenAndServe()), NewRelic causes data race. If you take it out, it is fine. What is the problem here and a solution please?

Thanks

go version go1.23.0 darwin/amd64

package main

import (
    "context"
    "log"
    "log/slog"
    "net/http"
    "os"
    "os/signal"
    "syscall"
    "time"

    "github.com/newrelic/go-agent/v3/newrelic"
)

const (
    licence = "1234567890qwerty"
)

func main() {
    // NewRelic ----------------------------------------------------------------
    app, err := newrelic.NewApplication(
        newrelic.ConfigAppName("Rest"),
        newrelic.ConfigLicense(licence),
        newrelic.ConfigAppLogForwardingEnabled(true),
    )
    if err != nil {
        log.Fatalln(err)
    }

    // HTTP api ----------------------------------------------------------------
    userCreatePath, userCreateHandle := newrelic.WrapHandleFunc(app, "POST /api/v1/users", func(w http.ResponseWriter, r *http.Request) {
        slog.Info("User created")
    })

    // HTTP router -------------------------------------------------------------
    rtr := http.NewServeMux()
    rtr.HandleFunc(userCreatePath, userCreateHandle)

    // HTTP server -------------------------------------------------------------
    srv := &http.Server{Handler: rtr, Addr: ":1234"}

    go func() {
        slog.Debug("Server started")
        if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
            slog.Error("Server start", "error", err)
        }
    }()

    ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
    defer stop()

    <-ctx.Done()

    ctx, cancel := context.WithTimeout(context.Background(), time.Second*5)
    defer cancel()

    if err := srv.Shutdown(ctx); err != nil {
        slog.Error("Server shutdown", "error", err)
    } else {
        slog.Debug("Server shutdown")
    }
}
$ go run -race cmd/api/main.go 
==================
WARNING: DATA RACE
Read at 0x00c00028c518 by goroutine 47:
  github.com/newrelic/go-agent/v3/newrelic.WrapHandle.func1()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/instrumentation.go:55 +0x10c
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2220 +0x47
  github.com/newrelic/go-agent/v3/newrelic.WrapHandleFunc.func1()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/instrumentation.go:152 +0x5a
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2220 +0x47
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2747 +0x255
  net/http.serverHandler.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3210 +0x2a1
  net/http.(*conn).serve()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2092 +0x12a4
  net/http.(*Server).Serve.gowrap3()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3360 +0x4f

Previous write at 0x00c00028c518 by goroutine 7:
  github.com/newrelic/go-agent/v3/newrelic.(*app).setState()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:508 +0xaa
  github.com/newrelic/go-agent/v3/newrelic.(*app).process()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:322 +0x103c
  github.com/newrelic/go-agent/v3/newrelic.newApp.gowrap1()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:464 +0x33

Goroutine 47 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3360 +0x8ec
  net/http.(*Server).ListenAndServe()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3259 +0xbc
  main.main.func3()
      /Users/myself/dev/golang/mix/rest/cmd/api/main.go:49 +0x46

Goroutine 7 (running) created at:
  github.com/newrelic/go-agent/v3/newrelic.newApp()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:464 +0xc2b
  github.com/newrelic/go-agent/v3/newrelic.NewApplication()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/application.go:259 +0x2fb
  main.main()
      /Users/myself/dev/golang/mix/rest/cmd/api/main.go:22 +0x1aa
==================
==================
WARNING: DATA RACE
Read at 0x00c00028efd8 by goroutine 47:
  github.com/newrelic/go-agent/v3/newrelic.WrapHandle.func1()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/instrumentation.go:55 +0x184
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2220 +0x47
  github.com/newrelic/go-agent/v3/newrelic.WrapHandleFunc.func1()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/instrumentation.go:152 +0x5a
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2220 +0x47
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2747 +0x255
  net/http.serverHandler.ServeHTTP()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3210 +0x2a1
  net/http.(*conn).serve()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:2092 +0x12a4
  net/http.(*Server).Serve.gowrap3()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3360 +0x4f

Previous write at 0x00c00028efd8 by goroutine 8:
  github.com/newrelic/go-agent/v3/newrelic.newAppRun()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/app_run.go:54 +0x2c7
  github.com/newrelic/go-agent/v3/newrelic.(*app).connectRoutine()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:145 +0x5a4
  github.com/newrelic/go-agent/v3/newrelic.newApp.gowrap2()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:465 +0x33

Goroutine 47 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3360 +0x8ec
  net/http.(*Server).ListenAndServe()
      /usr/local/Cellar/go/1.23.0/libexec/src/net/http/server.go:3259 +0xbc
  main.main.func3()
      /Users/myself/dev/golang/mix/rest/cmd/api/main.go:49 +0x46

Goroutine 8 (finished) created at:
  github.com/newrelic/go-agent/v3/newrelic.newApp()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/internal_app.go:465 +0xcaa
  github.com/newrelic/go-agent/v3/newrelic.NewApplication()
      /Users/myself/go/pkg/mod/github.com/newrelic/go-agent/v3@v3.34.0/newrelic/application.go:259 +0x2fb
  main.main()
      /Users/myself/dev/golang/mix/rest/cmd/api/main.go:22 +0x1aa
==================
2024/08/30 22:55:15 INFO User created
@bentcoder bentcoder added the bug label Aug 31, 2024
@bentcoder bentcoder changed the title Data race when running HTTP server in a goroutine WrapHandleFunc: Data race when running HTTP server in a goroutine Aug 31, 2024
@nr-swilloughby
Copy link
Contributor

is this happening inside a container or AWS runtime environment or something, or does it happen if running the code on an ordinary workstation shell?

@nr-swilloughby
Copy link
Contributor

I tried running your code example but did not see the race condition show up so far. Using go version go1.23.0 darwin/arm64. Will continue trying to reproduce the error.

@bentcoder
Copy link
Author

bentcoder commented Aug 31, 2024 •
edited
Loading

It happens in VSCode terminal, native OS terminal and iTerm2. I don't use Docker for this.

I hope you are using -race flag with go run command.

@nr-swilloughby
Copy link
Contributor

Thanks. Yes, I'm using -race. I'll keep looking.

@bentcoder
Copy link
Author

Just realised, it even happens when not using goroutine at all. Bottom part is like this:

	...

	// HTTP server
	srv := &http.Server{Handler: rtr, Addr: ":1234"}

	slog.Debug("Server started")
	if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
		slog.Error("Server start", "error", err)
	} else {
		slog.Debug("Server shutdown")
	}
}

@nr-swilloughby
Copy link
Contributor

I'm still not able to reproduce your error on my end, which may simply be a matter of timing. However, when analyzing the code flow that you're reporting, I believe I see where a race condition might be possible so I'm addressing that to see if that resolves what you're seeing.

@nr-swilloughby
Copy link
Contributor

I have merged a proposed fix to our develop branch which is where our code gets staged shortly before release. Could you try pulling a copy of the agent from that branch and try compiling with that to see if that solves your issue?

@bentcoder
Copy link
Author

Working fine now. Thank you.

REF:

go 1.23.0

require github.com/newrelic/go-agent/v3 v3.29.1-0.20240905201932-d95445cf6c4e

This was referenced Oct 10, 2024
Merged
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bentcoder @nr-swilloughby