Error on merging github pull request

[binarymist]

When I merge (every merge) a pull request generated by my staticman instance hosted on heroku, I receive the following error:

2021-04-22T02:30:20.417355+00:00 heroku[router]: at=info method=POST path="/v1/webhook" host=bmstaticmaninstance.herokuapp.com request_id=569654ed-47b1-4337-a1fd-27260ac51ce2 fwd="140.82.115.246" dyno=web.1 connect=0ms service=18ms status=200 bytes=223 protocol=https
2021-04-22T02:30:27.162232+00:00 app[web.1]: /app/node_modules/@octokit/request/dist-node/index.js:66
2021-04-22T02:30:27.162240+00:00 app[web.1]:         const error = new requestError.RequestError(message, status, {
2021-04-22T02:30:27.162242+00:00 app[web.1]:                       ^
2021-04-22T02:30:27.162243+00:00 app[web.1]: 
2021-04-22T02:30:27.162244+00:00 app[web.1]: RequestError [HttpError]: Reference does not exist
2021-04-22T02:30:27.162244+00:00 app[web.1]:     at /app/node_modules/@octokit/request/dist-node/index.js:66:23
2021-04-22T02:30:27.162244+00:00 app[web.1]:     at processTicksAndRejections (node:internal/process/task_queues:96:5) {
2021-04-22T02:30:27.162245+00:00 app[web.1]:   status: 422,
2021-04-22T02:30:27.162245+00:00 app[web.1]:   headers: {
2021-04-22T02:30:27.162246+00:00 app[web.1]:     'access-control-allow-origin': '*',
2021-04-22T02:30:27.162248+00:00 app[web.1]:     'access-control-expose-headers': 'ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Used, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type, Deprecation, Sunset',
2021-04-22T02:30:27.162248+00:00 app[web.1]:     connection: 'close',
2021-04-22T02:30:27.162249+00:00 app[web.1]:     'content-length': '122',
2021-04-22T02:30:27.162249+00:00 app[web.1]:     'content-security-policy': "default-src 'none'",
2021-04-22T02:30:27.162249+00:00 app[web.1]:     'content-type': 'application/json; charset=utf-8',
2021-04-22T02:30:27.162250+00:00 app[web.1]:     date: 'Thu, 22 Apr 2021 02:30:27 GMT',
2021-04-22T02:30:27.162251+00:00 app[web.1]:     'referrer-policy': 'origin-when-cross-origin, strict-origin-when-cross-origin',
2021-04-22T02:30:27.162251+00:00 app[web.1]:     server: 'GitHub.com',
2021-04-22T02:30:27.162252+00:00 app[web.1]:     'strict-transport-security': 'max-age=31536000; includeSubdomains; preload',
2021-04-22T02:30:27.162252+00:00 app[web.1]:     vary: 'Accept-Encoding, Accept, X-Requested-With',
2021-04-22T02:30:27.162253+00:00 app[web.1]:     'x-content-type-options': 'nosniff',
2021-04-22T02:30:27.162253+00:00 app[web.1]:     'x-frame-options': 'deny',
2021-04-22T02:30:27.162254+00:00 app[web.1]:     'x-github-media-type': 'github.v3; format=json',
2021-04-22T02:30:27.162254+00:00 app[web.1]:     'x-github-request-id': '8F8C:0CA8:1C4C94:501EB5:6080DFC3',
2021-04-22T02:30:27.162254+00:00 app[web.1]:     'x-ratelimit-limit': '5000',
2021-04-22T02:30:27.162255+00:00 app[web.1]:     'x-ratelimit-remaining': '4983',
2021-04-22T02:30:27.162255+00:00 app[web.1]:     'x-ratelimit-reset': '1619061787',
2021-04-22T02:30:27.162256+00:00 app[web.1]:     'x-ratelimit-used': '17',
2021-04-22T02:30:27.162256+00:00 app[web.1]:     'x-xss-protection': '0'
2021-04-22T02:30:27.162256+00:00 app[web.1]:   },
2021-04-22T02:30:27.162256+00:00 app[web.1]:   request: {
2021-04-22T02:30:27.162257+00:00 app[web.1]:     method: 'DELETE',
2021-04-22T02:30:27.162258+00:00 app[web.1]:     url: 'https://api.github.com/repos/binarymist/BinaryMistBlog/git/refs/heads/staticman_d1e13160-a311-11eb-9c0b-1f6159366f7a',
2021-04-22T02:30:27.162258+00:00 app[web.1]:     headers: {
2021-04-22T02:30:27.162259+00:00 app[web.1]:       accept: 'application/vnd.github.v3+json',
2021-04-22T02:30:27.162259+00:00 app[web.1]:       'user-agent': 'Staticman octokit.js/16.35.0 Node.js/16.0.0 (Linux 4.4; x64)',
2021-04-22T02:30:27.162260+00:00 app[web.1]:       authorization: 'token [REDACTED]',
2021-04-22T02:30:27.162260+00:00 app[web.1]:       'content-length': 0
2021-04-22T02:30:27.162261+00:00 app[web.1]:     },
2021-04-22T02:30:27.162261+00:00 app[web.1]:     request: {
2021-04-22T02:30:27.162261+00:00 app[web.1]:       timeout: 5000,
2021-04-22T02:30:27.162262+00:00 app[web.1]:       hook: [Function: bound bound register],
2021-04-22T02:30:27.162262+00:00 app[web.1]:       validate: {
2021-04-22T02:30:27.162263+00:00 app[web.1]:         owner: { required: true, type: 'string' },
2021-04-22T02:30:27.162263+00:00 app[web.1]:         ref: { required: true, type: 'string' },
2021-04-22T02:30:27.162263+00:00 app[web.1]:         repo: { required: true, type: 'string' }
2021-04-22T02:30:27.162264+00:00 app[web.1]:       }
2021-04-22T02:30:27.162264+00:00 app[web.1]:     }
2021-04-22T02:30:27.162264+00:00 app[web.1]:   },
2021-04-22T02:30:27.162265+00:00 app[web.1]:   documentation_url: 'https://docs.github.com/rest/reference/git#delete-a-reference'
2021-04-22T02:30:27.162265+00:00 app[web.1]: }
2021-04-22T02:30:27.269456+00:00 heroku[web.1]: Process exited with status 1
2021-04-22T02:30:27.342460+00:00 heroku[web.1]: State changed from up to crashed

Sometimes the staticman instance is automatically restarted, if this is the case, subscribers will get notifications, if the staticman instnce isn't restarted subscribers won't get notifications. When the next comment is posted the user gets the following error:

and the logs say:

2021-04-22T03:05:50.754634+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=POST path="/v3/entry/github/binarymist/BinaryMistBlog/master/comments" host=bmstaticmaninstance.herokuapp.com request_id=4496c735-dcfe-4558-98cb-4ffc10c25c39 fwd="201.118.135.64" dyno= connect= service= status=503 bytes= protocol=https
2021-04-22T03:05:51.682540+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/favicon.ico" host=bmstaticmaninstance.herokuapp.com request_id=4b93fafb-4cfe-4514-8408-80666220662c fwd="201.118.135.64" dyno= connect= service= status=503 bytes= protocol=https

and the post of the comment fails. After this every request receives seems to fail

Then I have to restart dyno manually, then I get:

2021-04-22T03:13:34.164644+00:00 heroku[web.1]: State changed from crashed to starting
2021-04-22T03:13:40.005441+00:00 heroku[web.1]: Starting process with command `npm start`
2021-04-22T03:13:42.814789+00:00 app[web.1]: 
2021-04-22T03:13:42.814814+00:00 app[web.1]: > [email protected] prestart
2021-04-22T03:13:42.814814+00:00 app[web.1]: > if [ ! -d node_modules ]; then npm install; fi
2021-04-22T03:13:42.814815+00:00 app[web.1]: 
2021-04-22T03:13:42.829369+00:00 app[web.1]: 
2021-04-22T03:13:42.829371+00:00 app[web.1]: > [email protected] start
2021-04-22T03:13:42.829371+00:00 app[web.1]: > node index.js
2021-04-22T03:13:42.829371+00:00 app[web.1]: 
2021-04-22T03:13:44.185541+00:00 app[web.1]: Staticman API running on port 38873
2021-04-22T03:13:44.739539+00:00 heroku[web.1]: State changed from starting to up

Now... I remember I had the next problem last time staticman was working, and it's still happening. When two comment posters subscribe to notifications, there on after on every merge of comment to the github repo, two notifications are sent to each subscribed user. This of course multiplies as the number of subscribed users goes up. Once we have four subscribers, each one of them receives 4 email messages that a new comment has been posted when I merge a comment pull request.

Any idea what's causing these issues?

The first one I haven't noticed befroe as I used to use the community provided staticman instance. Now that I'm using my own instance, I get to see the logs.

The second one is a long standing issue, #182

Am I perhaps missing a value or values from the api config?
All I have in Heroku is the following populated values (all detailed in the getting started guide):

GITHUB_APP_ID
GITHUB_PRIVATE_KEY
RSA_PRIVATE_KEY

My site configuration file (staticman.yml) is here.

There are no issues with my front-end, it's been good for years, examples:

• Blog post subscription: https://binarymist.io/post
• Check the posts with comment counts for proof

Thanks.

[hispanic]

RequestError [HttpError]: Reference does not exist

This response will be returned when the branch that Staticman is trying to delete has already been deleted. When merging in the comment, are you manually deleting the branch before Staticman can do it?

[binarymist]

Hi @hispanic, thanks for your response.
No.
Just tested this again.

On my merging of the pull request that staticman submitted, I can see staticman closing the pull request branch:

Same RequestError log as posted above.

The Github app logs that the closed action was successful (200 response)

The Github hook also logs the closed action was successful (200 response)

I'm not sure how anyone would be able to manually delete the branch after merge before staticman could do it automatically. One would have to be very fast? Even if this was the case which it's not, why would staticman crash every time?

Thanks.

[hispanic]

Maybe you have two webhooks set up and it is the second one that is failing? Keep in mind that apps running on the Heroku free plan are put to sleep ("Stopping all processes with SIGTERM") and that they take a while (10-30 seconds) to wake-up whenever they receive a request.

[binarymist]

Hmm, I can only see a single Github webhook, I've also been watching it's logs. I do plan on setting up another one on a different static site repo in the not to distant future though. Will this be a problem?

Thanks.

[binarymist]

It also seems that staticman crashes in some sort of state and is not restarted at all

[binarymist]

I can see the Github app logs a single open and then close event. I think if there were multiple Github webhooks I'd be seeing multiple close events?

[hispanic]

If you definitely believe the webhook is the trigger for your issues, you could try manually submitting equivalent requests to your Staticman instance using Insomnia, Postman, etc. I have no quick solutions to offer you. Sorry.

[miwucs]

I had the same issue, it turns out I had a github option to automatically delete branches checked https://docs.github.com/en/repositories/configuring-branches-and-merges-in-your-repository/configuring-pull-request-merges/managing-the-automatic-deletion-of-branches

Unchecking it solved the problem. But regardless, I don't think staticman should crash just because it receives an error from github, especially on branch deletion which is not critical. As mentioned in the original bug, the dyno doesn't always get restarted automatically, and then all users get an error until you run "heroku restart" manually.

[andsplat]

@miwucs I am getting this same 422 error when either merging or closing a pull request. I checked the setting you mentioned and it was not checked. I am still getting the error.

@binarymist were you able to fix this issue? I cannot find a lot of documentation around the 422 status error.

[andsplat]

I am now seeing 404 errors. I had one merge request work (not sure why?) and now I am seeing 404 status crashes when trying to merge or close a pull request. Not sure what to change.

[binarymist]

No fix.

[andsplat]

@binarymist sorry to hear that. Do you still use Staticman? Do you use a different configuration or just restart Heroku manually after every pull request merge or close?

[binarymist]

Staticman is still being used. I keep my eye on Heroku and manually restart when it falls over.

[andsplat]

@binarymist I might have fixed this. I blame the lack of instructions for implementing Staticman. If you are like me, I had to piece together instructions from a lot of different sources to get it to work (and some were using v2 versus v3 and GitHub application vs separate GitHub account, etc.).

In the end, I noticed I had two webhooks running. One on the repo and one in my GitHub App. It seems what was happening is that when I merged or closed a pull request, one of the webhooks acted first, which is why my comments were still working (ie: able to be posted to my blog), but when the second webhook tried to delete the branch, it got an error since the branch/file were already deleted. This resulted in my Heroku Staticman app crashing. I removed the webhook from my repo (just keeping the one in the GitHub App) and now I am not seeing the errors.

Hopefully this will work for you and others!

[dancwilliams]

@andsplat Thank you! I had the double hook as well. Have been racking my brain!

[andsplat]

@andsplat Thank you! I had the double hook as well. Have been racking my brain!

Glad it was helpful!