Refactor persistent logging to bramble-core.

2026-02-14 19:59:05 +01:00 · 2020-07-04 12:16:55 +01:00
parent ca5c18ece3
commit cda722a8b2
11 changed files with 13 additions and 13 deletions
--- a/bramble-core/src/main/java/org/briarproject/bramble/BrambleCoreModule.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/BrambleCoreModule.java
@@ -13,6 +13,7 @@ import org.briarproject.bramble.identity.IdentityModule;
 import org.briarproject.bramble.io.IoModule;
 import org.briarproject.bramble.keyagreement.KeyAgreementModule;
 import org.briarproject.bramble.lifecycle.LifecycleModule;
+import org.briarproject.bramble.logging.LoggingModule;
 import org.briarproject.bramble.plugin.PluginModule;
 import org.briarproject.bramble.properties.PropertiesModule;
 import org.briarproject.bramble.record.RecordModule;
@@ -41,6 +42,7 @@ import dagger.Module;
 		IoModule.class,
 		KeyAgreementModule.class,
 		LifecycleModule.class,
+		LoggingModule.class,
 		PluginModule.class,
 		PropertiesModule.class,
 		RecordModule.class,
--- a/bramble-core/src/main/java/org/briarproject/bramble/logging/BriefLogFormatter.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/logging/BriefLogFormatter.java
@@ -0,0 +1,64 @@
+package org.briarproject.bramble.logging;
+
+import org.briarproject.bramble.api.nullsafety.NotNullByDefault;
+
+import java.text.DateFormat;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.TimeZone;
+import java.util.logging.Formatter;
+import java.util.logging.LogRecord;
+
+import javax.annotation.concurrent.ThreadSafe;
+
+import static java.util.Locale.US;
+
+@ThreadSafe
+@NotNullByDefault
+public class BriefLogFormatter extends Formatter {
+
+	private final Object lock = new Object();
+	private final DateFormat dateFormat; // Locking: lock
+	private final Date date; // Locking: lock
+
+	public BriefLogFormatter() {
+		synchronized (lock) {
+			dateFormat = new SimpleDateFormat("MM-dd HH:mm:ss.SSS ", US);
+			dateFormat.setTimeZone(TimeZone.getTimeZone("UTC"));
+			date = new Date();
+		}
+	}
+
+	@Override
+	public String format(LogRecord record) {
+		String dateString;
+		synchronized (lock) {
+			date.setTime(record.getMillis());
+			dateString = dateFormat.format(date);
+		}
+		StringBuilder sb = new StringBuilder(dateString);
+		sb.append(record.getLevel().getName().charAt(0)).append('/');
+		String tag = record.getLoggerName();
+		tag = tag.substring(tag.lastIndexOf('.') + 1);
+		sb.append(tag).append(": ");
+		sb.append(record.getMessage());
+		Throwable t = record.getThrown();
+		if (t != null) {
+			sb.append('\n');
+			appendThrowable(sb, t);
+		}
+		sb.append('\n');
+		return sb.toString();
+	}
+
+	private void appendThrowable(StringBuilder sb, Throwable t) {
+		sb.append(t);
+		for (StackTraceElement e : t.getStackTrace())
+			sb.append("\n        at ").append(e);
+		Throwable cause = t.getCause();
+		if (cause != null) {
+			sb.append("\n     Caused by: ");
+			appendThrowable(sb, cause);
+		}
+	}
+}
--- a/bramble-core/src/main/java/org/briarproject/bramble/logging/FlushingStreamHandler.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/logging/FlushingStreamHandler.java
@@ -0,0 +1,43 @@
+package org.briarproject.bramble.logging;
+
+import java.io.OutputStream;
+import java.util.concurrent.Executor;
+import java.util.concurrent.ScheduledExecutorService;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.logging.Formatter;
+import java.util.logging.LogRecord;
+import java.util.logging.StreamHandler;
+
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+
+class FlushingStreamHandler extends StreamHandler {
+
+	private static final int FLUSH_DELAY_MS = 5_000;
+
+	private final ScheduledExecutorService scheduler;
+	private final Executor ioExecutor;
+	private final AtomicBoolean flushScheduled = new AtomicBoolean(false);
+
+	FlushingStreamHandler(ScheduledExecutorService scheduler,
+			Executor ioExecutor, OutputStream out, Formatter formatter) {
+		super(out, formatter);
+		this.scheduler = scheduler;
+		this.ioExecutor = ioExecutor;
+	}
+
+	@Override
+	public void publish(LogRecord record) {
+		super.publish(record);
+		if (!flushScheduled.getAndSet(true)) {
+			scheduler.schedule(this::scheduledFlush,
+					FLUSH_DELAY_MS, MILLISECONDS);
+		}
+	}
+
+	private void scheduledFlush() {
+		ioExecutor.execute(() -> {
+			flushScheduled.set(false);
+			flush();
+		});
+	}
+}
--- a/bramble-core/src/main/java/org/briarproject/bramble/logging/LoggingModule.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/logging/LoggingModule.java
@@ -0,0 +1,29 @@
+package org.briarproject.bramble.logging;
+
+import org.briarproject.bramble.api.lifecycle.LifecycleManager;
+import org.briarproject.bramble.api.logging.PersistentLogManager;
+
+import java.util.logging.Formatter;
+
+import javax.inject.Singleton;
+
+import dagger.Module;
+import dagger.Provides;
+
+@Module
+public class LoggingModule {
+
+	@Provides
+	Formatter provideFormatter() {
+		return new BriefLogFormatter();
+	}
+
+	@Provides
+	@Singleton
+	PersistentLogManager providePersistentLogManager(
+			LifecycleManager lifecycleManager,
+			PersistentLogManagerImpl persistentLogManager) {
+		lifecycleManager.registerOpenDatabaseHook(persistentLogManager);
+		return persistentLogManager;
+	}
+}
--- a/bramble-core/src/main/java/org/briarproject/bramble/logging/PersistentLogManagerImpl.java
+++ b/bramble-core/src/main/java/org/briarproject/bramble/logging/PersistentLogManagerImpl.java
@@ -0,0 +1,177 @@
+package org.briarproject.bramble.logging;
+
+import org.briarproject.bramble.api.crypto.CryptoComponent;
+import org.briarproject.bramble.api.crypto.SecretKey;
+import org.briarproject.bramble.api.db.DatabaseComponent;
+import org.briarproject.bramble.api.db.DbException;
+import org.briarproject.bramble.api.db.Transaction;
+import org.briarproject.bramble.api.lifecycle.IoExecutor;
+import org.briarproject.bramble.api.lifecycle.LifecycleManager.OpenDatabaseHook;
+import org.briarproject.bramble.api.lifecycle.ShutdownManager;
+import org.briarproject.bramble.api.logging.PersistentLogManager;
+import org.briarproject.bramble.api.nullsafety.NotNullByDefault;
+import org.briarproject.bramble.api.settings.Settings;
+import org.briarproject.bramble.api.system.Scheduler;
+import org.briarproject.bramble.api.transport.StreamReaderFactory;
+import org.briarproject.bramble.api.transport.StreamWriter;
+import org.briarproject.bramble.api.transport.StreamWriterFactory;
+
+import java.io.File;
+import java.io.FileInputStream;
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.io.InputStream;
+import java.io.OutputStream;
+import java.util.LinkedList;
+import java.util.List;
+import java.util.Scanner;
+import java.util.concurrent.Executor;
+import java.util.concurrent.ScheduledExecutorService;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.logging.Formatter;
+import java.util.logging.Handler;
+import java.util.logging.Logger;
+import java.util.logging.StreamHandler;
+
+import javax.annotation.Nullable;
+import javax.annotation.concurrent.ThreadSafe;
+import javax.inject.Inject;
+
+import static java.util.Collections.emptyList;
+import static java.util.logging.Level.WARNING;
+import static java.util.logging.Logger.getLogger;
+import static org.briarproject.bramble.util.LogUtils.logException;
+
+@ThreadSafe
+@NotNullByDefault
+class PersistentLogManagerImpl implements PersistentLogManager,
+		OpenDatabaseHook {
+
+	private static final Logger LOG =
+			getLogger(PersistentLogManagerImpl.class.getName());
+
+	private static final String LOG_FILE = "briar.log";
+	private static final String OLD_LOG_FILE = "briar.log.old";
+	private static final int MAX_LINES_TO_RETURN = 10_000;
+
+	private final ScheduledExecutorService scheduler;
+	private final Executor ioExecutor;
+	private final ShutdownManager shutdownManager;
+	private final DatabaseComponent db;
+	private final StreamReaderFactory streamReaderFactory;
+	private final StreamWriterFactory streamWriterFactory;
+	private final Formatter formatter;
+	private final SecretKey logKey;
+	private final AtomicBoolean handlerCreated = new AtomicBoolean(false);
+
+	@Nullable
+	private volatile SecretKey oldLogKey = null;
+
+	@Inject
+	PersistentLogManagerImpl(
+			@Scheduler ScheduledExecutorService scheduler,
+			@IoExecutor Executor ioExecutor,
+			ShutdownManager shutdownManager,
+			DatabaseComponent db,
+			StreamReaderFactory streamReaderFactory,
+			StreamWriterFactory streamWriterFactory,
+			Formatter formatter,
+			CryptoComponent crypto) {
+		this.scheduler = scheduler;
+		this.ioExecutor = ioExecutor;
+		this.shutdownManager = shutdownManager;
+		this.db = db;
+		this.streamReaderFactory = streamReaderFactory;
+		this.streamWriterFactory = streamWriterFactory;
+		this.formatter = formatter;
+		logKey = crypto.generateSecretKey();
+	}
+
+	@Override
+	public void onDatabaseOpened(Transaction txn) throws DbException {
+		Settings s = db.getSettings(txn, LOG_SETTINGS_NAMESPACE);
+		// Load the old log key, if any
+		byte[] oldKeyBytes = s.getBytes(LOG_KEY_KEY);
+		if (oldKeyBytes != null && oldKeyBytes.length == SecretKey.LENGTH) {
+			LOG.info("Loaded old log key");
+			oldLogKey = new SecretKey(oldKeyBytes);
+		}
+		// Store the current log key
+		s.putBytes(LOG_KEY_KEY, logKey.getBytes());
+		db.mergeSettings(txn, s, LOG_SETTINGS_NAMESPACE);
+	}
+
+	@Override
+	public Handler createLogHandler(File dir) throws IOException {
+		if (handlerCreated.getAndSet(true)) throw new IllegalStateException();
+		File logFile = new File(dir, LOG_FILE);
+		File oldLogFile = new File(dir, OLD_LOG_FILE);
+		if (oldLogFile.exists() && !oldLogFile.delete())
+			LOG.warning("Failed to delete old log file");
+		if (logFile.exists() && !logFile.renameTo(oldLogFile))
+			LOG.warning("Failed to rename log file");
+		try {
+			OutputStream out = new FileOutputStream(logFile);
+			StreamWriter writer =
+					streamWriterFactory.createLogStreamWriter(out, logKey);
+			StreamHandler handler = new FlushingStreamHandler(scheduler,
+					ioExecutor, writer.getOutputStream(), formatter);
+			// Flush the log and terminate the stream at shutdown
+			shutdownManager.addShutdownHook(() -> {
+				LOG.info("Shutting down");
+				handler.flush();
+				try {
+					writer.sendEndOfStream();
+				} catch (IOException e) {
+					logException(LOG, WARNING, e);
+				}
+			});
+			return handler;
+		} catch (SecurityException e) {
+			throw new IOException(e);
+		}
+	}
+
+	@Override
+	public List<String> getPersistedLog(File dir, boolean old)
+			throws IOException {
+		if (old) {
+			SecretKey oldLogKey = this.oldLogKey;
+			if (oldLogKey == null) {
+				LOG.info("Old log key has not been loaded");
+				return emptyList();
+			}
+			return getPersistedLog(new File(dir, OLD_LOG_FILE), oldLogKey);
+		} else {
+			return getPersistedLog(new File(dir, LOG_FILE), logKey);
+		}
+	}
+
+	private List<String> getPersistedLog(File logFile, SecretKey key)
+			throws IOException {
+		if (logFile.exists()) {
+			LOG.info("Reading log file");
+			LinkedList<String> lines = new LinkedList<>();
+			int numLines = 0;
+			InputStream in = new FileInputStream(logFile);
+			//noinspection TryFinallyCanBeTryWithResources
+			try {
+				InputStream reader = streamReaderFactory
+						.createLogStreamReader(in, key);
+				Scanner s = new Scanner(reader);
+				while (s.hasNextLine()) {
+					lines.add(s.nextLine());
+					if (numLines == MAX_LINES_TO_RETURN) lines.poll();
+					else numLines++;
+				}
+				s.close();
+				return lines;
+			} finally {
+				in.close();
+			}
+		} else {
+			LOG.info("Log file does not exist");
+			return emptyList();
+		}
+	}
+}