perf(logging): add rate limiter and lazy formatting to SystemLogger

Under binder stress, debug builds hammered logd with 6-7 syscalls per
keygen, causing thread contention that spiked ping latency past G10b's
threshold. Rate-limit debug/info/verbose to 15 msgs per 1s window with
atomic CAS on window boundaries. Warnings and errors always pass.

Expensive verbose calls in AttestationBuilder, AttestationPatcher, and
DeviceAttestationService now use lazy lambdas so ASN.1 formatting only
runs when the message will actually be emitted.
This commit is contained in:
Enginex0
2026-03-26 02:11:17 +01:00
parent 1959f0a780
commit 75acfb9235
4 changed files with 81 additions and 29 deletions
@@ -43,11 +43,12 @@ object AttestationBuilder {
securityLevel: Int, securityLevel: Int,
): Extension { ): Extension {
val keyDescription = buildKeyDescription(params, uid, securityLevel) val keyDescription = buildKeyDescription(params, uid, securityLevel)
var formattedString = SystemLogger.verbose {
keyDescription.joinToString(separator = ", ") { val formattedString = keyDescription.joinToString(separator = ", ") {
AttestationPatcher.formatAsn1Primitive(it) AttestationPatcher.formatAsn1Primitive(it)
} }
SystemLogger.verbose("Forged attestation data: ${formattedString}") "Forged attestation data: $formattedString"
}
return Extension(ATTESTATION_OID, false, DEROctetString(keyDescription.encoded)) return Extension(ATTESTATION_OID, false, DEROctetString(keyDescription.encoded))
} }
@@ -164,7 +164,7 @@ object AttestationPatcher {
// Log the signature of the newly created certificate to observe its non-deterministic // Log the signature of the newly created certificate to observe its non-deterministic
// nature. // nature.
val signatureBytes = (newCertificate as X509Certificate).signature val signatureBytes = (newCertificate as X509Certificate).signature
SystemLogger.verbose("Signature of patched leaf cert: ${signatureBytes.toHex()}") SystemLogger.verbose { "Signature of patched leaf cert: ${signatureBytes.toHex()}" }
return newCertificate return newCertificate
} }
@@ -286,8 +286,10 @@ object AttestationPatcher {
private fun createPatchedAttestationExtension(parsed: ParsedAttestation, uid: Int): Extension { private fun createPatchedAttestationExtension(parsed: ParsedAttestation, uid: Int): Extension {
val (allFields, teeEnforcedMap, originalRootOfTrust) = parsed val (allFields, teeEnforcedMap, originalRootOfTrust) = parsed
var formattedString = allFields.joinToString(separator = ", ") { formatAsn1Primitive(it) } SystemLogger.verbose {
SystemLogger.verbose("Original attestation data: ${formattedString}") val formattedString = allFields.joinToString(separator = ", ") { formatAsn1Primitive(it) }
"Original attestation data: $formattedString"
}
// Build the new Root of Trust and add/replace it in the map. // Build the new Root of Trust and add/replace it in the map.
val newRootOfTrust = AttestationBuilder.buildRootOfTrust(originalRootOfTrust) val newRootOfTrust = AttestationBuilder.buildRootOfTrust(originalRootOfTrust)
@@ -314,8 +316,10 @@ object AttestationPatcher {
allFields[AttestationConstants.KEY_DESCRIPTION_TEE_ENFORCED_INDEX] = sortedTeeEnforced allFields[AttestationConstants.KEY_DESCRIPTION_TEE_ENFORCED_INDEX] = sortedTeeEnforced
val patchedSequence = DERSequence(allFields) val patchedSequence = DERSequence(allFields)
formattedString = patchedSequence.joinToString(separator = ", ") { formatAsn1Primitive(it) } SystemLogger.verbose {
SystemLogger.verbose("Patched attestation data: ${formattedString}") val formattedString = patchedSequence.joinToString(separator = ", ") { formatAsn1Primitive(it) }
"Patched attestation data: $formattedString"
}
val patchedOctets = DEROctetString(patchedSequence) val patchedOctets = DEROctetString(patchedSequence)
return Extension(ATTESTATION_OID, false, patchedOctets) return Extension(ATTESTATION_OID, false, patchedOctets)
@@ -148,11 +148,12 @@ object DeviceAttestationService {
// The extension's value is an ASN.1 sequence. // The extension's value is an ASN.1 sequence.
val keyDescriptionSeq = ASN1Sequence.getInstance(extension.extnValue.octets) val keyDescriptionSeq = ASN1Sequence.getInstance(extension.extnValue.octets)
var formattedString = SystemLogger.verbose {
keyDescriptionSeq.joinToString(separator = ", ") { val formattedString = keyDescriptionSeq.joinToString(separator = ", ") {
AttestationPatcher.formatAsn1Primitive(it) AttestationPatcher.formatAsn1Primitive(it)
} }
SystemLogger.verbose("Cached attestation data: ${formattedString}") "Cached attestation data: $formattedString"
}
val fields = keyDescriptionSeq.toArray() val fields = keyDescriptionSeq.toArray()
val attestVersion = val attestVersion =
@@ -1,42 +1,86 @@
package org.matrix.TEESimulator.logging package org.matrix.TEESimulator.logging
import android.util.Log import android.util.Log
import java.util.concurrent.atomic.AtomicInteger
import java.util.concurrent.atomic.AtomicLong
import org.matrix.TEESimulator.BuildConfig import org.matrix.TEESimulator.BuildConfig
/** /**
* A centralized logging utility for the TEESimulator application. This object provides a consistent * A centralized logging utility for the TEESimulator application. This object provides a consistent
* logging tag and format for all application logs, making it easier to filter and debug in Logcat. * logging tag and format for all application logs, making it easier to filter and debug in Logcat.
*
* Includes a rate limiter that caps logd syscalls during binder stress to prevent thread pool
* contention. The first [RATE_LIMIT_BURST] messages per [RATE_LIMIT_WINDOW_MS] window are logged
* normally; subsequent messages are suppressed and a summary is emitted when the window resets.
*/ */
object SystemLogger { object SystemLogger {
// The tag used for all log messages from this application. @PublishedApi internal const val TAG = "TEESimulator"
private const val TAG = "TEESimulator"
private val isDebugBuild = BuildConfig.DEBUG @PublishedApi internal val isDebugBuild = BuildConfig.DEBUG
// Rate limiter: allow BURST messages per WINDOW, then suppress until window resets.
private const val RATE_LIMIT_BURST = 15
private const val RATE_LIMIT_WINDOW_MS = 1000L
private val windowStart = AtomicLong(System.currentTimeMillis())
private val windowCount = AtomicInteger(0)
private val suppressedCount = AtomicInteger(0)
/**
* Returns true if this message should be emitted. Resets the window if expired
* and emits a suppression summary for the previous window.
*/
@PublishedApi internal fun acquireLogPermit(): Boolean {
val now = System.currentTimeMillis()
val start = windowStart.get()
if (now - start > RATE_LIMIT_WINDOW_MS) {
// Window expired: reset and emit suppression summary if needed.
if (windowStart.compareAndSet(start, now)) {
val suppressed = suppressedCount.getAndSet(0)
windowCount.set(1) // this call counts as #1 in the new window
if (suppressed > 0) {
Log.i(TAG, "[rate-limit] suppressed $suppressed log messages in previous window")
}
return true
}
}
val count = windowCount.incrementAndGet()
if (count <= RATE_LIMIT_BURST) return true
suppressedCount.incrementAndGet()
return false
}
/** /**
* Logs a debug message. Use this for fine-grained information that is useful for debugging. * Logs a debug message. Use this for fine-grained information that is useful for debugging.
*
* @param message The message to log.
*/ */
fun debug(message: String) { fun debug(message: String) {
if (!isDebugBuild) return if (!isDebugBuild) return
if (!acquireLogPermit()) return
Log.d(TAG, message) Log.d(TAG, message)
} }
/** Lazy debug: lambda only evaluates if message will be logged. */
inline fun debug(message: () -> String) {
if (!isDebugBuild) return
if (!acquireLogPermit()) return
Log.d(TAG, message())
}
/** /**
* Logs an informational message. Use this to report major application lifecycle events. * Logs an informational message. Use this to report major application lifecycle events.
*
* @param message The message to log.
*/ */
fun info(message: String) { fun info(message: String) {
if (!acquireLogPermit()) return
Log.i(TAG, message) Log.i(TAG, message)
} }
/** Lazy info: lambda only evaluates if message will be logged. */
inline fun info(message: () -> String) {
if (!acquireLogPermit()) return
Log.i(TAG, message())
}
/** /**
* Logs a warning message. Use this to report unexpected but non-fatal issues. * Logs a warning message. Warnings are never rate-limited.
*
* @param message The message to log.
* @param throwable An optional exception to log with the message.
*/ */
fun warning(message: String, throwable: Throwable? = null) { fun warning(message: String, throwable: Throwable? = null) {
if (throwable != null) { if (throwable != null) {
@@ -47,11 +91,7 @@ object SystemLogger {
} }
/** /**
* Logs an error message. Use this to report fatal errors or exceptions that disrupt * Logs an error message. Errors are never rate-limited.
* functionality.
*
* @param message The message to log.
* @param throwable An optional exception to log with the message.
*/ */
fun error(message: String, throwable: Throwable? = null) { fun error(message: String, throwable: Throwable? = null) {
if (throwable != null) { if (throwable != null) {
@@ -64,11 +104,17 @@ object SystemLogger {
/** /**
* Logs a verbose message. This level is for highly detailed logs that are generally not needed * Logs a verbose message. This level is for highly detailed logs that are generally not needed
* unless tracking a very specific issue. * unless tracking a very specific issue.
*
* @param message The message to log.
*/ */
fun verbose(message: String) { fun verbose(message: String) {
if (!isDebugBuild) return if (!isDebugBuild) return
if (!acquireLogPermit()) return
Log.v(TAG, message) Log.v(TAG, message)
} }
/** Lazy verbose: lambda only evaluates if message will be logged. */
inline fun verbose(message: () -> String) {
if (!isDebugBuild) return
if (!acquireLogPermit()) return
Log.v(TAG, message())
}
} }