Additional logging

app/src/generic/java/org/tasks/analytics/Firebase.kt

@@ -1,5 +1,8 @@
 package org.tasks.analytics
 
+import android.content.Context
+import dagger.hilt.android.qualifiers.ApplicationContext
+import org.tasks.R
 import org.tasks.preferences.Preferences
 import org.tasks.time.DateTimeUtils2.currentTimeMillis
 import timber.log.Timber
@@ -8,17 +11,22 @@ import javax.inject.Inject
 
 @Suppress("UNUSED_PARAMETER")
 class Firebase @Inject constructor(
+    @param:ApplicationContext val context: Context,
     private val preferences: Preferences
 ) {
     fun reportException(t: Throwable) = Timber.e(t)
 
     fun updateRemoteConfig() {}
 
-    fun logEvent(event: Int, vararg params: Pair<Int, Any>) {}
+    fun logEvent(event: Int, vararg params: Pair<Int, Any>) {
+        Timber.d("${context.getString(event)} -> $params")
+    }
 
-    fun addTask(source: String) {}
+    fun addTask(source: String) =
+        logEvent(R.string.event_add_task, R.string.param_type to source)
 
-    fun completeTask(source: String) {}
+    fun completeTask(source: String) =
+        logEvent(R.string.event_complete_task, R.string.param_type to source)
 
     val subscribeCooldown: Boolean
         get() = installCooldown

app/src/googleplay/java/org/tasks/analytics/Firebase.kt

@@ -53,7 +53,9 @@ class Firebase @Inject constructor(
         logEvent(R.string.event_complete_task, R.string.param_type to source)
 
     fun logEvent(@StringRes event: Int, vararg p: Pair<Int, Any>) {
-        analytics?.logEvent(context.getString(event), Bundle().apply {
+        val eventName = context.getString(event)
+        Timber.d("$eventName -> $p")
+        analytics?.logEvent(eventName, Bundle().apply {
             p.forEach {
                 val key = context.getString(it.first)
                 when (it.second::class) {

app/src/main/java/com/todoroo/astrid/activity/TaskListFragment.kt

@@ -151,6 +151,7 @@ import org.tasks.ui.TaskListEvent
 import org.tasks.ui.TaskListEventBus
 import org.tasks.ui.TaskListViewModel
 import org.tasks.ui.TaskListViewModel.Companion.createSearchQuery
+import timber.log.Timber
 import java.util.Locale
 import javax.inject.Inject
 import kotlin.math.max
@@ -1056,6 +1057,7 @@ class TaskListFragment : Fragment(), OnRefreshListener, Toolbar.OnMenuItemClickL
                 val tasks =
                     (intent.getSerializableExtra(EXTRAS_TASK_ID) as? ArrayList<Long>)
                         ?.let {
+                            Timber.d("Repeating tasks: $it")
                             // hack to wait for task save transaction to complete
                             database.withTransaction {
                                 taskDao.fetch(it)

app/src/main/java/com/todoroo/astrid/service/TaskCompleter.kt

@@ -71,6 +71,7 @@ class TaskCompleter @Inject internal constructor(
         tasks.forEach { notificationManager.cancel(it.id) }
         val completed = completionDate > 0
         val modified = currentTimeMillis()
+        Timber.d("Completing $tasks")
         database.withTransaction {
             alarmDao.deleteSnoozed(tasks.map { it.id })
             tasks

app/src/main/java/com/todoroo/astrid/service/TaskDeleter.kt

@@ -21,6 +21,7 @@ import org.tasks.files.FileHelper
 import org.tasks.location.GeofenceApi
 import org.tasks.notifications.NotificationManager
 import org.tasks.sync.SyncAdapters
+import timber.log.Timber
 import javax.inject.Inject
 
 class TaskDeleter @Inject constructor(
@@ -46,6 +47,7 @@ class TaskDeleter @Inject constructor(
             .let { taskDao.fetch(it.toList()) }
             .filterNot { it.readOnly }
             .map { it.id }
+        Timber.d("markDeleted $ids")
         database.withTransaction {
             deletionDao.markDeleted(ids)
             cleanup(ids)
@@ -60,6 +62,7 @@ class TaskDeleter @Inject constructor(
     suspend fun delete(task: Long) = delete(listOf(task))
 
     suspend fun delete(tasks: List<Long>) {
+        Timber.d("Deleting $tasks")
         database.withTransaction {
             deletionDao.delete(tasks)
             cleanup(tasks)
@@ -69,6 +72,7 @@ class TaskDeleter @Inject constructor(
 
     suspend fun delete(list: CaldavCalendar) {
         vtodoCache.delete(list)
+        Timber.d("Deleting $list")
         database.withTransaction {
             val tasks = deletionDao.delete(list)
             delete(tasks)
@@ -78,6 +82,7 @@ class TaskDeleter @Inject constructor(
 
     suspend fun delete(account: CaldavAccount) {
         vtodoCache.delete(account)
+        Timber.d("Deleting $account")
         database.withTransaction {
             val tasks = deletionDao.delete(account)
             delete(tasks)

app/src/main/java/org/tasks/caldav/CaldavSynchronizer.kt

@@ -98,6 +98,7 @@ class CaldavSynchronizer @Inject constructor(
     private val vtodoCache: VtodoCache,
 ) {
     suspend fun sync(account: CaldavAccount) {
+        Timber.d("Synchronizing $account")
         Thread.currentThread().contextClassLoader = context.classLoader
 
         if (!inventory.hasPro && !account.isTasksOrg) {

app/src/main/java/org/tasks/caldav/VtodoCache.kt

@@ -6,6 +6,7 @@ import org.tasks.data.dao.CaldavDao
 import org.tasks.data.entity.CaldavAccount
 import org.tasks.data.entity.CaldavCalendar
 import org.tasks.data.entity.CaldavTask
+import timber.log.Timber
 import java.io.File
 import javax.inject.Inject
 import javax.inject.Singleton
@@ -28,7 +29,8 @@ class VtodoCache @Inject constructor(
                     ?.let { File(it, task.obj!!) }
                     ?: return@withContext
             source.copyTo(target, overwrite = true)
-            source.delete()
+            val deleted = source.delete()
+            Timber.d("Moved $source to $target [success=${deleted}]")
         }
 
     suspend fun getVtodo(caldavTask: CaldavTask?): String? {
@@ -65,20 +67,30 @@ class VtodoCache @Inject constructor(
     }
 
     suspend fun delete(calendar: CaldavCalendar, caldavTask: CaldavTask) = withContext(Dispatchers.IO) {
-        fileStorage
-            .getFile(calendar.account, caldavTask.calendar, caldavTask.obj)
-            ?.delete()
+        fileStorage.getFile(calendar.account, caldavTask.calendar, caldavTask.obj)?.let {
+            val deleted = it.delete()
+            Timber.d("Deleting $it [success=$deleted]")
+        }
     }
 
     suspend fun delete(calendar: CaldavCalendar) = withContext(Dispatchers.IO) {
-        fileStorage.getFile(calendar.account, calendar.uuid)?.deleteRecursively()
+        fileStorage.getFile(calendar.account, calendar.uuid)?.let {
+            val deleted = it.deleteRecursively()
+            Timber.d("Deleting $it [success=$deleted]")
+        }
     }
 
     suspend fun delete(account: CaldavAccount) = withContext(Dispatchers.IO) {
-        fileStorage.getFile(account.uuid)?.deleteRecursively()
+        fileStorage.getFile(account.uuid)?.let {
+            val deleted = it.deleteRecursively()
+            Timber.d("Deleting $it [success=$deleted]")
+        }
     }
 
     suspend fun clear() = withContext(Dispatchers.IO) {
-        fileStorage.getFile()?.deleteRecursively()
+        fileStorage.getFile()?.let {
+            val deleted = it.deleteRecursively()
+            Timber.d("Deleting $it [success=$deleted]")
+        }
     }
 }

app/src/main/java/org/tasks/etebase/EtebaseSynchronizer.kt

@@ -46,6 +46,7 @@ class EtebaseSynchronizer @Inject constructor(
     }
 
     suspend fun sync(account: CaldavAccount) {
+        Timber.d("Synchronizing $account")
         Thread.currentThread().contextClassLoader = context.classLoader
 
         if (!inventory.hasPro) {

app/src/main/java/org/tasks/gtasks/GoogleTaskSynchronizer.kt

@@ -60,7 +60,7 @@ class GoogleTaskSynchronizer @Inject constructor(
     private val invokers: InvokerFactory,
     private val alarmDao: AlarmDao,
 ) {
-    suspend fun sync(account: CaldavAccount, i: Int) {
+    suspend fun sync(account: CaldavAccount) {
         Timber.d("%s: start sync", account)
         try {
             synchronize(account)

app/src/main/java/org/tasks/jobs/SyncWork.kt

@@ -37,6 +37,7 @@ import org.tasks.opentasks.OpenTasksSynchronizer
 import org.tasks.preferences.Preferences
 import org.tasks.sync.microsoft.MicrosoftSynchronizer
 import org.tasks.time.DateTimeUtils2.currentTimeMillis
+import timber.log.Timber
 
 @HiltWorker
 class SyncWork @AssistedInject constructor(
@@ -56,9 +57,11 @@ class SyncWork @AssistedInject constructor(
 ) : BaseWorker(context, workerParams, firebase) {
 
     override suspend fun run(): Result {
+        Timber.d("Starting...")
         if (isBackground) {
             ContextCompat.getSystemService(context, ConnectivityManager::class.java)?.apply {
                 if (restrictBackgroundStatus == ConnectivityManagerCompat.RESTRICT_BACKGROUND_STATUS_ENABLED) {
+                    Timber.w("Background restrictions enabled, skipping sync")
                     return Result.failure()
                 }
             }
@@ -66,6 +69,7 @@ class SyncWork @AssistedInject constructor(
 
         synchronized(LOCK) {
             if (preferences.getBoolean(syncStatus, false)) {
+                Timber.e("Sync ongoing")
                 return Result.retry()
             }
             preferences.setBoolean(syncStatus, true)
@@ -103,12 +107,13 @@ class SyncWork @AssistedInject constructor(
         if (openTaskDao.shouldSync()) {
             openTasksSynchronizer.get().sync()
 
-            if (isImmediate && hasNetworkConnectivity) {
+            if (isImmediate) {
                 AccountManager
                     .get(context)
                     .accounts
                     .filter { OpenTaskDao.SUPPORTED_TYPES.contains(it.type) }
                     .forEach {
+                        Timber.d("Requesting sync for $it")
                         ContentResolver.requestSync(
                             it,
                             openTaskDao.authority,
@@ -124,9 +129,9 @@ class SyncWork @AssistedInject constructor(
 
     private suspend fun googleTaskJobs(): List<Deferred<Unit>> = coroutineScope {
         getGoogleAccounts()
-            .mapIndexed { i, account ->
+            .map { account ->
                 async(Dispatchers.IO) {
-                    googleTaskSynchronizer.get().sync(account, i)
+                    googleTaskSynchronizer.get().sync(account)
                 }
             }
     }

app/src/main/java/org/tasks/opentasks/OpenTasksSynchronizer.kt

@@ -44,6 +44,7 @@ class OpenTasksSynchronizer @Inject constructor(
     private val inventory: Inventory) {
 
     suspend fun sync() {
+        Timber.d("Starting OpenTasks sync...")
         val lists = openTaskDao.getListsByAccount().filterActive(caldavDao)
         lists.keys
             .filter { caldavDao.getAccountByUuid(it) == null }
@@ -70,6 +71,7 @@ class OpenTasksSynchronizer @Inject constructor(
         caldavDao.getAccounts(CaldavAccount.TYPE_OPENTASKS).forEach { account ->
             val entries = lists[account.uuid!!]
             if (entries == null) {
+                Timber.d("Removing $account")
                 taskDeleter.delete(account)
             } else if (!inventory.hasPro) {
                 setError(account, context.getString(R.string.requires_pro_subscription))
@@ -86,10 +88,14 @@ class OpenTasksSynchronizer @Inject constructor(
     }
 
     private suspend fun sync(account: CaldavAccount, lists: List<CaldavCalendar>) {
+        Timber.d("Synchronizing $account")
         val uuid = account.uuid!!
         caldavDao
                 .findDeletedCalendars(uuid, lists.mapNotNull { it.url })
-                .forEach { taskDeleter.delete(it) }
+                .forEach {
+                    Timber.d("Deleting $it")
+                    taskDeleter.delete(it)
+                }
         lists.forEach {
             val calendar = toLocalCalendar(it)
             if (calendar.access != CaldavCalendar.ACCESS_READ_ONLY) {
@@ -130,11 +136,19 @@ class OpenTasksSynchronizer @Inject constructor(
         val (deleted, updated) = taskDao
             .getCaldavTasksToPush(calendar.uuid!!)
             .partition { it.isDeleted }
-
-        (moved + deleted.map(Task::id).let { caldavDao.getTasks(it) })
+        if (moved.isEmpty() && deleted.isEmpty() && updated.isEmpty()) {
+            return
+        }
+        Timber.d("Pushing changes: updated=${updated.size} moved=${moved.size} deleted=${deleted.size}")
+        (moved + deleted.map(Task::id)
+            .let { caldavDao.getTasks(it) })
             .mapNotNull { it.remoteId }
-            .map { openTaskDao.delete(listId, it) }
-            .let { openTaskDao.batch(it) }
+            .takeIf { it.isNotEmpty() }
+            ?.map { openTaskDao.delete(listId, it) }
+            ?.let {
+                Timber.d("Deleting ${it.size} from content provider")
+                openTaskDao.batch(it)
+            }
         caldavDao.delete(moved)
         taskDeleter.delete(deleted.map { it.id })
 

app/src/main/java/org/tasks/sync/microsoft/MicrosoftSynchronizer.kt

@@ -10,7 +10,6 @@ import com.todoroo.astrid.service.TaskDeleter
 import dagger.hilt.android.qualifiers.ApplicationContext
 import io.ktor.client.call.body
 import io.ktor.http.isSuccess
-import kotlinx.serialization.encodeToString
 import kotlinx.serialization.json.Json
 import org.tasks.LocalBroadcastManager
 import org.tasks.Strings.isNullOrEmpty
@@ -62,6 +61,7 @@ class MicrosoftSynchronizer @Inject constructor(
     private val vtodoCache: VtodoCache,
 ) {
     suspend fun sync(account: CaldavAccount) {
+        Timber.d("Synchronizing $account")
         Thread.currentThread().contextClassLoader = context.classLoader
 
         if (isNullOrEmpty(account.password)) {

data/src/commonMain/kotlin/org/tasks/data/dao/CaldavDao.kt

@@ -6,6 +6,7 @@ import androidx.room.Insert
 import androidx.room.OnConflictStrategy
 import androidx.room.Query
 import androidx.room.Update
+import co.touchlab.kermit.Logger
 import kotlinx.coroutines.flow.Flow
 import org.tasks.data.CaldavFilters
 import org.tasks.data.CaldavTaskContainer
@@ -101,8 +102,9 @@ ORDER BY CASE cda_account_type
     @Update
     abstract suspend fun update(caldavCalendar: CaldavCalendar)
 
-    suspend fun insert(task: Task, caldavTask: CaldavTask, addToTop: Boolean): Long =
-        database.withTransaction {
+    suspend fun insert(task: Task, caldavTask: CaldavTask, addToTop: Boolean): Long {
+        Logger.d("CaldavDao") { "insert task=$task caldavTask=$caldavTask addToTop=$addToTop)" }
+        return database.withTransaction {
             if (task.order != null) {
                 return@withTransaction insert(caldavTask)
             }
@@ -119,6 +121,7 @@ ORDER BY CASE cda_account_type
             update(task)
             id
         }
+    }
 
     @Query("""
 SELECT MIN(IFNULL(`order`, (created - $APPLE_EPOCH) / 1000))
@@ -312,6 +315,7 @@ GROUP BY caldav_lists.cdl_uuid
         newParent: Long,
         newPosition: Long?,
     ) {
+        Logger.d("CaldavDao") { "move task=$task previousParent=$previousParent newParent=$newParent newPosition=$newPosition" }
         database.withTransaction {
             val previousPosition = task.caldavSortOrder
             if (newPosition != null) {
@@ -329,6 +333,7 @@ GROUP BY caldav_lists.cdl_uuid
     }
 
     suspend fun shiftDown(calendar: String, parent: Long, from: Long, to: Long? = null) {
+        Logger.d("CaldavDao") { "shiftDown calendar=$calendar parent=$parent from=$from to=$to" }
         database.withTransaction {
             val updated = ArrayList<Task>()
             val tasks = getTasksToShift(calendar, parent, from, to)

data/src/commonMain/kotlin/org/tasks/data/dao/DeletionDao.kt

@@ -3,6 +3,7 @@ package org.tasks.data.dao
 import androidx.room.Dao
 import androidx.room.Delete
 import androidx.room.Query
+import co.touchlab.kermit.Logger
 import org.tasks.data.dao.CaldavDao.Companion.LOCAL
 import org.tasks.data.db.Database
 import org.tasks.data.db.SuspendDbUtils.chunkedMap
@@ -59,13 +60,15 @@ WHERE recurring = 1
     @Delete
     internal abstract suspend fun deleteCaldavCalendar(caldavCalendar: CaldavCalendar)
 
-    suspend fun delete(caldavCalendar: CaldavCalendar): List<Long> =
-        database.withTransaction {
+    suspend fun delete(caldavCalendar: CaldavCalendar): List<Long> {
+        Logger.d("DeletionDao") { "deleting $caldavCalendar" }
+        return database.withTransaction {
             val tasks = getActiveCaldavTasks(caldavCalendar.uuid!!)
             delete(tasks)
             deleteCaldavCalendar(caldavCalendar)
             tasks
         }
+    }
 
     @Query("SELECT * FROM caldav_lists WHERE cdl_account = :account")
     abstract suspend fun getCalendars(account: String): List<CaldavCalendar>
@@ -76,8 +79,9 @@ WHERE recurring = 1
     @Query("DELETE FROM tasks WHERE _id IN (SELECT _id FROM tasks INNER JOIN caldav_tasks ON _id = cd_task INNER JOIN caldav_lists ON cdl_uuid = cd_calendar WHERE cdl_account = '$LOCAL' AND deleted > 0 AND cd_deleted = 0)")
     abstract suspend fun purgeDeleted()
 
-    suspend fun delete(caldavAccount: CaldavAccount): List<Long> =
-        database.withTransaction {
+    suspend fun delete(caldavAccount: CaldavAccount): List<Long> {
+        Logger.d("DeletionDao") { "deleting $caldavAccount" }
+        return database.withTransaction {
             val deleted = ArrayList<Long>()
             for (calendar in getCalendars(caldavAccount.uuid!!)) {
                 deleted.addAll(delete(calendar))
@@ -86,3 +90,4 @@ WHERE recurring = 1
             deleted
         }
     }
+}

data/src/commonMain/kotlin/org/tasks/data/dao/GoogleTaskDao.kt

@@ -5,6 +5,7 @@ import androidx.room.Delete
 import androidx.room.Insert
 import androidx.room.Query
 import androidx.room.Update
+import co.touchlab.kermit.Logger
 import org.tasks.data.db.Database
 import org.tasks.data.entity.CaldavAccount.Companion.TYPE_GOOGLE_TASKS
 import org.tasks.data.entity.CaldavTask
@@ -20,6 +21,7 @@ abstract class GoogleTaskDao(private val database: Database) {
     abstract suspend fun insert(tasks: Iterable<CaldavTask>)
 
     suspend fun insertAndShift(task: Task, caldavTask: CaldavTask, top: Boolean) {
+        Logger.d("GoogleTaskDao") { "insertAndShift task=$task caldavTask=$caldavTask top=$top" }
         database.withTransaction {
             if (top) {
                 task.order = 0
@@ -45,6 +47,7 @@ abstract class GoogleTaskDao(private val database: Database) {
     internal abstract suspend fun shiftUp(listId: String, parent: Long, position: Long)
 
     suspend fun move(task: Task, list: String, newParent: Long, newPosition: Long) {
+        Logger.d("GoogleTaskDao") { "move task=$task list=$list newParent=$newParent newPosition=$newPosition" }
         database.withTransaction {
             val previousParent = task.parent
             val previousPosition = task.order!!
@@ -166,6 +169,7 @@ WHERE cd_remote_id = :id
     abstract suspend fun updatePosition(id: String, parent: String?, position: String)
 
     suspend fun reposition(caldavDao: CaldavDao, listId: String) {
+        Logger.d("GoogleTaskDao") { "reposition listId=$listId" }
         database.withTransaction {
             caldavDao.updateParents(listId)
             val orderedTasks = getByRemoteOrder(listId)

data/src/commonMain/kotlin/org/tasks/data/dao/PrincipalDao.kt

@@ -5,6 +5,7 @@ import androidx.room.Delete
 import androidx.room.Insert
 import androidx.room.Query
 import androidx.room.Update
+import co.touchlab.kermit.Logger
 import kotlinx.coroutines.flow.Flow
 import org.tasks.data.PrincipalWithAccess
 import org.tasks.data.db.Database
@@ -35,9 +36,12 @@ WHERE list = :list
     @Delete
     abstract suspend fun delete(access: PrincipalAccess)
 
-    suspend fun getAll(): List<PrincipalWithAccess> = database.withTransaction {
+    suspend fun getAll(): List<PrincipalWithAccess> {
+        Logger.d("PrincipalDao") { "getAll" }
+        return database.withTransaction {
             getAllInternal()
         }
+    }
 
     @Query("SELECT * FROM principal_access")
     internal abstract suspend fun getAllInternal(): List<PrincipalWithAccess>

data/src/commonMain/kotlin/org/tasks/data/dao/TagDao.kt

@@ -4,6 +4,7 @@ import androidx.room.Dao
 import androidx.room.Delete
 import androidx.room.Insert
 import androidx.room.Query
+import co.touchlab.kermit.Logger
 import org.tasks.data.db.Database
 import org.tasks.data.entity.Tag
 import org.tasks.data.entity.TagData
@@ -37,6 +38,7 @@ abstract class TagDao(private val database: Database) {
     abstract suspend fun delete(tags: List<Tag>)
 
     open suspend fun applyTags(task: Task, tagDataDao: TagDataDao, current: Collection<TagData>) {
+        Logger.d("TagDao") { "applyTags task=$task current=$current" }
         database.withTransaction {
             val taskId = task.id
             val existing = HashSet(tagDataDao.getTagDataForTask(taskId))

data/src/commonMain/kotlin/org/tasks/data/dao/TagDataDao.kt

@@ -5,6 +5,7 @@ import androidx.room.Delete
 import androidx.room.Insert
 import androidx.room.Query
 import androidx.room.Update
+import co.touchlab.kermit.Logger
 import kotlinx.coroutines.flow.Flow
 import org.tasks.data.NO_ORDER
 import org.tasks.data.TagFilters
@@ -84,7 +85,9 @@ abstract class TagDataDao(private val database: Database) {
         tasks: List<Task>,
         partiallySelected: List<TagData>,
         selected: List<TagData>
-    ): List<Long> = database.withTransaction {
+    ): List<Long> {
+        Logger.d("TagDataDao") { "applyTags tasks=$tasks partiallySelected=$partiallySelected selected=$selected" }
+        return database.withTransaction {
             val modified = HashSet<Long>()
             val keep = partiallySelected.plus(selected).map { it.remoteId!! }
             for (sublist in tasks.chunked(DbUtils.MAX_SQLITE_ARGS - keep.size)) {
@@ -110,8 +113,10 @@ abstract class TagDataDao(private val database: Database) {
             }
             ArrayList(modified)
         }
+    }
 
     suspend fun delete(tagData: TagData) {
+        Logger.d("TagDataDao") { "deleting $tagData" }
         database.withTransaction {
             deleteTags(tagData.remoteId!!)
             deleteTagData(tagData)

kmp/src/commonMain/kotlin/org/tasks/data/TaskListQuery.kt

@@ -56,6 +56,6 @@ object TaskListQuery {
                 getRecursiveQuery(filter, preferences)
 
             else -> getNonRecursiveQuery(filter, preferences)
-        }.also { Logger.v { "Building query took ${currentTimeMillis() - start}ms" } }
+        }.also { Logger.v("TaskListQuery") { "Building query took ${currentTimeMillis() - start}ms" } }
     }
 }