Skip to content

Commit 77b7c61

Browse files
SessionHero01SessionHero01
authored
Better debug logs in pollers (#1990)
1 parent 8410d6d commit 77b7c61

4 files changed

Lines changed: 54 additions & 45 deletions

File tree

‎app/src/main/java/org/session/libsession/messaging/sending_receiving/pollers/BasePoller.kt‎

Lines changed: 25 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -36,11 +36,11 @@ private typealias PollRequestCallback<T> = SendChannel<Result<T>>
3636
* @param T The type of the result returned by the single polling.
3737
*/
3838
abstract class BasePoller<T>(
39+
private val debugLabel: String,
3940
private val networkConnectivity: NetworkConnectivity,
4041
private val appVisibilityManager: AppVisibilityManager,
4142
private val scope: CoroutineScope,
4243
) {
43-
protected val logTag: String = this::class.java.simpleName
4444

4545
private val manualPollRequestSender: SendChannel<PollRequestCallback<T>>
4646

@@ -80,7 +80,10 @@ abstract class BasePoller<T>(
8080
pollOnce(pollReason)
8181
}.onSuccess { numConsecutiveFailures = 0 }
8282
.onFailure {
83-
if (it is CancellationException) throw it
83+
if (it is CancellationException) {
84+
logE("Polling cancelled", it)
85+
throw it
86+
}
8487
numConsecutiveFailures += 1
8588
}
8689

@@ -101,15 +104,15 @@ abstract class BasePoller<T>(
101104
if (visible) {
102105
true
103106
} else {
104-
Log.d(logTag, "Polling paused - app in background")
107+
log("Polling paused - app in background")
105108
false
106109
}
107110
},
108111
networkConnectivity.networkAvailable.filter { hasNetwork ->
109112
if (hasNetwork) {
110113
true
111114
} else {
112-
Log.d(logTag, "Polling paused - no network connectivity")
115+
log("Polling paused - no network connectivity")
113116
false
114117
}
115118
},
@@ -121,7 +124,7 @@ abstract class BasePoller<T>(
121124
// If we are told we can only start executing from a time, wait until that.
122125
val delayMillis = minStartAt?.elapsedNow()?.let { -it.inWholeMilliseconds }
123126
if (delayMillis != null && delayMillis > 0) {
124-
Log.d(logTag, "Delay next poll for ${delayMillis}ms")
127+
log("Delay next poll for ${delayMillis}ms")
125128
delay(delayMillis)
126129
}
127130
}
@@ -151,19 +154,33 @@ abstract class BasePoller<T>(
151154
*/
152155
protected abstract suspend fun doPollOnce(isFirstPollSinceAppStarted: Boolean): T
153156

157+
/**
158+
* Provides detailed context of this poller for logging.
159+
*/
160+
protected fun log(message: String, e: Throwable? = null) {
161+
Log.d(javaClass.simpleName, "$debugLabel: $message", e)
162+
}
163+
164+
/**
165+
* Provides detailed context of this poller for logging.
166+
*/
167+
protected fun logE(message: String, e: Throwable? = null) {
168+
Log.e(javaClass.simpleName, "$debugLabel: $message", e)
169+
}
170+
154171
private suspend fun pollOnce(reason: String): T {
155172
val lastState = mutablePollState.value
156173
mutablePollState.value =
157174
PollState.Polling(reason, lastPolledResult = lastState.lastPolledResult)
158-
Log.d(logTag, "Start $reason polling")
175+
log("Start $reason polling")
159176
val result = runCatching {
160177
doPollOnce(isFirstPollSinceAppStarted = lastState is PollState.Idle)
161178
}
162179

163180
if (result.isSuccess) {
164-
Log.d(logTag, "$reason polling succeeded")
181+
log("$reason polling succeeded")
165182
} else if (result.exceptionOrNull() !is CancellationException) {
166-
Log.e(logTag, "$reason polling failed", result.exceptionOrNull())
183+
logE("$reason polling failed", result.exceptionOrNull())
167184
}
168185

169186
mutablePollState.value = PollState.Polled(

‎app/src/main/java/org/session/libsession/messaging/sending_receiving/pollers/OpenGroupPoller.kt‎

Lines changed: 7 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,6 @@ import org.session.libsession.messaging.sending_receiving.ReceivedMessageProcess
2929
import org.session.libsession.utilities.Address
3030
import org.session.libsession.utilities.ConfigFactoryProtocol
3131
import org.session.libsession.utilities.withUserConfigs
32-
import org.session.libsignal.utilities.Log
3332
import org.thoughtcrime.securesms.database.CommunityDatabase
3433
import org.thoughtcrime.securesms.util.AppVisibilityManager
3534
import org.thoughtcrime.securesms.util.NetworkConnectivity
@@ -64,7 +63,8 @@ class OpenGroupPoller @AssistedInject constructor(
6463
): BasePoller<Unit>(
6564
networkConnectivity = networkConnectivity,
6665
scope = scope,
67-
appVisibilityManager = appVisibilityManager
66+
appVisibilityManager = appVisibilityManager,
67+
debugLabel = "OpenGroupPoller($server)"
6868
) {
6969
override val successfulPollIntervalSeconds: Int
7070
get() = 4
@@ -243,8 +243,7 @@ class OpenGroupPoller @AssistedInject constructor(
243243
message = msg,
244244
)
245245
} catch (e: Exception) {
246-
Log.e(
247-
logTag,
246+
logE(
248247
"Error processing open group message ${msg.id} in ${threadAddress.debugString}",
249248
e
250249
)
@@ -276,7 +275,7 @@ class OpenGroupPoller @AssistedInject constructor(
276275

277276
val serverPubKeyHex = storage.getOpenGroupPublicKey(server)
278277
?: run {
279-
Log.e(logTag, "No community server public key cannot process inbox messages")
278+
log("No community server public key cannot process inbox messages")
280279
return
281280
}
282281

@@ -293,7 +292,7 @@ class OpenGroupPoller @AssistedInject constructor(
293292
)
294293

295294
} catch (e: Exception) {
296-
Log.e(logTag, "Error processing inbox message", e)
295+
logE("Error processing inbox message", e)
297296
}
298297
}
299298
}
@@ -310,7 +309,7 @@ class OpenGroupPoller @AssistedInject constructor(
310309

311310
val serverPubKeyHex = storage.getOpenGroupPublicKey(server)
312311
?: run {
313-
Log.e(logTag, "No community server public key cannot process inbox messages")
312+
logE("No community server public key cannot process inbox messages")
314313
return
315314
}
316315

@@ -327,7 +326,7 @@ class OpenGroupPoller @AssistedInject constructor(
327326
)
328327

329328
} catch (e: Exception) {
330-
Log.e(logTag, "Error processing outbox message", e)
329+
logE("Error processing outbox message", e)
331330
}
332331
}
333332
}

‎app/src/main/java/org/session/libsession/messaging/sending_receiving/pollers/Poller.kt‎

Lines changed: 13 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -6,11 +6,8 @@ import dagger.assisted.AssistedInject
66
import kotlinx.coroutines.CancellationException
77
import kotlinx.coroutines.CoroutineScope
88
import kotlinx.coroutines.async
9-
import kotlinx.coroutines.awaitAll
10-
import kotlinx.coroutines.delay
119
import kotlinx.coroutines.launch
1210
import kotlinx.coroutines.supervisorScope
13-
1411
import kotlinx.coroutines.withTimeoutOrNull
1512
import network.loki.messenger.libsession_util.Namespace
1613
import org.session.libsession.database.StorageProtocol
@@ -28,7 +25,6 @@ import org.session.libsession.utilities.ConfigMessage
2825
import org.session.libsession.utilities.UserConfigType
2926
import org.session.libsession.utilities.withUserConfigs
3027
import org.session.libsignal.database.LokiAPIDatabaseProtocol
31-
import org.session.libsignal.utilities.Log
3228
import org.session.libsignal.utilities.Snode
3329
import org.thoughtcrime.securesms.api.snode.AlterTtlApi
3430
import org.thoughtcrime.securesms.api.snode.RetrieveMessageApi
@@ -66,6 +62,7 @@ class Poller @AssistedInject constructor(
6662
appVisibilityManager: AppVisibilityManager,
6763
@Assisted scope: CoroutineScope
6864
) : BasePoller<Unit>(
65+
debugLabel = "MainPoller",
6966
networkConnectivity = networkConnectivity,
7067
scope = scope,
7168
appVisibilityManager = appVisibilityManager
@@ -114,11 +111,11 @@ class Poller @AssistedInject constructor(
114111
// region Private API
115112
private fun processPersonalMessages(messages: List<RetrieveMessageResponse.Message>) {
116113
if (messages.isEmpty()) {
117-
Log.d(logTag, "No personal messages to process")
114+
log("No personal messages to process")
118115
return
119116
}
120117

121-
Log.d(logTag, "Received ${messages.size} personal messages from snode")
118+
log("Received ${messages.size} personal messages from snode")
122119

123120
processor.startProcessing("Poller") { ctx ->
124121
for (message in messages) {
@@ -127,7 +124,7 @@ class Poller @AssistedInject constructor(
127124
namespace = Namespace.DEFAULT(),
128125
hash = message.hash
129126
)) {
130-
Log.d(logTag, "Skipping duplicated message ${message.hash}")
127+
log("Skipping duplicated message ${message.hash}")
131128
continue
132129
}
133130

@@ -147,19 +144,15 @@ class Poller @AssistedInject constructor(
147144
pro = result.pro,
148145
)
149146
} catch (ec: Exception) {
150-
Log.e(
151-
logTag,
152-
"Error while processing personal message with hash ${message.hash}",
153-
ec
154-
)
147+
logE("Error while processing personal message with hash ${message.hash}", ec)
155148
}
156149
}
157150
}
158151
}
159152

160153
private fun processConfig(messages: List<RetrieveMessageResponse.Message>, forConfig: UserConfigType) {
161154
if (messages.isEmpty()) {
162-
Log.d(logTag, "No messages to process for $forConfig")
155+
log("No messages to process for $forConfig")
163156
return
164157
}
165158

@@ -182,11 +175,11 @@ class Poller @AssistedInject constructor(
182175
messages = newMessages
183176
)
184177
} catch (e: Exception) {
185-
Log.e(logTag, "Error while merging user configs for $forConfig", e)
178+
logE("Error while merging user configs for $forConfig", e)
186179
}
187180
}
188181

189-
Log.d(logTag, "Processed ${newMessages.size} new messages for config $forConfig")
182+
log("Processed ${newMessages.size} new messages for config $forConfig")
190183
}
191184

192185
private fun RetrieveMessageResponse.Message.toConfigMessage(): ConfigMessage {
@@ -276,7 +269,7 @@ class Poller @AssistedInject constructor(
276269
} catch (e: Exception) {
277270
if (e is CancellationException) throw e
278271

279-
Log.e(logTag, "Error while extending TTL for hashes", e)
272+
logE("Error while extending TTL for hashes", e)
280273
}
281274
}
282275
}
@@ -325,7 +318,7 @@ class Poller @AssistedInject constructor(
325318
"Swarm is empty for user ${auth.accountId.hexString}"
326319
}
327320

328-
Log.d(logTag, "Start initial user profile polling from ${swarm.size} snodes")
321+
log("Start initial user profile polling from ${swarm.size} snodes")
329322

330323
val fetchMessageTasks = swarm.map { snode ->
331324
snode to async {
@@ -353,7 +346,7 @@ class Poller @AssistedInject constructor(
353346
deferred.await()
354347
}.onFailure { e ->
355348
if (e is CancellationException) throw e
356-
Log.d(logTag, "Error polling initial config from $snode")
349+
log("Error polling initial config from $snode")
357350
}
358351
}
359352

@@ -376,7 +369,7 @@ class Poller @AssistedInject constructor(
376369
}
377370

378371
else -> {
379-
Log.e(logTag, "Failed to fetch initial profile config from one snode", result.exceptionOrNull())
372+
logE("Failed to fetch initial profile config from one snode", result.exceptionOrNull())
380373
emptySequence()
381374
}
382375
}
@@ -389,7 +382,7 @@ class Poller @AssistedInject constructor(
389382
messages = messages
390383
)
391384

392-
Log.d(logTag, "Merged ${messages.size} config messages for initial profile poll")
385+
log("Merged ${messages.size} config messages for initial profile poll")
393386
}
394387
}
395388

‎app/src/main/java/org/thoughtcrime/securesms/groups/GroupPoller.kt‎

Lines changed: 9 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,11 @@ import org.session.libsession.utilities.Address
2020
import org.session.libsession.utilities.ConfigFactoryProtocol
2121
import org.session.libsession.utilities.ConfigMessage
2222
import org.session.libsession.utilities.getGroup
23+
import org.session.libsession.utilities.truncatedForDisplay
2324
import org.session.libsession.utilities.withGroupConfigs
2425
import org.session.libsignal.database.LokiAPIDatabaseProtocol
2526
import org.session.libsignal.exceptions.NonRetryableException
2627
import org.session.libsignal.utilities.AccountId
27-
import org.session.libsignal.utilities.Log
2828
import org.session.libsignal.utilities.Snode
2929
import org.thoughtcrime.securesms.api.snode.AlterTtlApi
3030
import org.thoughtcrime.securesms.api.snode.RetrieveMessageApi
@@ -58,7 +58,8 @@ class GroupPoller @AssistedInject constructor(
5858
): BasePoller<GroupPoller.GroupPollResult>(
5959
networkConnectivity = networkConnectivity,
6060
appVisibilityManager = appVisibilityManager,
61-
scope = scope
61+
scope = scope,
62+
debugLabel = "GroupPoller(${groupId.truncatedForDisplay()})"
6263
) {
6364
data class GroupPollResult(
6465
val groupExpired: Boolean?
@@ -90,7 +91,7 @@ class GroupPoller @AssistedInject constructor(
9091
throw NonRetryableException("Group has been kicked")
9192
}
9293

93-
Log.v(logTag, "Start polling group($groupId) message snode = ${snode.ip}")
94+
log("Start polling group($groupId) message snode = ${snode.ip}")
9495

9596
val adminKey = group.adminKey
9697

@@ -235,7 +236,7 @@ class GroupPoller @AssistedInject constructor(
235236
}
236237
}
237238

238-
Log.d(logTag, "Group($groupId) polling completed, success = ${result.isSuccess}")
239+
log("Group($groupId) polling completed, success = ${result.isSuccess}")
239240

240241
result.getOrThrow()
241242

@@ -276,8 +277,7 @@ class GroupPoller @AssistedInject constructor(
276277
return
277278
}
278279

279-
Log.d(
280-
logTag, "Handling group config messages(" +
280+
log("Handling group config messages(" +
281281
"info = ${infoResponse.size}, " +
282282
"keys = ${keysResponse.size}, " +
283283
"members = ${membersResponse.size})"
@@ -306,7 +306,7 @@ class GroupPoller @AssistedInject constructor(
306306
namespace = Namespace.GROUP_MESSAGES(),
307307
hash = message.hash
308308
)) {
309-
Log.v(logTag, "Skipping duplicated group message ${message.hash} for group $groupId")
309+
log("Skipping duplicated group message ${message.hash}")
310310
continue
311311
}
312312

@@ -327,12 +327,12 @@ class GroupPoller @AssistedInject constructor(
327327
pro = result.pro,
328328
)
329329
} catch (e: Exception) {
330-
Log.e(logTag, "Error handling group message", e)
330+
logE("Error handling group message", e)
331331
}
332332
}
333333
}
334334

335-
Log.d(logTag, "Handled ${messages.size} group messages for $groupId in ${System.currentTimeMillis() - start}ms")
335+
log("Handled ${messages.size} group messages in ${System.currentTimeMillis() - start}ms")
336336
}
337337

338338
@AssistedFactory

0 commit comments

Comments
 (0)