[drmem] DrMemory doesn't handle thread creation correctly

[derekbruening]

From [email protected] on April 05, 2010 10:50:58

I've been testing Chromium base_unittests under DrMemory 1.0.10 on Windows and sometimes it was giving me some strange reports when threads were created.
I was able to reproduce these reports by running ThreadSanitizer unittests.
Here is a short reproducer:

#include <stdio.h>
#include <windows.h>

class MyThread {
public:
typedef void (*worker_t)();

MyThread(worker_t worker, const char *name = NULL)
:w_(worker), name_(name) {}

~MyThread(){}

void Start() {
DWORD thr_id = 0;
t_ = ::CreateThread(NULL, 0, (LPTHREAD_START_ROUTINE)ThreadBody, this, 0, &thr_id); // Line 15
}

void Join() {
::WaitForSingleObject(t_, INFINITE);
}

HANDLE tid() const { return t_; }
private:
static DWORD WINAPI ThreadBody(MyThread *my_thread) {
if (my_thread->name_) { // Line 25
printf("Started thread '%s'\n", my_thread->name_);
}
my_thread->w_(); // Line 28
return 0;
}
HANDLE t_;
worker_t w_;
const char *name_;
};

void foo() {
printf("foo()\n");
}

int main() {
MyThread mt(foo);
mt.Start();
mt.Join(); // Line 43
return 0;
}

To my mind, this code doesn't have any uninitialized reads.

Here is the report:
Error #1: UNINITIALIZED READ 136 byte(s)
Elapsed time = 0:00:00.734 in thread 5768
system call NtCreateThread

0x7c8106f5 <KERNEL32.dll+0x106f5> KERNEL32.dll!CreateThread+0x1e
??:0
0x00401149 <test.exe+0x1149> test.exe!MyThread::Start+0x29
z:\dr-sandbox\test.cc:15+0x19
0x0040108d <test.exe+0x108d> test.exe!main+0x1d
z:\dr-sandbox\test.cc:43+0x0
0x00401510 <test.exe+0x1510> test.exe!__tmainCRTStartup+0x15f
f:\dd\vctools\crt_bld\self_x86\crt\src\crt0.c:327+0x12
0x7c817077 <KERNEL32.dll+0x17077> KERNEL32.dll!RegisterWaitForInputIdle+0x49
??:0

Error #2: UNADDRESSABLE ACCESS 1 byte(s)
Elapsed time = 0:00:00.781 in thread 4368
0x7c91b02a <ntdll.dll+0x1b02a> ntdll.dll!RtlUnicodeStringToInteger+0x199
??:0

Error #3: UNADDRESSABLE ACCESS 1 byte(s)
Elapsed time = 0:00:00.781 in thread 4368
system call NtContinue

Error #4: UNINITIALIZED READ
Elapsed time = 0:00:00.797 in thread 4368
0x00401186 <test.exe+0x1186> test.exe!MyThread::ThreadBody+0x6
z:\dr-sandbox\test.cc:25+0x3
0x7c80b729 <KERNEL32.dll+0xb729> KERNEL32.dll!GetModuleFileNameA+0x1ba
??:0

Error #5: UNINITIALIZED READ
Elapsed time = 0:00:00.797 in thread 4368
0x004011a3 <test.exe+0x11a3> test.exe!MyThread::ThreadBody+0x23
z:\dr-sandbox\test.cc:28+0x3
0x7c80b729 <KERNEL32.dll+0xb729> KERNEL32.dll!GetModuleFileNameA+0x1ba
??:0

Original issue: http://code.google.com/p/dynamorio/issues/detail?id=286

[derekbruening]

From [email protected] on April 05, 2010 08:03:21

note to me: this is PR 534421

Status: Accepted

[derekbruening]

From [email protected] on May 21, 2010 07:45:47

Will it be fixed in the next release?

re: other issues being fixed - awesome! Can't wait to test 1.0.11 :-)

[derekbruening]

From [email protected] on May 21, 2010 08:46:59

This one I have not gotten to yet. I have Issue 284 as higher priority. I may put
out a release before these 2 b/c I'd like feedback on the new non-perl infrastructure
from real-world use.

[derekbruening]

From [email protected] on May 21, 2010 08:48:51

Sounds good.

[derekbruening]

From [email protected] on May 31, 2010 03:44:23

This may be related to issue #309

[derekbruening]

From [email protected] on June 16, 2010 15:15:05

Derek, what's the status on this issue?

Can you please point me at some functions which may be related to these false reports?
Looks like some of the "UNINITIALIZED READS" are from register and some of them are from stack.
Maybe the initialization in event_thread_init (drmemory/drmemory.c) or shadow_registers_thread_init (drmemory/shadow.c) is incomplete?
I think I can try some extra logging locally to find out what we're missing.

Cc: derek.bruening

[derekbruening]

From [email protected] on June 20, 2010 09:14:30

this is a known issue: not initializing shadow for initial structures for a new thread on Windows

I plan to re-open issue #117 to get the mcontext

[derekbruening]

From [email protected] on June 21, 2010 14:20:18

As far as I can see from the 117 and from the code, we can't get mcontext before the first basic block/trace of each thread is about to be executed.
a) is it difficult to know the mcontext on thread creation?
b) if a) is difficult -> we can workaround by having a per-thread shadow_values_initialized bit and call the appropriate function on the first bb/trace for each thread.

[derekbruening]

From [email protected] on June 23, 2010 06:59:22

a) no, it's not difficult for subsequent threads: for the initial thread, however, the whole scheme of DR init being split from starting execution does not make it easy to get the info to the events w/o changes that affect parts of the start/stop API, etc.

b) this is what I'm already doing for the process-initial mc.

I will probably go with a combination: providing mc for subsequent threads but not initial, and keeping the existing delayed init for the initial thread.

[derekbruening]

From [email protected] on June 27, 2010 17:46:11

status update: I have Dr. Memory properly handling new thread TEB and stack, and fixed a bug in handling 0-arg syscalls that showed up in my thread tests, but there are still a few uninits in new threads that I am tracking down.

[derekbruening]

From [email protected] on June 29, 2010 22:07:29

the uninits are from not propagating NtContinue CONTEXT shadow vals to regs, so it all looks good now. will export fix once finalized.

[derekbruening]

From [email protected] on July 02, 2010 08:25:19

in drmem r23 :

Fixed multiple false positives reported for each thread creation on Windows:

• set shadow defined for new thread TEB by querying post-NtCreateThread
  (TEB is allocated by kernel so we never see its allocation)
• set shadow unaddr for thread TEB dealloc on thread exit
• set full range of kernel-written stack on Ki routine
• set below-TOS to defined and beyond-TOS to unaddr in thread init,
  which required augmenting issue allow get_dr_mcontext() to be called from dr_init() and from event callbacks #117/PR 395156 to support getting
  the mcontext on (non-primary thread) thread init
• in DR r368 : fixed bug in interception buffer mapping where the jmp back
  was also considered on the original app code side, causing the bb after
  an interception to be hidden from the client, resulting in false
  positives b/c Dr. Memory did not see some KiAPC code!
• set register shadow values based on NtContine CONTEXT
• suppressed RtlAllocateActivationContextStack leak that shows
  up with _beginthreadex() under the assumption that it's a false positive:
  but see drmem issue update runregression for new open-source setup #8 where suppressed leaks still show up by default!
• fix erroneous 1 arg listed for 0-arg windows syscalls which caused
  uninit in NtTestAlert in new threads

Status: Fixed

[derekbruening]

From [email protected] on July 02, 2010 08:25:59

assigning for verify and close

Owner: [email protected]

[derekbruening]

From [email protected] on July 22, 2010 04:18:34

There's still a NtCreateThread report when CreateThread is called.
(See https://code.google.com/p/drmemory/issues/detail?id=13 )

The child-thread reports are not present anymore, so I mark this issue as Verified

Status: Verified