http://bugs.winehq.org/show_bug.cgi?id=34865
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- Keywords| |download, win64 Status|UNCONFIRMED |NEW URL| |http://cran.rstudio.com/bin | |/windows/base/R-3.0.2-win.e | |xe CC| |focht@gmx.net Summary|Can't execute mingw |64-bit mingw toolchain from |toolchain provided by |Rtools fails to execute |Rtools |(cygwin 1.7.15-1, queued | |user APC not executed for | |signal handling) Ever Confirmed|0 |1
--- Comment #1 from Anastasius Focht focht@gmx.net 2013-11-10 18:04:54 CST --- Hello folks,
confirming. Run it with 'wineconsole' to avoid messed up tty and see more diagnostics ...
You initial analysis seems somewhat right, it's about signal delivery between processes through named pipes (this is what cygwin uses).
Actually the real problem seems to be delivery on the _same_ process :-)
Getting trace log:
--- snip --- $ pwd /home/focht/.wine-rtools/drive_c/Program Files/R/R-3.0.2/bin/x64
$ WINEDEBUG=+tid,+seh,+loaddll,+process,+relay wine ./R.exe --verbose --vanilla CMD INSTALL "C:\kimisc-master" --no-multiarch -d
... 002c:Call KERNEL32.CreateProcessW(0062dd30 L"C:\Rtools\bin\make.exe",00220692 L"C:\Rtools\bin\make.exe -f "Makevars.win" -f "C:/PROG~FBU/R/R-3_~NRD.2/etc/x64/Makeconf" -f "C:/PROG~FBU/R/R-3_~NRD.2/share/make/winshlib.mk" SHLIB_LDFLAGS='$(SHLIB_CXXLDFLAGS)' SHLIB_LD='$(SHLIB_CXXLD)' SHLIB="kimisc.dll" DEBUG=T WIN=64 TCLBIN=64 OBJECTS="rcpp_hello_world.o RcppExports.o"",00000000,00000000,00000001,04000020,00000000,00000000,0062fd30,0062fd74) ret=6110d206 ... 002c:trace:process:create_process_impl starting L"C:\Rtools\bin\make.exe" as Win32 binary (0x400000-0x425000) ... 002e:Call KERNEL32.__wine_kernel_init() ret=7bc5968d ... 002c:trace:process:create_process_impl started process pid 002d tid 002e 002c:Ret KERNEL32.CreateProcessW() retval=00000001 ret=6110d206 ... --- snip ---
Child 'make' (pid=0x2e) creates name pipe and event creation for signal communication:
Pipe handle to observe: 0x0000009c
(secondary) signal thread though user APC
--- snip --- 002e:Call KERNEL32.CreateNamedPipeA(0062f78c "\\.\pipe\cygwin-2b6b078c083f2559-45-",00000001,00000004,00000001,000000a4,000000a4,00000000,0062f8d0) ret=610b1b29 002e:Ret KERNEL32.CreateNamedPipeA() retval=00000098 ret=610b1b29 002e:Call KERNEL32.CreateFileA(0062f78c "\\.\pipe\cygwin-2b6b078c083f2559-45-",40000080,00000000,0062f8d0,00000003,00000000,00000000) ret=610b1a11 002e:Ret KERNEL32.CreateFileA() retval=0000009c ret=610b1a11 002e:Call ntdll.NtCreateEvent(0062f62c,001f0003,0062f60c,00000001,00000000) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 002e:Call KERNEL32.QueueUserAPC(61003db0,fffffffe,61188380) ret=610daa42 002e:Ret KERNEL32.QueueUserAPC() retval=00000001 ret=610daa42 002e:Call KERNEL32.TlsAlloc() ret=6107f46c 002e:Ret KERNEL32.TlsAlloc() retval=00000000 ret=6107f46c 002e:Ret PE DLL (proc=0x6107f390,module=0x61000000 L"cygwin1.dll",reason=PROCESS_ATTACH,res=0x1) retval=1 002e:Starting process L"C:\Rtools\bin\make.exe" (entryproc=0x401000) 002e:Call KERNEL32.GetModuleHandleA(00000000) ret=0041edba 002e:Ret KERNEL32.GetModuleHandleA() retval=00400000 ret=0041edba 002e:Call ntdll.NtCreateEvent(0062a864,001f0003,0062a844,00000001,00000000) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 --- snip ---
--- snip --- 002e:Call ntdll.NtWriteFile(000000b8,00000000,00000000,00000000,00629360,20042918,000000f3,611d0210,00000000) ret=6103442c g++ -m64 -I"C:/PROG~FBU/R/R-3_~NRD.2/include" -DNDEBUG -I"C:/Program Files/R/R-3.0.2/library/Rcpp/include" -I"d:/RCompile/CRANpkg/extralibs64/local/include" -O2 -Wall -gdwarf-2 -mtune=core2 -c rcpp_hello_world.cpp -o rcpp_hello_world.o 002e:Ret ntdll.NtWriteFile() retval=00000000 ret=6103442c 002e:Call ntdll.NtCreateEvent(00629494,001f0003,00629474,00000001,00000000) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 ... 002e:Call KERNEL32.CreateNamedPipeA(00629824 "\\.\pipe\cygwin-2b6b078c083f2559-45-pipe-0x1",40000001,00000004,00000001,00010000,00010000,00000000,6119a7e0) ret=610b1b29 002e:Ret KERNEL32.CreateNamedPipeA() retval=000000e0 ret=610b1b29 002e:Call KERNEL32.CreateFileA(00629824 "\\.\pipe\cygwin-2b6b078c083f2559-45-pipe-0x1",40000080,00000000,6119a7e0,00000003,40000000,00000000) ret=610b1a11 002e:Ret KERNEL32.CreateFileA() retval=000000e8 ret=610b1a11 002e:Call KERNEL32.DuplicateHandle(ffffffff,00000000,ffffffff,61279f28,00000000,00000001,00000002) ret=6117c75e 002e:Ret KERNEL32.DuplicateHandle() retval=00000000 ret=6117c75e 002e:Call KERNEL32.DuplicateHandle(ffffffff,00000000,ffffffff,6127a208,00000000,00000001,00000002) ret=6117c75e 002e:Ret KERNEL32.DuplicateHandle() retval=00000000 ret=6117c75e 002e:Call ntdll.NtCreateEvent(00629684,001f0003,00629664,00000000,00000001) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 002e:Call ntdll.NtCreateEvent(00629684,001f0003,00629664,00000000,00000001) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 ... 002e:Call KERNEL32.SetEvent(000000f0) ret=610389b6 002e:Ret KERNEL32.SetEvent() retval=00000001 ret=610389b6 002e:Call KERNEL32.CloseHandle(000000f0) ret=610389c4 002e:Ret KERNEL32.CloseHandle() retval=00000001 ret=610389c4 002e:Call KERNEL32.CloseHandle(000000e8) ret=61033f9a 002e:Ret KERNEL32.CloseHandle() retval=00000001 ret=61033f9a 002e:Call KERNEL32.SetHandleInformation(000000e0,00000001,00000000) ret=61033d58 002e:Ret KERNEL32.SetHandleInformation() retval=00000001 ret=61033d58 002e:Call ntdll.NtCreateEvent(00629664,001f0003,00629644,00000001,00000000) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 002e:Call KERNEL32.DuplicateHandle(ffffffff,ffffffff,ffffffff,00629974,00000000,00000001,00000002) ret=610dc0f8 002e:Ret KERNEL32.DuplicateHandle() retval=00000001 ret=610dc0f8 002e:Call ntdll.NtCreateEvent(006294d4,001f0003,006294b4,00000001,00000000) ret=6107f9f4 002e:Ret ntdll.NtCreateEvent() retval=00000000 ret=6107f9f4 002e:Call KERNEL32.WriteFile(0000009c,00629778,000000a4,0062981c,00000000) ret=610daef0 002e:Ret KERNEL32.WriteFile() retval=00000001 ret=610daef0 002e:Call KERNEL32.WaitForSingleObject(000000f4,0000ea60) ret=610db059 002a:Ret KERNEL32.WaitForSingleObject() retval=00000102 ret=6c71a3b1 ... 002e:Call KERNEL32.CloseHandle(000000f4) ret=610db06b 002e:Ret KERNEL32.CloseHandle() retval=00000001 ret=610db06b ... 002e:Call KERNEL32.GetStdHandle(fffffff4) ret=610e221d 002e:Ret KERNEL32.GetStdHandle() retval=000000bc ret=610e221d 002e:Call KERNEL32.WriteFile(000000bc,00621794,00000068,00629794,00000000) ret=610e2245 60014615 [main] make 45 sig_send: wait for sig_complete event failed, signal -40, rc 258, Win32 error 0 002e:Ret KERNEL32.WriteFile() retval=00000001 ret=610e2245 ... --- snip ---
Write a "signal" packet to pipe 0x0000009c and wait for event 0x000000f4 to be signaled. The event 0x000000f4 ought to be signaled from the other end of pipe - either by another process or from same process using a signal handling thread. Well, guess ... cygwin queues a user APC for that.
Main thread waits 60 sec for 0x000000f4 to become signaled and runs into WAIT_TIMEOUT (0x102 -> 258).
Using Winedbg we can figure out who calls this (NOTE: pids don't match, another run just to illustrate):
--- snip --- Wine-dbg>info process pid threads executable (all id:s are in hex) 00000033 1 'wineconsole.exe' 00000035 1 _ 'R.exe' 00000037 1 _ 'cmd.exe' 00000039 2 _ 'Rterm.exe' 0000003c 1 _ 'make.exe' 0000003e 1 _ 'make.exe' 0000002c 1 'make.exe' 00000021 1 'explorer.exe' 0000000e 5 'services.exe' 0000001b 3 _ 'plugplay.exe' 00000012 4 _ 'winedevice.exe' ... <attach to highest child pid> ... Backtrace: =>0 0xf777742e __kernel_vsyscall+0xe() in [vdso].so (0x00629328) 1 0xf756c233 __libc_read+0x22() in libpthread.so.0 (0x00629328) 2 0x7bc7e876 wait_select_reply+0x30(cookie=0x62940c) [/home/focht/projects/wine/wine-git/dlls/ntdll/server.c:333] in ntdll (0x00629328) 3 0x7bc7f65d server_select+0x182(select_op=0x629464, size=0x8, flags=0x2, timeout=0x6295a8) [/home/focht/projects/wine/wine-git/dlls/ntdll/server.c:597] in ntdll (0x00629438) 4 0x7bc88bdb NtWaitForMultipleObjects+0xd4(count=0x1, handles=0x6295b0, wait_all=0, alertable=0, timeout=0x6295a8) [/home/focht/projects/wine/wine-git/dlls/ntdll/sync.c:835] in ntdll (0x00629578) 5 0x7b875dc0 WaitForMultipleObjectsEx+0x160(count=<couldn't compute location>, handles=<couldn't compute location>, wait_all=<couldn't compute location>, timeout=<couldn't compute location>, alertable=<couldn't compute location>) [/home/focht/projects/wine/wine-git/dlls/kernel32/sync.c:188] in kernel32 (0x006296d8) 6 0x7b875ba7 WaitForSingleObject+0x45(handle=<couldn't compute location>, timeout=<couldn't compute location>) [/home/focht/projects/wine/wine-git/dlls/kernel32/sync.c:128] in kernel32 (0x00629718) 7 0x610db059 in cygwin1 (+0xdb058) (0x00629840) 8 0x610db897 in cygwin1 (+0xdb896) (0x00629910) 9 0x6107835e in cygwin1 (+0x7835d) (0x00629aa0) 10 0x610d50f5 in cygwin1 (+0xd50f4) (0x00629af0) 11 0x0040b0f5 in make (+0xb0f4) (0x00629b20) 12 0x0040b51c in make (+0xb51b) (0x00629b70) ... 24 0x0040efb8 in make (+0xefb7) (0x0062a970) 25 0x61007128 in cygwin1 (+0x7127) (0x0062ab70) --- snip ---
The child 'make' process has only one main thread.
Using the info from callstack and a disassembler on "cygwin1.dll" we can deduce where this binary comes from:
--- snip --- /home/corinna/src/cygwin/cygwin-1.7.15/cygwin-1.7.15-1/src/cygwin-1.7.15/winsup/cygwin/sigproc.cc --- snip ---
Source to CVS HEAD: http://cygwin.com/cgi-bin/cvsweb.cgi/src/winsup/cygwin/sigproc.cc?cvsroot=sr...
Checking if a tag exists for "cygwin-1.7.15-x":
--- snip --- Revision 1.384 / (download) - annotate - [select for diffs] , Wed May 2 16:39:39 2012 UTC (18 months, 1 week ago) by cgf Branch: MAIN CVS Tags: cygwin-1_7_15-release --- snip ---
Looking at the CVS commit history there seem to be lots of bugfixes and partial rewrite (merge) _after_ that tag (18 months old).
Source to CVS tag: http://cygwin.com/cgi-bin/cvsweb.cgi/src/winsup/cygwin/sigproc.cc?rev=1.384&...
You can cross-check between source code of "sig_send" function and looking at Wine trace log API calls.
For me it looks like the user APC which ought to handle the other pipe end/signalling is not called in between WriteFile() and WaitForSingleObject() because the main thread didn't enter an alertable state.
The be in alertable state, the (main) thread has to call SleepEx, SignalObjectAndWait, WaitForSingleObjectEx, WaitForMultipleObjectsEx, or MsgWaitForMultipleObjectsEx.
WaitForSingleObject() -> WaitForMultipleObjectsEx( ... bAlertable = FALSE)
Can standard WriteFile() cause queued APC to be executed? I don't know.
Regards