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.

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

Only one ServerStreamingCall can response when Clientconnection built on NIOTSEventLoopGroup #901

Closed
foxsin10 opened this issue Jul 18, 2020 · 24 comments · Fixed by #917
Closed
Labels
kind/support Adopter support requests.

Comments

@foxsin10
Copy link

What are you trying to achieve?

Can't response multiple ServerStreamingCall when EventLoopGroup was set to NIOTSEventLoopGroup on a real device, while it woks fine on simulators

What have you tried so far?

I build an app on iOS platform, currently I have two services, first one using UnaryCall, second one use ServerStreamingCall works like socket.
Both services' channel was provided by ClientConnection, and PlatformSupport.makeEventLoopGroup(loopCount:) was used to provide EventLoopGroup, which use NIOTSEventLoopGroup by default.
Recently I need to build a new service, which use ServerStreamingCall to send and response message. when build the channel, MultiThreadedEventLoopGroup works fine on real devices, while NIOTSEventLoopGroup can't.

Any ideas will be appreciated. Thanks

@foxsin10 foxsin10 added the kind/support Adopter support requests. label Jul 18, 2020
@Lukasa
Copy link
Collaborator

Lukasa commented Jul 18, 2020

When you say it doesn’t work, what does happen? Have you provisioned appropriate networking entitlements?

@foxsin10
Copy link
Author

foxsin10 commented Jul 20, 2020

Under this code snippet, I can make multiple ServerStreamingCall , which are only one or two parameters are different.

let group = MultiThreadedEventLoopGroup(numberOfThreads: 1)
let configuration = ClientConnection.Configuration(target: .hostAndPort(host, port), eventLoopGroup: group, errorDelegate: self, connectivityStateDelegate: self)

And under this code snippet :

let group = PlatformSupport.makeEventLoopGroup(loopCount: 1)
let configuration = ClientConnection.Configuration(target: .hostAndPort(host, port), eventLoopGroup: group, errorDelegate: self, connectivityStateDelegate: self)

I can only get fufilled ServerStreamingCall once.

I want to know why

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 20, 2020

When you say once, you mean once per app launch? Once per device? Once per server?

@foxsin10
Copy link
Author

No, Every time I present a viewcontroller, I can request once. The channel's lifecycle was binding to the controller.

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 21, 2020

Can you show the setup code from the view controller? How are you managing the grpc state there?

@foxsin10
Copy link
Author

foxsin10 commented Jul 21, 2020

here is my code. I use an instance of ChartGrpcClient class in the viewcontroller.I deleted some code

final class ChartGrpcClient<T: Codable> {
    private var grpcClient: Grpc_Gateway_GateWayCallClient?
    private var channel: ClientConnection?
    
    private var channelQueue: DispatchQueue {
        return chartDataHandleQueue
    }
    
    private var grpcCall: ServerStreamingCall<Grpc_Gateway_GateWayRequest, Grpc_Gateway_GateWayResponse>?

    func send(_ request: Grpc_Gateway_GateWayRequest, completionHandler: @escaping (T) -> Void) {
        let handler: (Grpc_Gateway_GateWayResponse) -> Void = { (response) in
            if let data = response.playLoad.data(using: .utf8),
                let result = try? JSONDecoder().decode(T.self, from: data) {
                
                DispatchQueue.main.async {
                    completionHandler(result)
                }
                
            }
        }
        self.grpcCall = self.grpcClient?.request(
            request,
            callOptions: self.buildCallOptions(),
            handler: handler
        )
     }
    
     func buildConnection() {
        let channel = self.buildChannel()
        self.channel = channel
        self.bind(toChannel: channel)
     }
    
     private func bind(toChannel channel: GRPCChannel) {
        _ = self.grpcCall?.cancel()
        self.grpcClient = Grpc_Gateway_GateWayCallClient(channel: channel)
     }
    
     private func buildChannel() -> ClientConnection {
        let group = MultiThreadedEventLoopGroup(numberOfThreads: 1)
        let configuration = ClientConnection.Configuration(
            target: .hostAndPort(host, port),
            eventLoopGroup: group,
            errorDelegate: self,
            connectivityStateDelegate: self
        )
        
        return ClientConnection(configuration: configuration)
     }
}

extension ChartGrpcClient: ClientErrorDelegate {
    func didCatchError(_ error: Error, logger: Logger, file: StaticString, line: Int) {}
}

extension ChartGrpcClient: ConnectivityStateDelegate {
    func connectivityStateDidChange(from oldState: ConnectivityState, to newState: ConnectivityState) {}
}

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 21, 2020

Ok, and how do you invoke this object in your view controller? What methods do you call?

@foxsin10
Copy link
Author

call buildConnection() after viewDidload().
Then maybe tap a button to trigger send(_ : , completionHandler: ).
When the group is assigned with NIOTSEventLoopGroup, it will work once on real device, but I can send multiple requests and get responses on a simulator.
But if I assigned the group with MultiThreadedEventLoopGroup , I can send multiple requests and get responses

@foxsin10
Copy link
Author

foxsin10 commented Jul 21, 2020

The object is a property of the viewcontroller.
The problem wasn't caused by the release of the object.

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 21, 2020

Can you print the logs from the connectivityStateDidChange in both cases?

@foxsin10
Copy link
Author

Here, under NIOTSEventLoopGroup :
639507D1-F986-435E-B185-50BBFCB3307D
And, under MultiThreadedEventLoopGroup :
77AF465E-7A56-484C-8A29-6F098B0315CF

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 21, 2020

Ok, so POSIXErrorCode: Operation timed out is an error from Network.framework that indicates a timeout has occurred. This happened after the connection went live. It would be valuable to see how this interleaved with calls to send and the completionHandler: can you add those as well, please?

While we're here, you are also ignoring any errors that may be returned in handler. It would also be good to see if anything is appearing there.

@foxsin10
Copy link
Author

There will be some changes to our Service, I will do some tests later.

@Lutzifer
Copy link
Contributor

I have the same Issue:

self.group = PlatformSupport.makeEventLoopGroup(loopCount: 2) // Using this works on Simulator, but not on the device

self.group = MultiThreadedEventLoopGroup(numberOfThreads: 2) // This works on both Simulator and Device

Is there anything I can provide?

@Lukasa
Copy link
Collaborator

Lukasa commented Jul 28, 2020

@Lutzifer What does "works" mean here?

If it's the same issue as above, can you aim to get all those diagnostics too?

@givip
Copy link

givip commented Aug 1, 2020

@Lukasa
Here is iOS project where you can reproduce: https://github.com/givip/gRPC-bug-1
For server I used: https://github.com/grpc/grpc-swift/tree/master/Sources/Examples/HelloWorld/Server

Behaviour:

  • Point to the HelloWorldServer host:port
  • Launch on any physical iOS device with server host:port

Result:

  • First request succeeded
  • Second request after some amount of time fails with error.

Expected:

  • Both requests succeeded.

@Lukasa
Copy link
Collaborator

Lukasa commented Aug 3, 2020

Unfortunately I don't reproduce that behaviour. If I run the same hello world server and client, I end up with the following logs (note that I added XXX: REQUEST X COMPLETE to make those really stand out):

2020-08-03T09:33:47+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 path=/helloworld.Greeter/SayHello starting rpc
2020-08-03T09:33:47+0100 info: new_state=connecting connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 old_state=idle connectivity state change
2020-08-03T09:33:47+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 making client bootstrap with event loop group of type NIOTSEventLoop
2020-08-03T09:33:47+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 starting rpc
2020-08-03T09:33:48+0100 debug: path=/helloworld.Greeter/SayHello connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C starting rpc
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C starting rpc
2020-08-03T09:33:48+0100 debug: request_part=head call_state=waiting for connection; 0 request part(s) buffered request_id=3D116830-6415-4C51-BEA0-279CCC482666 connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 debug: request_id=3D116830-6415-4C51-BEA0-279CCC482666 request_part=message call_state=waiting for connection; 1 request part(s) buffered connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 debug: request_id=3D116830-6415-4C51-BEA0-279CCC482666 request_part=end call_state=waiting for connection; 2 request part(s) buffered connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 debug: request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=head call_state=waiting for connection; 0 request part(s) buffered connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 debug: request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=message call_state=waiting for connection; 1 request part(s) buffered connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 debug: request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=end call_state=waiting for connection; 2 request part(s) buffered connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 buffering request part
2020-08-03T09:33:48+0100 info: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 remote_address=[IPv4]192.168.1.58/192.168.1.58:49589 event_loop=NIOTransportServices.NIOTSEventLoop gRPC connection ready
2020-08-03T09:33:48+0100 info: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 old_state=connecting new_state=ready connectivity state change
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 request_part=head unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 request_part=message unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 request_part=end unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 request buffer drained
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=head unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=message unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request_part=end unbuffering request part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C request buffer drained
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 response_part=initial metadata received response part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 response_part=message received response part
XXX: REQUEST 1 COMPLETE
gRPC_bug.Helloworld_HelloReply:
message: "Hello Hello_1!"

2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 response_part=trailing metadata received response part
2020-08-03T09:33:48+0100 debug: connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 response_part=status received response part
2020-08-03T09:33:48+0100 debug: status_message=OK status_code=0 request_id=3D116830-6415-4C51-BEA0-279CCC482666 duration_ms=237 connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 rpc call finished
2020-08-03T09:33:48+0100 debug: response_part=initial metadata connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C received response part
2020-08-03T09:33:48+0100 debug: response_part=message connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C received response part
XXX: REQUEST 2 COMPLETE
gRPC_bug.Helloworld_HelloReply:
message: "Hello Hello_2!"

2020-08-03T09:33:48+0100 debug: response_part=trailing metadata connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C received response part
2020-08-03T09:33:48+0100 debug: response_part=status connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C received response part
2020-08-03T09:33:48+0100 debug: status_code=0 duration_ms=237 status_message=OK request_id=81F73C96-E7D4-463E-BA8D-2A165B48E33C connection_id=2432FFE0-1C32-4666-8E60-17349C385479/0 rpc call finished

You can see the successful completion of both RPCs.

Do you have the equivalent logs from your run?

@givip
Copy link

givip commented Aug 3, 2020

Did you run on device? or on simulator? I have equivalent log without second Hello_2

@Lukasa
Copy link
Collaborator

Lukasa commented Aug 3, 2020

On device.

@givip
Copy link

givip commented Aug 3, 2020

What is iOS version you had? I tested on 13.5.1, now I found, that 13.6 is available.

@givip
Copy link

givip commented Aug 3, 2020

@Lukasa This is my log on 13.5.1 iPhone X, will update device shortly and test again.

UPD: Reproduced on 13.6 as well

2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 path=/helloworld.Greeter/SayHello starting rpc
2020-08-03T21:03:48+0400 info io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 old_state=idle new_state=connecting connectivity state change
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 making client bootstrap with event loop group of type NIOTSEventLoop
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 starting rpc
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : path=/helloworld.Greeter/SayHello request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 starting rpc
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 starting rpc
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 0 request part(s) buffered request_part=head request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C buffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 1 request part(s) buffered request_part=message request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C buffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 2 request part(s) buffered request_part=end request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C buffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 0 request part(s) buffered request_part=head request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 buffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 1 request part(s) buffered request_part=message request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 buffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 call_state=waiting for connection; 2 request part(s) buffered request_part=end request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 buffering request part
2020-08-03T21:03:48+0400 info io.grpc.client_channel : event_loop=NIOTransportServices.NIOTSEventLoop remote_address=[IPv4]192.168.1.16/192.168.1.16:58999 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 gRPC connection ready
2020-08-03T21:03:48+0400 info io.grpc.client_channel : new_state=ready old_state=connecting connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 connectivity state change
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C request_part=head connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C request_part=message connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C request_part=end connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 request buffer drained
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_part=head request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_part=message request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_part=end request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 unbuffering request part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 request buffer drained
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C response_part=initial metadata connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 received response part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C response_part=message connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 received response part
gRPC_bug.Helloworld_HelloReply:
message: "Hello Hello_1!"

2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C response_part=trailing metadata connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 received response part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C response_part=status connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 received response part
2020-08-03T21:03:48+0400 debug io.grpc.client_channel : request_id=B7F38AB3-C94C-4123-8FCF-83B48AF0048C status_message=OK connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 status_code=0 duration_ms=217 rpc call finished
2020-08-03 21:04:42.432263+0400 gRPC-bug[5178:1714111] [] tcp_output [C1:1] flags=[R.] seq=3255012579, ack=2868785812, win=1028 state=CLOSED rcv_nxt=2868785812, snd_una=3255012579
2020-08-03 21:04:42.436752+0400 gRPC-bug[5178:1714111] [] nw_read_request_report [C1] Receive failed with error "Operation timed out"
2020-08-03 21:04:42.437771+0400 gRPC-bug[5178:1714111] [] sb_empty_assert [C1:1] sbflush: sb 0x1050535d0 so 0x105053450 cc 0 mb 0x1050535e0
2020-08-03 21:04:42.441604+0400 gRPC-bug[5178:1714111] [] sb_empty_assert [C1:1] sbflush: sb 0x1050535d0 so 0x105053450 cc 0 mb 0x1050535e0, dumping backtrace:
        [arm64] libnetcore-1880.120.4
    0   libnetwork.dylib                    0x000000018eb68e94 __nw_create_backtrace_string + 116
    1   libusrtcp.dylib                     0x000000019184de40 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 273984
    2   libusrtcp.dylib                     0x000000019184cfe8 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 270312
    3   libusrtcp.dylib                     0x000000019184c2f8 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 267000
    4   libusrtcp.dylib                     0x0000000191851438 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 287800
    5   libusrtcp.dylib                     0x000000019182aa58 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 129624
    6   libdispatch.dylib                   0x0000000104292338 _dispatch_call_block_and_release + 24
    7   libdispatch.dylib                   0x0000000104293730 _dispatch_client_callout + 16
    8   libdispatch.dylib                   0x000000010429c81c _dispatch_workloop_invoke + 2480
    9   libdispatch.dylib                   0x00000001042a66c4 _dispatch_workloop_worker_thread + 1304
    10  libsystem_pthread.dylib             0x000000018c21cb74 _pthread_wqthread + 272
    11  libsystem_pthread.dylib             0x000000018c21f740 start_wqthread + 8
2020-08-03T21:04:42+0400 info io.grpc.client_channel : old_state=ready connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 new_state=transientFailure connectivity state change
2020-08-03T21:04:42+0400 debug io.grpc.client_channel : duration_ms=54038 status_code=14 connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 status_message=nil request_id=35BEF7B0-90DB-49A7-9124-133B7E151B85 rpc call finished
unavailable (14)
2020-08-03T21:04:42+0400 info io.grpc.client_channel : new_state=connecting old_state=transientFailure connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 connectivity state change
2020-08-03T21:04:42+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 making client bootstrap with event loop group of type NIOTSEventLoop
2020-08-03T21:04:42+0400 debug io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap
2020-08-03T21:04:42+0400 info io.grpc.client_channel : event_loop=NIOTransportServices.NIOTSEventLoop connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 remote_address=[IPv4]192.168.1.16/192.168.1.16:58999 gRPC connection ready
2020-08-03T21:04:42+0400 info io.grpc.client_channel : connection_id=C9FFD172-0C1F-467C-97E8-60714D0CB446/0 old_state=connecting new_state=ready connectivity state change
2020-08-03 21:04:43.439888+0400 gRPC-bug[5178:1714679] [] __nwlog_err_simulate_crash simulate crash already simulated "sb_empty_assert [C1:1] sbflush: sb 0x1050535d0 so 0x105053450 cc 0 mb 0x1050535e0"
2020-08-03 21:04:43.443231+0400 gRPC-bug[5178:1714679] [] sb_empty_assert [C1:1] sbflush: sb 0x1050535d0 so 0x105053450 cc 0 mb 0x1050535e0, dumping backtrace:
        [arm64] libnetcore-1880.120.4
    0   libnetwork.dylib                    0x000000018eb68e94 __nw_create_backtrace_string + 116
    1   libusrtcp.dylib                     0x000000019184de40 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 273984
    2   libusrtcp.dylib                     0x000000019184cfe8 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 270312
    3   libusrtcp.dylib                     0x000000019184c2f8 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 267000
    4   libusrtcp.dylib                     0x000000019180e560 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 13664
    5   libusrtcp.dylib                     0x00000001918547d0 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 301008
    6   libusrtcp.dylib                     0x0000000191854630 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 300592
    7   libusrtcp.dylib                     0x000000019181555c 049DC0B2-A42A-3EE3-B536-597E51BBA17C + 42332
    8   libdispatch.dylib                   0x0000000104293730 _dispatch_client_callout + 16
    9   libdispatch.dylib                   0x0000000104296390 _dispatch_continuation_pop + 524
    10  libdispatch.dylib                   0x00000001042a9614 _dispatch_source_invoke + 1412
    11  libdispatch.dylib                   0x000000010429c66c _dispatch_workloop_invoke + 2048
    12  libdispatch.dylib                   0x00000001042a66c4 _dispatch_workloop_worker_thread + 1304
    13  libsystem_pthread.dylib             0x000000018c21cb74 _pthread_wqthread + 272
    14  libsystem_pthread.dylib             0x000000018c21f740 start_wqthread + 8

@Lukasa
Copy link
Collaborator

Lukasa commented Aug 3, 2020

Thanks for those logs @Lutzifer, that pinned this issue down. This is the bug that caused us to write apple/swift-nio-transport-services#72. This also explains why I didn't see the issue: the problem is resolved in iOS 14, which is what I was running on my test device.

@glbrntt We should add the NIOFilterEmptyWritesHandler when crafting insecure channel pipelines using NIOTS.

@Lutzifer
Copy link
Contributor

Lutzifer commented Aug 4, 2020

Sorry, didn't find the time to post logs yet, so I thanks to @givip instead ;-)

@Lukasa
Copy link
Collaborator

Lukasa commented Aug 4, 2020

Whoops bad tag, sorry @givip! Thank you for the logs. :D

@glbrntt glbrntt linked a pull request Aug 4, 2020 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/support Adopter support requests.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants