Merge pull request #1127 from deltachat/target-anr

call maybeNetwork() from non-ui thread, fix background thread

deltachat-ios/AppDelegate.swift

@@ -40,9 +40,10 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         DBDebugToolkit.setupCrashReporting()
         
         let console = ConsoleDestination()
+        console.format = "$DHH:mm:ss.SSS$d $C$L$c $M" // see https://docs.swiftybeaver.com/article/20-custom-format
         logger.addDestination(console)
         dcContext.logger = DcLogger()
-        logger.info("launching")
+        logger.info("➡️ didFinishLaunchingWithOptions")
 
         window = UIWindow(frame: UIScreen.main.bounds)
         guard let window = window else {
@@ -65,8 +66,12 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         setStockTranslations()
 
         reachability.whenReachable = { reachability in
+            // maybeNetwork() shall not be called in ui thread;
+            // Reachability::reachabilityChanged uses DispatchQueue.main.async only
             logger.info("network: reachable", reachability.connection.description)
-            self.dcContext.maybeNetwork()
+            DispatchQueue.global(qos: .background).async { [weak self] in
+                self?.dcContext.maybeNetwork()
+            }
         }
 
         reachability.whenUnreachable = { _ in
@@ -94,6 +99,8 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
     // `open` is called when an url should be opened by Delta Chat.
     // we currently use that for handling oauth2 and for handing openpgp4fpr
     func application(_: UIApplication, open url: URL, options _: [UIApplication.OpenURLOptionsKey: Any] = [:]) -> Bool {
+        logger.info("➡️ open url")
+
         // gets here when app returns from oAuth2-Setup process - the url contains the provided token
         if let params = url.queryParameters, let token = params["code"] {
             NotificationCenter.default.post(name: NSNotification.Name("oauthLoginApproved"), object: nil, userInfo: ["token": token])
@@ -115,9 +122,17 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
     // we have 30 seconds time for our job, leave some seconds for graceful termination.
     // also, the faster we return, the sooner we get called again.
     func application(_: UIApplication, performFetchWithCompletionHandler completionHandler: @escaping (UIBackgroundFetchResult) -> Void) {
-        logger.info("---- background-fetch ----")
+        logger.info("➡️ performFetchWithCompletionHandler")
         increaseDebugCounter("notify-local-wakeup")
 
+        // if we're in foreground, there is nothing to do
+        if self.appIsInForeground {
+            logger.warning("➡️ app already in foreground")
+            completionHandler(.newData)
+            return
+        }
+
+        // we're in background, run IO for a little time
         dcContext.maybeStartIo()
         dcContext.maybeNetwork()
 
@@ -135,51 +150,43 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
     }
 
     func applicationWillEnterForeground(_: UIApplication) {
-        logger.info("---- foreground ----")
+        logger.info("➡️ applicationWillEnterForeground")
         appIsInForeground = true
         dcContext.maybeStartIo()
-        if reachability.connection != .none {
-            self.dcContext.maybeNetwork()
-        }
 
-        if let userDefaults = UserDefaults.shared, userDefaults.bool(forKey: UserDefaults.hasExtensionAttemptedToSend) {
-            userDefaults.removeObject(forKey: UserDefaults.hasExtensionAttemptedToSend)
-            let nc = NotificationCenter.default
+        DispatchQueue.global(qos: .background).async { [weak self] in
+            guard let self = self else { return }
+            if self.appIsInForeground {
+                if self.reachability.connection != .none {
+                    self.dcContext.maybeNetwork()
+                }
 
-            DispatchQueue.main.async {
-                nc.post(
-                    name: dcNotificationChanged,
-                    object: nil,
-                    userInfo: [:]
-                )
+                if let userDefaults = UserDefaults.shared, userDefaults.bool(forKey: UserDefaults.hasExtensionAttemptedToSend) {
+                    userDefaults.removeObject(forKey: UserDefaults.hasExtensionAttemptedToSend)
+                    DispatchQueue.main.async {
+                        NotificationCenter.default.post(
+                            name: dcNotificationChanged,
+                            object: nil,
+                            userInfo: [:]
+                        )
+                    }
+                }
             }
         }
     }
 
-    func applicationDidEnterBackground(_: UIApplication) {
-        logger.info("---- background ----")
-        appIsInForeground = false
-        maybeStop()
+    func applicationWillResignActive(_: UIApplication) {
+        logger.info("⬅️ applicationWillResignActive")
+        registerBackgroundTask()
     }
 
-    private func maybeStop() {
-        DispatchQueue.main.asyncAfter(deadline: .now() + 3) {
-            let app = UIApplication.shared
-            logger.info("state: \(app.applicationState) time remaining \(app.backgroundTimeRemaining)")
-
-            if app.applicationState != .background {
-                // only need to do sth in the background
-                return
-            } else if app.backgroundTimeRemaining < 10 {
-                self.dcContext.stopIo()
-            } else {
-                self.maybeStop()
-            }
-        }
+    func applicationDidEnterBackground(_: UIApplication) {
+        logger.info("⬅️ applicationDidEnterBackground")
+        appIsInForeground = false
     }
 
     func applicationWillTerminate(_: UIApplication) {
-        logger.info("---- terminate ----")
+        logger.info("⬅️ applicationWillTerminate")
         closeDatabase()
 
         reachability.stopNotifier()
@@ -254,32 +261,54 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
 
     func installEventHandler() {
         DispatchQueue.global(qos: .background).async {
-            self.registerBackgroundTask()
             let eventEmitter = self.dcContext.getEventEmitter()
             while true {
                 guard let event = eventEmitter.getNextEvent() else { break }
                 handleEvent(event: event)
             }
-            if self.backgroundTask != .invalid {
-                self.endBackgroundTask()
-            }
+            logger.info("⬅️ event emitter finished")
         }
     }
 
     // MARK: - BackgroundTask
 
+    // let the app run in background for a little while
+    // eg. to complete sending messages out and to react to responses.
     private func registerBackgroundTask() {
-        logger.info("background task registered")
+        logger.info("⬅️ registering background task")
         backgroundTask = UIApplication.shared.beginBackgroundTask { [weak self] in
-            self?.endBackgroundTask()
+            // usually, the background thread is finished before in maybeStop()
+            logger.info("⬅️ background expirationHandler called")
+            self?.unregisterBackgroundTask()
+        }
+        maybeStop()
+    }
+
+    private func unregisterBackgroundTask() {
+        if backgroundTask != .invalid {
+            UIApplication.shared.endBackgroundTask(backgroundTask)
+            backgroundTask = .invalid
         }
-        assert(backgroundTask != .invalid)
     }
 
-    private func endBackgroundTask() {
-        logger.info("background task ended")
-        UIApplication.shared.endBackgroundTask(backgroundTask)
-        backgroundTask = .invalid
+    private func maybeStop() {
+        DispatchQueue.main.asyncAfter(deadline: .now() + 3) {
+            let app = UIApplication.shared
+            if app.applicationState != .background {
+                logger.info("⬅️ no longer in background")
+                self.unregisterBackgroundTask()
+            } else if app.backgroundTimeRemaining < 10 {
+                logger.info("⬅️ few background time, \(app.backgroundTimeRemaining), stopping")
+                self.dcContext.stopIo()
+                DispatchQueue.main.asyncAfter(deadline: .now() + 3) {
+                    logger.info("⬅️ few background time, \(app.backgroundTimeRemaining), done")
+                    self.unregisterBackgroundTask()
+                }
+            } else {
+                logger.info("⬅️ remaining background time: \(app.backgroundTimeRemaining)")
+                self.maybeStop()
+            }
+        }
     }
 
 
@@ -294,12 +323,13 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         // register for showing notifications
         UNUserNotificationCenter.current()
           .requestAuthorization(options: [.alert, .sound, .badge]) { [weak self] granted, _ in
-            logger.info("Notifications: Permission granted: \(granted)")
-
             if granted {
                 // we are allowed to show notifications:
                 // register for receiving push notifications
+                logger.info("Notifications: Permission granted: \(granted)")
                 self?.maybeRegisterForRemoteNotifications()
+            } else {
+                logger.info("Notifications: Permission not granted.")
             }
         }
     }
@@ -341,7 +371,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         let endpoint = "https://notifications.delta.chat/register"
         #endif
 
-        logger.verbose("Notifications: POST token: \(tokenString) to \(endpoint)")
+        logger.info("Notifications: POST token: \(tokenString) to \(endpoint)")
 
         if let url = URL(string: endpoint) {
             var request = URLRequest(url: url)
@@ -353,9 +383,12 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
                     logger.error("Notifications: cannot POST to notification server: \(error)")
                     return
                 }
-                logger.info("Notifications: request to notification server succeeded with respose, data: \(String(describing: response)), \(String(describing: data))")
+                if let httpStatus = response as? HTTPURLResponse, httpStatus.statusCode == 200 {
+                    logger.info("Notifications: request to notification server succeeded")
+                } else {
+                    logger.error("Notifications: request to notification server failed: \(String(describing: response)), \(String(describing: data))")
+                }
                 self.notifyToken = tokenString
-
             }
             task.resume()
         } else {
@@ -387,9 +420,18 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
         _ application: UIApplication,
         didReceiveRemoteNotification userInfo: [AnyHashable: Any],
         fetchCompletionHandler completionHandler: @escaping (UIBackgroundFetchResult) -> Void) {
-        logger.verbose("Notifications: didReceiveRemoteNotification \(userInfo)")
+        logger.info("➡️ Notifications: didReceiveRemoteNotification \(userInfo)")
         increaseDebugCounter("notify-remote-receive")
 
+        // didReceiveRemoteNotification might be called if we're in foreground,
+        // in this case, there is no need to wait for things or do sth.
+        if self.appIsInForeground {
+            logger.warning("➡️ app already in foreground")
+            completionHandler(.newData)
+            return
+        }
+
+        // we're in background, run IO for a little time
         dcContext.maybeStartIo()
         dcContext.maybeNetwork()
 
@@ -425,17 +467,17 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
 
     // MARK: - Handle notification banners
 
-    // This method will be called if an incoming message was received while the app was in forground.
+    // This method will be called if an incoming message was received while the app was in foreground.
     // We don't show foreground notifications in the notification center because they don't get grouped properly
     func userNotificationCenter(_: UNUserNotificationCenter, willPresent notification: UNNotification, withCompletionHandler completionHandler: @escaping (UNNotificationPresentationOptions) -> Void) {
-        logger.info("forground notification")
+        logger.info("Notifications: foreground notification")
         completionHandler([.badge])
     }
 
     // this method will be called if the user tapped on a notification
     func userNotificationCenter(_: UNUserNotificationCenter, didReceive response: UNNotificationResponse, withCompletionHandler completionHandler: @escaping () -> Void) {
         if !response.notification.request.identifier.containsExact(subSequence: Constants.notificationIdentifier).isEmpty {
-            logger.info("handling notifications")
+            logger.info("Notifications: notification tapped")
             let userInfo = response.notification.request.content.userInfo
              if let chatId = userInfo["chat_id"] as? Int,
                  let msgId = userInfo["message_id"] as? Int {

docs/uiview-layout.md

@@ -1,4 +1,4 @@
-# UIView layout thoughts
+# code layout thoughts
 
 ## view definitions
   
@@ -116,6 +116,31 @@ a tricky part (see eg. [3]) seems to be to hold the correct type of rerences to
   https://developer.apple.com/tutorials/swiftui/interfacing-with-uikit
 
 
+## notification system
+
+- `NotificationCenter.default.post()`
+  post events to all observers _synchronously_ on the same thread;
+  this may not be the thread the observer registered itself [5].
+  Observers may receive the event in any random thread therefore.
+
+- best practise [6] would be that the observers assume,
+  they receive the notification in any thread
+  and call `DispatchQueue.main.async` where actually needed.
+  for new code, we should use that approach, it won't hurt.
+
+- however, existing code might assume
+  that the notification arrives in main thread;
+  therefore, we also call `DispatchQueue.main.async` for sending events out.
+
+- using always main thread for sending/receiving and adding/remove observers
+  also avoids other multithreading-issues of NotificationCenter itself,
+  see https://lapcatsoftware.com/articles/nsnotificationcenter-is-threadsafe-not.html
+  for details.
+
+tl;dr: post from main thread and also add/remove observers from main thread.
+on receiving, assume, things will block.
+
+
 ## some sources
 
 [1] https://developer.apple.com/documentation/uikit/uiapplication
@@ -126,3 +151,8 @@ a tricky part (see eg. [3]) seems to be to hold the correct type of rerences to
 https://github.com/deltachat/deltachat-ios/issues/323
   
 [4] https://developer.apple.com/documentation/uikit/uiapplicationdelegate/1622921-application
+
+[5] https://developer.apple.com/library/archive/documentation/Cocoa/Conceptual/Notifications/Articles/Threading.html#//apple_ref/doc/uid/20001289-CEGJFDFG
+
+[6] https://medium.com/@hadhi631/myths-and-facts-about-nsnotifcation-posting-and-receiving-df7f5729b19f
+