[Bug 32990] New: 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()

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: [e-mail]
        ReportedBy: [e-mail]
    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

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

Anastasius Focht  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail],
                   |                            |[e-mail]

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

André H.  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|[e-mail]       |
         AssignedTo|[e-mail]        |[e-mail]

--- Comment #1 from André H.  2013-02-16 15:26:16 CST ---
Assigning to me, should be easy to fix, needs some tests though.
Unrelated to Vincent.

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

--- Comment #2 from André H.  2013-02-18 16:26:08 CST ---
http://www.winehq.org/pipermail/wine-patches/2013-February/122303.html
tested with 7zFM, putty and own winelib testapp.
hard-float arguments are not yet supported, though...

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

André H.  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
      Fixed by SHA1|                            |242da6708202c1bd4835e49e2dd
                   |                            |2315c95ba0e24
             Status|NEW                         |RESOLVED
         Resolution|                            |FIXED

--- Comment #3 from André H.  2013-02-19 13:38:59 CST ---
patch got in -> fixed in todays git

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

--- Comment #4 from Alexandre Julliard  2013-03-01 14:50:59 CST ---
Closing bugs fixed in 1.5.25.

[Bug 32990] 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()

http://bugs.winehq.org/show_bug.cgi?id=32990

Alexandre Julliard  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #5 from Alexandre Julliard  2013-03-01 15:10:28 CST ---
Really closing bugs fixed in 1.5.25.

[Bug 32990] 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()

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=32990

Anastasius Focht  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
           Assignee|[e-mail]            |[e-mail]