dgs-framework icon indicating copy to clipboard operation
dgs-framework copied to clipboard
verified publisher icon Netflix

bug: Websocket session restarted every 10 seconds if "subscriptions-transport-ws" is used

Open sefi18 opened this issue 3 years ago • 1 comments

Expected behavior

  • Subscription with 'old' library "subscriptions-transport-ws" can be started (protocol: graphql-ws)
  • Websocket session is initialized and kept open until subscription is stopped

Actual behavior

  • Subscription with "subscriptions-transport-ws" can be started but the session is removed after 10 seconds
  • Subsequently a new session is started and again removed after 10 seconds

Steps to reproduce

This is reproducible with dgs-examples-java project

  • start subscription (increased log level to DEBUG)
subscription reviews{
  reviewAdded(showId: 1){
    username
    
  }
}

Log output:

2022-10-13 22:02:54.436  INFO 4148 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-10-13 22:02:54.436  INFO 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-10-13 22:02:54.437 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2022-10-13 22:02:54.437 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected AcceptHeaderLocaleResolver
2022-10-13 22:02:54.437 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected FixedThemeResolver
2022-10-13 22:02:54.438 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.view.DefaultRequestToViewNameTranslator@3c69d9cb
2022-10-13 22:02:54.438 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.support.SessionFlashMapManager@46af9841
2022-10-13 22:02:54.438 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2022-10-13 22:02:54.438  INFO 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
2022-10-13 22:02:54.454 DEBUG 4148 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Securing GET /subscriptions
2022-10-13 22:02:54.460 DEBUG 4148 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
2022-10-13 22:02:54.464 DEBUG 4148 --- [nio-8080-exec-1] o.s.s.w.a.AnonymousAuthenticationFilter  : Set SecurityContextHolder to anonymous SecurityContext
2022-10-13 22:02:54.470 DEBUG 4148 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [GET /subscriptions] with attributes [permitAll]
2022-10-13 22:02:54.470 DEBUG 4148 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Secured GET /subscriptions
2022-10-13 22:02:54.474 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/subscriptions", parameters={}
2022-10-13 22:02:54.486 DEBUG 4148 --- [nio-8080-exec-1] o.s.w.s.s.s.WebSocketHandlerMapping      : Mapped to org.springframework.web.socket.server.support.WebSocketHttpRequestHandler@3c108c05
2022-10-13 22:02:54.494 DEBUG 4148 --- [nio-8080-exec-1] o.s.w.s.s.s.WebSocketHttpRequestHandler  : GET /subscriptions
2022-10-13 22:02:54.561 DEBUG 4148 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 101 SWITCHING_PROTOCOLS
2022-10-13 22:02:54.563 DEBUG 4148 --- [nio-8080-exec-1] w.c.HttpSessionSecurityContextRepository : Did not store anonymous SecurityContext
2022-10-13 22:02:54.563 DEBUG 4148 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Cleared SecurityContextHolder to complete request
2022-10-13 22:02:54.603 DEBUG 4148 --- [nio-8080-exec-1] s.w.s.h.LoggingWebSocketHandlerDecorator : New StandardWebSocketSession[id=daac9c80-326f-4d75-3f1c-ea8cd98de10f, uri=ws://localhost:8080/subscriptions]
2022-10-13 22:02:54.852  INFO 4148 --- [nio-8080-exec-1] .d.s.w.WebsocketGraphQLWSProtocolHandler : Initialized connection for daac9c80-326f-4d75-3f1c-ea8cd98de10f
2022-10-13 22:02:55.286 DEBUG 4148 --- [nio-8080-exec-1] .n.g.d.i.DefaultDgsGraphQLContextBuilder : Created DGS context in 0ms
2022-10-13 22:02:55.322 DEBUG 4148 --- [nio-8080-exec-1] c.n.g.d.internal.DgsDataLoaderProvider   : Created DGS dataloader registry in 12ms
2022-10-13 22:02:55.414  INFO 4148 --- [nio-8080-exec-1] c.e.d.i.ExampleTracingInstrumentation    : Datafetcher Subscription.reviewAdded took 2ms
2022-10-13 22:02:55.426  INFO 4148 --- [nio-8080-exec-1] c.e.d.i.ExampleTracingInstrumentation    : Total execution time: 92ms
2022-10-13 22:02:55.429  INFO 4148 --- [nio-8080-exec-1] .d.s.w.WebsocketGraphQLWSProtocolHandler : Subscription started for 1
2022-10-13 22:03:04.610 DEBUG 4148 --- [        Timer-2] o.s.w.s.adapter.NativeWebSocketSession   : Closing StandardWebSocketSession[id=daac9c80-326f-4d75-3f1c-ea8cd98de10f, uri=ws://localhost:8080/subscriptions]
2022-10-13 22:03:04.613 DEBUG 4148 --- [        Timer-2] s.w.s.h.LoggingWebSocketHandlerDecorator : StandardWebSocketSession[id=daac9c80-326f-4d75-3f1c-ea8cd98de10f, uri=ws://localhost:8080/subscriptions] closed with CloseStatus[code=4408, reason=null]
2022-10-13 22:03:04.663  INFO 4148 --- [        Timer-0] .d.s.w.WebsocketGraphQLWSProtocolHandler : Cleaning up for session daac9c80-326f-4d75-3f1c-ea8cd98de10f
2022-10-13 22:03:05.324 DEBUG 4148 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Securing GET /subscriptions
2022-10-13 22:03:05.324 DEBUG 4148 --- [nio-8080-exec-3] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
2022-10-13 22:03:05.324 DEBUG 4148 --- [nio-8080-exec-3] o.s.s.w.a.AnonymousAuthenticationFilter  : Set SecurityContextHolder to anonymous SecurityContext
2022-10-13 22:03:05.325 DEBUG 4148 --- [nio-8080-exec-3] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [GET /subscriptions] with attributes [permitAll]
2022-10-13 22:03:05.325 DEBUG 4148 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Secured GET /subscriptions
2022-10-13 22:03:05.325 DEBUG 4148 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : GET "/subscriptions", parameters={}
2022-10-13 22:03:05.326 DEBUG 4148 --- [nio-8080-exec-3] o.s.w.s.s.s.WebSocketHandlerMapping      : Mapped to org.springframework.web.socket.server.support.WebSocketHttpRequestHandler@3c108c05
2022-10-13 22:03:05.326 DEBUG 4148 --- [nio-8080-exec-3] o.s.w.s.s.s.WebSocketHttpRequestHandler  : GET /subscriptions
2022-10-13 22:03:05.341 DEBUG 4148 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Completed 101 SWITCHING_PROTOCOLS
2022-10-13 22:03:05.342 DEBUG 4148 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Did not store anonymous SecurityContext
2022-10-13 22:03:05.342 DEBUG 4148 --- [nio-8080-exec-3] s.s.w.c.SecurityContextPersistenceFilter : Cleared SecurityContextHolder to complete request
2022-10-13 22:03:05.344 DEBUG 4148 --- [nio-8080-exec-3] s.w.s.h.LoggingWebSocketHandlerDecorator : New StandardWebSocketSession[id=3fad25d8-e55a-e782-6609-8072fdf41050, uri=ws://localhost:8080/subscriptions]
2022-10-13 22:03:05.350  INFO 4148 --- [nio-8080-exec-4] .d.s.w.WebsocketGraphQLWSProtocolHandler : Initialized connection for 3fad25d8-e55a-e782-6609-8072fdf41050
2022-10-13 22:03:05.352 DEBUG 4148 --- [nio-8080-exec-4] .n.g.d.i.DefaultDgsGraphQLContextBuilder : Created DGS context in 0ms
2022-10-13 22:03:05.353 DEBUG 4148 --- [nio-8080-exec-4] c.n.g.d.internal.DgsDataLoaderProvider   : Created DGS dataloader registry in 0ms
2022-10-13 22:03:05.356  INFO 4148 --- [nio-8080-exec-4] c.e.d.i.ExampleTracingInstrumentation    : Datafetcher Subscription.reviewAdded took 0ms
2022-10-13 22:03:05.357  INFO 4148 --- [nio-8080-exec-4] c.e.d.i.ExampleTracingInstrumentation    : Total execution time: 3ms
2022-10-13 22:03:05.357  INFO 4148 --- [nio-8080-exec-4] .d.s.w.WebsocketGraphQLWSProtocolHandler : Subscription started for 1
...

Reason:

  • The recent implementation of "graphql-ws" ("graphql-transport-ws" protocol) introduced a connection init timeout which is 10 seconds per default
  • if "graphql-transport-ws" protocol is used, the timeout is stopped by calling setConnectionInitReceived() in WebsocketGraphQLTransportWSProtocolHandler
  • this is however not the case if "subscriptions-transport-ws" is used -> after 10 seconds the connection timeout is triggered and the session (that es equally used by both handlers) is terminated

sefi18 avatar Oct 13 '22 20:10 sefi18

Thanks for reporting. I will fix this in the next release, likely in a week or two.

srinivasankavitha avatar Oct 13 '22 20:10 srinivasankavitha

@srinivasankavitha We also faced the same issue in the latest version 6.0.0

oleksii-hobzhelian-windmill avatar Feb 15 '23 13:02 oleksii-hobzhelian-windmill

Hi - the subscriptions-transport-ws is being deprecated in favor of the newer graphql-transport-ws protocol for websockets. Please refer to the docs here: https://netflix.github.io/dgs/advanced/subscriptions/#websockets. Would you be able to switch to that and try? If the problem persists, then we likely have a bug in the new implementation. We won't be making any changes to the older protocol since we plan to get rid of it soon, it's there mainly for backwards compatibility. Thanks!

On Wed, Feb 15, 2023 at 5:57 AM oleksii-hobzhelian-windmill < @.***> wrote:

@srinivasankavitha https://github.com/srinivasankavitha We also faced the same issue in the latest version 6.0.0

— Reply to this email directly, view it on GitHub https://github.com/Netflix/dgs-framework/issues/1271#issuecomment-1431410400, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJ5JPXKL2Z42BQ7T7KA3OI3WXTOEXANCNFSM6AAAAAAREUJ5KQ . You are receiving this because you were mentioned.Message ID: @.***>

srinivasankavitha avatar Feb 15 '23 17:02 srinivasankavitha

@srinivasankavitha With graphql-transport-ws it works much better. Thanks

oleksii-hobzhelian-windmill avatar Feb 20 '23 08:02 oleksii-hobzhelian-windmill