From 6a974c48ef9cdacd505fe253b893051ccc879305 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Mon, 25 Sep 2023 09:24:42 -0400 Subject: [PATCH] Add a log viewer to Spinner. This is more of a proof-of-concept/demo for using a websocket with Spinner. Gives an example of how we could push live updates to the webapp. Also, the logger is actually nice. Guaranteed to never get cluttered with system logs. Looks basically identical to our other log viewers. Filtering is basic but fast. And we could build much better tooling on top of this. --- ...SignalInstrumentationApplicationContext.kt | 4 +- .../securesms/ApplicationContext.java | 10 +- .../securesms/SpinnerApplicationContext.kt | 7 + dependencies.gradle | 4 +- gradle/verification-metadata.xml | 5 + .../org/signal/spinnertest/MainActivity.kt | 25 ++ .../app/src/main/res/layout/activity_main.xml | 6 + spinner/lib/build.gradle | 1 + spinner/lib/src/main/assets/css/main.css | 2 +- spinner/lib/src/main/assets/logs.hbs | 290 ++++++++++++++++++ .../lib/src/main/assets/partials/prefix.hbs | 1 + .../main/java/org/signal/spinner/Spinner.kt | 4 + .../java/org/signal/spinner/SpinnerLogItem.kt | 55 ++++ .../org/signal/spinner/SpinnerLogWebSocket.kt | 96 ++++++ .../java/org/signal/spinner/SpinnerLogger.kt | 98 ++++++ .../java/org/signal/spinner/SpinnerServer.kt | 54 +++- 16 files changed, 647 insertions(+), 15 deletions(-) create mode 100644 spinner/lib/src/main/assets/logs.hbs create mode 100644 spinner/lib/src/main/java/org/signal/spinner/SpinnerLogItem.kt create mode 100644 spinner/lib/src/main/java/org/signal/spinner/SpinnerLogWebSocket.kt create mode 100644 spinner/lib/src/main/java/org/signal/spinner/SpinnerLogger.kt diff --git a/app/src/androidTest/java/org/thoughtcrime/securesms/SignalInstrumentationApplicationContext.kt b/app/src/androidTest/java/org/thoughtcrime/securesms/SignalInstrumentationApplicationContext.kt index b4689f72e6..49f7c3078b 100644 --- a/app/src/androidTest/java/org/thoughtcrime/securesms/SignalInstrumentationApplicationContext.kt +++ b/app/src/androidTest/java/org/thoughtcrime/securesms/SignalInstrumentationApplicationContext.kt @@ -26,9 +26,7 @@ class SignalInstrumentationApplicationContext : ApplicationContext() { } override fun initializeLogging() { - persistentLogger = PersistentLogger(this) - - Log.initialize({ true }, AndroidLogger(), persistentLogger, inMemoryLogger) + Log.initialize({ true }, AndroidLogger(), PersistentLogger(this), inMemoryLogger) SignalProtocolLoggerProvider.setProvider(CustomSignalProtocolLogger()) diff --git a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java index f2c550b636..0e1e20afda 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java +++ b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java @@ -124,9 +124,6 @@ public class ApplicationContext extends MultiDexApplication implements AppForegr private static final String TAG = Log.tag(ApplicationContext.class); - @VisibleForTesting - protected PersistentLogger persistentLogger; - public static ApplicationContext getInstance(Context context) { return (ApplicationContext)context.getApplicationContext(); } @@ -265,10 +262,6 @@ public class ApplicationContext extends MultiDexApplication implements AppForegr MemoryTracker.stop(); } - public PersistentLogger getPersistentLogger() { - return persistentLogger; - } - public void checkBuildExpiration() { if (Util.getTimeUntilBuildExpiry() <= 0 && !SignalStore.misc().isClientDeprecated()) { Log.w(TAG, "Build expired!"); @@ -295,8 +288,7 @@ public class ApplicationContext extends MultiDexApplication implements AppForegr @VisibleForTesting protected void initializeLogging() { - persistentLogger = new PersistentLogger(this); - org.signal.core.util.logging.Log.initialize(FeatureFlags::internalUser, new AndroidLogger(), persistentLogger); + org.signal.core.util.logging.Log.initialize(FeatureFlags::internalUser, new AndroidLogger(), new PersistentLogger(this)); SignalProtocolLoggerProvider.setProvider(new CustomSignalProtocolLogger()); diff --git a/app/src/spinner/java/org/thoughtcrime/securesms/SpinnerApplicationContext.kt b/app/src/spinner/java/org/thoughtcrime/securesms/SpinnerApplicationContext.kt index 55de359079..1000f5b0f9 100644 --- a/app/src/spinner/java/org/thoughtcrime/securesms/SpinnerApplicationContext.kt +++ b/app/src/spinner/java/org/thoughtcrime/securesms/SpinnerApplicationContext.kt @@ -2,8 +2,11 @@ package org.thoughtcrime.securesms import android.content.ContentValues import android.os.Build +import org.signal.core.util.logging.AndroidLogger +import org.signal.core.util.logging.Log import org.signal.spinner.Spinner import org.signal.spinner.Spinner.DatabaseConfig +import org.signal.spinner.SpinnerLogger import org.thoughtcrime.securesms.database.DatabaseMonitor import org.thoughtcrime.securesms.database.GV2Transformer import org.thoughtcrime.securesms.database.GV2UpdateTransformer @@ -22,8 +25,10 @@ import org.thoughtcrime.securesms.database.RecipientTransformer import org.thoughtcrime.securesms.database.SignalDatabase import org.thoughtcrime.securesms.database.TimestampTransformer import org.thoughtcrime.securesms.keyvalue.SignalStore +import org.thoughtcrime.securesms.logging.PersistentLogger import org.thoughtcrime.securesms.recipients.Recipient import org.thoughtcrime.securesms.util.AppSignatureUtil +import org.thoughtcrime.securesms.util.FeatureFlags import java.util.Locale class SpinnerApplicationContext : ApplicationContext() { @@ -69,6 +74,8 @@ class SpinnerApplicationContext : ApplicationContext() { ) ) + Log.initialize({ FeatureFlags.internalUser() }, AndroidLogger(), PersistentLogger(this), SpinnerLogger()) + DatabaseMonitor.initialize(object : QueryMonitor { override fun onSql(sql: String, args: Array?) { Spinner.onSql("signal", sql, args) diff --git a/dependencies.gradle b/dependencies.gradle index c6ab2085aa..a819aeeea3 100644 --- a/dependencies.gradle +++ b/dependencies.gradle @@ -19,6 +19,7 @@ dependencyResolutionManagement { version('mp4parser', '1.9.39') version('android-gradle-plugin', '8.0.2') version('accompanist', '0.28.0') + version('nanohttpd', '2.3.1') // Android Plugins library('android-library', 'com.android.library', 'com.android.library.gradle.plugin').versionRef('android-gradle-plugin') @@ -144,7 +145,8 @@ dependencyResolutionManagement { library('stream', 'com.annimon:stream:1.1.8') library('lottie', 'com.airbnb.android:lottie:5.2.0') library('dnsjava', 'dnsjava:dnsjava:2.1.9') - library('nanohttpd-webserver', 'org.nanohttpd:nanohttpd-webserver:2.3.1') + library('nanohttpd-webserver', 'org.nanohttpd', 'nanohttpd-webserver').versionRef('nanohttpd') + library('nanohttpd-websocket', 'org.nanohttpd', 'nanohttpd-websocket').versionRef('nanohttpd') library('kotlinx-collections-immutable', 'org.jetbrains.kotlinx:kotlinx-collections-immutable:0.3.5') // Can't use the newest version because it hits some weird NoClassDefFoundException diff --git a/gradle/verification-metadata.xml b/gradle/verification-metadata.xml index a483a67e52..25e7a98035 100644 --- a/gradle/verification-metadata.xml +++ b/gradle/verification-metadata.xml @@ -5135,6 +5135,11 @@ https://docs.gradle.org/current/userguide/dependency_verification.html + + + + + diff --git a/spinner/app/src/main/java/org/signal/spinnertest/MainActivity.kt b/spinner/app/src/main/java/org/signal/spinnertest/MainActivity.kt index e0fdcceb8a..981f368009 100644 --- a/spinner/app/src/main/java/org/signal/spinnertest/MainActivity.kt +++ b/spinner/app/src/main/java/org/signal/spinnertest/MainActivity.kt @@ -3,10 +3,16 @@ package org.signal.spinnertest import android.database.sqlite.SQLiteDatabase import android.os.Build import android.os.Bundle +import android.widget.Button import androidx.appcompat.app.AppCompatActivity import androidx.core.content.contentValuesOf +import org.signal.core.util.ThreadUtil +import org.signal.core.util.logging.AndroidLogger +import org.signal.core.util.logging.Log import org.signal.spinner.Spinner +import org.signal.spinner.SpinnerLogger import java.util.UUID +import kotlin.random.Random class MainActivity : AppCompatActivity() { override fun onCreate(savedInstanceState: Bundle?) { @@ -26,6 +32,25 @@ class MainActivity : AppCompatActivity() { mapOf("main" to Spinner.DatabaseConfig(db = { db })), emptyMap() ) + + Log.initialize(AndroidLogger(), SpinnerLogger()) + + object : Thread() { + override fun run() { + while (true) { + when (Random.nextInt(0, 5)) { + 0 -> Log.v("MyTag", "Message: ${System.currentTimeMillis()}") + 1 -> Log.d("MyTag", "Message: ${System.currentTimeMillis()}") + 2 -> Log.i("MyTag", "Message: ${System.currentTimeMillis()}") + 3 -> Log.w("MyTag", "Message: ${System.currentTimeMillis()}") + 4 -> Log.e("MyTag", "Message: ${System.currentTimeMillis()}") + } + ThreadUtil.sleep(Random.nextLong(0, 200)) + } + } + }.start() + + findViewById + +
+ + +
+ + + {{> partials/suffix }} + + + + diff --git a/spinner/lib/src/main/assets/partials/prefix.hbs b/spinner/lib/src/main/assets/partials/prefix.hbs index fbc0f2eff2..69c93c49c1 100644 --- a/spinner/lib/src/main/assets/partials/prefix.hbs +++ b/spinner/lib/src/main/assets/partials/prefix.hbs @@ -23,6 +23,7 @@
  • Browse
  • Query
  • Recent
    • +
  • Logs
    • {{#each plugins}}
  • {{name}}
    • {{/each}} diff --git a/spinner/lib/src/main/java/org/signal/spinner/Spinner.kt b/spinner/lib/src/main/java/org/signal/spinner/Spinner.kt index ff7a0f5165..d28fc91e76 100644 --- a/spinner/lib/src/main/java/org/signal/spinner/Spinner.kt +++ b/spinner/lib/src/main/java/org/signal/spinner/Spinner.kt @@ -68,6 +68,10 @@ object Spinner { server.onSql(dbName, queryString) } + internal fun log(item: SpinnerLogItem) { + server.onLog(item) + } + private fun replaceQueryArgs(query: String, args: Array?): String { if (args == null) { return query diff --git a/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogItem.kt b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogItem.kt new file mode 100644 index 0000000000..e6fa198dd9 --- /dev/null +++ b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogItem.kt @@ -0,0 +1,55 @@ +/* + * Copyright 2023 Signal Messenger, LLC + * SPDX-License-Identifier: AGPL-3.0-only + */ + +package org.signal.spinner + +import android.util.Log +import org.json.JSONObject +import org.signal.core.util.ExceptionUtil +import java.text.SimpleDateFormat +import java.util.Date +import java.util.Locale + +internal data class SpinnerLogItem( + val level: Int, + val time: Long, + val thread: String, + val tag: String, + val message: String?, + val throwable: Throwable? +) { + fun serialize(): String { + val stackTrace: String? = throwable?.let { ExceptionUtil.convertThrowableToString(throwable) } + val formattedTime = dateFormat.format(Date(time)) + val paddedTag: String = when { + tag.length > 23 -> tag.substring(0, 23) + tag.length < 23 -> tag.padEnd(23) + else -> tag + } + + val levelString = when (level) { + Log.VERBOSE -> "V" + Log.DEBUG -> "D" + Log.INFO -> "I" + Log.WARN -> "W" + Log.ERROR -> "E" + else -> "?" + } + + val out = JSONObject() + out.put("level", levelString) + out.put("time", formattedTime) + out.put("thread", thread) + out.put("tag", paddedTag) + message?.let { out.put("message", it) } + stackTrace?.let { out.put("stackTrace", it) } + + return out.toString(0) + } + + companion object { + private val dateFormat = SimpleDateFormat("HH:mm:ss.SSS", Locale.US) + } +} diff --git a/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogWebSocket.kt b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogWebSocket.kt new file mode 100644 index 0000000000..b8f5feb67b --- /dev/null +++ b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogWebSocket.kt @@ -0,0 +1,96 @@ +/* + * Copyright 2023 Signal Messenger, LLC + * SPDX-License-Identifier: AGPL-3.0-only + */ + +package org.signal.spinner + +import android.annotation.SuppressLint +import android.util.Log +import fi.iki.elonen.NanoHTTPD +import fi.iki.elonen.NanoWSD +import fi.iki.elonen.NanoWSD.WebSocket +import java.io.IOException +import java.util.LinkedList +import java.util.Queue +import java.util.concurrent.locks.ReentrantLock +import kotlin.concurrent.withLock + +@SuppressLint("LogNotSignal") +internal class SpinnerLogWebSocket(handshakeRequest: NanoHTTPD.IHTTPSession) : WebSocket(handshakeRequest) { + + companion object { + private val TAG = "SpinnerLogWebSocket" + + private const val MAX_LOGS = 5_000 + + private val logs: Queue = LinkedList() + private val openSockets: MutableList = mutableListOf() + + private val lock = ReentrantLock() + private val condition = lock.newCondition() + + private val logThread: LogThread = LogThread().also { it.start() } + + fun onLog(item: SpinnerLogItem) { + lock.withLock { + logs += item + if (logs.size > MAX_LOGS) { + logs.remove() + } + condition.signal() + } + } + } + + override fun onOpen() { + Log.d(TAG, "onOpen()") + + lock.withLock { + openSockets += this + condition.signal() + } + } + + override fun onClose(code: NanoWSD.WebSocketFrame.CloseCode, reason: String?, initiatedByRemote: Boolean) { + Log.d(TAG, "onClose()") + + lock.withLock { + openSockets -= this + } + } + + override fun onMessage(message: NanoWSD.WebSocketFrame) { + Log.d(TAG, "onMessage()") + } + + override fun onPong(pong: NanoWSD.WebSocketFrame) { + Log.d(TAG, "onPong()") + } + + override fun onException(exception: IOException) { + Log.d(TAG, "onException()", exception) + } + + private class LogThread : Thread("SpinnerLog") { + override fun run() { + while (true) { + val (sockets, log) = lock.withLock { + while (logs.isEmpty() || openSockets.isEmpty()) { + condition.await() + } + + openSockets.toList() to logs.remove() + } + + sockets.forEach { socket -> + try { + socket.send(log.serialize()) + } catch (e: IOException) { + Log.w(TAG, "Failed to send a log to the socket!", e) + } + } + } + } + } +} diff --git a/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogger.kt b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogger.kt new file mode 100644 index 0000000000..46dec483b4 --- /dev/null +++ b/spinner/lib/src/main/java/org/signal/spinner/SpinnerLogger.kt @@ -0,0 +1,98 @@ +/* + * Copyright 2023 Signal Messenger, LLC + * SPDX-License-Identifier: AGPL-3.0-only + */ + +package org.signal.spinner + +import android.os.Looper +import android.util.Log +import org.signal.core.util.logging.Log.Logger + +class SpinnerLogger : Logger() { + + private val cachedThreadString: ThreadLocal = ThreadLocal() + + override fun v(tag: String, message: String?, t: Throwable?, keepLonger: Boolean) { + Spinner.log( + SpinnerLogItem( + level = Log.VERBOSE, + time = System.currentTimeMillis(), + thread = getThreadString(), + tag = tag, + message = message, + throwable = t + ) + ) + } + + override fun d(tag: String, message: String?, t: Throwable?, keepLonger: Boolean) { + Spinner.log( + SpinnerLogItem( + level = Log.DEBUG, + time = System.currentTimeMillis(), + thread = getThreadString(), + tag = tag, + message = message, + throwable = t + ) + ) + } + + override fun i(tag: String, message: String?, t: Throwable?, keepLonger: Boolean) { + Spinner.log( + SpinnerLogItem( + level = Log.INFO, + time = System.currentTimeMillis(), + thread = getThreadString(), + tag = tag, + message = message, + throwable = t + ) + ) + } + + override fun w(tag: String, message: String?, t: Throwable?, keepLonger: Boolean) { + Spinner.log( + SpinnerLogItem( + level = Log.WARN, + time = System.currentTimeMillis(), + thread = getThreadString(), + tag = tag, + message = message, + throwable = t + ) + ) + } + + override fun e(tag: String, message: String?, t: Throwable?, keepLonger: Boolean) { + Spinner.log( + SpinnerLogItem( + level = Log.ERROR, + time = System.currentTimeMillis(), + thread = getThreadString(), + tag = tag, + message = message, + throwable = t + ) + ) + } + + override fun flush() = Unit + + fun getThreadString(): String { + var threadString = cachedThreadString.get() + + if (cachedThreadString.get() == null) { + threadString = if (Looper.myLooper() == Looper.getMainLooper()) { + "main " + } else { + String.format("%-5s", Thread.currentThread().id) + } + + cachedThreadString.set(threadString) + } + + return threadString!! + } +} diff --git a/spinner/lib/src/main/java/org/signal/spinner/SpinnerServer.kt b/spinner/lib/src/main/java/org/signal/spinner/SpinnerServer.kt index 4556a396d9..420d6b41c1 100644 --- a/spinner/lib/src/main/java/org/signal/spinner/SpinnerServer.kt +++ b/spinner/lib/src/main/java/org/signal/spinner/SpinnerServer.kt @@ -7,12 +7,14 @@ import com.github.jknack.handlebars.Handlebars import com.github.jknack.handlebars.Template import com.github.jknack.handlebars.helper.ConditionalHelpers import fi.iki.elonen.NanoHTTPD +import fi.iki.elonen.NanoWSD import org.signal.core.util.ExceptionUtil import org.signal.core.util.ForeignKeyConstraint import org.signal.core.util.getForeignKeys import org.signal.core.util.logging.Log import org.signal.spinner.Spinner.DatabaseConfig import java.lang.IllegalArgumentException +import java.security.NoSuchAlgorithmException import java.text.SimpleDateFormat import java.util.Date import java.util.Locale @@ -33,7 +35,7 @@ internal class SpinnerServer( deviceInfo: Map String>, private val databases: Map, private val plugins: Map -) : NanoHTTPD(5000) { +) : NanoWSD(5000) { companion object { private val TAG = Log.tag(SpinnerServer::class.java) @@ -69,6 +71,8 @@ internal class SpinnerServer( session.method == Method.GET && session.uri == "/query" -> getQuery(dbParam) session.method == Method.POST && session.uri == "/query" -> postQuery(dbParam, dbConfig, session) session.method == Method.GET && session.uri == "/recent" -> getRecent(dbParam) + session.method == Method.GET && session.uri == "/logs" -> getLogs(dbParam) + isWebsocketRequested(session) && session.uri == "/logs/websocket" -> getLogWebSocket(session) else -> { val plugin = plugins[session.uri] if (plugin != null && session.method == Method.GET) { @@ -84,6 +88,10 @@ internal class SpinnerServer( } } + override fun openWebSocket(handshake: IHTTPSession): WebSocket { + return SpinnerLogWebSocket(handshake) + } + fun onSql(dbName: String, sql: String) { val commands: Queue = recentSql[dbName] ?: ConcurrentLinkedQueue() @@ -95,6 +103,10 @@ internal class SpinnerServer( recentSql[dbName] = commands } + fun onLog(item: SpinnerLogItem) { + SpinnerLogWebSocket.onLog(item) + } + private fun getIndex(dbName: String, db: SupportSQLiteDatabase): Response { return renderTemplate( "overview", @@ -205,6 +217,38 @@ internal class SpinnerServer( ) } + private fun getLogs(dbName: String): Response { + return renderTemplate( + "logs", + LogsPageModel( + environment = environment, + deviceInfo = deviceInfo.resolve(), + database = dbName, + databases = databases.keys.toList(), + plugins = plugins.values.toList() + ) + ) + } + + private fun getLogWebSocket(session: IHTTPSession): Response { + val headers = session.headers + val webSocket = openWebSocket(session) + + val handshakeResponse = webSocket.handshakeResponse + + try { + handshakeResponse.addHeader(HEADER_WEBSOCKET_ACCEPT, makeAcceptKey(headers[HEADER_WEBSOCKET_KEY])) + } catch (e: NoSuchAlgorithmException) { + return newFixedLengthResponse(Response.Status.INTERNAL_ERROR, NanoHTTPD.MIME_PLAINTEXT, "The SHA-1 Algorithm required for websockets is not available on the server.") + } + + if (headers.containsKey(HEADER_WEBSOCKET_PROTOCOL)) { + handshakeResponse.addHeader(HEADER_WEBSOCKET_PROTOCOL, headers[HEADER_WEBSOCKET_PROTOCOL]!!.split(",")[0]) + } + + return webSocket.handshakeResponse + } + private fun postQuery(dbName: String, dbConfig: DatabaseConfig, session: IHTTPSession): Response { val action: String = session.parameters["action"]?.get(0).toString() val rawQuery: String = session.parameters["query"]?.get(0).toString() @@ -448,6 +492,14 @@ internal class SpinnerServer( val recentSql: List? ) : PrefixPageData + data class LogsPageModel( + override val environment: String, + override val deviceInfo: Map, + override val database: String, + override val databases: List, + override val plugins: List + ) : PrefixPageData + data class PluginPageModel( override val environment: String, override val deviceInfo: Map,