4

I have a Go service serving as a web socket server on Heroku. The client pings the server every 20 seconds and it seems to keep the connection open. The problem is that when the socket connection is closed, Heroku router throws H15 error thinking that the request took too much time. For example, if web socket connection has been open for 300 seconds, Heroku log would show:

….H15…. dyno=web.1 connect=1ms service=300000ms status=503 bytes=147….

Anyone has experienced this?

1

4 Answers 4

7

yes! I have experienced that situation and after some deep debugging, I came to the conclusion that this is just a "false positive" in the Heroku Router engine. My debugging went like this:

  1. Create a WebSocket connection between the client and the WebSocket server running on Heroku.
  2. If you're using socket.io or a similar library it will most likely establish an HTTP polling connection before switching protocols to WebSocket. (You can see these GET/POST requests in the Heroku Router logs).
  3. Once the connection is established using the WebSocket protocol, the client will keep it alive by sending a heartbeat (actually the server can do this too). Initially, you won't see this request in the Heroku Router logs because it's still pending (it's open and sending packages of data every few seconds, the heartbeat). You can monitor this by using the Chrome DevTools Network tab.
  4. The heartbeat prevents Heroku Router from terminating the request, since every time a few bytes are transferred between the client and the server the Heroku Router timeout timer (55secs) is reset.
  5. However, whenever your client closes the connection (ie: closes the browser tab, refreshes the page, disconnects from the internet, etc); the Heroku Router detects the request being terminated and (here comes is my guess based on debugging) because the request was "pending" it reacts as if it was idle for X amount of milliseconds, where X is the time from when the request was received until it was closed, that's when you see logs like this: service=79859ms status=101

As a conclusion: Heroku Router will log an Error 15 line whenever your client app terminates a WebSocket connection which was working perfectly fine for X amount of milliseconds. So, in many cases, it can be just users leaving your app.

I hope this helps people and that you guys can go to sleep with one less thing to worry about :)

2
  • 1
    So based on this, should we just be ignoring these log service timeouts in our logs?
    – CanuckT
    Apr 3, 2021 at 4:31
  • Hi @CanuckT, yes, at least based on my experience 👍🏻you are not actually missing any requests.
    – Davo
    Apr 3, 2021 at 12:13
4

I solved the problem by sending pings from the server every second, as in the heroku nodejs example: https://github.com/heroku-examples/node-websockets/blob/master/server.js

1
  • Hi! Just a quick note on that. That setInterval in the example is used only to demonstrate that the server can constantly send information to the client. That is not meant to keep the WebSocket connection alive. Check my answer below in order to know why Heroku was reporting those errors. Hope this helps people.
    – Davo
    Jan 28, 2020 at 2:03
0

If anyone comes here looking for a solution from Java perspective:

@Component
public class SocketHandler extends TextWebSocketHandler {

    public static Map<String, WebSocketSession> sessions = new ConcurrentHashMap<>();

    @Override
    public void afterConnectionEstablished(WebSocketSession session) throws Exception {
        String userName = (String) session.getAttributes().get("userName");
        sessions.put(userName, session);
        super.afterConnectionEstablished(session);
    }

    @Override
    public void afterConnectionClosed(WebSocketSession session, CloseStatus status) throws Exception {
        String userName = (String) session.getAttributes().get("userName");
        sessions.remove(userName);
        super.afterConnectionClosed(session, status);
    }
}


@Configuration
@EnableWebSocket
public class WebSocketConfig implements WebSocketConfigurer {

    public void registerWebSocketHandlers(WebSocketHandlerRegistry registry) {
        registry.addHandler(new SocketHandler(), "/webSocket/AppName/*").addInterceptors(auctionInterceptor());;
    }

    @Bean
    public HandshakeInterceptor auctionInterceptor() {
        return new HandshakeInterceptor() {
            public boolean beforeHandshake(ServerHttpRequest request, ServerHttpResponse response,
                                           WebSocketHandler wsHandler, Map<String, Object> attributes) throws Exception {

                // Get the URI segment corresponding to the auction id during handshake
                String path = request.getURI().getPath();
                String userName = path.substring(path.lastIndexOf('/') + 1);

                // This will be added to the websocket session
                attributes.put("userName", userName);
                return true;
            }

            public void afterHandshake(ServerHttpRequest request, ServerHttpResponse response,
                                       WebSocketHandler wsHandler, Exception exception) {
                // Nothing to do after handshake
            }
        };
    }
}

Above is my WebSocket configuration in Spring boot, as I only want the connection to be created and keep it in a map with userName and session details.

After that in Springboot main method just added a ping every 30 seconds like this :

public static void main(String[] args) {
    SpringApplication.run(MayAppName.class, args);
    ScheduledExecutorService scheduler = Executors.newScheduledThreadPool(1);
    Runnable r = () -> {
        if(SocketHandler.sessions != null && !SocketHandler.sessions.isEmpty()) {
            for (Map.Entry<String, WebSocketSession> stringWebSocketSessionEntry : SocketHandler.sessions.entrySet()) {
                try {
                    // Dummy ping to keep connection alive.
                    stringWebSocketSessionEntry.getValue().sendMessage(new TextMessage("Dummy Ping"));
                } catch (IOException e) {
                    e.printStackTrace();
                }
            }

        }
    };

    scheduler.scheduleAtFixedRate(r, 0, 30, TimeUnit.SECONDS);
}

What this does is, it keeps pinging the subscriber every 30 seconds so that the default 55 seconds does not affect websocket connection, as suggested in Heroku docs.

Timeouts The normal Heroku HTTP routing timeout rules apply to WebSocket connections. Either client or server can prevent the connection from idling by sending an occasional ping packet over the connection.

0

Check for yourSocket.READYSTATE === WebSocket.OPEN before attempting to send.

If not open then make sure it is open by implementing something like this

Just implementing a ping-pong solution wasn't enough to keep my connections open.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.