Saswatibhoi opened a new issue #6644: Websocket Proxy Connectivity Issue (500 Server Error) URL: https://github.com/apache/pulsar/issues/6644 **Describe the bug** We are using Node.js with Websocket API to create the Producer and Consumer. Our infrastructure has as the below setup: Websocket Producer/Consumer -->>connects to a loadbalancer -->>connects to Websocket Proxy -->>Brokers. The Producers connects fine and we are able to produce messages. And, the Consumer is also able to connect and consume fine as long as the producer is producing and there are messages on the bus. But, whenever there is an idle time (when there is no messages on the bus) and the consumer is connected and waiting for the messages on the bus, it is throwing an "Unexpected server response: 500" Error. After multiple attempts of retry, the consumer reconnects again. But, as the Producer Idle time is 60-70% of the day, the consumer is intermittently throwing a lot of 500 server Error, and reconnect attempts in the client logs. Ideally, this is not the behavior we should be seeing while connecting to the Websocket Proxy. The retry should get connected. **From The Client Logs:** [start-subscription-consumer-prod] {"method": "rws.ts -> ReconnectingWebSocket -> connect", "message": "Reopening Websocket connection with ready state: 0", "data": {"url": "-----?subscriptionType=Shared"}} [start-subscription-consumer-prod] {"method": "rws.ts -> ReconnectingWebSocket -> connect", "message": "Error occurred in ReconnectingWebSocket connecting to websocket", "error": {"url": "---?subscriptionType=Shared"}} [start-subscription-consumer-prod] 2020-03-31 15:06:59: error: {"method": "consumer.ts -> getConsumerData","message": "Error occurred while connecting to websocket, Closing & Reopening","error": "Error: Unexpected server response: 500"} **From the Websocket Proxy Logs:** 14:38:37.605 [pulsar-websocket-web-1-2] DEBUG org.eclipse.jetty.server.HttpChannel - COMPLETE for /ws/v2/consumer/persistent/---- written=900 14:38:37.605 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - COMPLETE for /ws/v2/consumer/---- written=902 14:38:37.605 [pulsar-websocket-web-1-2] INFO org.eclipse.jetty.server.RequestLog - 63.17.8.211 - - [31/Mar/2020:14:38:27 -0400] "GET /ws/v2/consumer/----subscriptionType=Shared HTTP/1.1" 500 900 "-" "-" 9999 14:38:37.605 [pulsar-websocket-web-1-3] INFO org.eclipse.jetty.server.RequestLog - 63.17.17.34 - - [31/Mar/2020:14:38:27 -0400] "GET /ws/v2/consumer/----subscriptionType=Shared HTTP/1.1" 500 902 "-" "-" 10006 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - REQUEST for //vmb-aws-us-east-1-prod.verizon.com:8444/ws/v2/consumer/persistent/------subscriptionType=Shared on HttpChannelOverHttp@38ad8bac{r=1,c=false,a=IDLE,uri=//----subscriptionType=Shared,age=0} GET //---?subscriptionType=Shared HTTP/1.1 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@38ad8bac{r=1,c=false,a=IDLE,uri=----subscriptionType=Shared,age=0} onContentComplete 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@38ad8bac{r=1,c=false,a=IDLE,uri=----subscriptionType=Shared,age=0} onRequestComplete 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@38ad8bac{r=1,c=false,a=IDLE,uri=----subscriptionType=Shared,age=0} handle //----subscriptionType=Shared 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@38ad8bac{r=1,c=false,a=DISPATCHED,uri=---subscriptionType=Shared,age=0} action DISPATCH 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.Server - REQUEST GET /ws/v2/consumer/-- on HttpChannelOverHttp@38ad8bac{r=1,c=false,a=DISPATCHED,uri=---subscriptionType=Shared,age=0} 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.handler.ContextHandler - scope null||/ws/v2/consumer/---- @ o.e.j.s.ServletContextHandler@1c6804cd{/ws/v2/consumer,null,AVAILABLE} 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.server.handler.ContextHandler - context=/ws/v2/consumer||/--- @ o.e.j.s.ServletContextHandler@1c6804cd{/ws/v2/consumer,null,AVAILABLE} 14:38:42.537 [pulsar-websocket-web-1-3] DEBUG org.eclipse.jetty.servlet.ServletHandler - servlet /ws/v2/consumer||/--- -> ws-events@95770d2a==org.apache.pulsar.websocket.WebSocketConsumerServlet,jsp=null,order=-1,inst=true 14:38:42.537 [pulsar-websocket-web-1-3] INFO org.apache.pulsar.websocket.AbstractWebSocketHandler - [63.17.1.44:34686] Authenticated WebSocket client XYZ on topic ---- 14:38:42.543 [pulsar-websocket-web-1-4] DEBUG org.eclipse.jetty.server.HttpChannel - REQUEST for /---subscriptionType=Shared on HttpChannelOverHttp@2fb5dc40{r=1,c=false,a=IDLE,uri=----subscriptionType=Shared,age=0} GET //---subscriptionType=Shared HTTP/1.1 **From the Broker Logs:** [pulsar-client-io-45-6] INFO org.apache.pulsar.client.impl.ConsumerImpl - -- Subscribed to topic on WebsocketProxy:Port -- consumer: 7851 [pulsar-web-30-11] INFO org.eclipse.jetty.server.RequestLog - ClientIP - - [31/Mar/2020:08:19:39 -0400] "GET /ws/v2/consumer/--subscriptionType=Shared HTTP/1.1" 101 0 "-" "-" 4 Why the client IP is seen on the broker logs? As the client is connecting to the Websocket Proxy, we should only see websocket proxy Ips in the broker logs for the connections. Is there some kind of connection leakage in websocket proxy? As per our observation, there are multiple issues here with the connectivity to Websocket Proxys. Any suggestions to resolve this issues, please.
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
