Apply bg fetch test outcomes (#1550)

* do not set bgIoTimestamp in didFinishLaunchingWithOptions

if the app was killed before, that would let subsequent calls to
performFetchWithCompletionHandler()/didReceiveRemoteNotification() fail with
"fetch was just executed, skipping"

* tweak "qos" of fetch thread

`qos: background` and `main.asyncAfter`
may just not be executed in tens of minutes.

* call performFetch() also from didFinishLaunchingWithOptions with launchOptions?[.remoteNotification] set

while most times, this also results in didReceiveRemoteNotification being called
this is not always the case.
not sure at all, what these two entry points are needed for,
you do not find many information about that,
so it is good to be prepared for everything.
also, reading through stackoverflow, things have changed over time and iOS versions ...

* calculate 'last fetch' timestamps only when we are actually doing fetches

this was not 100% correct before as well,
however, by calling performFetch from didFinishLaunchingWithOptions
that statistic bug becomes more visible.

now, the shown times should all actually result in a fetch.

* show the last 3 wakeups in connectivity view

* add a hint about the remaining issue

* better function name

deltachat-ios/AppDelegate.swift

@@ -25,7 +25,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
 
     // purpose of `bgIoTimestamp` is to block rapidly subsequent calls to remote- or local-wakeups:
     //
-    // `bgIoTimestamp` is set to last init, enter-background or last remote- or local-wakeup;
+    // `bgIoTimestamp` is set to enter-background or last remote- or local-wakeup;
     // in the minute after these events, subsequent remote- or local-wakeups are skipped
     // in favor to the chance of being awakened when it makes more sense
     // and to avoid issues with calling concurrent series of startIo/maybeNetwork/stopIo.
@@ -38,8 +38,11 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
     // that is called if the app is started for the first time
     // or after the app is killed.
     //
-    // `didFinishLaunchingWithOptions` creates the context object and sets
-    // up other global things.
+    // - `didFinishLaunchingWithOptions` is also called before event methods as `didReceiveRemoteNotification` are called -
+    //   either _directly before_ (if the app was killed) or _long before_ (if the app was suspended).
+    //
+    // - in some cases `didFinishLaunchingWithOptions` is called _instead_ an event method and `launchOptions` tells the reason;
+    //   the event method may or may not be called in this case, see #1542 for some deeper information.
     //
     // `didFinishLaunchingWithOptions` is _not_ called
     // when the app wakes up from "suspended" state
@@ -49,8 +52,6 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         // setupCrashReporting() may create an additional handler, but we do not want to rely on that
         signal(SIGPIPE, SIG_IGN)
 
-        bgIoTimestamp = Double(Date().timeIntervalSince1970)
-
         DBDebugToolkit.setup(with: []) // empty array will override default device shake trigger
         DBDebugToolkit.setupCrashReporting()
         
@@ -143,6 +144,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         if let notificationOption = launchOptions?[.remoteNotification] {
             logger.info("Notifications: remoteNotification: \(String(describing: notificationOption))")
             increaseDebugCounter("notify-remote-launch")
+            performFetch(completionHandler: { (_) -> Void in })
         }
 
         if dcAccounts.getSelected().isConfigured() && !UserDefaults.standard.bool(forKey: "notifications_disabled") {
@@ -433,6 +435,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
             return
         }
         bgIoTimestamp = nowTimestamp
+        addDebugFetchTimestamp()
 
         // make sure to balance each call to `beginBackgroundTask` with `endBackgroundTask`
         var backgroundTask: UIBackgroundTaskIdentifier = .invalid
@@ -447,37 +450,45 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
             }
         }
 
-        // we're in background, run IO for a little time
-        dcAccounts.startIo()
-        dcAccounts.maybeNetwork()
+        let fetchSemaphore = DispatchSemaphore(value: 0)
 
-        DispatchQueue.main.asyncAfter(deadline: .now() + 10) { [weak self] in
-            logger.info("⬅️ finishing fetch")
+        // move work to non-main thread to not block UI (otherwise, in case we get suspended, the app is blocked totally)
+        // (we are using `qos: default` as `qos: .background` or `main.asyncAfter` may be delayed by tens of minutes)
+        DispatchQueue.global().async { [weak self] in
             guard let self = self else {
                 completionHandler(.failed)
                 return
             }
 
+            // we're in background, run IO for a little time
+            self.dcAccounts.startIo()
+            self.dcAccounts.maybeNetwork()
+
+            _ = fetchSemaphore.wait(timeout: .now() + 10)
+
+            // TOCHECK: it seems, we are not always reaching this point in code,
+            // the semaphore.wait does not exit after 10 seconds and the app gets suspended -
+            // maybe that is on purpose somehow to suspend inactive apps, not sure.
+            // this does not happen often, but still.
+            // cmp. https://github.com/deltachat/deltachat-ios/pull/1542#pullrequestreview-951620906
+            logger.info("⬅️ finishing fetch")
+
             if !self.appIsInForeground() {
                 self.dcAccounts.stopIo()
             }
 
             // to avoid 0xdead10cc exceptions, scheduled jobs need to be done before we get suspended;
             // we increase the probabilty that this happens by waiting a moment before calling completionHandler()
-            DispatchQueue.main.asyncAfter(deadline: .now() + 1) { [weak self] in
-                logger.info("⬅️ fetch done")
-                guard let self = self else {
-                    completionHandler(.failed)
-                    return
-                }
+            _ = fetchSemaphore.wait(timeout: .now() + 1)
 
-                self.pushToDebugArray(name: "notify-fetch-durations", value: Double(Date().timeIntervalSince1970)-nowTimestamp)
-                completionHandler(.newData)
+            logger.info("⬅️ fetch done")
 
-                if backgroundTask != .invalid {
-                    UIApplication.shared.endBackgroundTask(backgroundTask)
-                    backgroundTask = .invalid
-                }
+            self.pushToDebugArray(name: "notify-fetch-durations", value: Double(Date().timeIntervalSince1970)-nowTimestamp)
+            completionHandler(.newData)
+
+            if backgroundTask != .invalid {
+                UIApplication.shared.endBackgroundTask(backgroundTask)
+                backgroundTask = .invalid
             }
         }
     }
@@ -548,10 +559,11 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         }
     }
 
+    // Values calculated for debug log view
     private func increaseDebugCounter(_ name: String) {
         let nowDate = Date()
         let nowTimestamp = Double(nowDate.timeIntervalSince1970)
-        // Values calculated for debug log view
+
         let startTimestamp = UserDefaults.standard.double(forKey: name + "-start")
         if nowTimestamp > startTimestamp + 60*60*24 {
             let cal: Calendar = Calendar(identifier: .gregorian)
@@ -563,19 +575,20 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         let cnt = UserDefaults.standard.integer(forKey: name + "-count")
         UserDefaults.standard.set(cnt + 1, forKey: name + "-count")
         UserDefaults.standard.set(nowTimestamp, forKey: name + "-last")
+    }
 
-        // Values calculated for connectivity view
-        if name == "notify-remote-receive" || name == "notify-local-wakeup" {
-            let timestamps = UserDefaults.standard.array(forKey: Constants.Keys.notificationTimestamps)
-            var slidingTimeframe: [Double]
-            if timestamps != nil, let timestamps = timestamps as? [Double] {
-                slidingTimeframe = timestamps.filter({ nowTimestamp < $0 + 60 * 60 * 24 })
-            } else {
-                slidingTimeframe = [Double]()
-            }
-            slidingTimeframe.append(nowTimestamp)
-            UserDefaults.standard.set(slidingTimeframe, forKey: Constants.Keys.notificationTimestamps)
+    // Values calculated for connectivity view
+    private func addDebugFetchTimestamp() {
+        let nowTimestamp = Double(Date().timeIntervalSince1970)
+        let timestamps = UserDefaults.standard.array(forKey: Constants.Keys.notificationTimestamps)
+        var slidingTimeframe: [Double]
+        if timestamps != nil, let timestamps = timestamps as? [Double] {
+            slidingTimeframe = timestamps.filter({ nowTimestamp < $0 + 60 * 60 * 24 })
+        } else {
+            slidingTimeframe = [Double]()
         }
+        slidingTimeframe.append(nowTimestamp)
+        UserDefaults.standard.set(slidingTimeframe, forKey: Constants.Keys.notificationTimestamps)
     }
 
     private func pushToDebugArray(name: String, value: Double) {

deltachat-ios/Controller/ConnectivityViewController.swift

@@ -108,7 +108,15 @@ class ConnectivityViewController: WebViewViewController {
             averageDelta = (timestamps.last! - timestamps.first!) / Double(timestamps.count-1)
         }
 
-        let lastWakeup = DateUtils.getExtendedAbsTimeSpanString(timeStamp: timestamps.last!)
+        var lastWakeups = ""
+        var lastWakeupsCnt = 0
+        for timestamp in timestamps.reversed() {
+            lastWakeups += (lastWakeupsCnt > 0 ? ", " : "") + DateUtils.getExtendedAbsTimeSpanString(timeStamp: timestamp)
+            lastWakeupsCnt += 1
+            if lastWakeupsCnt >= 3 {
+                break
+            }
+        }
 
         if Int(averageDelta / Double(60 * 60)) > 1 {
             // more than 1 hour in average
@@ -116,7 +124,7 @@ class ConnectivityViewController: WebViewViewController {
                 .appending(title)
                 .appending(String.localized("delayed"))
                 .appending(", ")
-                .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeup))
+                .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeups))
                 .appending(", ")
                 .appending(String.localized(stringID: "notifications_avg_hours", count: Int(averageDelta / Double(60 * 60))))
         }
@@ -127,14 +135,14 @@ class ConnectivityViewController: WebViewViewController {
                 .appending(title)
                 .appending(String.localized("delayed"))
                 .appending(", ")
-                .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeup))
+                .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeups))
                 .appending(", ")
                 .appending(String.localized(stringID: "notifications_avg_minutes", count: Int(averageDelta / 60)))
         }
 
         return  "<span class=\"green dot\"></span>"
             .appending(title)
-            .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeup))
+            .appending(String.localizedStringWithFormat(String.localized("last_check_at"), lastWakeups))
             .appending(", ")
             .appending(String.localized(stringID: "notifications_avg_minutes", count: Int(averageDelta / 60)))
     }