Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Strange behavior with webhooks #827

Closed
scritch007 opened this issue Jan 3, 2015 · 6 comments
Closed

Strange behavior with webhooks #827

scritch007 opened this issue Jan 3, 2015 · 6 comments
Labels
💊 bug Something isn't working status: needs feedback Tell me more about it

Comments

@scritch007
Copy link

I update my issue description, regarding the other comments, but I'll leave my initial issue description below.

DeliverHooks called from gogs update doesn't seems to work.
Two issues, first one is the one described in comment 2. The gogs update doesn't wait for the DeliverHooks go routine which means that it is only done partially

Second issue I've found when calling DeliverHooks, not in a go routine, is that for some unknown reason (I'll investigate more on this) the req.Response() when calling the hooks will always fail in this process, but will succeed when called from gogs web
Two errors I've had so far:

I'm using the latest github version of gogs. This project seems really awesome. I wanted to test the webhook feature, but I have an issue when running it on my computer.

If I only enable one webhook, then I will never receive anything. If I create a second webhook, then I'll start receiving all the webhooks.

I've tried to reproduce this issue with the try.gogs.io, but it seems to work well.

From what I can see in the xorm logs, when only one webhook is enabled, I have the INSERT in the hook_task table and then an update setting the is_delivered value to true, which means that when > the "cron" comes, it doesn't see any new hook task to perfom and won't do anything.>

When more then one webhook is active on a repository, then I only get the INSERT and that's all, the update comes later on "cron" for the hooks.

Thanks a lot for your hard work, and hope you can help me with this issue. I can add some logs or try anythings like that if needed.

Here is the partial output of my xorm.log when only one webhook is available, this will even speak better then my previous explanations

[xorm] [debug] 2015/01/03 23:09:09.861022 [time] INSERT INTOhook_task(uuid,type,url,payload_content,content_type,event_type,is_ssl,is_delivered,is_succeed) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?) - args [add0f66e-ff25-4bd3-9412-201af69f085d 1 http://127.0.0.1:3001/hooks/toto/1 {"secret":"DFGHJK","ref":"refs/heads/master","commits":[{"id":"5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","message":"FGHJ\n","url":"http://localhost:3000/scritch007/a/commit/5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","author":{"name":"Benjamin Legrand","email":"dev@legrand.ws","username":"scritch007"}}],"repository":{"id":2,"name":"a","url":"http://localhost:3000/scritch007/a","description":"","website":"","watchers":0,"owner":{"name":"scritch007","email":"dev@legrand.ws","username":"scritch007"},"private":false},"pusher":{"name":"scritch007","email":"dev@legrand.ws","username":"scritch007"},"before":"749c84d375b86bc1dcc384983b5f3322ec44e5c1","after":"5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","compare_url":"http://localhost:3000/scritch007/a/compare/749c84d375b86bc1dcc384983b5f3322ec44e5c1...5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d"} 1 false false false] - execution took: 63660294ns [xorm] [info] 2015/01/03 23:09:09.861157 [sql] DELETE FROMupdate_taskWHEREuuid= ? [args] [631e6e2e-1033-4af4-81b2-6c7531db70b2] [xorm] [info] 2015/01/03 23:09:09.861346 [sql] SELECTid,uuid,type,url,payload_content,content_type,event_type,is_ssl,is_delivered,is_succeedFROMhook_taskWHERE is_delivered=? [args] [[false]] [xorm] [info] 2015/01/03 23:09:09.862708 [sql] UPDATEhook_taskSETuuid= ?,type= ?,url= ?,payload_content= ?,content_type= ?,event_type= ?,is_ssl= ?,is_delivered= ?,is_succeed= ? WHEREid= ? [args] [add0f66e-ff25-4bd3-9412-201af69f085d 1 http://127.0.0.1:3001/hooks/toto/1 {"secret":"DFGHJK","ref":"refs/heads/master","commits":[{"id":"5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","message":"FGHJ\n","url":"http://localhost:3000/scritch007/a/commit/5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","author":{"name":"Benjamin Legrand","email":"dev@legrand.ws","username":"scritch007"}}],"repository":{"id":2,"name":"a","url":"http://localhost:3000/scritch007/a","description":"","website":"","watchers":0,"owner":{"name":"scritch007","email":"dev@legrand.ws","username":"scritch007"},"private":false},"pusher":{"name":"scritch007","email":"dev@legrand.ws","username":"scritch007"},"before":"749c84d375b86bc1dcc384983b5f3322ec44e5c1","after":"5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d","compare_url":"http://localhost:3000/scritch007/a/compare/749c84d375b86bc1dcc384983b5f3322ec44e5c1...5000a717cf8e8bd1bc1aa503d8e8665f4ec4e74d"} 1 false true false 47]

@scritch007
Copy link
Author

For the record, removing the
go DeliverHooks()

from CommitRepoAction (gogs/models/action.go) fixes my problem.

@scritch007
Copy link
Author

I've investigated a little bit more, and I think I've found what is going wrong in here. Tell me if I missed something:

When you push through ssh,

  1. gogs update $1 $2 $3 is spawned, this will add some update_task entries
  2. gogs serv will be called.

This process will look at task to update and will then start a new go routine for handling the hooks.

this is the go DeliverHooks() call.

But it doesn't wait for this go routine to stop (this is because it doesn't want to block for all the hooks).
Since noone waits for this go routine, once the other jobs have been done, the process stops, and leaves the current DeliverHooks as they are.

An easy test to show that, is to add a sleep at the beginning of the DeliverHook some logs, and you'll see that those logs will never be shown.

This is probably why with one hook I get an error, but with more then one, the find is a little bit longer, and it doesn't even get into the delivery loop.

One other possible issue/race condition I've found, is that if DeliverHooks can be called both from the gogs serv and from gogs web, there is nothing that prevents it from calling twice the hooks with the same information. Indeed the only protection, is the find("is_delivered"=false) but if both makes this call at the same time then they could be doing the same thing

@unknwon
Copy link
Member

unknwon commented Jan 6, 2015

Hi @scritch007 , thanks your report and sorry for late!

removing the go DeliverHooks() from CommitRepoAction (gogs/models/action.go) fixes my problem.

I think this right solution, if you can confirm this DID solves your problem, I would remove and push to GitHub. 😄

@unknwon unknwon added 💊 bug Something isn't working status: needs feedback Tell me more about it labels Jan 6, 2015
@scritch007
Copy link
Author

Hi @unknwon

Yes this actually fixed the webhooks. Now the "cron" does it for you and correctly :). So this means that in the worst case you'll have to wait 60 seconds (by default) before being notified of the push. I don't think this is a problem, but maybe it would be nice to have a better fix.

Maybe for a later version, gogs serv could send a message (http or a signal) to the main gogs web process, so that this triggers the webhooks delivery. It's true that it would be nice to have realtime webhooks, but there are many more important feature then this.

@unknwon
Copy link
Member

unknwon commented Jan 6, 2015

Right, I forgot that gogs serv and gogs web makes two independent processes so that the isShooting actually won't work at all.

Maybe create a separate issue called realtime webhook would be best solution for now. How do you think?

@scritch007
Copy link
Author

Yes an enhancement issue would be great. I'm gonna create one, so that you can close this one.

@unknwon unknwon closed this as completed in bb26285 Jan 6, 2015
ethantkoenig added a commit to ethantkoenig/gogs that referenced this issue Feb 11, 2017
@ethantkoenig @lunny
Avoid duplicate queries in auth (gogs#827)
e86d935 
Avoid identical making calls to GetUserByID(..) in SignedInUser(..)
@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 23, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
💊 bug Something isn't working status: needs feedback Tell me more about it
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@scritch007 @unknwon