Signal/Android
1
0
Fork 0
mirror of https://github.com/signalapp/Signal-Android.git synced 2026-04-21 00:59:49 +01:00
Code Issues Packages Projects Releases Wiki Activity

Update logging to be size-limited and more performant.

Browse Source
This commit is contained in:
Greyson Parrelli
2021-07-23 07:39:16 -04:00
parent 3c748b2df6
commit 15a5f5966d
18 changed files with 253 additions and 167 deletions
Download Patch File Download Diff File Expand all files Collapse all files

100
app/src/main/java/org/thoughtcrime/securesms/database/LogDatabase.kt
View File

@@ -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.
@@ -38,13 +42,17 @@ 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"
@@ -52,14 +60,15 @@ class LogDatabase private constructor(
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
@@ -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 {
@@ -102,7 +118,13 @@ 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()
@@ -110,7 +132,7 @@ class LogDatabase private constructor(
}
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> {
@@ -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()) {
@@ -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
}

36
app/src/main/java/org/thoughtcrime/securesms/database/RecipientDatabase.java
View File

@@ -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}.
@@ -440,7 +438,7 @@ public class RecipientDatabase extends Database {
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);
@@ -453,7 +451,7 @@ public class RecipientDatabase extends Database {
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();
@@ -464,18 +462,18 @@ public class RecipientDatabase extends Database {
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);
}
@@ -486,11 +484,11 @@ public class RecipientDatabase extends Database {
} 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 {
@@ -500,13 +498,13 @@ public class RecipientDatabase extends Database {
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();
@@ -515,17 +513,17 @@ public class RecipientDatabase extends Database {
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();
}
}
@@ -2881,7 +2879,7 @@ public class RecipientDatabase extends Database {
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);
@@ -2966,17 +2964,17 @@ public class RecipientDatabase extends Database {
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

8
app/src/main/java/org/thoughtcrime/securesms/database/ThreadDatabase.java
View File

@@ -1276,16 +1276,16 @@ public class ThreadDatabase extends Database {
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());
@@ -1296,7 +1296,7 @@ public class ThreadDatabase extends Database {
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();

2
app/src/main/java/org/thoughtcrime/securesms/database/model/LogEntry.kt
View File

@@ -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
)