Delay GitHub issue searches

Experience has shown that these searches can return outdated results
if run immediately on status update webhook events. This has caused some
PRs to get stuck in the merging state without being merged, because the
last status update event has already been sent, but the search during
that event did not show that the PR was ready to be merged. Because
there will be no additional events for that PR (unless users manually
use `!check`, for example) the PR will not get merged.

A simpler solution would have been to simply sleep for the specified
amount (2 seconds by default) and then do the search. But that approach
would mean that the GitHub webhook HTTP request and its connection is
unnecessarily kept open for the duration of the sleep + how long it then
takes to finish the search + merge. This is not too much of an issue for
the default 2 second delay, because Go's standard HTTP server handles
concurrency nicely, and even thousands of concurrent requests (even if
they're just sleeping) could be handled without a problem. However, if
it turns out that 2 seconds isn't sufficient, and a longer period has to
be used, then the described problem can start becoming an issue.
Furthermore, the async approach is much nicer towards GitHub webhook
service, which probably has to worry about too many connections that
stay open for too long already.

This approach does make the HTTP responses and tests a bit less
valuable, because neither can capture the final success/failure any
longer. Tests can still check that the async code sends all the right
requests to GitHub etc, but without parsing the logs or mocking the
delay mechanism, there's no way for the tests to verify the result.

Author: deiwin

config.go

@@ -2,6 +2,7 @@ package main
 
 import (
 	"strconv"
+	"time"
 
 	"github.com/deiwin/gonfigure"
 )
@@ -10,22 +11,32 @@ var (
 	portProperty        = gonfigure.NewEnvProperty("PORT", "80")
 	accessTokenProperty = gonfigure.NewRequiredEnvProperty("GITHUB_ACCESS_TOKEN")
 	secretProperty      = gonfigure.NewRequiredEnvProperty("GITHUB_SECRET")
+	// In the format defined in time.ParseDuration. E.g. "300ms", "-1.5h" or "2h45m".
+	githubAPIDelayProperty = gonfigure.NewEnvProperty("GITHUB_API_DELAY", "2s")
 )
 
 type Config struct {
-	Port        int
-	AccessToken string
-	Secret      string
+	Port           int
+	AccessToken    string
+	Secret         string
+	GithubAPIDelay time.Duration
 }
 
 func NewConfig() Config {
 	port, err := strconv.Atoi(portProperty.Value())
 	if err != nil {
 		panic(err)
 	}
+
+	githubAPIDelay, err := time.ParseDuration(githubAPIDelayProperty.Value())
+	if err != nil {
+		panic(err)
+	}
+
 	return Config{
-		Port:        port,
-		AccessToken: accessTokenProperty.Value(),
-		Secret:      secretProperty.Value(),
+		Port:           port,
+		AccessToken:    accessTokenProperty.Value(),
+		Secret:         secretProperty.Value(),
+		GithubAPIDelay: githubAPIDelay,
 	}
 }

github_review_helper_suite_test.go

@@ -12,6 +12,7 @@ import (
 	"net/http/httptest"
 	"strconv"
 	"strings"
+	"sync"
 
 	"github.com/google/go-github/github"
 	grh "github.com/salemove/github-review-helper"
@@ -70,7 +71,8 @@ type WebhookTest func(WebhookTestContext)
 var TestWebhookHandler = func(test WebhookTest) bool {
 	Describe("webhook handler", func() {
 		var (
-			conf grh.Config
+			conf             grh.Config
+			asyncOperationWg *sync.WaitGroup
 
 			requestJSON = NewStringMemoizer(func() string {
 				return ""
@@ -101,7 +103,9 @@ var TestWebhookHandler = func(test WebhookTest) bool {
 			conf = grh.Config{
 				Secret: "a-secret",
 			}
-			*handler = grh.CreateHandler(conf, *gitRepos, *pullRequests, *repositories, *issues, *search)
+			asyncOperationWg = &sync.WaitGroup{}
+			*handler = grh.CreateHandler(conf, *gitRepos, asyncOperationWg, *pullRequests,
+				*repositories, *issues, *search)
 		})
 
 		JustBeforeEach(func() {
@@ -134,6 +138,9 @@ var TestWebhookHandler = func(test WebhookTest) bool {
 		var handle = func() {
 			response := (*handler)(*responseRecorder, *request)
 			response.WriteResponse(*responseRecorder)
+			// The delay is set to 0 for tests. Wait for all of the operations
+			// to finish to simplify test code.
+			asyncOperationWg.Wait()
 		}
 
 		test(WebhookTestContext{

handler.go

@@ -9,11 +9,14 @@ type Handler func(http.ResponseWriter, *http.Request) Response
 
 func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	response := h(w, r)
+	log.Println("Responding to the HTTP request with:")
+	response.logResponse()
 	response.WriteResponse(w)
 }
 
 type Response interface {
 	WriteResponse(http.ResponseWriter)
+	logResponse()
 }
 
 type ErrorResponse struct {
@@ -23,19 +26,33 @@ type ErrorResponse struct {
 }
 
 func (r ErrorResponse) WriteResponse(w http.ResponseWriter) {
+	http.Error(w, r.ErrorMessage, r.Code)
+}
+
+func (r ErrorResponse) logResponse() {
 	if r.Error != nil {
-		log.Printf("%s: %v\n", r.ErrorMessage, r.Error)
+		log.Printf("Error: %s: %v\n", r.ErrorMessage, r.Error)
 	} else {
-		log.Println(r.ErrorMessage)
+		log.Printf("Error: %s\n", r.ErrorMessage)
 	}
-	http.Error(w, r.ErrorMessage, r.Code)
 }
 
 type SuccessResponse struct {
 	Message string
 }
 
 func (r SuccessResponse) WriteResponse(w http.ResponseWriter) {
-	log.Printf("Responding with a success message: %s\n", r.Message)
 	w.Write([]byte(r.Message))
 }
+
+func (r SuccessResponse) logResponse() {
+	log.Printf("Success: %s\n", r.Message)
+}
+
+// handleAsyncResponse provides consistent error/success logging for operations
+// that are left to continue working after the original HTTP request that
+// initiated the operation has been handled and closed.
+func handleAsyncResponse(response Response) {
+	log.Println("Finishing an asynchronous operation with:")
+	response.logResponse()
+}

main.go

@@ -5,6 +5,7 @@ import (
 	"io/ioutil"
 	"net/http"
 	"os"
+	"sync"
 	"time"
 
 	"gopkg.in/tylerb/graceful.v1"
@@ -30,22 +31,25 @@ func main() {
 	defer os.RemoveAll(reposDir)
 
 	gitRepos := git.NewRepos(reposDir)
+	var asyncOperationWg sync.WaitGroup
 
 	mux := http.NewServeMux()
 	mux.Handle("/", CreateHandler(
 		conf,
 		gitRepos,
+		&asyncOperationWg,
 		githubClient.PullRequests,
 		githubClient.Repositories,
 		githubClient.Issues,
 		githubClient.Search,
 	))
 
 	graceful.Run(fmt.Sprintf(":%d", conf.Port), 10*time.Second, mux)
+	asyncOperationWg.Wait()
 }
 
-func CreateHandler(conf Config, gitRepos git.Repos, pullRequests PullRequests, repositories Repositories,
-	issues Issues, search Search) Handler {
+func CreateHandler(conf Config, gitRepos git.Repos, asyncOperationWg *sync.WaitGroup, pullRequests PullRequests,
+	repositories Repositories, issues Issues, search Search) Handler {
 	return func(w http.ResponseWriter, r *http.Request) Response {
 		body, err := ioutil.ReadAll(r.Body)
 		if err != nil {
@@ -61,7 +65,7 @@ func CreateHandler(conf Config, gitRepos git.Repos, pullRequests PullRequests, r
 		case "pull_request":
 			return handlePullRequestEvent(body, pullRequests, repositories)
 		case "status":
-			return handleStatusEvent(body, gitRepos, search, issues, pullRequests)
+			return handleStatusEvent(body, conf, asyncOperationWg, gitRepos, search, issues, pullRequests)
 		}
 		return SuccessResponse{"Not an event I understand. Ignoring."}
 	}
@@ -108,13 +112,19 @@ func handlePullRequestEvent(body []byte, pullRequests PullRequests, repositories
 	return checkForFixupCommitsOnPREvent(pullRequestEvent, pullRequests, repositories)
 }
 
-func handleStatusEvent(body []byte, gitRepos git.Repos, search Search, issues Issues,
-	pullRequests PullRequests) Response {
+func handleStatusEvent(body []byte, conf Config, asyncOperationWg *sync.WaitGroup, gitRepos git.Repos, search Search,
+	issues Issues, pullRequests PullRequests) Response {
 	statusEvent, err := parseStatusEvent(body)
 	if err != nil {
 		return ErrorResponse{err, http.StatusInternalServerError, "Failed to parse the request's body"}
 	} else if newPullRequestsPossiblyReadyForMerging(statusEvent) {
-		return mergePullRequestsReadyForMerging(statusEvent, gitRepos, search, issues, pullRequests)
+		delay(conf.GithubAPIDelay, func() Response {
+			return mergePullRequestsReadyForMerging(statusEvent, gitRepos, search, issues, pullRequests)
+		}, asyncOperationWg)
+		return SuccessResponse{
+			fmt.Sprintf("Status update might have caused a PR to become mergeable. Scheduled an operation "+
+				"which will start in %s to check for mergeable PRs.", conf.GithubAPIDelay.String()),
+		}
 	}
 	return SuccessResponse{"Status update does not affect any PRs mergeability. Ignoring."}
 }
@@ -179,3 +189,12 @@ func checkUserAuthorization(issueComment IssueComment, issues Issues, repositori
 	}
 	return nil, nil
 }
+
+func delay(duration time.Duration, operation func() Response, asyncOperationWg *sync.WaitGroup) {
+	asyncOperationWg.Add(1)
+	time.AfterFunc(duration, func() {
+		defer asyncOperationWg.Done()
+		response := operation()
+		handleAsyncResponse(response)
+	})
+}

merge_command_state_update_test.go

@@ -103,9 +103,11 @@ var _ = TestWebhookHandler(func(context WebhookTestContext) {
 						mockSearchQuery(1).Return(emptyResult, emptyResponse, errors.New("arbitrary error"))
 					})
 
-					It("fails with a gateway error", func() {
+					// async errors are logged, but won't affect the outcome of
+					// the HTTP request
+					It("returns 200 OK", func() {
 						handle()
-						Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+						Expect(responseRecorder.Code).To(Equal(http.StatusOK))
 					})
 				})
 
@@ -148,9 +150,11 @@ var _ = TestWebhookHandler(func(context WebhookTestContext) {
 								Return(emptyResult, emptyResponse, errArbitrary)
 						})
 
-						It("fails with a gateway error", func() {
+						// async errors are logged, but won't affect the outcome of
+						// the HTTP request
+						It("returns 200 OK", func() {
 							handle()
-							Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+							Expect(responseRecorder.Code).To(Equal(http.StatusOK))
 						})
 					})
 
@@ -176,7 +180,8 @@ var _ = TestWebhookHandler(func(context WebhookTestContext) {
 								Return(pr, emptyResponse, noError)
 						})
 
-						ItMergesPR(context, pr)
+						isAsync := true
+						ItMergesPR(context, pr, isAsync)
 					})
 				})
 

merge_command_test.go

@@ -218,7 +218,7 @@ func commentMentioning(user string) func(issueComment *github.IssueComment) bool
 	}
 }
 
-var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
+var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest, opts ...bool) {
 	var (
 		handle = context.Handle
 
@@ -230,6 +230,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 		issueAuthor string
 		issueNumber int
 		headRef     string
+
+		// async errors are logged, but won't affect the outcome of the HTTP
+		// request. The tests can only confirm that the right stubs were called
+		// for async operations.
+		isAsync bool
 	)
 	BeforeEach(func() {
 		responseRecorder = *context.ResponseRecorder
@@ -240,6 +245,12 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 		issueAuthor = *pr.User.Login
 		issueNumber = *pr.Number
 		headRef = *pr.Head.Ref
+
+		if len(opts) == 0 {
+			isAsync = false
+		} else {
+			isAsync = opts[0]
+		}
 	})
 
 	Context("with merge failing with an unknown error", func() {
@@ -260,7 +271,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 		It("fails with a gateway error", func() {
 			handle()
-			Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+			if isAsync {
+				Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+			} else {
+				Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+			}
 		})
 	})
 
@@ -306,7 +321,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 					Return(emptyResult, emptyResponse, noError)
 
 				handle()
-				Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+				if isAsync {
+					Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+				} else {
+					Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+				}
 			})
 
 			Context("with author notification failing", func() {
@@ -319,7 +338,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 				It("fails with a gateway error", func() {
 					handle()
-					Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+					if isAsync {
+						Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+					} else {
+						Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+					}
 				})
 			})
 		})
@@ -366,7 +389,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 		It("fails with a gateway error", func() {
 			handle()
-			Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+			if isAsync {
+				Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+			} else {
+				Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+			}
 		})
 	})
 
@@ -397,7 +424,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 			It("fails with a gateway error", func() {
 				handle()
-				Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+				if isAsync {
+					Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+				} else {
+					Expect(responseRecorder.Code).To(Equal(http.StatusBadGateway))
+				}
 			})
 		})
 
@@ -418,7 +449,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 				It("fails with an internal error", func() {
 					handle()
-					Expect(responseRecorder.Code).To(Equal(http.StatusInternalServerError))
+					if isAsync {
+						Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+					} else {
+						Expect(responseRecorder.Code).To(Equal(http.StatusInternalServerError))
+					}
 				})
 			})
 
@@ -439,7 +474,11 @@ var ItMergesPR = func(context WebhookTestContext, pr *github.PullRequest) {
 
 					It("fails with an internal error", func() {
 						handle()
-						Expect(responseRecorder.Code).To(Equal(http.StatusInternalServerError))
+						if isAsync {
+							Expect(responseRecorder.Code).To(Equal(http.StatusOK))
+						} else {
+							Expect(responseRecorder.Code).To(Equal(http.StatusInternalServerError))
+						}
 					})
 				})