False reports on tests using sockets

[derekbruening]

From timurrrr@google.com on November 01, 2010 06:56:40

As of r79 , the attached test (which uses socket, bind, listen, accept, connect, send, recv) produces 5 unaddr and 35 uninit reports. The report is attached as well.

Among other reports, this one looks related to other false positives I've seen on various Chromium tests working with registry:

Error #9: UNINITIALIZED READ: reading 0x0012fb20-0x0012fb24 4 byte(s) within 0x0012fb20-0x0012fb24 @0:00:02.939 in thread 2384 system call NtQueryValueKey 0x77dd7b68 <ADVAPI32.dll+0x7b68> ADVAPI32.dll!RegQueryValueExA 0x71ab7451 <WS2_32.dll+0x7451> WS2_32.dll!WSAStartup 0x71ab7da4 <WS2_32.dll+0x7da4> WS2_32.dll!WSCEnumProtocols 0x71ab7cfe <WS2_32.dll+0x7cfe> WS2_32.dll!WSCEnumProtocols 0x71ab768c <WS2_32.dll+0x768c> WS2_32.dll!WSAStartup 0x71ab8017 <WS2_32.dll+0x8017> WS2_32.dll!WSCEnumProtocols 0x71ab7f5b <WS2_32.dll+0x7f5b> WS2_32.dll!WSCEnumProtocols 0x71ab7eaf <WS2_32.dll+0x7eaf> WS2_32.dll!WSCEnumProtocols

Attachment: test.cpp report.txt

Original issue: http://code.google.com/p/drmemory/issues/detail?id=68

[derekbruening]

From timurrrr@google.com on November 01, 2010 04:23:06

I've suppressed all (or most of?) the warnings with these suppressions:

UNINITIALIZED READ ... WS2_32.dll!*

UNINITIALIZED READ ... ADVAPI32.dll!SetSecurityDescriptorDacl

UNINITIALIZED READ ... ADVAPI32.dll!RegValue

UNINITIALIZED READ ... MSWSOCK.dll!WSPStartup

UNADDRESSABLE ACCESS ... MSWSOCK.dll!WSPStartup

UNINITIALIZED READ ... ntdll.dll!RtlValidateUnicodeString

UNADDRESSABLE ACCESS ... ntdll.dll!RtlValidateUnicodeString

[derekbruening]

From timurrrr@google.com on November 01, 2010 04:23:30

What looks strange to me is that most of the time I start the tool it doesn't print out the stats after the run. The results.txt/global..txt files look interrupted in the middle of error printing - looks like the test crashes while printing the errors.

Cc: derek.bruening
Labels: -Priority-Low Priority-Medium Bug-ToolCrash

[derekbruening]

From timurrrr@google.com on November 01, 2010 06:46:03

More info on the crash

suppress.txt ends with UNINITIALIZED READ WSHTCPIP.dll!WSHGetSockaddrType MSWSOCK.dll! MSWSOCK.dll! ...

UNADDERSSABLE ACCESS IMM32.dll!CtfImmDispatchDefImeMessage

results.txt ends with Error #50: UNINITIALIZED READ: reading register eax @0:00:10.444 in thread 3372 0x71a912a3 <WSHTCPIP.dll+0x12a3> WSHTCPIP.dll!WSHGetSockaddrType ??:0 0x71a54e68 <MSWSOCK.dll+0x4e68> MSWSOCK.dll!? ??:0 0x71a56a32 <MSWSOCK.dll+0x6a32> MSWSOCK.dll!? ??:0 ...

global.PID.log ends with

Error #50: UNINITIALIZED READ: reading register eax @0:00:10.444 in thread 3372 0x71a912a3 <WSHTCPIP.dll+0x12a3> WSHTCPIP.dll!WSHGetSockaddrType ??:0 0x71a54e68 <MSWSOCK.dll+0x4e68> MSWSOCK.dll!? ??:0 0x71a56a32 <MSWSOCK.dll+0x6a32> MSWSOCK.dll!? ??:0 ...

Looks like it's crashing while printing the CtfImm... suppression?

[derekbruening]

From timurrrr@google.com on November 01, 2010 07:16:43

I think I've found the crashy error, will send a patch soon.

Status: Started

[derekbruening]

From timurrrr@google.com on November 01, 2010 08:19:37

Nope, my guess was wrong. I've modified the test slightly (new version attached) and now it hangs under Dr.Memory at approximately the same place in the test as it was crashing silently before.

Attachment: test.cpp

[derekbruening]

From timurrrr@google.com on November 01, 2010 10:22:44

The hang has stopped reproducing for me for some unknown reason. D'oh!

[derekbruening]

From timurrrr@google.com on November 01, 2010 11:07:39

After inserting verbosity printing with 'cout << "ADSAD\n"; cout.flush();" into the test it looks like there is some sort of a data race in Dr. Memory.

With the attached source code the output ends with: CCC2 DDD2 Trying to connect to server... FFF GGG1 Waiting for an inc (note the last line is incomplete)

Which means it stops when one thread does closesocket() and the other calls cout << "...";

Attachment: test.cpp

[derekbruening]

From timurrrr@google.com on November 01, 2010 11:17:29

I've added some NOTIFYs into the report.c/report_error and I can clearly see that it is called from one thread when the other is printing "waiting for an incoming connection".

[derekbruening]

From timurrrr@google.com on November 02, 2010 07:01:39

Looks like the race happens when two threads execture NtClose. Derek, any ideas?

Server has sent us "HELLO!"! Client before closesocket Server bef inserted into delay_free_tree: 0x001793e0-0x00179458 0 delayed free queue not full: delaying 313-th free of 0x001793e0-0x00179458 auxarg=0x00150000 free-pre client 15 changing base from 0x001793e0 to 0x00000000 found new retaddr: call to RtlFreeHeap from 0x71a91345 flushing 0x71a91345, should re-appear at 0x7c90ff2d processing pre system call `#200` NtRequestWaitReplyPort processing post system call `#200` NtRequestWaitReplyPort total size of PORT_MESSAGE arg 1 is 152 in event_basic_block(tag=0x71a91345) inside heap routine: adding nop-if-mem-unaddr checks exiting heap routine: NOT adding nop-if-mem-unaddr checks leaving alloc routine 0x7c90ff2d RtlFreeHeap in event_basic_block(tag=0x71a5412c) in event_basic_block(tag=0x71a54141) call\* @0x71a54142 tgt 0x7c90cfee processing pre system call `#25` NtClose ... call\* @0x71a54142 tgt 0x7c90cfee processing pre system call `#25` NtClose processing post system call `#25` NtClose in event_basic_block(tag=0x71a54148) in event_basic_block(tag=0x71a5455f) call\* @0x71a54560 tgt 0x7c90cfee processing pre system call `#25` NtClose **Attachment:** [test.cpp](http://code.google.com/p/drmemory/issues/detail?id=68#hc9)

[derekbruening]

From timurrrr@google.com on November 02, 2010 07:16:00

(the logs were collected with "-verbose 2")

[derekbruening]

From timurrrr@google.com on November 02, 2010 07:56:02

With the attached patch applied to Dr. Memory (adds some NOTIFYs when executing process_pre_syscall_reads_and_writes() for NtClose=25 on XP) it fails after the following lines of output: :::Dr.Memory::: PRE syscall NtClose, args_size = 4 :::Dr.Memory::: PRE syscall pre check defined :::Dr.Memory::: PRE syscall post check defined; num_args = 1 :::Dr.Memory::: 000 :::Dr.Memory::: PRE syscall post all Server has sent us "HELLO!"! Client before closesocket Server before closesocket :::Dr.Memory::: PRE syscall NtClose, args_size = 4 :::Dr.Memory::: PRE syscall pre check defined :::Dr.Memory::: PRE syscall post check defined; num_args = 1 :::Dr.Memory::: 000 :::Dr.Memory::: PRE syscall post all :::Dr.Memory::: PRE syscall NtClose, args_size = 4

The DrM source lines to be executed next are: <drmemory/syscall.c> 310 if (sysnum == 25) NOTIFY("PRE syscall %s, args_size = %d\n", 311 sysinfo->name, sysinfo->args_size); 312 num_args = IF_WINDOWS_ELSE(sysinfo->args_size/sizeof(reg_t), 313 sysinfo->args_size); 314 /* Treat all parameters as IN. 315 * There are no inlined OUT params anyway: have to at least set 316 * to NULL, unless truly ignored based on another parameter. 317 */ 318 if (sysnum == 25) NOTIFY("PRE syscall pre check defined\n");

Hmmm...

Attachment: ntclose.patch

[derekbruening]

From derek.br...@gmail.com on November 02, 2010 08:29:33

I can't reproduce any problems, but I'm using a VM (though with 2 VCPUs)

I'm not quite sure I understand the symptoms: you've seen both a crash and a hang? What were the callstacks during the hang (via windbg)? For the crash, attach windbg in the middle and see where it's crashing (probably won't hit any deliberate shadow faults in such a small app). Also, you can use -thread_logs to split the global log into per-thread files.

[derekbruening]

From timurrrr@google.com on November 02, 2010 08:35:29

I think I can't reproduce the hang anymore (not sure how it was happening) I'm on a VM with 2VCPUs too.

Will try windbg

[derekbruening]

From bruen...@google.com on April 25, 2011 14:48:26

the RegQueryValueKey mentioned in comment 1 may be issue #358

[derekbruening]

From timurrrr@google.com on May 03, 2011 07:27:55

NtQueryValueKey is mentioned in issue #358 too.

Cc: -derek.br...@gmail.com bruen...@google.com

[derekbruening]

From bruen...@google.com on May 03, 2011 07:38:05

not sure what you mean in comment 15 beyond comment 14

ioctl handling in issue #359 will probably address many of the other uninits here. I'll take this over to ensure the ioctls cover this test app.

Owner: bruen...@google.com
Cc: -bruen...@google.com timurrrr@google.com

[derekbruening]

From bruen...@google.com on May 03, 2011 08:27:06

unfortunately there are graphical syscalls in this app so ioctls alone won't get it to zero. still a useful target.

[derekbruening]

From timurrrr@google.com on May 03, 2011 08:41:46

graphical syscalls You mean the guts of winsock do some graphical syscalls?

Besides graphics syscalls - will the ioctl warnings disappear?

[derekbruening]

From bruen...@google.com on May 03, 2011 12:55:42

net_unittests.exe --gtest_filter="URLRequestTestHTTP.ProxyTunnelRedirectTest" does not have any of these, but this app does. things like:

Error #2: UNINITIALIZED READ: reading register ecx @0:00:03.962 in thread 6492 0x76527970 <USER32.dll+0x17970> USER32.dll!GetSysColor ??:0 0x7652affd <USER32.dll+0x1affd> USER32.dll!InitClientDrawing ??:0 0x7652b146 <USER32.dll+0x1b146> USER32.dll!ClientThreadSetup ??:0 0x7652c5ad <USER32.dll+0x1c5ad> USER32.dll!__ClientThreadSetup ??:0 0x7652ac6e <USER32.dll+0x1ac6e> USER32.dll!_UserClientDllInitialize ??:0 0x77bd9960 <ntdll.dll+0x39960> ntdll.dll!LdrpCallInitRoutine ??:0 0x77bdd8c9 <ntdll.dll+0x3d8c9> ntdll.dll!LdrpRunInitializeRoutines ??:0 0x77bdd78c <ntdll.dll+0x3d78c> ntdll.dll!LdrpLoadDll ??:0 0x77bdc4e5 <ntdll.dll+0x3c4e5> ntdll.dll!LdrLoadDll ??:0 0x76621d2a <KERNELBASE.dll+0x11d2a> KERNELBASE.dll!LoadLibraryExW ??:0 0x770e8b55 <WS2_32.dll+0x8b55> WS2_32.dll!DPROVIDER::Initialize ??:0 0x770e8972 <WS2_32.dll+0x8972> WS2_32.dll!DCATALOG::LoadProvider ??:0 0x770e89da <WS2_32.dll+0x89da> WS2_32.dll!DCATALOG::GetCountedCatalogItemFromAttributes ??:0 0x770e3d70 <WS2_32.dll+0x3d70> WS2_32.dll!WSASocketW ??:0 0x770e3f56 <WS2_32.dll+0x3f56> WS2_32.dll!socket ??:0 0x004019ce < issue68 .exe+0x19ce> issue68 .exe!ClientThread c:\src\dr\test\ issue68 .cpp:75 0x76793677 <KERNEL32.dll+0x13677> KERNEL32.dll!BaseThreadInitThunk ??:0 0x77bd9f02 <ntdll.dll+0x39f02> ntdll.dll!__RtlUserThreadStart ??:0 0x77bd9ed5 <ntdll.dll+0x39ed5> ntdll.dll!_RtlUserThreadStart ??:0

looks like it's using a different set of ioctls from ProxyTunnelRedirectTest