unavailable (14): Transport became inactive on big response

[o15a3d4l11s2]

Describe the bug

1. I am using the following: 1.1. iOS (Swift) 1.2. Cocoapods

   pod 'gRPC-Swift',          '1.6.1'
   pod 'gRPC-Swift-Plugins',  '1.6.1'
   pod 'SwiftProtobuf',       '1.18.0'

2. I am calling a gRPC that returns approximately 40 MB of data.

   let eventLoopGroup = MultiThreadedEventLoopGroup(numberOfThreads: System.coreCount)
   return ClientConnection.usingPlatformAppropriateTLS(for: eventLoopGroup).withMaximumReceiveMessageLength(100 * 1024 * 1024).connect(host: host, port: port)

   I use default CallOptions.

3. I have intentionally set the max. length to 100 MB as it otherwise shows an error the default 4MB are exceeded.

4. What exactly happens - I make the request, for approximately 1 minute it transfers data (seen in the Xcode Debug Navigation) and then it just stays inactive for a long period of time. Then it show the error unavailable (14): Transport became inactive.

5. A similar request with a response around 400 KB works properly.

Expected behaviour

I expect the API to return the response properly.

Additional information

I also checked the service through a gRPC client (Kreya) and the response is returned properly.

[glbrntt]

4. What exactly happens - I make the request, for approximately 1 minute it transfers data (seen in the Xcode Debug Navigation) and then it just stays inactive for a long period of time. Then it show the error unavailable (14): Transport became inactive.

Interesting. Do you think you could provide trace logs for this?

[o15a3d4l11s2]

@glbrntt, you can find attached a trace log. Note the timestamp of the last line (it is after the big delay).

[glbrntt]

Thanks for providing that. It looks like this is just from the request logger, can you also include the background activity logger (there are two loggers, one in CallOptions and another for the ClientConnection/GRPCChannelPool)? I'm expecting we'll see a more specific connection level error which may provide more context.

We only get about 19MB into the message before we stop making progress. Interestingly there's almost exactly 15 minutes between the last payload (13:29:08) and the connection being closed (13:44:07) which suggests the other side has given up on us.

[o15a3d4l11s2]

Thank you for your response. The detailed log is attached here.

Please note that I have named the loggers better: gRPC ClientConnection, gRPC CallOptions (Working), gRPC CallOptions (Problematic).

The log with the (Working) is a similar request with a very small amount of data and the (Problematic) is the one with the big amount of data.

Receiving the data takes approximately 2-3 minutes. In the logged example the response started 2022-01-25T17:40:04+0200 and stopped receiving 2022-01-25T17:42:14+0200 -> 2m10s

Then it stopped receiving and closed connection 2022-01-25T17:57:13+0200 -> 14m59s later

I cannot see a h2_end_stream=true received at the end and this seems like the problem according to me, but I do not receive more data either. Is there anything specific I can ask to be checked on the server? As a reference this request works successfully on a C# Windows application and also on a gRPC GUI Client on MacOS.

[glbrntt]

Thanks for providing that. Unfortunately I haven't been able to reproduce this locally.

Could you let me know the versions of each dependency? (in particular all the SwiftNIO dependencies).

Could you also tell me about the environment you're running this under? Is it a real device or simulator? Can you reproduce this on macOS with grpc-swift?

[o15a3d4l11s2]

I am using gRPC-Swift 1.6.1 and the dependencies from Podfile.lock are:

  - SwiftNIO (2.32.3):
    - SwiftNIOCore (= 2.32.3)
    - SwiftNIOEmbedded (= 2.32.3)
    - SwiftNIOPosix (= 2.32.3)
  - SwiftNIOConcurrencyHelpers (2.32.3):
    - CNIOAtomics (= 2.32.3)
  - SwiftNIOCore (2.32.3):
    - CNIOLinux (= 2.32.3)
    - SwiftNIOConcurrencyHelpers (= 2.32.3)
  - SwiftNIOEmbedded (2.32.3):
    - _NIODataStructures (= 2.32.3)
    - SwiftNIOCore (= 2.32.3)
  - SwiftNIOExtras (1.10.2):
    - SwiftNIO (< 3, >= 2.32.0)
  - SwiftNIOFoundationCompat (2.32.3):
    - SwiftNIO (= 2.32.3)
    - SwiftNIOCore (= 2.32.3)
  - SwiftNIOHPACK (1.18.3):
    - SwiftNIO (< 3, >= 2.32.0)
    - SwiftNIOConcurrencyHelpers (< 3, >= 2.32.0)
    - SwiftNIOCore (< 3, >= 2.32.0)
    - SwiftNIOHTTP1 (< 3, >= 2.32.0)
  - SwiftNIOHTTP1 (2.32.3):
    - CNIOHTTPParser (= 2.32.3)
    - SwiftNIO (= 2.32.3)
    - SwiftNIOConcurrencyHelpers (= 2.32.3)
    - SwiftNIOCore (= 2.32.3)
  - SwiftNIOHTTP2 (1.18.3):
    - SwiftNIO (< 3, >= 2.32.0)
    - SwiftNIOConcurrencyHelpers (< 3, >= 2.32.0)
    - SwiftNIOCore (< 3, >= 2.32.0)
    - SwiftNIOHPACK (= 1.18.3)
    - SwiftNIOHTTP1 (< 3, >= 2.32.0)
    - SwiftNIOTLS (< 3, >= 2.32.0)
  - SwiftNIOPosix (2.32.3):
    - _NIODataStructures (= 2.32.3)
    - CNIODarwin (= 2.32.3)
    - CNIOLinux (= 2.32.3)
    - CNIOWindows (= 2.32.3)
    - SwiftNIOConcurrencyHelpers (= 2.32.3)
    - SwiftNIOCore (= 2.32.3)
  - SwiftNIOSSL (2.15.1):
    - CNIOBoringSSL (= 2.15.1)
    - CNIOBoringSSLShims (= 2.15.1)
    - SwiftNIO (< 3, >= 2.32.0)
    - SwiftNIOConcurrencyHelpers (< 3, >= 2.32.0)
    - SwiftNIOCore (< 3, >= 2.32.0)
    - SwiftNIOTLS (< 3, >= 2.32.0)
  - SwiftNIOTLS (2.32.3):
    - SwiftNIO (= 2.32.3)
    - SwiftNIOCore (= 2.32.3)
  - SwiftNIOTransportServices (1.11.3):
    - SwiftNIO (< 3, >= 2.32.0)
    - SwiftNIOConcurrencyHelpers (< 3, >= 2.32.0)
    - SwiftNIOFoundationCompat (< 3, >= 2.32.0)
    - SwiftNIOTLS (< 3, >= 2.32.0)

I am able to reproduce the issue both on simulator and real device (iPhone Xʀ with iOS 15.3).

I have not tested under macOS, I will do so and write back with the results.

Update: I just created an isolated project that contains only gRPC library and the problematic request as a macOS application and it fails in the same way.

[o15a3d4l11s2]

I have created a simple gRPC server using C# on Windows with the problematic proto. It succeeds, but is abnormally slow. For comparison: calling the service with a dedicated desktop client (Kreya) takes approximately 10 seconds. Calling the same service through the gRPC-Swift client takes approximately 10 minutes. For the test project I followed https://github.com/grpc/grpc-swift/blob/main/docs/basic-tutorial.md#client-side-streaming-rpc. The only difference is that I set maximumReceiveMessageLength because the response is big. Is there something that I am doing so wrong that it takes 60 times more time for the Swift client to read the data? For the test I am using the computer and simulator, so resources are not limited.

As a possible solution I will most probably only return urls to the files instead of the whole content, but I still think sending less than 100 MB of content through gRPC should not be so dramatically slow.

Regarding my initial problem and test - I still am not sure how/why the gRPC request fails on the production server. I will most probably need to make an exact copy of the whole server in order to being able to check the code and make more tests.

[Lukasa]

Are you compiling in release mode? That is, swift build -c release?

[o15a3d4l11s2]

🤯 I cannot believe this. I feel very stupid now. I did not see this mentioned in the basic documentation and I am still surprised by the huge difference. Thank you a lot!

Is there a way to gRPC-Swift to always compile for release during app development process? (I am using Cocoapods for managing dependencies, but can also switch to SPM)

[Lukasa]

If you use SPM, this is an app-wide setting: so long as you enable compiling in release mode (usually in your Scheme) it will apply to grpc-swift. I don't know how to do this for Cocoapods I'm afraid.

[o15a3d4l11s2]

Thank you for the information, this is how I actually tested (with Cocoapods) - by setting the schema's build configuration for the whole project.

[Amit011121]

@o15a3d4l11s2 By changing build configuration setting dose this work for you? Because I'm also facing same issue unavailable (14): Transport became inactive on big response. Please update.

[o15a3d4l11s2]

@o15a3d4l11s2 By changing build configuration setting dose this work for you? Because I'm also facing same issue unavailable (14): Transport became inactive on big response. Please update.

By building a release version of the app, the problem is resolved. I could not find a way to set gRPC to release mode whilst building everything else in debug mode, which made development more inconvenient for me. Also based on my tests the communication is times faster in release. Maybe we have to check with the developers if it is possible to have the app behave like in release mode by default and only switch to the much slower debug mode if some flat is explicitly set?

[Amit011121]

@o15a3d4l11s2 thanks for the reply Even i also did same way as mentioned in older thread were you guys are talked about. It’s quite difficult to test in Debug mode.

[o15a3d4l11s2]

@Lukasa, I never understood why it has to run in build configuration release in order to work. Is there some documentation or hint what exactly differs in the grpc-swift logic in debug vs release mode?

It makes development quite complicated to always switch between debug and release build while developing because I need the data from gRPC synced on the device. To achieve this I build for release, sync the data, switch back to debug and continue development but it takes time for Xcode as it needs to build everything fresh because of the build change.

[glbrntt]

Semantically grpc-swift doesn't have many difference between debug and release. The main semantic difference I can think of are some assertions which exist in debug mode will be runtime errors in release mode, but that's not related to the problem you're seeing.

The main difference you're seeing is that in debug mode grpc-swift and its dependencies will perform additional state checks and the compiler optimisations will not be enabled resulting in much worse performance at runtime than in release mode.