WSS protocol errors

[dmjio]

Left ProtocolError "error:140D00CF:SSL routines:SSL_write:protocol is shutdown"

I get this error intermittently. I'm using http-streams to post to a snap-server which reads a websocket connection and sends data to the client. Having trouble tracking down the exact origin of the error. Wondering if anyone else has seen this.

[jaspervdj]

Looks like the SSL library is doing something wrong. Could you show how you are using it?

[dmjio]

@jaspervdj, sure and thanks! Not trying to hijack this issue but a few exceptions occur whenever an authenticated user either refreshes or closes their browser window. So maybe we could go through those as well :) before we get to Left Protocol Error

tail -f log/error.log shows these two errors on refresh and termination of a browser:

1. This one happens on each refresh / termination and is related to SLL it seems

[10/Jun/2014:22:04:12 +0000] ["192.168.50.1"]: an exception escaped to toplevel:
ConnectionAbruptlyTerminated

2. This one happens intermittently, harder to track down (UPDATE: this happens when a user migrates away from the page where the web socket connection originated)

[10/Jun/2014:22:08:56 +0000] ["192.168.50.1"]: an exception escaped to toplevel:
ServerAppDone

I saw this issue: jaspervdj/websockets-snap#9, which deals with the ServerAppDone error. I took your advice and implemented the bracket pattern, which cleanly closes the connection (sends a close message and removes it from the IntMap), but the exception still propagates to the highest level and escapes.

-- Initial handshake is made
handleWebSox :: Handler App (AuthManager App) ()
handleWebSox = currentUserId >>= maybe the404 handleUser
  where
    handleUser uid = do
      Just status <- queryDB (GetUserStatus uid)
      mvar <- withTop' id $ view websox
      when status $ WS.runWebSocketsSnap $ \pendingConn ->
          do let start        = WS.acceptRequest pendingConn
                 cleanup conn = WS.sendClose conn (BrowserClose uid)
                 action       = application mvar
             bracket start cleanup action

In regards to the ConnectionAbruptlyTerminated I thought this could possibly have been due to my lack of exception handling for ConnectionClosed. So I check for that exception, catch it, (happens on each refresh / termination), but the exception still escapes to the top-level! (I watch the server print caught conn closed to stdout, and ConnectionAbruptlyClosed - escaped to top level get written to error.log at the same time.

Here's all of it, if there's anything glaringly wrong I'd appreciate your feedback. Otherwise I'm not sure how the exception is escaping (after it's been caught). Unless there are multiple exceptions occurring at different layers.

-- | Types
type WSClients = I.IntMap WS.Connection

-- | Helper Functions
addConnection :: UID -> WS.Connection -> MVar WSClients -> IO ()
addConnection uid conn mvar =
    modifyMVar_ mvar $ \connections ->
        return (I.insert uid conn connections)

removeConnection :: UID -> MVar WSClients -> IO ()
removeConnection uid mvar =
    modifyMVar_ mvar $ \connections ->
        return (I.delete uid connections)

getConnection :: UID -> MVar WSClients -> IO (Maybe WS.Connection)
getConnection uid mvar =
    do result <- tryReadMVar mvar
       return $ case result of
                  Just conns -> I.lookup uid conns
                  Nothing -> Nothing

-- | Add/Remove browser connection to IntMap
application :: MVar WSClients -> WS.Connection -> IO ()
application mvar conn = do
    cmd  <- WS.receiveData conn :: IO Command
    case cmd of
      BrowserClose uid   -> removeConnection uid mvar
      BrowserConnect uid ->
          catch (handleConnection uid conn mvar) $ \(e :: SomeException) ->
              do case fromException e of
                   Just WS.ConnectionClosed -> do putStrLn "caught conn closed"
                                                  removeConnection uid mvar
                   _ -> print (e, "oh no :(") >> removeConnection uid mvar

-- | Block until data is received
handleConnection :: UID -> WS.Connection -> MVar WSClients -> IO ()
handleConnection uid conn mvar = do
      addConnection uid conn mvar
      forever $ do
        msg <- WS.receiveData conn
        case msg of
          cmd@UnknownCommand{..} -> return ()
          cmd -> sendMsg cmd mvar

-- | Push any WebSocket message to the client
sendMsg :: Command -> MVar WSClients -> IO ()
sendMsg cmd mvar = do
    result <- getConnection (uid cmd) mvar
    forM_ result $ \conn -> WS.sendTextData conn $ wsxMsg cmd

I think the Left : Protocol error occurs when another process POSTs to the web server and the connection gets closed. I'll see if the bracket pattern fixed some of that.

[dmjio]

Think I narrowed down the Left ProtocolError "error:140D00CF:SSL routines:SSL_write:protocol is shutdown. When the worker process POSTs to the web server without anything in the MVar IntMap two exceptions occur the first one is a Blocked Indefinitely on MVar which doesn't make any sense since I'm using tryReadMVar.... the non-blocking read.

The Left protocol seems to occur either because the request is never returned (since the MVar is empty) possibly.

-- Worker POSTs to Web Server here, send websocket notifications to client
workerUpdates :: Handler App App ()
workerUpdates = method POST handlePOST
    where handlePOST = do
            Just cmd <- getJSON
            mvar <- view websox
            io $ sendMsg cmd mvar -- I should be using a `try` here

-- | Push any WebSocket message to the client
sendMsg :: Command -> MVar WSClients -> IO ()
sendMsg cmd mvar = do
    result <- getConnection (uid cmd) mvar
    forM_ result $ \conn -> WS.sendTextData conn $ wsxMsg cmd

[dmjio]

Ok I'm dumb. ServerAppDone escaping to the top level occurs whenever I navigate away from the page that opens the web socket connection.

[dmjio]

Left ProtocolError "error:140D00CF:SSL routines:SSL_write:protocol is shutdown happens when WS.sendData msg conn is called after the connection has been severed. The connection is still present in the IntMap which means catching ConnectionClosed and removing the connection isn't occurring fast enough, or is just not happening altogether. The good part is that it can be caught before it escapes to the top. try (io (sendMsg cmd conn) :: IO SomeException ())

[dmjio]

Ok, kind of embarrassing, but I wasn't closing the websocket connection on the client ws.close(). So stale connections were left in the MVar. Attempts to write to these connections caused: ProtocolError "error:140D00CF:SSL routines:SSL_write:protocol is shutdown. Since close wasn't sent the thread was never cleanly killed. Pretty sure this also contributed to the MVar blocking indefinitely.

Adding the onbeforeunload event on the client made sure the close event was sent.

 var ws = new WebSocket('wss://' + window.location.hostname +  '/websox/');
 window.onbeforeunload = function() {
     console.log('closing websocket');
     if (ws) ws.close();
 };

Sadly, ServerAppDone still propogates to the highest level, even when trying to catch the exception in a transformer.

-- Initial handshake is made
handleWebSox :: Handler App (AuthManager App) ()
handleWebSox = currentUserId >>= maybe the404 handleUser
  where
    handleUser uid = do
      Just status <- queryDB (GetUserStatus uid)
      mvar <- withTop' id $ view websox
      when status $ do
        MIO.catch (handleWebSockets mvar uid) $ \(e :: SomeException) ->
            io $ case show e of
                   "ServerAppDone" -> putStrLn "Caught ya!" -- <-- never caught
                   other -> print ("caught another one", other)
    handleWebSockets mvar uid = do
        WS.runWebSocketsSnap $ \pendingConn ->
          do let start        = WS.acceptRequest pendingConn
                 cleanup conn = WS.sendClose conn (BrowserClose uid)
                 action conn  = application mvar conn
             bracket start cleanup action
        return ()

I'm excited for Snap 1.0 where monad-control can be used for the base monad. Hopefully enclosed-exceptions can be used to catch all exceptions like these. Any idea what the performance implications of exceptions that escape to the top-level are like?

[jaspervdj]

Your cleanup code does get run, right?

Exceptions escaping to the top-level are reasonably cheap, I think the logging overhead is pretty much to the only factor to take into account there.

[dmjio]

Yea cleanup gets called. As long as unhandled exceptions don't affect performance too much I'm ok with it. I can live with the logging for now.