[Bug] FxaPushSupportFeature is not resetting push subscription

[jonalmeida]

From @snorp 's logs we can see that FxaDeviceConstellation is requesting that we reset our push token, but we do not see a response from the FxaPushSupportFeature that should be monitoring that change.

deviceModel=null, regions=[], debugTags=[]))], lastModified=1594230842195)
10-14 10:58:44.771  9808  9985 E AtomicFile: Failed to sync file output stream
10-14 10:58:44.771  9808  9985 I experiments: onExperimentsUpdated - currently active experiment will stay active
10-14 10:58:44.772  9808  9932 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=7336ae90-84f8-4364-8a1d-1687908cd1e4, tags={ mozilla.components.service.experiments.ExperimentsUpdaterWorker, mozilla.components.service.experiments } ]
10-14 10:58:45.171  9808  9846 I FirefoxAccount: Successfully executed: getTokenServerEndpointURL
10-14 10:58:45.180  9808  9846 I FxaDeviceConstellation: Refreshing device list...
10-14 10:58:45.180  9808  9846 I FxaDeviceConstellation: Executing: fetching all devices
10-14 10:58:45.558  9808  9846 I FxaDeviceConstellation: Successfully executed: fetching all devices
10-14 10:58:45.559  9808  9846 I FxaDeviceConstellation: Current device needs push endpoint registration
10-14 10:58:45.559  9808  9846 I FxaDeviceConstellation: Refreshed device list; saw 3 device(s).
10-14 10:58:45.560  9808  9980 I FirefoxAccountStateMachine: Ran 'mozilla.components.service.fxa.manager.Event$Progress$AccountRestored@76399b9' side-effects for state Active(progressState=CompletingAuthentication), got successive event CompletedAuthentication(authType=mozilla.components.concept.sync.AuthType$Existing@81f780c)
10-14 10:58:45.560  9808  9980 I FirefoxAccountStateMachine: Processing event 'CompletedAuthentication(authType=mozilla.components.concept.sync.AuthType$Existing@81f780c)' for state Active(progressState=CompletingAuthentication). Next state is Idle(accountState=Authenticated)
10-14 10:58:45.565  9808  9846 I FirefoxAccount: Executing: getProfile
10-14 10:58:45.590  9808  9846 I FirefoxAccount: Successfully executed: getProfile

┆Issue is synchronized with this Jira Task

[kbrosnan]

@jonalmeida is this something for the Fenix team to fix or is it something the AC team wants to handle?

[jdragojevic]

@jonalmeida - logs from startup on Fenix nightly.

fenix-nightly-startup.txt

[jonalmeida]

From some debugging so far we've seen that snorp's logs are different from Janet's.

For snorp, we've hit the "fxa cannot communicate with your device" and the recovery mechanism is failing on bug mozilla-mobile/android-components#7143 which should be notifying us that our subscriptions are invalid.

I verified this by manually re-subscribing for our fxa push subscription and that seems to recover instantly.

For Janet, I'm seeing missing information in the send tab push messages that are coming through. Push messages with a chid but no body. That seems wrong to me.. but I need to verify with someone on FxA and Autopush if that is expected.

On release, this is what we see in the logs (Leanplum is logging the full message for us):

10-16 14:30:12.433 16028 16115 I AutoPushFeature: New push message decrypted.
10-16 14:30:12.434 16028 17358 I [INFO][Leanplum]: [com.leanplum.LeanplumPushFirebaseMessagingService::onMessageReceived::4]: Received: {con=aes128gcm, body=coLLhqHQWOE_VvvfoQ2RFgAAEABBBOZY-3EmXy2lvE0oEdFJmsXIHjk8airgeeMs1A2dOctq2MXHrRzr0E8jZaFBeafccd_5FZeTWAW_oMSPtdJgrdTNuRoqqzDGaA5U9ofQTLPH6619qzrN7sQWd3hOi8okJtdwHVQastfLRA6zkpRVQzc7tMsXNSM6dixfd1ImfkkpWLQqqUhxZgxPVNDS7BuiGl2FJBtOhityMVfmGke8H84JU9mQDgDjiMY5RhWIwQXVRKvHo_J8YPCqQFtikuxeBSj7Ajv9XLqnJ3xt_2YnseqGkzgeTB4U_dF_Kb3n5wRWQBI13j2lOS_y_L9Q6cDAifM9h62EeeSlDJmckMSKgiXh91tlfKJuzFEYXD8eMFmoNtLygh8T8_EBFo00mdG0VOkdMqy4DH2si2zlCjA3HUcwbcTNqwU1vVNDWimaguPF6fq4B_JnnqZjPL1UJAcfxMl0m0T5OUoqf8QFrg0, chid=aa48c879da8831a1b3d053b351105ae2}
10-16 14:30:12.472 16028 16115 I AutoPushObserver: Received new push message for fxa_push_scope_622fdb5d89554684963c96dbd9375813

For Nightly, when sending a tab I see this in the logs (sent to me via a direct message):

10-16 13:09:42.630  3688 10296 I SamsungAlarmManager: setLocked to kernel - T:3 / 20201016T133130, SetElapsed=380455279, nowELAPSED=379147907
10-16 13:09:42.632 16028 16115 I AutoPushFeature: New push message decrypted.
10-16 13:09:42.635 16028 16115 D push_ffi: push_dispatch_info_for_chid
10-16 13:09:42.636 16028 17358 I [INFO][Leanplum]: [com.leanplum.LeanplumPushFirebaseMessagingService::onMessageReceived::4]: Received: {chid=aa48c879da8831a1b3d053b351105ae2}

cc: @rfk and @jrconlin

[rfk]

That seems wrong to me.. but I need to verify with someone on FxA and Autopush if that is expected.

I agree, at first glance this seems wrong.

[jrconlin]

Yeah, I'm not sure about this one either. I'm not super familiar with the internals of send tab (particularly around the integration with pushbox and when that fetch happens).

Generally, new channel requests don't remove old channels from Push (the old channel remains valid unless it's explicitly dropped by the client), so it's odd that you're seeing this. I'm not sure where the breakage might be occurring,but I'll file this bug to track.

[rfk]

For snorp, we've hit the "fxa cannot communicate with your device" and the recovery mechanism is failing
on bug mozilla-mobile/android-components#7143 which should be notifying us that our subscriptions are invalid.

Cross-linking for context, I have the start of a theory about why this recovery mechanism is failing:

• Investigate verify_connection incorrectly returning empty list mozilla/application-services#3314 (comment)

[jdragojevic]

@jonalmeida - here are logs from doing a sign-out, sign-in, send tab on latest Fenix nightly. sign-out-sign-in-send-tab.txt

[jonalmeida]

Thanks @jdragojevic !

Just to verify, you are still not seeing a Send Tab show up?

In the logs, we are very clearly receiving a push message, decrypting, and notifying the account manager with the push message:

10-21 19:51:50.170  3688  3769 E Watchdog: !@Sync 6555 [2020-10-21 19:51:50.170] FD count : 566, wdog_way : softdog
10-21 19:52:01.666 29218  6495 I [INFO][Leanplum]: [com.leanplum.LeanplumPushFirebaseMessagingService::onMessageReceived::4]: Received: {con=aes128gcm, body=zTFUimOR9B-..[reduced content]..Yw, chid=88542ffee8203396927a8711010be643}
10-21 19:52:01.666 29218  6016 I AutoPushFeature: New push message decrypted.
10-21 19:52:01.683 29218  6016 I AutoPushObserver: Received new push message for fxa_push_scope_6989b9fdc00e46a8a79853903bdde15e

[jdragojevic]

@jonalmeida - the most recent logs (#15899 (comment)) are from after an uninstall / reinstall of the Fenix nightly application.

From the slack conversation the other day - I confirmed that signing in / out was not enough to solve the problem, but the uninstall / reinstall did fix it.

[jonalmeida]

Thanks Janet, I wrongly assumed these logs were before the uninstall/install. Everything looks fine in these new logs.

Coming back to the original logs from snorp then, I think I'm fine with closing this as a duplicate of mozilla-mobile/android-components#7143