GenerateKey goes into deadlock state under load

[taj07carter]

I have a simple HTTP server with an endpoint (GET http://localhost:8099/keygen) to generate a key. The handler for this endpoint invokes the GenerateKey func from the emitter-io client.

I have bench-marked this API endpoint, and found that the invocations to GenerateKey results in a deadlock state when I attempt to maintain a set number of concurrent requests for a duration of time. The problem is easily reproducible with 50 concurrent requests over a 2 minute period. Note that the problem is not evident when running a single keygen request at a time.

Here is a sample program to reproduce the deadlock. Ensure to set appropriate values for the SECRET_KEY, BROKER_HOST and BROKER_PORT constants.

Start it with the -race flag: go run -race main.go

package main

import (
	"fmt"
	"io"
	"log"
	"net/http"

	emitter "github.com/emitter-io/go/v2"
	uuid "github.com/satori/go.uuid"
)

const (
	SECRET_KEY  = "<your_secret_key>"
	BROKER_HOST = "172.16.238.16"
	BROKER_PORT = "8080"
)

func main() {
	// Create the client and connect to the broker
	c, err := emitter.Connect(fmt.Sprintf("tcp://%s:%s", BROKER_HOST, BROKER_PORT),
		func(_ *emitter.Client, msg emitter.Message) {
			log.Fatalf("[emitter] -> [B] received: '%s' topic: '%s'\n", msg.Payload(), msg.Topic())
		})
	if err != nil {
		log.Panic(err)
	}

	id := c.ID()
	fmt.Println("[emitter] -> [B] my name is " + id)

	// HTTP server
	keygenHandler := func(w http.ResponseWriter, req *http.Request) {
		channelId := uuid.NewV4()
		var key string

		key, err = c.GenerateKey(SECRET_KEY, fmt.Sprintf("channel/%s/", channelId), "r", 600)
		if err != nil {
			log.Panic(err)
		}

		fmt.Println(key)
		io.WriteString(w, key)

	}

	http.HandleFunc("/keygen", keygenHandler)
	log.Fatal(http.ListenAndServe(":8099", nil))
}

Sample output in console. The data race warning is displayed and the client stopped processing any GenerateKey requests. You have to restart the application for the emitter to process keygen requests again once it got into this state.

[emitter] -> [B] my name is 4V6M6QLQUALAVMBFHYAB4FBUAM
Dth2fColoWPf-ev9oMrALfiR4tHq8IfJ
il0NhYJBE39DjyZEW0E5JE_UkSs1ZpjT
==================
WARNING: DATA RACE
Write at 0x00c000012d10 by goroutine 23:
  main.main.func2()
      /home/fedora/code/go/src/gallagher.com/emitter/main.go:39 +0x1cc
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2012 +0x51
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2387 +0x288
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2807 +0xce
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1895 +0x837

Previous write at 0x00c000012d10 by goroutine 17:
  main.main.func2()
      /home/fedora/code/go/src/gallagher.com/emitter/main.go:39 +0x1cc
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2012 +0x51
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2387 +0x288
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2807 +0xce
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1895 +0x837

Goroutine 23 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2933 +0x5b6
  net/http.(*Server).ListenAndServe()
      /usr/local/go/src/net/http/server.go:2830 +0x102
  net/http.ListenAndServe()
      /usr/local/go/src/net/http/server.go:3086 +0x394
  main.main()
      /home/fedora/code/go/src/gallagher.com/emitter/main.go:50 +0x39f

Goroutine 17 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2933 +0x5b6
  net/http.(*Server).ListenAndServe()
      /usr/local/go/src/net/http/server.go:2830 +0x102
  net/http.ListenAndServe()
      /usr/local/go/src/net/http/server.go:3086 +0x394
  main.main()
      /home/fedora/code/go/src/gallagher.com/emitter/main.go:50 +0x39f
==================
A6hXQ3rYsDnqumkJI6P6d7AK_d1Em9Qi
Ntz_T1oKWqJITuND_XzOedEE6zHE38nE
UzZ2LRhUI1TrabWS3zgbAAU_4EskDihq
3vPlZHTZLfGVnYqHhlxd6NT1yM6VeeYq
KuwMTDGgCNynLaV0WwGCLPxLvrG_-Mrw
L3vPQNZ_C3AkUEQUfEJasW-8_76j3tyw
4FI-mJx0CjwI-zN7Zf30F61VZvYwAyFD
919r9uI313ab3z9KOv7cnHy8FEwY1vSL
UbmcPFKhI2Ud-qK3p35qYxr8UGdQKmmm
iIkN4riDZwCkFh3uuGA0g0LDFgB20shT
kmvTzE-6M0HKiIv1Abp-KDRqQI0THnv7
BQ2uc8FOb7xIi9JHqjmn69X6EQaLFc_O
ZAdYcVfG5z9_6cU75F0XD5m2_hFy0qAp
eEiYIuOet1LoRltOC1BPJ6caE9rAUN8K
aeS3Uy-jWw-LvtBLMVats9EyS9jnj0SV
0cFPKG1W_EaWff5dWCzgT9n_OM-MgiRO
XPwNcVWJEyE-r1q41rtWcMzRIDGL674T
b8k9eXyYYJA6tK6KjZc76lic1Qu_MYfk
k3EuWAQ2aWCx7zxzjwEb9gwSUfWoOzDN
GyxFArsBXfT6yg24rmRnDI1p753qLisu
C7YrBQE4IJ8rgxAJPPRUBl-RJjEESIh8
37zUludZIaCYSzorWLSRSA5QG-Vh0Wex
LhjXcEGiO68vEcm44l8YntyMBGywcgZx
gPqq6uKs8Z4QLiMh7rNLjF7dv-mx5iJ1

[taj07carter]

It seems like this problem was already fixed in a PR: #28

Is it possible to build and tag a new version? I have tested with the source from master and I cannot reproduce the error anymore.