Improve debug logging mechanisms

mobile/build.gradle

@@ -78,6 +78,7 @@ dependencies {
     implementation "org.jetbrains.kotlin:kotlin-stdlib-jdk7:$kotlinVersion"
     baseImplementation 'com.android.billingclient:billing:1.2'
     baseImplementation 'com.crashlytics.sdk.android:crashlytics:2.9.8'
+    baseImplementation 'com.google.firebase:firebase-core:16.0.6'
     testImplementation "androidx.arch.core:core-testing:$lifecycleVersion"
     testImplementation "androidx.room:room-testing:$roomVersion"
     testImplementation 'junit:junit:4.12'

mobile/src/base/java/be/mygod/vpnhotspot/DebugHelper.kt

@@ -0,0 +1,42 @@
+package be.mygod.vpnhotspot
+
+import android.os.Bundle
+import android.util.Log
+import androidx.annotation.Size
+import be.mygod.vpnhotspot.App.Companion.app
+import com.crashlytics.android.Crashlytics
+import com.google.firebase.analytics.FirebaseAnalytics
+import io.fabric.sdk.android.Fabric
+import timber.log.Timber
+
+object DebugHelper {
+    private val analytics by lazy { FirebaseAnalytics.getInstance(app.deviceStorage) }
+
+    fun init() {
+        Fabric.with(app.deviceStorage, Crashlytics())
+        Timber.plant(object : Timber.DebugTree() {
+            override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
+                if (t == null) Crashlytics.log(priority, tag, message) else {
+                    // Crashlytics.logException doesn't print to logcat
+                    if (priority >= Log.WARN || priority == Log.DEBUG) Log.println(priority, tag, message)
+                    if (priority >= Log.INFO) Crashlytics.logException(t)
+                }
+            }
+        })
+    }
+
+    fun log(tag: String?, message: String?) {
+        if (BuildConfig.DEBUG) Timber.tag(tag).d(message) else Crashlytics.log("$tag: $message")
+    }
+
+    fun setString(key: String, value: String?) = Crashlytics.setString(key, value)
+
+    /**
+     * This method is used to log "expected" and well-handled errors, i.e. we care less about logs, etc.
+     * logException is inappropriate sometimes because it flushes all logs that could be used to investigate other bugs.
+     */
+    fun logEvent(@Size(min = 1L, max = 40L) event: String, extras: Bundle? = null) {
+        Timber.i(if (extras == null) event else "$event, extras: $extras")
+        analytics.logEvent(event, extras)
+    }
+}

mobile/src/base/java/be/mygod/vpnhotspot/Timber.kt

@@ -1,26 +0,0 @@
-package be.mygod.vpnhotspot
-
-import android.util.Log
-import be.mygod.vpnhotspot.App.Companion.app
-import com.crashlytics.android.Crashlytics
-import io.fabric.sdk.android.Fabric
-import timber.log.Timber
-
-fun initTimber() {
-    Fabric.with(app.deviceStorage, Crashlytics())
-    Timber.plant(object : Timber.DebugTree() {
-        override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
-            if (t == null) Crashlytics.log(priority, tag, message) else {
-                // Crashlytics.logException doesn't print to logcat
-                if (priority >= Log.WARN || priority == Log.DEBUG) Log.println(priority, tag, message)
-                if (priority >= Log.INFO) Crashlytics.logException(t)
-            }
-        }
-    })
-}
-
-fun debugLog(tag: String?, message: String?) {
-    if (BuildConfig.DEBUG) Timber.tag(tag).d(message) else Crashlytics.log("$tag: $message")
-}
-
-fun timberSetString(key: String, value: String?) = Crashlytics.setString(key, value)

mobile/src/fdroid/java/be/mygod/vpnhotspot/DebugHelper.kt

@@ -0,0 +1,13 @@
+package be.mygod.vpnhotspot
+
+import android.os.Bundle
+import androidx.annotation.Size
+import timber.log.Timber
+
+object DebugHelper {
+    fun init() = Timber.plant(Timber.DebugTree())
+    fun log(tag: String?, message: String?) = Timber.tag(tag).d(message)
+    fun setString(key: String, value: String?) = Timber.tag(key).d(value)
+    fun logEvent(@Size(min = 1L, max = 40L) event: String, extras: Bundle? = null) =
+            Timber.tag("logEvent").d("$event: $extras")
+}

mobile/src/fdroid/java/be/mygod/vpnhotspot/Timber.kt

@@ -1,9 +0,0 @@
-package be.mygod.vpnhotspot
-
-import timber.log.Timber
-
-fun initTimber() = Timber.plant(Timber.DebugTree())
-
-fun debugLog(tag: String?, message: String?) = Timber.tag(tag).d(message)
-
-fun timberSetString(key: String, value: String?) = Timber.tag(key).d(value)

mobile/src/main/java/be/mygod/vpnhotspot/App.kt

@@ -32,7 +32,7 @@ class App : Application() {
             deviceStorage.moveSharedPreferencesFrom(this, PreferenceManager.getDefaultSharedPreferencesName(this))
             deviceStorage.moveDatabaseFrom(this, AppDatabase.DB_NAME)
         } else deviceStorage = this
-        initTimber()
+        DebugHelper.init()
         ServiceNotification.updateNotificationChannels()
     }
 

mobile/src/main/java/be/mygod/vpnhotspot/LocalOnlyHotspotService.kt

@@ -42,7 +42,7 @@ class LocalOnlyHotspotService : IpNeighbourMonitoringService() {
     private var receiverRegistered = false
     private val receiver = broadcastReceiver { _, intent ->
         val ifaces = TetheringManager.getLocalOnlyTetheredIfaces(intent.extras ?: return@broadcastReceiver)
-        debugLog(TAG, "onTetherStateChangedLocked: $ifaces")
+        DebugHelper.log(TAG, "onTetherStateChangedLocked: $ifaces")
         check(ifaces.size <= 1)
         val iface = ifaces.singleOrNull()
         binder.iface = iface
@@ -85,7 +85,7 @@ class LocalOnlyHotspotService : IpNeighbourMonitoringService() {
                 }
 
                 override fun onStopped() {
-                    debugLog(TAG, "LOHCallback.onStopped")
+                    DebugHelper.log(TAG, "LOHCallback.onStopped")
                     reservation = null
                 }
 

mobile/src/main/java/be/mygod/vpnhotspot/RepeaterService.kt

@@ -251,7 +251,7 @@ class RepeaterService : Service(), WifiP2pManager.ChannelListener, SharedPrefere
      * Used during step 2, also called when connection changed
      */
     private fun onP2pConnectionChanged(info: WifiP2pInfo, net: NetworkInfo?, group: WifiP2pGroup) {
-        debugLog(TAG, "P2P connection changed: $info\n$net\n$group")
+        DebugHelper.log(TAG, "P2P connection changed: $info\n$net\n$group")
         when {
             !info.groupFormed || !info.isGroupOwner || !group.isGroupOwner -> {
                 if (routingManager != null) clean() // P2P shutdown, else other groups changing before start, ignore

mobile/src/main/java/be/mygod/vpnhotspot/manage/ManageBar.kt

@@ -6,13 +6,19 @@ import android.content.Intent
 import android.os.Build
 import android.provider.Settings
 import android.view.View
+import androidx.core.os.bundleOf
 import androidx.databinding.BaseObservable
 import androidx.recyclerview.widget.RecyclerView
 import be.mygod.vpnhotspot.App.Companion.app
+import be.mygod.vpnhotspot.DebugHelper
 import be.mygod.vpnhotspot.databinding.ListitemManageBinding
-import timber.log.Timber
 
 object ManageBar : Manager() {
+    private const val TAG = "ManageBar"
+    private const val SETTINGS_PACKAGE = "com.android.settings"
+    private const val SETTINGS_1 = "com.android.settings.Settings\$TetherSettingsActivity"
+    private const val SETTINGS_2 = "com.android.settings.TetherSettings"
+
     object Data : BaseObservable() {
         /**
          * It's hard to change tethering rules with Tethering hardware acceleration enabled for now.
@@ -38,8 +44,7 @@ object ManageBar : Manager() {
 
     fun start(context: Context) {
         try {
-            context.startActivity(Intent()
+            context.startActivity(Intent().setClassName(SETTINGS_PACKAGE, SETTINGS_1))
-                    .setClassName("com.android.settings", "com.android.settings.Settings\$TetherSettingsActivity"))
         } catch (e: ActivityNotFoundException) {
             startAlternative(context, e)
         } catch (e: SecurityException) {
@@ -49,13 +54,12 @@ object ManageBar : Manager() {
 
     private fun startAlternative(context: Context, e: RuntimeException) {
         try {
-            context.startActivity(Intent()
+            context.startActivity(Intent().setClassName("com.android.settings", SETTINGS_2))
-                    .setClassName("com.android.settings", "com.android.settings.TetherSettings"))
+            DebugHelper.logEvent(TAG, bundleOf(Pair(SETTINGS_1, e.message)))
-            Timber.w(e)
         } catch (e: ActivityNotFoundException) {
-            Timber.w(e)
+            DebugHelper.logEvent(TAG, bundleOf(Pair(SETTINGS_1, e.message), Pair(SETTINGS_2, e.message)))
         } catch (e: SecurityException) {
-            Timber.w(e)
+            DebugHelper.logEvent(TAG, bundleOf(Pair(SETTINGS_1, e.message), Pair(SETTINGS_2, e.message)))
         }
     }
 }

mobile/src/main/java/be/mygod/vpnhotspot/manage/TetheringFragment.kt

@@ -54,7 +54,7 @@ class TetheringFragment : Fragment(), ServiceConnection {
             ifaceLookup = try {
                 NetworkInterface.getNetworkInterfaces().asSequence().associateBy { it.name }
             } catch (e: SocketException) {
-                Timber.w(e)
+                Timber.d(e)
                 emptyMap()
             }
             this@TetheringFragment.enabledTypes =

mobile/src/main/java/be/mygod/vpnhotspot/net/IpNeighbour.kt

@@ -58,7 +58,7 @@ data class IpNeighbour(val ip: InetAddress, val dev: String, val lladdr: String,
                     if (iface == null) Timber.w("Failed to find network interface #$index")
                     else return listOf(IpNeighbour(ip, iface.name, lladdr, state), result)
                 } catch (e: SocketException) {
-                    Timber.w(e)
+                    Timber.d(e)
                 }
                 listOf(result)
             } catch (e: Exception) {

mobile/src/main/java/be/mygod/vpnhotspot/net/monitor/IpMonitor.kt

@@ -1,8 +1,10 @@
 package be.mygod.vpnhotspot.net.monitor
 
+import android.system.ErrnoException
+import android.system.OsConstants
 import be.mygod.vpnhotspot.App.Companion.app
+import be.mygod.vpnhotspot.DebugHelper
 import be.mygod.vpnhotspot.R
-import be.mygod.vpnhotspot.debugLog
 import be.mygod.vpnhotspot.util.thread
 import be.mygod.vpnhotspot.widget.SmartSnackbar
 import timber.log.Timber
@@ -21,7 +23,6 @@ abstract class IpMonitor : Runnable {
         Monitor, MonitorRoot, Poll
     }
 
-    private class MonitorFailure : RuntimeException("Failed to set up monitor, switching to polling")
     private class FlushFailure : RuntimeException()
     protected abstract val monitoredObject: String
     protected abstract fun processLine(line: String)
@@ -44,17 +45,17 @@ abstract class IpMonitor : Runnable {
             try {
                 process.errorStream.bufferedReader().forEachLine { Timber.e(it) }
             } catch (_: InterruptedIOException) { } catch (e: IOException) {
-                Timber.w(e)
+                if ((e.cause as? ErrnoException)?.errno != OsConstants.EBADF) Timber.w(e)
             }
         }
         try {
             process.inputStream.bufferedReader().forEachLine(this::processLine)
         } catch (_: InterruptedIOException) { } catch (e: IOException) {
-            Timber.w(e)
+            if ((e.cause as? ErrnoException)?.errno != OsConstants.EBADF) Timber.w(e)
         }
         err.join()
         process.waitFor()
-        debugLog("IpMonitor", "Monitor process exited with ${process.exitValue()}")
+        DebugHelper.log("IpMonitor", "Monitor process exited with ${process.exitValue()}")
     }
 
     init {
@@ -68,7 +69,7 @@ abstract class IpMonitor : Runnable {
                 }
                 handleProcess(ProcessBuilder("su", "-c", "exec ip monitor $monitoredObject"))
                 if (destroyed) return@thread
-                Timber.i(MonitorFailure())
+                DebugHelper.logEvent("ip_monitor_failure")
             }
             val pool = Executors.newScheduledThreadPool(1)
             pool.scheduleAtFixedRate(this, 1, 1, TimeUnit.SECONDS)

mobile/src/main/java/be/mygod/vpnhotspot/net/monitor/TrafficRecorder.kt

@@ -2,7 +2,7 @@ package be.mygod.vpnhotspot.net.monitor
 
 import android.util.LongSparseArray
 import androidx.core.os.postDelayed
-import be.mygod.vpnhotspot.debugLog
+import be.mygod.vpnhotspot.DebugHelper
 import be.mygod.vpnhotspot.net.Routing.Companion.IPTABLES
 import be.mygod.vpnhotspot.room.AppDatabase
 import be.mygod.vpnhotspot.room.TrafficRecord
@@ -33,14 +33,14 @@ object TrafficRecorder {
                 downstream = downstream)
         AppDatabase.instance.trafficRecordDao.insert(record)
         synchronized(this) {
-            debugLog(TAG, "Registering ($ip, $upstream, $downstream)")
+            DebugHelper.log(TAG, "Registering ($ip, $upstream, $downstream)")
             check(records.put(Triple(ip, upstream, downstream), record) == null)
             scheduleUpdateLocked()
         }
     }
     fun unregister(ip: InetAddress, upstream: String?, downstream: String) = synchronized(this) {
         update()    // flush stats before removing
-        debugLog(TAG, "Unregistering ($ip, $upstream, $downstream)")
+        DebugHelper.log(TAG, "Unregistering ($ip, $upstream, $downstream)")
         if (records.remove(Triple(ip, upstream, downstream)) == null) Timber.w(
                 "Failed to find traffic record for ($ip, $downstream, $upstream).")
     }
@@ -145,7 +145,7 @@ object TrafficRecorder {
     fun clean() = synchronized(this) {
         update()
         unscheduleUpdateLocked()
-        debugLog(TAG, "Cleaning records")
+        DebugHelper.log(TAG, "Cleaning records")
         records.clear()
     }
 

mobile/src/main/java/be/mygod/vpnhotspot/net/monitor/VpnMonitor.kt

@@ -2,7 +2,7 @@ package be.mygod.vpnhotspot.net.monitor
 
 import android.net.*
 import be.mygod.vpnhotspot.App.Companion.app
-import be.mygod.vpnhotspot.debugLog
+import be.mygod.vpnhotspot.DebugHelper
 import timber.log.Timber
 
 object VpnMonitor : UpstreamMonitor() {
@@ -29,7 +29,7 @@ object VpnMonitor : UpstreamMonitor() {
                 val oldProperties = available.put(network, properties)
                 if (old != network) {
                     if (old != null) {
-                        debugLog(TAG, "Assuming old VPN interface ${available[old]} is dying")
+                        DebugHelper.log(TAG, "Assuming old VPN interface ${available[old]} is dying")
                         callbacks.forEach { it.onLost() }
                     }
                     currentNetwork = network
@@ -75,7 +75,7 @@ object VpnMonitor : UpstreamMonitor() {
             if (available.isNotEmpty()) {
                 val next = available.entries.first()
                 currentNetwork = next.key
-                debugLog(TAG, "Switching to ${next.value.interfaceName} as VPN interface")
+                DebugHelper.log(TAG, "Switching to ${next.value.interfaceName} as VPN interface")
                 callbacks.forEach { it.onAvailable(next.value.interfaceName!!, next.value.dnsServers) }
             } else currentNetwork = null
         }

mobile/src/main/java/be/mygod/vpnhotspot/net/wifi/P2pSupplicantConfiguration.kt

@@ -3,7 +3,7 @@ package be.mygod.vpnhotspot.net.wifi
 import android.net.wifi.p2p.WifiP2pGroup
 import android.os.Build
 import be.mygod.vpnhotspot.App.Companion.app
-import be.mygod.vpnhotspot.timberSetString
+import be.mygod.vpnhotspot.DebugHelper
 import be.mygod.vpnhotspot.util.RootSession
 import java.io.File
 
@@ -79,9 +79,9 @@ class P2pSupplicantConfiguration(private val group: WifiP2pGroup, ownerAddress:
                 }
                 Pair(result, target!!)
             } catch (e: RuntimeException) {
-                timberSetString(TAG, parser.lines.joinToString("\n"))
+                DebugHelper.setString(TAG, parser.lines.joinToString("\n"))
-                timberSetString("$TAG.ownerAddress", ownerAddress)
+                DebugHelper.setString("$TAG.ownerAddress", ownerAddress)
-                timberSetString("$TAG.p2pGroup", group.toString())
+                DebugHelper.setString("$TAG.p2pGroup", group.toString())
                 throw e
             }
         }

mobile/src/main/java/be/mygod/vpnhotspot/net/wifi/WifiP2pManagerHelper.kt

@@ -4,8 +4,10 @@ import android.annotation.SuppressLint
 import android.net.wifi.WpsInfo
 import android.net.wifi.p2p.WifiP2pGroup
 import android.net.wifi.p2p.WifiP2pManager
+import be.mygod.vpnhotspot.DebugHelper
 import com.android.dx.stock.ProxyBuilder
 import timber.log.Timber
+import java.lang.IllegalArgumentException
 import java.lang.reflect.Proxy
 
 object WifiP2pManagerHelper {
@@ -27,7 +29,7 @@ object WifiP2pManagerHelper {
         try {
             setWifiP2pChannels.invoke(this, c, lc, oc, listener)
         } catch (e: NoSuchMethodException) {
-            Timber.w(e)
+            DebugHelper.logEvent("NoSuchMethod_setWifiP2pChannels")
             listener.onFailure(UNSUPPORTED)
         }
     }
@@ -45,7 +47,7 @@ object WifiP2pManagerHelper {
         try {
             startWps.invoke(this, c, wps, listener)
         } catch (e: NoSuchMethodException) {
-            Timber.w(e)
+            DebugHelper.logEvent("NoSuchMethod_startWps")
             listener.onFailure(UNSUPPORTED)
         }
     }
@@ -64,7 +66,7 @@ object WifiP2pManagerHelper {
         try {
             deletePersistentGroup.invoke(this, c, netId, listener)
         } catch (e: NoSuchMethodException) {
-            Timber.w(e)
+            DebugHelper.logEvent("NoSuchMethod_deletePersistentGroup")
             listener.onFailure(UNSUPPORTED)
         }
     }
@@ -90,11 +92,11 @@ object WifiP2pManagerHelper {
         val proxy = Proxy.newProxyInstance(interfacePersistentGroupInfoListener.classLoader,
                 arrayOf(interfacePersistentGroupInfoListener)) { proxy, method, args ->
                     if (method.name == "onPersistentGroupInfoAvailable") {
-                        if (args.size != 1) Timber.w("Unexpected args: $args")
+                        if (args.size != 1) Timber.w(IllegalArgumentException("Unexpected args: $args"))
                         listener(getGroupList.invoke(args[0]) as Collection<WifiP2pGroup>)
                         null
                     } else {
-                        Timber.w("Unexpected method, calling super: $method")
+                        Timber.w(IllegalArgumentException("Unexpected method, calling super: $method"))
                         ProxyBuilder.callSuper(proxy, method, args)
                     }
                 }