socket.on(clientEvent: .connect) called repeatedly and getting error "Session ID unknown"

[kinza88]

I am using socket.io swift client in my app. I am getting same errors over again and these are as follows:

Errors:

2017-12-13 15:30:32.514653+0500 TestTarget[12264:255378] ERROR SocketEngine: Engine tried opening while connected. Assuming this was a reconnect

2017-12-13 15:30:32.515026+0500 TestTarget[12264:255378] LOG SocketEngine: Starting engine. Server: ######/ 2017-12-13 15:30:32.515207+0500 TestTarget[12264:255378] LOG SocketEngine: Handshaking 2017-12-13 15:30:32.515569+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Doing polling GET ######/socket.io/?transport=polling&b64=1 2017-12-13 15:30:32.515909+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:32.771374+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:33.271314+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Got polling response 2017-12-13 15:30:33.271560+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"} 2017-12-13 15:30:33.272203+0500 TestTarget[12264:255378] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"} 2017-12-13 15:30:33.272971+0500 TestTarget[12264:255378] ERROR SocketEngine: Session ID unknown 2017-12-13 15:30:33.273210+0500 TestTarget[12264:255202] ERROR SocketIOClient: Session ID unknown 2017-12-13 15:30:33.273446+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"] 2017-12-13 15:30:33.273668+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data:

I have searched alot but didn't find anything about these issues.

What happens when these errors come:

As soon as these errors appear, socket tries to get connected again and again and socket.on(clientEvent: .connect) {data, ack in .... is repeatedly called and nothing else happens.

How these issues appeared:

I connected the socket by using following commands:

var socket = SocketIOClient(socketURL: "url", config: [.log(true), .compress]) socket.connect(timeoutAfter: 10) { let errorObj = CError() errorObj.message = "Request timed out" print("Request timed out") connectionError(errorObj) }

I got the error mentioned above. After that I connected the socket simply as: socket.connect()

And everything worked fine. The socket got connected successfully. But after that when I emitted data on socket, i got the same error again.

My observation:

May be this is error is called when connection is already present and socket tries to get connected again. But i have revised my code. socket.connect() is called only once.

Here are the complete logs in case they help:

2017-12-13 15:30:01.785460+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:01.785773+0500 TestTarget[12264:255202] LOG SocketIOClient: Adding engine 2017-12-13 15:30:01.788207+0500 TestTarget[12264:255378] LOG SocketEngine: Starting engine. Server: "URL" 2017-12-13 15:30:01.788370+0500 TestTarget[12264:255378] LOG SocketEngine: Handshaking 2017-12-13 15:30:01.788953+0500 TestTarget[12264:255202] LOG SocketIOClient: Adding handler for event: connect 2017-12-13 15:30:01.790470+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Doing polling GET "URL"/socket.io/?transport=polling&b64=1 2017-12-13 15:30:07.481497+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Got polling response 2017-12-13 15:30:07.483412+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Got poll message: 95:0{"sid":"fEKHZ-HApjVawAOuAABA","upgrades":["websocket"],"pingInterval":5000,"pingTimeout":5000} 2017-12-13 15:30:07.486256+0500 TestTarget[12264:255377] LOG SocketEngine: Got message: 0{"sid":"fEKHZ-HApjVawAOuAABA","upgrades":["websocket"],"pingInterval":5000,"pingTimeout":5000} 2017-12-13 15:30:07.497644+0500 TestTarget[12264:255202] LOG SocketIOClient: Engine opened Connect 2017-12-13 15:30:07.497728+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Doing polling GET "URL"/?transport=polling&b64=1&sid=fEKHZ-HApjVawAOuAABA 2017-12-13 15:30:07.498001+0500 TestTarget[12264:255202] LOG SocketIOClient: Socket connected 2017-12-13 15:30:07.498379+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:07.498575+0500 TestTarget[12264:255377] LOG SocketEngine: Writing poll: has data: false 2017-12-13 15:30:07.499527+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: connect with data: ["/"] 2017-12-13 15:30:07.499598+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Sending poll: as type: 2 Success 2017-12-13 15:30:11.179346+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Created POST string: 1:2 2017-12-13 15:30:11.179775+0500 TestTarget[12264:255377] LOG SocketEnginePolling: POSTing 2017-12-13 15:30:11.180766+0500 TestTarget[12264:255377] LOG SocketEnginePolling: Doing polling POST "URL"/socket.io/?transport=polling&b64=1&sid=fEKHZ-HApjVawAOuAABA 2017-12-13 15:30:19.338687+0500 TestTarget[12264:255709] LOG SocketEngine: Writing poll: has data: false 2017-12-13 15:30:19.339160+0500 TestTarget[12264:255709] LOG SocketEnginePolling: Sending poll: as type: 2 2017-12-13 15:30:19.356512+0500 TestTarget[12264:255709] LOG SocketEnginePolling: Got polling response 2017-12-13 15:30:19.357566+0500 TestTarget[12264:255709] LOG SocketEnginePolling: Got poll message: 2:40 2017-12-13 15:30:19.358142+0500 TestTarget[12264:255709] LOG SocketEngine: Got message: 40 2017-12-13 15:30:19.359113+0500 TestTarget[12264:255709] LOG SocketIOClient: Should parse message: 0 2017-12-13 15:30:19.360388+0500 TestTarget[12264:255709] LOG SocketEnginePolling: Doing polling GET "URL"socket.io/?transport=polling&b64=1&sid=fEKHZ-HApjVawAOuAABA 2017-12-13 15:30:30.606061+0500 TestTarget[12264:255202] LOG SocketIOClient: Emitting: 2["join",{"jwt":"#########"}] 2017-12-13 15:30:30.606417+0500 TestTarget[12264:255714] LOG SocketEngine: Writing poll: 2["join",{"jwt":"#########"}] has data: false 2017-12-13 15:30:32.510240+0500 TestTarget[12264:255202] LOG SocketIOClient: Adding handler for event: join-response 2017-12-13 15:30:32.510301+0500 TestTarget[12264:255714] LOG SocketEnginePolling: Sending poll: 2["join",{"jwt":"#########"}] as type: 4 2017-12-13 15:30:32.512229+0500 TestTarget[12264:255202] LOG SocketParser: Parsing 0 2017-12-13 15:30:32.512965+0500 TestTarget[12264:255202] LOG SocketParser: Decoded packet as: SocketPacket {type: 0; data: []; id: -1; placeholders: 0; nsp: /} 2017-12-13 15:30:32.513171+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:32.513388+0500 TestTarget[12264:255202] LOG SocketIOClient: Starting reconnect 2017-12-13 15:30:32.513619+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: reconnect with data: ["Ping timeout"] 2017-12-13 15:30:32.513776+0500 TestTarget[12264:255202] LOG SocketIOClient: Trying to reconnect 2017-12-13 15:30:32.514019+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: reconnectAttempt with data: [-1] 2017-12-13 15:30:32.514199+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:32.514653+0500 TestTarget[12264:255378] ERROR SocketEngine: Engine tried opening while connected. Assuming this was a reconnect 2017-12-13 15:30:32.515026+0500 TestTarget[12264:255378] LOG SocketEngine: Starting engine. Server: "URL" 2017-12-13 15:30:32.515207+0500 TestTarget[12264:255378] LOG SocketEngine: Handshaking 2017-12-13 15:30:32.515569+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Doing polling GET "URL"/socket.io/?transport=polling&b64=1 2017-12-13 15:30:32.515909+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:32.771374+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:33.271314+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Got polling response 2017-12-13 15:30:33.271560+0500 TestTarget[12264:255378] LOG SocketEnginePolling: Got poll message: {"code":1,"message":"Session ID unknown"} 2017-12-13 15:30:33.272203+0500 TestTarget[12264:255378] LOG SocketEngine: Got message: {"code":1,"message":"Session ID unknown"} 2017-12-13 15:30:33.272971+0500 TestTarget[12264:255378] ERROR SocketEngine: Session ID unknown 2017-12-13 15:30:33.273210+0500 TestTarget[12264:255202] ERROR SocketIOClient: Session ID unknown 2017-12-13 15:30:33.273446+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: error with data: ["Session ID unknown"] 2017-12-13 15:30:33.273668+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:33.642489+0500 TestTarget[12264:255708] LOG SocketEnginePolling: Got polling response 2017-12-13 15:30:33.642748+0500 TestTarget[12264:255708] LOG SocketEnginePolling: Got poll message: 95:0{"sid":"TCNPsSmuea8-mq5eAABB","upgrades":["websocket"],"pingInterval":5000,"pingTimeout":5000} 2017-12-13 15:30:33.642992+0500 TestTarget[12264:255708] LOG SocketEngine: Got message: 0{"sid":"TCNPsSmuea8-mq5eAABB","upgrades":["websocket"],"pingInterval":5000,"pingTimeout":5000} 2017-12-13 15:30:33.644986+0500 TestTarget[12264:255202] LOG SocketIOClient: Engine opened Connect 2017-12-13 15:30:33.645023+0500 TestTarget[12264:255708] LOG SocketEngine: Writing poll: has data: false 2017-12-13 15:30:33.645455+0500 TestTarget[12264:255202] LOG SocketIOClient: Socket connected 2017-12-13 15:30:33.645830+0500 TestTarget[12264:255708] LOG SocketEnginePolling: Sending poll: as type: 2 2017-12-13 15:30:33.646382+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus] 2017-12-13 15:30:33.646725+0500 TestTarget[12264:255708] LOG SocketEnginePolling: Created POST string: 1:2266:42["join",{"jwt":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjVhMTU0NzI4NjRiM2ExNjAyNjFiMDNkYSIsImVtYWlsIjoia2luemFzYWdoaXI0MEBnbWFpbC5jb20iLCJuYW1lIjoiS2luemEgU2FnaGlyIiwiaWF0IjoxNTEzMTYxMDA3LCJleHAiOjE1NDQ2OTcwMDd9.hjwAV4hY4hVnBb9tyDv7cXotArpLCnkUHllVLtmXEK4"}]1:2 2017-12-13 15:30:33.646978+0500 TestTarget[12264:255202] LOG SocketIOClient: Handling event: connect with data: ["/"]

I am using version 12.1.3 of socketio client.

[kinza88]

@nuclearace I have given the complete explanation of my problem. I want you to have a look at it. Thanks.

[nuclearace]

Probably need some better clearing of the session id. If you use forceNew does it still happen.

[kinza88]

if i use forceNew = true. It gives me syntax error. This is i am initializing socket variable

var socket = SocketIOClient(socketURL: URL(string: "URL")!, config: [.log(true), .compress])

[nuclearace]

forceNew is a config option.

[kinza88]

I tried this but still no effect. Moreover i encounter the above scenario every 3/5 times.

[nuclearace]

I'm not sure why forceNew wouldn't work. It should create a new engine for each connect.

If you tweak around here to clear the sid if "code" is 1 does that fix the issue?

[kinza88]

I have tried .forceNew(true) and got this error 1/6 times. The error ratio has got less upto some extent but it isn't completely gone.

clearing sid and connecting again is a good option. Can you tell me some command in which i get this {"code":1,"message":"Session ID unknown"} as response, break it and check error code and connect again? Maybe some socket.on.. command? I have gone through the link you provided but didn't find any such command in which there is a check on code.

[nuclearace]

@kinza88 It would require modifying that method I linked in the library. As for causing the issue in the first place, I'm not sure.

Are you doing any kind of load balancing that might cause a request to go to a different server? That could be one cause of unknown session id.

[kinza88]

No i am not using any load balancing. There is only one server that is in node js. I have noticed another strange thing. If I use socket.connect() socket.emit and socket.on commands in AppDelegate, everything works fine. But as soon as I move these commands from AppDelegate to some other file and call the function of that file from AppDelegate, this error appears. I have checked using deinit, the resources of that file are not getting deinitialized. I don't have any idea why this thing is happening.

[kinza88]

2017-12-15 15:45:34.133480+0500 TestTarget[5332:230404] TIC Read Status [1:0x60000017f440]: 1:57

I am also getting this in logs. I searched about it and found that in swift it means that socket has disconnected. I have socket.on("disconnect") in my code but it is not getting called even on TIC Read Status.

Can you suggest me some way to know when socket got disconnected so that i can connect it again?

[kinza88]

hey! @nuclearace I need your help to solve this issues. I have searched the "TIC Read Status" error in Apple Forums and what a specialist said is:

Unfortunately this specific log point doesn’t help you much because the ENOTCONN (TIC Read Status) error just means that a TCP connection has closed. To learn more you need to dig into the logs generated by the high-level API you’re using.

Can you help me in digging out why this TCP connection is getting closed? As I am getting no clear reason for it from the logs.

[nuclearace]

@kinza88 I'm not sure I can be much help. This library operates on a fairly high level above the underlying networking. It relies on either URLSession or Starscream to tell it when the connection is lost.

[kinza88]

Okay, then can you tell me how can i debug the code? Is there some tool to debug socket.io? I need lower level logs to sort out the problem as current logs are not really self explanatory.

[kinza88]

Hey! @nuclearace Can you suggest any solution for this error:

2017-12-21 20:01:18.297090+0800 SocketIOTest[62610:8531659] ERROR SocketEngine: Engine tried opening while connected. Assuming this was a reconnect

My code is very simple.

public var socket = SocketIOClient(socketURL: URL(string: "URL")!, config: [.log(true), .compress, .forceNew(true)])
socket.connect()
socket.on("connect") {data, ack in
      print("Connected successfully")
}

[kinza88]

This problem got resolved by upgrading socket.io version. And now it is 13.0.1