Socket.io-client-swift: Socket disconnects automatically and after disconnect it's not reconnect. Get lots of logs in console.

Created on 19 Dec 2017 · 31Comments · Source: socketio/socket.io-client-swift

I tried to reconnect but got following logs

Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: reconnect, with items: Optional(["Ping timeout"])
Got event: reconnectAttempt, with items: Optional([-1])
Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: reconnectAttempt, with items: Optional([-2])
Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: reconnectAttempt, with items: Optional([-3])
Got event: statusChange, with items: Optional([SocketIO.SocketIOClientStatus])
Got event: disconnect, with items: Optional(["Got Disconnect"])
Got event: error, with items: Optional(["Session ID unknown"])

Please check and let me know if i did anything wrong.

Thanks in advance.

bug unconfirmed

Source

bhautikmobileappdev

Most helpful comment

@nuclearace Hmmmm.... Magic happened. I don't know how guys I am working with set up their server connection. Nobody notified me of any changes there, neither before the event nor today. But currently connection and sockets are working perfectly! And correctly switching between polling and websockets :+1: Although I did pod deintegrate and pod install again, switching to previous version 13.0.0, and when I found out that it is working just fine, I tried to reproduce the issue and did one more pod deintegrate and pod install again with 13.1.0 version, after that it worked like charm! :1st_place_medal:

bl82 on 4 Jan 2018

🎉1 👍1

All 31 comments

Can you provide more detail? What version are you using on the client/server, what configs are used, server settings (ping info.)

nuclearace on 20 Dec 2017

@nuclearace

pod 'Socket.IO-Client-Swift', '10.0.1'

bhautikmobileappdev on 21 Dec 2017

Hey.. did you get any solution to this problem?
@nuclearace @bhautikmobileappdev

kinza88 on 1 Jan 2018

Same problem for me I constantly get "Session ID unknown" error:
My Podfile:

source 'https://github.com/CocoaPods/Specs.git'
platform :ios, '8.4'
use_frameworks!
target 'Votecast' do
pod 'Socket.IO-Client-Swift' # Or latest version
pod 'Fabric'
pod 'Crashlytics'
pod 'MBProgressHUD'
pod 'PNChart'

end

My SocketIO swift class:

import Foundation
import SocketIO
@objc public class SocketProvider : NSObject {

    let str = "https://dev.votecast.dk/" //Prod server

    var descr = "SocketProvider class"
    var socket : SocketIOClient
    var manager : SocketManager

Init of Socket Manager:

        self.manager = SocketManager(socketURL: URL(string: str)!, config: [.log(true), .connectParams(["user_id": id])])
        self.socket = manager.defaultSocket
        self.socket.on("connect") {data, ack in

            let dict = [["sid":self.socket.sid]]

            loggerHandler(dict, "connected")
            print("socket connected")
        }

When I try to connect using forceWebsocket I get: "Invalid HTTP upgrade" socket error and connection drops abruptly.
When I switch to default configuration or forcePolling I get:
2018-01-03 17:39:46.374430+0200 Votecast[38357:921519] LOG SocketEnginePolling: Got poll message: 97:0{"sid":"9Ln0tyN13zNfDQx_AAnx","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":15000}

I attach both logs to this comment.
socket_io_swift_13_1_websocket.log
socket_io_swift_13_1_default.log

bl82 on 3 Jan 2018

@bl82 I'm not sure, there's a lot going on in your logs. What kind of connection management are you doing. I see a lot of manager being released and client being released messages.

nuclearace on 3 Jan 2018

@nuclearace Here is my full code for connection management:

    @objc public func connectSocketIOSimple(loggerHandler: @escaping (Array<Any>?, NSString?) -> Void) {
        self.manager = SocketManager(socketURL: URL(string: str)!, config: [.log(true), .forceNew(true), .connectParams(["user_id": id])])
        self.socket = manager.defaultSocket

        self.socket.on("connect") {data, ack in

            let dict = [["sid":self.socket.sid]]

            loggerHandler(dict, "connected")
            print("socket connected")
        }

        self.socket.on("reconnect") {data, ack in

            let dict = [["sid":self.socket.sid]]

            loggerHandler(dict, "connected")
            print("socket connected")
        }

        self.socket.on("user connected") {data, ack in
            print(data)
        }

        self.socket.on("disconnect") {data, ack in
            self.manager.reconnect()

            print("socket diconnected")
        }

        self.socket.on("error") {data, ack in
            self.manager.reconnect()
            print("socket error")
        }

        self.socket.on("chapter.update") {data, ack in
            print(data)
            loggerHandler(data, "chapter.update")
        }

        self.socket.on("event.update") {data, ack in
            print(data)
            loggerHandler(data, "event.update")
        }

        self.socket.on("event.transition") {data, ack in
            print(data)
            loggerHandler(data, "event.transition")
        }

        self.socket.on("chapter.transition") {data, ack in
            print(data)
            loggerHandler(data, "chapter.transition")
        }

        self.socket.on("chapter_member_status.update") {data, ack in
            print(data)
            loggerHandler(data, "chapter_member_status.update")
        }

        //New events handlers

        self.socket.on("event.started") {data, ack in
            print(data)
            loggerHandler(data, "event.started")
        }

        self.socket.on("event.stopped") {data, ack in
            print(data)
            loggerHandler(data, "event.stopped")
        }

        self.socket.on("event.restarted") {data, ack in
            print(data)
            loggerHandler(data, "event.restarted")
        }

        self.socket.on("chapter.vote.started") {data, ack in
            print(data)
            loggerHandler(data, "chapter.vote.started")
        }

        self.socket.on("chapter.vote.cancelled") {data, ack in
            print(data)
            loggerHandler(data, "chapter.vote.cancelled")
        }

        self.socket.on("chapter.vote.completed") {data, ack in
            print(data)
            loggerHandler(data, "chapter.vote.completed")
        }

        self.socket.on("chapter.approve.started") {data, ack in
            print(data)
            loggerHandler(data, "chapter.approve.started")
        }

        self.socket.on("chapter.approve.cancelled") {data, ack in
            print(data)
            loggerHandler(data, "chapter.approve.cancelled")
        }

        self.socket.on("chapter.approve.completed") {data, ack in
            print(data)
            loggerHandler(data, "chapter.approve.completed")
        }

        self.socket.on("chapter.values.reset") {data, ack in
            print(data)
            loggerHandler(data, "chapter.values.reset")
        }

        self.socket.on("chapter_member.update") {data, ack in
            print(data)
            loggerHandler(data, "chapter_member.update")
        }


        self.socket.connect()
    }

bl82 on 3 Jan 2018

@nuclearace I am not sure as well, it was working in just before I returned to develop new feature and updated from cocoapods, let me know, what I can investigate further? it is a blocker for me right now. feature I was working on is done, but during testing sockets no longer communicate properly. btw I was running test from simulator.

bl82 on 3 Jan 2018

@nuclearace server is set to both transports:

transports: [
            'websocket',
            'polling'
        ]

And version of Socket IO on server is 2.x

bl82 on 3 Jan 2018

So the error event shouldn't need a reconnect call, if something breaks the connection it should automatically reconnect. Beyond that, I'm not sure, I haven't been able to reproduce this. So a sample server/client that shows the issue happening would help.

nuclearace on 3 Jan 2018

bl82 on 4 Jan 2018

🎉1 👍1

Very strange. I wonder if it was some server or networking issue.

nuclearace on 5 Jan 2018

Don't you think reason can be in
self.manager.reconnect() in self.socket.on("disconnect")
according to docs

reconnect()
Tries to reconnect to the server.
This will cause a disconnect event to be emitted, as well as an reconnectAttempt event.

so in theory you are causing endless loop on first disconnect

Dumk0 on 5 Jan 2018

I actually need to update that documentation, reconnect() shouldn't emit a .disconnect anymore. It emits .reconnect.

nuclearace on 5 Jan 2018

@nuclearace @Dumk0 Removed reconnect from on disconnect and from on error handlers. Same result and log flood is 100% reproducible, upon quick start/stop of socket session on version 13.1.0.
Meanwhile version 13.0.0 working 100% correctly, tested simultaneously on 5 devices...
You may wish to reopen this bug. If I can help you somehow, I can try to provide you with something.

bl82 on 5 Jan 2018

Hm. 13.1.0 did change how some connect stuff is done.

https://github.com/socketio/socket.io-client-swift/pull/881/files

nuclearace on 5 Jan 2018

First guess would be this. https://github.com/socketio/socket.io-client-swift/pull/881/files#diff-0a1f28547352834d5f60fc457346f374R132

nuclearace on 5 Jan 2018

Easiest thing to do would probably step through a debugger and see what's happening.

nuclearace on 5 Jan 2018

@bl82 I'm still not able to reproduce locally, so I'm going to need a project that demonstrates the issue.

nuclearace on 6 Jan 2018

@bhautikmobileappdev @bl82 Anymore on this? I would like to get to the bottom of this, but I've not been able to reproduce.

nuclearace on 8 Jan 2018

@nuclearace I think you can close it. It boiled down to incorrect flow in my case. Which was fixed.

bl82 on 9 Jan 2018

LOG SocketIOClient{/}: Handling event: pong with data: []
2018-01-09 14:00:32.683163+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: ping with data: []
2018-01-09 14:00:32.684144+0500 Cuufy[306:42757] LOG SocketEngine: Writing ws:  has data: false
2018-01-09 14:00:32.684372+0500 Cuufy[306:42757] LOG SocketEngineWebSocket: Sending ws:  as type: 2
2018-01-09 14:00:34.009715+0500 Cuufy[306:42757] **ERROR** SocketEngine: The operation couldn’t be completed. Socket is not connected
2018-01-09 14:00:34.010192+0500 Cuufy[306:35607] **ERROR** SocketManager: The operation couldn’t be completed. Socket is not connected
2018-01-09 14:00:34.010751+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: error with data: ["The operation couldn’t be completed. Socket is not connected"]
2018-01-09 14:00:34.012332+0500 Cuufy[306:35607] LOG SocketManager: Starting reconnect
2018-01-09 14:00:34.013333+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: statusChange with data: [connecting]
2018-01-09 14:00:34.013748+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: reconnect with data: ["The operation couldn’t be completed. Socket is not connected"]
2018-01-09 14:00:34.013887+0500 Cuufy[306:35607] LOG SocketManager: Trying to reconnect
2018-01-09 14:00:34.014341+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-1]
2018-01-09 14:00:34.016010+0500 Cuufy[306:35607] LOG SocketManager: Adding engine
2018-01-09 14:00:34.016686+0500 Cuufy[306:35607] LOG SocketEngine: Engine is being released
2018-01-09 14:00:34.017595+0500 Cuufy[306:42742] LOG SocketEngine: Starting engine. Server: https://URL:5105/
2018-01-09 14:00:34.017717+0500 Cuufy[306:42742] LOG SocketEngine: Handshaking
2018-01-09 14:00:34.018133+0500 Cuufy[306:42742] LOG SocketEnginePolling: Doing polling GET https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1
2018-01-09 14:00:36.689597+0500 Cuufy[306:42757] LOG SocketEnginePolling: Got polling response
2018-01-09 14:00:36.690024+0500 Cuufy[306:42757] LOG SocketEnginePolling: Got poll message: 97:0{"sid":"nfR94Z0JH4inbDU9AAAZ","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}
2018-01-09 14:00:36.690809+0500 Cuufy[306:42757] LOG SocketEngine: Got message: 0{"sid":"nfR94Z0JH4inbDU9AAAZ","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}
2018-01-09 14:00:36.696378+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: ping with data: []
2018-01-09 14:00:36.696861+0500 Cuufy[306:35607] LOG SocketManager: Engine opened Connect
2018-01-09 14:00:36.697034+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Socket connected
2018-01-09 14:00:36.697233+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: statusChange with data: [connected]
2018-01-09 14:00:36.697458+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: connect with data: ["/"]
2018-01-09 14:00:36.697600+0500 Cuufy[306:35607] *************** SOCKET CONNECTED
connected
2018-01-09 14:00:36.698156+0500 Cuufy[306:42757] LOG SocketEnginePolling: Doing polling GET https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:36.704386+0500 Cuufy[306:42757] LOG SocketEngine: Writing poll:  has data: false
2018-01-09 14:00:36.704643+0500 Cuufy[306:42757] LOG SocketEnginePolling: Sending poll:  as type: 2
2018-01-09 14:00:36.704950+0500 Cuufy[306:42757] LOG SocketEnginePolling: Created POST string: 1:2
2018-01-09 14:00:36.706386+0500 Cuufy[306:42757] LOG SocketEnginePolling: POSTing
2018-01-09 14:00:36.710479+0500 Cuufy[306:42757] LOG SocketEnginePolling: Doing polling POST https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:36.711886+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Emitting: 24["join",{"jwt":"******"}]
2018-01-09 14:00:36.712754+0500 Cuufy[306:42742] LOG SocketEngine: Writing poll: 24["join",{"jwt":"******"}] has data: false
2018-01-09 14:00:36.713540+0500 Cuufy[306:42742] LOG SocketEnginePolling: Sending poll: 24["join",{"jwt":"******"}] as type: 4
2018-01-09 14:00:37.293414+0500 Cuufy[306:42883] LOG SocketEnginePolling: Got polling response
2018-01-09 14:00:37.293722+0500 Cuufy[306:42883] LOG SocketEnginePolling: Got poll message: 2:40
2018-01-09 14:00:37.294048+0500 Cuufy[306:42883] LOG SocketEngine: Got message: 40
2018-01-09 14:00:37.294639+0500 Cuufy[306:35607] LOG SocketParser: Parsing 0
2018-01-09 14:00:37.295230+0500 Cuufy[306:35607] LOG SocketParser: Decoded packet as: SocketPacket {type: 0; data: []; id: -1; placeholders: 0; nsp: /}
2018-01-09 14:00:37.295837+0500 Cuufy[306:42883] LOG SocketEnginePolling: Doing polling GET https://URL:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:38.694690+0500 Cuufy[306:42888] LOG SocketEnginePolling: Created POST string: 282:424["join",{"jwt":"******"}]
2018-01-09 14:00:38.696074+0500 Cuufy[306:42888] LOG SocketEnginePolling: POSTing
2018-01-09 14:00:38.696693+0500 Cuufy[306:42888] LOG SocketEnginePolling: Doing polling POST https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:38.698497+0500 Cuufy[306:42888] LOG SocketEnginePolling: Got polling response
2018-01-09 14:00:38.698741+0500 Cuufy[306:42888] LOG SocketEnginePolling: Got poll message: 1:3
2018-01-09 14:00:38.699252+0500 Cuufy[306:42888] LOG SocketEngine: Got message: 3
2018-01-09 14:00:38.699658+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: pong with data: []
2018-01-09 14:00:38.700512+0500 Cuufy[306:42888] LOG SocketEnginePolling: Doing polling GET https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:38.966968+0500 Cuufy[306:42816] LOG SocketEngineWebSocket: Sending ws: probe as type: 2
2018-01-09 14:00:39.009808+0500 Cuufy[306:42888] LOG SocketEnginePolling: Got polling response
2018-01-09 14:00:39.010326+0500 Cuufy[306:42888] LOG SocketEnginePolling: Got poll message: 64:434[{"message":"Joined Successfully","code":200,"success":true}]
2018-01-09 14:00:39.011089+0500 Cuufy[306:42888] LOG SocketEngine: Got message: 434[{"message":"Joined Successfully","code":200,"success":true}]
2018-01-09 14:00:39.012114+0500 Cuufy[306:35607] LOG SocketParser: Parsing 34[{"message":"Joined Successfully","code":200,"success":true}]
2018-01-09 14:00:39.013086+0500 Cuufy[306:35607] LOG SocketParser: Decoded packet as: SocketPacket {type: 3; data: [{
    code = 200;
    message = "Joined Successfully";
    success = 1;
}]; id: 4; placeholders: -1; nsp: /}
2018-01-09 14:00:39.013219+0500 Cuufy[306:42888] LOG SocketEnginePolling: Doing polling GET https://www.binexsolutions.com:5105/socket.io/?transport=polling&b64=1&sid=nfR94Z0JH4inbDU9AAAZ
2018-01-09 14:00:39.013463+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling ack: 4 with data: [{
    code = 200;
    message = "Joined Successfully";
    success = 1;
}]
2018-01-09 14:08:21.965744+0500 Cuufy[306:35607] LOG OnAckCallback: OnAckCallback for 4 being released
2018-01-09 14:08:21.967943+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: ping with data: []
2018-01-09 14:08:21.972928+0500 Cuufy[306:42757] LOG SocketEngine: Got message: 3probe
2018-01-09 14:08:21.973552+0500 Cuufy[306:42757] LOG SocketEngine: Received probe response, should upgrade to WebSockets
2018-01-09 14:08:21.973725+0500 Cuufy[306:42757] LOG SocketEngine: Upgrading transport to WebSockets
2018-01-09 14:08:21.974067+0500 Cuufy[306:42757] LOG SocketEnginePolling: Sending poll:  as type: 6
2018-01-09 14:08:21.974350+0500 Cuufy[306:42757] LOG SocketEnginePolling: Created POST string: 1:6
2018-01-09 14:08:21.975033+0500 Cuufy[306:42757] LOG SocketEnginePolling: POSTing
2018-01-09 14:08:21.975423+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: pong with data: []
2018-01-09 14:08:21.977430+0500 Cuufy[306:42757] LOG SocketEngine: Flushing probe wait
2018-01-09 14:08:21.990905+0500 Cuufy[306:42757] LOG SocketEngine: Writing poll:  has data: false
2018-01-09 14:08:21.991113+0500 Cuufy[306:42757] LOG SocketEnginePolling: Sending poll:  as type: 2
2018-01-09 14:08:23.213012+0500 Cuufy[306:42883] LOG SocketEnginePolling: Got polling response
2018-01-09 14:08:23.213370+0500 Cuufy[306:42883] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"}
2018-01-09 14:08:23.214575+0500 Cuufy[306:42883] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"}
2018-01-09 14:08:23.215156+0500 Cuufy[306:42883] **ERROR** SocketEngine: Session ID unknown
2018-01-09 14:08:23.215468+0500 Cuufy[306:35607] **ERROR** SocketManager: Session ID unknown
2018-01-09 14:08:23.215768+0500 Cuufy[306:35607] LOG SocketIOClient{/}: Handling event: error with data: ["Session ID unknown"]
2018-01-09 14:08:23.216178+0500 Cuufy[306:42883] LOG SocketEngine: Switching to WebSockets

@nuclearace This the way how i get it. It is clear from the logs that the socket was connected. Then for some reasons it got disconnected. After that it tried to reconnect and it and did it. But then it encountered the error "Session Id unknown"
Can you suggest some appropriate solution?
P.s Socket.io version is 13.1.0

kinza88 on 9 Jan 2018

@bl82 can you explain the bad flow and how you fixed Incase someone else runs into it?

@kinza88 Are you doing any load balancing between multiple socket.io servers that would cause the client to hit a server it didn’t originally make the request to?

nuclearace on 9 Jan 2018

Or are you putting the socket into to the background and reopening the app?

nuclearace on 9 Jan 2018

@nuclearace
No there is no load balancing. There is only one server.
Although I am calling socket.disconnect() when the app goes in background and then calling socket.connect()when app comes in foreground

kinza88 on 9 Jan 2018

@nuclearace any updates?

kinza88 on 15 Jan 2018

@kinza88 No, I was never able to reproduce.

nuclearace on 8 Mar 2018

@bl82 can you explain the bad flow and how you fixed Incase someone else runs into it?
I recommend taking backend team with mobile developers to trace this issue, check with debug and break points whole flow and see if you have somewhere in code duplicated calls for either creating a connect after disconnect or reconnecting. My flow was flawed, during slight change of backend logic, when new condition (edge case) arrived and flow started working in different way, skipping necessary check and recreating connections multiple times. Such issues are better tracked with careful step-by-step debug of your own code. I also recommend making all Socket Connection methods and management to be put in separated class.

bl82 on 4 Apr 2018

I bumped into this issue, and it turns out that migration from 12.x to 13.x you need to keep let socketManager = SocketManager(socketURL: someURL) in your class level (not a temporary variable). in 12.x, you keep SocketIOClient (aka, socket). Gee, can somebody make it more obvious when making this change. This is the place that I found out this change: https://github.com/socketio/socket.io-client-swift/blob/master/Usage%20Docs/12to13.md

ryan2x on 14 May 2018

@ryan2x That's what the docs and CHANGELOG are for. It's also mentioned in the CHANGELOG for 13 to checkout the migration guide. I guess a link would have been more helpful, but it still mentions where to find it.

nuclearace on 14 May 2018

@ryan2x @nuclearace As for me I did migration from 12 to 13 version, before facing this issue. Don't think it is related. Maybe it is causing similar behaviour if not migrated to v13 properly.

bl82 on 16 May 2018

hello,in OC ,When the network is unconnected，I take the initiative to call [socket disconnect];But the log has been printed on the console,I don't understand.

The logs:
2018-05-18 17:00:33.483088+0800 Delivery[1030:258011] LOG SocketEngine: Writing ws: has data: false
2018-05-18 17:00:33.484839+0800 Delivery[1030:258011] LOG SocketEngineWebSocket: Sending ws: as type: 2
2018-05-18 17:00:33.486843+0800 Delivery[1030:253545] LOG SocketIOClient{/}: Handling event: ping with data: []
2018-05-18 17:00:33.539325+0800 Delivery[1030:258012] LOG SocketEngine: Got message: 3
2018-05-18 17:00:33.541451+0800 Delivery[1030:253545] LOG SocketIOClient{/}: Handling event: pong with data: []