[BUG] WSAEFAULT

[Kiddinglife]

Problem

Brieftly to say, the erorr is overlapped WSARecv call in gRPC that fails with a WSAEFAULT error.

What version of gRPC and what language are you using?

1.37.1

What operating system (Linux, Windows,...) and version?

windows 10

What runtime / compiler are you using (e.g. python version or version of gcc)

Python3.9 and VS2019 compiler

What did you do?

Run an sample ping-pong program with server side written by c++ and client side written written by csharp. let it run whole night.

What did you expect to see?

no errors

What did you see instead?

WSAEFAULT

I suspect if this line of code causes the bug

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 290 in ea389c0

if (info->wsa_error != WSAEWOULDBLOCK) {

according to the msdn api doc,

WSAEWOULDBLOCK | Windows NT:  Overlapped sockets: there are too many outstanding overlapped I/O requests. Nonoverlapped sockets: The socket is marked as nonblocking and the receive operation cannot be completed immediately.

is it handled correctly when the error is other than WSAEWOULDBLOCK ? so I am wondering if the right check here is if (info->wsa_error == 0)
Also why not continuing reading more data when the received bytes == the recv buffer size in case there are more data in the socket buffer. there shoudl be a while loop for non-overlapped wsarecv until it got ewouldblock error.

I also suspect if this line of code causes the bug.

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 299 in ea389c0

&bytes_read, &flags, &info->overlapped, NULL);

according to msdn api doc,

lpNumberOfBytesRecvd
A pointer to the number, in bytes, of data received by this call if the receive operation completes immediately.
Use NULL for this parameter if the lpOverlapped parameter is not NULL to avoid potentially erroneous results. This parameter can be NULL only if the lpOverlapped parameter is not NULL.

So I am wondering if &bytes_read shoudl be changed to NULL.

Also I am wondering how this piece of code works ?

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 192 in ea389c0

if (info->wsa_error != 0 && !tcp->shutting_down) {

why it is checking tcp->shutting_down instead of checking the retunred error code from wsarecv to detect the local/remote socket shutdown ?
Also why it does not apply the locker when read the value of tcp->shutting_down ? I can see it is protected with locker when set to true.

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 456 in ea389c0

static void win_shutdown(grpc_endpoint* ep, grpc_error_handle why) {

Also why not using the erro code from the next time wsarecv or wsasend to detect the local/remote socket abort/shutdown. The use of tcp-shutting_down looks a bit doggy.

Also there is inconsistency here:

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 292 in ea389c0

grpc_core::ExecCtx::Run(DEBUG_LOCATION, &tcp->on_read, GRPC_ERROR_NONE);

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 311 in ea389c0

grpc_socket_notify_on_read(tcp->socket, &tcp->on_read);

finally I am wondering if it is correct to mix use of overlapped and non-overlapped wsarecv api ?
when you created the socket, I can see it is overlapped socket. but why the non-overlapped wsarecv is used here ?

grpc/src/core/lib/iomgr/socket_windows.cc

Line 188 in fd3bd70

s_wsa_socket_flags = WSA_FLAG_OVERLAPPED;

Proposed Solution:
The way to operate with winsock in grpc looks a little bit doggy. the winsock apis are quite hard to make it right.
Please refer to the libuv as an example about how to operate winsock: either use overlapped or non-overlapped wsarecv.
overlapped wsarecv: https://github.com/libuv/libuv/blob/9918a1743816dc49d6c664e41641d78ffd4a0705/src/win/tcp.c#L513
non-overlapped wsarecv: https://github.com/libuv/libuv/blob/9918a1743816dc49d6c664e41641d78ffd4a0705/src/win/tcp.c#L1068

I will recompile the grpc with the proposed changes later and then let us see how it goes.

[drfloob]

Hi @Kiddinglife. Following up, did you determine there was no bug here?

[Kiddinglife]

I am now testing it with 1.40.0 I can see there is bug fix in that version regarding to windsock.

[Kiddinglife]

Not working.

[nicolasnoble]

Do you have the exact line of code from the logs or trace that triggered the WSAEFAULT?

[yashykt]

@nicolasnoble please correct me if I'm wrong -

 I suspect if this line of code causes the bug
grpc/src/core/lib/iomgr/tcp_windows.cc

Line 290 in ea389c0

 if (info->wsa_error != WSAEWOULDBLOCK) { 

according to the msdn api doc,
WSAEWOULDBLOCK | Windows NT:  Overlapped sockets: there are too many outstanding overlapped I/O requests. Nonoverlapped sockets: The socket is marked as nonblocking and the receive operation cannot be completed immediately.

is it handled correctly when the error is other than WSAEWOULDBLOCK ? so I am wondering if the right check here is if (info->wsa_error == 0)

We are only checking for WSAEWOULDBLOCK since that's the only case we would want to try an asynchronous read. For all other cases, the on_read callback should be able to deal with them.

I also suspect if this line of code causes the bug.
grpc/src/core/lib/iomgr/tcp_windows.cc

Line 299 in ea389c0

 &bytes_read, &flags, &info->overlapped, NULL); 

according to msdn api doc,
lpNumberOfBytesRecvd
A pointer to the number, in bytes, of data received by this call if the receive operation completes immediately.
Use NULL for this parameter if the lpOverlapped parameter is not NULL to avoid potentially erroneous results. This parameter can be NULL only if the lpOverlapped parameter is not NULL.

So I am wondering if &bytes_read shoudl be changed to NULL.

I'm not sure about this but it doesn't seem to be used anyway, so it should be safe to use NULL. #27361

Also I am wondering how this piece of code works ?
grpc/src/core/lib/iomgr/tcp_windows.cc

Line 192 in ea389c0

 if (info->wsa_error != 0 && !tcp->shutting_down) { 

why it is checking tcp->shutting_down instead of checking the retunred error code from wsarecv to detect the local/remote socket shutdown ?
Also why it does not apply the locker when read the value of tcp->shutting_down ? I can see it is protected with locker when set to true.

That does seem to be the case. @nicolasnoble do we need a lock here?

Also why not using the erro code from the next time wsarecv or wsasend to detect the local/remote socket abort/shutdown. The use of tcp-shutting_down looks a bit doggy.

The win_shutdown is an API for internal gRPC usage to let the socket library know that it is done with the socket and that all read/write callbacks should be failed.

Also there is inconsistency here:
grpc/src/core/lib/iomgr/tcp_windows.cc

Line 292 in ea389c0

 grpc_core::ExecCtx::Run(DEBUG_LOCATION, &tcp->on_read, GRPC_ERROR_NONE); 

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 311 in ea389c0

 grpc_socket_notify_on_read(tcp->socket, &tcp->on_read); 

These achieve two separate things. In the first case, we already have a result from the read call and we just want to invoke the on_read callback to work on the result and in the second case grpc_socket_notify_on_read, the read is asynchronous and we are waiting on an IO notification that the read is done.

finally I am wondering if it is correct to mix use of overlapped and non-overlapped wsarecv api ?
when you created the socket, I can see it is overlapped socket. but why the non-overlapped wsarecv is used here ?

I believe the reason is a shorthand for performance reasons, so as to avoid an asynchronous path .

[yashykt]

(Closed by mistake by clicking on Close with comment instead of Comment)

[nicolasnoble]

What I'm really asking is for a log extract so I can see more specifically what's going on here. I have no idea what line of code in our codebase can emit the "overlapped WSARecv call in gRPC that fails with a WSAEFAULT error" message for instance. So before actually committing to investigate further, I'd like to make sure we have enough context and data, which we don't.

[Kiddinglife]

Hey @nico I am now also very confused about the error. you got efault error and then stream removed and disconnected. Nothing special I would say so. As I said, I am doubting if there is a buffer slice overwrite/corruption no matter in heap/stack due to the potential race condition in iocp and background threads. I am now doing the experiment with only using the first wsarecv and logging the buffer slice address to see if I can find something special. Also it will be helpful if you can show me where those iocp and background threads operate those buffer slices ? is there any possibility the buffer slices somehow is used after freed or pointing to somewhere out of process virtual address boundary ? for example, the tcp->read_slices->count is decremented by other thread but without locker and the background thread uses the wrong count to initialize the WSABUF buffers[MAX_WSABUF_COUNT];. in such case, some buffer's pointer is not assigned correctly and keeps some random values. and thus cause efault error.

[yashykt]

Hi @Kiddinglife, @nicolasnoble said, if you can provide logs/traces that show the error that would be very helpful.

[cfandrich]

Hi @yashykt,
The error we see in the logs is the following:

[2021-9-20 14:4:43.597] GRPCPlugin(Runtime) [3016] INFO: OP[message_decompress:185D1400]: CANCEL:{"created":"@1632164683.597000000","description":"Error in HTTP transport completing operation","file":"E:\GDK-VLT\Runtime\core\GDK\Externals\gRPC_1_40_0\src\core\ext\transport\chttp2\transport\chttp2_transport.cc","file_line":1236,"referenced_errors":[{"created":"@1632164683.597000000","description":"Attempt to send initial metadata after stream was closed","file":"E:\GDK-VLT\Runtime\core\GDK\Externals\gRPC_1_40_0\src\core\ext\transport\chttp2\transport\chttp2_transport.cc","file_line":1472,"referenced_errors":[{"created":"@1632164683.595000000","description":"Endpoint read failed","file":"E:\GDK-VLT\Runtime\core\GDK\Externals\gRPC_1_40_0\src\core\ext\transport\chttp2\transport\chttp2_transport.cc","file_line":2520,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1632164683.594000000","description":"OS Error","file":"E:\GDK-VLT\Runtime\core\GDK\Externals\gRPC_1_40_0\src\core\lib\iomgr\tcp_windows.cc","file_line":307,"os_error":"The system detected an invalid pointer address in attempting to use a pointer argument in a call.\r\n","syscall":"WSARecv","wsa_error":10014}]}]},{"created":"@1632164683.597000000","description":"Attempt to send trailing metadata after stream was closed","file":"E:\GDK-VLT\Runtime\core\GDK\Externals\gRPC_1_40_0\src\core\ext\transport\chttp2\transport\chttp2_transport.cc","file_line":1548}],"target_address":"ipv6:[::1]:50506"}

[yashykt]

#27457 might be related

[cfandrich]

@yashykt - That looked promising but we were still able to reproduce the WSAEFAULT error on the overlapped WSARecv call even after removing the memset call (for #27457).

[yashykt]

@nicolasnoble is driving this

[Schramp]

I am concerned the fact that the WSABUF buffers[MAX_WSABUF_COUNT] is allocated on the stack is problematic. Could that explain the error reported by @cfandrich ?

grpc/src/core/lib/iomgr/tcp_windows.cc

Line 248 in ea389c0

WSABUF buffers[MAX_WSABUF_COUNT];

I have similar concerns for the WSASend side.

[drfloob]

This issue has become a collection of Windows I/O bugs, some of which have been fixed. I'm going to focus exclusively on the WSAEFAULT and its reproduction cases. For any other issues, please file another issue if they are still relevant.

@cfandrich can you create a minimal, complete example that reproduces this issue? If it is still reproducible on the latest gRPC version, I'll be curious to dig in. If you suspect use-after-free, and can't produce an example, then consider using some Windows tools (some built into visual studio) that can help catch various memory corruption problems. You could consider running your application with a JIT debugger enabled, or running it in a debugger with various detection tools enabled.

I am concerned the fact that the WSABUF buffers[MAX_WSABUF_COUNT] is allocated on the stack is problematic.

@Schramp I believe we discussed this on another issue, and it is fine per the Windows API spec.

[Schramp]

I am concerned the fact that the WSABUF buffers[MAX_WSABUF_COUNT] is allocated on the stack is problematic.

@Schramp I believe we discussed this on another issue, and it is fine per the Windows API spec.

yes, we already discussed this (#28432 (comment)), and you rightfully corrected me on my misunderstanding of the API. So you should ignore my remark on the stack allocation of buffers[MAX_WSABUF_COUNT]

[grpc-bot]

More than 30 days have passed since label "disposition/requires reporter action" was added. Closing this issue. Please feel free to re-open/create a new issue if this is still relevant.