Pause and resume-or-terminate (#829)

* Pause management
Add API to ILogManager to support Pause/Resume/Wait

* Android wrapper and tests

* Change expected values for PauseManager

* Documentation (use-after-free)

* Repair git merge damage

Author: larvacea

docs/use-after-free.md

@@ -0,0 +1,30 @@
+# How to Not Crash on Shutdown
+
+In any concurrent application, there is a race on shutdown between the destruction of SDK components and threads that may be calling SDK methods. This can occur both with static destructors (e.g., the static `LogManager` instance) and destructors for heap-allocated log manager instances. The most common symptom is a read-dereference crash in a `LogEvent` call stack caused by a read-after-free of the internal state of a log manager (less frequently one may see a read-after-free in the background threads of the a log manager; `LogEvent` is typically called more frequently than these background tasks, so it predominates).
+
+As an interim solution, the SDK has added the `PauseActivity` and `WaitPause` methods, and modified the `FlushAndTeardown` method. Applications can reduce or eliminate use-after-free crashes by managing SDK lifetime and using these methods on shutdown.
+
+## PauseActivity and WaitPause
+
+The `PauseActivity` and `WaitPause` methods provide a reliable mechanism to completely quiesce the SDK prior to shutdown. While the SDK is quiesced, calls to `LogEvent`, `Flush`, and `UploadNow` will have no effect (they will return immediately without doing anything), and the SDK's background threads will not run.
+
+`PauseActivity` starts the process of quiescing the SDK. It does not abort calls-in-progress from either other application threads into SDK methods, or from SDK background jobs. The SDK will quiesce once those calls in progress complete.
+
+`WaitPause` waits for these calls to complete. It will return once the SDK is completely quiesced. The time required is potentially unbounded (as with any concurrent operation) though in practice the bound should be on the order of the time required to complete synchronous writes to the persistent database.
+
+For shutdown, the suggested sequence of SDK calls is:
+
+- `Flush` to persist all current telemetry to persistent storage.
+- `PauseActivity` to start the quiesce.
+- `WaitPause` to ensure that the quiesce completed.
+- proceed with other shutdown activity as needed.
+- ideally use `join` or similar mechanisms to quiesce all application threads before shutdown.
+- Since the application should be quiesced, use `SIGKILL` or similar immediate-exit mechanisms to avoid firing destructors and freeing heap at exit, thus avoiding use-after-free crashes on application exit.
+
+## SDK Lifetime Management
+
+The final two steps in that suggested sequence (`join` and `SIGKILL`) should ensure that the SDK outlives potential callers. The `join` step requires potentially unbounded time to complete, and the time in practice depends on application architecture. Thus the suggestion to use `SIGKILL` to terminate execution, possibly before the `join` completes. The immediate-exit effects are no more disruptive than use-after-free crashes, should you be worried about in-flight write operations at exit.
+
+## FlushAndTeardown
+
+The pull request that introduces `PauseActivity` adds calls to `PauseActivity` followed by `WaitPause` in the existing `FlushAndTeardown` method. If one wishes to use this backstop to quiesce the SDK, the application should call `Flush` before `FlushAndTeardown`. This looks redundant (doesn't FlushAndTeardown actually flush, you might ask), but despite the method name `FlushAndTeardown`, the call to `Flush` is required to ensure persistence before the `PauseActivity` quiesce.

lib/android_build/app/src/androidTest/java/com/microsoft/applications/events/maesdktest/SDKUnitNativeTest.java

@@ -92,6 +92,165 @@ public void useAppContext() {
     assertEquals("com.microsoft.applications.events.maesdktest", appContext.getPackageName());
   }
 
+  static class Waiter implements Runnable {
+    @Override
+    public void run() {
+      LogManager.waitPause();
+    }
+  }
+
+  @Test
+  public void notPausedInitially() {
+    System.loadLibrary("native-lib");
+    System.loadLibrary("maesdk");
+
+    Context appContext = InstrumentationRegistry.getInstrumentation().getTargetContext();
+    HttpClient client = new HttpClient(appContext);
+    OfflineRoom.connectContext(appContext);
+
+    final String token =
+            "0123456789abcdef0123456789abcdef-01234567-0123-0123-0123-0123456789ab-0123";
+
+    ILogger logger = LogManager.initialize(token);
+    assertThat(logger, isA(ILogger.class));
+    Thread t = new Thread(new Waiter());
+    t.start();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(false));
+    assertThat(LogManager.startActivity(), is(true));
+    LogManager.endActivity();
+  }
+
+  @Test
+  public void pausingWillWait() {
+    System.loadLibrary("native-lib");
+    System.loadLibrary("maesdk");
+
+    Context appContext = InstrumentationRegistry.getInstrumentation().getTargetContext();
+    HttpClient client = new HttpClient(appContext);
+    OfflineRoom.connectContext(appContext);
+
+    final String token =
+            "0123456789abcdef0123456789abcdef-01234567-0123-0123-0123-0123456789ab-0123";
+
+    ILogger logger = LogManager.initialize(token);
+    assertThat(logger, isA(ILogger.class));
+    assertThat(LogManager.startActivity(), is(true));
+    LogManager.pauseActivity();
+    Thread t = new Thread(new Waiter());
+    t.start();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(true));
+    LogManager.endActivity();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(false));
+    LogManager.resumeActivity();
+  }
+
+  class InstanceWaiter implements Runnable {
+    ILogManager logManager;
+
+    public InstanceWaiter(ILogManager x) {
+      logManager = x;
+    }
+
+    @Override
+    public void run() {
+      logManager.waitPause();
+    }
+  }
+
+  @Test
+  public void pauseOnInstance() {
+    System.loadLibrary("native-lib");
+    System.loadLibrary("maesdk");
+
+    Context appContext = InstrumentationRegistry.getInstrumentation().getTargetContext();
+    HttpClient client = new HttpClient(appContext);
+    OfflineRoom.connectContext(appContext);
+
+    final String token =
+            "0123456789abcdef0123456789abcdef-01234567-0123-0123-0123-0123456789ab-0123";
+
+    ILogConfiguration custom = LogManager.logConfigurationFactory();
+    custom.set(LogConfigurationKey.CFG_STR_PRIMARY_TOKEN, token);
+    custom.set(LogConfigurationKey.CFG_INT_MAX_TEARDOWN_TIME, (long) 5);
+    custom.set(LogConfigurationKey.CFG_STR_FACTORY_NAME, "AThing");
+
+    final ILogManager secondaryManager = LogManagerProvider.createLogManager(custom);
+    assertThat(secondaryManager.startActivity(), is(true));
+    secondaryManager.pauseActivity();
+    Thread t = new Thread(new InstanceWaiter(secondaryManager));
+    t.start();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(true));
+    secondaryManager.endActivity();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(false));
+    secondaryManager.resumeActivity();
+  }
+
+  @Test
+  public void resumingAlsoEnds() {
+    System.loadLibrary("native-lib");
+    System.loadLibrary("maesdk");
+
+    Context appContext = InstrumentationRegistry.getInstrumentation().getTargetContext();
+    HttpClient client = new HttpClient(appContext);
+    OfflineRoom.connectContext(appContext);
+
+    final String token =
+            "0123456789abcdef0123456789abcdef-01234567-0123-0123-0123-0123456789ab-0123";
+
+    ILogger logger = LogManager.initialize(token);
+    assertThat(logger, isA(ILogger.class));
+    assertThat(LogManager.startActivity(), is(true));
+    LogManager.pauseActivity();
+    Thread t = new Thread(new Waiter());
+    t.start();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(true));
+    LogManager.resumeActivity();
+    try {
+      t.join(5);
+    } catch (InterruptedException e) {
+      e.printStackTrace();
+      fail("Waiter interrupted");
+    }
+    assertThat(t.isAlive(), is(false));
+    LogManager.endActivity();
+  }
+
   @Test
   public void runNativeTests() {
     System.loadLibrary("native-lib");

lib/android_build/maesdk/src/main/java/com/microsoft/applications/events/ILogManager.java

@@ -68,4 +68,10 @@ public interface ILogManager extends AutoCloseable {
   public boolean registerPrivacyGuard();
 
   public boolean unregisterPrivacyGuard();
+  
+  public void pauseActivity();
+  public void resumeActivity();
+  public void waitPause();
+  public boolean startActivity();
+  public void endActivity();
 }

lib/android_build/maesdk/src/main/java/com/microsoft/applications/events/LogManager.java

@@ -932,5 +932,10 @@ public static boolean unregisterPrivacyGuard() {
     // we should let LogManager remove it when it d'tors.
     return PrivacyGuard.isInitialized() && nativeUnregisterPrivacyGuardOnDefaultLogManager();
   }
-}
 
+  public static native void pauseActivity();
+  public static native void resumeActivity();
+  public static native void waitPause();
+  public static native boolean startActivity();
+  public static native void endActivity();
+}

lib/android_build/maesdk/src/main/java/com/microsoft/applications/events/LogManagerProvider.java

@@ -293,5 +293,36 @@ public boolean registerPrivacyGuard() {
     public boolean unregisterPrivacyGuard() {
       return PrivacyGuard.isInitialized() && nativeUnregisterPrivacyGuard(nativeLogManager);
     }
+    
+    protected native void nativePauseActivity(long nativeLogManager);
+    protected native void nativeResumeActivity(long nativeLogManager);
+    protected native void nativeWaitPause(long nativeLogManager);
+    protected native boolean nativeStartActivity(long nativeLogManager);
+    protected native void nativeEndActivity(long nativeLogManager);
+
+    @Override
+    public void pauseActivity() {
+      nativePauseActivity(nativeLogManager);
+    }
+
+    @Override
+    public void resumeActivity() {
+      nativeResumeActivity(nativeLogManager);
+    }
+
+    @Override
+    public void waitPause() {
+      nativeWaitPause(nativeLogManager);
+    }
+
+    @Override
+    public boolean startActivity() {
+      return nativeStartActivity(nativeLogManager);
+    }
+
+    @Override
+    public void endActivity() {
+      nativeEndActivity(nativeLogManager);
+    }
   }
 }

lib/api/LogManagerImpl.cpp

@@ -364,6 +364,8 @@ namespace MAT_NS_BEGIN
 
     void LogManagerImpl::FlushAndTeardown()
     {
+        PauseActivity();
+        WaitPause();
         LOG_INFO("Shutting down...");
         LOCKGUARD(m_lock);
         if (m_alive)
@@ -754,7 +756,7 @@ namespace MAT_NS_BEGIN
 
     void LogManagerImpl::ResetLogSessionData()
     {
-        if (m_logSessionDataProvider) 
+        if (m_logSessionDataProvider)
         {
             m_logSessionDataProvider->ResetLogSessionData();
         }
@@ -868,25 +870,93 @@ namespace MAT_NS_BEGIN
     {
 
         LOCKGUARD(m_lock);
-        if (GetSystem()) 
+        if (GetSystem())
         {
             // cleanup pending http requests
-            GetSystem()->cleanup(); 
-        
+            GetSystem()->cleanup();
+
             // cleanup log session ( UUID)
             if (m_logSessionDataProvider)
             {
                 m_logSessionDataProvider->DeleteLogSessionData();
             }
-    
+
             // cleanup offline storage ( this will also cleanup retry queue for http requests
-            if (m_offlineStorage) 
-            {	
-                m_offlineStorage->DeleteAllRecords();	
+            if (m_offlineStorage)
+            {
+                m_offlineStorage->DeleteAllRecords();
             }
         }
         return STATUS_SUCCESS;
     }
+
+    // Pause/Resume interface
+
+    void LogManagerImpl::PauseActivity()
+    {
+        std::unique_lock<std::mutex> lock(m_pause_mutex);
+        if (m_pause_state != PauseState::Active) {
+            return;
+        }
+
+        if (m_pause_active_count == 0)
+        {
+            m_pause_state = PauseState::Paused;
+            // notify under lock because a waiting thread
+            // may destroy objects (including this object)
+            m_pause_cv.notify_all();
+        }
+        else
+        {
+            m_pause_state = PauseState::Pausing;
+        }
+    }
+
+    void LogManagerImpl::ResumeActivity()
+    {
+        std::unique_lock<std::mutex> lock(m_pause_mutex);
+        if (m_pause_state == PauseState::Active) {
+            return;
+        }
+        m_pause_state = PauseState::Active;
+        m_pause_cv.notify_all();
+    }
+
+    void LogManagerImpl::WaitPause()
+    {
+        std::unique_lock<std::mutex> lock(m_pause_mutex);
+        if (m_pause_state != PauseState::Pausing) {
+            return;
+        }
+        m_pause_cv.wait(lock, [this]() -> bool {
+            return m_pause_state != PauseState::Pausing;
+        });
+    }
+
+    bool LogManagerImpl::StartActivity()
+    {
+        std::unique_lock<std::mutex> lock(m_pause_mutex);
+        if (m_pause_state != PauseState::Active) {
+            return false;
+        }
+        m_pause_active_count += 1;
+        return true;
+    }
+
+    void LogManagerImpl::EndActivity()
+    {
+        std::unique_lock<std::mutex> lock(m_pause_mutex);
+        if (m_pause_active_count == 0) {
+            return;
+        }
+        m_pause_active_count -= 1;
+        if (m_pause_active_count > 0) {
+            return;
+        }
+        if (m_pause_state == PauseState::Pausing) {
+            m_pause_state = PauseState::Paused;
+            m_pause_cv.notify_all();
+        }
+    }
 }
 MAT_NS_END
-