Skip to content

Panic and data race calling a Windows function in user32.dll and fmt.Println #31742

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
Closed
tischda opened this issue Apr 29, 2019 · 2 comments
Closed

Panic and data race calling a Windows function in user32.dll and fmt.Println #31742

tischda opened this issue Apr 29, 2019 · 2 comments
Labels
FrozenDueToAge

Comments

@tischda
Copy link

tischda commented Apr 29, 2019 •
edited
Loading

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

$ go version
go version go1.12.4 windows/amd64

Does this issue reproduce with the latest release?

yes, but it worked with 1.10 and 1.11

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

go env Output
$ go env
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Daniel\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=u:\src\go
set GOPROXY=
set GORACE=
set GOROOT=c:\usr\bin\go
set GOTMPDIR=
set GOTOOLDIR=c:\usr\bin\go\pkg\tool\windows_amd64
set GCCGO=gccgo
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=c:\temp\go-build945310246=/tmp/go-build -gno-record-gcc-switches

What did you do?

Small project here: https://github.com/tischda/refresh
Appveyor: https://ci.appveyor.com/project/tischda/refresh

var (
	moduser32 = syscall.NewLazyDLL("user32.dll")
	procSendMessageTimeout = moduser32.NewProc("SendMessageTimeoutW")
)

func SendMessageTimeout(hwnd HWND, msg uint32, wParam, lParam uintptr, fuFlags, uTimeout uint32) uintptr {
	ret, _, _ := procSendMessageTimeout.Call(
		uintptr(hwnd),
		uintptr(msg),
		wParam,
		lParam,
		uintptr(fuFlags),
		uintptr(uTimeout))

	return ret
}

func main() {
...
		ret := SendMessageTimeout(HWND_BROADCAST, WM_SETTINGCHANGE, 0,
			uintptr(unsafe.Pointer(StringToUTF16Ptr("Environment"))), SMTO_NORMAL|SMTO_ABORTIFHUNG, 5000)

		// If the function succeeds, the return value is nonzero
		if ret == 0 {
			fmt.Println("Refresh: Error")
			os.Exit(1)
		} else {
			// FIXME: printing something here creates a data race
			fmt.Println("Refresh: Success")
		}
}

What did you expect to see?

Refresh: Success

What did you see instead?

fatal error: unexpected signal during runtime execution
[signal 0xc0000005 code=0x1 addr=0x18 pc=0x454466]

runtime stack:
runtime.throw(0x4e7ee9, 0x2a)
        c:/usr/bin/go/src/runtime/panic.go:617 +0x79
runtime.sigpanic()
        c:/usr/bin/go/src/runtime/signal_windows.go:227 +0x272
runtime.asmstdcall(0x599da0, 0x1, 0x4c000c, 0x1f6ab98, 0xc000095d08, 0x2d0, 0xc00003c000, 0x4300f0, 0x0, 0x450b25, ...)
        c:/usr/bin/go/src/runtime/sys_windows_amd64.s:64 +0x66
runtime.asmcgocall(0x1, 0x4c000c)
        c:/usr/bin/go/src/runtime/asm_amd64.s:635 +0x73

goroutine 1 [syscall, locked to thread]:
runtime.cgocall(0x454400, 0x597d50, 0x14)
        c:/usr/bin/go/src/runtime/cgocall.go:128 +0x55 fp=0xc000095d70 sp=0xc000095d38 pc=0x403c85
syscall.Syscall6(0x76d7fa50, 0x6, 0xffff, 0x1a, 0x0, 0xc000068100, 0x2, 0x1388, 0x0, 0x0, ...)
        c:/usr/bin/go/src/runtime/syscall_windows.go:197 +0xed fp=0xc000095da0 sp=0xc000095d70 pc=0x4445cd
syscall.(*Proc).Call(0xc000060460, 0xc000080090, 0x6, 0x6, 0x30, 0x4c1620, 0x1, 0xc000080090)
        c:/usr/bin/go/src/syscall/dll_windows.go:181 +0x6ea fp=0xc000095e98 sp=0xc000095da0 pc=0x48236a
syscall.(*LazyProc).Call(0xc000082300, 0xc000080090, 0x6, 0x6, 0x0, 0x0, 0x4d2601, 0xc000082300)
        c:/usr/bin/go/src/syscall/dll_windows.go:333 +0x66 fp=0xc000095ee8 sp=0xc000095e98 pc=0x483676
main.SendMessageTimeout(...)
        u:/src/go/src/github.com/tischda/refresh/win_user32.go:33
main.main()
        u:/src/go/src/github.com/tischda/refresh/main.go:29 +0x22b fp=0xc000095f98 sp=0xc000095ee8 pc=0x4a962b
runtime.main()
        c:/usr/bin/go/src/runtime/proc.go:200 +0x20c fp=0xc000095fe0 sp=0xc000095f98 pc=0x42d50c
runtime.goexit()
        c:/usr/bin/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc000095fe8 sp=0xc000095fe0 pc=0x452c01

When I build with go build -race I get this DATA RACE:

refresh.exe Output
==================
WARNING: DATA RACE
Read at 0x00c00006c280 by goroutine 0:
  internal/poll.(*fdMutex).rwlock()
      c:/usr/bin/go/src/internal/poll/fd_mutex.go:132 +0x87
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_mutex.go:239 +0x6b
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c00006c280 by main goroutine:
  os.newFile()
      c:/usr/bin/go/src/os/file_windows.go:52 +0xb1
  os.NewFile()
      c:/usr/bin/go/src/os/file_windows.go:76 +0x8a
  os.init.ializers()
      c:/usr/bin/go/src/os/file.go:60 +0x319
  os.init()
      :1 +0xbc
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x00c00006c4b7 by goroutine 0:
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c00006c4b0 by main goroutine:
  os.newFile()
      c:/usr/bin/go/src/os/file_windows.go:52 +0xb1
  os.NewFile()
      c:/usr/bin/go/src/os/file_windows.go:76 +0x8a
  os.init.ializers()
      c:/usr/bin/go/src/os/file.go:60 +0x319
  os.init()
      :1 +0xbc
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Write at 0x00c00006c450 by goroutine 0:
  sync.(*Mutex).Lock()
      c:/usr/bin/go/src/sync/mutex.go:74 +0x54
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:664 +0x471
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c00006c450 by main goroutine:
  os.newFile()
      c:/usr/bin/go/src/os/file_windows.go:52 +0xb1
  os.NewFile()
      c:/usr/bin/go/src/os/file_windows.go:76 +0x8a
  os.init.ializers()
      c:/usr/bin/go/src/os/file.go:60 +0x319
  os.init()
      :1 +0xbc
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x00c00006c460 by goroutine 0:
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c00006c460 by main goroutine:
  os.newFile()
      c:/usr/bin/go/src/os/file_windows.go:52 +0xb1
  os.NewFile()
      c:/usr/bin/go/src/os/file_windows.go:76 +0x8a
  os.init.ializers()
      c:/usr/bin/go/src/os/file.go:60 +0x319
  os.init()
      :1 +0xbc
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x000000628ec0 by goroutine 0:
  internal/poll.(*FD).writeConsole()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:737 +0x2ef
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x000000628ec0 by main goroutine:
  syscall.init.ializers()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:139 +0x29f9
  syscall.init()
      :1 +0xad
  os.init()
      :1 +0xa3
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x00c000041250 by goroutine 0:
  syscall.(*LazyProc).Find()
      c:/usr/bin/go/src/syscall/dll_windows.go:287 +0x56
  syscall.(*LazyProc).mustFind()
      c:/usr/bin/go/src/syscall/dll_windows.go:309 +0x43
  syscall.(*LazyProc).Addr()
      c:/usr/bin/go/src/syscall/dll_windows.go:318 +0x43
  syscall.WriteConsole()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:1298 +0x66
  internal/poll.(*FD).writeConsole()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:737 +0x2ef
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c000041250 by main goroutine:
  syscall.(*LazyDLL).NewProc()
      c:/usr/bin/go/src/syscall/dll_windows.go:264 +0x61
  syscall.init.ializers()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:139 +0x29df
  syscall.init()
      :1 +0xad
  os.init()
      :1 +0xa3
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Write at 0x00c000041230 by goroutine 0:
  sync.(*Mutex).Lock()
      c:/usr/bin/go/src/sync/mutex.go:74 +0x54
  syscall.(*LazyProc).Find()
      c:/usr/bin/go/src/syscall/dll_windows.go:288 +0x89
  syscall.(*LazyProc).mustFind()
      c:/usr/bin/go/src/syscall/dll_windows.go:309 +0x43
  syscall.(*LazyProc).Addr()
      c:/usr/bin/go/src/syscall/dll_windows.go:318 +0x43
  syscall.WriteConsole()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:1298 +0x66
  internal/poll.(*FD).writeConsole()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:737 +0x2ef
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c000041230 by main goroutine:
  syscall.(*LazyDLL).NewProc()
      c:/usr/bin/go/src/syscall/dll_windows.go:264 +0x61
  syscall.init.ializers()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:139 +0x29df
  syscall.init()
      :1 +0xad
  os.init()
      :1 +0xa3
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x00c000004068 by goroutine 0:
  syscall.(*LazyDLL).Load()
      c:/usr/bin/go/src/syscall/dll_windows.go:232 +0x56
  syscall.(*LazyProc).Find()
      c:/usr/bin/go/src/syscall/dll_windows.go:291 +0xf1
  syscall.(*LazyProc).mustFind()
      c:/usr/bin/go/src/syscall/dll_windows.go:309 +0x43
  syscall.(*LazyProc).Addr()
      c:/usr/bin/go/src/syscall/dll_windows.go:318 +0x43
  syscall.WriteConsole()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:1298 +0x66
  internal/poll.(*FD).writeConsole()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:737 +0x2ef
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c000004068 by main goroutine:
  syscall.NewLazyDLL()
      c:/usr/bin/go/src/syscall/dll_windows.go:269 +0x61
  syscall.init.ializers()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:38 +0x66
  syscall.init()
      :1 +0xad
  os.init()
      :1 +0xa3
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
==================
WARNING: DATA RACE
Read at 0x00c000004090 by goroutine 0:
  syscall.(*LazyProc).Find()
      c:/usr/bin/go/src/syscall/dll_windows.go:295 +0x174
  syscall.(*LazyProc).mustFind()
      c:/usr/bin/go/src/syscall/dll_windows.go:309 +0x43
  syscall.(*LazyProc).Addr()
      c:/usr/bin/go/src/syscall/dll_windows.go:318 +0x43
  syscall.WriteConsole()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:1298 +0x66
  internal/poll.(*FD).writeConsole()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:737 +0x2ef
  internal/poll.(*FD).Write()
      c:/usr/bin/go/src/internal/poll/fd_windows.go:678 +0x206
  os.(*File).Write()
      c:/usr/bin/go/src/os/file_windows.go:224 +0xae
  fmt.Fprintln()
      c:/usr/bin/go/src/fmt/print.go:266 +0xb9
  main.main()
      c:/usr/bin/go/src/fmt/print.go:275 +0x457
Previous write at 0x00c000004090 by main goroutine:
  syscall.LoadDLL()
      c:/usr/bin/go/src/syscall/dll_windows.go:93 +0x447
  syscall.(*LazyDLL).Load()
      c:/usr/bin/go/src/syscall/dll_windows.go:236 +0xf5
  syscall.(*LazyProc).Find()
      c:/usr/bin/go/src/syscall/dll_windows.go:291 +0xf1
  syscall.(*LazyProc).mustFind()
      c:/usr/bin/go/src/syscall/dll_windows.go:309 +0x43
  syscall.(*LazyProc).Addr()
      c:/usr/bin/go/src/syscall/dll_windows.go:318 +0x43
  syscall.GetStdHandle()
      c:/usr/bin/go/src/syscall/zsyscall_windows.go:366 +0x55
  syscall.getStdHandle()
      c:/usr/bin/go/src/syscall/syscall_windows.go:394 +0x3f
  syscall.init.ializers()
      c:/usr/bin/go/src/syscall/syscall_windows.go:388 +0x246
  syscall.init()
      :1 +0xad
  os.init()
      :1 +0xa3
  fmt.init()
      :1 +0xa8
  flag.init()
      :1 +0x99
  main.init()
      :1 +0x99
==================
Found 9 data race(s)

When I remove the line fmt.Println("Refresh: Success")
and compile with go build -race
then it works (it prints nothing or course, but it does refresh the environment variables).

Now you would think the problem comes from the fmt.Println, but when I build the code without fmt.Println with go build (no -race option), it just panics.
@randall77
Copy link
Contributor

Now you would think the problem comes from the fmt.Println, but when I build the code without fmt.Println with go build (no -race option), it just panics.

That sounds like the first bug to tackle. It may be the cause of all of the rest of the behaviors you see.

First, the microsoft docs for this function have an additional parameter, PDWORD_PTR lpdwResult. The docs are unclear (to me, at least) whether this needs to be set for the type of messages you're sending. But it wouldn't hurt to set it to nil, otherwise the value passed will be junk, which is a possible source of segfaults.

Second, this is very suspect: uintptr(unsafe.Pointer(StringToUTF16Ptr("Environment"))). You're allocating an object on the heap, then converting it to uintptr. At that point the object on the heap can be garbage collected. Then you're passing that uintptr to windows which will try to access the possibly freed object.

The Go runtime promises to do the right thing with these weird uintptr(unsafe.Pointer(...)) arguments when passed to the results of NewLazyDLL or NewProc, but we don't make such a promise for your wrapper function. You should try modifying your SendMessageTimeout function to take real Go types for the wParam and lParam parameters (unsafe.Pointer at least, but *uint16 or even []uint16 would be better) and do the cast to uintptr in the SendMessageTimeout function when calling procSendMessageTimeout.Call.

@tischda
Copy link
Author

tischda commented Apr 30, 2019

Thank you, that put me on the right direction:

ret := SendMessageTimeout(HWND_BROADCAST, WM_SETTINGCHANGE, StringToUTF16Ptr(""),
			StringToUTF16Ptr("Environment"), SMTO_NORMAL|SMTO_ABORTIFHUNG, 5000)

The modified function:

func SendMessageTimeout(hwnd HWND, msg uint32, wParam, lParam *uint16, fuFlags, uTimeout uint32) uintptr {
	ret, _, _ := procSendMessageTimeout.Call(
		uintptr(hwnd),
		uintptr(msg),
		uintptr(unsafe.Pointer(wParam)),
		uintptr(unsafe.Pointer(lParam)),
		uintptr(fuFlags),
		uintptr(uTimeout),
		0)

Now it works.

I found this documented in unsafe.go :

// If a pointer argument must be converted to uintptr for use as an argument,
// that conversion must appear in the call expression itself:
//
//	syscall.Syscall(SYS_READ, uintptr(fd), uintptr(unsafe.Pointer(p)), uintptr(n))
//
// The compiler handles a Pointer converted to a uintptr in the argument list of
// a call to a function implemented in assembly by arranging that the referenced
// allocated object, if any, is retained and not moved until the call completes,
// even though from the types alone it would appear that the object is no longer
// needed during the call.
//
// For the compiler to recognize this pattern,
// the conversion must appear in the argument list:
//
//	// INVALID: uintptr cannot be stored in variable
//	// before implicit conversion back to Pointer during system call.
//	u := uintptr(unsafe.Pointer(p))
//	syscall.Syscall(SYS_READ, uintptr(fd), u, uintptr(n))

I also found in the 1.12 release notes that "the Go runtime now releases memory back to the operating system more aggressively", which is probably why the issue appeared with 1.12.

Thank you, I think we can close this.

@golang golang locked and limited conversation to collaborators Apr 29, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@tischda @randall77 @gopherbot