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

syscall: Windows WriteConsole syscall hangs indefinitely #34929

Closed
alankm opened this issue Oct 16, 2019 · 3 comments
Closed

syscall: Windows WriteConsole syscall hangs indefinitely #34929

alankm opened this issue Oct 16, 2019 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows

Comments

@alankm
Copy link

alankm commented Oct 16, 2019

What version of Go are you using (go version)?

$ go version
go version go1.13.1 windows/amd64

Does this issue reproduce with the latest release?

I'm not sure. I'm having a hard time reproducing the error from the very same binary...

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Dev\AppData\Local\go-build
set GOENV=C:\Users\Dev\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\Dev\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\Dev\AppData\Local\Temp\go-build288488298=/tmp/go-build -gno-record-gcc-switches

What did you do?

Attempted to print something to the console, running an application in PowerShell.

After nothing happened for a while, I used "ctrl+c" to try and kill the process. This program has signal handlers to gracefully handle SIGINT. The program responded instantly to the SIGINT, and happily printed some log lines to the console during this logic.

What did you expect to see?

My logs, printed to the console without issue, in a timely manner.

What did you see instead?

I cannot say for sure if the SIGINT somehow un-froze the logic or if the frozen thread stayed frozen forever. However, my program coincidentally happens to include logic designed to detect potential deadlocks. After the SIGINT this detection logic printed stack traces of goroutines that hadn't returned in a timely manner.

Here is part of the stack trace that I believe is relevant:

Here is what goroutine 1814 is doing now
goroutine 1814 [syscall, 5 minutes, locked to thread]:
syscall.Syscall6(0x7ffec3bb5360, 0x5, 0x58, 0xc000614ee4, 0x1, 0xc0005f6650, 0x0, 0x0, 0x0, 0x0, ...)
        c:/go/src/runtime/syscall_windows.go:197 +0xfa
syscall.WriteConsole(0x58, 0xc000614ee4, 0x1, 0xc0005f6650, 0x0, 0x1, 0x0)
        c:/go/src/syscall/zsyscall_windows.go:1298 +0xb6
internal/poll.(*FD).writeConsole(0xc000032500, 0xc000614ee0, 0x1, 0x1, 0x52, 0x0, 0x1)
        c:/go/src/internal/poll/fd_windows.go:769 +0x2f6
internal/poll.(*FD).Write(0xc000032500, 0xc000614ee0, 0x1, 0x1, 0x0, 0x0, 0x0)
        c:/go/src/internal/poll/fd_windows.go:704 +0x1da
os.(*File).write(...)
        c:/go/src/os/file_windows.go:230
os.(*File).Write(0xc000006018, 0xc000614ee0, 0x1, 0x1, 0x1, 0x0, 0x23bc520)
        c:/go/src/os/file.go:153 +0x78
github.com/mattn/go-colorable.(*Writer).Write(0xc0000be0f0, 0xc000210a80, 0x36, 0x40, 0x40, 0x60, 0xc0005f6f08)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/mattn/go-colorable@v0.1.2/colorable_windows.go:443 +0x2e30

I do not know what could cause this syscall to stall for 5 minutes. I find it hard to believe that it has anything to do with Go, but I haven't had any success searching for an answer in the Windows syscall man pages.
@mattn
Copy link
Member

mattn commented Oct 16, 2019

Can you provide whole part of stacktrace? Can you reproduce always?

@alankm
Copy link
Author

alankm commented Oct 16, 2019 •
edited

I have never been able to reproduce it.

Here is more of the stack trace, but I don't imagine it can possibly help you any further.

goroutine 1814 [syscall, 5 minutes, locked to thread]:
syscall.Syscall6(0x7ffec3bb5360, 0x5, 0x58, 0xc000614ee4, 0x1, 0xc0005f6650, 0x0, 0x0, 0x0, 0x0, ...)
        c:/go/src/runtime/syscall_windows.go:197 +0xfa
syscall.WriteConsole(0x58, 0xc000614ee4, 0x1, 0xc0005f6650, 0x0, 0x1, 0x0)
        c:/go/src/syscall/zsyscall_windows.go:1298 +0xb6
internal/poll.(*FD).writeConsole(0xc000032500, 0xc000614ee0, 0x1, 0x1, 0x52, 0x0, 0x1)
        c:/go/src/internal/poll/fd_windows.go:769 +0x2f6
internal/poll.(*FD).Write(0xc000032500, 0xc000614ee0, 0x1, 0x1, 0x0, 0x0, 0x0)
        c:/go/src/internal/poll/fd_windows.go:704 +0x1da
os.(*File).write(...)
        c:/go/src/os/file_windows.go:230
os.(*File).Write(0xc000006018, 0xc000614ee0, 0x1, 0x1, 0x1, 0x0, 0x23bc520)
        c:/go/src/os/file.go:153 +0x78
github.com/mattn/go-colorable.(*Writer).Write(0xc0000be0f0, 0xc000210a80, 0x36, 0x40, 0x40, 0x60, 0xc0005f6f08)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/mattn/go-colorable@v0.1.2/colorable_windows.go:443 +0x2e30
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.StreamHandler.func1(0xc000085a00, 0x56, 0xc0005f6f30)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:43 +0x88
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc000098f00, 0xc000085a00, 0x77aa87, 0x20eddf8)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.SyncHandler.func1(0xc000085a00, 0x0, 0x0)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:57 +0xb1
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc000004860, 0xc000085a00, 0x77aa87, 0xc000085a00)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.LazyHandler.func1(0xc000085a00, 0x1e38d60, 0xc000154030)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:293 +0x33f
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc000004880, 0xc000085a00, 0x77aa87, 0xc000085a00)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.(*swapHandler).Log(0xc00006cd30, 0xc000085a00, 0x0, 0x0)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler_go14.go:14 +0x7e
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.MultiHandler.func1(0xc000085a00, 0x772696, 0x2030000)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:204 +0x6e
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc00050f380, 0xc000085a00, 0x326d7c2, 0x49)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.FilterHandler.func1(0xc000085a00, 0xd0, 0xc8)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:145 +0x71
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc00050f3a0, 0xc000085a00, 0xc8, 0xc000085a00)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.FilterHandler.func1(0xc000085a00, 0x173f5ca, 0x322ed08)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:145 +0x71
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.funcHandler.Log(0xc00050f520, 0xc000085a00, 0xd0, 0x1effb40)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler.go:31 +0x37
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.(*swapHandler).Log(0xc000511ee0, 0xc000085a00, 0x322ed08, 0x322ed68)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/handler_go14.go:14 +0x7e
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.(*logger).write(0xc00050f2e0, 0xc00020ec00, 0x16, 0x3, 0x0, 0x0, 0x0)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/logger.go:106 +0x241
code.vorteil.io/vorteil/vrepo/vcli/pkg/util/log15.(*logger).Info(0xc00050f2e0, 0xc00020ec00, 0x16, 0x0, 0x0, 0x0)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/util/log15/logger.go:139 +0x6d
code.vorteil.io/vorteil/vrepo/vcli/pkg/daemon.(*Daemon).initializeNodesGraph.func4(0x1bdb740, 0x0, 0xc0004c8c60, 0xc0006143f8, 0x7, 0xc000006b48, 0x1, 0x1, 0xc0005fafa0, 0x23e28e0, ...)
        C:/Gitlab-Runner/builds/K9y3tnma/0/vorteil/vrepo/vcli/pkg/daemon/nodes.go:414 +0x53b
github.com/graphql-go/graphql.resolveField(0xc0005e23c0, 0xc00042b080, 0x1bdb740, 0x0, 0xc000006b48, 0x1, 0x1, 0xc0005fafa0, 0x0, 0x0, ...)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/graphql-go/graphql@v0.7.8/executor.go:649 +0x5eb
github.com/graphql-go/graphql.executeFieldsSerially(0xc0005e23c0, 0xc00042b080, 0x1bdb740, 0x0, 0xc0004c8bd0, 0x0, 0xc00042afd0)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/graphql-go/graphql@v0.7.8/executor.go:262 +0x216
github.com/graphql-go/graphql.executeOperation(0xc0005e23c0, 0x1bdb740, 0x0, 0x23ed5e0, 0xc000304380, 0xc00042b080)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/graphql-go/graphql@v0.7.8/executor.go:189 +0x2fe
github.com/graphql-go/graphql.Execute.func2(0xc000006b40, 0xc000096500, 0xc000080120, 0x0)
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/graphql-go/graphql@v0.7.8/executor.go:79 +0x256
created by github.com/graphql-go/graphql.Execute
        C:/Windows/system32/config/systemprofile/go/pkg/mod/github.com/graphql-go/graphql@v0.7.8/executor.go:54 +0x2e0
 debug=probe

@dmitshur dmitshur added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows labels Oct 21, 2019
@dmitshur dmitshur changed the title Windows WriteConsole syscall hangs indefinitely. syscall: Windows WriteConsole syscall hangs indefinitely Oct 21, 2019
@alankm
Copy link
Author

alankm commented Nov 7, 2019

I think I've just come across the answer to this question. It seems that Powershell basically pauses if you click around and is woken up by pressing enter. It must not just be the rendering that's paused, but the actual output too.

@alankm alankm closed this as completed Nov 7, 2019
@golang golang locked and limited conversation to collaborators Nov 6, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@mattn @dmitshur @gopherbot @alankm