GSSocketStream win32 Assertion

[hmelder]

Brief Introduction

The GSInetSocketStream/GSInet6SocketStream classes abstract platform-dependent networking APIs away and expose them via the standard NSStream interface. Each socket stream has an input (GSSocketInputStream) and an output stream (GSSocketOutputStream).

After opening a new socket, the socket is recorded and monitored. On POSIX compliant systems the socket file descriptor is used as the loop id GSSocketStream.m:1715. On Windows, the loop id is an event object which is set up to receive socket events. The event object is associated with the socket via the WSAEventSelect function.

Winsock2 Events

Windows only permits a single event object to be associated with a socket at any time. GSInetSocketInputStream coordinates two Windows event objects via the _dispatch method. If one stream is closed, the _dispatch method GSSocketStream.m:2041 automatically switches to the second (sibling) event object GSSocketStream.m:1926.

The _dispatch method discovers changes for the selected socket. On Windows, the WSAEnumNetWorkEvents function is used.

First Bug

We use the keepalive test as an example:

Starting the server:

$ ./obj/keepalive.exe --GNU-Debug=NSStream -FileName C:/tools-windows-msvc/src/gnustep-base/Tests/base/NSURL/Chunked.dat -FileHdrs YES -Count 1 -Port 12345

Log (GSInetServerStream is initialised and added to the default Runloop):

2022-08-18 16:39:31.506 keepalive[10644:2748] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetServerStream: 0x32e5bae8> sock 644 loopID 0x288 (type 0) to <NSRunLoop: 0x32e8a348> mode NSDefaultRunLoopMode
2022-08-18 16:39:31.511 keepalive[10644:2748] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0x32e5bae8> sock 644 loopID 0x288 sendEvent NSStreamEventOpenCompleted
Ready

Sending a message to the server:

$ curl localhost:12345

Log MSVC:

2022-08-18 16:39:31.506 keepalive[10644:2748] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetServerStream: 0x32e5bae8> sock 644 loopID 0x288 (type 0) to <NSRunLoop: 0x32e8a348> mode NSDefaultRunLoopMode
2022-08-18 16:39:31.511 keepalive[10644:2748] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0x32e5bae8> sock 644 loopID 0x288 sendEvent NSStreamEventOpenCompleted
Ready

--- Send HTTP request ---

2022-08-18 16:39:43.601 keepalive[10644:2748] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0x32e5bae8> sock 644 loopID 0x288 sendEvent NSStreamEventHasBytesAvailable

--- Add GSInetInputStream to Runloop ---

2022-08-18 16:39:43.603 keepalive[10644:2748] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetInputStream: 0x32f56728> sock 652 loopID 0x294 (type 0) to <NSRunLoop: 0x32e8a348> mode NSDefaultRunLoopMode
2022-08-18 16:39:43.603 keepalive[10644:2748] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0x32f56728> sock 652 loopID 0x294 sendEvent NSStreamEventOpenCompleted
2022-08-18 16:39:43.604 keepalive[10644:2748] File GSSocketStream.m: 2081. In [GSInetInputStream -_dispatch] <GSInetInputStream: 0x32f56728> sock 652 loopID 0x294 EVENTS 0x3
2022-08-18 16:39:43.604 keepalive[10644:2748] GSSocketStream.m:2126  Assertion failed in GSInetInputStream(instance), method _dispatch.  NSInternalInconsistencyException

Log Debian aarch64:

--- GSInetServerStream object is instantiated and added to the Runloop ---

2022-08-18 07:45:15.689 keepalive[5305:5305] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetServerStream: 0x1a09ea78> sock 6 loopID 0x6 (type 0) to <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode

--- Socket initialisation completed ---

2022-08-18 07:45:15.690 keepalive[5305:5305] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0x1a09ea78> sock 6 loopID 0x6 sendEvent NSStreamEventOpenCompleted
Ready

--- Send HTTP request  ---

2022-08-18 07:45:31.576 keepalive[5305:5305] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0x1a09ea78> sock 6 loopID 0x6 sendEvent NSStreamEventHasBytesAvailable

--- Add GSInetInputStream to Runloop ---

2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 (type 0) to <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode
2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 sendEvent NSStreamEventOpenCompleted
2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 sendEvent NSStreamEventHasBytesAvailable

--- Add GSInetOutputStream to Runloop ---

2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 (type 1) to <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode
2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 sendEvent NSStreamEventOpenCompleted
2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 sendEvent NSStreamEventHasSpaceAvailable

2022-08-18 07:45:31.577 keepalive[5305:5305] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 (desc 7,1) from <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 sendEvent NSStreamEventHasBytesAvailable
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 sendEvent NSStreamEventEndEncountered
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetInputStream: 0x1a0dd6f8> sock 7 loopID 0x7 (desc 7,0) from <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode

2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetInputStream: 0x1a0dd6f8> sock -1 loopID 0xffffffffffffffff (desc -1,0) from <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 (type 1) to <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 07:45:31.579 keepalive[5305:5305] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetOutputStream: 0x1a0e8388> sock 7 loopID 0x7 (desc 7,1) from <NSRunLoop: 0x1a060c78> mode NSDefaultRunLoopMode

The GSInetOutput stream object is added to the Runloop after the socket receives a write event (FD_WRITE) GSSocketStream.m:2124. The NSStreamEventHasBytesAvailable notification is never send and the write stream remains open, causing an assertion.

First Bug Fix

WSAEnumNetworkEvents returns the value '0x03' in the lNetworkEvents field, indicating that the FD_READ and FD_WRITE flag is set. In this case the NSStreamEventHasBytesAvailable event should be send, but the FD_WRITE flag is also set. Fix:

diff --git a/Source/GSSocketStream.m b/Source/GSSocketStream.m
index 88a72ec43..e414c3ed7 100644
--- a/Source/GSSocketStream.m
+++ b/Source/GSSocketStream.m
@@ -2584,6 +2584,16 @@ setNonBlocking(SOCKET fd)
        }
       else
        {
+         if (events.lNetworkEvents & FD_READ)
+           {
+             [_sibling _setStatus: NSStreamStatusOpen];
+             while ([_sibling hasBytesAvailable]
+               && [_sibling _unhandledData] == NO)
+               {
+                 [_sibling _sendEvent: NSStreamEventHasBytesAvailable];
+               }
+           }
+
          if (events.lNetworkEvents & FD_WRITE)
            {
              /* Clear NSStreamStatusWriting if it was set */
@@ -2599,15 +2609,6 @@ setNonBlocking(SOCKET fd)
              [self _sendEvent: NSStreamEventHasSpaceAvailable];
            }

-         if (events.lNetworkEvents & FD_READ)
-           {
-             [_sibling _setStatus: NSStreamStatusOpen];
-             while ([_sibling hasBytesAvailable]
-               && [_sibling _unhandledData] == NO)
-               {
-                 [_sibling _sendEvent: NSStreamEventHasBytesAvailable];
-               }
-           }
          if (events.lNetworkEvents & FD_CLOSE)
            {
              [self _setClosing: YES];

Example:

$ curl localhost:12345
This is the data in the first chunk
and this is the second one
consequence

Log:

2022-08-18 17:09:01.342 keepalive[9464:3508] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetServerStream: 0xa5904de8> sock 444 loopID 0x1c0 (type 0) to <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:01.347 keepalive[9464:3508] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0xa5904de8> sock 444 loopID 0x1c0 sendEvent NSStreamEventOpenCompleted
Ready

2022-08-18 17:09:12.833 keepalive[9464:3508] File GSStream.m: 549. In [GSInetServerStream -_sendEvent:delegate:] <GSInetServerStream: 0xa5904de8> sock 444 loopID 0x1c0 sendEvent NSStreamEventHasBytesAvailable

--- Add GSInetInputStream to Runloop ---

2022-08-18 17:09:12.835 keepalive[9464:3508] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 (type 0) to <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:12.835 keepalive[9464:3508] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 sendEvent NSStreamEventOpenCompleted
2022-08-18 17:09:12.835 keepalive[9464:3508] File GSSocketStream.m: 2081. In [GSInetInputStream -_dispatch] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 EVENTS 0x3
2022-08-18 17:09:12.835 keepalive[9464:3508] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 sendEvent NSStreamEventHasBytesAvailable

--- Add GSInetOutputStream to Runloop ---

2022-08-18 17:09:12.836 keepalive[9464:3508] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 (type 0) to <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:12.836 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventOpenCompleted
2022-08-18 17:09:12.836 keepalive[9464:3508] File GSStream.m: 549. In [GSInetInputStream -_sendEvent:delegate:] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 sendEvent NSStreamEventHasBytesAvailable
2022-08-18 17:09:12.836 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 17:09:12.836 keepalive[9464:3508] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 (desc 676,0) from <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode

--- The socket is not closed ---

2022-08-18 17:09:12.837 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 17:09:12.837 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 17:09:12.837 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 17:09:12.837 keepalive[9464:3508] File GSStream.m: 549. In [GSInetOutputStream -_sendEvent:delegate:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 sendEvent NSStreamEventHasSpaceAvailable
2022-08-18 17:09:12.838 keepalive[9464:3508] File GSStream.m: 501. In [GSInetOutputStream -_recordError:] <GSInetOutputStream: 0xa5a069e8> sock 668 loopID 0x2a4 - An existing connection was forcibly closed by the remote host.

--- Callback from NSStreamEventHasSpaceAvailable write attempts ---
2022-08-18 17:09:12.838 keepalive[9464:3508] Unable to write the payload! write:maxLength: returned -1
2022-08-18 17:09:12.839 keepalive[9464:3508] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 (desc 672,0) from <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:12.839 keepalive[9464:3508] File GSStream.m: 117. In [NSRunLoop -addStream:mode:] <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 (type 0) to <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:12.840 keepalive[9464:3508] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetInputStream: 0xa5a053e8> sock 668 loopID 0x2a0 (desc 672,0) from <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:12.840 keepalive[9464:3508] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetInputStream: 0xa5a053e8> sock -1 loopID (null) (desc 0,0) from <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode
2022-08-18 17:09:31.356 keepalive[9464:3508] File GSStream.m: 131. In [NSRunLoop -removeStream:mode:] -removeStream:mode: <GSInetServerStream: 0xa5904de8> sock 444 loopID 0x1c0 (desc 448,0) from <NSRunLoop: 0xa58fea48> mode NSDefaultRunLoopMode

Second Bug

The socket is not closed and _dispatch in a loop.

[hmelder]

GSInetServerStream:

Normal HTTP flow: