Skip to content

Commit

Permalink
Update logging to be size-limited and more performant.
Browse files Browse the repository at this point in the history
  • Loading branch information
@greyson-signal
greyson-signal committed Jul 23, 2021
1 parent 3c748b2 commit 15a5f59
Show file tree
Hide file tree
Showing 18 changed files with 251 additions and 165 deletions.
6 changes: 5 additions & 1 deletion app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java
View file
Expand Up @@ -18,6 +18,7 @@

import android.content.Context;
import android.os.Build;
import android.os.SystemClock;

import androidx.annotation.NonNull;
import androidx.annotation.Nullable;
Expand All @@ -37,6 +38,7 @@
import org.signal.ringrtc.CallManager;
import org.thoughtcrime.securesms.avatar.AvatarPickerStorage;
import org.thoughtcrime.securesms.database.DatabaseFactory;
import org.thoughtcrime.securesms.database.LogDatabase;
import org.thoughtcrime.securesms.database.SqlCipherLibraryLoader;
import org.thoughtcrime.securesms.database.helpers.SQLCipherOpenHelper;
import org.thoughtcrime.securesms.dependencies.ApplicationDependencies;
Expand Down Expand Up @@ -246,10 +248,12 @@ private void initializeSecurityProvider() {
}

private void initializeLogging() {
persistentLogger = new PersistentLogger(this, TimeUnit.DAYS.toMillis(2));
persistentLogger = new PersistentLogger(this);
org.signal.core.util.logging.Log.initialize(FeatureFlags::internalUser, new AndroidLogger(), persistentLogger);

SignalProtocolLoggerProvider.setProvider(new CustomSignalProtocolLogger());

SignalExecutors.UNBOUNDED.execute(() -> LogDatabase.getInstance(this).trimToSize());
}

private void initializeCrashHandling() {
Expand Down
100 changes: 90 additions & 10 deletions app/src/main/java/org/thoughtcrime/securesms/database/LogDatabase.kt
View file
Expand Up @@ -10,14 +10,18 @@ import org.signal.core.util.logging.Log
import org.thoughtcrime.securesms.crypto.DatabaseSecret
import org.thoughtcrime.securesms.crypto.DatabaseSecretProvider
import org.thoughtcrime.securesms.database.model.LogEntry
import org.thoughtcrime.securesms.util.ByteUnit
import org.thoughtcrime.securesms.util.CursorUtil
import org.thoughtcrime.securesms.util.SqlUtil
import org.thoughtcrime.securesms.util.Stopwatch
import java.io.Closeable
import java.util.concurrent.TimeUnit

/**
* Stores logs.
*
* Logs are very performance-critical, particularly inserts and deleting old entries.
* Logs are very performance critical. Even though this database is written to on a low-priority background thread, we want to keep throughput high and ensure
* that we aren't creating excess garbage.
*
* This is it's own separate physical database, so it cannot do joins or queries with any other
* tables.
Expand All @@ -38,28 +42,33 @@ class LogDatabase private constructor(
companion object {
private val TAG = Log.tag(LogDatabase::class.java)

private const val DATABASE_VERSION = 1
private val MAX_FILE_SIZE = ByteUnit.MEGABYTES.toBytes(10)
private val DEFAULT_LIFESPAN = TimeUnit.DAYS.toMillis(2)
private val LONGER_LIFESPAN = TimeUnit.DAYS.toMillis(7)

private const val DATABASE_VERSION = 2
private const val DATABASE_NAME = "signal-logs.db"

private const val TABLE_NAME = "log"
private const val ID = "_id"
private const val CREATED_AT = "created_at"
private const val EXPIRES_AT = "expires_at"
private const val KEEP_LONGER = "keep_longer"
private const val BODY = "body"
private const val SIZE = "size"

private val CREATE_TABLE = """
CREATE TABLE $TABLE_NAME (
$ID INTEGER PRIMARY KEY,
$CREATED_AT INTEGER,
$EXPIRES_AT INTEGER,
$BODY TEXT,
$KEEP_LONGER INTEGER DEFAULT 0,
$BODY TEXT,
$SIZE INTEGER
)
""".trimIndent()

private val CREATE_INDEXES = arrayOf(
"CREATE INDEX log_expires_at_index ON $TABLE_NAME ($EXPIRES_AT)"
"CREATE INDEX keep_longer_index ON $TABLE_NAME ($KEEP_LONGER)",
"CREATE INDEX log_created_at_keep_longer_index ON $TABLE_NAME ($CREATED_AT, $KEEP_LONGER)"
)

@SuppressLint("StaticFieldLeak") // We hold an Application context, not a view context
Expand Down Expand Up @@ -88,6 +97,13 @@ class LogDatabase private constructor(

override fun onUpgrade(db: SQLiteDatabase, oldVersion: Int, newVersion: Int) {
Log.i(TAG, "onUpgrade($oldVersion, $newVersion)")

if (oldVersion < 2) {
db.execSQL("DROP TABLE log")
db.execSQL("CREATE TABLE log (_id INTEGER PRIMARY KEY, created_at INTEGER, keep_longer INTEGER DEFAULT 0, body TEXT, size INTEGER)")
db.execSQL("CREATE INDEX keep_longer_index ON $TABLE_NAME ($KEEP_LONGER)")
db.execSQL("CREATE INDEX log_created_at_keep_longer_index ON $TABLE_NAME ($CREATED_AT, $KEEP_LONGER)")
}
}

override fun getSqlCipherDatabase(): SQLiteDatabase {
Expand All @@ -102,15 +118,21 @@ class LogDatabase private constructor(
logs.forEach { log ->
db.insert(TABLE_NAME, null, buildValues(log))
}
db.delete(TABLE_NAME, "$EXPIRES_AT < ?", SqlUtil.buildArgs(currentTime))

db.delete(
TABLE_NAME,
"($CREATED_AT < ? AND $KEEP_LONGER = ?) OR ($CREATED_AT < ? AND $KEEP_LONGER = ?)",
SqlUtil.buildArgs(currentTime - DEFAULT_LIFESPAN, 0, currentTime - LONGER_LIFESPAN, 1)
)

db.setTransactionSuccessful()
} finally {
db.endTransaction()
}
}

fun getAllBeforeTime(time: Long): Reader {
return Reader(readableDatabase.query(TABLE_NAME, arrayOf(BODY), "$CREATED_AT < ?", SqlUtil.buildArgs(time), null, null, null))
return CursorReader(readableDatabase.query(TABLE_NAME, arrayOf(BODY), "$CREATED_AT < ?", SqlUtil.buildArgs(time), null, null, null))
}

fun getRangeBeforeTime(start: Int, length: Int, time: Long): List<String> {
Expand All @@ -125,6 +147,52 @@ class LogDatabase private constructor(
return lines
}

fun trimToSize() {
val currentTime = System.currentTimeMillis()
val stopwatch = Stopwatch("trim")

val sizeOfSpecialLogs: Long = getSize("$KEEP_LONGER = ?", arrayOf("1"))
val remainingSize = MAX_FILE_SIZE - sizeOfSpecialLogs

stopwatch.split("keepers-size")

if (remainingSize <= 0) {
writableDatabase.delete(TABLE_NAME, "$KEEP_LONGER = ?", arrayOf("0"))
return
}

val sizeDiffThreshold = MAX_FILE_SIZE * 0.01

var lhs: Long = currentTime - DEFAULT_LIFESPAN
var rhs: Long = currentTime
var mid: Long = 0
var sizeOfChunk: Long

while (lhs < rhs - 2) {
mid = (lhs + rhs) / 2
sizeOfChunk = getSize("$CREATED_AT > ? AND $CREATED_AT < ? AND $KEEP_LONGER = ?", SqlUtil.buildArgs(mid, currentTime, 0))

if (sizeOfChunk > remainingSize) {
lhs = mid
} else if (sizeOfChunk < remainingSize) {
if (remainingSize - sizeOfChunk < sizeDiffThreshold) {
break
} else {
rhs = mid
}
} else {
break
}
}

stopwatch.split("binary-search")

writableDatabase.delete(TABLE_NAME, "$CREATED_AT < ? AND $KEEP_LONGER = ?", SqlUtil.buildArgs(mid, 0))

stopwatch.split("delete")
stopwatch.stop(TAG)
}

fun getLogCountBeforeTime(time: Long): Int {
readableDatabase.query(TABLE_NAME, arrayOf("COUNT(*)"), "$CREATED_AT < ?", SqlUtil.buildArgs(time), null, null, null).use { cursor ->
return if (cursor.moveToFirst()) {
Expand All @@ -138,19 +206,31 @@ class LogDatabase private constructor(
private fun buildValues(log: LogEntry): ContentValues {
return ContentValues().apply {
put(CREATED_AT, log.createdAt)
put(EXPIRES_AT, log.createdAt + log.lifespan)
put(KEEP_LONGER, if (log.keepLonger) 1 else 0)
put(BODY, log.body)
put(SIZE, log.body.length)
}
}

private fun getSize(query: String?, args: Array<String>?): Long {
readableDatabase.query(TABLE_NAME, arrayOf("SUM($SIZE)"), query, args, null, null, null).use { cursor ->
return if (cursor.moveToFirst()) {
cursor.getLong(0)
} else {
0
}
}
}

private val readableDatabase: SQLiteDatabase
get() = getReadableDatabase(databaseSecret.asString())

private val writableDatabase: SQLiteDatabase
get() = getWritableDatabase(databaseSecret.asString())

class Reader(private val cursor: Cursor) : Iterator<String>, Closeable {
interface Reader : Iterator<String>, Closeable

class CursorReader(private val cursor: Cursor) : Reader {
override fun hasNext(): Boolean {
return !cursor.isLast && cursor.count > 0
}
Expand Down
36 changes: 17 additions & 19 deletions app/src/main/java/org/thoughtcrime/securesms/database/RecipientDatabase.java
View file
Expand Up @@ -156,8 +156,6 @@ public class RecipientDatabase extends Database {
private static final String IDENTITY_STATUS = "identity_status";
private static final String IDENTITY_KEY = "identity_key";

static final long IMPORTANT_LOG_DURATION = TimeUnit.DAYS.toMillis(7);

/**
* Values that represent the index in the capabilities bitmask. Each index can store a 2-bit
* value, which in this case is the value of {@link Recipient.Capability}.
Expand Down Expand Up @@ -440,7 +438,7 @@ Optional<RecipientId> getByUsername(@NonNull String username) {
RecipientId finalId;

if (!byE164.isPresent() && !byUuid.isPresent()) {
Log.i(TAG, "Discovered a completely new user. Inserting.", IMPORTANT_LOG_DURATION);
Log.i(TAG, "Discovered a completely new user. Inserting.", true);
if (highTrust) {
long id = db.insert(TABLE_NAME, null, buildContentValuesForNewUser(e164, uuid));
finalId = RecipientId.from(id);
Expand All @@ -453,7 +451,7 @@ Optional<RecipientId> getByUsername(@NonNull String username) {
RecipientSettings e164Settings = getRecipientSettings(byE164.get());
if (e164Settings.uuid != null) {
if (highTrust) {
Log.w(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s), but that user already has a UUID (%s). Likely a case of re-registration. High-trust, so stripping the E164 from the existing account and assigning it to a new entry.", uuid, byE164.get(), e164Settings.uuid), IMPORTANT_LOG_DURATION);
Log.w(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s), but that user already has a UUID (%s). Likely a case of re-registration. High-trust, so stripping the E164 from the existing account and assigning it to a new entry.", uuid, byE164.get(), e164Settings.uuid), true);

removePhoneNumber(byE164.get(), db);
recipientNeedingRefresh = byE164.get();
Expand All @@ -464,18 +462,18 @@ Optional<RecipientId> getByUsername(@NonNull String username) {
long id = db.insert(TABLE_NAME, null, insertValues);
finalId = RecipientId.from(id);
} else {
Log.w(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s), but that user already has a UUID (%s). Likely a case of re-registration. Low-trust, so making a new user for the UUID.", uuid, byE164.get(), e164Settings.uuid), IMPORTANT_LOG_DURATION);
Log.w(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s), but that user already has a UUID (%s). Likely a case of re-registration. Low-trust, so making a new user for the UUID.", uuid, byE164.get(), e164Settings.uuid), true);

long id = db.insert(TABLE_NAME, null, buildContentValuesForNewUser(null, uuid));
finalId = RecipientId.from(id);
}
} else {
if (highTrust) {
Log.i(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s). High-trust, so updating.", uuid, byE164.get()), IMPORTANT_LOG_DURATION);
Log.i(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s). High-trust, so updating.", uuid, byE164.get()), true);
markRegisteredOrThrow(byE164.get(), uuid);
finalId = byE164.get();
} else {
Log.i(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s). Low-trust, so making a new user for the UUID.", uuid, byE164.get()), IMPORTANT_LOG_DURATION);
Log.i(TAG, String.format(Locale.US, "Found out about a UUID (%s) for a known E164 user (%s). Low-trust, so making a new user for the UUID.", uuid, byE164.get()), true);
long id = db.insert(TABLE_NAME, null, buildContentValuesForNewUser(null, uuid));
finalId = RecipientId.from(id);
}
Expand All @@ -486,11 +484,11 @@ Optional<RecipientId> getByUsername(@NonNull String username) {
} else if (!byE164.isPresent() && byUuid.isPresent()) {
if (e164 != null) {
if (highTrust) {
Log.i(TAG, String.format(Locale.US, "Found out about an E164 (%s) for a known UUID user (%s). High-trust, so updating.", e164, byUuid.get()), IMPORTANT_LOG_DURATION);
Log.i(TAG, String.format(Locale.US, "Found out about an E164 (%s) for a known UUID user (%s). High-trust, so updating.", e164, byUuid.get()), true);
setPhoneNumberOrThrow(byUuid.get(), e164);
finalId = byUuid.get();
} else {
Log.i(TAG, String.format(Locale.US, "Found out about an E164 (%s) for a known UUID user (%s). Low-trust, so doing nothing.", e164, byUuid.get()), IMPORTANT_LOG_DURATION);
Log.i(TAG, String.format(Locale.US, "Found out about an E164 (%s) for a known UUID user (%s). Low-trust, so doing nothing.", e164, byUuid.get()), true);
finalId = byUuid.get();
}
} else {
Expand All @@ -500,13 +498,13 @@ Optional<RecipientId> getByUsername(@NonNull String username) {
if (byE164.equals(byUuid)) {
finalId = byUuid.get();
} else {
Log.w(TAG, String.format(Locale.US, "Hit a conflict between %s (E164 of %s) and %s (UUID %s). They map to different recipients.", byE164.get(), e164, byUuid.get(), uuid), new Throwable(), IMPORTANT_LOG_DURATION);
Log.w(TAG, String.format(Locale.US, "Hit a conflict between %s (E164 of %s) and %s (UUID %s). They map to different recipients.", byE164.get(), e164, byUuid.get(), uuid), new Throwable(), true);

RecipientSettings e164Settings = getRecipientSettings(byE164.get());

if (e164Settings.getUuid() != null) {
if (highTrust) {
Log.w(TAG, "The E164 contact has a different UUID. Likely a case of re-registration. High-trust, so stripping the E164 from the existing account and assigning it to the UUID entry.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "The E164 contact has a different UUID. Likely a case of re-registration. High-trust, so stripping the E164 from the existing account and assigning it to the UUID entry.", true);

removePhoneNumber(byE164.get(), db);
recipientNeedingRefresh = byE164.get();
Expand All @@ -515,17 +513,17 @@ Optional<RecipientId> getByUsername(@NonNull String username) {

finalId = byUuid.get();
} else {
Log.w(TAG, "The E164 contact has a different UUID. Likely a case of re-registration. Low-trust, so doing nothing.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "The E164 contact has a different UUID. Likely a case of re-registration. Low-trust, so doing nothing.", true);
finalId = byUuid.get();
}
} else {
if (highTrust) {
Log.w(TAG, "We have one contact with just an E164, and another with UUID. High-trust, so merging the two rows together.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "We have one contact with just an E164, and another with UUID. High-trust, so merging the two rows together.", true);
finalId = merge(byUuid.get(), byE164.get());
recipientNeedingRefresh = byUuid.get();
remapped = new Pair<>(byE164.get(), byUuid.get());
} else {
Log.w(TAG, "We have one contact with just an E164, and another with UUID. Low-trust, so doing nothing.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "We have one contact with just an E164, and another with UUID. Low-trust, so doing nothing.", true);
finalId = byUuid.get();
}
}
Expand Down Expand Up @@ -2881,7 +2879,7 @@ Optional<RecipientId> getByColumn(@NonNull String column, String value) {
RecipientSettings e164Settings = getRecipientSettings(byE164);

// Recipient
Log.w(TAG, "Deleting recipient " + byE164, IMPORTANT_LOG_DURATION);
Log.w(TAG, "Deleting recipient " + byE164, true);
db.delete(TABLE_NAME, ID_WHERE, SqlUtil.buildArgs(byE164));
RemappedRecords.getInstance().addRecipient(context, byE164, byUuid);

Expand Down Expand Up @@ -2966,17 +2964,17 @@ Optional<RecipientId> getByColumn(@NonNull String column, String value) {
boolean hasUuidSession = DatabaseFactory.getSessionDatabase(context).getAllFor(byUuid).size() > 0;

if (hasE164Session && hasUuidSession) {
Log.w(TAG, "Had a session for both users. Deleting the E164.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "Had a session for both users. Deleting the E164.", true);
db.delete(SessionDatabase.TABLE_NAME, SessionDatabase.RECIPIENT_ID + " = ?", SqlUtil.buildArgs(byE164));
} else if (hasE164Session && !hasUuidSession) {
Log.w(TAG, "Had a session for E164, but not UUID. Re-assigning to the UUID.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "Had a session for E164, but not UUID. Re-assigning to the UUID.", true);
ContentValues values = new ContentValues();
values.put(SessionDatabase.RECIPIENT_ID, byUuid.serialize());
db.update(SessionDatabase.TABLE_NAME, values, SessionDatabase.RECIPIENT_ID + " = ?", SqlUtil.buildArgs(byE164));
} else if (!hasE164Session && hasUuidSession) {
Log.w(TAG, "Had a session for UUID, but not E164. No action necessary.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "Had a session for UUID, but not E164. No action necessary.", true);
} else {
Log.w(TAG, "Had no sessions. No action necessary.", IMPORTANT_LOG_DURATION);
Log.w(TAG, "Had no sessions. No action necessary.", true);
}

// Mentions
Expand Down
8 changes: 4 additions & 4 deletions app/src/main/java/org/thoughtcrime/securesms/database/ThreadDatabase.java
View file
Expand Up @@ -1276,16 +1276,16 @@ public boolean update(long threadId, boolean unarchive, boolean allowDeletion) {
throw new IllegalStateException("Must be in a transaction!");
}

Log.w(TAG, "Merging threads. Primary: " + primaryRecipientId + ", Secondary: " + secondaryRecipientId, RecipientDatabase.IMPORTANT_LOG_DURATION);
Log.w(TAG, "Merging threads. Primary: " + primaryRecipientId + ", Secondary: " + secondaryRecipientId, true);

ThreadRecord primary = getThreadRecord(getThreadIdFor(primaryRecipientId));
ThreadRecord secondary = getThreadRecord(getThreadIdFor(secondaryRecipientId));

if (primary != null && secondary == null) {
Log.w(TAG, "[merge] Only had a thread for primary. Returning that.", RecipientDatabase.IMPORTANT_LOG_DURATION);
Log.w(TAG, "[merge] Only had a thread for primary. Returning that.", true);
return new MergeResult(primary.getThreadId(), -1, false);
} else if (primary == null && secondary != null) {
Log.w(TAG, "[merge] Only had a thread for secondary. Updating it to have the recipientId of the primary.", RecipientDatabase.IMPORTANT_LOG_DURATION);
Log.w(TAG, "[merge] Only had a thread for secondary. Updating it to have the recipientId of the primary.", true);

ContentValues values = new ContentValues();
values.put(RECIPIENT_ID, primaryRecipientId.serialize());
Expand All @@ -1296,7 +1296,7 @@ public boolean update(long threadId, boolean unarchive, boolean allowDeletion) {
Log.w(TAG, "[merge] No thread for either.");
return new MergeResult(-1, -1, false);
} else {
Log.w(TAG, "[merge] Had a thread for both. Deleting the secondary and merging the attributes together.", RecipientDatabase.IMPORTANT_LOG_DURATION);
Log.w(TAG, "[merge] Had a thread for both. Deleting the secondary and merging the attributes together.", true);

SQLiteDatabase db = databaseHelper.getWritableDatabase();

Expand Down
2 changes: 1 addition & 1 deletion app/src/main/java/org/thoughtcrime/securesms/database/model/LogEntry.kt
View file
Expand Up @@ -2,6 +2,6 @@ package org.thoughtcrime.securesms.database.model

data class LogEntry(
val createdAt: Long,
val lifespan: Long,
val keepLonger: Boolean,
val body: String
)

0 comments on commit 15a5f59

Please sign in to comment.