Reconnecting causes disconnect/reconnect loop when using client certificate authentication

[thully]

I'm working on an iOS app that uses socket.io and client certificate authentication, the latter of which is implemented using a custom URLSessionDelegate. It works fine on the initial connection, though if I lose the connection for whatever reason, the client will be stuck in a disconnect/reconnect infinite loop when the connection is re-established. This does not happen if I don't use client certificate authentication, and does not happen if I add the forceNew(true) option. The issue was somewhat intermittent in past releases, but seems to happen consistently as of 12.x. Note that I am not reconnecting manually - this is just the client auto-reconnecting.

Below is an excerpt of the log messages

2017-11-07 17:34:55.823635-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: POSTing
2017-11-07 17:34:55.825466-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling POST https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1&sid=Yot112F4WlL9vCReAAEl
2017-11-07 17:34:55.825770-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.825901-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got poll message:
2017-11-07 17:34:55.826273-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling GET https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1&sid=Yot112F4WlL9vCReAAEl
2017-11-07 17:34:55.827355-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.827977-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got poll message: 1:1
2017-11-07 17:34:55.829027-0500 DriverApp[1527:27119756] LOG SocketEngine: Got message: 1
2017-11-07 17:34:55.829671-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.829709-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling GET https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1&sid=Yot112F4WlL9vCReAAEl
2017-11-07 17:34:55.830357-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.830736-0500 DriverApp[1527:27117443] LOG SocketIOClient: Starting reconnect
2017-11-07 17:34:55.831590-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.832181-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: reconnect with data: ["1"]
2017-11-07 17:34:55.832607-0500 DriverApp[1527:27119756] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.832970-0500 DriverApp[1527:27117443] LOG SocketIOClient: Trying to reconnect
2017-11-07 17:34:55.834749-0500 DriverApp[1527:27119756] ERROR SocketEngine: Session ID unknown
2017-11-07 17:34:55.834828-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: reconnectAttempt with data: [-1]
2017-11-07 17:34:55.835897-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.836580-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling GET https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1&sid=Yot112F4WlL9vCReAAEl
2017-11-07 17:34:55.837595-0500 DriverApp[1527:27117443] ERROR SocketIOClient: Session ID unknown
2017-11-07 17:34:55.839019-0500 DriverApp[1527:27119756] LOG SocketEngine: Engine is being closed.
2017-11-07 17:34:55.839180-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"]
2017-11-07 17:34:55.840284-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Created POST string: 1:1
2017-11-07 17:34:55.841555-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling POST https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1&sid=Yot112F4WlL9vCReAAEl
2017-11-07 17:34:55.842362-0500 DriverApp[1527:27119756] LOG SocketEngine: Starting engine. Server: https://141.212.164.57:8443
2017-11-07 17:34:55.842372-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.843030-0500 DriverApp[1527:27119756] LOG SocketEngine: Handshaking
2017-11-07 17:34:55.843572-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Doing polling GET https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1
2017-11-07 17:34:55.844029-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.844183-0500 DriverApp[1527:27119756] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.844780-0500 DriverApp[1527:27119756] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.845164-0500 DriverApp[1527:27119756] ERROR SocketEngine: Session ID unknown
2017-11-07 17:34:55.845504-0500 DriverApp[1527:27117443] ERROR SocketIOClient: Session ID unknown
2017-11-07 17:34:55.845919-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"]
2017-11-07 17:34:55.846441-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.904359-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.905291-0500 DriverApp[1527:27119734] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.905469-0500 DriverApp[1527:27119734] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.905885-0500 DriverApp[1527:27119734] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.906132-0500 DriverApp[1527:27119734] ERROR SocketEngine: Session ID unknown
2017-11-07 17:34:55.906315-0500 DriverApp[1527:27117443] ERROR SocketIOClient: Session ID unknown
2017-11-07 17:34:55.906547-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"]
2017-11-07 17:34:55.906793-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.922608-0500 DriverApp[1527:27117443] LOG SocketIOClient: Trying to reconnect
2017-11-07 17:34:55.922846-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: reconnectAttempt with data: [-2]
2017-11-07 17:34:55.923048-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:55.923266-0500 DriverApp[1527:27119734] LOG SocketEngine: Starting engine. Server: https://141.212.164.57:8443
2017-11-07 17:34:55.923390-0500 DriverApp[1527:27119734] LOG SocketEngine: Handshaking
2017-11-07 17:34:55.923599-0500 DriverApp[1527:27119734] LOG SocketEnginePolling: Doing polling GET https://141.212.164.57:8443/driver/socket.io/?transport=polling&b64=1
2017-11-07 17:34:55.925560-0500 DriverApp[1527:27117579] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:55.926594-0500 DriverApp[1527:27117579] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.926884-0500 DriverApp[1527:27117579] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"}
2017-11-07 17:34:55.948369-0500 DriverApp[1527:27117579] ERROR SocketEngine: Session ID unknown
2017-11-07 17:34:55.948814-0500 DriverApp[1527:27117443] ERROR SocketIOClient: Session ID unknown
2017-11-07 17:34:55.948985-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"]
2017-11-07 17:34:55.949596-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:56.022647-0500 DriverApp[1527:27120401] LOG SocketEnginePolling: Got polling response
2017-11-07 17:34:56.022931-0500 DriverApp[1527:27120401] LOG SocketEnginePolling: Got poll message: 97:0{"sid":"LSYFsMA2Tl4vEXMsAAEm","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}
2017-11-07 17:34:56.023089-0500 DriverApp[1527:27120401] LOG SocketEngine: Got message: 0{"sid":"LSYFsMA2Tl4vEXMsAAEm","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}
2017-11-07 17:34:56.025291-0500 DriverApp[1527:27117443] LOG SocketIOClient: Engine opened Connect
2017-11-07 17:34:56.025318-0500 DriverApp[1527:27120401] LOG SocketEngine: Writing poll: has data: false
2017-11-07 17:34:56.025469-0500 DriverApp[1527:27117443] LOG SocketIOClient: Socket connected
2017-11-07 17:34:56.025632-0500 DriverApp[1527:27120401] LOG SocketEnginePolling: Sending poll: as type: 2
2017-11-07 17:34:56.025853-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-11-07 17:34:56.026224-0500 DriverApp[1527:27120401] LOG SocketEnginePolling: Created POST string: 1:2
2017-11-07 17:34:56.026511-0500 DriverApp[1527:27117443] LOG SocketIOClient: Handling event: connect with data: ["/"]
2017-11-07 17:34:56.027073-0500 DriverApp[1527:27120401] LOG SocketEnginePolling: POSTing
2017-11-07 17:34:56.027565-0500 DriverApp[1527:27117443] LOG SocketIOClient: Emitting:

[thully]

As a side question, what would be best practices with this library to make sure reconnection works reliably? Should I be re-creating my socket object manually in some circumstances, or is forceNew(true) enough?

[nuclearace]

forceNew should generally be enough.

[thully]

Does that hold for explicitly-requested disconnects as well (i.e. disconnects initiated by calling socket.disconnect(), or disconnects initiated by the server)? We're been using a wrapper around the library to allow us to do custom authentication and handle calls to emit when not connected.In this wrapper we had also been tracking all the added handlers as well and reconstructing the socket object on disconnect to avoid a problem similar to above. Is that unnecessary with forceNew?

[kacak9229]

Hey Thully just wondering, how does your Singleton Design structure? I'm using token and I have a lot of problems

This is my Singleton Design, I'm building an app similar like Uber

import SocketIO

class SocketIOManager: NSObject {
    
    static let sharedInstance = SocketIOManager()
    
    var socket: SocketIOClient!
    
    private override init() {
        self.socket = SocketIOClient(socketURL: URL(string: mainURL)!, config: [.log(false), .compress, .connectParams(["token": getToken()])])
        super.init()
    }
    
    func establishConnection() {
       socket.connect()
    
    }
  
    func closeConnection() {
        socket.disconnect()
    }

}

Is this good enough?

[kinza88]

@nuclearace @thully
Hey .. Did you find any solution to this problem?

[ambrose40]

@nuclearace @thully @kinza88
I wonder if this was resolved, started happening with update 13.1.0
Related issues, I've posted my conf and logs there:
#918
#913

[stefanoa]

I tested on v13.3.0 and I can confirm the issue is still there, the problem is related to the use of a proxy (in our case HAProxy).
To recreate the issue simply install the socket.io server behind a proxy, connect a client to it and simply perform a server restart; the reconnect will fail indefinitely.

This is because the proxy will respond with a valid HTTP code (503 in our case) and than the polling mechanism somehow fails to correctly detect the problem.
The issue is in SocketEnginePollable in

func doLongPoll(for req: URLRequest) {
        waitingForPoll = true
        doRequest(for: req) {[weak self] data, res, err in
            guard let this = self, this.polling else { return }

            // err should be != nil also for status code != 200 but currently is nil even for 503 (Bad Gateway)
            if err != nil || data == nil {
                DefaultSocketLogger.Logger.error(err?.localizedDescription ?? "Error", type: "SocketEnginePolling")

                if this.polling {
                    this.didError(reason: err?.localizedDescription ?? "Error")
                }

                return
            }
            // If the server returns an error code (503 for example) the error is undetected and the flow continue here but the reconnect fails indefinitely

            DefaultSocketLogger.Logger.log("Got polling response", type: "SocketEnginePolling")

            if let str = String(data: data!, encoding: .utf8) {
                this.parsePollingMessage(str)
            }

            this.waitingForPoll = false

            if this.fastUpgrade {
                this.doFastUpgrade()
            } else if !this.closed && this.polling {
                this.doPoll()
            }
        }
    }

If a restart of the server is done (to release new features for example) the connection on the client is lost but the reconnect fails indefinitely. I added some comments in the code to explain the problem.

I patched the code to consider as errors all the HTTP status codes different from 200 and it works correctly for us.

[nuclearace]

@stefanoa Ah, so in this case err is nil and there is data about the 503? That makes sense to add a status check here.

[nuclearace]

@stefanoa checked e877bb2 to look at status codes when polling.

[stefanoa]

@nuclearace It works for me but maybe it is better to manage the statusCode in the doRequest method because the issue can happen in other cases.