Fix debug log censoring collisions (EXPOSUREAPP-7196) #3230

d4rken · 2021-05-19T16:43:03Z

@kolyaopahle found an issue for some uncensored log entries. The underlying cause was that if there is a collision between different censors, i.e. that two censor modules replace elements on the same line, the original string does not match what the other censor module expects. Example:

message = "Hello world

after module 1:
message = "Hello"

module 2 wants to replace "Hello world", but only finds "Hello" which is no match.

In this PR @kolyaopahle and me reworked the mechanism:

The censoring mechanism to longer run in serial on the data that should be censored. All censor modules run at the same time.
Each censor module now produces a CensoredString(String,IntRage). With String being the changed message, and IntRange the start and end index of what was modified in the original log message.
After all censors are done, the DebugLogger checks if more than one censor module modified the original message. If that is the case, the minimum and maximum index of modifications in the original log message is removed and replaced with a placeholder <censoring-collision>. This leaves us with some information that is useful for debugging and also removes any information that should have been censored.

Give the debug logger an additional thread to parallelize censoring.

d4rken · 2021-05-20T09:30:48Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/censors/BugCensor.kt

+        operator fun CensoredString.plus(newer: CensoredString?): CensoredString {
+            if (newer == null) return this
+
+            val range = when {
+                newer.range == null -> this.range
+                this.range == null -> newer.range
+                else -> min(this.range.first, newer.range.first)..max(this.range.last, newer.range.last)
+            }
+
+            return CensoredString(string = newer.string, range = range)
+        }


Operator to make chaining censoring easier by being able to use var old += new

d4rken · 2021-05-20T09:31:20Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/censors/BugCensor.kt

+        fun CensoredString.censor(orig: String, replacement: String): CensoredString? {
+            val start = this.string.indexOf(orig)
+            if (start == -1) return null
+
+            val end = start + replacement.length
+            return CensoredString(
+                string = this.string.replace(orig, replacement),
+                range = start..end
+            )
+        }


Acts like String.replace but tells us the start+end index of the match.

d4rken · 2021-05-20T09:32:16Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/debuglog/DebugLogger.kt

-                    val censoredLine = bugCensors.get().fold(rawLine) { prev, censor ->
-                        censor.checkLog(prev) ?: prev
+
+                    val formattedMessage = rawLine.format()


As we don't need to censor logtags, we pre compute the log message and only pass that to censors.

d4rken · 2021-05-20T09:33:40Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/debuglog/DebugLogger.kt

+                    val censored: Collection<BugCensor.CensoredString> = bugCensors.get()
+                        .map {
+                            async {
+                                it.checkLog(formattedMessage)
+                            }
+                        }
+                        .awaitAll()
+                        .filterNotNull()
+                        .filter { it.range != null }


@kolyaopahle and me performance tested the censoring and we were at ~100ms if we run all censors in sequence. This now runs in parallel the DebugScope threads, reaching 10-20ms per logline.
For all bug censors that are stateful (i.e. do local caching), thread safe has to be taken into consideration though.

d4rken · 2021-05-20T09:34:04Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/debuglog/DebugLogger.kt

+                            val minMin = censored.minOf { it.range!!.first }
+                            val maxMax = censored.maxOf { it.range!!.last }
+                            formattedMessage.replaceRange(minMin, maxMax, CENSOR_COLLISION_PLACERHOLDER)


Part that deletes whole sections if there was a censoring collision.

d4rken · 2021-05-20T09:34:33Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/debuglog/LogLine.kt

+        return if (throwable != null) {
+            baseLine + "\n" + getStackTraceString(throwable)
+        } else {
+            baseLine
+        }


We previously overlooked that the actual stacktrace was not written to log 😦

d4rken · 2021-05-20T11:00:31Z

Merge this after #3230

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/util/CWADebug.kt

# Conflicts: # Corona-Warn-App/src/test/java/de/rki/coronawarnapp/bugreporting/debuglog/internal/LogSnapshotterTest.kt

harambasicluka · 2021-05-20T13:50:48Z

Merge this after #3230

Deadlock!

LukasLechnerDev · 2021-05-20T13:53:14Z

...rn-App/src/main/java/de/rki/coronawarnapp/bugreporting/debuglog/internal/DebugLoggerScope.kt

@@ -9,7 +9,8 @@ import javax.inject.Qualifier
 import kotlin.coroutines.CoroutineContext

 object DebugLoggerScope : CoroutineScope {
-    val dispatcher = Executors.newSingleThreadExecutor(
+    val dispatcher = Executors.newFixedThreadPool(
+        4,


Why exactly 4 here? Would it make sense to use Dispatchers.Default?

We tested 1 to 16 threads, 4 yielded the most performance gain with the least amount of threads.

1 thread ~ 110ms per logline on avg

2 ~ 50ms

3 ~ 35ms

4 ~ 20ms

5 ~ 15-20ms

6 ~ 11-20ms
etc. diminishing returns

Using Dispatchers.Default would not be bad, but we decided against it to reduce impact on other app operations.

Dispatchers.Default provides a thread count equal to the number of cores, e.g. 4, if the logging mechanisms block for some reasons, the coroutines running on Default through out the app could starve as fewer or even no threads are available. I don't think this would happen, but just to be sure it can't and to reduce the impact of logging on the app and to make the behavior recorded by the logger more accurate to what is happening when it is not active, it is nicer to work on different threads here.

Makes Sense! Thanks for the in-depth explanation 👍

LukasLechnerDev

LGTM. Tested it on device and got the <censoring-collision> in the log.

…h, not it's replacement.

…ons' into fix/7196-debug-censoring-collisions

d4rken · 2021-05-20T15:42:03Z

Merge this after #3230

Deadlock!

😄 I meant #3235

LukasLechnerDev

LGTM#2. Thank you for the new unit test 👍

sonarcloud · 2021-05-21T10:38:48Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

87.0% Coverage
0.0% Duplication

d4rken added 6 commits May 19, 2021 16:24

Detect censoring collision and replace whole line with placeholder.

6b75f22

Give the debug logger an additional thread to parallelize censoring.

Smart censoring collision handling.

d53f5ed

Tweak logging performance.

c79152a

Adjusted unit tests to censoring changes.

875dc72

Print stacktraces to debug log too!

f1d4413

Make KLINT happy

c02a91a

d4rken added the maintainers Tag pull requests created by maintainers label May 19, 2021

d4rken added this to the 2.3.0 milestone May 19, 2021

d4rken requested a review from a team May 19, 2021 16:43

d4rken and others added 4 commits May 19, 2021 18:50

Adjust tests to changed log formatting.

d5bec2e

Add tests for throwable formatting in debuglogger lines.

ef81c36

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

aefd196

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

fcf606f

d4rken commented May 20, 2021

View reviewed changes

d4rken added bug Something isn't working author merge PR to be merged by author labels May 20, 2021

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

25ae218

LukasLechnerDev self-assigned this May 20, 2021

LukasLechnerDev reviewed May 20, 2021

View reviewed changes

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/util/CWADebug.kt Outdated Show resolved Hide resolved

d4rken and others added 4 commits May 20, 2021 15:12

Re-enable debug tree.

b4b7af0

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

f5885f2

# Conflicts: # Corona-Warn-App/src/test/java/de/rki/coronawarnapp/bugreporting/debuglog/internal/LogSnapshotterTest.kt

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

72bb114

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

88c3643

LukasLechnerDev reviewed May 20, 2021

View reviewed changes

LukasLechnerDev previously approved these changes May 20, 2021

View reviewed changes

d4rken added 3 commits May 20, 2021 17:32

Fix incorrect censoring range. We need the range of the original matc…

dd57979

…h, not it's replacement.

Fix duplicate new line if exceptions are logged.

0a3613f

Merge remote-tracking branch 'origin/fix/7196-debug-censoring-collisi…

8f316a1

…ons' into fix/7196-debug-censoring-collisions

d4rken dismissed LukasLechnerDev’s stale review via 8f316a1 May 20, 2021 15:36

d4rken removed the author merge PR to be merged by author label May 20, 2021

LukasLechnerDev approved these changes May 21, 2021

View reviewed changes

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

7e5ecf3

mtwalli approved these changes May 21, 2021

View reviewed changes

Merge branch 'release/2.3.x' into fix/7196-debug-censoring-collisions

446867a

mtwalli self-assigned this May 21, 2021

harambasicluka merged commit 4e47438 into release/2.3.x May 21, 2021

harambasicluka deleted the fix/7196-debug-censoring-collisions branch May 21, 2021 10:40

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix debug log censoring collisions (EXPOSUREAPP-7196) #3230

Fix debug log censoring collisions (EXPOSUREAPP-7196) #3230

d4rken commented May 19, 2021

d4rken May 20, 2021 •

edited

d4rken May 20, 2021

d4rken May 20, 2021

d4rken May 20, 2021

d4rken May 20, 2021

d4rken May 20, 2021

d4rken commented May 20, 2021

harambasicluka commented May 20, 2021 •

edited

LukasLechnerDev May 20, 2021 •

edited

d4rken May 20, 2021 •

edited

LukasLechnerDev May 20, 2021

LukasLechnerDev left a comment

d4rken commented May 20, 2021

LukasLechnerDev left a comment

sonarcloud bot commented May 21, 2021

Fix debug log censoring collisions (EXPOSUREAPP-7196) #3230

Fix debug log censoring collisions (EXPOSUREAPP-7196) #3230

Conversation

d4rken commented May 19, 2021

d4rken May 20, 2021 • edited

Choose a reason for hiding this comment

d4rken May 20, 2021

Choose a reason for hiding this comment

d4rken May 20, 2021

Choose a reason for hiding this comment

d4rken May 20, 2021

Choose a reason for hiding this comment

d4rken May 20, 2021

Choose a reason for hiding this comment

d4rken May 20, 2021

Choose a reason for hiding this comment

d4rken commented May 20, 2021

harambasicluka commented May 20, 2021 • edited

LukasLechnerDev May 20, 2021 • edited

Choose a reason for hiding this comment

d4rken May 20, 2021 • edited

Choose a reason for hiding this comment

LukasLechnerDev May 20, 2021

Choose a reason for hiding this comment

LukasLechnerDev left a comment

Choose a reason for hiding this comment

d4rken commented May 20, 2021

LukasLechnerDev left a comment

Choose a reason for hiding this comment

sonarcloud bot commented May 21, 2021

d4rken May 20, 2021 •

edited

harambasicluka commented May 20, 2021 •

edited

LukasLechnerDev May 20, 2021 •

edited

d4rken May 20, 2021 •

edited