Bugfix and improved logging

ChangeLog

@@ -1,3 +1,14 @@
+2019-08-12  Richard Frith-Macdonald <rfm@gnu.org>
+
+	* Source/GSSocketStream.m: Fix for hang when writing large https
+	requests.
+	* Source/GSStream.h: improve diagnostics
+	* Source/GSStream.m: improve diagnostics
+	* Source/NSURLProtocol.m: improve diagnostics
+	* Tests/base/NSURLConnection/Helpers/NSURLConnectionTest.m:
+	* Tests/base/NSURLConnection/test05.m:
+	Bugfix and new testcase for https request with large (over 64KB) body.
+
 2019-08-09  Richard Frith-Macdonald <rfm@gnu.org>
 
 	* Source/NSRunLoop.m:

Source/GSSocketStream.m

@@ -434,6 +434,8 @@ GSTLSPush(gnutls_transport_ptr_t handle, const void *buffer, size_t len)
 #endif
 
     }
+  NSDebugFLLog(@"NSStream", @"GSTLSPush write %p of %u on %u",
+    [tls ostream], (unsigned)result, (unsigned)len);
   return result;
 }
 
@@ -675,7 +677,7 @@ static NSArray  *keys = nil;
 - (void) stream: (NSStream*)stream handleEvent: (NSStreamEvent)event
 {
   NSDebugMLLog(@"NSStream",
-    @"GSTLSHandler got %"PRIdPTR" on %p", event, stream);
+    @"GSTLSHandler got %@ on %p", [stream stringFromEvent: event], stream);
 
   if (handshake == YES)
     {
@@ -742,7 +744,26 @@ static NSArray  *keys = nil;
 
 - (NSInteger) write: (const uint8_t *)buffer maxLength: (NSUInteger)len
 {
-  return [session write: buffer length: len];
+  NSInteger	offset = 0;
+
+  /* The low level code to perform the TLS session write may return a
+   * partial write even though the output stream is still writable.
+   * That means we wouldn't get an event to say there's more space and
+   * our overall write (for a large amount of data) could hang.  
+   * To avoid that, we try writing more data as long as the stream
+   * still has space available.
+   */
+  while ([ostream hasSpaceAvailable] && offset < len)
+    {
+      NSInteger	written;
+
+      written = [session write: buffer + offset length: len - offset];
+      if (written > 0)
+	{
+	  offset += written;
+	}
+    }
+  return offset;
 }
 
 @end

Source/GSStream.h

@@ -90,6 +90,9 @@
  */
 @interface GSStream : NSStream
 IVARS
+/** Return description of current event mask.
+ */
+- (NSString*) _stringFromEvents;
 @end
 
 @interface GSAbstractServerStream : GSServerStream
@@ -154,6 +157,14 @@ IVARS
  */
 - (void) _unschedule;
 
+/** Return name of event
+ */
+- (NSString*) stringFromEvent: (NSStreamEvent)e;
+
+/** Return name of status
+ */
+- (NSString*) stringFromStatus: (NSStreamStatus)s;
+
 @end
 
 @interface GSInputStream : NSInputStream

Source/GSStream.m

@@ -110,20 +110,32 @@ static RunLoopEventType typeForStream(NSStream *aStream)
 @implementation	NSRunLoop (NSStream)
 - (void) addStream: (NSStream*)aStream mode: (NSString*)mode
 {
-  [self addEvent: [aStream _loopID]
-	    type: typeForStream(aStream)
+  RunLoopEventType 	type = typeForStream(aStream);
+  void			*event = [aStream _loopID];
+
+  NSDebugMLLog(@"NSStream",
+    @"-addStream:mode: %@ (desc %d,%d) to %@ mode %@",
+    aStream, (int)(intptr_t)event, type, self, mode);
+  [self addEvent: event
+	    type: type
 	 watcher: (id<RunLoopEvents>)aStream
 	 forMode: mode];
 }
 
 - (void) removeStream: (NSStream*)aStream mode: (NSString*)mode
 {
+  RunLoopEventType 	type = typeForStream(aStream);
+  void			*event = [aStream _loopID];
+
+  NSDebugMLLog(@"NSStream",
+    @"-removeStream:mode: %@ (desc %d,%d) from %@ mode %@",
+    aStream, (int)(intptr_t)event, type, self, mode);
   /* We may have added the stream more than once (eg if the stream -open
    * method was called more than once, so we need to remove all event
    * registrations.
    */
-  [self removeEvent: [aStream _loopID]
-	       type: typeForStream(aStream)
+  [self removeEvent: event
+	       type: type
 	    forMode: mode
 		all: YES];
 }
@@ -215,6 +227,7 @@ static RunLoopEventType typeForStream(NSStream *aStream)
 		 extra: (void*)extra
 	       forMode: (NSString*)mode
 {
+//  NSDebugMLLog(@"NSStream", @"receivedEvent for %@ - %d", self, type);
   [self _dispatch];
 }
 
@@ -321,6 +334,23 @@ static RunLoopEventType typeForStream(NSStream *aStream)
   return _currentStatus;
 }
 
+- (NSString*) _stringFromEvents
+{
+  NSMutableString	*s = [NSMutableString stringWithCapacity: 100];
+
+  if (_events & NSStreamEventOpenCompleted)
+    [s appendString: @"|NSStreamEventOpenCompleted"];
+  if (_events & NSStreamEventHasBytesAvailable)
+    [s appendString: @"|NSStreamEventHasBytesAvailable"];
+  if (_events & NSStreamEventHasSpaceAvailable)
+    [s appendString: @"|NSStreamEventHasSpaceAvailable"];
+  if (_events & NSStreamEventErrorOccurred)
+    [s appendString: @"|NSStreamEventErrorOccurred"];
+  if (_events & NSStreamEventEndEncountered)
+    [s appendString: @"|NSStreamEventEndEncountered"];
+  return s;
+}
+
 @end
 
 
@@ -379,6 +409,46 @@ static RunLoopEventType typeForStream(NSStream *aStream)
 {
 }
 
+- (NSString*) stringFromEvent: (NSStreamEvent)e
+{
+  switch (e)
+    {
+      case NSStreamEventNone:
+	return @"NSStreamEventNone";
+      case NSStreamEventOpenCompleted:
+	return @"NSStreamEventOpenCompleted";
+      case NSStreamEventHasBytesAvailable:
+	return @"NSStreamEventHasBytesAvailable";
+      case NSStreamEventHasSpaceAvailable:
+	return @"NSStreamEventHasSpaceAvailable";
+      case NSStreamEventErrorOccurred:
+	return @"NSStreamEventErrorOccurred";
+      case NSStreamEventEndEncountered:
+	return @"NSStreamEventEndEncountered";
+      default:
+	return [NSString stringWithFormat:
+	  @"NSStreamEventValue%ld", (long)e];
+    }
+}
+
+- (NSString*) stringFromStatus: (NSStreamStatus)s
+{
+  switch (s)
+    {
+      case NSStreamStatusNotOpen: return @"NSStreamStatusNotOpen";
+      case NSStreamStatusOpening: return @"NSStreamStatusOpening";
+      case NSStreamStatusOpen: return @"NSStreamStatusOpen";
+      case NSStreamStatusReading: return @"NSStreamStatusReading";
+      case NSStreamStatusWriting: return @"NSStreamStatusWriting";
+      case NSStreamStatusAtEnd: return @"NSStreamStatusAtEnd";
+      case NSStreamStatusClosed: return @"NSStreamStatusClosed";
+      case NSStreamStatusError: return @"NSStreamStatusError";
+      default:
+	return [NSString stringWithFormat:
+	  @"NSStreamStatusValue%ld", (long)s];
+    }
+}
+
 @end
 
 @implementation	GSStream (Private)

Source/NSURLProtocol.m

@@ -1733,12 +1733,12 @@ static NSURLProtocol	*placeholder = nil;
 		}
 	      if (sent == YES)
 		{
-		  if (_debug)
-		    {
-		      NSLog(@"%@ request sent", self);
-		    }
 		  if (_shouldClose == YES)
 		    {
+		      if (_debug)
+			{
+			  NSLog(@"%@ request sent ... closing", self);
+			}
 		      [this->output setDelegate: nil];
 		      [this->output removeFromRunLoop:
 			[NSRunLoop currentRunLoop]
@@ -1746,6 +1746,10 @@ static NSURLProtocol	*placeholder = nil;
 		      [this->output close];
 		      DESTROY(this->output);
 		    }
+		  else if (_debug)
+		    {
+		      NSLog(@"%@ request sent", self);
+		    }
 		}
 	      return;  // done
 	    }

Tests/base/NSURLConnection/Helpers/NSURLConnectionTest.m

@@ -33,7 +33,7 @@
 
 @implementation NSURLConnectionTest
 
-+ (Class)testWebServerClass
++ (Class) testWebServerClass
 {
   return [TestWebServer class];
 }
@@ -101,6 +101,12 @@ static NSMapTable *_flagMap = nil;
     {
       NSLog(@"%@: started with request:\n%@", self, _request);
       [self logFlags];
+
+      NSMutableSet	*s = [[NSProcessInfo processInfo] debugSet];
+      [s addObject: @"NSURLConnection"];
+      [s addObject: @"NSURLProtocol"];
+      [s addObject: @"NSStream"];
+      [s addObject: @"NSRunLoop"];
     }
 
   _conn = [[NSURLConnection alloc] initWithRequest: _request
@@ -226,7 +232,7 @@ static NSMapTable *_flagMap = nil;
   NSEndMapTableEnumeration(&en);  
 }
 
-- (NSError *)error
+- (NSError*) error
 {
   return _error;
 }

Tests/base/NSURLConnection/test05.m

@@ -18,11 +18,11 @@ int main(int argc, char **argv, char **env)
   // load the test suite's classes
   fm = [NSFileManager defaultManager];
   helperPath = [[fm currentDirectoryPath]
-		 stringByAppendingString: @"/Helpers/TestConnection.bundle"];
+    stringByAppendingString: @"/Helpers/TestConnection.bundle"];
   bundle = [NSBundle bundleWithPath: helperPath];
   loaded = [bundle load];
 
-  if(loaded)
+  if (loaded)
     {
       NSDictionary *d;
       Class testClass;
@@ -35,64 +35,68 @@ int main(int argc, char **argv, char **env)
 
       // the extra dictionary commanding to use HTTPS
       d = [NSDictionary dictionaryWithObjectsAndKeys:
-			  @"HTTPS", @"Protocol",
-			nil];
+	@"HTTPS", @"Protocol",
+	nil];
       // create a shared TestWebServer instance for performance
-      server = [[[testClass testWebServerClass] alloc] initWithAddress: @"localhost"
-								  port: @"1234"
-								  mode: NO
-								 extra: d];
+      server = [[[testClass testWebServerClass] alloc]
+	initWithAddress: @"localhost"
+	port: @"1234"
+	mode: NO
+        extra: d];
       [server setDebug: debug];
       [server start: d]; // 127.0.0.1:1234 HTTPS
 
-      /*
-       *  Simple GET via HTTPS without authorization with empty response's body and
-       *  the response's status code 204 (by default)
+      /* Simple GET via HTTPS without authorization with empty response's
+       * body and the response's status code 204 (by default)
        */
       testCase = [testClass new];
       [testCase setDebug: debug];
-      // the reference set difference (from the default reference set) we expect
-      // the flags must not be set because we request a path with no authorization
-      // See NSURLConnectionTest.h for details (the key words are 'TestCase' and 'ReferenceFlags')
+      /* the reference set difference (from the default reference set)
+       * we expect the flags must not be set because we request a path
+       * with no authorization See NSURLConnectionTest.h for details
+       * (the key words are 'TestCase' and 'ReferenceFlags')
+       */
       refs = [NSDictionary dictionaryWithObjectsAndKeys:
-			     @"NO", @"GOTUNAUTHORIZED", 
-			   @"NO", @"AUTHORIZED",        
-			   @"NO", @"NOTAUTHORIZED",     
-			    nil];
+	@"NO", @"GOTUNAUTHORIZED", 
+	@"NO", @"AUTHORIZED",        
+	@"NO", @"NOTAUTHORIZED",     
+	nil];
       // the extra dictionary with test case's parameters
       d = [NSDictionary dictionaryWithObjectsAndKeys:
-			  server, @"Instance", // we use the shared TestWebServer instance
-			@"/withoutauth", @"Path", // the path commands to use no authorization
-			refs, @"ReferenceFlags", // the expected reference set difference
-			nil];
+	server, @"Instance", // we use the shared TestWebServer instance
+	@"/withoutauth", @"Path", // the path commands to use no authorization
+	refs, @"ReferenceFlags", // the expected reference set difference
+	nil];
       [testCase setUpTest: d];
       [testCase startTest: d];
-      PASS([testCase isSuccess], "HTTPS... no auth...GET https://localhost:1234/withoutauth");
+      PASS([testCase isSuccess],
+	"HTTPS... no auth...GET https://localhost:1234/withoutauth");
       [testCase tearDownTest: d];
       DESTROY(testCase);
 
-      /*
-       *  Simple GET via HTTPS without authorization with the response's status code 400
-       *  and non-empty response's body
+      /* Simple GET via HTTPS without authorization with the response's
+       * status code 400 and non-empty response's body
        */
       testCase = [testClass new];
       [testCase setDebug: debug];
-      // the reference set difference (from the default reference set) we expect
-      // the flags must not be set because we request a path with no authorization
-      // See NSURLConnectionTest.h for details (the key words are 'TestCase' and 'ReferenceFlags')
+      /* the reference set difference (from the default reference set)
+       * we expect the flags must not be set because we request a path
+       * with no authorization. See NSURLConnectionTest.h for details
+       * (the key words are 'TestCase' and 'ReferenceFlags')
+       */
       refs = [NSDictionary dictionaryWithObjectsAndKeys:
-			     @"NO", @"GOTUNAUTHORIZED", 
-			   @"NO", @"AUTHORIZED",        
-			   @"NO", @"NOTAUTHORIZED",     
-			    nil];
+	@"NO", @"GOTUNAUTHORIZED", 
+	@"NO", @"AUTHORIZED",        
+	@"NO", @"NOTAUTHORIZED",     
+	nil];
       // the extra dictionary with test case's parameters
       d = [NSDictionary dictionaryWithObjectsAndKeys:
-			  server, @"Instance", // we use the shared TestWebServer instance
-			@"400/withoutauth", @"Path", // request the handler responding with 400
-			@"400", @"StatusCode", // the expected status code
-			@"You have issued a request with invalid data", @"Content", // the expected response's body
-			refs, @"ReferenceFlags", // the expected reference set difference
-			nil];
+	server, @"Instance", // we use the shared TestWebServer instance
+	@"400/withoutauth", @"Path", // request the handler responding with 400
+	@"400", @"StatusCode", // the expected status code
+	@"You have issued a request with invalid data", @"Content", // the expected response's body
+	refs, @"ReferenceFlags", // the expected reference set difference
+	nil];
       [testCase setUpTest: d];
       [testCase startTest: d];
       PASS([testCase isSuccess], "HTTPS... no auth... response 400... GET https://localhost:1234/400/withoutauth");
@@ -105,55 +109,60 @@ int main(int argc, char **argv, char **env)
        */
       testCase = [testClass new];
       [testCase setDebug: debug];
-      // the reference set difference (from the default reference set) we expect
-      // the flags must not be set because we request a path with no authorization
-      // See NSURLConnectionTest.h for details (the key words are 'TestCase' and 'ReferenceFlags')
+      /* the reference set difference (from the default reference set)
+       * we expect the flags must not be set because we request a path
+       * with no authorization. See NSURLConnectionTest.h for details
+       * (the key words are 'TestCase' and 'ReferenceFlags')
+       */
       refs = [NSDictionary dictionaryWithObjectsAndKeys:
-			     @"NO", @"GOTUNAUTHORIZED", 
-			   @"NO", @"AUTHORIZED",        
-			   @"NO", @"NOTAUTHORIZED",     
-			    nil];
+	@"NO", @"GOTUNAUTHORIZED", 
+	@"NO", @"AUTHORIZED",        
+	@"NO", @"NOTAUTHORIZED",     
+	nil];
       // the extra dictionary with test case's parameters
       d = [NSDictionary dictionaryWithObjectsAndKeys:
-			  server, @"Instance", // we use the shared TestWebServer instance
-			@"400/withoutauth", @"Path", // request the handler responding with 400
-			@"400", @"StatusCode", // the expected status code
-			@"You have issued a request with invalid data", @"Content", // the expected response's body
-			@"Some payload", @"Payload", // the custom payload
-			@"POST", @"Method",    // use POST
-			refs, @"ReferenceFlags", // the expected reference set difference
-			nil];
+	server, @"Instance", // we use the shared TestWebServer instance
+	@"400/withoutauth", @"Path", // request the handler responding with 400
+	@"400", @"StatusCode", // the expected status code
+	@"You have issued a request with invalid data", @"Content", // expected
+	@"Some payload", @"Payload", // the custom payload
+	@"POST", @"Method",    // use POST
+	refs, @"ReferenceFlags", // the expected reference set difference
+	nil];
       [testCase setUpTest: d];
       [testCase startTest: d];
       PASS([testCase isSuccess], "HTTPS... no auth... payload... response 400 .... POST https://localhost:1234/400/withoutauth");
       [testCase tearDownTest: d];
       DESTROY(testCase);
 
-      /*
-       *  Tests redirecting... it uses an auxilliary TestWebServer instance and proceeds
-       *  in two stages. The first one is to get the status code 301 and go to the URL
-       *  given in the response's header 'Location'. The second stage is a simple GET on
-       *  the given URL with the status code 204 and empty response's body.
+      /* Tests redirecting... it uses an auxilliary TestWebServer instance
+       * and proceeds in two stages. The first one is to get the status
+       * code 301 and go to the URL given in the response's header 'Location'.
+       * The second stage is a simple GET on the given URL with the status
+       * code 204 and empty response's body.
        */
       testCase = [testClass new];
       [testCase setDebug: debug];
-      // the reference set difference (from the default reference set) we expect
-      // the flags must not be set because we request a path with no authorization
-      // See NSURLConnectionTest.h for details (the key words are 'TestCase' and 'ReferenceFlags')
+      /* the reference set difference (from the default reference set)
+       * we expect the flags must not be set because we request a path
+       * with no authorization. See NSURLConnectionTest.h for details
+       * (the key words are 'TestCase' and 'ReferenceFlags')
+       */
       refs = [NSDictionary dictionaryWithObjectsAndKeys:
 			     @"NO", @"GOTUNAUTHORIZED", 
 			   @"NO", @"AUTHORIZED",        
 			   @"NO", @"NOTAUTHORIZED",     
 			   @"YES", @"GOTREDIRECT",
 			   nil];
-      // the extra dictionary with test case's parameters
+      /* the extra dictionary with test case's parameters
+       */
       d = [NSDictionary dictionaryWithObjectsAndKeys:
-			  server, @"Instance", // we use the shared TestWebServer instance
-			@"/301/withoutauth", @"Path", // request the handler responding with a redirect
-			@"/withoutauth", @"RedirectPath", // the URL's path of redirecting 
-			@"YES", @"IsAuxilliary", // start an auxilliary TestWebServer instance
-			refs, @"ReferenceFlags", // the expected reference set difference
-			nil];      
+	server, @"Instance", // we use the shared TestWebServer instance
+	@"/301/withoutauth", @"Path", // request a redirect
+	@"/withoutauth", @"RedirectPath", // the URL's path of redirecting 
+	@"YES", @"IsAuxilliary", // start an auxilliary TestWebServer instance
+	refs, @"ReferenceFlags", // the expected reference set difference
+	nil];      
       [testCase setUpTest: d];
       [testCase startTest: d];
       PASS([testCase isSuccess], "HTTPS... no auth... redirecting... GET https://localhost:1234/301/withoutauth");

Tests/base/NSURLConnection/test07.m

@@ -0,0 +1,103 @@
+/**
+ *  Tests for HTTPS without authorization (big request)
+ */
+#import <Foundation/Foundation.h>
+#import "Helpers/NSURLConnectionTest.h"
+#import "Helpers/TestWebServer.h"
+#import <Testing.h>
+
+int main(int argc, char **argv, char **env)
+{
+  CREATE_AUTORELEASE_POOL(arp);
+  NSFileManager 	*fm;
+  NSBundle 		*bundle;
+  BOOL 			loaded;
+  NSString 		*helperPath;
+
+  // load the test suite's classes
+  fm = [NSFileManager defaultManager];
+  helperPath = [[fm currentDirectoryPath]
+    stringByAppendingString: @"/Helpers/TestConnection.bundle"];
+  bundle = [NSBundle bundleWithPath: helperPath];
+  loaded = [bundle load];
+
+  if (loaded)
+    {
+      NSDictionary 		*d;
+      Class 			testClass;
+      NSDictionary		*refs;
+      TestWebServer		*server;
+      NSMutableString		*payload;
+      NSURLConnectionTest 	*testCase;
+      BOOL 			debug = NO;
+
+      testClass = [bundle principalClass]; // NSURLConnectionTest
+
+      // the extra dictionary commanding to use HTTPS
+      d = [NSDictionary dictionaryWithObjectsAndKeys:
+	@"HTTPS", @"Protocol",
+	nil];
+      // create a shared TestWebServer instance for performance
+      server = [[[testClass testWebServerClass] alloc]
+	initWithAddress: @"localhost"
+	port: @"1234"
+	mode: NO
+        extra: d];
+      [server setDebug: debug];
+      [server start: d]; // 127.0.0.1:1234 HTTPS
+
+      /* Simple POST via HTTPS with the response's status code 400 and
+       * non-empty response's body
+       */
+      testCase = [testClass new];
+      [testCase setDebug: debug];
+      /* the reference set difference (from the default reference set)
+       * we expect the flags must not be set because we request a path
+       * with no authorization. See NSURLConnectionTest.h for details
+       * (the key words are 'TestCase' and 'ReferenceFlags')
+       */
+      refs = [NSDictionary dictionaryWithObjectsAndKeys:
+	@"NO", @"GOTUNAUTHORIZED", 
+	@"NO", @"AUTHORIZED",        
+	@"NO", @"NOTAUTHORIZED",     
+	nil];
+
+      // the extra dictionary with test case's parameters
+      payload = [NSMutableString stringWithCapacity: 1024 * 128];
+      for (int i = 0; i < 2000; i++)
+	{
+	  [payload appendFormat:
+	    @"%09daaaaaaaaaabbbbbbbbbbcccccccccccdddddddddd\n",
+	    i * 50];
+	}
+      d = [NSDictionary dictionaryWithObjectsAndKeys:
+	server, @"Instance", // we use the shared TestWebServer instance
+	@"400/withoutauth", @"Path", // request the handler responding with 400
+	@"400", @"StatusCode", // the expected status code
+	@"You have issued a request with invalid data", @"Content", // expected
+	payload, @"Payload", // the custom payload
+	@"POST", @"Method",    // use POST
+	refs, @"ReferenceFlags", // the expected reference set difference
+	nil];
+      [testCase setUpTest: d];
+      [testCase startTest: d];
+      PASS([testCase isSuccess], "HTTPS... big payload... response 400 .... POST https://localhost:1234/400/withoutauth");
+      [testCase tearDownTest: d];
+      DESTROY(testCase);
+
+      // cleaning
+      [server stop];
+      DESTROY(server);
+    }
+  else
+    {
+      // no classes no tests
+      [NSException raise: NSInternalInconsistencyException
+		  format: @"can't load bundle TestConnection"];
+    }
+
+
+  DESTROY(arp);
+
+  return 0;
+}