From 024cb66d37a21ae1b29643b5bdca5f3796cb7973 Mon Sep 17 00:00:00 2001
From: Matthias Urhahn <darken@darken.eu>
Date: Thu, 27 Aug 2020 09:30:51 +0200
Subject: [PATCH] Improve transaction logging (#1061) (Spawned by
EXPOSUREAPP-2267)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Add explicit tags to allow for type specific filtering and fix bad log statements.
Move OkHttp web logging to VERBOSE (from INFO).
Co-authored-by: Matthias Urhahn <matthias.urhahn@sap.com>
Co-authored-by: Jakob Möller <jakob.moeller@sap.com>
---
.../rki/coronawarnapp/http/ServiceFactory.kt | 9 ++-
.../RetrieveDiagnosisKeysTransaction.kt | 14 ++--
.../transaction/RiskLevelTransaction.kt | 70 +++++++++++--------
.../coronawarnapp/transaction/Transaction.kt | 8 +--
4 files changed, 58 insertions(+), 43 deletions(-)
diff --git a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/http/ServiceFactory.kt b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/http/ServiceFactory.kt
index ae9366bfd..9e383ff44 100644
--- a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/http/ServiceFactory.kt
+++ b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/http/ServiceFactory.kt
@@ -22,6 +22,7 @@ import okhttp3.logging.HttpLoggingInterceptor
import retrofit2.Retrofit
import retrofit2.converter.gson.GsonConverterFactory
import retrofit2.converter.protobuf.ProtoConverterFactory
+import timber.log.Timber
import java.io.File
import java.util.concurrent.TimeUnit
@@ -43,8 +44,12 @@ class ServiceFactory {
*/
private val mInterceptors: List<Interceptor> = listOf(
WebSecurityVerificationInterceptor(),
- HttpLoggingInterceptor().also {
- if (BuildConfig.DEBUG) it.setLevel(HttpLoggingInterceptor.Level.BODY)
+ HttpLoggingInterceptor(object : HttpLoggingInterceptor.Logger {
+ override fun log(message: String) {
+ Timber.tag("OkHttp").v(message)
+ }
+ }).apply {
+ if (BuildConfig.DEBUG) setLevel(HttpLoggingInterceptor.Level.BODY)
},
RetryInterceptor(),
HttpErrorParser()
diff --git a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RetrieveDiagnosisKeysTransaction.kt b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RetrieveDiagnosisKeysTransaction.kt
index 37f736283..a770f1ed1 100644
--- a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RetrieveDiagnosisKeysTransaction.kt
+++ b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RetrieveDiagnosisKeysTransaction.kt
@@ -143,7 +143,7 @@ object RetrieveDiagnosisKeysTransaction : Transaction() {
* not check in before.
*/
if (!InternalExposureNotificationClient.asyncIsEnabled()) {
- Timber.w("EN is not enabled, skipping RetrieveDiagnosisKeys")
+ Timber.tag(TAG).w("EN is not enabled, skipping RetrieveDiagnosisKeys")
executeClose()
return@lockAndExecuteUnique
}
@@ -173,7 +173,7 @@ object RetrieveDiagnosisKeysTransaction : Transaction() {
****************************************************/
executeAPISubmission(token, keyFiles, exposureConfiguration)
} else {
- Timber.w("no key files, skipping submission to internal API.")
+ Timber.tag(TAG).w("no key files, skipping submission to internal API.")
}
/****************************************************
* Fetch Date Update
@@ -205,17 +205,17 @@ object RetrieveDiagnosisKeysTransaction : Transaction() {
}
private fun rollbackSetup() {
- Timber.v("rollback $SETUP")
+ Timber.tag(TAG).v("rollback $SETUP")
LocalData.lastTimeDiagnosisKeysFromServerFetch(lastFetchDateForRollback.get())
}
private fun rollbackToken() {
- Timber.v("rollback $TOKEN")
+ Timber.tag(TAG).v("rollback $TOKEN")
LocalData.googleApiToken(googleAPITokenForRollback.get())
}
private suspend fun rollbackFilesFromWebRequests() {
- Timber.v("rollback $FILES_FROM_WEB_REQUESTS")
+ Timber.tag(TAG).v("rollback $FILES_FROM_WEB_REQUESTS")
KeyCacheRepository.getDateRepository(CoronaWarnApplication.getAppContext())
.clear()
}
@@ -226,7 +226,7 @@ object RetrieveDiagnosisKeysTransaction : Transaction() {
private suspend fun executeSetup() = executeState(SETUP) {
lastFetchDateForRollback.set(LocalData.lastTimeDiagnosisKeysFromServerFetch())
val currentDate = Date(System.currentTimeMillis())
- Timber.d("using $currentDate as current date in Transaction.")
+ Timber.tag(TAG).d("using $currentDate as current date in Transaction.")
currentDate
}
@@ -277,7 +277,7 @@ object RetrieveDiagnosisKeysTransaction : Transaction() {
token
)
}
- Timber.d("Diagnosis Keys provided successfully, Token: $token")
+ Timber.tag(TAG).d("Diagnosis Keys provided successfully, Token: $token")
}
/**
diff --git a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RiskLevelTransaction.kt b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RiskLevelTransaction.kt
index 7551fc672..8bd531250 100644
--- a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RiskLevelTransaction.kt
+++ b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RiskLevelTransaction.kt
@@ -7,10 +7,9 @@ import de.rki.coronawarnapp.R
import de.rki.coronawarnapp.exception.RiskLevelCalculationException
import de.rki.coronawarnapp.nearby.InternalExposureNotificationClient
import de.rki.coronawarnapp.notification.NotificationHelper
-import de.rki.coronawarnapp.risk.RiskLevelCalculation
import de.rki.coronawarnapp.risk.DefaultRiskLevelCalculation
-import de.rki.coronawarnapp.risk.RiskScoreAnalysis
import de.rki.coronawarnapp.risk.DefaultRiskScoreAnalysis
+import de.rki.coronawarnapp.risk.RiskLevel
import de.rki.coronawarnapp.risk.RiskLevel.INCREASED_RISK
import de.rki.coronawarnapp.risk.RiskLevel.LOW_LEVEL_RISK
import de.rki.coronawarnapp.risk.RiskLevel.NO_CALCULATION_POSSIBLE_TRACING_OFF
@@ -18,23 +17,24 @@ import de.rki.coronawarnapp.risk.RiskLevel.UNDETERMINED
import de.rki.coronawarnapp.risk.RiskLevel.UNKNOWN_RISK_INITIAL
import de.rki.coronawarnapp.risk.RiskLevel.UNKNOWN_RISK_OUTDATED_RESULTS
import de.rki.coronawarnapp.risk.RiskLevel.UNKNOWN_RISK_OUTDATED_RESULTS_MANUAL
-import de.rki.coronawarnapp.risk.RiskLevel
+import de.rki.coronawarnapp.risk.RiskLevelCalculation
+import de.rki.coronawarnapp.risk.RiskScoreAnalysis
import de.rki.coronawarnapp.risk.TimeVariables
import de.rki.coronawarnapp.server.protocols.ApplicationConfigurationOuterClass
import de.rki.coronawarnapp.service.applicationconfiguration.ApplicationConfigurationService
import de.rki.coronawarnapp.storage.LocalData
import de.rki.coronawarnapp.storage.RiskLevelRepository
+import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_APP_CONNECTIVITY
+import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_INCREASED_RISK
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_TRACING
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_UNKNOWN_RISK_INITIAL_NO_KEYS
+import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_UNKNOWN_RISK_INITIAL_TRACING_DURATION
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_UNKNOWN_RISK_OUTDATED
-import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_APP_CONNECTIVITY
+import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CLOSE
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.RETRIEVE_APPLICATION_CONFIG
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.RETRIEVE_EXPOSURE_SUMMARY
-import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_INCREASED_RISK
-import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CHECK_UNKNOWN_RISK_INITIAL_TRACING_DURATION
-import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.UPDATE_RISK_LEVEL
import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.RISK_CALCULATION_DATE_UPDATE
-import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.CLOSE
+import de.rki.coronawarnapp.transaction.RiskLevelTransaction.RiskLevelTransactionState.UPDATE_RISK_LEVEL
import de.rki.coronawarnapp.util.ConnectivityHelper
import de.rki.coronawarnapp.util.TimeAndDateExtensions.millisecondsToHours
import kotlinx.coroutines.Dispatchers
@@ -274,7 +274,7 @@ object RiskLevelTransaction : Transaction() {
val isTracingEnabled = InternalExposureNotificationClient.asyncIsEnabled()
if (!isTracingEnabled) return@executeState NO_CALCULATION_POSSIBLE_TRACING_OFF
- Timber.v("$transactionId - TRACING_NOT_ACTIVE_RISK not applicable")
+ Timber.tag(TAG).v("$transactionId - TRACING_NOT_ACTIVE_RISK not applicable")
return@executeState UNDETERMINED
}
@@ -287,10 +287,12 @@ object RiskLevelTransaction : Transaction() {
// if there was no key retrieval before, we return no calculation state
TimeVariables.getLastTimeDiagnosisKeysFromServerFetch()
?: return@executeState UNKNOWN_RISK_INITIAL.also {
- Timber.v("$transactionId - no last time diagnosis keys from server fetch timestamp was found")
+ Timber.tag(TAG).v(
+ "$transactionId - no last time diagnosis keys from server fetch timestamp was found"
+ )
}
- Timber.v("$transactionId - CHECK_UNKNOWN_RISK_INITIAL_NO_KEYS not applicable")
+ Timber.tag(TAG).v("$transactionId - CHECK_UNKNOWN_RISK_INITIAL_NO_KEYS not applicable")
return@executeState UNDETERMINED
}
@@ -314,18 +316,22 @@ object RiskLevelTransaction : Transaction() {
) {
if (ConnectivityHelper.autoModeEnabled(CoronaWarnApplication.getAppContext())) {
return@executeState UNKNOWN_RISK_OUTDATED_RESULTS.also {
- Timber.v("diagnosis keys outdated and active tracing time is above threshold")
- Timber.v("manual mode not active (background jobs enabled)")
+ Timber.tag(TAG).v(
+ "diagnosis keys outdated and active tracing time is above threshold"
+ )
+ Timber.tag(TAG).v("manual mode not active (background jobs enabled)")
}
} else {
return@executeState UNKNOWN_RISK_OUTDATED_RESULTS_MANUAL.also {
- Timber.v("diagnosis keys outdated and active tracing time is above threshold")
- Timber.v("manual mode active (background jobs disabled)")
+ Timber.tag(TAG).v(
+ "diagnosis keys outdated and active tracing time is above threshold"
+ )
+ Timber.tag(TAG).v("manual mode active (background jobs disabled)")
}
}
}
- Timber.v("$transactionId - CHECK_UNKNOWN_RISK_OUTDATED not applicable")
+ Timber.tag(TAG).v("$transactionId - CHECK_UNKNOWN_RISK_OUTDATED not applicable")
return@executeState UNDETERMINED
}
@@ -358,7 +364,7 @@ object RiskLevelTransaction : Transaction() {
executeState(RETRIEVE_APPLICATION_CONFIG) {
return@executeState getApplicationConfiguration()
.also {
- Timber.v(TAG, "$transactionId - retrieved configuration from backend")
+ Timber.tag(TAG).v("$transactionId - retrieved configuration from backend")
}
}
@@ -370,7 +376,9 @@ object RiskLevelTransaction : Transaction() {
val exposureSummary = getNewExposureSummary()
return@executeState exposureSummary.also {
- Timber.v(TAG, "$transactionId - get the exposure summary for further calculation")
+ Timber.tag(TAG).v(
+ "$transactionId - get the exposure summary for further calculation"
+ )
}
}
@@ -400,7 +408,7 @@ object RiskLevelTransaction : Transaction() {
)
}
- public fun getRiskLevel(
+ fun getRiskLevel(
riskLevelCalculation: RiskLevelCalculation,
riskScoreAnalysis: RiskScoreAnalysis,
attenuationParameters: ApplicationConfigurationOuterClass.AttenuationDuration,
@@ -413,7 +421,7 @@ object RiskLevelTransaction : Transaction() {
attenuationParameters,
exposureSummary
).also {
- Timber.v(TAG, "calculated risk with the given config: $it")
+ Timber.tag(TAG).v("calculated risk with the given config: $it")
}
// get the high risk score class
@@ -428,7 +436,7 @@ object RiskLevelTransaction : Transaction() {
highRiskScoreClass.max
)
) {
- Timber.v("$riskScore is above the defined min value ${highRiskScoreClass.min}")
+ Timber.tag(TAG).v("$riskScore is above the defined min value ${highRiskScoreClass.min}")
return INCREASED_RISK
} else if (riskScore > highRiskScoreClass.max) {
throw RiskLevelCalculationException(
@@ -436,7 +444,7 @@ object RiskLevelTransaction : Transaction() {
)
}
- Timber.v("$transactionId - INCREASED_RISK not applicable")
+ Timber.tag(TAG).v("$transactionId - INCREASED_RISK not applicable")
return UNDETERMINED
}
@@ -448,11 +456,11 @@ object RiskLevelTransaction : Transaction() {
) {
// if the active tracing duration is not above the defined threshold we return no calculation state
if (!isActiveTracingTimeAboveThreshold()) {
- Timber.v("$transactionId - active tracing time is not enough")
+ Timber.tag(TAG).v("$transactionId - active tracing time is not enough")
return@executeState UNKNOWN_RISK_INITIAL
}
- Timber.v("$transactionId - UNKNOWN_RISK_INITIAL not applicable")
+ Timber.tag(TAG).v("$transactionId - UNKNOWN_RISK_INITIAL not applicable")
return@executeState UNDETERMINED
}
@@ -461,7 +469,7 @@ object RiskLevelTransaction : Transaction() {
*/
private suspend fun executeUpdateRiskLevelScore(riskLevel: RiskLevel) =
executeState(UPDATE_RISK_LEVEL) {
- Timber.v("$transactionId - update the risk level with $riskLevel")
+ Timber.tag(TAG).v("$transactionId - update the risk level with $riskLevel")
updateRiskLevelScore(riskLevel)
}
@@ -469,7 +477,7 @@ object RiskLevelTransaction : Transaction() {
* Executes the [CLOSE] Transaction State
*/
private suspend fun executeClose() = executeState(CLOSE) {
- Timber.v("$transactionId - transaction will close")
+ Timber.tag(TAG).v("$transactionId - transaction will close")
lastCalculatedRiskLevelScoreForRollback.set(null)
lastCalculatedRiskLevelDate.set(null)
}
@@ -488,7 +496,9 @@ object RiskLevelTransaction : Transaction() {
*/
private suspend fun isValidResult(riskLevel: RiskLevel): Boolean {
if (riskLevel != UNDETERMINED) {
- Timber.v("$transactionId - $riskLevel was determined by the transaction. UPDATE and CLOSE will be called")
+ Timber.tag(TAG).d(
+ "$transactionId - $riskLevel was determined by the transaction. UPDATE and CLOSE will be called"
+ )
lastCalculatedRiskLevelScoreForRollback.set(RiskLevelRepository.getLastCalculatedScore())
executeUpdateRiskLevelScore(riskLevel)
lastCalculatedRiskLevelDate.set(LocalData.lastTimeRiskLevelCalculation())
@@ -507,7 +517,7 @@ object RiskLevelTransaction : Transaction() {
private suspend fun getApplicationConfiguration(): ApplicationConfigurationOuterClass.ApplicationConfiguration =
withContext(Dispatchers.Default) {
return@withContext ApplicationConfigurationService.asyncRetrieveApplicationConfiguration()
- .also { Timber.v("configuration from backend: $it") }
+ .also { Timber.tag(TAG).d("configuration from backend: $it") }
}
/**
@@ -523,7 +533,7 @@ object RiskLevelTransaction : Transaction() {
val activeTracingDurationInHours = durationTracingIsActive.millisecondsToHours()
return (activeTracingDurationInHours >= durationTracingIsActiveThreshold).also {
- Timber.v(
+ Timber.tag(TAG).v(
"active tracing time ($activeTracingDurationInHours h) is above threshold " +
"($durationTracingIsActiveThreshold h): $it"
)
@@ -560,7 +570,7 @@ object RiskLevelTransaction : Transaction() {
InternalExposureNotificationClient.asyncGetExposureSummary(googleToken)
return exposureSummary.also {
- Timber.v("$transactionId - generated new exposure summary with $googleToken")
+ Timber.tag(TAG).v("$transactionId - generated new exposure summary with $googleToken")
}
}
diff --git a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/Transaction.kt b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/Transaction.kt
index f43dfd36a..54e5d219f 100644
--- a/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/Transaction.kt
+++ b/Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/Transaction.kt
@@ -91,7 +91,7 @@ abstract class Transaction {
private fun setState(state: TransactionState) =
currentTransactionState.set(state)
.also {
- Timber.d("$transactionId - STATE CHANGE: ${currentTransactionState.get()}")
+ Timber.tag(TAG).d("$transactionId - STATE CHANGE: ${currentTransactionState.get()}")
}
/**
@@ -217,7 +217,7 @@ abstract class Transaction {
if (unique && internalMutualExclusionLock.isLocked) {
val runningString = "TRANSACTION WITH ID $transactionId ALREADY RUNNING " +
"($currentTransactionState) AS UNIQUE, SKIPPING EXECUTION."
- Timber.w(runningString)
+ Timber.tag(TAG).w(runningString)
return
}
try {
@@ -231,7 +231,7 @@ abstract class Transaction {
val completedString =
"TRANSACTION $transactionId COMPLETED (${System.currentTimeMillis()}) " +
"in $it ms, STATES EXECUTED: ${getExecutedStates()}"
- Timber.i(completedString)
+ Timber.tag(TAG).i(completedString)
}
resetExecutedStateStack()
}
@@ -274,7 +274,7 @@ abstract class Transaction {
* @throws RollbackException throws a rollback exception when handleRollbackError() is called
*/
protected open suspend fun rollback() {
- if (BuildConfig.DEBUG) Timber.d("Initiate Rollback")
+ if (BuildConfig.DEBUG) Timber.tag(TAG).d("Initiate Rollback")
}
/**
--
GitLab