Intermittently seeing "sync: WaitGroup is reused before previous Wait has returned" in transport.go #103
Comments
caldempsey
changed the title
|
Hi @mmacheerpuppy! Thanks for reporting the issue! As a quick reference, this is the code reported to be faulty: Lines 199 to 217 in 54d5222 Indeed that usage of @mmacheerpuppy I imagine your code might be calling It's a bit late here in my time zone, so I'll defer writing a test to expose the problem and a fix later. Thanks again for reporting the issue! |
|
@rhcarvalho Oh thanks, that explains a lot, I have used Flush liberally as a de-facto method to ensure all errors have been sent from the application (I admit I kind of took it as an await statement originally). I suspected something was a bit fishy with the usage of sync.WaitGroup but honestly I'm a little new to it myself (coming from a Scala/Elixir background) so not aware of all the conditions that actually throw a panic. Appreciate your late response and I really appreciate your time, I'm also in EU time. Thank you so much ♥ |
|
Thank you @rhcarvalho for the explanation, I had the same issue, was doing flush per each report. |
|
This test can be used to reproduce the issue: type testWriter testing.T
func (t *testWriter) Write(p []byte) (int, error) {
t.Logf("%s", p)
return len(p), nil
}
func TestHTTPTransportFlush(t *testing.T) {
var counter uint64
ts := httptest.NewTLSServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
t.Logf("[SERVER] received event: #%d", atomic.AddUint64(&counter, 1))
}))
defer ts.Close()
Logger.SetOutput((*testWriter)(t))
tr := NewHTTPTransport()
tr.Configure(ClientOptions{
Dsn: fmt.Sprintf("https://user@%s/42", ts.Listener.Addr()),
HTTPClient: ts.Client(),
})
var wg sync.WaitGroup
for i := 0; i < 2; i++ {
i := i
wg.Add(1)
go func() {
defer wg.Done()
for j := 0; j < 2; j++ {
t.Logf("tr.SendEvent #%d from goroutine #%d", j, i)
tr.SendEvent(NewEvent())
ok := tr.Flush(100 * time.Millisecond)
if !ok {
t.Error("Flush() timed out")
}
}
}()
}
wg.Wait()
}Example run: Without instrumenting Posting it here for transparency and future reference. |
|
Running the test above with |
|
A small fix to prevent the panic "sync: WaitGroup is reused before previous Wait has returned" is to synchronize calls to diff --git a/transport.go b/transport.go
index d0f39d9..90e7ec3 100644
--- a/transport.go
+++ b/transport.go
@@ -102,10 +102,12 @@ type HTTPTransport struct {
client *http.Client
transport *http.Transport
- buffer chan *http.Request
+ buffer chan *http.Request
+ wg sync.WaitGroup // counter of buffered requests
+ flushSemaphore chan struct{} // limit concurrent calls to Flush
+
disabledUntil time.Time
- wg sync.WaitGroup
start sync.Once
// Size of the transport buffer. Defaults to 30.
@@ -130,9 +132,10 @@ func (t *HTTPTransport) Configure(options ClientOptions) {
Logger.Printf("%v\n", err)
return
}
-
t.dsn = dsn
+
t.buffer = make(chan *http.Request, t.BufferSize)
+ t.flushSemaphore = make(chan struct{}, 1)
if options.HTTPTransport != nil {
t.transport = options.HTTPTransport
@@ -202,8 +205,10 @@ func (t *HTTPTransport) Flush(timeout time.Duration) bool {
c := make(chan struct{})
go func() {
+ t.flushSemaphore <- struct{}{}
t.wg.Wait()
close(c)
+ <-t.flushSemaphore
}()
select {However, that doesn't fix the race between This type of race was discussed here: https://groups.google.com/d/msg/golang-nuts/W5fol0e4qt8/_XEPBGMQkNwJ.
|
* test: HTTPTransport The ConcurrentSendAndFlush test reveals a data race in the old HTTPTransport implementation. * fix: HTTPTransport.Flush panic and data race Rewrite HTTPTransport internals to remove a data race and occasional panics. Prior to this, HTTPTransport used a `sync.WaitGroup` to track how many in-flight requests existed, and `Flush` waited until the observed number of in-flight requests reached zero. Unsynchronized access to the WaitGroup lead to panics (reuse before wg.Wait returns) and data races (undefined order of wg.Add and wg.Wait calls). The new implementation changes the `Flush` behavior to wait until the current in-flight requests are processed, inline with other SDKs and the Unified API. Fixes #103.
I've seen the panic
"sync: WaitGroup is reused before the previous Wait has returned"in a routine atgithub.com/getsentry/sentry-go/transport.go:201. Not sure how to debug this or how to explore the conditions. I can't find anything in the documentation that can help me explore the conditions post-panic. The stack trace leads me to...Any advice is appreciated on tools I can use to better break this open when it does occur!
The text was updated successfully, but these errors were encountered: