Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

GSSocketStream win32 Assertion #266

Open
hmelder opened this issue Aug 18, 2022 · 1 comment
Open

GSSocketStream win32 Assertion #266

hmelder opened this issue Aug 18, 2022 · 1 comment
Labels
bug Use this tag for reporting bugs or issues that impede the software's normal functionality. windows Label issues that are specific to the Windows operating system with this tag.

Comments

@hmelder
Copy link
Contributor

hmelder commented Aug 18, 2022

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
Copy link
Contributor Author

hmelder commented Aug 23, 2022

GSInetServerStream:
Screenshot 2022-08-22 at 15 43 19

Normal HTTP flow:
Screenshot 2022-08-22 at 15 51 04

@triplef triplef mentioned this issue Sep 11, 2022
Merged
@hmelder hmelder added bug Use this tag for reporting bugs or issues that impede the software's normal functionality. windows Label issues that are specific to the Windows operating system with this tag. labels Sep 9, 2023
@triplef triplef mentioned this issue Jan 30, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Use this tag for reporting bugs or issues that impede the software's normal functionality. windows Label issues that are specific to the Windows operating system with this tag.
Milestone
No milestone
Development

No branches or pull requests
1 participant
@hmelder