Loosing extraHeaders when locking - unlocking device twice

[mbouxin]

The issue has been reproduced systematically on Version: 15.0.0 Ios 12.2 iphone 8

If I have my application in foreground and lock my phone, the application looses socket connection. When I unlock my phone once, it reconnects. But if I do the same twice, the second reconnection fails. I attach here after the setup of the socket and the logs of the first and second reconnection.

Socket setup

func connection(serverURL: NSString, cookieN: String, appD: String, token: String) {
    manager = SocketManager(socketURL: URL(string: serverURL as String)!, config: [
      .compress,
      .extraHeaders(["Cookie" : cookieN+"=" + token, "Origin" : appD]),
      .connectParams(["native" : "true"]),
      .reconnects(true),
      .reconnectAttempts(-1),
      .reconnectWait(1),
      .log(true)
      ]
    )
    socket = manager!.defaultSocket

    socket?.on("XXX") {data, ack in
     YYY
    }

    socket?.connect()
  }

On first reconnect everything works fine:

2019-04-24 11:11:33.634460+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["L’opération n’a pas pu s’achever. Socket non connecté"] 2019-04-24 11:11:33.634525+0200 idomed[7692:3172117] LOG SocketManager: Starting reconnect 2019-04-24 11:11:33.634550+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: statusChange with data: [connecting, 2] idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnect with data: ["L’opération n’a pas pu s’achever. Socket non connecté"] 2019-04-24 11:11:33.634685+0200 idomed[7692:3172117] LOG SocketManager: Trying to reconnect 11:33.634705+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-1] 2019-04-24 11:11:33.634816+0200 idomed[7692:3172117] LOG SocketManager: Scheduling reconnect in 1.5971699499637069s 0200 idomed[7692:3172321] LOG SocketEngine: Starting engine. Server: https://dev.idomed.fr 2019-04-24 11:11:33.634920+0200 idomed[7692:3172321] LOG SocketEngine: Handshaking 2019-04-24 11:11:33.635101+0200 idomed[7692:3172321] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true 2019-04-24 11:11:34.055160+0200 idomed[7692:3172321] LOG SocketEnginePolling: Got polling response 2019-04-24 11:11:34.055219+0200 idomed[7692:3172321] LOG SocketEnginePolling: Got poll message: 171:0{"sid":"8Xd6Y58YxQQ4ELacz81V6MzTVRygAX8pPaBgsZdadxlJ6lZl5BcDqKv/6Lad+bvINUdS2rJ7SytGFh84/zTKDA==-native","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000} 2019-04-24 11:11:34.055246+0200 idomed[7692:3172321] LOG SocketEngine: Got message: 0{"sid":"8Xd6Y58YxQQ4ELacz81V6MzTVRygAX8pPaBgsZdadxlJ6l2019-04-24 11:11:34.056089+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: ping with data: [] +0200 idomed[7692:3172117] LOG SocketManager: Engine opened Connect 2019-04-24 11:11:34.056143+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Socket connected 2019-04-24 11:11:34.056174+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: statusChange with data: [connected, 3] 2019-04-24 11:11:34.056187+0200 idomed[7692:3172321] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true&sid=8Xd6Y58YxQQ4ELacz81V6MzTVRygAX8pPaBgsZdadxlJ6lZl2019-04-24 11:11:34.056202+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: connect with data: ["/"] 2019-04-24 11:11:34.056385+0200 idomed[7692:3172321] LOG Sock2019-04-24 11:11:34.056411+0200 idomed[7692:3172321] LOG SocketEnginePolling: Sending poll: as type: 2 2019-04-24 11:11:34.056435+0200 idomed[7692:3172321] LOG SocketEnginePolling: Created POST string: 1:2 04-24 11:11:34.056532+0200 idomed[7692:3172321] LOG SocketEnginePolling: POSTing 2019-04-24 11:11:34.056564+0200 idomed[7692:3172321] LOG SocketEnginePolling: Doing polling POST https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true&sid=8Xd62019-04-24 11:11:34.085853+0200 idomed[7692:3172771] LOG SocketEnginePolling: Got polling response 2019-04-24 11:11:34.085912+0200 idomed[7692:3172771] LOG SocketEnginePolling: Got poll message: 2:40 2019-04-24 11:11:34.085938+0200 idomed[7692:3172771] LOG SocketEngine: Got message: 40 2019-04-24 11:11:34.085991+0200 idomed[7692:3172117] LOG SocketParser: Parsing 0 2019-04-24 11:11:34.086026+0200 idomed[7692:3172117] LOG SocketParser: Decoded packet as: SocketPacket {type: 0; data: []; id: -1; placehold2019-04-24 11:11:34.086066+0200 idomed[7692:3172771] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true&sid=8Xd6Y58YxQQ4ELacz81V6MzTVRygAX8pPaBgsZdadxlJ6lZl5BcDqKv%2F6Lad%2BbvINU2019-04-24 11:11:34.155067+0200 idomed[7692:3172771] LOG SocketEnginePolling: Got polling response

The second reconnect fails

2019-04-24 11:11:43.245919+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["L’opé2019-04-24 11:11:43.246007+0200 idomed[7692:3172117] LOG SocketManager: Starting reconnect 2019-04-24 11:11:43.246032+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: statusChange wi2019-04-24 11:11:43.246064+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnect with data: ["L’opération n’a pas pu s’achever. Socket non connecté"] 7] LOG SocketManager: Trying to reconnect 2019-04-24 11:11:43.246162+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-1] 2019-04-24 11:11:43.246220+0200 idomed[7692:3172117] LOG SocketManager: Scheduling reco2019-04-24 11:11:43.247153+0200 idomed[7692:3172691] LOG SocketEngine: Starting engine. Server: https://dev.idomed.fr 2019-04-24 11:11:43.247183+0200 idomed[7692:3172691] LOG SocketEngine: Handshaking 305+0200 idomed[7692:3172691] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true 2019-04-24 11:11:43.374519+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["Error"] 2019-04-24 11:11:43.410648+0200 idomed[7692:3172691] LOG SocketIOClient{/}: Handling event: error with data: ["Tried emitting when not connected"] 2019-04-24 11:11:43.410771+0200 idomed[7692:3172691] LOG SocketIOClient{/}: Handling event: error with data: ["Tried emitting when not connected"] 2019-04-24 11:11:45.069187+0200 idomed[7692:3172117] LOG SocketManager: Trying to reconnect 2019-04-24 11:11:45.069268+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-2] 2019-04-24 11:11:45.069337+0200 idomed[7692:3172117] LOG SocketManager: Scheduling reconnect in 3.060733838453362s 2019-04-24 11:11:45.069407+0200 idomed[7692:3172771] LOG SocketEngine: Starting engine. Server: https://dev.idomed.fr 2019-04-24 11:11:45.069432+0200 idomed[7692:3172771] LOG S2019-04-24 11:11:45.069619+0200 idomed[7692:3172771] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true 2019-04-24 11:11:45.154309+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["Error"] 2019-04-24 11:11:48.433416+0200 idomed[7692:3172117] LOG SocketManager: Trying to reconnect 2019-04-24 11:11:48.433576+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-3] 2019-04-24 11:11:48.433757+0200 idomed[7692:3172117] LOG SocketManager: Scheduling reconnect in 4.7231257145259535s 2019-04-24 11:11:48.433766+0200 idomed[7692:3172771] LOG SocketEngine: Starting engine. Server: https://dev.idomed.fr 433832+0200 idomed[7692:3172771] LOG SocketEngine: Handshaking 2019-04-24 11:11:48.434327+0200 idomed[7692:3172771] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true 2019-04-24 11:11:48.539816+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["Error"] 2019-04-24 11:11:53.619056+0200 idomed[7692:3172117] LOG SocketManager: Trying to reconnect 2019-04-24 11:11:53.619367+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-4] 2019-04-24 11:11:53.619756+0200 idomed[7692:3172117] LOG SocketManager: Scheduling reconnect in 6.748849286019798s 2019-04-24 11:11:53.620024+0200 idomed[7692:3172827] LOG SocketEngine: Starting engine. Server: https://dev.idomed.fr 2019-04-24 11:11:53.620355+0200 idomed[7692:3172827] LOG SocketEngine: Handshaking 2019-04-24 11:11:53.621426+0200 idomed[7692:3172827] LOG SocketEnginePolling: Doing polling GET https://dev.idomed.fr/socket.io/?transport=polling&b64=1&native=true 2019-04-24 11:11:53.735374+0200 idomed[7692:3172117] LOG SocketIOClient{/}: Handling event: error with data: ["Error"]

[mbouxin]

I just realized investigating the problem that the extraHeader are missing on the second reconnection...

I tested: forcing it does fix my issue. The only thing left is to understand why extraHeaders are lost

[devintangbohu]

I have encountered the same problem, that is, extraheaders has been lost. How did you solve it?

[mbouxin]

I have encountered the same problem, that is, extraheaders has been lost. How did you solve it?

My solution is that I detect when app comes foreground and then I force headers doing this

manager?.config.insert(.extraHeaders(["headerA"` : "ValueA", "HeaderB" : ValueB]), replacing: `true)

[devintangbohu]

According to your method to solve the problem of loss, thank you.