Skip to content

Reconnecting causes disconnect/reconnect loop when using client certificate authentication #857

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
thully opened this issue Nov 7, 2017 · 11 comments
Closed

Reconnecting causes disconnect/reconnect loop when using client certificate authentication #857

thully opened this issue Nov 7, 2017 · 11 comments
Assignees
@nuclearace
Labels
bug

Comments

@thully
Copy link

thully commented Nov 7, 2017

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
Copy link
Author

thully commented Nov 7, 2017

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
Copy link
Member

forceNew should generally be enough.

@thully
Copy link
Author

thully commented Nov 8, 2017

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
Copy link

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
Copy link

kinza88 commented Jan 1, 2018

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

@ambrose40
Copy link

@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
Copy link

stefanoa commented Oct 2, 2018

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
Copy link
Member

@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 nuclearace self-assigned this Oct 2, 2018
@nuclearace nuclearace added the bug label Oct 2, 2018
nuclearace added a commit that referenced this issue Oct 2, 2018
@nuclearace
check for 200 status code when polling #857
e877bb2
@nuclearace
Copy link
Member

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

@stefanoa
Copy link

stefanoa commented Oct 2, 2018

@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.

nuclearace added a commit that referenced this issue Oct 4, 2018
@nuclearace
Merge branch 'development'
016e127 
* development:
  update changelog and bump pod version
  check for 200 status code when polling #857
  update xcode versino
  set the right URL in websocket creation
  fix cookies import when create the websocket
  Be sure to keep secure config even if config is changed. Fix #1078
  Don't need to write DispatchTime
  use while let instead of while and if let
@dangquochoi2007
Copy link

Could you please check it again?. I upgrade version 16.1.1 still meet issue above.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nuclearace nuclearace

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@thully @nuclearace @stefanoa @ambrose40 @kacak9229 @dangquochoi2007 @kinza88