App can take minutes to notify endpoints about new incoming parcels (Internet sync)

[gnarea]

I'm using the echo app with access to the Internet, and I can see in the Android Gateway logs that my parcel is being sent and received very quickly. However, the echo app isn't notified about the new parcel until a few minutes later. I can reproduce this easily, though not 100% of the time.

Here's an example:

2021-01-18 11:39:29.187 4900-4931/tech.relaycorp.gateway I/PublicSync: Starting public sync
2021-01-18 11:39:29.189 4900-4932/tech.relaycorp.gateway I/DeliverParcelsToGateway: Delivering parcels to Public Gateway (keepAlive=true)
2021-01-18 11:39:29.190 4900-4921/tech.relaycorp.gateway I/llectParcelsFromGateway: Collecting parcels from Public Gateway (keepAlive=true)
2021-01-18 11:39:37.638 4900-4921/tech.relaycorp.gateway I/DeliverParcelsToGateway: Delivering parcel to Gateway 9cb43ec0-ef23-48fc-96bb-195e812d4761
2021-01-18 11:39:38.802 4900-4921/tech.relaycorp.gateway I/llectParcelsFromGateway: Collected parcel from Gateway 9cb43ec0-ef23-48fc-96bb-195e812d4761

As you can see, the parcel 9cb43ec0-ef23-48fc-96bb-195e812d4761 was collected 1.16 seconds after its delivery started. However, I could see the notification on the echo app around 2 minutes later, but neither the echo or gateway apps currently offer any logging to confirm this (I'll be adding some in a PR).

[gnarea]

I haven't noticed this recently so I'm taking this out of the public alpha launch project.

[gnarea]

I'm noticing this occasionally on Android 8 (Nexus 5X):

Awala logs:

2023-10-12 14:01:57.691 11549-11594 llectParcelsFromGateway tech.relaycorp.gateway               I  Collected parcel from Gateway 8868331269893917
2023-10-12 14:01:57.691 11549-11594 llectParcelsFromGateway tech.relaycorp.gateway               I  Notifying endpoint 01e769435844a461708fcc2464245bf33dd9335c3c6e912d12beb389f774ee95f
2023-10-12 14:01:57.721 11549-11594 NotifyEndpoints         tech.relaycorp.gateway               I  Notifying tech.relaycorp.letro about IncomingParcel

Relevant logs in Letro when it works (notice the 3-minute delay):

2023-10-12 14:04:04.120 12474-12744 AwalaManager            tech.relaycorp.letro                 I  Receive message: application/vnd.relaycorp.letro.account-creation

[sdsantos]

I tested with the Ping app, and the worse case I've seen is 8 seconds of delay, if I previously killed the Ping app.

I did notice that the current version of Ping is using the old version of the SDK, that still has this issue: relaycorp/awala-endpoint-android#341

This means that sometimes the Ping app was notified, but it crashed silently in the background, and did not receive the message. Maybe those minute delays you saw were from multiple notification attempts (other parcels were received) until one worked?

---

Otherwise, more reproduction steps for this issue would be very helpful.

[gnarea]

Maybe those minute delays you saw were from multiple notification attempts (other parcels were received) until one worked?

I can't remember 🤔

Otherwise, more reproduction steps for this issue would be very helpful.

Indeed... Unfortunately (or fortunately?), this is extremely rate in both Awala Ping and Letro.

Is there any logging that we should consider adding, so we have more info next time it happens?

[sdsantos]

Is there any logging that we should consider adding, so we have more info next time it happens?

If the issue is a background crash, it may be hard to get the logs for that, because logcat may have already restarted the session. What would help is a longer log from the Awala app. Did it get more parcels and retry Notifying in those 3 minutes?

[gnarea]

Did it get more parcels and retry Notifying in those 3 minutes?

Can't remember 🤔