{"action":"created","issue":{"url":"https://api.github.com/repos/golang/go/issues/23479","repository_url":"https://api.github.com/repos/golang/go","labels_url":"https://api.github.com/repos/golang/go/issues/23479/labels{/name}","comments_url":"https://api.github.com/repos/golang/go/issues/23479/comments","events_url":"https://api.github.com/repos/golang/go/issues/23479/events","html_url":"https://github.com/golang/go/issues/23479","id":289788353,"number":23479,"title":"Windows service timeout during system startup   ","user":{"login":"kneden","id":17029374,"avatar_url":"https://avatars0.githubusercontent.com/u/17029374?v=4","gravatar_id":"","url":"https://api.github.com/users/kneden","html_url":"https://github.com/kneden","followers_url":"https://api.github.com/users/kneden/followers","following_url":"https://api.github.com/users/kneden/following{/other_user}","gists_url":"https://api.github.com/users/kneden/gists{/gist_id}","starred_url":"https://api.github.com/users/kneden/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kneden/subscriptions","organizations_url":"https://api.github.com/users/kneden/orgs","repos_url":"https://api.github.com/users/kneden/repos","events_url":"https://api.github.com/users/kneden/events{/privacy}","received_events_url":"https://api.github.com/users/kneden/received_events","type":"User","site_admin":false},"labels":[{"id":373402289,"url":"https://api.github.com/repos/golang/go/labels/NeedsInvestigation","name":"NeedsInvestigation","color":"ededed","default":false},{"id":199753992,"url":"https://api.github.com/repos/golang/go/labels/OS-Windows","name":"OS-Windows","color":"ededed","default":false},{"id":150880243,"url":"https://api.github.com/repos/golang/go/labels/help%20wanted","name":"help wanted","color":"fbca04","default":true}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/golang/go/milestones/62","html_url":"https://github.com/golang/go/milestone/62","labels_url":"https://api.github.com/repos/golang/go/milestones/62/labels","id":2827591,"number":62,"title":"Go1.11","description":"","creator":{"login":"rsc","id":104030,"avatar_url":"https://avatars1.githubusercontent.com/u/104030?v=4","gravatar_id":"","url":"https://api.github.com/users/rsc","html_url":"https://github.com/rsc","followers_url":"https://api.github.com/users/rsc/followers","following_url":"https://api.github.com/users/rsc/following{/other_user}","gists_url":"https://api.github.com/users/rsc/gists{/gist_id}","starred_url":"https://api.github.com/users/rsc/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rsc/subscriptions","organizations_url":"https://api.github.com/users/rsc/orgs","repos_url":"https://api.github.com/users/rsc/repos","events_url":"https://api.github.com/users/rsc/events{/privacy}","received_events_url":"https://api.github.com/users/rsc/received_events","type":"User","site_admin":false},"open_issues":781,"closed_issues":151,"state":"open","created_at":"2017-10-10T13:39:17Z","updated_at":"2018-02-28T18:22:54Z","due_on":"2018-07-31T07:00:00Z","closed_at":null},"comments":16,"created_at":"2018-01-18T21:52:15Z","updated_at":"2018-02-28T18:56:39Z","closed_at":null,"author_association":"NONE","body":"### What version of Go are you using (`go version`)?\r\ngo version go1.9.2 windows/amd64\r\n\r\n### Does this issue reproduce with the latest release?\r\nYes.\r\n\r\n### What operating system and processor architecture are you using (`go env`)?\r\n```\r\nset GOARCH=amd64\r\nset GOBIN=\r\nset GOEXE=.exe\r\nset GOHOSTARCH=amd64\r\nset GOHOSTOS=windows\r\nset GOOS=windows\r\nset GOPATH=C:\\Users\\XXXXX\\d\\go\r\nset GORACE=\r\nset GOROOT=C:\\Go\r\nset GOTOOLDIR=C:\\Go\\pkg\\tool\\windows_amd64\r\nset GCCGO=gccgo\r\nset CC=gcc\r\nset GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\\Users\\XXXXX\\AppData\\Local\\Temp\\go-build933228923=/tmp/go-build -gno-record-gcc-switches\r\nset CXX=g++\r\nset CGO_ENABLED=1\r\nset CGO_CFLAGS=-g -O2\r\nset CGO_CPPFLAGS=\r\nset CGO_CXXFLAGS=-g -O2\r\nset CGO_FFLAGS=-g -O2\r\nset CGO_LDFLAGS=-g -O2\r\nset PKG_CONFIG=pkg-config\r\n```\r\n\r\n### What did you do?\r\n\r\nConfigured our Go language application to start as a Windows Service, with start type of 'Automatic'. The service is expected to start when the system boots up. Sometimes the service process will not be running after the system has booted up and the 'Windows Logs / 'System' logs in Event Viewer show two logs:\r\n\r\n```\r\nEvent ID: 7009\r\nLevel: Error\r\nText:\r\nA timeout was reached (30000 milliseconds) while waiting for the <service name> service to connect.\r\n```\r\n\r\n```\r\nEvent ID: 7000\r\nLevel: Error\r\nText:\r\nThe <service name> service failed to start due to the following error: \r\nThe service did not respond to the start or control request in a timely fashion.\r\n```\r\n\r\nThese events do not appear in the logs when the service successfully starts.\r\n\r\nIt appears that Windows terminates the service process when the service fails to respond to the Windows Service start event within the 30 s time frame. Our application contains the Windows Service code based on the sample code from `sys/windows/svc/example`.\r\n\r\nThis timeout issue occurs both with 64-bit and 32-bit versions of our executable.\r\n\r\n### What did you expect to see?\r\n\r\nThe Go language Windows service start reliably every time the system boots up.\r\n\r\n### What did you see instead?\r\n\r\nThe Go language service does not start reliably on some systems on boot-up.\r\n\r\nSome observations from systems where the service often fails to start during boot-up:\r\n\r\n1. Manually starting the service once the system is up and running has never failed to start correctly. Timestamps from the logs show the process starting quickly (no more than a few seconds).\r\n2. Setting the service's start type to 'Automatic (Delayed Start)', where Windows starts the service 120 s after the 'Automatic' services, works without fail. The user is able to login to the desktop well before the service has been started. It is possible to change this global Windows setting to a lower value (eg 60 s) to make it less noticeable to the user, but because it will affect **all** delayed start services, it is not an acceptable solution. Some search results claim a per-service delay value can be specified, but we were not able to make this work.\r\n3. Changing the 30000 ms (30 s) Windows service timeout value to larger values (60 s or 90 s) allowed the service to startup. However, this is a global Windows setting and it is not possible to set the timeout per-service. Again, this is not an acceptable solution.\r\n4. We experimented with using the Windows Service \"Recovery\" settings to restart our service in an attempt to mitigate this problem. However, it appears that these recovery settings have no effect for services that fail to start in time.\r\n5. We instrumented our service with timestamped logs when the first imported package is initialized and when `main()` starts. We found that `main()` was often not reached when the timeout occurred. Sometimes even the first imported package's initialization was not reached.\r\n6. A stripped-down Windows service that just logged would often fail to start, but it was less likely to happen compared to our full-fledged service.\r\n7. Using a simple C++ Windows Service ([code here](https://code.msdn.microsoft.com/windowsapps/CppWindowsService-cacf4948)) modified to launch our executable (running as a 'normal' application, not as a Windows Service) always launched without fail (no timeouts) during boot-up. Logs within our executable, as well as in the C++ service (just prior to the `CreateProcess()` call that started our executable) often showed large time deltas. The logs indicated it often took a long time for the Go executable to get launched, and also to reach the `main()`.\r\n\r\nWhile we have some systems (VirtualBox VMs) that reliably show these startup problems, the issue is harder to reproduce on other systems. We have VirtualBox VMs where the problem occurs only occasionally and we have yet to see the timeout occur on non-virtual Windows 10 installations. Timestamp-instrumented loads on those systems sometimes show time deltas of up to 10 s during startup. While this is not long enough to trigger the 30 s timeout on a powerful real system, the concern is that in virtualized environments and/or slower systems the timeout will be reached and the service will not start.\r\n\r\n### Sample Programs\r\n\r\nSample code can be found in [this GitHub repository](https://github.com/Openera/winserv), including instructions for building and installing (README.md).\r\n\r\nBoth the `launchserv.exe` and `winserv.exe` programs contain the Go Windows Service code (again, based one the sample code). The Go Windows Service sample code was combined into a single file in both cases in order to 'flatten' the main package for tracking imported package initialization.\r\n\r\nIt is intended that only one of the two should run as a Windows Service. The recommended configuration is to install `launchserv.exe` as a Windows Service (\"my service\"), and it will in turn launch `winserv.exe` as a child process (`winserv.exe` will run as a 'normal' program, not a service). `launchserv.exe` writes a timestamped log just prior to starting `winserv.exe`, which allows measuring the time it takes for `winserv.exe` to start.\r\n\r\n`winserv.exe` contains a large number of standard package imports, to mimic a real program. These imports are marked as 'unused' and as such only their initializations run (variable initialization and `init()`).\r\n\r\nThe VirtualBox version of the Win10 MSEdge test VM can be downloaded from Microsoft [here](https://developer.microsoft.com/en-us/microsoft-edge/tools/vms/) to run these test programs. The following changes may help to increase the likelihood of seeing the issue with this, or other systems:\r\n\r\n* Increase the number of CPU cores from 1 (to say 2 or 4). This might increase the concurrent activity when the system is starting up.\r\n* Install the Guest Additions.\r\n* Install other software that starts services when the system boots. For example, one VM that shows the issue very reliably has two VNC server packages, OpenVPN client and an SSL VPN client (Array Networks) (as well as other software) installed. \r\n\r\nMultiple boot-ups of the system may be required to see the problem. In many cases, a VM may sometimes demonstrate the problem, but then not do so at other times. YMMV.\r\n\r\nWhen delays are seen, the two most common places are:\r\n\r\n1. Launching `winserv.exe`; that is, between the last `launchserv.exe` log and the first `winserv.exe` log. Time deltas as high as 26 s have been seen (and as low as less than 400 ms) have been seen on an Win10/MSEdge VM.\r\n2. The 'lots of imports' in `winserv.exe` `main.go`, between the 'b' and 'c' logs. These are the large number of unused standard package imports. Times as high as 9 s (and less than 100 ms on the low end) have been seen on the same Win10/MSEdge VM.\r\n\r\nThis service is an important component of our product; we are adding more functionality all the time. As the amount of code increases, it seems even more likely that this problem will occur. If there is anything else we can do to help resolve this issue (experiments, measurements, debugging, etc), please let us know."},"comment":{"url":"https://api.github.com/repos/golang/go/issues/comments/369344573","html_url":"https://github.com/golang/go/issues/23479#issuecomment-369344573","issue_url":"https://api.github.com/repos/golang/go/issues/23479","id":369344573,"user":{"login":"kneden","id":17029374,"avatar_url":"https://avatars0.githubusercontent.com/u/17029374?v=4","gravatar_id":"","url":"https://api.github.com/users/kneden","html_url":"https://github.com/kneden","followers_url":"https://api.github.com/users/kneden/followers","following_url":"https://api.github.com/users/kneden/following{/other_user}","gists_url":"https://api.github.com/users/kneden/gists{/gist_id}","starred_url":"https://api.github.com/users/kneden/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kneden/subscriptions","organizations_url":"https://api.github.com/users/kneden/orgs","repos_url":"https://api.github.com/users/kneden/repos","events_url":"https://api.github.com/users/kneden/events{/privacy}","received_events_url":"https://api.github.com/users/kneden/received_events","type":"User","site_admin":false},"created_at":"2018-02-28T18:56:39Z","updated_at":"2018-02-28T18:56:39Z","author_association":"NONE","body":"I assume 'debug' and 'release' refer to with and without debug symbols (`go build -ldflags \"-s -w\"` for the latter). If that is the case, then all Go binaries I was building were with debug symbols.\r\n\r\nI rebuilt our application with those link flags, which resulted in a Windows executable that was about 1/3 smaller. However, it behaved the same as before, timing out when starting as a normal Windows service at boot-up."}}
{"actor":{"display_login":"kneden"}}