Improve logging

This commit is contained in:
Mygod
2020-08-08 07:51:47 +08:00
parent 6b10334919
commit c3b2d476e5
4 changed files with 64 additions and 58 deletions

View File

@@ -0,0 +1,27 @@
package be.mygod.librootkotlinx
import android.util.Log
interface Logger {
companion object {
/**
* Override this variable to change default behavior,
* which is to print to [android.util.Log] under tag "RootServer" except for [d].
*/
@JvmStatic
var me = object : Logger { }
private const val TAG = "RootServer"
}
fun d(m: String?, t: Throwable? = null) { }
fun e(m: String?, t: Throwable? = null) {
Log.e(TAG, m, t)
}
fun i(m: String?, t: Throwable? = null) {
Log.i(TAG, m, t)
}
fun w(m: String?, t: Throwable? = null) {
Log.w(TAG, m, t)
}
}

View File

@@ -6,7 +6,6 @@ import android.os.Parcelable
import android.os.RemoteException import android.os.RemoteException
import android.system.Os import android.system.Os
import android.system.OsConstants import android.system.OsConstants
import android.util.Log
import androidx.collection.LongSparseArray import androidx.collection.LongSparseArray
import androidx.collection.set import androidx.collection.set
import androidx.collection.valueIterator import androidx.collection.valueIterator
@@ -23,7 +22,7 @@ import java.util.*
import java.util.concurrent.CountDownLatch import java.util.concurrent.CountDownLatch
import kotlin.system.exitProcess import kotlin.system.exitProcess
class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> Unit = { Log.w(TAG, it) }) { class RootServer {
private sealed class Callback(private val server: RootServer, private val index: Long, private sealed class Callback(private val server: RootServer, private val index: Long,
protected val classLoader: ClassLoader?) { protected val classLoader: ClassLoader?) {
var active = true var active = true
@@ -107,12 +106,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
private val callbackLookup = LongSparseArray<Callback>() private val callbackLookup = LongSparseArray<Callback>()
private val mutex = Mutex() private val mutex = Mutex()
/** private fun readUnexpectedStderr(): String? {
* If we encountered unexpected output from stderr during initialization, its content will be stored here.
*
* It is advised to read this after initializing the instance.
*/
fun readUnexpectedStderr(): String? {
if (!this::process.isInitialized) return null if (!this::process.isInitialized) return null
var available = process.errorStream.available() var available = process.errorStream.available()
return if (available <= 0) null else String(ByteArrayOutputStream().apply { return if (available <= 0) null else String(ByteArrayOutputStream().apply {
@@ -131,10 +125,10 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
val line = readLine() ?: throw EOFException() val line = readLine() ?: throw EOFException()
if (line.endsWith(token)) { if (line.endsWith(token)) {
val extraLength = line.length - token.length val extraLength = line.length - token.length
if (extraLength > 0) warnLogger(line.substring(0, extraLength)) if (extraLength > 0) Logger.me.w(line.substring(0, extraLength))
break break
} }
warnLogger(line) Logger.me.w(line)
} }
} }
private fun doInit(context: Context, niceName: String) { private fun doInit(context: Context, niceName: String) {
@@ -146,7 +140,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
writer.flush() writer.flush()
val reader = process.inputStream.bufferedReader() val reader = process.inputStream.bufferedReader()
reader.lookForToken(token1) reader.lookForToken(token1)
if (isDebugEnabled) Log.d(TAG, "Root shell initialized") Logger.me.d("Root shell initialized")
reader to writer reader to writer
} catch (e: Exception) { } catch (e: Exception) {
throw NoShellException(e) throw NoShellException(e)
@@ -166,7 +160,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
output = writer output = writer
require(!active) require(!active)
active = true active = true
if (isDebugEnabled) Log.d(TAG, "Root server initialized") Logger.me.d("Root server initialized")
} }
private fun callbackSpin() { private fun callbackSpin() {
@@ -187,7 +181,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
} }
} else null } else null
} ?: break } ?: break
if (isDebugEnabled) Log.d(TAG, "Received callback #$index: $result") Logger.me.d("Received callback #$index: $result")
callback(input, result) callback(input, result)
} }
} }
@@ -198,7 +192,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
* @param context Any [Context] from the app. * @param context Any [Context] from the app.
* @param niceName Name to call the rooted Java process. * @param niceName Name to call the rooted Java process.
*/ */
suspend fun init(context: Context, niceName: String = "${context.packageName}:root") { suspend fun init(context: Context, niceName: String = "${context.packageName}:root") = try {
val future = CompletableDeferred<Unit>() val future = CompletableDeferred<Unit>()
callbackListenerExit = GlobalScope.async(Dispatchers.IO) { callbackListenerExit = GlobalScope.async(Dispatchers.IO) {
try { try {
@@ -211,7 +205,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
val errorReader = async(Dispatchers.IO) { val errorReader = async(Dispatchers.IO) {
try { try {
process.errorStream.bufferedReader().useLines { seq -> process.errorStream.bufferedReader().useLines { seq ->
for (line in seq) warnLogger(line) for (line in seq) Logger.me.w(line)
} }
} catch (_: IOException) { } } catch (_: IOException) { }
} }
@@ -222,21 +216,15 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
process.destroy() process.destroy()
throw e throw e
} finally { } finally {
if (isDebugEnabled) Log.d(TAG, "Waiting for exit") Logger.me.d("Waiting for exit")
errorReader.await() errorReader.await()
process.waitFor() process.waitFor()
withContext(NonCancellable) { closeInternal(true) } withContext(NonCancellable) { closeInternal(true) }
} }
} }
future.await() future.await()
}
/**
* Convenience function that initializes and also logs warnings to [Log].
*/
suspend fun initAndroidLog(context: Context, niceName: String = "${context.packageName}:root") = try {
init(context, niceName)
} finally { } finally {
readUnexpectedStderr()?.let { Log.e(TAG, it) } readUnexpectedStderr()?.let { Logger.me.e(it) }
} }
/** /**
@@ -245,7 +233,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
private fun sendLocked(command: Parcelable) { private fun sendLocked(command: Parcelable) {
output.writeParcelable(command) output.writeParcelable(command)
output.flush() output.flush()
if (isDebugEnabled) Log.d(TAG, "Sent #$counter: $command") Logger.me.d("Sent #$counter: $command")
counter++ counter++
} }
@@ -307,15 +295,15 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
private suspend fun closeInternal(fromWorker: Boolean = false) = mutex.withLock { private suspend fun closeInternal(fromWorker: Boolean = false) = mutex.withLock {
if (active) { if (active) {
active = false active = false
if (isDebugEnabled) Log.d(TAG, if (fromWorker) "Shutting down from worker" else "Shutting down from client") Logger.me.d(if (fromWorker) "Shutting down from worker" else "Shutting down from client")
try { try {
sendLocked(Shutdown()) sendLocked(Shutdown())
output.close() output.close()
process.outputStream.close() process.outputStream.close()
} catch (e: IOException) { } catch (e: IOException) {
Log.i(TAG, "send Shutdown failed", e) Logger.me.i("send Shutdown failed", e)
} }
if (isDebugEnabled) Log.d(TAG, "Client closed") Logger.me.d("Client closed")
} }
if (fromWorker) { if (fromWorker) {
for (callback in callbackLookup.valueIterator()) callback.cancel() for (callback in callbackLookup.valueIterator()) callback.cancel()
@@ -331,13 +319,6 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
} }
companion object { companion object {
/**
* If set to true, debug information will be printed to logcat.
*/
@JvmStatic
var isDebugEnabled = false
private const val TAG = "RootServer"
private const val SUCCESS = 0 private const val SUCCESS = 0
private const val EX_GENERIC = 1 private const val EX_GENERIC = 1
private const val EX_PARCELABLE = 2 private const val EX_PARCELABLE = 2
@@ -366,7 +347,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
@JvmStatic @JvmStatic
fun main(args: Array<String>) { fun main(args: Array<String>) {
Thread.setDefaultUncaughtExceptionHandler { thread, throwable -> Thread.setDefaultUncaughtExceptionHandler { thread, throwable ->
Log.e(TAG, "Uncaught exception from $thread", throwable) Logger.me.e("Uncaught exception from $thread", throwable)
exitProcess(1) exitProcess(1)
} }
rootMain(args) rootMain(args)
@@ -430,7 +411,7 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
// thread safety: usage of input should be in main thread // thread safety: usage of input should be in main thread
val input = DataInputStream(System.`in`.buffered()) val input = DataInputStream(System.`in`.buffered())
var counter = 0L var counter = 0L
if (isDebugEnabled) Log.d(TAG, "Server entering main loop") Logger.me.d("Server entering main loop")
loop@ while (true) { loop@ while (true) {
val command = try { val command = try {
input.readParcelable<Parcelable>(RootServer::class.java.classLoader) input.readParcelable<Parcelable>(RootServer::class.java.classLoader)
@@ -438,14 +419,14 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
break break
} }
val callback = counter val callback = counter
if (isDebugEnabled) Log.d(TAG, "Received #$callback: $command") Logger.me.d("Received #$callback: $command")
when (command) { when (command) {
is CancelCommand -> cancellables[command.index]?.invoke() is CancelCommand -> cancellables[command.index]?.invoke()
is RootCommandOneWay -> defaultWorker.launch { is RootCommandOneWay -> defaultWorker.launch {
try { try {
command.execute() command.execute()
} catch (e: Throwable) { } catch (e: Throwable) {
Log.e(command.javaClass.simpleName, "Unexpected exception in RootCommandOneWay", e) Logger.me.e("Unexpected exception in RootCommandOneWay ($command.javaClass.simpleName)", e)
} }
} }
is RootCommand<*> -> { is RootCommand<*> -> {
@@ -490,10 +471,10 @@ class RootServer @JvmOverloads constructor(private val warnLogger: (String) -> U
counter++ counter++
} }
job.cancel() job.cancel()
if (isDebugEnabled) Log.d(TAG, "Clean up initiated before exit. Jobs: ${job.children.joinToString()}") Logger.me.d("Clean up initiated before exit. Jobs: ${job.children.joinToString()}")
if (runBlocking { withTimeoutOrNull(5000) { job.join() } } == null) { if (runBlocking { withTimeoutOrNull(5000) { job.join() } } == null) {
Log.w(TAG, "Clean up timeout: ${job.children.joinToString()}") Logger.me.w("Clean up timeout: ${job.children.joinToString()}")
} else if (isDebugEnabled) Log.d(TAG, "Clean up finished, exiting") } else Logger.me.d("Clean up finished, exiting")
} }
} }
} }

View File

@@ -9,7 +9,6 @@ import java.util.concurrent.TimeUnit
* This object manages creation of [RootServer] and times them out automagically, with default timeout of 5 minutes. * This object manages creation of [RootServer] and times them out automagically, with default timeout of 5 minutes.
*/ */
abstract class RootSession { abstract class RootSession {
protected open fun createServer() = RootServer()
protected abstract suspend fun initServer(server: RootServer) protected abstract suspend fun initServer(server: RootServer)
/** /**
* Timeout to close [RootServer] in milliseconds. * Timeout to close [RootServer] in milliseconds.
@@ -30,7 +29,7 @@ abstract class RootSession {
usersCount = 0 usersCount = 0
} }
check(usersCount == 0L) { "Unexpected $server, $usersCount" } check(usersCount == 0L) { "Unexpected $server, $usersCount" }
val server = createServer() val server = RootServer()
try { try {
initServer(server) initServer(server)
this.server = server this.server = server

View File

@@ -2,24 +2,22 @@ package be.mygod.vpnhotspot.root
import android.os.Parcelable import android.os.Parcelable
import android.util.Log import android.util.Log
import be.mygod.librootkotlinx.RootCommandNoResult import be.mygod.librootkotlinx.*
import be.mygod.librootkotlinx.RootServer
import be.mygod.librootkotlinx.RootSession
import be.mygod.librootkotlinx.systemContext
import be.mygod.vpnhotspot.App.Companion.app import be.mygod.vpnhotspot.App.Companion.app
import be.mygod.vpnhotspot.BuildConfig
import be.mygod.vpnhotspot.util.Services import be.mygod.vpnhotspot.util.Services
import kotlinx.android.parcel.Parcelize import kotlinx.android.parcel.Parcelize
import timber.log.Timber import timber.log.Timber
object RootManager : RootSession() { object RootManager : RootSession(), Logger {
@Parcelize @Parcelize
class RootInit : RootCommandNoResult { class RootInit : RootCommandNoResult {
override suspend fun execute(): Parcelable? { override suspend fun execute(): Parcelable? {
RootServer.isDebugEnabled = BuildConfig.DEBUG
Timber.plant(object : Timber.DebugTree() { Timber.plant(object : Timber.DebugTree() {
override fun log(priority: Int, tag: String?, message: String, t: Throwable?) { override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
if (priority >= Log.WARN) System.err.println("$priority/$tag: $message") if (priority >= Log.WARN) {
System.err.println("$priority/$tag: $message")
t?.printStackTrace()
}
if (t == null) { if (t == null) {
Log.println(priority, tag, message) Log.println(priority, tag, message)
} else { } else {
@@ -29,19 +27,20 @@ object RootManager : RootSession() {
} }
} }
}) })
Logger.me = RootManager
Services.init { systemContext } Services.init { systemContext }
return null return null
} }
} }
override fun createServer() = RootServer { Timber.w(it) } override fun d(m: String?, t: Throwable?) = Timber.d(t, m)
override fun e(m: String?, t: Throwable?) = Timber.e(t, m)
override fun i(m: String?, t: Throwable?) = Timber.i(t, m)
override fun w(m: String?, t: Throwable?) = Timber.w(t, m)
override suspend fun initServer(server: RootServer) { override suspend fun initServer(server: RootServer) {
RootServer.isDebugEnabled = BuildConfig.DEBUG Logger.me = this
try { server.init(app.deviceStorage)
server.init(app.deviceStorage)
} finally {
server.readUnexpectedStderr()?.let { Timber.e(it) }
}
server.execute(RootInit()) server.execute(RootInit())
} }
} }