The service did not respond to the start or control request in a timely fashion #15159

markburgessstl · 2021-03-25T17:42:50Z

Gitea version: 1.14.0-rc2 (gitea-1.14.0-rc2-windows-4.0-amd64.exe download)
Git version: 2.7
Operating system: Windows Server 2008 R2
Database: SQLite

Gitea does not start up when running as a Windows service. "The service did not respond to the start or control request in a timely fashion" . I have set the registry option ServicesPipeTimeout to 240000 which is 4 minutes. The gitea.exe process can be seen in the task manager, but it eventually dies.

Running gitea web, it starts up just fine.
Version 1.13.6 starts up fine as a service on the same machine.

gitea.log.txt
app.ini.txt

JulianOrteil · 2021-03-25T18:59:17Z

To avoid duplicating issues, I will append to this ticket.

A coworker and I are also encountering this same issue in pretty much the exact same manner as @markburgessstl here and #15134. We attempted to follow the recommended "gitea migrate" commandlet metioned in #15134 but to no avail.

Log:

2021/03/25 12:35:54 ...dules/setting/log.go:333:newLogService() [I] Gitea Log Mode: File(File:debug)
2021/03/25 12:35:54 ...dules/setting/log.go:250:generateNamedLogger() [I] Router Log: Console(console:debug)
2021/03/25 12:35:54 ...les/setting/cache.go:73:newCacheService() [I] Cache Service Enabled
2021/03/25 12:35:54 ...les/setting/cache.go:88:newCacheService() [I] Last Commit Cache Service Enabled
2021/03/25 12:35:54 ...s/setting/session.go:77:newSessionService() [I] Session Service Enabled
2021/03/25 12:35:54 ...es/setting/mailer.go:109:newMailService() [I] Mail Service Enabled
2021/03/25 12:35:54 ...es/setting/mailer.go:131:newNotifyMailService() [I] Notify Mail Service Enabled
2021/03/25 12:35:54 ...s/storage/storage.go:151:initAttachments() [I] Initialising Attachment storage with type: 
2021/03/25 12:35:54 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at C:\Gitea\data\attachments
2021/03/25 12:35:54 ...s/storage/storage.go:145:initAvatars() [I] Initialising Avatar storage with type: 
2021/03/25 12:35:54 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at C:\Gitea\data\avatars
2021/03/25 12:35:54 ...s/storage/storage.go:163:initRepoAvatars() [I] Initialising Repository Avatar storage with type: 
2021/03/25 12:35:54 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at C:\Gitea\data\repo-avatars
2021/03/25 12:35:54 ...s/storage/storage.go:157:initLFS() [I] Initialising LFS storage with type: 
2021/03/25 12:35:54 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at C:/Gitea/data/lfs
2021/03/25 12:35:54 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: push_update Starting
2021/03/25 12:35:54 ...ue/queue_bytefifo.go:96:Run() [D] level: push_update-level Starting
2021/03/25 12:35:54 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: mail Starting
2021/03/25 12:35:54 ...ue/queue_bytefifo.go:96:Run() [D] level: mail-level Starting
2021/03/25 12:35:54 routers/init.go:150:GlobalInit() [I] SQLite3 Supported
2021/03/25 12:35:54 routers/init.go:68:initDBEngine() [I] Beginning ORM engine initialization.
2021/03/25 12:35:54 routers/init.go:75:initDBEngine() [I] ORM engine initialization attempt #1/10...
2021/03/25 12:35:54 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: notification-service Starting
2021/03/25 12:35:54 ...rm/session_schema.go:25:Ping() [I] PING DATABASE postgres
2021/03/25 12:35:54 ...ue/queue_bytefifo.go:96:Run() [D] level: notification-service-level Starting
2021/03/25 12:35:55 ...rm/session_schema.go:360:Sync2() [W] Table user Column max_repo_creation db default is '-1', struct default is -1
2021/03/25 12:35:56 ...rm/session_schema.go:431:Sync2() [W] Table session has column created_unix but struct has not related field
2021/03/25 12:35:56 routers/init.go:155:GlobalInit() [I] ORM engine initialization successful!
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: update_mirrors
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: repo_health_check
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: check_repo_stats
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: archive_cleanup
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: sync_external_users
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: deleted_branches_cleanup
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: update_migration_poster_id
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: cleanup_hook_task_table
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_inactive_accounts
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_repo_archives
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: git_gc_repos
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_sshkeys
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_sshprincipals
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_hooks
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: reinit_missing_repos
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_missing_repos
2021/03/25 12:35:56 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_generated_repository_avatars
2021/03/25 12:35:56 ...i/websspi_windows.go:87:New() [I] Credential handle expiry: 2185-07-20 12:34:33.712009116 -0600 CST
2021/03/25 12:35:56 ...er/issues/indexer.go:142:func2() [I] PID 764: Initializing Issue Indexer: bleve
2021/03/25 12:35:56 ...er/issues/indexer.go:221:func3() [I] Issue Indexer Initialization took 109.3727ms
2021/03/25 12:35:56 ...xer/stats/indexer.go:84:populateRepoIndexer() [I] Done (re)populating the repo stats indexer with existing repositories
2021/03/25 12:35:56 ...ue/queue_bytefifo.go:96:Run() [D] level: issue_indexer Starting
2021/03/25 12:35:56 ...ue/queue_bytefifo.go:96:Run() [D] unique-level: repo_stats_update-level Starting
2021/03/25 12:35:56 ...ue/queue_bytefifo.go:96:Run() [D] unique-level: pr_patch_checker-level Starting
2021/03/25 12:35:56 ...ue/queue_bytefifo.go:96:Run() [D] level: task-level Starting
2021/03/25 12:35:57 cmd/web.go:189:listen() [I] Listen: http://0.0.0.0:3000
2021/03/25 12:35:57 cmd/web.go:192:listen() [I] LFS server enabled
2021/03/25 12:35:57 ...s/graceful/server.go:55:NewServer() [I] Starting new Web server: tcp:0.0.0.0:3000 on PID: 764
2021/03/25 12:35:57 ...s/graceful/server.go:66:func1() [D] Starting server on tcp:0.0.0.0:3000 (PID: 764)

This is running on a Windows Server 2016 machine. We are trying to fix our original problem see in #14167.

zeripath · 2021-03-25T20:35:50Z

hmm... This is very strange... just testing on linux here I can't see a reason why the SVC manager isn't being informed of a successful startup correctly.

I guess it might be reasonable to set:

[server]
...
STARTUP_TIMEOUT=30s

and see if that improves things - but it doesn't look like there is a significant delay in the startup so it may simply delay the problem for 30 seconds.

Are you able to compile gitea? If so it may be reasonable to add some logging in to the SVC handler.

markburgessstl · 2021-03-25T20:56:17Z

hmm... This is very strange... just testing on linux here I can't see a reason why the SVC manager isn't being informed of a successful startup correctly.

I guess it might be reasonable to set:
[server]
...
STARTUP_TIMEOUT=30s
and see if that improves things - but it doesn't look like there is a significant delay in the startup so it may simply delay the problem for 30 seconds.

Are you able to compile gitea? If so it may be reasonable to add some logging in to the SVC handler.

I tried the STARTUP_TIMEOUT but it didn't make any difference.
Unfortunately I can't compile Gitea on Windows

zeripath · 2021-03-25T21:48:14Z

Fine:

https://eldritchkitty.com/~andrew/gitea-915748a93-windows-4.0-amd64.exe

Is a build of:

https://github.com/go-gitea/gitea/compare/release/v1.14...zeripath:logging-for-15159?expand=1

Using:

make release-windows

It should match the detached signature:

https://eldritchkitty.com/~andrew/gitea-915748a93-windows-4.0-amd64.exe.asc

which I will copy below:

Which is signed by my gpg key attached this account (and elsewhere) and can be obtained from:

https://github.com/zeripath.gpg

If you do not wish to check the signature. The file should have the sha256sum:

63f24650b75a9ef8365c5d238b663d5551fe10b053b765b476ca1e557fb0a44d

JulianOrteil · 2021-03-26T02:10:53Z

Fine:

https://eldritchkitty.com/~andrew/gitea-915748a93-windows-4.0-amd64.exe

Is a build of:

https://github.com/go-gitea/gitea/compare/release/v1.14...zeripath:logging-for-15159?expand=1

Using:

make release-windows

It should match the detached signature:

https://eldritchkitty.com/~andrew/gitea-915748a93-windows-4.0-amd64.exe.asc

which I will copy below:
-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEE0s922pXyAemQFTKrPN50Yx8Tp0gFAmBdAwIACgkQPN50Yx8T
p0jOgRAAgqoYelsheDd+J7xSv7x6yU9V3SRjl1x6c5GEIDb3xD4c+JroWVXUjSHx
mF34Wt6+rWZVopSmja6J8juE4VgDgwwcisaEBiq0JkXFaZIMgZKtr6TM95hmwcCZ
7rd2pBcg0JxMPcSRKaN0EJ2IswKZtru7kV+FtdxGK2SnmcG6fsAggL+9CedTMlgI
4nHVnWaXzLQNrE/w36hhF65QmLQDTzUla7DXWb8SKEhX9cEGo1ON4gIvk29nSK/e
2GvWYMZU+T3p/q7EDQXLa5NghBdt+L56bfPEkYTA2cJhCu7Z65EHfr9ylENcDDAB
PjCK7OUf/oZwhOd3Ty0ovYctOaKEcFMWe1TlaSHYT45XixNpYbIVOZNXPsvvt3HY
HNcf8Cqqn8sxCkkOCpGRrs9HS+COT52kTYHrCy8eqVR79QBvbNlbPueh/MAKY4Cg
7kebShNfXmsDH2d/2Ni+nsW61JOT8Dg+gK8gweXPJCKcjOIA2LT2uB5Fr3SyREgF
WknzJjD4EyiTegqo9IphtKGoGx83HUUkvHqZJ+oPYjP8jeXYlTxkOn6MHEx+6nMD
GEISrSx2uuIBfV67dVVRFgvC2fdFxlgh+OB4YmZQ2mIA1Ebl/O+89Fga0tK/8t6m
CMDzoO6rmmY5a1HnRmpe8a+KHViLK8J+P92SH99nhOTqE5NENcQ=
=e9GE
-----END PGP SIGNATURE-----
Which is signed by my gpg key attached this account (and elsewhere) and can be obtained from:

https://github.com/zeripath.gpg

If you do not wish to check the signature. The file should have the sha256sum:
63f24650b75a9ef8365c5d238b663d5551fe10b053b765b476ca1e557fb0a44d

Awesome, thanks for the work. We will try this tomorrow morning and give you feedback (and logs) on what happens if there is no change.

markburgessstl · 2021-03-26T09:42:19Z

zeripath, thank you for the special build. I ran it this morning, and as expected it timed out after a few minutes. The log is attached.
gitea.log.txt

JulianOrteil · 2021-03-26T14:04:44Z

Our log as well:

gitea.log

zeripath · 2021-03-26T23:27:10Z

I can't see any log line saying starting SVC handler there and there should be 4 inform cleanups called but it looks like there's only two.

This is weird and I am suspicious that something has unhitched this functionality - which is great because I don't completely remember how I got it wired in in the first place and I can't test it myself.

JulianOrteil · 2021-03-29T13:12:11Z

Ok, no worries. For now, I can just start Gitea manually if needed since it runs fine from the command line (just not as a service). Let me know if you, or any other contributor/maintainer needs any more details from my side.

zeripath · 2021-03-29T21:31:32Z

OK

lets try:

https://eldritchkitty.com/~andrew/gitea-e5e9c67a03f4-windows-4.0-amd64.exe

sha256sum:

fd9042e5b0359e742020ab4e70d2facd4b0c9169aaa479b70965693c6c49fd5c  gitea-e5e9c67a03f4-windows-4.0-amd64.exe

This adds some more logging

markburgessstl · 2021-03-29T23:01:05Z

gitea.log

Here's my log. I tried three times to start the service.

Windows thinks the service is "starting" or "START_PENDING"

Thank you!

zeripath · 2021-03-30T00:10:34Z

Please could you set LOG_SQL=false in the [database] section of your app.ini . Logging SQL statements is way too noisy and irrelevant to this problem.

This time it looks like we're getting the inform cleanups but I'm not seeing the new logging statements I put in.

In particular I should see something like Graceful manager starting up logged at error level.

zeripath · 2021-03-30T00:14:03Z

But...

I do see this:

2021/03/29 17:33:30 ...l/manager_windows.go:109:Execute() [I] sending running status
2021/03/29 17:33:30 ...l/manager_windows.go:117:Execute() [I] sent running status

That means that gitea does think it's telling the SVC host it's running.

markburgessstl · 2021-03-30T11:12:47Z

Yes, it thinks that but that's not happening.
Let me know if you need more logs or anything else to help get to the bottom of it

JulianOrteil · 2021-03-30T15:43:21Z

@zeripath Here is our log file. We also had no luck with this exe, but thank you again for your work in helping solve this!

We are running Gitea on a Windows Server 2016 machine, just as a reminder.
gitea.log

JulianOrteil · 2021-03-30T15:45:50Z

My apologies, Windows Server 2019*.

zeripath · 2021-03-30T17:01:01Z

agh! I think I've found the issue!

zeripath · 2021-03-30T17:03:37Z

gitea/modules/graceful/manager_windows.go

Lines 76 to 81 in f5b6dc9

    
           isInteractive, err := svc.IsWindowsService() 
        
           if err != nil { 
        
           	log.Error("Unable to ascertain if running as an Interactive Session: %v", err) 
        
           	return 
        
           } 
        
           if isInteractive {

The IsInteractive should be IsWindowsService and should therefore be on line 81 !isInteractive

zeripath · 2021-03-30T17:04:30Z

This is a regression from #14263

…teractive sessions Unfortunately go-gitea#14623 changed from the deprecated IsInteractiveSession to IsWindowsService without recognising that they are the complement of each other. This means that Windows SVC control is not working correctly. This PR adds some Tracing statements but also fixes the bug. Fix go-gitea#15159 Signed-off-by: Andrew Thornton <art27@cantab.net>

…teractive sessions (go-gitea#15210) Backport go-gitea#15210 Unfortunately go-gitea#14623 changed from the deprecated IsInteractiveSession to IsWindowsService without recognising that they are the complement of each other. This means that Windows SVC control is not working correctly. This PR adds some Tracing statements but also fixes the bug. Fix go-gitea#15159 Signed-off-by: Andrew Thornton <art27@cantab.net>

JulianOrteil · 2021-03-30T18:50:24Z

Excellent work, thank you very much for the PR!

To prevent this issue in the future, could we add a test to ensure the server will run as a service? I'm not a Go developer nor do I know your/the team's environment, so I don't know how feasible this would be. I know Github has Actions, so could it be done there?

zeripath · 2021-03-30T21:38:50Z

We don't run tests on Windows - Windows isn't free - and I'm not certain of how we would test this reliably as in almost all testing scenarios you wouldn't actually have the thing attach to the SVC host anyway.

The particular bug is unlikely to be replicated in any case.

All I can say is that we need people to test the RCs like you have done, bear with us if we find problems, and help us with logging etc. This isn't that different from any other debugging situation.

JulianOrteil · 2021-03-31T15:31:16Z

Understandable.

I looked more into GitHub Actions as I was going to counter with that, but it doesn't yet allow services on Windows nor MacOS, only Linux. Regardless, thought I'd give it a shot!

Thanks for the clarification.

…e sessions (#15210) Unfortunately #14623 changed from the deprecated IsInteractiveSession to IsWindowsService without recognising that they are the complement of each other. This means that Windows SVC control is not working correctly. This PR adds some Tracing statements but also fixes the bug. Fix #15159 Signed-off-by: Andrew Thornton <art27@cantab.net> Co-authored-by: techknowlogick <techknowlogick@gitea.io>

…e sessions (#15210) (#15211) Backport #15210 Unfortunately #14623 changed from the deprecated IsInteractiveSession to IsWindowsService without recognising that they are the complement of each other. This means that Windows SVC control is not working correctly. This PR adds some Tracing statements but also fixes the bug. Fix #15159 Signed-off-by: Andrew Thornton <art27@cantab.net>

JulianOrteil · 2021-03-31T20:24:53Z

Hey, since this is now closed, can @markburgessstl and I get a built exe with these changes just to cover us until the official release? Thanks.

jolheiser · 2021-03-31T20:27:01Z

Once the build is done, it should be available (for 1.14) at https://dl.gitea.io/gitea/1.14

…teractive sessions (go-gitea#15210) Unfortunately go-gitea#14623 changed from the deprecated IsInteractiveSession to IsWindowsService without recognising that they are the complement of each other. This means that Windows SVC control is not working correctly. This PR adds some Tracing statements but also fixes the bug. Fix go-gitea#15159 Signed-off-by: Andrew Thornton <art27@cantab.net> Co-authored-by: techknowlogick <techknowlogick@gitea.io>

zeripath mentioned this issue Mar 30, 2021

Fix regression from #14623 - use debug SVC handler only on interactive sessions #15210

Merged

zeripath mentioned this issue Mar 30, 2021

Fix regression from #14623 - use debug SVC handler only on interactive sessions (#15210) #15211

Merged

lafriks closed this as completed in #15210 Mar 31, 2021

go-gitea locked and limited conversation to collaborators May 13, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

The service did not respond to the start or control request in a timely fashion #15159

The service did not respond to the start or control request in a timely fashion #15159

markburgessstl commented Mar 25, 2021

JulianOrteil commented Mar 25, 2021

zeripath commented Mar 25, 2021

markburgessstl commented Mar 25, 2021

zeripath commented Mar 25, 2021

JulianOrteil commented Mar 26, 2021

markburgessstl commented Mar 26, 2021

JulianOrteil commented Mar 26, 2021

zeripath commented Mar 26, 2021

JulianOrteil commented Mar 29, 2021

zeripath commented Mar 29, 2021

markburgessstl commented Mar 29, 2021 •

edited

Loading

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

markburgessstl commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

zeripath commented Mar 30, 2021

JulianOrteil commented Mar 31, 2021

JulianOrteil commented Mar 31, 2021

jolheiser commented Mar 31, 2021

The service did not respond to the start or control request in a timely fashion #15159

The service did not respond to the start or control request in a timely fashion #15159

Comments

markburgessstl commented Mar 25, 2021

JulianOrteil commented Mar 25, 2021

zeripath commented Mar 25, 2021

markburgessstl commented Mar 25, 2021

zeripath commented Mar 25, 2021

JulianOrteil commented Mar 26, 2021

markburgessstl commented Mar 26, 2021

JulianOrteil commented Mar 26, 2021

zeripath commented Mar 26, 2021

JulianOrteil commented Mar 29, 2021

zeripath commented Mar 29, 2021

markburgessstl commented Mar 29, 2021 • edited Loading

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

markburgessstl commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

zeripath commented Mar 30, 2021

JulianOrteil commented Mar 30, 2021

zeripath commented Mar 30, 2021

JulianOrteil commented Mar 31, 2021

JulianOrteil commented Mar 31, 2021

jolheiser commented Mar 31, 2021

markburgessstl commented Mar 29, 2021 •

edited

Loading