search

grpc / grpc-swift

The Swift language implementation of gRPC.
Apache License 2.0
2.01k stars 416 forks source link

preconditionInEventLoop crash in my testcase #1412

Closed ripplek closed 2 years ago

ripplek commented 2 years ago

Describe the bug

  1. I am using the following: 1.1. iOS (Swift) 1.2. Cocoapods pod 'gRPC-Swift', :git => 'https://github.com/grpc/grpc-swift.git', :branch => '1.7.1-async-await'
  2. Below is how I init my GRPCChannel 
    
let keepalive = ClientConnectionKeepalive(interval: .seconds(15), timeout: .seconds(10))

let channel = try GRPCChannelPool.with( target: .hostAndPort(host, Int(port)), transportSecurity: .plaintext, eventLoopGroup: NIOTSEventLoopGroup(loopCount: 5, defaultQoS: .default) ) { // Configure keepalive. $0.keepalive = keepalive $0.backgroundActivityLogger = channelLogger } return channel

3. I have a `ClientInterceptor` for retry request
```Swift
public final class NotReallyAuthClientInterceptor<Request: Message, Response: Message>: ClientInterceptor<Request, Response> {
    private let client: GRPCClient

    private enum State {
        // We're trying the call, these are the parts we've sent so far.
        case trying([GRPCClientRequestPart<Request>])
        // We're retrying using this call.
        case retrying(Call<Request, Response>)
    }

    private var state: State = .trying([])

    public init(client: GRPCClient) {
        self.client = client
    }

    public override func cancel(
        promise: EventLoopPromise<Void>?,
        context: ClientInterceptorContext<Request, Response>
    ) {
        switch self.state {
        case .trying:
            context.cancel(promise: promise)

        case let .retrying(call):
            call.cancel(promise: promise)
            context.cancel(promise: nil)
        }
    }

    public override func send(
        _ part: GRPCClientRequestPart<Request>,
        promise: EventLoopPromise<Void>?,
        context: ClientInterceptorContext<Request, Response>
    ) {
        var part = part
        if case var .metadata(headers) = part {
            headers.replaceOrAdd(name: "authorization", value: "Robot")
            headers.replaceOrAdd(name: "access_token", value: APICommon.accessToken)
            part = .metadata(headers)
        }
        switch self.state {
        case var .trying(parts):
            // Record the part, incase we need to retry.
            parts.append(part)
            self.state = .trying(parts)
            // Forward the request part.
            context.send(part, promise: promise)

        case let .retrying(call):
            // We're retrying, send the part to the retry call.
            call.send(part, promise: promise)
        }
    }

    public override func receive(
        _ part: GRPCClientResponsePart<Response>,
        context: ClientInterceptorContext<Request, Response>
    ) {
        switch self.state {
        case let .trying(parts):
            switch part {
                // If 'authentication' fails this is the only part we expect, we can forward everything else.
            case let .end(status, trailers) where status.code == .unauthenticated:
                // We only know how to deal with magic.
                guard trailers.first(name: "www-authenticate") == "Robot" else {
                    // We can't handle this, fail.
                    context.receive(part)
                    return
                }

                guard case let .some(.metadata(metadata)) = parts.first, let requestToken = metadata.first(name: "access_token") else {
                    context.receive(part)
                    return
                }

                @Sendable func updateMetadataRetry() {
                    // We know how to handle this: make a new call.
                    let call: Call<Request, Response> = self.client.channel.makeCall(
                        path: context.path,
                        type: context.type,
                        callOptions: context.options,
                        // We could grab interceptors from the client, but we don't need to.
                        interceptors: [LoggingRobotClientInterceptor()]
                    )

                    // We're retying the call now.
                    self.state = .retrying(call)

                    // Invoke the call and redirect responses here.

                    call.invoke(onError: context.errorCaught(_:), onResponsePart: context.receive(_:))

                    var newParts = parts
                    // Parts must contain the metadata as the first item if we got that first response.
                    if case var .some(.metadata(metadata)) = parts.first {
                        metadata.replaceOrAdd(name: "access_token", value: APICommon.accessToken)
                        newParts[0] = .metadata(metadata)
                    }

                    // Now replay any requests on the retry call.
                    for part in newParts {
                        call.send(part, promise: nil)
                    }
                }

                if let refreshTokenReq = tokenRequestCache[requestToken] {
                    Task {
                        switch await refreshTokenReq.result {
                        case .success:
                            updateMetadataRetry()
                        case .failure:
                            context.receive(part)
                        }
                    }
                    return
                }

                tokenRequestCache[requestToken] = Task<App_RefreshTokensReply, Error> {
                    do {
                        let reply = try await App_AccountAsyncClient(channel: self.client.channel, interceptors: RobotClientInterceptorFactory(client: self.client)).refreshTokens(.with { $0.refreshToken = APICommon.refreshToken })
                        APICommon.accessToken = reply.accessToken
                        APICommon.refreshToken = reply.refreshToken
                        updateMetadataRetry()
                        log.warning("refresh token success: \(reply)")
                        return reply
                    } catch {
                        log.error("refresh token failed: \(error)")
                        tokenRequestCache[requestToken] = nil
                        context.receive(part)
                        throw error
                    }
                }

            default:
                context.receive(part)
            }

        case .retrying:
            // Ignore anything we receive on the original call.
            ()
        }
    }
}

  1. below is my testcase

    class RbotTests: GRPCTestCase {
private var group: EventLoopGroup!
private var server: Server!
private var rbot: Rbot!

override func setUp() {
    super.setUp()
    group = NIOTSEventLoopGroup(loopCount: 1, defaultQoS: .default)
    server = try! Server
        .insecure(group: self.group)
        .withServiceProviders([
            AccountAsyncProvider(),
            RobotAsyncProvider()
        ])
        .withLogger(self.serverLogger)
        .bind(host: "localhost", port: 0)
        .wait()
    APICommon.host = "localhost"
    APICommon.port = Int32(self.server.channel.localAddress!.port!)

}

override func tearDown() {
    super.tearDown()
}

func testGenerateBindRobotQRCode() async {
    self.rbot = try! await Rbot.with(thirdAccount: "kun.zhang@voidtech.com.cn")
    do {
        for try await status in rbot.robotBind(.air, ssid: "sky-China-5G", password: "asdasd") {
            log.info("\(status)")
        }
    } catch {
        XCTFail(error.localizedDescription)
    }
}
}

  2. sometimes the testcase crash in call.invoke(onError: context.errorCaught(_:), onResponsePart: context.receive(_:))

                   @Sendable func updateMetadataRetry() {
                   // We know how to handle this: make a new call.
                   let call: Call<Request, Response> = self.client.channel.makeCall(
                       path: context.path,
                       type: context.type,
                       callOptions: context.options,
                       // We could grab interceptors from the client, but we don't need to.
                       interceptors: [LoggingRobotClientInterceptor()]
                   )

                   // We're retying the call now.
                   self.state = .retrying(call)

                   // Invoke the call and redirect responses here.

                   call.invoke(onError: context.errorCaught(_:), onResponsePart: context.receive(_:))

                   var newParts = parts
                   // Parts must contain the metadata as the first item if we got that first response.
                   if case var .some(.metadata(metadata)) = parts.first {
                       metadata.replaceOrAdd(name: "access_token", value: APICommon.accessToken)
                       newParts[0] = .metadata(metadata)
                   }

                   // Now replay any requests on the retry call.
                   for part in newParts {
                       call.send(part, promise: nil)
                   }
               }

    `

Additional information

Test Suite 'Selected tests' started at 2022-05-25 11:28:02.229 Test Suite 'RobotSDKTests.xctest' started at 2022-05-25 11:28:02.230 Test Suite 'RbotTests' started at 2022-05-25 11:28:02.230 Test Case '-[RobotSDKTests.RbotTests testGenerateBindRobotQRCode]' started. 2022-05-25 11:28:02.288753+0800 RobotSDK[87525:1909802] [] nw_listener_socket_inbox_create_socket setsockopt SO_NECP_LISTENUUID failed [2: No such file or directory] 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] PoolManager.swift:172 initialize(perPoolConfiguration:logger:) : poolmanager.pools.waiters_per_pool=100 poolmanager.pools.conns_per_pool=1 poolmanager.pools.count=5 poolmanager.id=ObjectIdentifier(0x0000600003857e00) initializing connection pool manager

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] ConnectionPool.swift:370 _enqueueWaiter(deadline:promise:logger:initializer:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 pool.waiters.count=0 pool.waiter.id=ObjectIdentifier(0x0000600000e26800) waiting for a connection to become available

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:378 _enqueueWaiter(deadline:promise:logger:initializer:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.waiters.count=1 enqueued connection waiter

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionPool.swift:426 _shouldBringUpAnotherConnection() : pool.reservations.loadThreshold=0.9 poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.reservations.count=1 pool.reservations.capacity=0 pool.reservations.load=inf stream reservation load factor greater than or equal to threshold, bringing up additional connection if available

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:195 send(_:promise:context:) : > Starting '/app.Account/BindThirdAccount' RPC, headers: ['authorization': 'Robot', 'access_token': '74']

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : request_part=metadata grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 call_state=awaitingTransport (0 parts buffered) buffering request part

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:200 send(_:promise:context:) : > Sending request with 'RobotSDK.App_BindThirdAccountRequest: thirdAccount: "kun.zhang@voidtech.com.cn" plat: IOS '

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 request_part=message call_state=awaitingTransport (1 parts buffered) buffering request part

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:204 send(_:promise:context:) : > Closing request stream

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 request_part=end call_state=awaitingTransport (2 parts buffered) buffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] PlatformSupport.swift:199 makeClientBootstrap(group:logger:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 making client bootstrap with event loop group of type NIOTSEventLoop

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] PlatformSupport.swift:203 makeClientBootstrap(group:logger:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 Network.framework is available and the EventLoopGroup is compatible with NIOTS, creating a NIOTSConnectionBootstrap

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionManager.swift:621 channelActive(channel:multiplexer:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 connectivity_state=connecting activating connection

11:28:02.330 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:499 receiveSettings(_:): HTTP2 settings update { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_settings_initial_window_size=8388608 h2_settings_max_concurrent_streams=0 h2_settings_max_frame_size=8388608 h2_settings_max_header_listsize=16384 } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:499 receiveSettings(:) : h2_settings_initial_window_size=8388608 h2_settings_max_concurrent_streams=100 grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 grpc.conn.addr_local=::1 h2_settings_max_frame_size=16384 h2_settings_max_header_list_size=16384 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) HTTP2 settings update

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionManager.swift:743 ready() : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 connectivity_state=active connection ready

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:661 tryServiceWaiters() : pool.waiters.count=1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) servicing waiters

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:687 tryServiceWaiters() : poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.waiters.count=0 pool.waiters.serviced=1 done servicing waiters

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] ClientTransport.swift:333 _transportActivated(channel:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 activated stream channel

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:871 unbuffer() : request_parts=3 grpc.conn.addr_remote=::1 grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 grpc.conn.addr_local=::1 unbuffering request parts

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : request_part=metadata grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:509 write(context:data:promise:) : h2_headers=[([], ":method", "POST"), ([], ":path", "/app.Account/BindThirdAccount"), ([], ":authority", "localhost"), ([], ":scheme", "http"), ([], "content-type", "application/grpc"), ([], "te", "trailers"), ([], "grpc-timeout", "19999881u"), ([], "authorization", "Robot"), ([], "access_token", "74"), ([], "user-agent", "grpc-swift-nio/1.7.1-async-await.1")] h2_payload=HEADERS grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 h2_end_stream=false writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 request_part=message grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:536 write(context:data:promise:) : h2_data_bytes=34 h2_end_stream=false grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 h2_payload=DATA writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : grpc.conn.addr_local=::1 request_part=end grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 grpc.conn.addr_remote=::1 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:569 write(context:data:promise:) : h2_payload=DATA h2_end_stream=true h2_data_bytes=0 grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:) : h2_active_streams=1 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_stream_id=HTTP2StreamID(1) HTTP2 stream created

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:900 unbuffer() : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 request buffer drained

11:28:02.384 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:): HTTP2 stream created { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=1 h2_stream_id=HTTP2StreamID(1) } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:355 readHeaders(content:context:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 h2_payload=HEADERS h2_end_stream=false h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc")] received HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:226 receive(_:context:) : < Received headers: [':status': '200', 'content-type': 'application/grpc']

11:28:02.388 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(_:logger:): HTTP2 stream closed { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=0 h2_stream_id=HTTP2StreamID(1) } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:429 readData(content:context:) : h2_payload=DATA h2_data_bytes=5 h2_end_stream=false grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 received HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:232 receive(_:context:) : < Received response with 'RobotSDK.App_BindThirdAccountReply: '

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(_:logger:) : h2_active_streams=0 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_stream_id=HTTP2StreamID(1) HTTP2 stream closed

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:355 readHeaders(content:context:) : grpc_request_id=208A5FE4-CAAC-4E34-BACC-AF0E4BEC2A28 h2_end_stream=true h2_headers=[([], "grpc-status", "0")] h2_payload=HEADERS received HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:239 receive(_:context:) : < Response stream closed /app.Account/BindThirdAccount with status: 'ok (0)' and trailers: ['grpc-status': '0']

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] ClientTransport.swift:333 _transportActivated(channel:) : grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 activated stream channel

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:871 unbuffer() : request_parts=0 grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 unbuffering request parts

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:900 unbuffer() : grpc.conn.addr_remote=::1 grpc.conn.addr_local=::1 grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 request buffer drained

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:195 send(_:promise:context:) : > Starting '/app.Robot/BindMachine' RPC, headers: ['authorization': 'Robot', 'access_token': '74']

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:509 write(context:data:promise:) : h2_headers=[([], ":method", "POST"), ([], ":path", "/app.Robot/BindMachine"), ([], ":authority", "localhost"), ([], ":scheme", "http"), ([], "content-type", "application/grpc"), ([], "te", "trailers"), ([], "grpc-timeout", "19999971u"), ([], "authorization", "Robot"), ([], "access_token", "74"), ([], "user-agent", "grpc-swift-nio/1.7.1-async-await.1")] grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 h2_payload=HEADERS h2_end_stream=false writing HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:200 send(_:promise:context:) : > Sending request with 'RobotSDK.App_BindMachineRequest: machineModel: "Rbot_air" '

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:536 write(context:data:promise:) : grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 h2_payload=DATA h2_data_bytes=14 h2_end_stream=false writing HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:204 send(_:promise:context:) : > Closing request stream

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:569 write(context:data:promise:) : h2_payload=DATA grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 h2_data_bytes=0 h2_end_stream=true writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:) : h2_active_streams=1 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_stream_id=HTTP2StreamID(3) HTTP2 stream created

11:28:02.399 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:): HTTP2 stream created { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=1 h2_streamid=HTTP2StreamID(3) } 11:28:02.401 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(:logger:): HTTP2 stream closed { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=0 h2_streamid=HTTP2StreamID(3) } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(:logger:) : h2_active_streams=0 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_stream_id=HTTP2StreamID(3) HTTP2 stream closed

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:355 readHeaders(content:context:) : grpc_request_id=14F90D4D-B361-4F3C-B0C4-9765E8C51A79 h2_payload=HEADERS h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc"), ([], "grpc-status", "16"), ([], "www-authenticate", "Robot")] h2_end_stream=true received HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💛 WARNING] Interceptors.swift:241 receive(_:context:) : < Response stream closed /app.Robot/BindMachine with status: 'unauthenticated (16)' and trailers: [':status': '200', 'content-type': 'application/grpc', 'grpc-status': '16', 'www-authenticate': 'Robot']

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:195 send(_:promise:context:) : > Starting '/app.Account/RefreshTokens' RPC, headers: ['authorization': 'Robot', 'access_token': '74']

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:200 send(_:promise:context:) : > Sending request with 'RobotSDK.App_RefreshTokensRequest: refreshToken: "cGBMje7F40wt6VL3HVtAjfXtLqZL+yukF/xSr6PdaZre2Yt/jf5fFtjLCAM5nayuCXqv6RayZFzCVSGPZ14R/XK2+aodYBDHE+jgNWyK5yhRctH+AE5bnnybSc6dNmT2F2cWa1ihjwZ5/zodk2+hrzhgxe1m6ZLZxh4ZacK4SMYZ299SKcJPpoSPJ5AxYDjkUVlWT3hqOiJ9Rlr7x68VvpjXvJwy6rbcZtko+qO1bNyNfzdXO4Cw31ldXhtAvZYwmilIut7yKMt37Qd88t7xaDU=.bba0955e42054885f5d908a14138957a97520abd38d6036dd6a588c052f42b5c.V2" '

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:204 send(_:promise:context:) : > Closing request stream

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:) : h2_active_streams=1 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_stream_id=HTTP2StreamID(5) HTTP2 stream created

11:28:02.410 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:): HTTP2 stream created { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=1 h2_streamid=HTTP2StreamID(5) } 2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:226 receive(:context:) : < Received headers: [':status': '200', 'content-type': 'application/grpc']

11:28:02.412 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(_:logger:): HTTP2 stream closed { grpc_connection_id=848AF8C4-0DA4-4D40-A198-FC83A76BA6BD h2_active_streams=0 h2_streamid=HTTP2StreamID(5) } 2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:232 receive(:context:) : < Received response with 'RobotSDK.App_RefreshTokensReply: error { msg: "success" } accessToken: "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsInZlcnNpb24iOiIyIn0=.eyJzZXNzaW9uSGFuZGxlIjoiMzk3YjZmNGYtNmYwZi00NGRjLWFhMzMtMjljMDcwMGI2MmEyIiwidXNlcklkIjoiT2JqZWN0SUQoXCI2Mjg0YTI2NTZlZWZmMDQ1ZTg2MzE5MWNcIikiLCJyZWZyZXNoVG9rZW5IYXNoMSI6IjQxYWVjZTNjN2FiOGQ1NzdkODc1MDg5MzgwY2Y5YjdmNDYyYTc3NDcxMGQ2NDlmOGNjYmZiYzJhZWNkMjY5MjMiLCJ1c2VyRGF0YSI6e30sImV4cGlyeVRpbWUiOjE2NTI5NzQ2NTE3NDUsInRpbWVDcmVhdGVkIjoxNjUyOTMxNDUxNzQ1LCJsbXJ0IjoxNjUyOTMxNDUxNzQ1fQ==.poq41KmXxE9ux4lgjIofwqpXI+N2aYakrKuf7/Y4WHMBStDfNURxQYHN58Kx84iCbLlGigz7ENpE4oLiLktPxnNeS2zSFxkpmW1QY2hnNDsOT4E7gNBL3YyOoSBVIsc+k9gIFkczCxqY2gjwzUTiQZvGfh1JSmP3EIYvF25uETPIYKlerWffNF4uKU5E77/OF3B+qEoobh6NYs4/TQQ3hKl475OAYMLva7jnw8qGeHwGSDPksO08M1feKH8mOURbANU1NQkI3jMk9AuyGtlbOgloACv9I38IlsGtzHwyoDE9eTSRBxrAoq/Ouy/7b37sIm0PC2tucssqWRwKzxGJMA==" refreshToken: "cGBMje7F40wt6VL3HVtAjfXtLqZL+yukF/xSr6PdaZre2Yt/jf5fFtjLCAM5nayuCXqv6RayZFzCVSGPZ14R/XK2+aodYBDHE+jgNWyK5yhRctH+AE5bnnybSc6dNmT2F2cWa1ihjwZ5/zodk2+hrzhgxe1m6ZLZxh4ZacK4SMYZ299SKcJPpoSPJ5AxYDjkUVlWT3hqOiJ9Rlr7x68VvpjXvJwy6rbcZtko+qO1bNyNfzdXO4Cw31ldXhtAvZYwmilIut7yKMt37Qd88t7xaDU=.bba0955e42054885f5d908a14138957a97520abd38d6036dd6a588c052f42b5c.V2" '

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] Call.swift:123 invoke(onError:onResponsePart:) : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 path=/app.Robot/BindMachine starting rpc

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] ConnectionPool.swift:370 _enqueueWaiter(deadline:promise:logger:initializer:) : pool.waiter.id=ObjectIdentifier(0x0000600000e2d9a0) pool.waiters.count=0 grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 waiting for a connection to become available

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:378 _enqueueWaiter(deadline:promise:logger:initializer:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.waiters.count=1 enqueued connection waiter

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(_:logger:) : h2_stream_id=HTTP2StreamID(5) grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=DC02ADC5-4B0E-42CE-A51B-491018C8987A/0 h2_active_streams=0 HTTP2 stream closed

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionPool.swift:426 _shouldBringUpAnotherConnection() : pool.reservations.count=1 pool.reservations.load=inf pool.reservations.capacity=0 poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.reservations.loadThreshold=0.9 stream reservation load factor greater than or equal to threshold, bringing up additional connection if available

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:239 receive(_:context:) : < Response stream closed /app.Account/RefreshTokens with status: 'ok (0)' and trailers: ['grpc-status': '0']

2022-05-25T11:28:02+0800 [Robot] [💛 WARNING] Interceptors.swift:152 receive(_:context:) : refresh token success: RobotSDK.App_RefreshTokensReply: error { msg: "success" } accessToken: "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsInZlcnNpb24iOiIyIn0=.eyJzZXNzaW9uSGFuZGxlIjoiMzk3YjZmNGYtNmYwZi00NGRjLWFhMzMtMjljMDcwMGI2MmEyIiwidXNlcklkIjoiT2JqZWN0SUQoXCI2Mjg0YTI2NTZlZWZmMDQ1ZTg2MzE5MWNcIikiLCJyZWZyZXNoVG9rZW5IYXNoMSI6IjQxYWVjZTNjN2FiOGQ1NzdkODc1MDg5MzgwY2Y5YjdmNDYyYTc3NDcxMGQ2NDlmOGNjYmZiYzJhZWNkMjY5MjMiLCJ1c2VyRGF0YSI6e30sImV4cGlyeVRpbWUiOjE2NTI5NzQ2NTE3NDUsInRpbWVDcmVhdGVkIjoxNjUyOTMxNDUxNzQ1LCJsbXJ0IjoxNjUyOTMxNDUxNzQ1fQ==.poq41KmXxE9ux4lgjIofwqpXI+N2aYakrKuf7/Y4WHMBStDfNURxQYHN58Kx84iCbLlGigz7ENpE4oLiLktPxnNeS2zSFxkpmW1QY2hnNDsOT4E7gNBL3YyOoSBVIsc+k9gIFkczCxqY2gjwzUTiQZvGfh1JSmP3EIYvF25uETPIYKlerWffNF4uKU5E77/OF3B+qEoobh6NYs4/TQQ3hKl475OAYMLva7jnw8qGeHwGSDPksO08M1feKH8mOURbANU1NQkI3jMk9AuyGtlbOgloACv9I38IlsGtzHwyoDE9eTSRBxrAoq/Ouy/7b37sIm0PC2tucssqWRwKzxGJMA==" refreshToken: "cGBMje7F40wt6VL3HVtAjfXtLqZL+yukF/xSr6PdaZre2Yt/jf5fFtjLCAM5nayuCXqv6RayZFzCVSGPZ14R/XK2+aodYBDHE+jgNWyK5yhRctH+AE5bnnybSc6dNmT2F2cWa1ihjwZ5/zodk2+hrzhgxe1m6ZLZxh4ZacK4SMYZ299SKcJPpoSPJ5AxYDjkUVlWT3hqOiJ9Rlr7x68VvpjXvJwy6rbcZtko+qO1bNyNfzdXO4Cw31ldXhtAvZYwmilIut7yKMt37Qd88t7xaDU=.bba0955e42054885f5d908a14138957a97520abd38d6036dd6a588c052f42b5c.V2"

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:195 send(_:promise:context:) : > Starting '/app.Robot/BindMachine' RPC, headers: ['authorization': 'Robot', 'access_token': 'eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsInZlcnNpb24iOiIyIn0=.eyJzZXNzaW9uSGFuZGxlIjoiMzk3YjZmNGYtNmYwZi00NGRjLWFhMzMtMjljMDcwMGI2MmEyIiwidXNlcklkIjoiT2JqZWN0SUQoXCI2Mjg0YTI2NTZlZWZmMDQ1ZTg2MzE5MWNcIikiLCJyZWZyZXNoVG9rZW5IYXNoMSI6IjQxYWVjZTNjN2FiOGQ1NzdkODc1MDg5MzgwY2Y5YjdmNDYyYTc3NDcxMGQ2NDlmOGNjYmZiYzJhZWNkMjY5MjMiLCJ1c2VyRGF0YSI6e30sImV4cGlyeVRpbWUiOjE2NTI5NzQ2NTE3NDUsInRpbWVDcmVhdGVkIjoxNjUyOTMxNDUxNzQ1LCJsbXJ0IjoxNjUyOTMxNDUxNzQ1fQ==.poq41KmXxE9ux4lgjIofwqpXI+N2aYakrKuf7/Y4WHMBStDfNURxQYHN58Kx84iCbLlGigz7ENpE4oLiLktPxnNeS2zSFxkpmW1QY2hnNDsOT4E7gNBL3YyOoSBVIsc+k9gIFkczCxqY2gjwzUTiQZvGfh1JSmP3EIYvF25uETPIYKlerWffNF4uKU5E77/OF3B+qEoobh6NYs4/TQQ3hKl475OAYMLva7jnw8qGeHwGSDPksO08M1feKH8mOURbANU1NQkI3jMk9AuyGtlbOgloACv9I38IlsGtzHwyoDE9eTSRBxrAoq/Ouy/7b37sIm0PC2tucssqWRwKzxGJMA==']

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : request_part=metadata call_state=awaitingTransport (0 parts buffered) grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 buffering request part

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:200 send(_:promise:context:) : > Sending request with 'RobotSDK.App_BindMachineRequest: machineModel: "Rbot_air" '

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 call_state=awaitingTransport (1 parts buffered) request_part=message buffering request part

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:204 send(_:promise:context:) : > Closing request stream

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:853 buffer(_:promise:) : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 call_state=awaitingTransport (2 parts buffered) request_part=end buffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] PlatformSupport.swift:199 makeClientBootstrap(group:logger:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 making client bootstrap with event loop group of type NIOTSEventLoop

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] PlatformSupport.swift:203 makeClientBootstrap(group:logger:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 Network.framework is available and the EventLoopGroup is compatible with NIOTS, creating a NIOTSConnectionBootstrap

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionManager.swift:621 channelActive(channel:multiplexer:) : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 connectivity_state=connecting activating connection

11:28:02.424 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:499 receiveSettings(_:): HTTP2 settings update { grpc_connection_id=E8183975-D1EC-47B3-B6CA-9EC79B603D3F h2_settings_initial_window_size=8388608 h2_settings_max_concurrent_streams=0 h2_settings_max_frame_size=8388608 h2_settings_max_header_listsize=16384 } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:499 receiveSettings(:) : grpc.conn.addr_remote=::1 h2_settings_max_header_list_size=16384 h2_settings_max_concurrent_streams=100 h2_settings_max_frame_size=16384 grpc.conn.addr_local=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 h2_settings_initial_window_size=8388608 HTTP2 settings update

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] ConnectionManager.swift:743 ready() : poolmanager.id=ObjectIdentifier(0x0000600003857e00) grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 connectivity_state=active connection ready

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:661 tryServiceWaiters() : poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.waiters.count=1 servicing waiters

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [🖤 TRACE] ConnectionPool.swift:687 tryServiceWaiters() : poolmanager.id=ObjectIdentifier(0x0000600003857e00) pool.waiters.count=0 pool.waiters.serviced=1 done servicing waiters

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [💚 DEBUG] ClientTransport.swift:333 _transportActivated(channel:) : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 activated stream channel

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:871 unbuffer() : grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 request_parts=3 grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 unbuffering request parts

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 request_part=metadata grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:509 write(context:data:promise:) : h2_headers=[([], ":method", "POST"), ([], ":path", "/app.Robot/BindMachine"), ([], ":authority", "localhost"), ([], ":scheme", "http"), ([], "content-type", "application/grpc"), ([], "te", "trailers"), ([], "grpc-timeout", "19999975u"), ([], "authorization", "Robot"), ([], "access_token", "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsInZlcnNpb24iOiIyIn0=.eyJzZXNzaW9uSGFuZGxlIjoiMzk3YjZmNGYtNmYwZi00NGRjLWFhMzMtMjljMDcwMGI2MmEyIiwidXNlcklkIjoiT2JqZWN0SUQoXCI2Mjg0YTI2NTZlZWZmMDQ1ZTg2MzE5MWNcIikiLCJyZWZyZXNoVG9rZW5IYXNoMSI6IjQxYWVjZTNjN2FiOGQ1NzdkODc1MDg5MzgwY2Y5YjdmNDYyYTc3NDcxMGQ2NDlmOGNjYmZiYzJhZWNkMjY5MjMiLCJ1c2VyRGF0YSI6e30sImV4cGlyeVRpbWUiOjE2NTI5NzQ2NTE3NDUsInRpbWVDcmVhdGVkIjoxNjUyOTMxNDUxNzQ1LCJsbXJ0IjoxNjUyOTMxNDUxNzQ1fQ==.poq41KmXxE9ux4lgjIofwqpXI+N2aYakrKuf7/Y4WHMBStDfNURxQYHN58Kx84iCbLlGigz7ENpE4oLiLktPxnNeS2zSFxkpmW1QY2hnNDsOT4E7gNBL3YyOoSBVIsc+k9gIFkczCxqY2gjwzUTiQZvGfh1JSmP3EIYvF25uETPIYKlerWffNF4uKU5E77/OF3B+qEoobh6NYs4/TQQ3hKl475OAYMLva7jnw8qGeHwGSDPksO08M1feKH8mOURbANU1NQkI3jMk9AuyGtlbOgloACv9I38IlsGtzHwyoDE9eTSRBxrAoq/Ouy/7b37sIm0PC2tucssqWRwKzxGJMA=="), ([], "user-agent", "grpc-swift-nio/1.7.1-async-await.1")] h2_end_stream=false grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 h2_payload=HEADERS writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : grpc.conn.addr_remote=::1 grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 request_part=message grpc.conn.addr_local=::1 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:536 write(context:data:promise:) : h2_payload=DATA grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 h2_data_bytes=14 h2_end_stream=false writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:881 unbuffer() : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 grpc.conn.addr_remote=::1 request_part=end grpc.conn.addr_local=::1 unbuffering request part

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:569 write(context:data:promise:) : h2_payload=DATA grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 h2_data_bytes=0 h2_end_stream=true writing HTTP2 frame

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Channel] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:) : grpc.conn.addr_remote=::1 poolmanager.id=ObjectIdentifier(0x0000600003857e00) h2_active_streams=1 h2_stream_id=HTTP2StreamID(1) grpc.conn.addr_local=::1 grpc_connection_id=324F3F12-7ED6-45FF-A2F4-4DC719148B9B/0 HTTP2 stream created

2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] ClientTransport.swift:900 unbuffer() : grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 grpc.conn.addr_local=::1 grpc.conn.addr_remote=::1 request buffer drained

11:28:02.434 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:646 streamCreated(_:logger:): HTTP2 stream created { grpc_connection_id=E8183975-D1EC-47B3-B6CA-9EC79B603D3F h2_active_streams=1 h2_stream_id=HTTP2StreamID(1) } 2022-05-25T11:28:02+0800 [RobotSDK.GRPC.Client] [🖤 TRACE] GRPCClientChannelHandler.swift:355 readHeaders(content:context:) : h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc")] h2_end_stream=false h2_payload=HEADERS grpc_request_id=2660F275-34BD-4365-B269-D78E1E95A001 received HTTP2 frame

2022-05-25T11:28:02+0800 [Robot] [💙 INFO] Interceptors.swift:226 receive(_:context:) : < Received headers: [':status': '200', 'content-type': 'application/grpc']

11:28:02.436 [server] [💚 DEBUG] GRPCIdleHandlerStateMachine.swift:668 streamClosed(_:logger:): HTTP2 stream closed { grpc_connection_id=E8183975-D1EC-47B3-B6CA-9EC79B603D3F h2_active_streams=0 h2_stream_id=HTTP2StreamID(1) } (lldb)

ripplek commented 2 years ago
image
FranzBusch commented 2 years ago

Thanks for opening this @ripplek. After looking through your call stack and the code you provided I am certain that this is not a bug in grpc-swift.

The precondition that is being triggered asserts that the a call to the ClientInterceptorContext.receive() is on the correct event loop. This is happening because you are spawning Task and calling the context.receive method inside the task here:

Task {
    switch await refreshTokenReq.result {
    case .success:
        updateMetadataRetry()
    case .failure:
        context.receive(part)
    }
}

When you create a new Task the content inside the task is executed on one of the threads of the cooperative thread pool.

I would advise you to be careful with mixing NIO EventLoop based APIs and Swift Concurrency APIs. What you are trying to achieve is probably better rewritten completely using EventLoopFutures.

If you still want to go down the route of mixing the two concepts you need to think carefully on which thread you are executing and make the necessary thread jumps back to the EventLoop by calling something like eventLoop.execute {}. However, this can introduce data races quite easily so be extra careful!

glbrntt commented 2 years ago

@FranzBusch is absolutely right here: the send/receive methods on the interceptor context must be called from the appropriate eventLoop. This precondition is in place to make sure that the API is used correctly.

See also: https://github.com/grpc/grpc-swift/blob/0981d4dccc2cd029d53cd5da43fc9bebea2c81e4/Sources/GRPC/Interceptor/ClientInterceptors.swift#L44-L50

ripplek commented 2 years ago

Hello @FranzBusch @glbrntt, Thanks for your reply, I updated my code and tested

Test A

if let refreshTokenReq = tokenRequestCache[requestToken] {
    Task {
        switch await refreshTokenReq.result {
        case .success:
            context.eventLoop.execute {
                updateMetadataRetry()
            }
        case .failure:
            context.eventLoop.execute {
                context.receive(part)
            }
        }
    }
    return
}

tokenRequestCache[requestToken] = Task<App_RefreshTokensReply, Error> {
    do {
        let reply = try await App_AccountAsyncClient(channel: self.client.channel)
            .refreshTokens(.with { $0.refreshToken = APICommon.refreshToken })
        APICommon.accessToken = reply.accessToken
        APICommon.refreshToken = reply.refreshToken

        context.eventLoop.execute {
            updateMetadataRetry()
        }
        log.warning("refresh token success: \(reply)")
        return reply
    } catch {
        log.error("refresh token failed: \(error)")
        tokenRequestCache[requestToken] = nil
        context.eventLoop.execute {
            context.receive(part)
        }
        throw error
    }
}

Test B

@Sendable func updateMetadataRetry() {
    // We know how to handle this: make a new call.
    let call: Call<Request, Response> = self.client.channel.makeCall(
        path: context.path,
        type: context.type,
        callOptions: context.options,
        // We could grab interceptors from the client, but we don't need to.
        interceptors: []
    )

    // We're retying the call now.
    self.state = .retrying(call)

    // Invoke the call and redirect responses here.
    call.invoke {  error in
        if context.eventLoop.inEventLoop {
            context.errorCaught(error)
        } else {
            context.eventLoop.execute {
                context.errorCaught(error)
            }
        }
    } onResponsePart: { part in
        if context.eventLoop.inEventLoop {
            context.receive(part)
        } else {
            context.eventLoop.execute {
                context.receive(part)
            }
        }
    }

    var newParts = parts
    // Parts must contain the metadata as the first item if we got that first response.
    if case var .some(.metadata(metadata)) = parts.first {
        metadata.replaceOrAdd(name: "access_token", value: APICommon.accessToken)
        newParts[0] = .metadata(metadata)
    }

    // Now replay any requests on the retry call.
    for part in newParts {
        call.send(part, promise: nil)
    }
}

Test B finally solved my problem, This is my final revision

@Sendable func updateMetadataRetry() {
    // We know how to handle this: make a new call.
    let call: Call<Request, Response> = self.client.channel.makeCall(
        path: context.path,
        type: context.type,
        callOptions: context.options,
        // We could grab interceptors from the client, but we don't need to.
        interceptors: []
    )

    // We're retying the call now.
    self.state = .retrying(call)

    // Invoke the call and redirect responses here.
    call.invoke {  error in
        if context.eventLoop.inEventLoop {
            context.errorCaught(error)
        } else {
            context.eventLoop.execute {
                context.errorCaught(error)
            }
        }
    } onResponsePart: { part in
        if context.eventLoop.inEventLoop {
            context.receive(part)
        } else {
            context.eventLoop.execute {
                context.receive(part)
            }
        }
    }

    var newParts = parts
    // Parts must contain the metadata as the first item if we got that first response.
    if case var .some(.metadata(metadata)) = parts.first {
        metadata.replaceOrAdd(name: "access_token", value: APICommon.accessToken)
        newParts[0] = .metadata(metadata)
    }

    // Now replay any requests on the retry call.
    for part in newParts {
        call.send(part, promise: nil)
    }
}

if let refreshTokenReq = tokenRequestCache[requestToken] {
    Task {
        switch await refreshTokenReq.result {
        case .success:
            updateMetadataRetry()
        case .failure:
            context.eventLoop.execute {
                context.receive(part)
            }
        }
    }
    return
}

tokenRequestCache[requestToken] = Task<App_RefreshTokensReply, Error> {
    do {
        let reply = try await App_AccountAsyncClient(channel: self.client.channel)
            .refreshTokens(.with { $0.refreshToken = APICommon.refreshToken })
        APICommon.accessToken = reply.accessToken
        APICommon.refreshToken = reply.refreshToken
        updateMetadataRetry()
        log.warning("refresh token success: \(reply)")
        return reply
    } catch {
        log.error("refresh token failed: \(error)")
        tokenRequestCache[requestToken] = nil
        context.eventLoop.execute {
            context.receive(part)
        }
        throw error
    }
}