Add better logging for integration tests by injecting a ThreadFactory that can set thread names

bramble-android/src/main/java/org/briarproject/bramble/BrambleAndroidModule.java

@@ -9,6 +9,7 @@ import org.briarproject.bramble.socks.SocksModule;
 import org.briarproject.bramble.system.AndroidSystemModule;
 import org.briarproject.bramble.system.AndroidTaskSchedulerModule;
 import org.briarproject.bramble.system.AndroidWakefulIoExecutorModule;
+import org.briarproject.bramble.system.DefaultThreadFactoryModule;
 
 import dagger.Module;
 
@@ -18,6 +19,7 @@ import dagger.Module;
 		AndroidSystemModule.class,
 		AndroidTaskSchedulerModule.class,
 		AndroidWakefulIoExecutorModule.class,
+		DefaultThreadFactoryModule.class,
 		CircumventionModule.class,
 		DnsModule.class,
 		ReportingModule.class,

bramble-core/src/main/java/org/briarproject/bramble/TimeLoggingExecutor.java

@@ -4,6 +4,7 @@ import org.briarproject.nullsafety.NotNullByDefault;
 
 import java.util.concurrent.BlockingQueue;
 import java.util.concurrent.RejectedExecutionHandler;
+import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.ThreadPoolExecutor;
 import java.util.concurrent.TimeUnit;
 import java.util.logging.Logger;
@@ -19,9 +20,10 @@ public class TimeLoggingExecutor extends ThreadPoolExecutor {
 	public TimeLoggingExecutor(String tag, int corePoolSize, int maxPoolSize,
 			long keepAliveTime, TimeUnit unit,
 			BlockingQueue<Runnable> workQueue,
+			ThreadFactory threadFactory,
 			RejectedExecutionHandler handler) {
 		super(corePoolSize, maxPoolSize, keepAliveTime, unit, workQueue,
-				handler);
+				threadFactory, handler);
 		log = Logger.getLogger(tag);
 	}
 

bramble-core/src/main/java/org/briarproject/bramble/crypto/CryptoExecutorModule.java

@@ -9,6 +9,7 @@ import java.util.concurrent.Executor;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.LinkedBlockingQueue;
 import java.util.concurrent.RejectedExecutionHandler;
+import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.ThreadPoolExecutor;
 
 import javax.inject.Inject;
@@ -37,31 +38,31 @@ public class CryptoExecutorModule {
 	private static final int MAX_EXECUTOR_THREADS =
 			Math.max(1, Runtime.getRuntime().availableProcessors() - 1);
 
-	private final ExecutorService cryptoExecutor;
-
 	public CryptoExecutorModule() {
-		// Use an unbounded queue
-		BlockingQueue<Runnable> queue = new LinkedBlockingQueue<>();
-		// Discard tasks that are submitted during shutdown
-		RejectedExecutionHandler policy =
-				new ThreadPoolExecutor.DiscardPolicy();
-		// Create a limited # of threads and keep them in the pool for 60 secs
-		cryptoExecutor = new TimeLoggingExecutor("CryptoExecutor", 0,
-				MAX_EXECUTOR_THREADS, 60, SECONDS, queue, policy);
 	}
 
 	@Provides
 	@Singleton
 	@CryptoExecutor
 	ExecutorService provideCryptoExecutorService(
-			LifecycleManager lifecycleManager) {
+			LifecycleManager lifecycleManager, ThreadFactory threadFactory) {
+		// Use an unbounded queue
+		BlockingQueue<Runnable> queue = new LinkedBlockingQueue<>();
+		// Discard tasks that are submitted during shutdown
+		RejectedExecutionHandler policy =
+				new ThreadPoolExecutor.DiscardPolicy();
+		// Create a limited # of threads and keep them in the pool for 60 secs
+		ExecutorService cryptoExecutor = new TimeLoggingExecutor(
+				"CryptoExecutor", 0, MAX_EXECUTOR_THREADS, 60, SECONDS, queue,
+				threadFactory, policy);
 		lifecycleManager.registerForShutdown(cryptoExecutor);
 		return cryptoExecutor;
 	}
 
 	@Provides
 	@CryptoExecutor
-	Executor provideCryptoExecutor() {
+	Executor provideCryptoExecutor(
+			@CryptoExecutor ExecutorService cryptoExecutor) {
 		return cryptoExecutor;
 	}
 }

bramble-core/src/main/java/org/briarproject/bramble/db/DatabaseExecutorModule.java

@@ -9,6 +9,7 @@ import java.util.concurrent.Executor;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.LinkedBlockingQueue;
 import java.util.concurrent.RejectedExecutionHandler;
+import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.ThreadPoolExecutor;
 
 import javax.inject.Inject;
@@ -28,24 +29,20 @@ public class DatabaseExecutorModule {
 		ExecutorService executorService;
 	}
 
-	private final ExecutorService databaseExecutor;
-
-	public DatabaseExecutorModule() {
+	@Provides
+	@Singleton
+	@DatabaseExecutor
+	ExecutorService provideDatabaseExecutorService(
+			LifecycleManager lifecycleManager, ThreadFactory threadFactory) {
 		// Use an unbounded queue
 		BlockingQueue<Runnable> queue = new LinkedBlockingQueue<>();
 		// Discard tasks that are submitted during shutdown
 		RejectedExecutionHandler policy =
 				new ThreadPoolExecutor.DiscardPolicy();
 		// Use a single thread and keep it in the pool for 60 secs
-		databaseExecutor = new TimeLoggingExecutor("DatabaseExecutor", 0, 1,
-				60, SECONDS, queue, policy);
-	}
-
-	@Provides
-	@Singleton
-	@DatabaseExecutor
-	ExecutorService provideDatabaseExecutorService(
-			LifecycleManager lifecycleManager) {
+		ExecutorService databaseExecutor = new TimeLoggingExecutor(
+				"DatabaseExecutor", 0, 1, 60, SECONDS, queue, threadFactory,
+				policy);
 		lifecycleManager.registerForShutdown(databaseExecutor);
 		return databaseExecutor;
 	}

bramble-core/src/main/java/org/briarproject/bramble/event/DefaultEventExecutorModule.java

@@ -3,6 +3,7 @@ package org.briarproject.bramble.event;
 import org.briarproject.bramble.api.event.EventExecutor;
 
 import java.util.concurrent.Executor;
+import java.util.concurrent.ThreadFactory;
 
 import javax.inject.Singleton;
 
@@ -22,10 +23,11 @@ public class DefaultEventExecutorModule {
 	@Provides
 	@Singleton
 	@EventExecutor
-	Executor provideEventExecutor() {
+	Executor provideEventExecutor(ThreadFactory threadFactory) {
 		return newSingleThreadExecutor(r -> {
-			Thread t = new Thread(r);
+			Thread t = threadFactory.newThread(r);
 			t.setDaemon(true);
+			t.setName(t.getName() + "-Event");
 			return t;
 		});
 	}

bramble-core/src/main/java/org/briarproject/bramble/lifecycle/LifecycleModule.java

@@ -9,6 +9,7 @@ import java.util.concurrent.Executor;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.RejectedExecutionHandler;
 import java.util.concurrent.SynchronousQueue;
+import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.ThreadPoolExecutor;
 
 import javax.inject.Inject;
@@ -28,19 +29,6 @@ public class LifecycleModule {
 		Executor executor;
 	}
 
-	private final ExecutorService ioExecutor;
-
-	public LifecycleModule() {
-		// The thread pool is unbounded, so use direct handoff
-		BlockingQueue<Runnable> queue = new SynchronousQueue<>();
-		// Discard tasks that are submitted during shutdown
-		RejectedExecutionHandler policy =
-				new ThreadPoolExecutor.DiscardPolicy();
-		// Create threads as required and keep them in the pool for 60 seconds
-		ioExecutor = new ThreadPoolExecutor(0, Integer.MAX_VALUE,
-				60, SECONDS, queue, policy);
-	}
-
 	@Provides
 	@Singleton
 	ShutdownManager provideShutdownManager() {
@@ -57,7 +45,16 @@ public class LifecycleModule {
 	@Provides
 	@Singleton
 	@IoExecutor
-	Executor provideIoExecutor(LifecycleManager lifecycleManager) {
+	Executor provideIoExecutor(LifecycleManager lifecycleManager,
+			ThreadFactory threadFactory) {
+		// The thread pool is unbounded, so use direct handoff
+		BlockingQueue<Runnable> queue = new SynchronousQueue<>();
+		// Discard tasks that are submitted during shutdown
+		RejectedExecutionHandler policy =
+				new ThreadPoolExecutor.DiscardPolicy();
+		// Create threads as required and keep them in the pool for 60 seconds
+		ExecutorService ioExecutor = new ThreadPoolExecutor(0,
+				Integer.MAX_VALUE, 60, SECONDS, queue, threadFactory, policy);
 		lifecycleManager.registerForShutdown(ioExecutor);
 		return ioExecutor;
 	}

bramble-core/src/main/java/org/briarproject/bramble/system/DefaultTaskSchedulerModule.java

@@ -6,6 +6,7 @@ import org.briarproject.bramble.api.system.TaskScheduler;
 import java.util.concurrent.RejectedExecutionHandler;
 import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.ScheduledThreadPoolExecutor;
+import java.util.concurrent.ThreadFactory;
 
 import javax.inject.Inject;
 import javax.inject.Singleton;
@@ -21,18 +22,15 @@ public class DefaultTaskSchedulerModule {
 		TaskScheduler scheduler;
 	}
 
-	private final ScheduledExecutorService scheduledExecutorService;
-
-	public DefaultTaskSchedulerModule() {
+	@Provides
+	@Singleton
+	TaskScheduler provideTaskScheduler(LifecycleManager lifecycleManager,
+			ThreadFactory threadFactory) {
 		// Discard tasks that are submitted during shutdown
 		RejectedExecutionHandler policy =
 				new ScheduledThreadPoolExecutor.DiscardPolicy();
-		scheduledExecutorService = new ScheduledThreadPoolExecutor(1, policy);
-	}
-
-	@Provides
-	@Singleton
-	TaskScheduler provideTaskScheduler(LifecycleManager lifecycleManager) {
+		ScheduledExecutorService scheduledExecutorService =
+				new ScheduledThreadPoolExecutor(1, threadFactory, policy);
 		lifecycleManager.registerForShutdown(scheduledExecutorService);
 		return new TaskSchedulerImpl(scheduledExecutorService);
 	}

bramble-core/src/main/java/org/briarproject/bramble/system/DefaultThreadFactoryModule.java

@@ -0,0 +1,18 @@
+package org.briarproject.bramble.system;
+
+import java.util.concurrent.Executors;
+import java.util.concurrent.ThreadFactory;
+
+import javax.inject.Singleton;
+
+import dagger.Module;
+import dagger.Provides;
+
+@Module
+public class DefaultThreadFactoryModule {
+	@Provides
+	@Singleton
+	ThreadFactory provideThreadFactory() {
+		return Executors.defaultThreadFactory();
+	}
+}

bramble-core/src/test/java/org/briarproject/bramble/plugin/file/RemovableDriveIntegrationTestComponent.java

@@ -10,6 +10,7 @@ import org.briarproject.bramble.api.plugin.file.RemovableDriveManager;
 import org.briarproject.bramble.battery.DefaultBatteryManagerModule;
 import org.briarproject.bramble.event.DefaultEventExecutorModule;
 import org.briarproject.bramble.mailbox.ModularMailboxModule;
+import org.briarproject.bramble.system.DefaultThreadFactoryModule;
 import org.briarproject.bramble.system.DefaultWakefulIoExecutorModule;
 import org.briarproject.bramble.system.TimeTravelModule;
 import org.briarproject.bramble.test.TestDatabaseConfigModule;
@@ -29,6 +30,7 @@ import dagger.Component;
 		DefaultBatteryManagerModule.class,
 		DefaultEventExecutorModule.class,
 		DefaultWakefulIoExecutorModule.class,
+		DefaultThreadFactoryModule.class,
 		TestDatabaseConfigModule.class,
 		TestDnsModule.class,
 		TestFeatureFlagModule.class,

bramble-core/src/test/java/org/briarproject/bramble/test/BrambleCoreIntegrationTestModule.java

@@ -11,6 +11,7 @@ import dagger.Module;
 		DefaultBatteryManagerModule.class,
 		DefaultEventExecutorModule.class,
 		DefaultWakefulIoExecutorModule.class,
+		TestThreadFactoryModule.class,
 		TestDatabaseConfigModule.class,
 		TestFeatureFlagModule.class,
 		TestMailboxDirectoryModule.class,

bramble-core/src/test/java/org/briarproject/bramble/test/TestThreadFactoryModule.java

@@ -0,0 +1,66 @@
+package org.briarproject.bramble.test;
+
+import java.util.concurrent.Executors;
+import java.util.concurrent.ThreadFactory;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
+
+import dagger.Module;
+import dagger.Provides;
+
+@Module
+public class TestThreadFactoryModule {
+
+	@Nullable
+	private final String prefix;
+
+	public TestThreadFactoryModule() {
+		this(null);
+	}
+
+	public TestThreadFactoryModule(@Nullable String prefix) {
+		this.prefix = prefix;
+	}
+
+	@Provides
+	ThreadFactory provideThreadFactory() {
+		if (prefix == null) return Executors.defaultThreadFactory();
+		return new TestThreadFactory(prefix);
+	}
+
+	/**
+	 * This class is mostly copied from
+	 * {@link Executors#defaultThreadFactory()} only adds a given prefix.
+	 */
+	static class TestThreadFactory implements ThreadFactory {
+		private static final AtomicInteger poolNumber = new AtomicInteger(1);
+		private final ThreadGroup group;
+		private final AtomicInteger threadNumber = new AtomicInteger(1);
+		private final String namePrefix;
+
+		private TestThreadFactory(String prefix) {
+			SecurityManager s = System.getSecurityManager();
+			this.group = s != null ? s.getThreadGroup() :
+					Thread.currentThread().getThreadGroup();
+			this.namePrefix =
+					prefix + "-p-" + poolNumber.getAndIncrement() + "-t-";
+		}
+
+		@Override
+		public Thread newThread(@Nonnull Runnable r) {
+			Thread t = new Thread(this.group, r,
+					this.namePrefix + this.threadNumber.getAndIncrement(), 0L);
+			if (t.isDaemon()) {
+				t.setDaemon(false);
+			}
+
+			if (t.getPriority() != 5) {
+				t.setPriority(5);
+			}
+
+			return t;
+		}
+	}
+}

briar-headless/src/main/java/org/briarproject/briar/headless/HeadlessModule.kt

@@ -22,6 +22,7 @@ import org.briarproject.bramble.plugin.tor.UnixTorPluginFactory
 import org.briarproject.bramble.plugin.tor.WindowsTorPluginFactory
 import org.briarproject.bramble.system.ClockModule
 import org.briarproject.bramble.system.DefaultTaskSchedulerModule
+import org.briarproject.bramble.system.DefaultThreadFactoryModule
 import org.briarproject.bramble.system.DefaultWakefulIoExecutorModule
 import org.briarproject.bramble.system.DesktopSecureRandomModule
 import org.briarproject.bramble.util.OsUtils.isLinux
@@ -44,6 +45,7 @@ import javax.inject.Singleton
         DefaultEventExecutorModule::class,
         DefaultTaskSchedulerModule::class,
         DefaultWakefulIoExecutorModule::class,
+        DefaultThreadFactoryModule::class,
         DesktopSecureRandomModule::class,
         HeadlessBlogModule::class,
         HeadlessContactModule::class,

briar-headless/src/test/java/org/briarproject/briar/headless/HeadlessTestModule.kt

@@ -17,6 +17,7 @@ import org.briarproject.bramble.api.plugin.simplex.SimplexPluginFactory
 import org.briarproject.bramble.event.DefaultEventExecutorModule
 import org.briarproject.bramble.system.ClockModule
 import org.briarproject.bramble.system.DefaultTaskSchedulerModule
+import org.briarproject.bramble.system.DefaultThreadFactoryModule
 import org.briarproject.bramble.system.DefaultWakefulIoExecutorModule
 import org.briarproject.bramble.test.TestFeatureFlagModule
 import org.briarproject.bramble.test.TestSecureRandomModule
@@ -37,6 +38,7 @@ import javax.inject.Singleton
         DefaultEventExecutorModule::class,
         DefaultTaskSchedulerModule::class,
         DefaultWakefulIoExecutorModule::class,
+        DefaultThreadFactoryModule::class,
         TestFeatureFlagModule::class,
         TestSecureRandomModule::class,
         HeadlessBlogModule::class,

mailbox-integration-tests/src/test/java/org/briarproject/bramble/mailbox/AbstractMailboxIntegrationTest.java

@@ -18,6 +18,8 @@ import org.briarproject.bramble.api.mailbox.MailboxUpdateWithMailbox;
 import org.briarproject.bramble.api.sync.GroupId;
 import org.briarproject.bramble.test.BrambleIntegrationTest;
 import org.briarproject.bramble.test.TestDatabaseConfigModule;
+import org.briarproject.bramble.test.TestLogFormatter;
+import org.briarproject.bramble.test.TestThreadFactoryModule;
 import org.briarproject.briar.api.messaging.PrivateMessage;
 import org.briarproject.mailbox.lib.AbstractMailbox;
 import org.briarproject.mailbox.lib.TestMailbox;
@@ -43,6 +45,10 @@ abstract class AbstractMailboxIntegrationTest
 
 	static final String URL_BASE = "http://127.0.0.1:8000";
 
+	AbstractMailboxIntegrationTest() {
+		TestLogFormatter.use();
+	}
+
 	private final File dir1 = new File(testDir, "alice");
 	private final File dir2 = new File(testDir, "bob");
 	private final SecretKey rootKey = getSecretKey();
@@ -73,13 +79,16 @@ abstract class AbstractMailboxIntegrationTest
 		mailbox.stopLifecycle(true);
 	}
 
-	MailboxIntegrationTestComponent startTestComponent(
+	private MailboxIntegrationTestComponent startTestComponent(
 			File databaseDir, String name) throws Exception {
+		TestThreadFactoryModule threadFactoryModule =
+				new TestThreadFactoryModule(name);
 		TestDatabaseConfigModule dbModule =
 				new TestDatabaseConfigModule(databaseDir);
 		MailboxIntegrationTestComponent component =
 				DaggerMailboxIntegrationTestComponent
 						.builder()
+						.testThreadFactoryModule(threadFactoryModule)
 						.testDatabaseConfigModule(dbModule)
 						.build();
 		injectEagerSingletons(component);

mailbox-integration-tests/src/test/java/org/briarproject/bramble/test/TestLogFormatter.java

@@ -0,0 +1,57 @@
+package org.briarproject.bramble.test;
+
+import org.briarproject.nullsafety.NotNullByDefault;
+
+import java.text.DateFormat;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.logging.ConsoleHandler;
+import java.util.logging.LogManager;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+import java.util.logging.SimpleFormatter;
+
+import javax.annotation.concurrent.ThreadSafe;
+
+@ThreadSafe
+@NotNullByDefault
+public class TestLogFormatter extends SimpleFormatter {
+
+	private final Object lock = new Object();
+	private final DateFormat dateFormat; // Locking: lock
+	private final Date date; // Locking: lock
+
+	public static void use() {
+		LogManager.getLogManager().reset();
+		Logger rootLogger = LogManager.getLogManager().getLogger("");
+		ConsoleHandler handler = new ConsoleHandler();
+		handler.setFormatter(new TestLogFormatter());
+		rootLogger.addHandler(handler);
+	}
+
+	private TestLogFormatter() {
+		synchronized (lock) {
+			dateFormat = new SimpleDateFormat("HH:mm:ss.SSS");
+			date = new Date();
+		}
+	}
+
+	@Override
+	public String format(LogRecord rec) {
+		if (rec.getThrown() == null) {
+			String dateString;
+			synchronized (lock) {
+				date.setTime(rec.getMillis());
+				dateString = dateFormat.format(date);
+			}
+			return String.format("%s [%s] %s %s - %s\n",
+					dateString,
+					Thread.currentThread().getName(),
+					rec.getLevel().getName(),
+					rec.getLoggerName(),
+					rec.getMessage());
+		} else {
+			return super.format(rec);
+		}
+	}
+}