Multiple ARTMessage being sent to the app after reestablishing connection from disconnection

[renbevz]

Hello and good day!

Which version of the Ably SDK are you using?

1.2.32

On which platform does the issue happen?

iOS17.5.1

Are you using Carthage?

no

Are you using Cocoapods?

yes,

Which version of Xcode are you using?

15.3

What did you do?

Describe the problem.
I let the application simulate the disconnection to see if ably would handle the reconnection seamlessly which it did but it causes the app to receive multiple ARTMessage

Add a short snippet of code to show the problem

  let options = ARTClientOptions(key: "<API key>")
        options.autoConnect = true
        ablyRealtime = ARTRealtime(options: options)
        ablyRealtime?.connection.on { stateChange in
            let stateChange = stateChange
            switch stateChange.current {
            case .connected:
                Logger.log(.debug, "IConnected to Ably!")
                do {
                    let storeId = try getStoreId()
                    let channel = self.ablyRealtime?.channels.get(storeId)
                    channel?.subscribe { message in
                          do {
                              Logger.log(.debug, "able to get message")
                              print(message)
                              let message = try JSONDecoder().decode(RootResponseSocketMessageEncodable.self, from: JSONSerialization.data(withJSONObject: message.data ?? Data()))
                             print(message)
                            } catch {
                                Logger.log(.error, "Error decoding message: \(error)")
                            }
                    }
                    
                    _ = self.ablyRealtime?.connection.on { change in
                        print("New connection state is \(change.current)")
                    }
                    
                } catch {
                    self.showAlert()
                }
            case .failed:
                Logger.log(.error, "Failed to connect to Ably!")
            case .closed:
                Logger.log(.error, "Closed connection to Ably!")
            case .closing:
                Logger.log(.error, "Closing connection to Ably!")
            case .disconnected:
                Logger.log(.error, "Disconnected to Ably!")
            default:
                break
            }
        }

What did you expect to happen?

Should only receive 1 ARTMessage just like on the first launch

What happened instead?

Was able to receive 2 or more ARTMessage

Add relevant console logs.

Thank you for your assistance on this.

┆Issue is synchronized with this Jira Task by Unito

[umair-ably]

Hi @renbevz, would you be able to share some extended logs showing the "Disconnected to Ably!" output too please?

[maratal]

Isn't it just the same message printed twice? The object address is the same (and the message id too). @renbevz @umair-ably

[renbevz]

Hi @renbevz, would you be able to share some extended logs showing the "Disconnected to Ably!" output too please?

Hi @umair-ably ,

Here's the logs for reference:

6/11/24, 7:32:36 AM [ERROR] [BaseViewController.swift:374 setupSocket()]: Disconnected to Ably!
<ARTConnectionStateChange: 0x3039ad380> - 
	 current: Disconnected; 
	 previous: Connected; 
	 reason: Error 57 - NSPOSIXErrorDomain (reason: NSPOSIXErrorDomain); 
	 retryIn: 0.100000; 
	 retryAttempt: (null); 

New connection state is ARTRealtimeConnectionState(rawValue: 3)

6/11/24, 7:39:03 AM [ERROR] [BaseViewController.swift:374 setupSocket()]: Disconnected to Ably! <ARTConnectionStateChange: 0x30295a680> - 
	 current: Disconnected; 
	 previous: Connecting; 
	 reason: Error 0 - no Internet connection; 
	 retryIn: 19.715751; 
	 retryAttempt: (null); 

New connection state is ARTRealtimeConnectionState(rawValue: 3)

[umair-ably]

Apologies, I wasn't clear enough @renbevz. Could you send one long set of console output that includes the disconnected and message received logs.

I have the same thought as @maratal so would like to cross check as many IDs and timestamps

[renbevz]

Hello @umair-ably here's the complete logs that I have prepared that the app is using.

Please let me know if this would suffice.

Thank you.

6/13/24, 9:00:17 AM [DEBUG] [BaseViewController.swift:345 initializeSocket()]: Initially Connected to Ably!

6/13/24, 9:03:25 AM [DEBUG] [BaseViewController.swift:351 initializeSocket()]: able to get message
6/13/24, 9:03:25 AM [DEBUG] [BaseViewController.swift:352 initializeSocket()]: <ARTMessage: 0x303fdd4a0> {
 id: xMw2Ct9Io_:0:0,
 clientId: (null),
 connectionId: xMw2Ct9Io_,
 timestamp: 2024-06-13 01:03:24 +0000,
 encoding: (null),
 data: {
    event = NewMessage;
    message = "You have a new Bevz Message, click here to open the app.";
    payload =     {
        createdAt = 1718240602421;
        message = "this is for testing demo for github";
        messageId = "8559302f-3738-4d3e-8e45-fbf636fa62d3";
        subject = "test message github";
    };
    timestamp = 1718240602421;
    title = "test message github";
},
 name: NewMessage
}

6/13/24, 9:03:25 AM [INFO] [NotificationManager.swift:46 scheduleLocalNotification(title:body:notificationId:)]: Notification 
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:35 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:35 AM [ERROR] [BaseViewController.swift:374 initializeSocket()]: Disconnected to Ably!
6/13/24, 9:03:35 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 3)
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
[Mixpanel - MixpanelInstance.swift - func reachabilityCallback(reachability:flags:unsafePointer:)] (info) - reachability changed, wifi=false
[Mixpanel - MixpanelInstance.swift - func reachabilityCallback(reachability:flags:unsafePointer:)] (info) - reachability changed, wifi=false
6/13/24, 9:03:35 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:35 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 1)
6/13/24, 9:03:35 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:35 AM [ERROR] [BaseViewController.swift:374 initializeSocket()]: Disconnected to Ably!
6/13/24, 9:03:35 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 3)

Connection 3: encountered error(1:53)
Connection 5: encountered error(1:53)
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:35 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
nw_connection_get_connected_socket_block_invoke [C9] Client called nw_connection_get_connected_socket on unconnected nw_connection
TCP Conn 0x302dd3700 Failed : error 0:50 [50]
6/13/24, 9:03:48 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:48 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 1)
6/13/24, 9:03:48 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:48 AM [ERROR] [BaseViewController.swift:374 initializeSocket()]: Disconnected to Ably!
6/13/24, 9:03:48 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 3)
nw_connection_get_connected_socket_block_invoke [C10] Client called nw_connection_get_connected_socket on unconnected nw_connection
TCP Conn 0x302de4e60 Failed : error 0:50 [50]
6/13/24, 9:03:53 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:53 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:53 AM [INFO] [BaseViewController.swift:137 setupNetworkMonitorQueue()]: Internet connection is not available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:420 checkInternetConnectionForWebsocket()]: Reestablishing websocket from offline
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:420 checkInternetConnectionForWebsocket()]: Reestablishing websocket from offline
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:420 checkInternetConnectionForWebsocket()]: Reestablishing websocket from offline
[Mixpanel - MixpanelInstance.swift - func reachabilityCallback(reachability:flags:unsafePointer:)] (info) - reachability changed, wifi=true
[Mixpanel - MixpanelInstance.swift - func reachabilityCallback(reachability:flags:unsafePointer:)] (info) - reachability changed, wifi=true
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:54 AM [INFO] [BaseViewController.swift:134 setupNetworkMonitorQueue()]: Internet connection is available.
6/13/24, 9:03:59 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:03:59 AM [ERROR] [BaseViewController.swift:374 initializeSocket()]: Disconnected to Ably!
6/13/24, 9:03:59 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 3)
ERROR: (ARTRealtime.m:1492) R:0x3020dbc00 No activity seen from realtime in 26.426273 seconds; assuming connection has dropped
6/13/24, 9:04:23 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:04:23 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 1)
6/13/24, 9:04:23 AM [DEBUG] [BZMenuViewController.swift:165 updateConnectionNotification(_:)]: Entered Change status log
6/13/24, 9:04:23 AM [DEBUG] [BaseViewController.swift:345 initializeSocket()]: Initially Connected to Ably!
6/13/24, 9:04:23 AM [DEBUG] [BaseViewController.swift:361 initializeSocket()]: New connection state is ARTRealtimeConnectionState(rawValue: 2)

6/13/24, 9:04:48 AM [DEBUG] [BaseViewController.swift:351 initializeSocket()]: able to get message
6/13/24, 9:04:48 AM [DEBUG] [BaseViewController.swift:352 initializeSocket()]: <ARTMessage: 0x303f85310> {
 id: xMw2Ct9Io_:1:0,
 clientId: (null),
 connectionId: xMw2Ct9Io_,
 timestamp: 2024-06-13 01:04:48 +0000,
 encoding: (null),
 data: {
    event = NewMessage;
    message = "You have a new Bevz Message, click here to open the app.";
    payload =     {
        createdAt = 1718240687111;
        message = "this is for new message testing demo for github";
        messageId = "087dffa1-29f4-4e66-995a-33cb53cabd84";
        subject = "test message github new message";
    };
    timestamp = 1718240687111;
    title = "test message github new message";
},
 name: NewMessage
}
6/13/24, 9:04:48 AM [DEBUG] [BaseViewController.swift:351 initializeSocket()]: able to get message
6/13/24, 9:04:48 AM [DEBUG] [BaseViewController.swift:352 initializeSocket()]: <ARTMessage: 0x303f85310> {
 id: xMw2Ct9Io_:1:0,
 clientId: (null),
 connectionId: xMw2Ct9Io_,
 timestamp: 2024-06-13 01:04:48 +0000,
 encoding: (null),
 data: {
    event = NewMessage;
    message = "You have a new Bevz Message, click here to open the app.";
    payload =     {
        createdAt = 1718240687111;
        message = "this is for new message testing demo for github";
        messageId = "087dffa1-29f4-4e66-995a-33cb53cabd84";
        subject = "test message github new message";
    };
    timestamp = 1718240687111;
    title = "test message github new message";
},
 name: NewMessage
}

[umair-ably]

Hey @renbevz, the issue lies in subscribing in the connected state case within the connection changed closure.

This means you'd have N number of subscriptions (and printed messages) for the N number of times you disconnect and reconnect.

Instead, you only need to subscribe once, and outside of any callbacks like below; Ably handles the receiving of messages after reconnecting for you without the need to subscribe again.

do {
    let storeId = try getStoreId()
    let channel = self.ablyRealtime?.channels.get(storeId)
    channel?.subscribe { message in
        do {
            Logger.log(.debug, "able to get message")
            print(message)
            let message = try JSONDecoder().decode(RootResponseSocketMessageEncodable.self, from: JSONSerialization.data(withJSONObject: message.data ?? Data()))
            print(message)
        } catch {
            Logger.log(.error, "Error decoding message: \(error)")
        }
    }
} catch {
    self.showAlert()
}  


let options = ARTClientOptions(key: "<API key>")
    options.autoConnect = true
    ablyRealtime = ARTRealtime(options: options)
    ablyRealtime?.connection.on { stateChange in
      let stateChange = stateChange
      switch stateChange.current {
      case .connected:
        Logger.log(.debug, "IConnected to Ably!")
        // use state changes to present additional UI context around connection states, not to manage channel subscriptions
      case .failed:
        Logger.log(.error, "Failed to connect to Ably!")
      case .closed:
        Logger.log(.error, "Closed connection to Ably!")
      case .closing:
        Logger.log(.error, "Closing connection to Ably!")
      case .disconnected:
        Logger.log(.error, "Disconnected to Ably!")
      default:
        break
      }
    }

It's worth keeping in mind you'll need to use an appropriate pattern for your use case in case your application tries to subscribe to the same channel after backgrounding/foregrounding the app, or perhaps calling viewDidAppear several times, etc...

[renbevz]

Hello @umair-ably , Sorry for the very late response on this as I just recently circled back the implementation of Ably on the project and currently upon checking, the app weren't doing such reinitialization or resubscription of connection, unless the user did delete the app or the user log out and log in again.

This line of code is only executed once after logging in

let options = ARTClientOptions(key: "<API key>")
    options.autoConnect = true
    ablyRealtime = ARTRealtime(options: options)

The only scenario that I did on the app is to disconnect and reconnect the internet connection in which it doesn't involve any closing of connection and staying with only with one instance of Ably which which shows the status of the connection.

Please let me know if you need to know more details about this. Thank you as always for answering my queries and apologies for the late response on this.