Websocket connection closes immediately on error.

[Euan Robertson]

Hello,

I'm attempting to use the Websocket channel for R4 subscriptions, and I'm trying to determine if what I'm seeing is a bug or part of the standard that I haven't come across yet.

My order of operations goes as follows

• Connect to Websocket endpoint
• POST a bundle of Subscription resources
• Iterate over the IDs and send `bind Subscription/x` over the Websocket.

Since we are performing these steps serially, if we send the bind string before the server has processed the new Subscription and made the status "active" (which happens way after the response to the bundle POST has come back), not only does the bind fail with a "Cannot find subscription" error in the logs, but also immediately closes the Websocket connection from the server side.

If either the server responded on the Websocket with an error, or held onto the bind until the subscription is ready, or even just never responded at all, we could pretty easily work around this with some retry logic, but the fact that it shuts down the Websocket connection as well makes this difficult.

It feels like all we can do here is POST the Subscriptions, then loop a GET for the same subscriptions until they are marked as active, then do the bind.

My questions are as follows

• Is shutting down the Websocket immediately on first "error" intended behaviour? If so, is there a way to disable that?
• Is there a more recommended way of creating subscriptions and setting up the Websocket to avoid this scenario?

Thanks!

Euan Robertson

[Peter Micuch]

Hi Euan,

I have observed very same behavior as you. When I create subscription and if I try to bind to it immediately, it works sometimes and sometimes I see same behavior as you described. So this is sporadic and clearly timing issue.

Hapi just logs that the requested bind subscription could not be found although CREATE operation for it is visible in the logs. When I did a workaround and first invoke GET for each subscription that I wanted to bind to, then this error is not appearing anymore.

Closing the websocket for no reason in this case is really strange. I agree either processing pipeline should be checked if requested subscription is on is way or get some error message back. Here are the logs from the scenario (hapi version 6.8.3 in this case):

2024-07-15T16:56:59.362450118+02:00 2024-07-15 14:56:59.225 [http-nio-8080-exec-2] INFO  c.u.f.j.s.u.S.SUBS1 [SubscriptionDebugLogInterceptor.java:198] Resource Subscription/fe3def73-e3ee-4a6e-9775-a7051eabe67c was submitted to the processing pipeline (op=CREATE)
2024-07-15T16:56:59.364207189+02:00 2024-07-15 14:56:59.237 [http-nio-8080-exec-2] INFO  fhirtest.access [LoggingInterceptor.java:177] Path[/fhir] Source[] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON]
2024-07-15T16:56:59.366039260+02:00 2024-07-15 14:56:59.300 [http-nio-8080-exec-5] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:93] Websocket connection has been created
2024-07-15T16:56:59.368069227+02:00 2024-07-15 14:56:59.301 [http-nio-8080-exec-5] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:72] Incoming WebSocket connection from /172.20.0.122:47956
2024-07-15T16:56:59.369789999+02:00 2024-07-15 14:56:59.301 [http-nio-8080-exec-4] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:81] Textmessage: bind fe3def73-e3ee-4a6e-9775-a7051eabe67c
2024-07-15T16:56:59.371513471+02:00 2024-07-15 14:56:59.301 [http-nio-8080-exec-4] WARN  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:177] Invalid bind request - Unknown subscription: Subscription/fe3def73-e3ee-4a6e-9775-a7051eabe67c
2024-07-15T16:56:59.373254243+02:00 2024-07-15 14:56:59.302 [http-nio-8080-exec-4] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:66] Closing WebSocket connection from /172.20.0.122:47956
2024-07-15T16:56:59.375172812+02:00 2024-07-15 14:56:59.302 [http-nio-8080-exec-4] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:98] Websocket connection is closing
2024-07-15T16:56:59.377194079+02:00 2024-07-15 14:56:59.304 [subscription-matching-5] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionChannelRegistry.java:63] Adding subscription fe3def73-e3ee-4a6e-9775-a7051eabe67c to channel subscription-delivery-websocket-fe3def73-e3ee-4a6e-9775-a7051eabe67c
2024-07-15T16:56:59.378938851+02:00 2024-07-15 14:56:59.304 [subscription-matching-5] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionRegistry.java:136] Registered active subscription Subscription/fe3def73-e3ee-4a6e-9775-a7051eabe67c - Have 1 registered
2024-07-15T16:56:59.463308986+02:00 2024-07-15 14:56:59.309 [http-nio-8080-exec-8] ERROR o.s.w.s.h.ExceptionWebSocketHandlerDecorator [ExceptionWebSocketHandlerDecorator.java:90] Closing session due to exception for StandardWebSocketSession[id=83a9398f-f037-8fe2-6d70-f9cb06de2d3b, uri=ws://hapiserver/r4/websocket]
2024-07-15T16:56:59.522767525+02:00 java.lang.IllegalStateException: WebSocketHandler not found for StandardWebSocketSession[id=83a9398f-f037-8fe2-6d70-f9cb06de2d3b, uri=ws://hapiserver/r4/websocket]
2024-07-15T16:56:59.527725645+02:00 at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.getHandler(PerConnectionWebSocketHandler.java:113)
2024-07-15T16:56:59.531698180+02:00 at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.handleTransportError(PerConnectionWebSocketHandler.java:91)
2024-07-15T16:56:59.534846229+02:00 at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleTransportError(WebSocketHandlerDecorator.java:80)
2024-07-15T16:56:59.542883399+02:00 at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleTransportError(LoggingWebSocketHandlerDecorator.java:64)
2024-07-15T16:56:59.546201846+02:00 at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleTransportError(ExceptionWebSocketHandlerDecorator.java:68)
2024-07-15T16:56:59.548368011+02:00 at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.onError(StandardWebSocketHandlerAdapter.java:157)
2024-07-15T16:56:59.551583359+02:00 at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.onError(WsHttpUpgradeHandler.java:234)
2024-07-15T16:56:59.553878622+02:00 at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:156)
2024-07-15T16:56:59.555899889+02:00 at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60)
2024-07-15T16:56:59.557629161+02:00 at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57)
2024-07-15T16:56:59.559377133+02:00 at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:926)
2024-07-15T16:56:59.561123904+02:00 at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1791)
2024-07-15T16:56:59.562870376+02:00 at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
2024-07-15T16:56:59.564522349+02:00 at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
2024-07-15T16:56:59.566160523+02:00 at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
2024-07-15T16:56:59.567893695+02:00 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
2024-07-15T16:56:59.569737765+02:00 at java.base/java.lang.Thread.run(Thread.java:833)

And here is the log when I try to GET subscription resource before actually binding it with websocket:

2024-07-15T18:56:50.424976217+02:00 2024-07-15 16:56:50.378 [http-nio-8080-exec-3] INFO  c.u.f.j.s.u.S.SUBS1 [SubscriptionDebugLogInterceptor.java:198] Resource Subscription/2ae33cf4-f9aa-4173-bb48-77804f460052 was submitted to the processing pipeline (op=CREATE)
2024-07-15T18:56:50.464186982+02:00 2024-07-15 16:56:50.458 [http-nio-8080-exec-3] INFO  fhirtest.access [LoggingInterceptor.java:177] Path[/fhir] Source[] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON]
2024-07-15T18:56:50.470727177+02:00 2024-07-15 16:56:50.464 [subscription-matching-1] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionChannelRegistry.java:63] Adding subscription 2ae33cf4-f9aa-4173-bb48-77804f460052 to channel subscription-delivery-websocket-2ae33cf4-f9aa-4173-bb48-77804f460052
2024-07-15T18:56:50.472736644+02:00 2024-07-15 16:56:50.464 [subscription-matching-1] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionRegistry.java:136] Registered active subscription Subscription/2ae33cf4-f9aa-4173-bb48-77804f460052 - Have 1 registered
2024-07-15T18:56:50.858065412+02:00 2024-07-15 16:56:50.850 [http-nio-8080-exec-7] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:93] Websocket connection has been created
2024-07-15T18:56:50.860096379+02:00 2024-07-15 16:56:50.851 [http-nio-8080-exec-7] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:72] Incoming WebSocket connection from /172.20.0.97:48202
2024-07-15T18:56:50.862033548+02:00 2024-07-15 16:56:50.855 [http-nio-8080-exec-7] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:81] Textmessage: bind 2ae33cf4-f9aa-4173-bb48-77804f460052

Regards,

Peter 

Dátum: pondelok 27. februára 2023, čas: 13:14:40 UTC+1, odosielateľ: Euan Robertson

[Peter Micuch]

Well I have to correct myself. When I ran the test in the loop many times, it seems that even getting the subscription resource and checking if it is active does not help to overcome the issue. So in the test: I create a subscription with status Requested, Hapi changes it to Active and you can see that it was the read by the test. Then when I try to bind it to websocket, it then fails 

2024-07-16 13:16:40.872 [http-nio-8080-exec-6] INFO  fhirtest.access [LoggingInterceptor.java:177] Path[/fhir] Source[] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON] Operation[create  Subscription] UA[] Params[] ResponseEncoding[JSON]
2024-07-16 13:16:40.873 [subscription-matching-3] INFO  c.u.f.j.s.m.m.s.SubscriptionActivatingSubscriber [SubscriptionActivatingSubscriber.java:139] Activating subscription Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f from status requested to active
2024-07-16 13:16:40.885 [http-nio-8080-exec-4] INFO  fhirtest.access [LoggingInterceptor.java:177] Path[/fhir] Source[] Operation[read  Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f] UA[] Params[] ResponseEncoding[] Operation[read  Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f] UA[] Params[] ResponseEncoding[]
2024-07-16 13:16:40.939 [http-nio-8080-exec-7] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:93] Websocket connection has been created
2024-07-16 13:16:40.939 [http-nio-8080-exec-7] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:72] Incoming WebSocket connection from /172.20.0.81:57420
2024-07-16 13:16:40.941 [http-nio-8080-exec-5] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:81] Textmessage: bind 6679391a-7df8-4e3d-98e0-43a6c727695f
2024-07-16 13:16:40.941 [http-nio-8080-exec-5] WARN  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:177] Invalid bind request - Unknown subscription: Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f
2024-07-16 13:16:40.942 [http-nio-8080-exec-5] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:66] Closing WebSocket connection from /172.20.0.81:57420
2024-07-16 13:16:40.942 [http-nio-8080-exec-5] INFO  c.u.f.j.s.m.d.w.SubscriptionWebsocketHandler [SubscriptionWebsocketHandler.java:98] Websocket connection is closing
2024-07-16 13:16:40.942 [subscription-matching-1] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionChannelRegistry.java:63] Adding subscription 6679391a-7df8-4e3d-98e0-43a6c727695f to channel subscription-delivery-websocket-6679391a-7df8-4e3d-98e0-43a6c727695f
2024-07-16 13:16:40.942 [subscription-matching-1] INFO  c.u.f.j.s.m.r.SubscriptionRegistry [SubscriptionRegistry.java:136] Registered active subscription Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f - Have 1 registered
2024-07-16 13:16:40.949 [http-nio-8080-exec-1] ERROR o.s.w.s.h.ExceptionWebSocketHandlerDecorator [ExceptionWebSocketHandlerDecorator.java:90] Closing session due to exception for StandardWebSocketSession[id=90c7d136-a0f2-e5e4-272c-bc5b51ae4162, uri=ws://hapiserver/r4/websocket]
 java.lang.IllegalStateException: WebSocketHandler not found for StandardWebSocketSession[id=90c7d136-a0f2-e5e4-272c-bc5b51ae4162, uri=ws://hapiserver/r4/websocket]
   at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.getHandler(PerConnectionWebSocketHandler.java:113)
   at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.handleTransportError(PerConnectionWebSocketHandler.java:91)
   at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleTransportError(WebSocketHandlerDecorator.java:80)
   at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleTransportError(LoggingWebSocketHandlerDecorator.java:64)
   at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleTransportError(ExceptionWebSocketHandlerDecorator.java:68)
   at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.onError(StandardWebSocketHandlerAdapter.java:157)
   at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.onError(WsHttpUpgradeHandler.java:234)
   at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:156)
   at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60)
   at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57)
   at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:926)
   at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1791)
   at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
   at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
   at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
   at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
   at java.base/java.lang.Thread.run(Thread.java:833)

This clearly looks like a bug. Workaround for this is to check if websocket is closed (not aborted!) and when it is, retry to create it. Close is detected as MessageType: Close and then you can see CloseStatus: ProtocolError and CloseStatusDescription: Invalid bind request - Unknown subscription: Subscription/6679391a-7df8-4e3d-98e0-43a6c727695f.

po 15. 7. 2024 o 19:14 Peter Micuch <pmi...@gmail.com> napísal(a):

--
You received this message because you are subscribed to the Google Groups "HAPI FHIR" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hapi-fhir+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/hapi-fhir/cd760e30-b59d-4083-9c09-08a6e11610c3n%40googlegroups.com.