Open Radar

 
Summary:
There are services that communicate via HTTP/2 in a full-duplex streaming way. That is, the response is streamed in chunks back to the client at the same time as the request is received in chunks, and the content of each response chunk depends on the request chunks being received.

A good example use case is a speech-to-text service, in which the client uploads voice as it captures it, and the server keeps updating its response as it becomes more confident of the transcription.

When used in such an HTTP/2 request, NSURLSession gets into an infinite loop.

Steps to Reproduce:
Bring up an HTTP/2 echo server, that echoes in the response each byte of the request as soon as it is received.

Create an URLSession with a streaming request and a delegate, and set up your Stream so that it won't send further bytes until the corresponding echo from the server has been received in the delegate.


Expected Results:
The delegate is called with each chunk of data received, independently of whether the request Stream is finished or not.

Actual Results:
The delegate's method "urlSession(_ session: URLSession, task: URLSessionTask, needNewBodyStream completionHandler: (InputStream?) -> Swift.Void)" is called in an infinite loop (as long as it keeps providing a stream).

Full log output, with print("Task need new body stream") in my delegate:

2016-06-16 14:11:16.343920 iOSgRPCSwiftTester[34890:5091467] bundleid: io.grpc.iOSgRPCSwiftTester, enable_level: 0, persist_level: 0, propagate_with_activity: 0
2016-06-16 14:11:16.344838 iOSgRPCSwiftTester[34890:5091467] subsystem: com.apple.UIKit, category: HIDEvents, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0
2016-06-16 14:11:16.447068 iOSgRPCSwiftTester[34890:5091460] Created DB, header sequence number = 264
2016-06-16 14:11:16.453088 iOSgRPCSwiftTester[34890:5091460] Created DB, header sequence number = 264
2016-06-16 14:11:16.497520 iOSgRPCSwiftTester[34890:5091460] subsystem: com.apple.BaseBoard, category: MachPort, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0
2016-06-16 14:11:16.539466 iOSgRPCSwiftTester[34890:5091460] subsystem: com.apple.FrontBoard, category: Common, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0

Task need new body stream
2016-06-16 14:11:16.864100 iOSgRPCSwiftTester[34890:5091463] subsystem: com.apple.network, category: , enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0
2016-06-16 14:11:16.866329 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_handler_start [1 grpc-test.sandbox.googleapis.com:443 initial path (null)]
2016-06-16 14:11:16.867046 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 initial path (null)] reported event path:start
2016-06-16 14:11:16.868753 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 waiting path (satisfied)] reported event path:satisfied
2016-06-16 14:11:16.870435 iOSgRPCSwiftTester[34890:5091460] subsystem: com.apple.SystemConfiguration, category: SCPreferences, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0
2016-06-16 14:11:16.871870 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event resolver:start_dns
2016-06-16 14:11:16.873818 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_resolver_update [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 2607:f8b0:400e:c04::451.443
2016-06-16 14:11:16.874142 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event resolver:receive_dns
2016-06-16 14:11:16.874438 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_resolver_start_next_child [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] starting child endpoint 2607:f8b0:400e:c04::451.443
2016-06-16 14:11:16.874694 iOSgRPCSwiftTester[34890:5091463] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-06-16 14:11:16.875003 iOSgRPCSwiftTester[34890:5091460] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-06-16 14:11:16.875232 iOSgRPCSwiftTester[34890:5091463] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-06-16 14:11:16.875478 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_resolver_start_next_child [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] starting next child endpoint in 250ms
2016-06-16 14:11:16.875756 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_handler_start [1.1 2607:f8b0:400e:c04::451.443 initial path (null)]
2016-06-16 14:11:16.876038 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 initial path (null)] reported event path:start
2016-06-16 14:11:16.876663 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 waiting path (satisfied)] reported event path:satisfied
2016-06-16 14:11:16.876907 iOSgRPCSwiftTester[34890:5091460] [] __nwlog_err_simulate_crash_libsystem libsystem simulate crash unavailable, [libsystem_network.dylib: nw_endpoint_get_hostname :: incorrect endpoint type 1]
2016-06-16 14:11:16.877316 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_get_hostname incorrect endpoint type 1, dumping backtrace:
        [x86_64] libnetcore-805.0.0.2.2
    0   libsystem_network.dylib             0x0000000108d8e37f __nw_create_backtrace_string + 123
    1   libsystem_network.dylib             0x0000000108d9046e nw_endpoint_get_hostname + 75
    2   libnetwork.dylib                    0x0000000109b86be7 nw_endpoint_proxy_handler_should_use_proxy + 125
    3   libnetwork.dylib                    0x0000000109b9404f nw_endpoint_handler_path_change + 1509
    4   libnetwork.dylib                    0x0000000109b938a2 nw_endpoint_handler_start + 570
    5   libnetwork.dylib                    0x0000000109baa026 nw_endpoint_resolver_start_next_child + 2050
    6   libdispatch.dylib                   0x0000000108ae71e8 _dispatch_call_block_and_release + 12
    7   libdispatch.dylib                   0x0000000108b13dee _dispatch_client_callout + 8
    8   libdispatch.dylib                   0x0000000108aeea1d _dispatch_queue_serial_drain + 239
    9   libdi
2016-06-16 14:11:16.879045 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] reported event flow:start_connect
2016-06-16 14:11:16.879467 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_resolver_update [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 74.125.25.81:443
2016-06-16 14:11:16.879729 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event resolver:receive_dns
2016-06-16 14:11:16.899831 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_flow_protocol_connected [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] Output protocol connected
2016-06-16 14:11:16.900915 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_flow_connected_path_change [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)] Connected path is satisfied
2016-06-16 14:11:16.901247 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)] reported event flow:finish_connect
2016-06-16 14:11:16.901678 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 ready resolver (satisfied)] reported event flow:finish_connect
2016-06-16 14:11:16.902318 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)] reported event flow:changed_viability
2016-06-16 14:11:16.902860 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 ready resolver (satisfied)] reported event flow:changed_viability
2016-06-16 14:11:16.904177 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_start_tls_while_connected [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)]
2016-06-16 14:11:16.905513 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] reported event flow:start_secondary_connect
2016-06-16 14:11:16.905954 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event flow:start_secondary_connect
2016-06-16 14:11:16.906517 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] reported event flow:start_connect
2016-06-16 14:11:16.907005 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event flow:start_connect
2016-06-16 14:11:16.907613 iOSgRPCSwiftTester[34890:5091460] [] nw_endpoint_flow_protocol_connected [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] Transport protocol connected
2016-06-16 14:11:16.908165 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] reported event flow:finish_transport
2016-06-16 14:11:16.908590 iOSgRPCSwiftTester[34890:5091460] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 in_progress resolver (satisfied)] reported event flow:finish_transport
2016-06-16 14:11:16.983349 iOSgRPCSwiftTester[34890:5091463] [] nw_endpoint_flow_protocol_connected [1.1 2607:f8b0:400e:c04::451.443 in_progress socket-flow (satisfied)] Output protocol connected
2016-06-16 14:11:16.986520 iOSgRPCSwiftTester[34890:5091463] [] nw_endpoint_flow_connected_path_change [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)] Connected path is satisfied
2016-06-16 14:11:16.987386 iOSgRPCSwiftTester[34890:5091463] [] nw_connection_endpoint_report [1.1 2607:f8b0:400e:c04::451.443 ready socket-flow (satisfied)] reported event flow:finish_connect
2016-06-16 14:11:16.987871 iOSgRPCSwiftTester[34890:5091463] [] nw_connection_endpoint_report [1 grpc-test.sandbox.googleapis.com:443 ready resolver (satisfied)] reported event flow:finish_connect

Task need new body stream

Task need new body stream

Task need new body stream

Task need new body stream

Task need new body stream

...

Version:
SimulatorApp-678.9 CoreSimulator-260.5, running iOS 10.0 (14A5261u); XCode 8.0 beta (8S128d)

Notes:
In XCode 7.3.1 / iOS SDK 9.3, instead of an infinite loop, NSURLSession fails the request with the following NSError (sent to the delegate's session:task:didCompleteWithError:)

code: -1017
domain: NSURLErrorDomain
message: cannot parse response
userInfo: [
  NSUnderlyingError:
    Error Domain=kCFErrorDomainCFNetwork
    Code=-1017 "(null)"
    UserInfo={
      NSErrorPeerAddressKey=<CFData 0x7fa4534866c0 [0x10217ea40]>{
        length = 16,
        capacity = 16,
        bytes = 0x100201bb4a7d1c510000000000000000
      },
      _kCFStreamErrorCodeKey=-1,
      _kCFStreamErrorDomainKey=4
    },
    NSErrorFailingURLStringKey: https://grpc-test.sandbox.googleapis.com/grpc.testing.TestService/FullDuplexCall,
    NSErrorFailingURLKey: https://grpc-test.sandbox.googleapis.com/grpc.testing.TestService/FullDuplexCall,
    _kCFStreamErrorDomainKey: 4,
    _kCFStreamErrorCodeKey: -1,
    NSLocalizedDescription: cannot parse  response
]