http://bugs.winehq.org/show_bug.cgi?id=34648
Bug #: 34648 Summary: J2SE Runtime Environment 5.0 Update 10 installer 'patchjre' tool crashes due to unbuffered io on redirected stdout pipe Product: Wine Version: 1.7.3 Platform: x86 OS/Version: Linux Status: NEW Severity: normal Priority: P2 Component: msvcrt AssignedTo: wine-bugs@winehq.org ReportedBy: focht@gmx.net Classification: Unclassified
Hello folks,
as the summary says ...
The first thing to notice is the installer seeming to hang without showing GUI. It actually tries to call home to 'jal.sun.com' which might take up to a minute until it times out. Not sure why they didn't remove the DNS entry if the host is dead/filtered/blocked anyway.
--- snip --- 0009:trace:wininet:HTTP_HttpSendRequestW Request header -> L"HEAD /webapps/installstat/CountryLookup HTTP/1.1\r\nHost: jal.sun.com\r\nContent-Length: 0\r\nUser-Agent: jupdate\r\nCache-Control: no-cache\r\nConnection: Keep-Alive\r\n\r\n" 0009:trace:wininet:GetAddress L"jal.sun.com" 0009:trace:wininet:HTTP_ResolveName resolved L"jal.sun.com" to 192.18.97.143 0009:trace:wininet:open_http_connection connecting to L"jal.sun.com", proxy (null) --- snip ---
(test with a browser)
The crash itself can be reproduced by running the following command after failed install attempt:
--- snip --- $ pwd /home/focht/.wine/drive_c/Program Files/Common Files/Java/Update/Base Images/jre1.5.0.b64/patch-jre1.5.0_10.b03
$ wine ./patchjre.exe -s "C:\Program Files\Java\jre1.5.0_10" --- snip ---
Backtrace:
--- snip --- Unhandled exception: page fault on read access to 0x00000001 in 32-bit code (0xf7527245). Register dump: CS:0023 SS:002b DS:002b ES:002b FS:0063 GS:006b EIP:f7527245 ESP:0033c33c EBP:0033c398 EFLAGS:00010206( R- -- I - -P- ) EAX:00000001 EBX:f75a5000 ECX:00000022 EDX:00000000 ESI:7e5ea308 EDI:7b868ca6 Stack dump: 0x0033c33c: 00000001 00000000 00000004 0033c398 0x0033c34c: 00000000 00000000 0012fa10 00000000 0x0033c35c: 00000000 00000000 00000000 0033c340 0x0033c36c: 7e61e000 7e5ea308 7b868ca6 0033c398 0x0033c37c: 7e5ea32f 00000001 0040a32c 0033db40 0x0033c38c: 0040626c 00000000 00000000 0033db40 000c: sel=0067 base=00000000 limit=00000000 16-bit --x Backtrace: =>0 0xf7527245 __strstr_sse42+0x25() in libc.so.6 (0x0033c398) 1 0x7e5ea32f MSVCRT_strstr+0x26(haystack=*** invalid address 0x1 ***, needle=""") [/home/focht/projects/wine/wine-git/dlls/msvcrt/string.c:1725] in msvcrt (0x0033c398) 2 0x0040628f in patchjre (+0x628e) (0x0033db40) 3 0x00401155 in patchjre (+0x1154) (0x0033fd84) 4 0x00406daa in patchjre (+0x6da9) (0x0033fe20) 5 0x7b863cf0 call_process_entry+0xb() in kernel32 (0x0033fe38) --- snip ---
The patcher creates pipes for child process stdio:
--- snip --- 0025:Call KERNEL32.CreatePipe(0033db30,0033db24,0033db18,00000400) ret=0040616e 0025:Ret KERNEL32.CreatePipe() retval=00000001 ret=0040616e 0025:Call KERNEL32.CreatePipe(0033db34,0033db28,0033db18,00000400) ret=0040618b 0025:Ret KERNEL32.CreatePipe() retval=00000001 ret=0040618b 0025:Call KERNEL32.CreatePipe(0033db38,0033db2c,0033db18,00000400) ret=004061a2 0025:Ret KERNEL32.CreatePipe() retval=00000001 ret=004061a2 ... 0025:Call KERNEL32.SetHandleInformation(00000064,00000001,00000000) ret=00406205 0025:Ret KERNEL32.SetHandleInformation() retval=00000001 ret=00406205 0025:Call KERNEL32.SetHandleInformation(00000068,00000001,00000000) ret=0040620d 0025:Ret KERNEL32.SetHandleInformation() retval=00000001 ret=0040620d 0025:Call KERNEL32.SetHandleInformation(00000070,00000001,00000000) ret=00406215 0025:Ret KERNEL32.SetHandleInformation() retval=00000001 ret=00406215 --- snip ---
The child process is started:
--- snip --- ... 0025:Call KERNEL32.CreateProcessA(00000000,0033cbbc "C:\Program Files\Java\jre1.5.0_10\bin\java.exe -fullversion",00000000,00000000,00000001,08000008,00000000,00000000,0033dabc,0033db00) ret=00406248 ... 0027:Call KERNEL32.__wine_kernel_init() ret=7bc594f9 0025:Ret KERNEL32.CreateProcessA() retval=00000001 ret=00406248 ... --- snip ---
The parent (patcher) immediately issues a blocking read on child stdout pipe without waiting for anything. It blocks until the child writes something to other end of pipe:
--- snip --- 0025:Call KERNEL32.ReadFile(00000070,0033d3bc,00000100,0033db48,00000000) ret=0040626c --- snip ---
The child parses the command line and (f)prints out the version string to "stdout" pipe. I added more trace info to show 'MSVCRT_fwrite' and 'MSVCRT__write' calls + args.
--- snip --- 0027:trace:msvcrt:MSVCRT__isatty :fd (2) handle (0x74) 0027:Call KERNEL32.GetFileType(00000074) ret=7ecacf3f 0027:Ret KERNEL32.GetFileType() retval=00000003 ret=7ecacf3f 0027:trace:msvcrt:pf_printf_a Format is: "%s full version "%s"\n" 0027:trace:msvcrt:_lock (30) 0027:trace:msvcrt:MSVCRT_fwrite :file (0x7ed22320) ptr (0x40809c) wrcnt (4) file->_cnt=0 0027:trace:msvcrt:MSVCRT__isatty :fd (2) handle (0x74) 0027:Call KERNEL32.GetFileType(00000074) ret=7ecacf3f 0027:Ret KERNEL32.GetFileType() retval=00000003 ret=7ecacf3f 0027:Call ntdll.RtlAllocateHeap(00110000,00000008,00000200) ret=7ecb8877 0027:Ret ntdll.RtlAllocateHeap() retval=00134f48 ret=7ecb8877 0027:trace:msvcrt:MSVCRT__write :fd (2) handle (116) buf (0x40809c) len (4) 0027:Call KERNEL32.WriteFile(00000074,0040809c,00000004,0033f7a4,00000000) ret=7ecb4157 0027:Ret KERNEL32.WriteFile() retval=00000001 ret=7ecb4157 0027:trace:msvcrt:_unlock (30) 0027:trace:msvcrt:_lock (30) --- snip ---
Upon pipe write of client, the parent's blocking read returns and it starts parsing the output:
--- snip --- 0025:Ret KERNEL32.ReadFile() retval=00000001 ret=0040626c Regards ... 0025:Call msvcrt.strstr(0033d3bc "java",0040a32c """) ret=00406280 ... 0025:Ret msvcrt.strstr() retval=00000000 ret=00406280 ... 0025:Call msvcrt.strstr(00000001,0040a32c """) ret=0040628f ... 0025:trace:seh:raise_exception code=c0000005 flags=0 addr=0xf747d245 ip=f747d245 tid=0025 --- snip ---
Unfortunately the buffer of client fprintf() call was not written in one piece (buffered io) causing the parent to read only a partial string. Due to crappy coding it crashes (2x strstr for '"' won't work for partial data). As seen in trace the first 4 bytes were directly written to pipe without any buffering.
The child process fprintf() call to stdout (pipe):
--- snip --- ... 0040111F mov dword ptr [40AEB8h], 40809Ch ; offset "java" ... 00402007 push 4085DCh ; offset to "1.5.0-b64" 0040200C push dword ptr [40AEB8h] ; -> "java" 00402012 add eax, 40h 00402015 push 4085E8h ; offset to "%s full version "%s"\n" 0040201A push eax ; FILE * 0040201B call fprintf --- snip ---
The first call to WriteFile() is actually the result of outputting first string argument after format string -> 40809Ch = "java" (len=4).
Each vfprintf() argument handler -> pf_output_xxx will immediately trigger an unbuffered write to the pipe(s).
Example session with winedbg showing use of buffered stdio when started from console (len = 0x1f):
--- snip --- =>0 0x7b83db29 WriteFile(hFile=0x17, buffer=0x112110, bytesToWrite=0x1f, bytesWritten=0x33f9bc, overlapped=(nil)) [/home/focht/projects/wine/wine-git/dlls/kernel32/file.c:529] in kernel32 (0x0033fa38) 1 0x7ecace65 msvcrt_flush_buffer+0x54(file=0x7ed22320) [/home/focht/projects/wine/wine-git/dlls/msvcrt/file.c:565] in msvcrt (0x0033fa78) 2 0x7ecad0b8 remove_std_buffer+0x10(file=0x7ed22320) [/home/focht/projects/wine/wine-git/dlls/msvcrt/file.c:628] in msvcrt (0x0033fa98) 3 0x7ecb7630 MSVCRT_vfprintf+0x91(file=0x7ed22320, format="%s full version "%s" ", valist="") [/home/focht/projects/wine/wine-git/dlls/msvcrt/file.c:4491] in msvcrt (0x0033fae8) 4 0x7ecb7aca MSVCRT_fprintf+0x35(file=0x7ed22320, format="%s full version "%s" ") [/home/focht/projects/wine/wine-git/dlls/msvcrt/file.c:4612] in msvcrt (0x0033fb1c) 5 0x00402021 in java (+0x2020) (0x00111ff3) --- snip ---
It seems to me that buffered io should be still done even if stdout is connected to a pipe.
Regards