Skip to content
This repository has been archived by the owner on Jun 20, 2023. It is now read-only.

Improve transaction logging #1061

Merged
merged 6 commits into from
Aug 27, 2020
Merged

Improve transaction logging #1061

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
a038896
Improve transaction logging
d4rken Aug 21, 2020
6ca75b7
Merge branch 'dev' into feat/improved-transaction-logging
jakobmoellerdev Aug 25, 2020
c3e8d1a
Merge branch 'dev' into feat/improved-transaction-logging
d4rken Aug 26, 2020
49e9e73
Merge branch 'dev' into feat/improved-transaction-logging
d4rken Aug 26, 2020
a74f27d
Merge branch 'dev' into feat/improved-transaction-logging
jakobmoellerdev Aug 26, 2020
9c3f5e2
Merge branch 'dev' into feat/improved-transaction-logging
jakobmoellerdev Aug 26, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 7 additions & 2 deletions Corona-Warn-App/src/main/java/de/rki/coronawarnapp/http/ServiceFactory.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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()
Expand Down
14 changes: 7 additions & 7 deletions ...rn-App/src/main/java/de/rki/coronawarnapp/transaction/RetrieveDiagnosisKeysTransaction.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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()
}
Expand All @@ -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
}

Expand Down Expand Up @@ -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")
}

/**
Expand Down
70 changes: 40 additions & 30 deletions Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/RiskLevelTransaction.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,34 +7,34 @@ 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
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
Expand Down Expand Up @@ -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
}

Expand All @@ -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
}

Expand All @@ -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
}

Expand Down Expand Up @@ -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")
}
}

Expand All @@ -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"
)
}
}

Expand Down Expand Up @@ -400,7 +408,7 @@ object RiskLevelTransaction : Transaction() {
)
}

public fun getRiskLevel(
fun getRiskLevel(
riskLevelCalculation: RiskLevelCalculation,
riskScoreAnalysis: RiskScoreAnalysis,
attenuationParameters: ApplicationConfigurationOuterClass.AttenuationDuration,
Expand All @@ -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
Expand All @@ -428,15 +436,15 @@ 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(
IllegalStateException("risk score is above the max threshold for score class")
)
}

Timber.v("$transactionId - INCREASED_RISK not applicable")
Timber.tag(TAG).v("$transactionId - INCREASED_RISK not applicable")
return UNDETERMINED
}

Expand All @@ -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
}

Expand All @@ -461,15 +469,15 @@ 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)
}

/**
* 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)
}
Expand All @@ -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())
Expand All @@ -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") }
}

/**
Expand All @@ -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"
)
Expand Down Expand Up @@ -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")
}
}

Expand Down
8 changes: 4 additions & 4 deletions Corona-Warn-App/src/main/java/de/rki/coronawarnapp/transaction/Transaction.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()}")
}

/**
Expand Down Expand Up @@ -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 {
Expand All @@ -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()
}
Expand Down Expand Up @@ -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")
}

/**
Expand Down