Pushing many commits with 'Require Signed Commits' enabled fails with 'Gitea: Internal Server Connection Error' #13765

Closed
opened 2025-11-02 10:52:30 -06:00 by GiteaMirror · 11 comments
Owner

Originally created by @Mik4sa on GitHub (Nov 28, 2024).

Description

On a private repo / gitea instance I merged our default branch into a fairly old feature branch resulting into 1938 commits to be pushed at once. When pushing I get an error after about 64 seconds, so roughly after a minute.
This is what I get in my console:

$ git push
Enumerating objects: 19, done.
Counting objects: 100% (19/19), done.
Delta compression using up to 16 threads
Compressing objects: 100% (6/6), done.
Writing objects: 100% (7/7), 826 bytes | 413.00 KiB/s, done.
Total 7 (delta 5), reused 0 (delta 0), pack-reused 0 (from 0)
remote:
remote: Gitea: Internal Server Connection Error
remote: * Checking 1 references
To https://gitea.[...].de/[OWNER]/[REPO]
 ! [remote rejected]       test-push-many-commits -> test-push-many-commits (pre-receive hook declined)
error: failed to push some refs to 'https://gitea.[...].de/[OWNER]/[REPO]'

In the logs from gitea I've found these messages:

2024/11/28 09:44:43 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 5e282dc2d42e2376b183e2f8fb432e0eff9769a3
2024/11/28 09:44:43 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 5e282dc2d42e2376b183e2f8fb432e0eff9769a3
2024/11/28 09:44:43 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60995.7ms @ private/hook_pre_receive.go:105(private.HookPreReceive)

I tried the push several times, so I found this error for every try:

2024/11/28 08:17:51 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 9d7b64edd639a30b8a9210b514637ae0b1b2c584
2024/11/28 08:17:51 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 9d7b64edd639a30b8a9210b514637ae0b1b2c584
2024/11/28 08:17:51 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60995.2ms @ private/hook_pre_receive.go:105(private.HookPreReceive)
2024/11/28 08:23:09 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: f33b08cfb9b2f6dd7c9324ded61c189a85d46a52
2024/11/28 08:23:09 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit f33b08cfb9b2f6dd7c9324ded61c189a85d46a52
2024/11/28 08:23:09 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60998.5ms @ private/hook_pre_receive.go:105(private.HookPreReceive)
2024/11/28 08:26:51 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: c201bae87cc121be48437940ca59c0b76c0948e1
2024/11/28 08:26:51 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit c201bae87cc121be48437940ca59c0b76c0948e1
2024/11/28 08:26:51 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60996.2ms @ private/hook_pre_receive.go:105(private.HookPreReceive)
2024/11/28 08:30:49 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 6292dbd965c3ee366f29e2baf86d4770bea70801
2024/11/28 08:30:49 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 6292dbd965c3ee366f29e2baf86d4770bea70801
2024/11/28 08:30:49 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 61006.1ms @ private/hook_pre_receive.go:105(private.HookPreReceive)
2024/11/28 08:57:02 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 25f3e9316c75df247f342ffef7cd68f6287d4f06
2024/11/28 08:57:02 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 25f3e9316c75df247f342ffef7cd68f6287d4f06
2024/11/28 08:57:02 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 61006.9ms @ private/hook_pre_receive.go:105(private.HookPreReceive)

Note that branch protection for this branch (all branches) is enabled. The only enabled setting is 'Require Signed Commits'.

The log states that there are unverified commits. Which isnt true. Looking into the default branch I can see that the commit is signed and verified by Gitea. All of them. Interestingly it's always a different commit which should be unverified, according to the logs. Also this error always appear after 61 seconds which is very close to 60 seconds. Sounds like a timeout or something.
The push was successful after I disabled the requirement for signed commits.

Is there a timeout for the pre_receive hook I can adjust or for the signature check? I couldn't find any.
Also I tried to quickly check the source code but couldn't find any timeout, directly. But note that I'm not firm with go nor with the code of Gitea.

Gitea Version

1.22.3

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

No response

Screenshots

No response

Git Version

2.39.1.windows.1

Operating System

Windows Server 2016 - Version 1607 (Build 14393.6452)

How are you running Gitea?

  • Using gitea-1.22.3-windows-4.0-amd64.exe from your download page
  • Registered as a Windows service with the following command line: D:\gitea\gitea.exe web --config D:\gitea\custom\conf\app.ini

Database

MSSQL

Originally created by @Mik4sa on GitHub (Nov 28, 2024). ### Description On a private repo / gitea instance I merged our default branch into a fairly old feature branch resulting into 1938 commits to be pushed at once. When pushing I get an error after about 64 seconds, so roughly after a minute. This is what I get in my console: ``` $ git push Enumerating objects: 19, done. Counting objects: 100% (19/19), done. Delta compression using up to 16 threads Compressing objects: 100% (6/6), done. Writing objects: 100% (7/7), 826 bytes | 413.00 KiB/s, done. Total 7 (delta 5), reused 0 (delta 0), pack-reused 0 (from 0) remote: remote: Gitea: Internal Server Connection Error remote: * Checking 1 references To https://gitea.[...].de/[OWNER]/[REPO] ! [remote rejected] test-push-many-commits -> test-push-many-commits (pre-receive hook declined) error: failed to push some refs to 'https://gitea.[...].de/[OWNER]/[REPO]' ``` In the logs from gitea I've found these messages: ``` 2024/11/28 09:44:43 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 5e282dc2d42e2376b183e2f8fb432e0eff9769a3 2024/11/28 09:44:43 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 5e282dc2d42e2376b183e2f8fb432e0eff9769a3 2024/11/28 09:44:43 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60995.7ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` I tried the push several times, so I found this error for every try: ``` 2024/11/28 08:17:51 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 9d7b64edd639a30b8a9210b514637ae0b1b2c584 2024/11/28 08:17:51 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 9d7b64edd639a30b8a9210b514637ae0b1b2c584 2024/11/28 08:17:51 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60995.2ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` ``` 2024/11/28 08:23:09 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: f33b08cfb9b2f6dd7c9324ded61c189a85d46a52 2024/11/28 08:23:09 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit f33b08cfb9b2f6dd7c9324ded61c189a85d46a52 2024/11/28 08:23:09 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60998.5ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` ``` 2024/11/28 08:26:51 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: c201bae87cc121be48437940ca59c0b76c0948e1 2024/11/28 08:26:51 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit c201bae87cc121be48437940ca59c0b76c0948e1 2024/11/28 08:26:51 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 60996.2ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` ``` 2024/11/28 08:30:49 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 6292dbd965c3ee366f29e2baf86d4770bea70801 2024/11/28 08:30:49 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 6292dbd965c3ee366f29e2baf86d4770bea70801 2024/11/28 08:30:49 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 61006.1ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` ``` 2024/11/28 08:57:02 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 25f3e9316c75df247f342ffef7cd68f6287d4f06 2024/11/28 08:57:02 .../hook_pre_receive.go:216:preReceiveBranch() [W] Forbidden: Branch: test-push-many-commits in <Repository 10055:[OWNER]/[REPO]> is protected from unverified commit 25f3e9316c75df247f342ffef7cd68f6287d4f06 2024/11/28 08:57:02 ...eb/routing/logger.go:102:func1() [I] router: completed POST /api/internal/hook/pre-receive/[OWNER]/[REPO] for 127.0.0.1:0, 403 Forbidden in 61006.9ms @ private/hook_pre_receive.go:105(private.HookPreReceive) ``` Note that branch protection for this branch (all branches) is enabled. The only enabled setting is 'Require Signed Commits'. The log states that there are unverified commits. Which isnt true. Looking into the default branch I can see that the commit is signed and verified by Gitea. All of them. Interestingly it's always a different commit which should be unverified, according to the logs. Also this error always appear after 61 seconds which is very close to 60 seconds. Sounds like a timeout or something. The push was successful after I disabled the requirement for signed commits. Is there a timeout for the pre_receive hook I can adjust or for the signature check? I couldn't find any. Also I tried to quickly check the source code but couldn't find any timeout, directly. But note that I'm not firm with go nor with the code of Gitea. ### Gitea Version 1.22.3 ### Can you reproduce the bug on the Gitea demo site? No ### Log Gist _No response_ ### Screenshots _No response_ ### Git Version 2.39.1.windows.1 ### Operating System Windows Server 2016 - Version 1607 (Build 14393.6452) ### How are you running Gitea? - Using gitea-1.22.3-windows-4.0-amd64.exe from your download page - Registered as a Windows service with the following command line: D:\gitea\gitea.exe web --config D:\gitea\custom\conf\app.ini ### Database MSSQL
GiteaMirror added the type/bug label 2025-11-02 10:52:30 -06:00
Author
Owner

@Mik4sa commented on GitHub (Mar 13, 2025):

Any update here? We are still facing this issue.

@Mik4sa commented on GitHub (Mar 13, 2025): Any update here? We are still facing this issue.
Author
Owner

@wxiaoguang commented on GitHub (Mar 13, 2025):

The failure is from this call: https://github.com/go-gitea/gitea/blob/release/v1.23/routers/private/hook_verification.go#L48

Unfortunately the related "verification" code is extremely complex, it seems impossible (to me) to guess the root problem by just reading code.

If you need to figure out the root problem, maybe you need to try to debug it in your environment.


Meanwhile, let's do a best guess: maybe the failure is not caused by the verification, but just by your reverse proxy (or some other settings) because it always fails in 60s and the failed commit ID seems random.

-> https://github.com/go-gitea/gitea/issues/33865#issuecomment-2720302992

@wxiaoguang commented on GitHub (Mar 13, 2025): The failure is from this call: https://github.com/go-gitea/gitea/blob/release/v1.23/routers/private/hook_verification.go#L48 Unfortunately the related "verification" code is extremely complex, it seems impossible (to me) to guess the root problem by just reading code. If you need to figure out the root problem, maybe you need to try to debug it in your environment. ---- Meanwhile, let's do a best guess: maybe the failure is not caused by the verification, but just by your reverse proxy (or some other settings) because it always fails in 60s and the failed commit ID seems random. -> https://github.com/go-gitea/gitea/issues/33865#issuecomment-2720302992
Author
Owner

@Mik4sa commented on GitHub (Mar 13, 2025):

Thank you for your reply. Back then I tried changing some timeouts but without luck. I'll try this at some point again and come back :)

@Mik4sa commented on GitHub (Mar 13, 2025): Thank you for your reply. Back then I tried changing some timeouts but without luck. I'll try this at some point again and come back :)
Author
Owner

@Mik4sa commented on GitHub (Mar 14, 2025):

It does not seem to be the reverse proxy I'm using. Lowering the read timeout results in a different message.
Also, today I found a different log message:

2025/03/14 17:45:35 ...mmit_verification.go:106:ParseCommitWithSignature() [E] GetUserByEmail: context canceled
2025/03/14 17:45:35 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 897f807f6bde0250ea2290830ee061e0a43692dc

So I'm reffering to this one: GetUserByEmail: context canceled

What does context canceled mean though? It always takes about 65 (definitive more then 60) seconds.

@Mik4sa commented on GitHub (Mar 14, 2025): It does not seem to be the reverse proxy I'm using. Lowering the read timeout results in a different message. Also, today I found a different log message: ```txt 2025/03/14 17:45:35 ...mmit_verification.go:106:ParseCommitWithSignature() [E] GetUserByEmail: context canceled 2025/03/14 17:45:35 ...hook_verification.go:50:func2() [E] readAndVerifyCommitsFromShaReader failed: Unverified commit: 897f807f6bde0250ea2290830ee061e0a43692dc ``` So I'm reffering to this one: `GetUserByEmail: context canceled` What does `context canceled` mean though? It always takes about 65 (definitive more then 60) seconds.
Author
Owner

@ChristopherHX commented on GitHub (Mar 15, 2025):

What does context canceled mean though?

Gitea noticed you closed the http connection (if this was not you cancelling the request then it is the reverse proxy) , then the next cancellable operation returns this error (this error message is a detail of the golang standard library)

5s is the time Gitea took to react to your cancel request + the time any reverse proxy / network etc. took to forward this cancellation.

I have written programs that take more than 5s to finish gracefully.

Normally reverse proxy sent gateway timeout to the client if it times out.

@ChristopherHX commented on GitHub (Mar 15, 2025): > What does `context canceled` mean though? Gitea noticed you closed the http connection (if this was not you cancelling the request then it is the reverse proxy) , then the next cancellable operation returns this error (this error message is a detail of the golang standard library) 5s is the time Gitea took to react to your cancel request + the time any reverse proxy / network etc. took to forward this cancellation. I have written programs that take more than 5s to finish gracefully. Normally reverse proxy sent gateway timeout to the client if it times out.
Author
Owner

@Mik4sa commented on GitHub (Mar 18, 2025):

hmm I actually still think that the problem is somewhere else. But I'm unsure where to check.
I've made a new test on gitea in docker on my local machine. So there is no more a proxy between the client (me) and the gitea host. I still get that error.
Any ideas what else I could check / verify?

@Mik4sa commented on GitHub (Mar 18, 2025): hmm I actually still think that the problem is somewhere else. But I'm unsure where to check. I've made a new test on gitea in docker on my local machine. So there is no more a proxy between the client (me) and the gitea host. I still get that error. Any ideas what else I could check / verify?
Author
Owner

@TheFox0x7 commented on GitHub (Mar 18, 2025):

Wouldn't this fit the issue?
c0b55670dc/modules/private/hook.go (L107-L113)

http client will time out after 60 seconds + some more from old commits if any, which would cancel the server request. I don't have the means to test this theory unfortunately.
@Mik4sa Can you compile gitea from source? If so you can try to adjust the timeout there to 120 seconds for example and see if this changes the result - either it'll fail later, resolve the issue... or I my guess is wrong.

@TheFox0x7 commented on GitHub (Mar 18, 2025): Wouldn't this fit the issue? https://github.com/go-gitea/gitea/blob/c0b55670dc79b18b444837b3c9600a573cecc837/modules/private/hook.go#L107-L113 http client will time out after 60 seconds + some more from old commits if any, which would cancel the server request. I don't have the means to test this theory unfortunately. @Mik4sa Can you compile gitea from source? If so you can try to adjust the timeout there to 120 seconds for example and see if this changes the result - either it'll fail later, resolve the issue... or I my guess is wrong.
Author
Owner

@Mik4sa commented on GitHub (Mar 18, 2025):

@TheFox0x7
Nice, thank you. I'll try this tomorrow. I already searched through the code but didn't found this one. I was looking for it :)

Yes, I can compile and try this one. Did this already for other tests :)

@Mik4sa commented on GitHub (Mar 18, 2025): @TheFox0x7 Nice, thank you. I'll try this tomorrow. I already searched through the code but didn't found this one. I was looking for it :) Yes, I can compile and try this one. Did this already for other tests :)
Author
Owner

@Mik4sa commented on GitHub (Mar 19, 2025):

@TheFox0x7
That was the missing part! Thank you. I changed just that value from 60 to 300 (5 minutes) and after 3 minutes my commits were successfully pushed :)

Is someone of you willing to make the needed changes? I guess the default configured timeouts should / could be used for that too?

@Mik4sa commented on GitHub (Mar 19, 2025): @TheFox0x7 That was the missing part! Thank you. I changed just that value from 60 to 300 (5 minutes) and after 3 minutes my commits were successfully pushed :) Is someone of you willing to make the needed changes? I guess the default configured timeouts should / could be used for that too?
Author
Owner

@TheFox0x7 commented on GitHub (Mar 19, 2025):

It could use the default, or account for amount of incoming commits as well. Or both. I'm not sure what the right fix is for these things.

I'm guessing (haven't looked) that the []NewCommitsIds is the count of incoming commits, so we could modify the timeout to be:

time.Duration(60+len(opts.OldCommitIDs)) * time.Second + len(opts.OldCommitIDs)*100*time.Millisecond)

And replace hardcoded 60 with a git.timeout (or other) setting.

@TheFox0x7 commented on GitHub (Mar 19, 2025): It could use the default, or account for amount of incoming commits as well. Or both. I'm not sure what the right fix is for these things. I'm guessing (haven't looked) that the []NewCommitsIds is the count of incoming commits, so we could modify the timeout to be: ```go time.Duration(60+len(opts.OldCommitIDs)) * time.Second + len(opts.OldCommitIDs)*100*time.Millisecond) ``` And replace hardcoded 60 with a `git.timeout` (or other) setting.
Author
Owner

@Mik4sa commented on GitHub (Mar 20, 2025):

I've just checked opts.OldCommitIDs and opts.NewCommitIDs both have the value 1. So it's not the count of all pushing commits.
I think it's ok to start with the default timeout. We could look what will happen.

@Mik4sa commented on GitHub (Mar 20, 2025): I've just checked `opts.OldCommitIDs` and `opts.NewCommitIDs` both have the value 1. So it's not the count of all pushing commits. I think it's ok to start with the default timeout. We could look what will happen.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: github-starred/gitea#13765