Add more logging for sleep and alarms.

briar-android/src/main/java/org/briarproject/briar/android/BriarBroadcastReceiver.java

@@ -5,7 +5,6 @@ import android.content.Intent;
 import android.content.IntentFilter;
 import android.net.ConnectivityManager;
 import android.net.NetworkInfo;
-import android.os.Build;
 import android.os.PowerManager;
 import android.support.v4.content.WakefulBroadcastReceiver;
 import android.util.Log;
@@ -23,6 +22,9 @@ import static android.net.ConnectivityManager.TYPE_WIFI;
 import static android.os.BatteryManager.EXTRA_LEVEL;
 import static android.os.BatteryManager.EXTRA_PLUGGED;
 import static android.os.BatteryManager.EXTRA_SCALE;
+import static android.os.Build.VERSION.SDK_INT;
+import static android.os.PowerManager.ACTION_DEVICE_IDLE_MODE_CHANGED;
+import static android.os.PowerManager.ACTION_POWER_SAVE_MODE_CHANGED;
 
 public class BriarBroadcastReceiver extends WakefulBroadcastReceiver {
 
@@ -33,10 +35,8 @@ public class BriarBroadcastReceiver extends WakefulBroadcastReceiver {
 		filter.addAction(ACTION_BATTERY_CHANGED);
 		filter.addAction(ACTION_POWER_CONNECTED);
 		filter.addAction(ACTION_POWER_DISCONNECTED);
-		if (Build.VERSION.SDK_INT >= 21)
+		if (SDK_INT >= 21) filter.addAction(ACTION_POWER_SAVE_MODE_CHANGED);
-			filter.addAction(PowerManager.ACTION_POWER_SAVE_MODE_CHANGED);
+		if (SDK_INT >= 23) filter.addAction(ACTION_DEVICE_IDLE_MODE_CHANGED);
-		if (Build.VERSION.SDK_INT >= 23)
-			filter.addAction(PowerManager.ACTION_DEVICE_IDLE_MODE_CHANGED);
 		filter.addAction(ACTION_AIRPLANE_MODE_CHANGED);
 		filter.addAction(CONNECTIVITY_ACTION);
 		return filter;
@@ -48,35 +48,37 @@ public class BriarBroadcastReceiver extends WakefulBroadcastReceiver {
 		if (ACTION_SCREEN_ON.equals(action)) {
 			Log.i("DEVICE_STATUS", "Screen on");
 		} else if (ACTION_SCREEN_OFF.equals(action)) {
-			Log.i("DEVICE_STATUS","Screen off");
+			Log.i("DEVICE_STATUS", "Screen off");
 		} else if (ACTION_BATTERY_CHANGED.equals(action)) {
 			int level = i.getIntExtra(EXTRA_LEVEL, -1);
 			int scale = i.getIntExtra(EXTRA_SCALE, -1);
 			int plugged = i.getIntExtra(EXTRA_PLUGGED, -1);
-			Log.i("DEVICE_STATUS", "Battery level: " + (level / (float) scale) + ", plugged: " + (plugged != 0));
+			Log.i("DEVICE_STATUS", "Battery level: " + (level / (float) scale)
+					+ ", plugged: " + (plugged != 0));
 		} else if (ACTION_POWER_CONNECTED.equals(action)) {
-			Log.i("DEVICE_STATUS","Power connected");
+			Log.i("DEVICE_STATUS", "Power connected");
 		} else if (ACTION_POWER_DISCONNECTED.equals(action)) {
-			Log.i("DEVICE_STATUS","Power disconnected");
+			Log.i("DEVICE_STATUS", "Power disconnected");
-		} else if (Build.VERSION.SDK_INT >= 21
+		} else if (SDK_INT >= 21
-				&& PowerManager.ACTION_POWER_SAVE_MODE_CHANGED.equals(action)) {
+				&& ACTION_POWER_SAVE_MODE_CHANGED.equals(action)) {
-			PowerManager pm = (PowerManager) ctx.getSystemService(POWER_SERVICE);
+			PowerManager pm = (PowerManager)
-			Log.i("DEVICE_STATUS","Power save mode: " + pm.isPowerSaveMode());
+					ctx.getSystemService(POWER_SERVICE);
-		} else if (Build.VERSION.SDK_INT >= 23
+			Log.i("DEVICE_STATUS", "Power save mode: " + pm.isPowerSaveMode());
-				&& PowerManager.ACTION_DEVICE_IDLE_MODE_CHANGED.equals(action)) {
+		} else if (SDK_INT >= 23
-			PowerManager pm = (PowerManager) ctx.getSystemService(POWER_SERVICE);
+				&& ACTION_DEVICE_IDLE_MODE_CHANGED.equals(action)) {
-			Log.i("DEVICE_STATUS","Idle mode: " + pm.isDeviceIdleMode());
+			PowerManager pm = (PowerManager)
+					ctx.getSystemService(POWER_SERVICE);
+			Log.i("DEVICE_STATUS", " Idle mode: " + pm.isDeviceIdleMode());
 		} else if (ACTION_AIRPLANE_MODE_CHANGED.equals(action)) {
-			Log.i("DEVICE_STATUS","Airplane mode: " + i.getBooleanExtra("state", false));
+			Log.i("DEVICE_STATUS",
+					"Airplane mode: " + i.getBooleanExtra("state", false));
 		} else if (CONNECTIVITY_ACTION.equals(action)) {
-			ConnectivityManager cm =
+			ConnectivityManager cm = (ConnectivityManager)
-					(ConnectivityManager) ctx.getSystemService(CONNECTIVITY_SERVICE);
+					ctx.getSystemService(CONNECTIVITY_SERVICE);
 			NetworkInfo net = cm.getActiveNetworkInfo();
 			boolean online = net != null && net.isConnected();
 			boolean wifi = net != null && net.getType() == TYPE_WIFI;
-			Log.i("DEVICE_STATUS","Online: " + online + ", wifi: " + wifi);
+			Log.i("DEVICE_STATUS", "Online: " + online + ", wifi: " + wifi);
 		}
 	}
 }
-
-

briar-android/src/main/java/org/briarproject/briar/android/BriarService.java

@@ -32,7 +32,6 @@ import org.briarproject.briar.android.logout.HideUiActivity;
 import org.briarproject.briar.android.navdrawer.NavDrawerActivity;
 
 import java.util.concurrent.CountDownLatch;
-import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.logging.Logger;
 
@@ -56,12 +55,14 @@ import static android.os.PowerManager.PARTIAL_WAKE_LOCK;
 import static android.support.v4.app.NotificationCompat.CATEGORY_SERVICE;
 import static android.support.v4.app.NotificationCompat.PRIORITY_MIN;
 import static android.support.v4.app.NotificationCompat.VISIBILITY_SECRET;
-import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static java.util.logging.Level.INFO;
 import static java.util.logging.Level.WARNING;
 import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResult.ALREADY_RUNNING;
 import static org.briarproject.bramble.api.lifecycle.LifecycleManager.StartResult.SUCCESS;
 import static org.briarproject.briar.android.TestingConstants.ACTION_ALARM;
+import static org.briarproject.briar.android.TestingConstants.ALARM_DELAY;
+import static org.briarproject.briar.android.TestingConstants.EXTRA_DUE_MILLIS;
+import static org.briarproject.briar.android.TestingConstants.WAKE_LOCK_DURATION;
 import static org.briarproject.briar.api.android.AndroidNotificationManager.FAILURE_CHANNEL_ID;
 import static org.briarproject.briar.api.android.AndroidNotificationManager.FAILURE_NOTIFICATION_ID;
 import static org.briarproject.briar.api.android.AndroidNotificationManager.ONGOING_CHANNEL_ID;
@@ -82,13 +83,15 @@ public class BriarService extends Service {
 
 	private final AtomicBoolean created = new AtomicBoolean(false);
 	private final Binder binder = new BriarBinder();
-	private final BriarBroadcastReceiver testReceiver = new BriarBroadcastReceiver();
 
 	private AlarmManager alarm;
 
 	@Nullable
 	private BroadcastReceiver receiver = null;
 
+	@Nullable
+	private BriarBroadcastReceiver testReceiver = null;
+
 	@Inject
 	protected DatabaseConfig databaseConfig;
 	// Fields that are accessed from background threads must be volatile
@@ -188,36 +191,33 @@ public class BriarService extends Service {
 		filter.addAction("android.intent.action.QUICKBOOT_POWEROFF");
 		filter.addAction("com.htc.intent.action.QUICKBOOT_POWEROFF");
 		registerReceiver(receiver, filter);
+		testReceiver = new BriarBroadcastReceiver();
 		registerReceiver(testReceiver, testReceiver.getIntentFilter());
 	}
 
 	private void setAlarm() {
-		PendingIntent pi = getPendingIntent();
+		long dueMillis = SystemClock.elapsedRealtime() + ALARM_DELAY;
-		long millis = getElapsedRealTimeMillis(15000, MILLISECONDS);
+		PendingIntent pi = getPendingIntent(dueMillis);
 		if (SDK_INT >= 23) {
 			alarm.setExactAndAllowWhileIdle(ELAPSED_REALTIME_WAKEUP,
-					millis, pi);
+					dueMillis, pi);
 		} else if (SDK_INT >= 19) {
-			alarm.setExact(ELAPSED_REALTIME_WAKEUP, millis, pi);
+			alarm.setExact(ELAPSED_REALTIME_WAKEUP, dueMillis, pi);
 		} else {
-			alarm.set(ELAPSED_REALTIME_WAKEUP, millis, pi);
+			alarm.set(ELAPSED_REALTIME_WAKEUP, dueMillis, pi);
 		}
-		Log.i("ALARM_TEST", "Alarm set");
+		Log.i("ALARM_TEST", "Alarm set for " + ALARM_DELAY + " ms");
 	}
 
-	long getElapsedRealTimeMillis(long delay, TimeUnit unit) {
+	PendingIntent getPendingIntent(long dueMillis) {
-		return SystemClock.elapsedRealtime()
-				+ MILLISECONDS.convert(delay, unit);
-	}
-
-	PendingIntent getPendingIntent() {
 		return PendingIntent.getService(getApplicationContext(), 0,
-				getAlarmIntent(), FLAG_CANCEL_CURRENT);
+				getAlarmIntent(dueMillis), FLAG_CANCEL_CURRENT);
 	}
 
-	Intent getAlarmIntent() {
+	Intent getAlarmIntent(long dueMillis) {
 		Intent i = new Intent(getApplicationContext(), BriarService.class);
 		i.setAction(ACTION_ALARM);
+		i.putExtra(EXTRA_DUE_MILLIS, dueMillis);
 		return i;
 	}
 
@@ -256,19 +256,24 @@ public class BriarService extends Service {
 	@Override
 	public int onStartCommand(Intent intent, int flags, int startId) {
 		if (ACTION_ALARM.equals(intent.getAction())) {
+			long dueMillis = intent.getLongExtra(EXTRA_DUE_MILLIS, 0);
+			long late = SystemClock.elapsedRealtime() - dueMillis;
+			Log.i("ALARM_TEST", "Alarm fired " + late + " ms late");
 			//acquire wakelock
 			PowerManager powerManager = (PowerManager)
 					getApplicationContext().getSystemService(POWER_SERVICE);
 			WakeLock wakeLock = powerManager.newWakeLock(PARTIAL_WAKE_LOCK,
 					"briar:TestWakeLock");
 			wakeLock.acquire();
-			Log.i("ALARM_TEST", "WakeLock acquired");
+			Log.i("ALARM_TEST", "WakeLock acquired for "
+					+ WAKE_LOCK_DURATION + " ms");
 			new Handler().postDelayed(() -> {
-				//release wakelock
+				//set alarm before releasing wake lock
-				wakeLock.release();
-				Log.i("ALARM_TEST", "WakeLock released");
 				setAlarm();
-			}, 5000);
+				//release wakelock
+				Log.i("ALARM_TEST", "Releasing WakeLock");
+				wakeLock.release();
+			}, WAKE_LOCK_DURATION);
 		}
 		return START_NOT_STICKY; // Don't restart automatically if killed
 	}
@@ -284,7 +289,7 @@ public class BriarService extends Service {
 		LOG.info("Destroyed");
 		stopForeground(true);
 		if (receiver != null) unregisterReceiver(receiver);
-		unregisterReceiver(testReceiver);
+		if (testReceiver != null) unregisterReceiver(testReceiver);
 		// Stop the services in a background thread
 		new Thread(() -> {
 			if (started) lifecycleManager.stopServices();

briar-android/src/main/java/org/briarproject/briar/android/SleepMonitor.java

@@ -20,8 +20,8 @@ public class SleepMonitor implements Runnable {
 	private static final int INTERVAL_MS = 5000;
 
 	/**
-	 * If the difference between uptime and real time changes by more than this amount, assume deep
+	 * If the difference between uptime and real time changes by more than
-	 * sleep has occurred.
+	 * this amount, assume deep sleep has occurred.
 	 */
 	private static final int MIN_SLEEP_DURATION_MS = 1000;
 
@@ -42,10 +42,20 @@ public class SleepMonitor implements Runnable {
 
 	@Override
 	public void run() {
+		long lastRealtime = realtime;
 		long sleepDuration = getSleepDuration();
 		if (sleepDuration > MIN_SLEEP_DURATION_MS) {
-			String start = getTime(System.currentTimeMillis() - sleepDuration);
+			long elapsed = realtime - lastRealtime;
-			Log.i("SLEEP_INFO", "System slept for " + sleepDuration + " ms (since " + start + ")");
+			long now = System.currentTimeMillis();
+			String earliestStart = getTime(now - elapsed);
+			String earliestEnd = getTime(now - elapsed + sleepDuration);
+			String latestStart = getTime(now - sleepDuration);
+			String latestEnd = getTime(now);
+			Log.i("SLEEP_INFO", "System slept for " + sleepDuration
+					+ " ms since last check " + elapsed
+					+ " ms ago (earliest " + earliestStart + " - "
+					+ earliestEnd + ", latest " + latestStart + " - "
+					+ latestEnd + ")");
 		}
 	}
 

briar-android/src/main/java/org/briarproject/briar/android/TestingConstants.java

@@ -42,5 +42,8 @@ public interface TestingConstants {
 	boolean FEATURE_FLAG_SIGN_IN_REMINDER = IS_DEBUG_BUILD;
 
 	String ACTION_ALARM = "org.briarproject.briar.android.ACTION_ALARM";
+	String EXTRA_DUE_MILLIS = "org.briarproject.briar.android.DUE_MILLIS";
+	int WAKE_LOCK_DURATION = 5000;
+	int ALARM_DELAY = 15000;
 
 }