Forums

Possible issue with uswgi/nginx buffer being too small, Github Web Hooks

Hey there! I am having some trouble with my django app recieving the POST data correctly from a Github Web Hook payload. I have used request bucket (http://requestb.in/1bksjpj1?inspect) to see that the payload is being delivered correctly from Github. However when I recieve it on my site it is broken and incomplete. The server logs show something like..

2014-09-29 22:41:27 [(u'payload', [u'{"ref":"refs/heads/master","before":"60d049104b8984ba1334774c6c93847a4de7315e","after":"828537223df5ddc9919671f4c5ece9871391af69","created":false,"deleted":false,"forced":false,"base_ref":null,"compare":"https://github.com/valeyard/SearchDemon/compare/60d049104b89...828537223df5","commits":[{"id":"828537223df5ddc9919671f4c5ece9871391af69","distinct":true,"message":"s","timestamp":"2014-09-29T22:51:08+01:00","url":"https://github.com/valeyard/SearchDemon/commit/828537223df5ddc9919671f4c5ece9871391af69","author":{"name":"valeyard","email":"mrpontius@gmail.com","username":"valeyard"},"committer":{"name":"valeyard","email":"mrpontius@gmail.com","username":"valeyard"},"added":[],"removed":[],"modified":["searchDemonProject/.idea/workspace.xml","searchDemonProject/searchdemon/githubtasks.py"]}],"head_commit":{"id":"828537223df5ddc9919671f4c5ece9871391af69","distinct":true,"message":"s","timestamp":"2014-09-29T22:51:08+ 2014-09-29 22:41:27 /api.github.com/repos/valeyard/SearchDemon/pulls{/number}","milestones_url":"https://api.github.com/repos/valeyard/SearchDemon/milestones{/number}","notifications_url":"https://api.github.com/repos/valeyard/SearchDemon/notifications{?since,all,participating}","labels_url":"https://api.github.com/repos/valeyard/SearchDemon/labels{/name}","releases_url":"https://api.github.com/repos/valeyard/SearchDemon/releases{/id}","created_at":1410819054,"updated_at":"2014-09-24T17:12:44Z","pushed_at":1412027504,"git_url":"git://github.com/valeyard/SearchDemon.git","ssh_url":"git@github.com:valeyard/SearchDemon.git","clone_url":"https://github.com/valeyard/SearchDemon.git","svn_url":"https://github.com/valeyard/SearchDemon","homepage":null,"size":1172,"stargazers_count":0,"watchers_count":0,"language":"Python","has_issues":true,"has_downloads":true,"has_wiki":true,"has_pages":false,"forks_count":0,"mirror_url":null,"open_issues_count":0,"forks" 2014-09-29 22:41:27 Mon Sep 29 17:41:27 2014 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /searchdemon/stackcommits/ (ip 10.138.64.83) !!! 2014-09-29 22:41:27 Mon Sep 29 17:41:27 2014 - uwsgi_response_write_headers_do(): Broken pipe [core/writer.c line 229] during POST /searchdemon/stackcommits/ (10.138.64.83)

You can see from the timestamps that is arriving in different parts, and it isn't complete either. The size of thepayload, in this case, is 8588 and is delivered with the application/x-www-form-urlencoded header Sorry the above request output is, i believe, when i was using the json header. This is the urlencode header stuff:

2014-09-29 23:10:24 payload=%7B%22ref%22%3A%22refs%2Fheads%2Fmaster%22%2C%22before%22%3A%2260e1960a95c7bd381f67f2b2dbbacd1ff48cb424%22%2C%22after%22%3A%223842add94f763c4b08ab5dce611af1e434996554%22%2C%22created%22%3Afalse%2C%22deleted%22%3Afalse%2C%22forced%22%3Afalse%2C%22base_ref%22%3Anull%2C%22compare%22%3A%22https%3A%2F%2Fgithub.com%2Fvaleyard%2FSearchDemon%2Fcompare%2F60e1960a95c7...3842add94f76%22%2C%22commits%22%3A%5B%7B%22id%22%3A%223842add94f763c4b08ab5dce611af1e434996554%22%2C%22distinct%22%3Atrue%2C%22message%22%3A%22asas%5Cn%5Cnas%22%2C%22timestamp%22%3A%222014-09-29T23%3A39%3A04%2B01%3A00%22%2C%22url%22%3A%22https%3A%2F%2Fgithub.com%2Fvaleyard%2FSearchDemon%2Fcommit%2F3842add94f763c4b08ab5dce611af1e434996554%22%2C%22author%22%3A%7B%22name%22%3A%22valeyard%22%2C%22email%22%3A%22mrpontius%40gmail.com%22%2C%22username%22%3A%22valeyard%22%7D%2C%22committer%22%3A%7B%22name%22%3A%22valeyard%22%2C%22email%22%3A%22mrpontius%40gmail.com%22%2C%22 2014-09-29 23:10:24 aleyard%2FSearchDemon%2Flanguages%22%2C%22stargazers_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fstargazers%22%2C%22contributors_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fcontributors%22%2C%22subscribers_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fsubscribers%22%2C%22subscription_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fsubscription%22%2C%22commits_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fcommits%7B%2Fsha%7D%22%2C%22git_commits_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fgit%2Fcommits%7B%2Fsha%7D%22%2C%22comments_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fcomments%7B%2Fnumber%7D%22%2C%22issue_comment_url%22%3A%22https%3A%2F%2Fapi.github.com%2Frepos%2Fvaleyard%2FSearchDemon%2Fissues%2Fcomments%2F%7Bnum 2014-09-29 23:10:24 s%3A%2F%2Fapi.github.com%2Fusers%2Fvaleyard%2Forgs%22%2C%22repos_url%22%3A%22https%3A%2F%2Fapi.github.com%2Fusers%2Fvaleyard%2Frepos%22%2C%22events_url%22%3A%22https%3A%2F%2Fapi.github.com%2Fusers%2Fvaleyard%2Fevents%7B%2Fprivacy%7D%22%2C%22received_events_url%22%3A%22https%3A%2F%2Fapi.github.com%2Fusers%2Fvaleyard%2Freceived_events%22%2C%22type%22%3A%22User%22%2C%22site_admin%22%3Afalse%7D%7D

The above request should be around 2x in length, and not separated in multiple parts either

Any idea why this is isn't receiving properly? Thanks!

The requests are definetely being sent correctly from Github, as evidenced from the Request Bin link. But it just doesn't seem to make it through.

I'm not sure what's happening there, but I doubt the issue is with our infrastructure. I have successfully created a little Flask view that accepts and dumps the body of a GitHub webhook POST. The payload that I receive when it's url-encoded is 9075 bytes long and it's accepted and parsed by Flask correctly. I have also tried with a JSON payload (I didn't check the size) and that worked perfectly, too.

I'm not sure what might be going on with your code, but a wild guess might be that your view takes too long receiving the request and so Github decides to not sit around waiting for it. The Github webhook configuration page has a way to send test messages and reports the result of the call there (it helped me early on when I had a misplaced colon that was making trouble). Have you tried it?

yeah Github reports that the payloads are being delivered, sometimes as quick as 0.3s successfully. I am not sure how to figure out where exactly the break in the chain is, there isn't much complexity here :(

Thanks very much for the answer glenn.

Hmm, so it's definetely not a PA infrastructure problem. The view I am using is literally just printing the request though, so it shouldn't be an issue of it taking too long; :::python

def stackcommits(request):
    context = RequestContext(request)

    if request.method == 'POST':
        print urllib2.unquote(request.body)

    return HttpResponse("")

But I know you aren't Python/Django support so I will look elsewhere for now

I think you're just seeing a logging artifact. The message is being delivered as a single POST, but the logger is breaking up the message because it is too long. Instead of just printing the message (which sends it to the server log), use

print >> sys.stderr, request.body

and it will appear in the error log without truncation.