Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) #1604

d4rken · 2020-11-13T16:56:45Z

@ralfgehrer and me found the crash issue.

The file that should contain the json is empty.

When GSON reads it and deserializes it, it doesn't care that the file is empty, it will just create a new object that looks non-null, but is actually null. You only find out about that though when you try to access it.

In this case it was triggered by the mutate call here and the mutate extension function would call toMutableMap() where Kotlin would then notice that the object is actually null.

The symptoms for affected users are fixed by forcing an evaluation via require(it.size >= 0) and this triggers an exception, and we delete the corrupt data file.

We are not 100% certain what leads to the empty file though, suspicions:

While the documentation states that close() calls flush() implicitly, the underlying implementation does not?
GSON Serialization fails, but at that point the file writer already created a new empty file. Why does it fail random though? A wrong serialization config would fail every time.
Process death at a really unlucky point in time, but this seems very unlikely, the timing would really have to been just right. Currently we didn't use the buffered version of the writer, so I'd expect the file to contain garbage, not just be empty, but the stacktraces show that the file must have been empty.
A storage/IO/Permission issue that allowed file creation, but not writing. We thought about low storage space, but the block size on Android is 4KB, and the json data is much smaller than that. So why would we be able to create a 4KB block on the file system but then not be able to write to it...

java.lang.NullPointerException:
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$calculationStates$2$setupTimeoutEnforcer$1$1$1.invokeSuspend (DefaultCalculationTracker.kt:5)
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$calculationStates$2$setupTimeoutEnforcer$1$1$1.invoke (DefaultCalculationTracker.kt:2)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1$invokeSuspend$$inlined$collect$1.emit (Collect.kt:6)
  at kotlinx.coroutines.flow.SharedFlowImpl.collect (SharedFlow.kt:12)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invokeSuspend (HotDataFlow.kt:15)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invoke (HotDataFlow.kt:2)
  at kotlinx.coroutines.flow.ChannelFlowBuilder.collectTo (Builders.kt:1)
  at kotlinx.coroutines.flow.internal.ChannelFlow$collectToFun$1.invokeSuspend (ChannelFlow.kt:2)
  at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith (ContinuationImpl.kt:3)
  at kotlinx.coroutines.DispatchedTask.run (DispatchedTask.kt:15)
  at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely (CoroutineScheduler.kt:1)
  at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run (CoroutineScheduler.kt:13)

  java.lang.NullPointerException:
  at kotlin.collections.ArraysKt___ArraysKt.toMutableMap (_Arrays.kt)
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$trackNewCalaculation$1.invoke (DefaultCalculationTracker.kt:6)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1$invokeSuspend$$inlined$collect$1.emit (Collect.kt:6)
  at kotlinx.coroutines.flow.SharedFlowImpl.collect (SharedFlow.kt:12)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invokeSuspend (HotDataFlow.kt:15)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invoke (HotDataFlow.kt:2)
  at kotlinx.coroutines.flow.ChannelFlowBuilder.collectTo (Builders.kt:1)
  at kotlinx.coroutines.flow.internal.ChannelFlow$collectToFun$1.invokeSuspend (ChannelFlow.kt:2)
  at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith (ContinuationImpl.kt:3)
  at kotlinx.coroutines.DispatchedTask.run (DispatchedTask.kt:15)
  at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely (CoroutineScheduler.kt:1)
  at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run (CoroutineScheduler.kt:13)

  java.lang.NullPointerException:
  at kotlin.collections.ArraysKt___ArraysKt.toMutableMap (Unknown Source:2)
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$finishCalculation$1.invokeSuspend (DefaultCalculationTracker.kt:2)
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$finishCalculation$1.invoke (DefaultCalculationTracker.kt:2)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1$invokeSuspend$$inlined$collect$1.emit (Collect.kt:6)
  at kotlinx.coroutines.flow.SharedFlowImpl.collect (SharedFlow.kt:12)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invokeSuspend (HotDataFlow.kt:15)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1.invoke (HotDataFlow.kt:2)
  at kotlinx.coroutines.flow.ChannelFlowBuilder.collectTo (Builders.kt:1)
  at kotlinx.coroutines.flow.internal.ChannelFlow$collectToFun$1.invokeSuspend (ChannelFlow.kt:2)
  at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith (ContinuationImpl.kt:3)
  at kotlinx.coroutines.DispatchedTask.run (DispatchedTask.kt:15)
  at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely (CoroutineScheduler.kt:1)
  at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run (CoroutineScheduler.kt:13)

  
  java.lang.NullPointerException:
  at kotlin.collections.ArraysKt___ArraysKt.toMutableMap (Unknown Source:2)
  at de.rki.coronawarnapp.nearby.modules.calculationtracker.DefaultCalculationTracker$trackNewCalaculation$1.invoke (DefaultCalculationTracker.kt:6)
  at de.rki.coronawarnapp.util.flow.HotDataFlow$internalFlow$1$invokeSuspend$$inlined$collect$1.emit (Collect.kt:6)
  at kotlinx.coroutines.flow.SharedFlowImpl.collect (SharedFlow.kt:12)
  at kotlinx.coroutines.flow.SharedFlowImpl$collect$1.invokeSuspend (Unknown Source:12)
  at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith (ContinuationImpl.kt:3)
  at kotlinx.coroutines.DispatchedTask.run (DispatchedTask.kt:15)
  at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely (CoroutineScheduler.kt:1)
  at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run (CoroutineScheduler.kt:13)

…es, we end up with an empty file. GSON deserializes this into a null object that looks like a non-null object until it is evaluated some time later. Force an evaluation via `require(it.size >= 0)` and delete the corrupt data file when catching the exception.

d4rken · 2020-11-13T17:06:20Z

The flush() should not be necessary as the close() call via .use { } would also internally call flush(). 🤔

This would point to the app process having died mid-write.

d4rken · 2020-11-13T17:11:30Z

Still think it's the cause, but I don't get how this could be so common. While our user numbers are high, hitting this exact execution point, is like getting hit by lightning 🤔 .

sonarqubecloud · 2020-11-13T17:43:21Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities (and 0 Security Hotspots to review)
0 Code Smells

55.6% Coverage
0.0% Duplication

kolyaopahle

Code Looks good to me, sadly i was not able to reproduce the error on any of my devices. I'm also quite confused about the frequency of this issue.

d4rken · 2020-11-13T17:59:11Z

Upon further research the issue could also appear if GSON crashes while serializing the data, as the file writer we use will create an empty file.

So in the timeline:

Open file writer -> Empty file is created
GSON crashes for some reason

We end up with an empty data file too. I don't see how GSON could just crash randomly though.

d4rken · 2020-11-13T18:34:26Z

As the issue is most likely to occur during writing, we've added .report for the exception that can be caught during writing. Our favorite dialog will show a message and the stacktrace that will help us understand the underlying issue.

harambasicluka · 2020-11-16T07:58:37Z

This PR requires 3 to 4 reviews as it can't be tested and wasn't catched by the testers during 1.6.0 testing.

chris-cwa

look conclusive in theory

harambasicluka

LGTM, also @thomasaugsten tested it (s. jira comments)

d4rken · 2020-11-16T11:08:54Z

Will follow up with another PR to rule out one more edge case.

d4rken added bug Something isn't working maintainers Tag pull requests created by maintainers prio PRs to review first. labels Nov 13, 2020

d4rken added this to the 1.6.0 milestone Nov 13, 2020

d4rken requested a review from a team November 13, 2020 16:56

d4rken changed the title ~~Flush json data after writing it (EXPOSUREAPP-3777~~ Flush json data after writing it (EXPOSUREAPP-3777) Nov 13, 2020

d4rken added 2 commits November 13, 2020 18:30

Show a visible error dialog if we fail to save data.

2137080

Used buffered versions of readers and writer.

64b39cf

kolyaopahle approved these changes Nov 13, 2020

View reviewed changes

d4rken changed the title ~~Flush json data after writing it (EXPOSUREAPP-3777)~~ Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) Nov 13, 2020

harambasicluka modified the milestones: 1.6.0, 1.6.1 Nov 16, 2020

chris-cwa approved these changes Nov 16, 2020

View reviewed changes

ralfgehrer assigned kolyaopahle and chris-cwa Nov 16, 2020

harambasicluka approved these changes Nov 16, 2020

View reviewed changes

harambasicluka added the do not merge label Nov 16, 2020

d4rken removed the do not merge label Nov 16, 2020

d4rken merged commit a6335e7 into release/1.6.x Nov 16, 2020

d4rken deleted the fix/3777-flush-data-to-prevent-faulty-json branch November 16, 2020 11:09

vaubaehn mentioned this pull request Nov 16, 2020

Application 1.6.0 crashes on startup - MediaTek bug #1609

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) #1604

Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) #1604

d4rken commented Nov 13, 2020 •

edited

Loading

d4rken commented Nov 13, 2020

d4rken commented Nov 13, 2020

sonarqubecloud bot commented Nov 13, 2020

kolyaopahle left a comment

d4rken commented Nov 13, 2020 •

edited

Loading

d4rken commented Nov 13, 2020

harambasicluka commented Nov 16, 2020

chris-cwa left a comment

harambasicluka left a comment

d4rken commented Nov 16, 2020

Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) #1604

Handle failure to persist GSON serialized JSON data (EXPOSUREAPP-3777) #1604

Conversation

d4rken commented Nov 13, 2020 • edited Loading

d4rken commented Nov 13, 2020

d4rken commented Nov 13, 2020

sonarqubecloud bot commented Nov 13, 2020

kolyaopahle left a comment

Choose a reason for hiding this comment

d4rken commented Nov 13, 2020 • edited Loading

d4rken commented Nov 13, 2020

harambasicluka commented Nov 16, 2020

chris-cwa left a comment

Choose a reason for hiding this comment

harambasicluka left a comment

Choose a reason for hiding this comment

d4rken commented Nov 16, 2020

d4rken commented Nov 13, 2020 •

edited

Loading

d4rken commented Nov 13, 2020 •

edited

Loading