search

go-gitea / gitea

Git with a cup of tea! Painless self-hosted all-in-one software development service, including Git hosting, code review, team collaboration, package registry and CI/CD
https://gitea.com
MIT License
44.08k stars 5.41k forks source link

pre-receive takes a long time to finish on push #28446

Open PulsarFX opened 9 months ago

PulsarFX commented 9 months ago

Description

This is a windows service setup with gitea-1.21.1-gogit-windows-4.0-amd64

I've been tracing an issue with very long times for push to finish. It took ~12s on each try, although the changes are very small. The repo is very small, too. (All times in this description are measured from client side)

After lots of digging I am down to this essence:

I changed app.ini to

collected from from https://docs.gitea.com/installation/windows-service and #22370

I also changed the service account from the default "local system" to "network service" and back to "local system" with interactive enabled, but it doesn't fix it. When I start gitea from cli, no 12,x seconds can be seen. Then it's constantly at around 1 second.

My question is: what does this process do or wait for: C:\gitea\gitea-1.21.1-gogit-windows-4.0-amd64.exe hook --config=C:\gitea\custom\conf\app.ini pre-receive is there a way to have it log its actions? A trace log from gitea with a slow push is at the gist address.

I am happy that I am down from 12-20seconds push times, just by using the right user name. I would even be more happy, to get rid of the spikes because of the pre-receive process. ;-)

Gitea Version

1.21.1-gogit-windows-4.0-amd64

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

https://gist.github.com/PulsarFX/be9133b81c2c6d0db3a3c902b441edf1

Screenshots

This screenshot shows the git processes started by gitea, and the env.exe which starts the gitea exe again, via the pre-receive-hook scripts: grafik

Git Version

2.43.0, Wire Protocol Version 2 Enabled

Operating System

win10

How are you running Gitea?

installed via nssm.exe as windows service

Database

SQLite

lunny commented 9 months ago

I can find two slow log.

2023/12/12 20:06:32 ...eb/routing/logger.go:68:func1() [W] router: slow      POST /taggerei/taggerei.git/git-receive-pack for [::1]:61556, elapsed 3698.7ms @ repo/githttp.go:500(repo.ServiceReceivePack)

and

2023/12/12 20:06:39 ...dules/git/command.go:345:Run() [D] slow git.Command.Run: "C:\\Program Files\\Git\\cmd\\git.exe" -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= receive-pack --stateless-rpc C:\gitea\data\gitea-repositories\taggerei\taggerei.git (9.7827557s)
PulsarFX commented 9 months ago

I think this is the birds eye view. The client is sitting and waiting for the server to return. All data has already been transfered. In GitExtensions this looks like this: First, the transfer is done and the cursor keeps on blinking for many seconds: grafik

Then, finally it looks like this: grafik

On our .net client the log looks like this:

2023-12-13 09:20:38.1418 [  3]  INFO  GitService: Push Start for repo .\\taggerei\sources\(xycv) -> http://localhost:3000/taggerei/taggerei.git(refs/heads/xycv) 
2023-12-13 09:20:38.2320 [  3] DEBUG  GitService: git push: 0 of 6 objects sent to server. 12 bytes sent to the server. (Elapsed: 00:00:00.0880108) 
2023-12-13 09:20:50.3128 [  3] DEBUG  GitService: git push: 6 of 6 objects sent to server. 1216 bytes sent to the server. (Elapsed: 00:00:12.1687881) 
2023-12-13 09:20:50.3638 [  3]  INFO  GitService: Push Finished for repo .\\taggerei\sources\ (Elapsed: 00:00:12.2197249)

From all the tests I've done so far, it looks like the delay comes from the pre-receive hook, when gitea starts itself again (shown in the first screenshot). Is there a way to see what is happening in there? Or can I disable hooks alltogether? My guess is, that it's a kind of timeout because of user restrictions, when gitea is run as windows service.

For reference, a perfect run looks like this:

2023-12-13 09:39:27.7926 [  6]  INFO  GitService: Push Start for repo .\\taggerei\sources\(xycv) -> http://localhost:3000/taggerei/taggerei.git(refs/heads/xycv) 
2023-12-13 09:39:27.8610 [  6] DEBUG  GitService: git push: 0 of 6 objects sent to server. 12 bytes sent to the server. (Elapsed: 00:00:00.0663798) 
2023-12-13 09:39:28.4928 [  6] DEBUG  GitService: git push: 6 of 6 objects sent to server. 1218 bytes sent to the server. (Elapsed: 00:00:00.6982429) 
2023-12-13 09:39:28.5437 [  6]  INFO  GitService: Push Finished for repo .\\taggerei\sources\ (Elapsed: 00:00:00.7490811)

In this scenario, the second gitea.exe shows up only fractions of time in ProcessExplorer or it's even to short to show up in the list at all.

I don't think the RUN_USER has any affect on this issue. Today it was 12s again when the service runs as Local System. When I use my account instead to start the windows service, it's 0,7s every time on each client. Then also my user is executing the pre-receive: C:\gitea\gitea-1.21.1-gogit-windows-4.0-amd64.exe hook --config=C:\gitea\custom\conf\app.ini pre-receive

PulsarFX commented 8 months ago

Is no one else experiencing this behaviour on a windows service? I found 2 or more tickets where problems with the windows service existed ( #15454 and #19053) Currently I am running gitea with my user account, but this can't be the solution for this.

lunny commented 8 months ago

Do you have real pre-receive scripts in those repositories?

PulsarFX commented 8 months ago

No, these are naked hook repos

PulsarFX commented 8 months ago

Is there something I can help with to investigate? I just discovered, that using my domain user to run the service has a strong drawback: Windows can only run/start the service, if I am connected to our company vpn.

lunny commented 8 months ago

Take a look at the logs again, it should not be related with Gitea's pre-receive hook handle. The consuming time is under the git command 

2023/12/12 20:06:29 ...s/process/manager.go:188:Add() [T] Start 6578af35-11: C:\Program Files\Git\cmd\git.exe receive-pack --stateless-rpc [repo_path: C:\gitea\data\gitea-repositories\taggerei\taggerei.git] (from 6578af35-10) (normal)

and before Gitea's pre-receive invoked.

2023/12/12 20:06:29 ...s/process/manager.go:188:Add() [T] Start 6578af35-11: C:\Program Files\Git\cmd\git.exe receive-pack --stateless-rpc [repo_path: C:\gitea\data\gitea-repositories\taggerei\taggerei.git] (from 6578af35-10) (normal)
2023/12/12 20:06:32 ...eb/routing/logger.go:68:func1() [W] router: slow      POST /taggerei/taggerei.git/git-receive-pack for [::1]:61556, elapsed 3698.7ms @ repo/githttp.go:500(repo.ServiceReceivePack)
2023/12/12 20:06:38 ...s/process/manager.go:188:Add() [T] Start 6578af3e: POST: /api/internal/hook/pre-receive/taggerei/taggerei (request)
PulsarFX commented 8 months ago

Which log do you mean? Is there another log, except what is set in app.ini?

[log]
ROOT_PATH = C:/gitea/log
LEVEL = warn
MODE = tofile

[log.tofile]
MODE = file
FILE_NAME = file.log

To recap: gitea runs absoluteley fine, when I start it from CLI. It bogs, when it runs as windows service with the default local system user. For me this is screaming: "access rights problem".

In ...\hooks\pre-receive.d there is one file called gitea with this content:

#!/usr/bin/env bash
# AUTO GENERATED BY GITEA, DO NOT MODIFY
C:/gitea/gitea-1.21.1-gogit-windows-4.0-amd64.exe hook --config="C:\\gitea\\custom\\conf\\app.ini" pre-receive

This is the same call as I can see in ProcessExplorer sitting around, when it bogs. I just switched to the system account and it bogs right away on the first try. Then I removed the gitea file from the pre-receive.d folder. After this, it is this process sitting and waiting:

C:\gitea\gitea-1.21.1-gogit-windows-4.0-amd64.exe hook --config=C:\gitea\custom\conf\app.ini update refs/heads/jhgfd ffc906fe49bcefb59ad2125e4323c4f9a9685aa4 11a1df8d52e436e15b412538089fba0fe55424f8

Then I tried disabling all network connections. This doesn't have a clear effect.