Connection timout on first attempt with new 2.4.4 version

Montrazul commented 7 years ago

Hello. Today I updated to realm version 2.4.4 and since I have done it the very first connection attempt always fails. See the following logoutput:

2017-03-16 19:15:28.084 MYPROJECT[8954:147713] Sync: Connection[1]: Resolving 'youwontgetmyip:9444'
2017-03-16 19:15:28.085 MYPROJECT[8954:147713] Sync: Connection[1]: Connecting to endpoint 'ipv6:9444' (1/2)
2017-03-16 19:16:43.130 MYPROJECT[8954:147713] Sync: Connection[1]: Failed to connect to endpoint 'ipv69444': Operation timed out
2017-03-16 19:16:43.131 MYPROJECT[8954:147713] Sync: Connection[1]: Connecting to endpoint 'youwontgetmyip:9444' (2/2)
2017-03-16 19:16:43.162 MYPROJECT[8954:147713] Sync: Connection[1]: Connected to endpoint 'youwontgetmyip:9444' (from 'youwontgetmyip:50375')
2017-03-16 19:16:43.359 MYPROJECT[8954:147713] Sync: Connection[1]: Session[1]: Sending: BIND(server_path='/dec9da04c06dab1081426789487a31fb/MY_PROJECT', signed_user_token_size=597, need_file_ident_pair=1)
2017-03-16 19:16:43.386 MYPROJECT[8954:147713] Sync: Connection[1]: Session[1]: Received: ALLOC(server_file_ident=112908771122006566, client_file_ident=19, client_file_ident_secret=7567029755090513518)
2017-03-16 19:16:43.396 MYPROJECT[8954:147713] Sync: Connection[1]: Session[1]: Sending: IDENT(server_file_ident=112908771122006566, client_file_ident=19, client_file_ident_secret=7567029755090513518, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_session_ident=0)
2017-03-16 19:16:44.017 [Info] [main] [SyncViewController.swift:87] addNotification(email:) > got notification for: myemail@email.com
2017-03-16 19:16:44.017 [Debug] [main] [SyncViewController.swift:104] addNotificationProgress(email:) > sync progress
2017-03-16 19:16:44.017 [Debug] [main] [SyncViewController.swift:105] addNotificationProgress(email:) > fraction transferred 0.170071142260183
2017-03-16 19:16:44.017 [Debug] [main] [SyncViewController.swift:106] addNotificationProgress(email:) > transferrable bytes 5998966
2017-03-16 19:16:44.017 [Debug] [main] [SyncViewController.swift:107] addNotificationProgress(email:) > transferred bytes 1020251
2017-03-16 19:16:44.605 [Info] [main] [SyncViewController.swift:87] addNotification(email:) > got notification for: myemail@email.com
2017-03-16 19:16:44.605 [Debug] [main] [SyncViewController.swift:104] addNotificationProgress(email:) > sync progress
2017-03-16 19:16:44.605 [Debug] [main] [SyncViewController.swift:105] addNotificationProgress(email:) > fraction transferred 0.499064005363591
2017-03-16 19:16:44.606 [Debug] [main] [SyncViewController.swift:106] addNotificationProgress(email:) > transferrable bytes 5998966
2017-03-16 19:16:44.606 [Debug] [main] [SyncViewController.swift:107] addNotificationProgress(email:) > transferred bytes 2993868
2017-03-16 19:16:44.837 [Info] [main] [SyncViewController.swift:87] addNotification(email:) > got notification for: myemail@email.com
2017-03-16 19:16:44.838 [Debug] [main] [SyncViewController.swift:104] addNotificationProgress(email:) > sync progress
2017-03-16 19:16:44.838 [Debug] [main] [SyncViewController.swift:105] addNotificationProgress(email:) > fraction transferred 0.668570383629445
2017-03-16 19:16:44.838 [Debug] [main] [SyncViewController.swift:106] addNotificationProgress(email:) > transferrable bytes 5998966
2017-03-16 19:16:44.838 [Debug] [main] [SyncViewController.swift:107] addNotificationProgress(email:) > transferred bytes 4010731
2017-03-16 19:16:45.320 [Info] [main] [SyncViewController.swift:87] addNotification(email:) > got notification for: myemail@email.com
2017-03-16 19:16:45.320 [Debug] [main] [SyncViewController.swift:104] addNotificationProgress(email:) > sync progress
2017-03-16 19:16:45.320 [Debug] [main] [SyncViewController.swift:105] addNotificationProgress(email:) > fraction transferred 0.999900982936059
2017-03-16 19:16:45.320 [Debug] [main] [SyncViewController.swift:106] addNotificationProgress(email:) > transferrable bytes 5998966
2017-03-16 19:16:45.321 [Debug] [main] [SyncViewController.swift:107] addNotificationProgress(email:) > transferred bytes 5998372
2017-03-16 19:16:45.322 [Info] [main] [SyncViewController.swift:87] addNotification(email:) > got notification for: myemail@email.com
2017-03-16 19:16:45.322 [Debug] [main] [SyncViewController.swift:104] addNotificationProgress(email:) > sync progress
2017-03-16 19:16:45.322 [Debug] [main] [SyncViewController.swift:105] addNotificationProgress(email:) > fraction transferred 1.0
2017-03-16 19:16:45.322 [Debug] [main] [SyncViewController.swift:106] addNotificationProgress(email:) > transferrable bytes 5998966
2017-03-16 19:16:45.322 [Debug] [main] [SyncViewController.swift:107] addNotificationProgress(email:) > transferred bytes 5998966
2017-03-16 19:16:45.322 [Debug] [main] [SyncViewController.swift:116] addNotificationProgress(email:) > login progress completed: dec9da04c06dab1081426789487a31fb

As you can see the first connection failed. The second is successfull. It is happening on every start of my app when I do the following:

import Foundation
import UIKit
import RealmSwift

class SyncViewController: UIViewController {
    @IBOutlet weak var progressLabel: UILabel!;
    @IBOutlet weak var progressBar: UIProgressView!;
    var notificationToken: NotificationToken!;
    var notificationTokenProgress: NotificationToken!;
    var user: SyncUser!;

    static func storyboardInstance() -> SyncViewController? {
        let storyboard = UIStoryboard(name: String(describing: NSStringFromClass(SyncViewController.classForCoder()).components(separatedBy: ".").last!), bundle: nil);

        return storyboard.instantiateInitialViewController() as? SyncViewController;
    }

    override func viewDidLoad() {
        super.viewDidLoad();

        self.triggerRealm();
    }

    override func viewDidDisappear(_ animated: Bool) {
        self.removeNotificationBlock();
    }
    override func didReceiveMemoryWarning() {
        super.didReceiveMemoryWarning()
    }

    func triggerRealm() {
        logger.debug("trigger realm");

        let email = SecureManager.getSharedInstance().getLogged()!;

        self.addNotification(email: email);
        self.addNotificationProgress(email: email);
    }

    func addNotification(email: String) {
        self.notificationToken = VKB_REALM_Manager.getSharedInstance().getRealm().addNotificationBlock({ _ in
            logger.info("got notification for: \(email)");
        });
    }

    func addNotificationProgress(email: String) {
        if (self.user != nil) {
            let session = self.user.session(for: URL(string: HelperUrls.URL_REALM)!)!;

            logger.info("start notification for: \(email)");

            self.notificationTokenProgress = session.addProgressNotification(for: .download, mode: .forCurrentlyOutstandingWork) { progress in
                DispatchQueue.main.async {
                    logger.debug("sync progress");
                    logger.debug("fraction transferred \(progress.fractionTransferred)");
                    logger.debug("transferrable bytes \(progress.transferrableBytes)");
                    logger.debug("transferred bytes \(progress.transferredBytes)");

                    if (!progress.fractionTransferred.isNaN) {
                        self.progressBar.setProgress(Float(progress.fractionTransferred), animated: true);
                        self.progressLabel.text = "\(Int((progress.fractionTransferred * 100))) %";
                    }

                    if (progress.isTransferComplete) {
                        if (self.user != nil) {
                            logger.debug("login progress completed: \(self.user.identity!)");

                            self.user = nil;

                            self.presentSplitView();
                        }
                    }
                }
            }
        }
    }

    func removeNotificationBlock() {
        self.notificationToken?.stop();
        self.notificationTokenProgress?.stop();
    }

    func presentSplitView() {
        if let vc = SplitViewController.storyboardInstance() {
            self.present(vc, animated: true, completion: nil);
        }
    }
}

bdash commented 7 years ago

Is this the timeout you're referring to?

2017-03-16 19:15:28.085 MYPROJECT[8954:147713] Sync: Connection[1]: Connecting to endpoint '2a01:488:42:1000:50ed:8479:ff86:e919:9444' (1/2)
2017-03-16 19:16:43.130 MYPROJECT[8954:147713] Sync: Connection[1]: Failed to connect to endpoint '2a01:488:42:1000:50ed:8479:ff86:e919:9444': Operation timed out

It appears that the hostname you're connecting to resolves to both an IPv4 and IPv6 address. The timeout happens when attempting to connect to the Realm Object Server connect via the IPv6 address. This may be because you've not configured the Object Server to listen on the IPv6 interface, or a firewall is preventing the connection when made via IPv6, or any number of similar causes.

Montrazul commented 7 years ago

And this is only when using 2.4.4? We never faced that problem using 2.4.3

bdash commented 7 years ago

Nothing has changed with regards to this aspect of Realm's behavior between v2.4.3 and v2.4.4.

Montrazul commented 7 years ago

So then it is something related to 2.4.4. Since we have no problems with 2.4.3.

bdash commented 7 years ago

That's quite possibly due to luck rather than anything having changed with Realm.

As I noted earlier, the hostname you're connecting to resolves to both an IPv4 and an IPv6 address. The order in which Realm attempts to connect to these addresses is undefined (typically it's the order in which the operating system happens to provide them to us). If we happen to connect to the IPv4 address first, or the device doesn't have IPv6 connectivity and so only the IPv4 address is used, the timeout will not be observed.

I would suggest the following:

Determine whether you intend your Realm Object Server to be reachable via IPv6.
If you do intend it to be reachable via IPv6, investigate why it's not reachable. It may be due to the Object Server not being configured to listen on the IPv6 interface, or due to a firewall interfering.
If you don't intend it to be reachable via IPv6, either
- create a new hostname that only lists an IPv4 address, or
- update your existing DNS entry to not list an IPv6 address for the hostname you're using, or
- update the server's configuration to reject packets destined for closed ports rather than silently dropping them. This would cause an attempt to connect via IPv6 to fail immediately rather than waiting until the connection attempt times out.

Montrazul commented 7 years ago

We tested four different realm versions now. The older three werent even trying to use IPv6. Never. And the 2.4.4 is always using IPv6 first. So... I guess there has to be a change causing this.

But ofcourse you are right. Its simple to handle it. A simple forwarding does the trick.

realm / realm-swift

Connection timout on first attempt with new 2.4.4 version #4741