http://bugs.winehq.org/show_bug.cgi?id=32990
Bug #: 32990 Summary: Wine on ARM: relay tracing is broken with entry points having an odd number of arguments, calling into glibc code that makes use of alloca() Product: Wine Version: 1.5.24 Platform: arm OS/Version: Linux Status: NEW Severity: normal Priority: P2 Component: ntdll AssignedTo: wine-bugs@winehq.org ReportedBy: focht@gmx.net Classification: Unclassified
Hello folks,
relay tracing doesn't work properly on ARM :(
Example app (others have similar problem):
WINEDEBUG=+tid,+seh,+relay,+time,+file
--- snip --- ... 002e:Call KERNEL32.LZOpenFileW(408baf68 L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe",40d1fb8c,00000000) ret=40f17cec 002e:trace:file:LZOpenFileA (Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe,0x40d1fb8c,0) 002e:trace:file:OpenFile Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe OF_READ OF_SHARE_COMPAT 002e:trace:file:OpenFile Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe 0000 002e:trace:file:RtlGetFullPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" 520 0x40d1f7b8 (nil)) 002e:trace:file:RtlDosPathNameToNtPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe",0x40d1f740,(nil),(nil)) 002e:trace:file:RtlGetFullPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" 520 0x40d1f4c0 (nil)) 002e:trace:file:wine_nt_to_unix_file_name L"\??\Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" -> "/home/linaro/.wine/dosdevices/z:/home/linaro/wine-apps/windefender/unpacked/MPSigStub.exe" 002e:trace:file:RtlGetFullPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" 520 0x40d1f7b4 (nil)) 002e:trace:file:OpenFile found "Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" 002e:trace:file:_lopen ("Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe",0000) 002e:trace:file:CreateFileW L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" GENERIC_READ FILE_SHARE_READ FILE_SHARE_WRITE creation 3 attributes 0x80 002e:trace:file:RtlDosPathNameToNtPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe",0x40d1f900,(nil),(nil)) 002e:trace:file:RtlGetFullPathName_U (L"Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" 520 0x40d1f670 (nil)) 002e:trace:file:wine_nt_to_unix_file_name L"\??\Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe" -> "/home/linaro/.wine/dosdevices/z:/home/linaro/wine-apps/windefender/unpacked/MPSigStub.exe" 002e:trace:file:CreateFileW returning 0x2c 002e:trace:seh:raise_exception info[0]=00000000 002e:trace:seh:raise_exception info[1]=30435454 002e:trace:seh:raise_exception Pc:30435454 Sp:40d1f884 Lr:0a30 Cpsr:600f0030 r0:0004 r1:401f3005 r2:0000 r3:168f8 002e:trace:seh:raise_exception r4:0004 r5:40d1f880 r6:168f8 r7:40d1f894 r8:0004 r9:81a3f10 r10:0000 Fp:4033a950 Ip:0000 002e:trace:seh:call_stack_handlers calling handler at 0x403f487c code=c0000005 flags=0 002e:Call KERNEL32.UnhandledExceptionFilter(40d1f6d8) ret=403f48e0 wine: Unhandled page fault on read access to 0x30435454 at address 0x30435454 (thread 002e), starting debugger... 002e:trace:seh:start_debugger Starting debugger "winedbg --auto 45 48" --- snip ---
First approach was using winedbg with Cpsr-fixed (=usable) gdbstub:
--- snip --- Wine-gdb> b FileTimeToDosDateTime ... Wine-gdb> bt #0 FileTimeToDosDateTime (ft=0x40d5fac8, fatdate=0x40d5fad0, fattime=0x40d5fad2) at /home/linaro/wine/wine-git/dlls/kernel32/time.c:1053 #1 0x40a5f378 in OpenFile (name=0x40901618 "Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe", ofs=0x40d5fbe4, mode=0) at /home/linaro/wine/wine-git/dlls/kernel32/file.c:2596 #2 0x40a785a8 in LZOpenFileA (fn=0x40901618 "Z:\home\linaro\wine-apps\windefender\unpacked\MPSigStub.exe", ofs=0x40d5fbe4, mode=0) at /home/linaro/wine/wine-git/dlls/kernel32/lzexpand.c:540 #3 0x40a7871c in LZOpenFileW (fn=0x40901598, ofs=0x40d5fbe4, mode=0) at /home/linaro/wine/wine-git/dlls/kernel32/lzexpand.c:566 #4 0x4046bcec in GetFileVersionInfoSizeW (filename=0x40901598, handle=0x40d5fc8c) at /home/linaro/wine/wine-git/dlls/version/version.c:590 #5 0x0041cd82 in ?? () #6 0x0041cd82 in ?? () Backtrace stopped: previous frame identical to this frame (corrupt stack?) --- snip ---
--- snip --- 1052 unixtime = t;
1053 tm = gmtime( &unixtime );
1054 if (fattime)
=> 0x40aa363c <+144>: sub r3, r11, #12 0x40aa3640 <+148>: mov r0, r3 0x40aa3644 <+152>: bl 0x40a1f1dc 0x40aa3648 <+156>: str r0, [r11, #-8] 0x40aa364c <+160>: ldr r3, [r11, #-40] ; 0x28 0x40aa3650 <+164>: cmp r3, #0 0x40aa3654 <+168>: beq 0x40aa36b0 <FileTimeToDosDateTime+260> --- snip ---
Thumb veneer to glibc code because my userland is thumb2:
--- snip --- 0x40a1f1dc add r12, pc, #0, 12 0x40a1f1e0 add r12, r12, #729088 ; 0xb2000 0x40a1f1e4 ldr pc, [r12, #3932]! ; 0xf5c --- snip ---
Arriving at gmtime() code (in thumb mode):
--- snip --- 0x402b60bc <gmtime> ldr r2, [pc, #8] ; (0x402b60c8 <gmtime+12>) 0x402b60be <gmtime+2> movs r1, #0 0x402b60c0 <gmtime+4> add r2, pc 0x402b60c2 <gmtime+6> b.w 0x402b7210 0x402b60c6 <gmtime+10> nop 0x402b60c8 <gmtime+12> b.n 0x402b64ac 0x402b60ca <gmtime+14> movs r7, r0 --- snip ---
Unfortunately winedbg crashed all time while trying to dig deeper into glibc code.
So I switched over to a commercial JTAG debugger solution - not these toys ;-) After some hours of debugging I finally nailed it ...
The problem appears here:
gmtime() -> __tz_convert() -> tzset_internal() -> __tzfile_read()
http://www.eglibc.org/cgi-bin/viewvc.cgi/trunk/libc/time/tzfile.c?revision=2...
--- snip --- void __tzfile_read (const char *file, size_t extra, char **extrap) { static const char default_tzdir[] = TZDIR; size_t num_isstd, num_isgmt; register FILE *f; ... /* Read the POSIX TZ-style information if possible. */ if (sizeof (time_t) == 8 && tzspec != NULL) { /* Skip over the newline first. */ if (getc_unlocked (f) != '\n' || (fread_unlocked (tzspec, 1, tzspec_len - 1, f) != tzspec_len - 1)) tzspec = NULL; else tzspec[tzspec_len - 1] = '\0'; } else if (sizeof (time_t) == 4 && tzhead.tzh_version[0] != '\0') { /* Get the TZ string. */ ... tzspec_len = st.st_size - off - 1; char *tzstr = alloca (tzspec_len); if (getc_unlocked (f) != '\n' || (fread_unlocked (tzstr, 1, tzspec_len - 1, f) != tzspec_len - 1)) goto lose; tzstr[tzspec_len - 1] = '\0'; tzspec = __tzstring (tzstr); } ... --- snip ---
"fread_unlocked (tzstr, 1, tzspec_len - 1, f)" didn't come back, as it overwrote parts of the stack in fread_unlocked() -> _IO_sgetn().
The interesting part is the call to alloca() which looks like gcc builtin alloca code used to get a stack-based buffer for "tzstr" argument.
It seems that alloca() depends on proper stack alignment in caller. In relay case it always resulted in less than stack pointer during aligning of buffer.
= Without relay:
tz_convert entry: r13 = 0x409CFA58 __tzfile_read+0x714: r13 = 0x409CF938 -> r5 = 0x409CF938 (tzstr aligned)
= With relay:
tz_convert entry: r13 = 0x40A3F9A4 __tzfile_read+0x714: r13 = 0x40A3F884 -> r5 = 0x40A3F880 (tzstr aligned)
The ARM ABI requires that the stack be aligned to 8 bytes as it is noted in Procedure Call Standard for the ARM Architecture:
http://infocenter.arm.com/help/topic/com.arm.doc.ihi0042d/index.html
"SP must be 8-byte aligned on entry to AAPCS-conforming functions"
http://infocenter.arm.com/help/topic/com.arm.doc.ihi0046b/IHI0046B_ABI_Advis...
The origin of the problem (misaligned stack) can be traced back to Wine's relay debugging, specifically the "call_entry_point" function for ARM.
Source: http://source.winehq.org/git/wine.git/blob/1ceec8c78982d7ef5124e86a8da531664...
--- snip --- 358 #elif defined(__arm__) 359 __ASM_GLOBAL_FUNC( call_entry_point, 360 "push {r4, r5, LR}\n\t" 361 "mov r4, r0\n\t" 362 "mov r5, SP\n\t" 363 "lsl r3, r1, #2\n\t" 364 "cmp r3, #0\n\t" 365 "beq 5f\n\t" 366 "sub SP, SP, r3\n\t" 367 "bic SP, SP, #15\n\t" 368 "1:\tsub r3, r3, #4\n\t" 369 "ldr r0, [r2, r3]\n\t" 370 "str r0, [SP, r3]\n\t" 371 "cmp r3, #0\n\t" 372 "bgt 1b\n\t" 373 "cmp r1, #1\n\t" 374 "bgt 2f\n\t" 375 "pop {r0}\n\t" 376 "b 5f\n\t" 377 "2:\tcmp r1, #2\n\t" 378 "bgt 3f\n\t" 379 "pop {r0-r1}\n\t" 380 "b 5f\n\t" 381 "3:\tcmp r1, #3\n\t" 382 "bgt 4f\n\t" 383 "pop {r0-r2}\n\t" 384 "b 5f\n\t" 385 "4:\tpop {r0-r3}\n\t" 386 "5:\tblx r4\n\t" 387 "mov SP, r5\n\t" 388 "pop {r4, r5, PC}" ) --- snip ---
After the stack area for entry point register arguments has been reserved, the stack is aligned to 16 bytes (why here?). The entry point r0-rN values get written to the stack. Finally these values are put into r0-rN through "pop" instructions before calling the real entry point. Unfortunately if the entry point has an odd number of arguments the "pop" instructions cause a misalignment of the stack. While this is not a problem for "pure" Wine code this is bad for glibc.
If you make sure that the stack is at least 8-byte aligned before "blx" then relay tracing works properly for ARM. Already tested ;-)
Regards