1. Home
  2. Categories
  3. Coding Help
  4. GitHub webhook timed out

GitHub webhook timed out

  • ben_lubar

    If you want to play along at home:

    time curl -H 'X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae' -H 'User-Agent: GitHub-Hookshot/dummy' -H 'X-GitHub-Event: ping' -d '{}' -i https://buildmaster.local.lubar.me/hooks/github

    The response should be 204 No Content.

    On my local machine, this takes 0.2 seconds, even if I remove the hosts file override for buildmaster.local.lubar.me's IP address.

    From the forum server, this takes 10-20 seconds. My ISP is doing something weird.

    GitHub's timeout for hooks is 10 seconds. I'm thinking the best way to solve this would be making a proxy somewhere that forwards the request asynchronously. Is that a thing that already exists?

    The proxy would be getting at most a handful of requests per day, all with payloads of a few kilobytes at most. Is there somewhere I could set this up for free?

    1
  • PleegWat
    Java Dev

    The time is spent in the TLS handshake, according to curl's verbose flag. Might indeed be your provider throttling things. A TCP dump might help identifying whether your ISP is causing delay or it's on your end, but you'd have to make traces for both the client and the server for the same request.

    $ time curl -v --trace-time -H 'X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae' -H 'User-Agent: GitHub-Hookshot/dummy' -H 'X-GitHub-Event
: ping' -d '{}' -i https://buildmaster.local.lubar.me/hooks/github
20:56:20.239563 * Hostname was NOT found in DNS cache
20:56:20.303482 *   Trying 99.63.169.4...
20:56:21.865039 * Connected to buildmaster.local.lubar.me (99.63.169.4) port 443 (#0)
20:56:21.869830 * successfully set certificate verify locations:
20:56:21.873311 *   CAfile: none
  CApath: /etc/ssl/certs
20:56:21.884984 * SSLv3, TLS handshake, Client hello (1):
20:56:31.587407 * SSLv3, TLS handshake, Server hello (2):
20:56:33.717801 * SSLv3, TLS handshake, CERT (11):
20:56:33.725282 * SSLv3, TLS handshake, Server key exchange (12):
20:56:33.731960 * SSLv3, TLS handshake, Server finished (14):
20:56:33.737407 * SSLv3, TLS handshake, Client key exchange (16):
20:56:33.741748 * SSLv3, TLS change cipher, Client hello (1):
20:56:33.745696 * SSLv3, TLS handshake, Finished (20):
20:56:35.248226 * SSLv3, TLS change cipher, Client hello (1):
20:56:35.250705 * SSLv3, TLS handshake, Finished (20):
20:56:35.252633 * SSL connection using ECDHE-RSA-AES256-GCM-SHA384
20:56:35.254868 * Server certificate:
20:56:35.259671 *        subject: CN=ben.lubar.me
20:56:35.262312 *        start date: 2017-12-19 08:30:28 GMT
20:56:35.264066 *        expire date: 2018-03-19 08:30:28 GMT
20:56:35.266194 *        subjectAltName: buildmaster.local.lubar.me matched
20:56:35.269691 *        issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
20:56:35.272601 *        SSL certificate verify ok.
20:56:35.274683 > POST /hooks/github HTTP/1.1
20:56:35.274683 > Host: buildmaster.local.lubar.me
20:56:35.274683 > Accept: */*
20:56:35.274683 > X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae
20:56:35.274683 > User-Agent: GitHub-Hookshot/dummy
20:56:35.274683 > X-GitHub-Event: ping
20:56:35.274683 > Content-Length: 2
20:56:35.274683 > Content-Type: application/x-www-form-urlencoded
20:56:35.274683 >
20:56:35.299935 * upload completely sent off: 2 out of 2 bytes
20:56:37.128284 < HTTP/1.1 204 No Content
HTTP/1.1 204 No Content
20:56:37.132384 * Server nginx/1.10.3 (Ubuntu) is not blacklisted
20:56:37.136781 < Server: nginx/1.10.3 (Ubuntu)
Server: nginx/1.10.3 (Ubuntu)
20:56:37.151500 < Date: Mon, 12 Feb 2018 19:56:34 GMT
Date: Mon, 12 Feb 2018 19:56:34 GMT
20:56:37.164054 < Connection: keep-alive
Connection: keep-alive
20:56:37.167007 < Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
20:56:37.169226 < Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
20:56:37.175382 < X-Content-Type-Options: nosniff
X-Content-Type-Options: nosniff
20:56:37.179685 < Referrer-Policy: strict-origin-when-cross-origin
Referrer-Policy: strict-origin-when-cross-origin
20:56:37.181916 < X-XSS-Protection: 1; mode=block
X-XSS-Protection: 1; mode=block
20:56:37.187513 < X-Frame-Options: SAMEORIGIN
X-Frame-Options: SAMEORIGIN

20:56:37.191639 <
20:56:37.194717 * Connection #0 to host buildmaster.local.lubar.me left intact

real    0m17.075s
user    0m0.000s
sys     0m0.031s
    1 ben_lubar 1 Reply
  • ben_lubar

    @pleegwat from my Windows PC using LXSS:

    $ time curl -v --trace-time -H 'X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae' -H 'User-Agent: GitHub-Hookshot/dummy' -H 'X-GitHub-Event: ping' -d '{}' -i https://buildmaster.local.lubar.me/hooks/github
14:12:16.299389 * Hostname was NOT found in DNS cache
14:12:16.313535 *   Trying 192.168.1.79...
14:12:16.314775 * Connected to buildmaster.local.lubar.me (192.168.1.79) port 443 (#0)
14:12:16.315736 * successfully set certificate verify locations:
14:12:16.316353 *   CAfile: none
  CApath: /etc/ssl/certs
14:12:16.316964 * SSLv3, TLS handshake, Client hello (1):
14:12:16.342355 * SSLv3, TLS handshake, Server hello (2):
14:12:16.343594 * SSLv3, TLS handshake, CERT (11):
14:12:16.346163 * SSLv3, TLS handshake, Server key exchange (12):
14:12:16.347242 * SSLv3, TLS handshake, Server finished (14):
14:12:16.348465 * SSLv3, TLS handshake, Client key exchange (16):
14:12:16.349054 * SSLv3, TLS change cipher, Client hello (1):
14:12:16.349693 * SSLv3, TLS handshake, Finished (20):
14:12:16.351483 * SSLv3, TLS change cipher, Client hello (1):
14:12:16.352337 * SSLv3, TLS handshake, Finished (20):
14:12:16.353137 * SSL connection using ECDHE-RSA-AES256-GCM-SHA384
14:12:16.354101 * Server certificate:
14:12:16.354623 *        subject: CN=ben.lubar.me
14:12:16.355116 *        start date: 2017-12-19 08:30:28 GMT
14:12:16.355550 *        expire date: 2018-03-19 08:30:28 GMT
14:12:16.356155 *        subjectAltName: buildmaster.local.lubar.me matched
14:12:16.356755 *        issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
14:12:16.357315 *        SSL certificate verify ok.
14:12:16.357987 > POST /hooks/github HTTP/1.1
14:12:16.357987 > Host: buildmaster.local.lubar.me
14:12:16.357987 > Accept: */*
14:12:16.357987 > X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae
14:12:16.357987 > User-Agent: GitHub-Hookshot/dummy
14:12:16.357987 > X-GitHub-Event: ping
14:12:16.357987 > Content-Length: 2
14:12:16.357987 > Content-Type: application/x-www-form-urlencoded
14:12:16.357987 >
14:12:16.363077 * upload completely sent off: 2 out of 2 bytes
14:12:16.363496 < HTTP/1.1 204 No Content
HTTP/1.1 204 No Content
14:12:16.364072 * Server nginx/1.10.3 (Ubuntu) is not blacklisted
14:12:16.364545 < Server: nginx/1.10.3 (Ubuntu)
Server: nginx/1.10.3 (Ubuntu)
14:12:16.364983 < Date: Mon, 12 Feb 2018 20:12:16 GMT
Date: Mon, 12 Feb 2018 20:12:16 GMT
14:12:16.365436 < Connection: keep-alive
Connection: keep-alive
14:12:16.365928 < Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
14:12:16.366435 < Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
14:12:16.366924 < X-Content-Type-Options: nosniff
X-Content-Type-Options: nosniff
14:12:16.367392 < Referrer-Policy: strict-origin-when-cross-origin
Referrer-Policy: strict-origin-when-cross-origin
14:12:16.367820 < X-XSS-Protection: 1; mode=block
X-XSS-Protection: 1; mode=block
14:12:16.369485 < X-Frame-Options: SAMEORIGIN
X-Frame-Options: SAMEORIGIN

14:12:16.369982 <
14:12:16.370393 * Connection #0 to host buildmaster.local.lubar.me left intact

real    0m0.662s
user    0m0.016s
sys     0m0.109s

    And without the hosts override:

    $ time curl -v --trace-time -H 'X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae' -H 'User-Agent: GitHub-Hookshot/dummy' -H 'X-GitHub-Event: ping' -d '{}' -i https://buildmaster.local.lubar.me/hooks/github --resolve 'buildmaster.local.lubar.me:443:99.63.169.4'
14:13:46.738186 * Added buildmaster.local.lubar.me:443:99.63.169.4 to DNS cache
14:13:46.739189 * Hostname was found in DNS cache
14:13:46.739877 *   Trying 99.63.169.4...
14:13:46.742597 * Connected to buildmaster.local.lubar.me (99.63.169.4) port 443 (#0)
14:13:46.743470 * successfully set certificate verify locations:
14:13:46.743942 *   CAfile: none
  CApath: /etc/ssl/certs
14:13:46.744462 * SSLv3, TLS handshake, Client hello (1):
14:13:46.767193 * SSLv3, TLS handshake, Server hello (2):
14:13:46.767943 * SSLv3, TLS handshake, CERT (11):
14:13:46.770058 * SSLv3, TLS handshake, Server key exchange (12):
14:13:46.770841 * SSLv3, TLS handshake, Server finished (14):
14:13:46.771653 * SSLv3, TLS handshake, Client key exchange (16):
14:13:46.772046 * SSLv3, TLS change cipher, Client hello (1):
14:13:46.772494 * SSLv3, TLS handshake, Finished (20):
14:13:46.773850 * SSLv3, TLS change cipher, Client hello (1):
14:13:46.774324 * SSLv3, TLS handshake, Finished (20):
14:13:46.775032 * SSL connection using ECDHE-RSA-AES256-GCM-SHA384
14:13:46.777892 * Server certificate:
14:13:46.779828 *        subject: CN=ben.lubar.me
14:13:46.780660 *        start date: 2017-12-19 08:30:28 GMT
14:13:46.781302 *        expire date: 2018-03-19 08:30:28 GMT
14:13:46.784907 *        subjectAltName: buildmaster.local.lubar.me matched
14:13:46.785724 *        issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
14:13:46.788173 *        SSL certificate verify ok.
14:13:46.789358 > POST /hooks/github HTTP/1.1
14:13:46.789358 > Host: buildmaster.local.lubar.me
14:13:46.789358 > Accept: */*
14:13:46.789358 > X-Hub-Signature: sha1=5aada0848e7a8bacb49af924d1200dae29d271ae
14:13:46.789358 > User-Agent: GitHub-Hookshot/dummy
14:13:46.789358 > X-GitHub-Event: ping
14:13:46.789358 > Content-Length: 2
14:13:46.789358 > Content-Type: application/x-www-form-urlencoded
14:13:46.789358 >
14:13:46.801584 * upload completely sent off: 2 out of 2 bytes
14:13:46.802706 < HTTP/1.1 204 No Content
HTTP/1.1 204 No Content
14:13:46.803805 * Server nginx/1.10.3 (Ubuntu) is not blacklisted
14:13:46.804416 < Server: nginx/1.10.3 (Ubuntu)
Server: nginx/1.10.3 (Ubuntu)
14:13:46.805454 < Date: Mon, 12 Feb 2018 20:13:46 GMT
Date: Mon, 12 Feb 2018 20:13:46 GMT
14:13:46.809358 < Connection: keep-alive
Connection: keep-alive
14:13:46.812246 < Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
14:13:46.813178 < Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
Public-Key-Pins: pin-sha256="YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg="; pin-sha256="sRHdihwgkaib1P1gxX8HFszlD+7/gTfNvuAybgLPNis="; max-age=2592000; includeSubDomains
14:13:46.814092 < X-Content-Type-Options: nosniff
X-Content-Type-Options: nosniff
14:13:46.821628 < Referrer-Policy: strict-origin-when-cross-origin
Referrer-Policy: strict-origin-when-cross-origin
14:13:46.822837 < X-XSS-Protection: 1; mode=block
X-XSS-Protection: 1; mode=block
14:13:46.823929 < X-Frame-Options: SAMEORIGIN
X-Frame-Options: SAMEORIGIN

14:13:46.825356 <
14:13:46.826086 * Connection #0 to host buildmaster.local.lubar.me left intact

real    0m0.310s
user    0m0.000s
sys     0m0.078s
    1
  • ben_lubar

    Alright, I now have this running on Google App Engine:

    package lubar_webhook_proxy

import (
	"bytes"
	"errors"
	"io/ioutil"
	"net/http"
	"strings"
	"time"

	"golang.org/x/net/context"

	"google.golang.org/appengine"
	"google.golang.org/appengine/delay"
	"google.golang.org/appengine/log"
	"google.golang.org/appengine/taskqueue"
	"google.golang.org/appengine/urlfetch"
)

type GitHubRequest struct {
	UserAgent string
	Signature string
	Event     string
	Delivery  string
	Payload   []byte
}

var laterGitHubRequest = delay.Func("GitHub-BuildMaster", func(ctx context.Context, req GitHubRequest) error {
	r, err := http.NewRequest("POST", "https://buildmaster.local.lubar.me/hooks/github", bytes.NewReader(req.Payload))
	if err != nil {
		return err
	}
	r.Header.Set("User-Agent", req.UserAgent)
	r.Header.Set("X-Hub-Signature", req.Signature)
	r.Header.Set("X-GitHub-Event", req.Event)
	r.Header.Set("X-GitHub-Delivery", req.Delivery)
	r.Header.Set("Content-Type", "application/json; charset=utf-8")

	ctxTimeout, cancel := context.WithTimeout(ctx, 5*time.Minute)
	defer cancel()

	client := urlfetch.Client(ctxTimeout)
	start := time.Now()

	resp, err := client.Do(r)
	if err != nil {
		return err
	}
	defer resp.Body.Close()

	if resp.StatusCode == http.StatusNoContent {
		log.Debugf(ctx, "[GitHub webhook] queued build: %v\n\nagent: %q\ndelivery: %q\nevent: %q\nsignature: %q\npayload: %q", time.Since(start), req.UserAgent, req.Delivery, req.Event, req.Signature, req.Payload)
		return nil // build was queued
	}
	body, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		return err
	}
	log.Errorf(ctx, "[GitHub webhook] %q: %q\n\nagent: %q\ndelivery: %q\nevent: %q\nsignature: %q\npayload: %q", resp.Status, body, req.UserAgent, req.Delivery, req.Event, req.Signature, req.Payload)
	if resp.StatusCode == http.StatusBadRequest {
		return nil // payload or signature was invalid
	}
	return errors.New(resp.Status)
})

func GitHubBuildMaster(w http.ResponseWriter, r *http.Request) {
	userAgent := r.UserAgent()
	signature := r.Header.Get("X-Hub-Signature")
	event := r.Header.Get("X-GitHub-Event")
	delivery := r.Header.Get("X-GitHub-Delivery")

	if r.Method != "POST" || !strings.HasPrefix(userAgent, "GitHub-Hookshot/") || signature == "" || event == "" || delivery == "" {
		http.Error(w, "This is the GitHub webhook endpoint.", http.StatusForbidden)
		return
	}
	defer r.Body.Close()

	payload, err := ioutil.ReadAll(r.Body)
	if err != nil {
		http.Error(w, err.Error(), http.StatusBadRequest)
		return
	}
	// GitHub documents payloads as being a maximum of five megabytes.
	// Drop payloads that are more than ten.
	if len(payload) > 10*1024*1024 {
		http.Error(w, "payload too big", http.StatusRequestEntityTooLarge)
		return
	}

	task, err := laterGitHubRequest.Task(GitHubRequest{
		UserAgent: userAgent,
		Signature: signature,
		Event:     event,
		Delivery:  delivery,
		Payload:   payload,
	})
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}
	task.RetryOptions = &taskqueue.RetryOptions{
		AgeLimit: time.Hour * 24 * 7,
	}
	taskqueue.Add(appengine.NewContext(r), task, "")
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}

	w.WriteHeader(http.StatusAccepted)
}

func init() {
	http.HandleFunc("/github/buildmaster", GitHubBuildMaster)
}

    It should stay well below the free quota limit.

    1
Log in to reply