net: ExecIO invalid number of bytes written

[bioothod]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version devel +ffedff7 Sun Jan 8 00:01:30 2017 +0000 linux/amd64

What operating system and processor architecture are you using (go env)?

It is linux, but go was cross-compiled for windows

While debugging bug in grpc-go server bugs grpc/grpc-go#1054 I added several debug prints to find out why bufio.Flush() sometimes returns short write error when flushing data into http2 connection, in particular, I checked number of bytes returned from netFD.Write() method, and although most of the time it returned smaller number of bytes than buffer size, I got this error once:

Write: ExecIO: n: 38, len: 33

I.e. len(buf) in this method returns 33, but ExecIO returned 38.

How is it possible?

[bioothod]

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/zbr/awork/go"
GORACE=""
GOROOT="/home/zbr/awork/gosrc"
GOTOOLDIR="/home/zbr/awork/gosrc/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="x86_64-w64-mingw32-gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build080248458=/tmp/go-build -gno-record-gcc-switches"
CXX="x86_64-w64-mingw32-g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

[bradfitz]

What version of Go?

[bioothod]

go version devel +ffedff7 Sun Jan 8 00:01:30 2017 +0000 linux/amd64

A git clone from about a month ago

[bradfitz]

Sorry, I meant what version of Windows?

[bioothod]

Hmm, its wine 2.0-rc1 :)

[bradfitz]

Could you file a bug with Wine instead?

It's hard enough supporting a dozen operating systems without also supporting Windows-on-Linux (#18537 etc) and Linux-on-Windows (#17365 etc).

[bioothod]

You think its a good idea to ask wine developers about why some internal method in the deep windows runtime core of golang returns invalid number of bytes?

[bradfitz]

It's Wine's job to act like Windows.

If a program (e.g. grpc-go's test suite) runs fine on Windows but doesn't run on Wine, then it's a bug in Wine.

I don't care how the Wine developers debug it. I'm just saying it's not Go's job to adapt to their differences in behavior. ("bugs")

If a user has Wine bugs with a Go program, they can just use their Go program on Linux, FreeBSD, NetBSD, OpenBSD, Mac OS X, Dragonfly BSD, Plan 9, Solaris, or other operating systems that Go natively supports.

There's no reason for users to subject themselves to Wine, right? What am I missing?

[bioothod]

I can not ask wine developers to debug issues like network connection write returning invalid number of bytes, since there are so many levels prior calling real syscall which writes the data.
If syscall6() returns invalid number of bytes, it is pretty likely a wine problem. But yet there is a whole ioSrv on top of the low-level networking syscalls, and given that network in wine works too, I'd rather investigate higher levels first, hence an issue with a question in golang.

[bradfitz]

Why are you using Wine?

[bioothod]

That's actually a pretty frequent issue, and it doesn't look like something is broken (it is not until it is flush call, and as a workaround I will submit a proof-of-concept patch which spins inside Flush() method, well, flushing data into the writer, and only returns after error):

WSASend: fd: 136, buf: {Len:30 Buf:0x5b77e000}, qty: 38, len: 30, o: {Internal:0 InternalHigh:30 Offset:0 OffsetHigh:0 HEvent:0}, e: <nil>
WSASend: fd: 136, buf: {Len:37 Buf:0x5b77e000}, qty: 38, len: 37, o: {Internal:0 InternalHigh:37 Offset:0 OffsetHigh:0 HEvent:0}, e: <nil>

print above was made from the following debug patch:

diff --git a/src/net/fd_windows.go b/src/net/fd_windows.go
index a976f2a..4db6ba9 100644
--- a/src/net/fd_windows.go
+++ b/src/net/fd_windows.go

@@ -500,9 +510,18 @@ func (fd *netFD) Write(buf []byte) (int, error) {
        }
        o := &fd.wop
        o.InitBuf(buf)
-       n, err := wsrv.ExecIO(o, "WSASend", func(o *operation) error {
-               return syscall.WSASend(o.fd.sysfd, &o.buf, 1, &o.qty, 0, &o.o, nil)
+       n, err := wsrv.ExecIO(o, "WSASend1", func(o *operation) error {
+               len := o.buf.Len
+               e := syscall.WSASend(o.fd.sysfd, &o.buf, 1, &o.qty, 0, &o.o, nil)
+               if o.qty != len {
+                       fmt.Printf("WSASend: fd: %+v, buf: %+v, qty: %d, len: %d, o: %+v, e: %v\n",
+                               o.fd.sysfd, o.buf, o.qty, len, o.o, e)
+               }
+               return e
        })
+       if n != len(buf) || err != nil {
+               fmt.Printf("Write: ExecIO: n: %d, len: %d, error: %v\n", n, len(buf), err)
+       }
        if _, ok := err.(syscall.Errno); ok {
                err = os.NewSyscallError("wsasend", err)
        }

[bradfitz]

/cc @alexbrainman as FYI

[bioothod]

@bradfitz
I have a side project which have to deal with DLL provided by third parties. I decided to create a simple grpc/http service instead of wrapping everything around functions from that DLL, and golang won because it is very convenient for these kind of services.
I didn't want to mess with mingw and boost to write a simple server though.

Since I work on linux and do not really know windows ecosystem, I decided to work with wine (first).

[bradfitz]

@bioothod, fair enough. I just want you to know that you're in uncharted waters. Good luck.

[bioothod]

@bradfitz I understand that, and thnk you. Though it is not that much different from some other complex system one has to have to deal with, its just takes some time to get into

[bradfitz]

/cc @johnsonj too

Jeff, this isn't a priority for us since it works on Windows and only fails on Wine, but it might be interesting to you anyway to verify that we're using the Win32 API correctly and not making too many assumptions. Maybe we're just getting lucky.

[alexbrainman]

print above was made from the following debug patch

So, if I read your output correctly, WSASend is asked to send 30 (or 37) bytes, and returned that it has sent 38 bytes. That sounds wrong to me. Mind you, the WSASend might be returning error. Does it return error?

Alex

[bioothod]

Yup, it looks like it was asked to send 30 bytes, but it returns 38. It looks like it is always 38, but I'm not 100% sure. There is no error in this case, both errno and return value are zero.

According to this https://msdn.microsoft.com/en-us/library/windows/desktop/ms742203(v=vs.85).aspx, it is not recommended to use &qty both with overlapped pointer

Use NULL for this parameter if the lpOverlapped parameter is not NULL to avoid potentially erroneous results

I will investigate it further.

[bioothod]

@alexbrainman you know, just setting overlapped pointer to nil fixes the problem.

No matter what @bradfitz and his fellow legal friends will tell about patches in github, but this is roughly the fix I use, and it passes my grpc test under quite a load of about 50 ping-pong krps which golang under wine never passed before

diff --git a/src/net/fd_windows.go b/src/net/fd_windows.go
index a976f2a..e588dec 100644
--- a/src/net/fd_windows.go
+++ b/src/net/fd_windows.go

-       n, err := wsrv.ExecIO(o, "WSASend", func(o *operation) error {
-               return syscall.WSASend(o.fd.sysfd, &o.buf, 1, &o.qty, 0, &o.o, nil)
+       n, err := wsrv.ExecIO(o, "WSASend", func(o *operation) error {
+               return syscall.WSASend(o.fd.sysfd, &o.buf, 1, &o.qty, 0, nil, nil)

[bioothod]

It requires a bit more overlapped work, namely only accept/connect/cancel use this structure now. What do you think, should I submit a patch?

[johnsonj]

@bioothod @alexbrainman do we allow the creation of overlapped sockets in the first place? A little grep-ing doesn't show any exposure. This could be a case of Wine not ignoring lpOverlapped when WSA_FLAG_OVERLAPPED is not set.

[bioothod]

Well, some code uses *Ex() family of functions (namely connect/accept) which have to accept overlapped sockets and according to msdn all sockets are created with this feature by default. But I never ever saw how golang parses or somehow uses this structure, so it might be safe just to remove it.

[johnsonj]

Do you know if this only occurs with multiple writes? It'd be great to see a min-repro or failing test in golang.

I'm curious if we're passing Win32 a pointer then re-using it again for a subsequent call before it's completed. We need to allocate a unique lpOverlapped for each WSASend:

The lpOverlapped parameter must be valid for the duration of the overlapped operation. If multiple I/O operations are simultaneously outstanding, each must reference a separate WSAOVERLAPPED structure. msdn

Setting the lpOverlapped param to nil will make the socket non-async which is not desirable.

If both lpOverlapped and lpCompletionRoutine are NULL, the socket in this function will be treated as a non-overlapped socket. msdn

[bioothod]

It does happen with single writer too.

It looks like all sockets are potentially overlapped (I did not understand whether it is required or not to set WSA_FLAG_OVERLAPPED bit though) but we do not ever set completion function at all, i.e. we somehow partially setup async operation: we have control overlapped structure, but we do not have completion callback, and it is enough to work on real windows. This probably is somehow worked out in windows, but we do not use WSAGetOverlappedResult() either which should be used to find out status of the pending operations without completion callback.

My patch makes it clear that we do not have async sockets, which we did not have anyway - WSASend() works like usual send() on real windows and behaves badly on wine, since we neither provide completion handler nor use WSAGetOverlappedResult(). Also, we do reuse overlapped control structure for all operations, which might lead to serious data corruption bugs.

As of whether this bug is a wine bug or not - I'm not sure it is wine, since msdn clearly says that it is possible to have error if both sent bytes and overlapped pointers are set

Use NULL for this parameter if the lpOverlapped parameter is not NULL to avoid potentially erroneous results
https://msdn.microsoft.com/en-us/library/windows/desktop/ms742203(v=vs.85).aspx

and the fact that native windows does not expose this behaviour doesn't mean it will not in some future versions. Wine kind of pays it forward :)

[johnsonj]

Sorry to clarify- multiple writes meaning more than a single send on a given socket. Not necessarily multiple goroutines because a socket opened with ConnectEx will be async and return before the write is completed. Which is why Windows wants us to have a callback or a struct to talk back to us when it completes.

It could simply be a timing issue that doesn't repro in Windows today but I agree we are using the API incorrectly. We shouldn't look at (or pass in a handle for writing) lpNumberOfBytesSent for an async sockets. We should be providing a callback or a non-shared lpOverlapped for async sockets.

Perhaps we extend ConnectEx to take a user callback and use this for writes? If a user is creating async sockets they should be keeping an eye on the results.

[bioothod]

I didn't check how grpc sends data, but my protocol implies request-response of quite small messages (like 20-30 bytes), so I believe they all are being sent with single write-single read in a loop one after another.

Sometimes I got this error quickly after the start, it looks like it could be the race you mentioned but on the server side after it just had accepted the client and started to send him the first message. It can be completely different though.

Changing windows code to be fully async is a nice way to go, but it will not be much of a profit, since there are no users out there who might fully utilize this feature - there is no api and there are no other operation systems who might implement it as well. Quite contrary, using common send() without all these features is quite common and accepted by the industry, and, well, MUCH simpler to implement at least in a short term.

[bradfitz]

No, grpc has separate goroutines doing writes and doing reads. It's not one goroutine alternating between the two tasks.

[johnsonj]

As far as I can tell, we use ConnectEx when possible which means network writes on windows are async today. I'll defer to @alexbrainman to see if this is intended.

The fix of passing a nil lpOverlapped changes all windows sockets to behave as synchronous sockets (same as linux?), but it is a behavior change.

[bioothod]

You are right, there is async IO and it should work if fd and its operation fields (read or write) are not shared. If grpc happens to write into the same connection from multiple goroutines in parallel, this probably can lead to data corruption because of reused overlapped control structure.

My patch which dropped overlapped structure from read and write path (actually they both seems to be affected on wine) simply turned async sockets into sync, and it either "fixed" this race or just disabled wine-specific artefacts.

It looks like testing this possible overlapped bug will be a bit more challenging - I not only have to allocate overlapped control structure per WSASend()/WSARecv() call, but also save it into global pool (to prevent GC from taking it) and provide CGO callback which will pull it back and reset the socket if there is an error.

[alexbrainman]

According to this https://msdn.microsoft.com/en-us/library/windows/desktop/ms742203(v=vs.85).aspx, it is not recommended to use &qty both with overlapped pointer

Use NULL for this parameter if the lpOverlapped parameter is not NULL to avoid potentially erroneous results

Perhaps Go implementation is at fault here. But we never seen any errors here.

Going by https://msdn.microsoft.com/en-us/library/windows/desktop/ms742203(v=vs.85).aspx

Overlapped Socket I/O
If an overlapped operation completes immediately, WSASend returns a value of zero and the lpNumberOfBytesSent parameter is updated with the number of bytes sent. If the overlapped operation is successfully initiated and will complete later, WSASend returns SOCKET_ERROR and indicates error code WSA_IO_PENDING. In this case, lpNumberOfBytesSent is not updated.

I assumed that we must pass lpNumberOfBytesSent parameter in case IO completes before WSASend finishes. So we don't wait for IO to complete after WSASend returned.

just setting overlapped pointer to nil fixes the problem.

I am not surprised. But that makes WSASend wait until IO completes. So your program will be consuming OS thread here waiting for IO. That is what Go net library is trying to avoid here.

do we allow the creation of overlapped sockets in the first place?

I do not know how Go makes sockets overlapped. Maybe all Windows TCP sockets are OK for non-blocking IO. Maybe the fact that we pass OVERLAPPED everywhere makes them non-blocking.

We need to allocate a unique lpOverlapped for each WSASend

It is not true. We can reuse lpOverlapped again and again (and we do). As long as we do not use same lpOverlapped for different IOs simultaneously.

we have control overlapped structure, but we do not have completion callback, and it is enough to work on real windows.

You do not have to use completion callback function. You can just use WaitForSingleObject (or any other Wait* function) and WSAGetOverlappedResult to get IO result. Or use CreateIoCompletionPort, GetQueuedCompletionStatus and WSAGetOverlappedResult. You can see Go implementation in netpoll_windows.go in runtime package.

It could simply be a timing issue that doesn't repro in Windows today but I agree we are using the API incorrectly. We shouldn't look at (or pass in a handle for writing) lpNumberOfBytesSent for an async sockets.

See my explanation above.

Alex

[johnsonj]

Thanks Alex.

I do not know how Go makes sockets overlapped

See my comment. If ConnectEx is on a platform and suitable then it is used which makes the socket overlapped.

Edit: I see that net.ioSrv.ExecIO blocks until the call is completed which answers my question below.

Curious why it's ok to reuse the same lpOverlapped. Do we block on subsequent writes to a socket if it the previous async operation hasn't completed? Or does Windows do this for us? I'm suspicious of it because It seems a bit like re-using a buffer for subsequent calls and it's got a few internal fields on it for some sort of internal bookkeeping.

Here's psuedocode of what I think is happening today:

WSAOVERLAPPED Overlapped;
WSASendTo(SendToSocket, &DataBuf1, 1,
                   &BytesSent, Flags,  &RecvAddr,
                   RecvAddrSize, &Overlapped, NULL);
WSASendTo(SendToSocket, &DataBuf2, 1,
                   &BytesSent, Flags, &RecvAddr,
                   RecvAddrSize, &Overlapped, NULL);

Wine keeps a long living reference to the structure on a per-WSASend-call basis.

[alexbrainman]

Do we block on subsequent writes to a socket if it the previous async operation hasn't completed?

We do. windows netFD has pd field that is used to ensure only single write in flight.
(It has been a while and I could be wrong about it, but I doubt)

Alex

[bioothod]

So, @alexbrainman what is the solution for my problem? Setting lpOverlapped to nil makes socket non-async (does it implies non-blocking?) and fixes the bug, otherwise WSASend() returns invalid number of bytes sometimes (more than requested to be written) and sometimes less, if the latter happens during Flush() call, it ends up with connection closing.

This is trivially reproducible under wine with several clients and grpc_test server I posted link above.

[alexbrainman]

Setting lpOverlapped to nil makes socket non-async (does it implies non-blocking?) and fixes the bug

As I understand it, setting lpOverlapped to nil makes WSASend wait until IO completes before returning. That, obviously, occupy OS thread. If that suits you, then fine.

WSASend() returns invalid number of bytes sometimes (more than requested to be written)

WSASend should not return number of bytes sent greater than requested. It is a bug in WSASend, or the way we use WSASend. But I don't see else we can call WSASend. Perhaps you can look at WINE source code (or even debug that call) to understand the problem.

sometimes less

I don't see that as a problem. It is up to the caller to handle this case. If some code fails to do that, I think that code needs adjustment.

Alex

[bioothod]

Well, I started to debug wine to find out why WSASend() returns invalid number of bytes already, so far no info to share though, but windows itself clearly warns against simultaneously using lpOverlapped and lpNumberOfBytesSent which can produce error

lpNumberOfBytesSent [out]

A pointer to the number, in bytes, sent by this call if the I/O 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.

[bioothod]

Filled wine bug: https://bugs.winehq.org/show_bug.cgi?id=42377

[johnsonj]

Fixed in wine: https://bugs.winehq.org/show_bug.cgi?id=42377#c18