search

alkee-allm / k2proto

grpc service sample
6 stars 2 forks source link

ping response 받은 frontend 의 crash #51

Closed alkee-allm closed 4 years ago

alkee-allm commented 4 years ago

Frontend server를 먼저 띄우고 ServerManager 를 띄우는 상황에 가끔씩 발생.

Console log:

warn: K2svc.Background.ServerManagementBackground[0]
      ERROR on ping : Service is unimplemented.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST http://[::1]:9060/K2B.ServerHost/Stop application/grpc
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /K2B.ServerHost/Stop'

Debug output:

예외 발생: 'System.ApplicationException'(K2svc.dll)
'System.ApplicationException' 형식의 예외가 K2svc.dll에서 발생했지만 사용자 코드에서 처리되지 않았습니다.
invalid backend request of /K2B.ServerHost/Stop from ipv6:[::1]:65282

Call stack:

>   K2svc.dll!K2svc.Filter.BackendValidator.UnaryServerHandler<K2B.StopRequest, K2B.Null>(K2B.StopRequest request, Grpc.Core.ServerCallContext context, Grpc.Core.UnaryServerMethod<K2B.StopRequest, K2B.Null> continuation) 줄 31   C#
    [외부 코드] 
    K2svc.dll!K2svc.Startup.Configure.AnonymousMethod__0(Microsoft.AspNetCore.Http.HttpContext context, System.Func<System.Threading.Tasks.Task> next) 줄 79 C#
    [외부 코드]

Screenshot: image

Detail:

$exception

  | 이름 | 값 | 형식
-- | -- | -- | --
◢ | $exception | {"invalid backend request of /K2B.ServerHost/Stop from ipv6:[::1]:65282"} | System.ApplicationException
  | ▶ Data | {System.Collections.ListDictionaryInternal} | System.Collections.IDictionary {System.Collections.ListDictionaryInternal}
  | HResult | -2146232832 | int
  | HelpLink | null | string
  | ▶ InnerException | null | System.Exception
  | Message | "invalid backend request of /K2B.ServerHost/Stop from ipv6:[::1]:65282" | string
  | Source | "K2svc" | string
  | StackTrace | "   at K2svc.Filter.BackendValidator.UnaryServerHandler[TRequest,TResponse](TRequest request, ServerCallContext context, UnaryServerMethod`2 continuation) in C:\\work\\local\\K2\\K2svc\\Filter\\BackendValidator.cs:line 32\r\n   at Grpc.Shared.Server.InterceptorPipelineBuilder`2.<>c__DisplayClass5_0.<<UnaryPipeline>b__1>d.MoveNext()" | string
  | ▶ TargetSite | {System.Threading.Tasks.Task`1[TResponse] UnaryServerHandler[TRequest,TResponse](TRequest, Grpc.Core.ServerCallContext, Grpc.Core.UnaryServerMethod`2[TRequest,TResponse])} | System.Reflection.MethodBase {System.Reflection.RuntimeMethodInfo}
  | ▶ Static members |   |  
  | ▶ Non-Public members |   |  
alkee-allm commented 4 years ago

서버코드 수정(#38)이후 재현이 되지 않는다. 하지만 ServerManager 없이 실행되는 경우 클라이언트가 연결되면 클라이언트에서 No status received grpc::Status 반환되어 진행불가.

처리되지 않은 예외 발생(0x00007FFEB36E3E49, K2client.exe): Microsoft C++ 예외: std::basic_string<char,std::char_traits<char>,std::allocator<char> >, 메모리 위치 0x000000CB2DDFE698. 발생
status = {code_=UNKNOWN (2) error_message_="No status received" binary_error_details_="" }

이는 서버가 아직 register 되지 않아 발생한 문제.. 이를 개발환경에서 쉽게 확인할 수 있도록 할 필요가 있다.

alkee-allm commented 4 years ago

client 가 연결된 상태에서 ServerManager process 를 열었다 닫았다를 반복하니 아래와 같은 문제 발생

output:

예외 발생: 'Grpc.Core.RpcException'(System.Private.CoreLib.dll)
'Grpc.Core.RpcException' 형식의 예외가 System.Private.CoreLib.dll에서 발생했지만 사용자 코드에서 처리되지 않았습니다.
Status(StatusCode=DeadlineExceeded, Detail="")

exception:

  | 이름 | 값 | 형식
-- | -- | -- | --
◢ | $exception | {"Status(StatusCode=DeadlineExceeded, Detail=\"\")"} | Grpc.Core.RpcException
  | ▶ Data | {System.Collections.ListDictionaryInternal} | System.Collections.IDictionary {System.Collections.ListDictionaryInternal}
  | HResult | -2146233088 | int
  | HelpLink | null | string
  | ▶ InnerException | null | System.Exception
  | Message | "Status(StatusCode=DeadlineExceeded, Detail=\"\")" | string
  | Source | "System.Private.CoreLib" | string
  | StackTrace | "   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()\r\n   at Grpc.Net.Client.Internal.HttpClientCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)\r\n   at Grpc.Core.Interceptors.InterceptingCallInvoker.<BlockingUnaryCall>b__3_0[TRequest,TResponse](TRequest req, ClientInterceptorContext`2 ctx)\r\n   at Grpc.Core.ClientBase.ClientBaseConfiguration.ClientBaseConfigurationInterceptor.BlockingUnaryCall[TRequest,TResponse](TRequest request, ClientInterceptorContext`2 context, BlockingUnaryCallContinuation`2 continuation)\r\n   at Grpc.Core.Interceptors.InterceptingCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)\r\n   at K2B.SessionManager.SessionManagerClient.AddUser(AddUserRequest request, CallOptions options) in C:\\work\\local\\K2\\K2svc\\obj\\Debug\\netcoreapp3.1\\BackendGrpc.cs:line 537\r\n   at K2B.SessionManager.SessionManagerClient.AddUser(AddUserRequest request, Metadata headers, Nullable`1 deadline, CancellationToken cancellationToken) in C:\\work\\local\\K2\\K2svc\\obj\\Debug\\netcoreapp3.1\\BackendGrpc.cs:line 533\r\n   at K2svc.Frontend.PushService.PushStreamDb.SyncUsersToSessionManager(SessionManagerClient target, String backendAddress, Metadata headers) in C:\\work\\local\\K2\\K2svc\\Frontend\\PushService.cs:line 181\r\n   at K2svc.Backend.ServerHostBackend.UpdateBackend(UpdateBackendRequest request, ServerCallContext context) in C:\\work\\local\\K2\\K2svc\\Backend\\ServerHostBackend.cs:line 58\r\n   at Grpc.Shared.Server.UnaryServerMethodInvoker`3.<ResolvedInterceptorInvoker>d__3.MoveNext()" | string
  | ▶ Status | {Status(StatusCode=DeadlineExceeded, Detail="")} | Grpc.Core.Status
  | StatusCode | DeadlineExceeded | Grpc.Core.StatusCode
  | ▶ TargetSite | {Void Throw()} | System.Reflection.MethodBase {System.Reflection.RuntimeMethodInfo}
  | ▶ Trailers | {Grpc.Core.Metadata} | Grpc.Core.Metadata
  | ▶ Static members |   |  
  | ▶ Non-Public members |   |  

callstack:

>   K2svc.dll!K2B.SessionManager.SessionManagerClient.AddUser(K2B.AddUserRequest request, Grpc.Core.CallOptions options) 줄 537  C#
    K2svc.dll!K2B.SessionManager.SessionManagerClient.AddUser(K2B.AddUserRequest request, Grpc.Core.Metadata headers, System.DateTime? deadline, System.Threading.CancellationToken cancellationToken) 줄 533    C#
    K2svc.dll!K2svc.Frontend.PushService.PushStreamDb.SyncUsersToSessionManager(K2B.SessionManager.SessionManagerClient target, string backendAddress, Grpc.Core.Metadata headers) 줄 181    C#
    K2svc.dll!K2svc.Backend.ServerHostBackend.UpdateBackend(K2B.UpdateBackendRequest request, Grpc.Core.ServerCallContext context) 줄 58 C#
    [외부 코드] 
    K2svc.dll!K2svc.Filter.BackendValidator.UnaryServerHandler<K2B.UpdateBackendRequest, K2B.Null>(K2B.UpdateBackendRequest request, Grpc.Core.ServerCallContext context, Grpc.Core.UnaryServerMethod<K2B.UpdateBackendRequest, K2B.Null> continuation) 줄 30    C#
    [외부 코드] 
    K2svc.dll!K2svc.Startup.Configure.AnonymousMethod__0(Microsoft.AspNetCore.Http.HttpContext context, System.Func<System.Threading.Tasks.Task> next) 줄 80 C#
    [외부 코드]

code:

            public void SyncUsersToSessionManager(K2B.SessionManager.SessionManagerClient target, string backendAddress, Metadata headers)
            {
                lock (users)
                    foreach (var u in users)
                    {
                        target.AddUser(new K2B.AddUserRequest { Force = true, UserId = u.Value.Id, BackendListeningAddress = backendAddress } // << DeadlineExceeded
                        , headers: headers, deadline: DateTime.UtcNow.AddSeconds(0.5));
                    }
            }

PushStreamDb 가 logger 를 가지고있지 않아(DI를 사용하지 않음), exception handling 하더라도 로깅할 방법이 없다. 서비스중에 exception 이 발생하더라도 문제가 발생할 것 같지는 않지만, 개발환경을 위해 아무 로깅을 하지 않더라도 exception handling 하는 것이 나을 듯.

함수에 logger 를 parameter 로 넣도록(마음에 들지 않는다...)해 logging.

alkee-allm commented 4 years ago

exception handling 후 클라이언트가 연결된 상태에서 ServerManager 를 지속적으로 연결-연결해제(process 실행 종료 반복) 하다보니, 아래와 같은 로그와 함께 client 연결(push connection)이 종료됨

fail: Grpc.AspNetCore.Server.ServerCallHandler[17]
      Error sending message.
System.InvalidOperationException: Response Content-Length mismatch: too many bytes written (5 of 0).
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowTooManyBytesWritten(Int32 count)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.VerifyAndUpdateWrite(Int32 count)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Advance(Int32 bytes)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponsePipeWriter.Advance(Int32 bytes)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.WriteHeader(PipeWriter pipeWriter, Int32 length, Boolean compress)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.WriteMessage(ReadOnlySpan`1 data)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.Complete(Byte[] payload)
   at Grpc.Core.Marshaller`1.EmulateContextualSerializer(T message, SerializationContext context)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.WriteMessageAsync[TResponse](PipeWriter pipeWriter, TResponse response, HttpContextServerCallContext serverCallContext, Action`2 serializer, Boolean canFlush)
fail: Grpc.AspNetCore.Server.ServerCallHandler[6]
      Error when executing service method 'AddUser'.
System.InvalidOperationException: Response Content-Length mismatch: too many bytes written (5 of 0).
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowTooManyBytesWritten(Int32 count)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.VerifyAndUpdateWrite(Int32 count)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Advance(Int32 bytes)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponsePipeWriter.Advance(Int32 bytes)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.WriteHeader(PipeWriter pipeWriter, Int32 length, Boolean compress)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.WriteMessage(ReadOnlySpan`1 data)
   at Grpc.AspNetCore.Server.Internal.HttpContextSerializationContext.Complete(Byte[] payload)
   at Grpc.Core.Marshaller`1.EmulateContextualSerializer(T message, SerializationContext context)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.WriteMessageAsync[TResponse](PipeWriter pipeWriter, TResponse response, HttpContextServerCallContext serverCallContext, Action`2 serializer, Boolean canFlush)
   at Grpc.AspNetCore.Server.Internal.CallHandlers.UnaryServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext)
   at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall)
warn: K2svc.Backend.ServerHostBackend[0]
      failed to sync users : Grpc.Core.RpcException: Status(StatusCode=DeadlineExceeded, Detail="")
         at Grpc.Net.Client.Internal.HttpClientCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)
         at Grpc.Core.Interceptors.InterceptingCallInvoker.<BlockingUnaryCall>b__3_0[TRequest,TResponse](TRequest req, ClientInterceptorContext`2 ctx)
         at Grpc.Core.ClientBase.ClientBaseConfiguration.ClientBaseConfigurationInterceptor.BlockingUnaryCall[TRequest,TResponse](TRequest request, ClientInterceptorContext`2 context, BlockingUnaryCallContinuation`2 continuation)
         at Grpc.Core.Interceptors.InterceptingCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)
         at K2B.SessionManager.SessionManagerClient.AddUser(AddUserRequest request, CallOptions options) in C:\work\local\K2\K2svc\obj\Debug\netcoreapp3.1\BackendGrpc.cs:line 537
         at K2B.SessionManager.SessionManagerClient.AddUser(AddUserRequest request, Metadata headers, Nullable`1 deadline, CancellationToken cancellationToken) in C:\work\local\K2\K2svc\obj\Debug\netcoreapp3.1\BackendGrpc.cs:line 533
         at K2svc.Frontend.PushService.PushStreamDb.SyncUsersToSessionManager(SessionManagerClient target, String backendAddress, Metadata headers, ILogger logger) in C:\work\local\K2\K2svc\Frontend\PushService.cs:line 183

exception 발생했다고 client 연결이 종료되는 것은 문제가 있는데..

log 를 좀 더 보니, KickUser 가 자동으로 발생하고 있다.

icrosoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/2 POST http://[::1]:9060/K2B.SessionManager/AddUser application/grpc 
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executing endpoint 'gRPC - /K2B.SessionManager/AddUser'
Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/2 POST http://[::1]:9060/K2B.SessionHost/KickUser application/grpc 
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executing endpoint 'gRPC - /K2B.SessionHost/KickUser'
K2svc.Backend.SessionHostBackend: Information: force to disconnect user : k2
예외 발생: 'Grpc.Core.RpcException'(System.Private.CoreLib.dll)
K2svc.Backend.ServerHostBackend: Warning: failed to sync users : Status(StatusCode=DeadlineExceeded, Detail="")
예외 발생: 'System.OperationCanceledException'(System.Private.CoreLib.dll)
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executed endpoint 'gRPC - /K2B.SessionHost/KickUser'
예외 발생: 'System.OperationCanceledException'(System.Private.CoreLib.dll)

디버깅 때문에 break 걸어두었을 때 ServerManager 가 ping timout 처리 하면서 stop 시키기 때문.(#37)