1082219 - [FMD] Remote wipe ('Erase') not working

Status: RESOLVED WORKSFORME

(Cloud Services Graveyard :: Find My Device, defect)

Description

[Yeojin Chung [:YeojinC]]

Attachment: logcat_20141013_FMDErase.txt

Description:
When the user selects "Erase" on the Find My Device website, the device does not wipe out the internal memory or SD card. The website logs out, and the device gets disconnected afterwards without erasing any content.
   
Repro Steps:
1) Update a Flame device to BuildID: 20141013001201.
2) Go to Settings > Find My Device.
3) Turn on "Enable Find My Device", and log in with an account.
4) On a Web Browser: Navigate to https://find.firefox.com and sign in with your FxA account.
5) When the device is found on the map, select "Erase", and confirm to erase the device.
  
Actual:
The device does not restart and/or wipe itself.  

Expected: 
The device stays on, and the content does not get erased.
  
Environmental Variables:
Device: Flame 2.1
BuildID: 20141013001201
Gaia: d18e130216cd3960cd327179364d9f71e42debda
Gecko: 610ee0e6a776
Gonk: 52c909e821d107d414f851e267dedcd7aae2cebf
Version: 34.0a2 (2.1)
Firmware: V180
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0
  
Repro frequency: 100%
Link to failed test case:
https://moztrap.mozilla.org/manage/case/14046/
https://moztrap.mozilla.org/manage/case/14047/
https://moztrap.mozilla.org/manage/case/14048/
https://moztrap.mozilla.org/manage/case/14049/
See attached: logcat, video
https://www.youtube.com/watch?edit=vd&v=35C9a3428UE

Comment 1

[Yeojin Chung [:YeojinC]]

This issue also reproduces on Flame 2.2 and Flame 2.1:

Flame 2.2 

Device: Flame 2.2 Master KK (319mb) (Full Flash)
BuildID: 20141013040202
Gaia: 3b81896f04a02697e615fa5390086bd5ecfed84f
Gecko: f547cf19d104
Gonk: 52c909e821d107d414f851e267dedcd7aae2cebf
Version: 35.0a1 (2.2 Master)
Firmware: V180
User Agent: Mozilla/5.0 (Mobile; rv:35.0) Gecko/35.0 Firefox/35.0

Flame 2.0

Device: Flame 2.0 KK (319mb) (Full Flash)
BuildID: 20141013000204
Gaia: 6effca669c5baaf6cd7a63c91b71a02c6bd953b3
Gecko: 54ec9cb26b59
Gonk: 52c909e821d107d414f851e267dedcd7aae2cebf
Version: 32.0 (2.0)
Firmware: V180
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

The device gets disconnected, but the content does not get erased.

Comment 2

[Marcia Knous [:marcia]]

[Blocking Requested - why for this release]: Regression in functionality that needs to work on all branches.

Comment 3

[Marcia Knous [:marcia]]

The behavior I am currently seeing is as follows:

1. Initiate Erase Command while logged into the website
2. Map briefly shows with "X" through device
3. Suddenly I am logged out of the website and the phone is never erased.

Comment 4

[Marcia Knous [:marcia]]

Attachment: Logcat with Gaia Debug Traces enabled

Adding this logcat with Gaia debug traces which I captured while reproducing the issue in case it helps.

Comment 5

[JR Conlin [:jrconlin,:jconlin]]

For what it's worth, I'm able to hold a websock connection open for > 5m at a time using a simple python script. I don't believe that AWS is prematurely closing connections.

Comment 6

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Thanks for attaching the logcat output, Marcia.

It looks to me (grepping for 'POST-ing') like the push endpoint stops working: the first 5 connection attempts succeed, and the last 4 attempts fail with a 401 client error.

JR, any thoughts on what might cause the apparent push failures in the attached logcat?

Comment 7

[JR Conlin [:jrconlin,:jconlin]]

Unfortunately, I can't check kibana because the logs are not going there. That's a different problem, but it means that I can only guess right now what the problem could be.

My gut says that this may be a case where the device is either sending an empty assertion or is failing to send a valid HAWK header. I checked the production database and there's no record of a device with an ID of "131e73aa409aa68e8037feb106e4d123", so I'd guess the former rather than the latter. 

If a device has not registered previously, it needs to send the Assertion. If a device has registered previously, it needs to sign the request with a HAWK signature that matches the previously provided value.

Comment 8

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Hmm. Looking more closely at the 401 errors, it appears that adb logcat was executed twice.

In the first logcat output, FMD successfully registers with the push server, and uses that endpoint successfully:

server interaction #1
I/GeckoDump( 1788): [findmydevice] findmydevice received push endpoint!
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/register/:{"pushurl":"https://updates.push.services.mozilla.com/update/xjaG1RZbyuV5BxZo8afQPZVmEHzW5TNxuViTprL6Hu9np5_f2p8qlMrgWau7pcf6uWhipnt8z4V5p2ITEyRYs9CzGcJoyLfU6Eo2JTXti1awwi9_KA==","accepts":["track","erase","lock","ring"],"assert":<browserid assertion, snipped for legibility>}
I/GeckoDump( 1788): [findmydevice] successful request, response: {"clientid":"f9dce08dfcfc4d93839dd25b0b4894b14b9486f999ed46f20b9228059b8211fa","deviceid":"131e73aa409aa68e8037feb106e4d123","secret":"R61jnozqO8Xg9IAbhaDrIQ=="}
I/GeckoDump( 1788): [findmydevice] findmydevice successfully registered: {"clientid":"f9dce08dfcfc4d93839dd25b0b4894b14b9486f999ed46f20b9228059b8211fa","deviceid":"131e73aa409aa68e8037feb106e4d123","secret":"R61jnozqO8Xg9IAbhaDrIQ=="}


The other successful server interactions use the established push endpoint:


server interaction #2:
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/131e73aa409aa68e8037feb106e4d123: {"has_passcode":false}
I/GeckoDump( 1788): [findmydevice] successful request, response: {}
I/GeckoDump( 1788): [findmydevice] current id set to: "f9dce08dfcfc4d93839dd25b0b4894b14b9486f999ed46f20b9228059b8211fa"

server interaction #3:
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/131e73aa409aa68e8037feb106e4d123: {"has_passcode":false}
I/GeckoDump( 1788): [findmydevice] successful request, response: {"t":{"d":60}}
I/GeckoDump( 1788): [findmydevice] command t, args [60]

server interaction #4:
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/131e73aa409aa68e8037feb106e4d123: {"t":{"ok":true,"la":37.3872118,"lo":-122.0603017,"acc":100,"ti":1413323267415},"has_passcode":false}
I/GeckoDump( 1788): [findmydevice] successful request, response: {}

server interaction #5:
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/131e73aa409aa68e8037feb106e4d123: {"t":{"ok":true,"la":37.3872118,"lo":-122.0603017,"acc":100,"ti":1413323281649},"has_passcode":false}
I/GeckoDump( 1788): [findmydevice] successful request, response: {}


In the second adb logcat output, it looks like FMD never successfully connects using the deviceid that was returned in server interaction #1.


server interaction #6:
I/GeckoDump( 1788): [findmydevice] findmydevice attempting registration.
I/GeckoDump( 1788): [findmydevice] registering: false
I/GeckoDump( 1788): [findmydevice] findmydevice received push endpoint!
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/register/: {"pushurl":"https://updates.push.services.mozilla.com/update/VACFo6eXm5XToFDmBzCE3UgcZgji6yWhklbrKhHNO5Mr1npjvgWJUkGUAioufLtBW3CIEUILRMGZlwif9A_0siePKV2vY1ha2_yi83nR-xeJ4Q_Q3A==","accepts":["track","erase","lock","ring"],"deviceid":"131e73aa409aa68e8037feb106e4d123"}
I/GeckoDump( 1788): [findmydevice] request failed with status 401
I/GeckoDump( 1788): [findmydevice] findmydevice request failed with status: 401

server interaction #7:
I/GeckoDump( 1788): [findmydevice] findmydevice attempting registration.
I/GeckoDump( 1788): [findmydevice] registering: false
I/GeckoDump( 1788): [findmydevice] findmydevice received push endpoint!
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/register/: {"pushurl":"https://updates.push.services.mozilla.com/update/lG-UuNDASVaxvfSqR_FKokbYCQUrEPwvJbjFah0ePLUMBWtOMHo6odlhGCbO9g72Nq6O-Fs-hM3PJWbQTsij6l2H-ceUZ3m8bWOvbOu7dtnKLcdu3w==","accepts":["track","erase","lock","ring"],"deviceid":"131e73aa409aa68e8037feb106e4d123"}
I/GeckoDump( 1788): [findmydevice] request failed with status 401
I/GeckoDump( 1788): [findmydevice] findmydevice request failed with status: 401

server interaction #8:
I/GeckoDump( 1788): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[],"command":[{}]}
I/GeckoDump( 1788): [findmydevice] findmydevice attempting registration.
I/GeckoDump( 1788): [findmydevice] registering: false
I/GeckoDump( 1788): [findmydevice] findmydevice received push endpoint!
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/register/: {"pushurl":"https://updates.push.services.mozilla.com/update/FRS39IqEh0g52lfVL2UmA4enbyeXOsL2stJR9J3q1zVfcdSdNtXzrsU8oWLvN8KJ6ypdOtjysqp0J4EEH4ZXCf1eprzEOoxIG6HmVidjWmKOmU91RQ==","accepts":["track","erase","lock","ring"],"deviceid":"131e73aa409aa68e8037feb106e4d123"}
I/GeckoDump( 1788): [findmydevice] request failed with status 401

server interaction #9:
I/GeckoDump( 1788): [findmydevice] findmydevice attempting registration.
I/GeckoDump( 1788): [findmydevice] registering: false
I/GeckoDump( 1788): [findmydevice] findmydevice received push endpoint!
I/GeckoDump( 1788): [findmydevice] POST-ing to https://find.firefox.com/1/register/: {"pushurl":"https://updates.push.services.mozilla.com/update/K-9futVpcyiFGKnGB-4SspAuOh5CBIR0Wt0BruYjYgfPUh6kFshgum-tLxm1nSbyqS_6gh510tBr5YcjxfQbpxJ4r0YbdmgzkMhvT8kMs0HAT6ln5A==","accepts":["track","erase","lock","ring"],"deviceid":"131e73aa409aa68e8037feb106e4d123"}
I/GeckoDump( 1788): [findmydevice] request failed with status 401
I/GeckoDump( 1788): [findmydevice] findmydevice request failed with status: 401

Comment 9

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

(In reply to JR Conlin [:jrconlin,:jconlin] from comment #7)
> Unfortunately, I can't check kibana because the logs are not going there.
> That's a different problem, but it means that I can only guess right now
> what the problem could be.

Is it a known issue that we don't have logging? What's the bug number?

> 
> My gut says that this may be a case where the device is either sending an
> empty assertion or is failing to send a valid HAWK header. I checked the
> production database and there's no record of a device with an ID of
> "131e73aa409aa68e8037feb106e4d123", so I'd guess the former rather than the
> latter.

That's funny. Is there some reason it looks like that deviceid worked properly for a track call in the first set of logged interactions?

> 
> If a device has not registered previously, it needs to send the Assertion.
> If a device has registered previously, it needs to sign the request with a
> HAWK signature that matches the previously provided value.

Hmm. Not sure if that's debuggable based on the logcat output. Thoughts?

Comment 10

[JR Conlin [:jrconlin,:jconlin]]

(In reply to Jared Hirsch [:_6a68] [NEEDINFO pls] from comment #9)
> (In reply to JR Conlin [:jrconlin,:jconlin] from comment #7)
> > Unfortunately, I can't check kibana because the logs are not going there.
> > That's a different problem, but it means that I can only guess right now
> > what the problem could be.
> 
> Is it a known issue that we don't have logging? What's the bug number?
https://bugzilla.mozilla.org/show_bug.cgi?id=1082219
This may just be because I am not in the office and may need to have some special configuration to properly hit the logging box. 

> 
> > 
> > My gut says that this may be a case where the device is either sending an
> > empty assertion or is failing to send a valid HAWK header. I checked the
> > production database and there's no record of a device with an ID of
> > "131e73aa409aa68e8037feb106e4d123", so I'd guess the former rather than the
> > latter.
> 
> That's funny. Is there some reason it looks like that deviceid worked
> properly for a track call in the first set of logged interactions?

I have no idea why. Unless the device was erased between the first instance, is trying to reuse the ID and never sent a new assertion. Since the server has no data corresponding to an erased device, it can't reauthorize the device without an assertion.

> 
> > 
> > If a device has not registered previously, it needs to send the Assertion.
> > If a device has registered previously, it needs to sign the request with a
> > HAWK signature that matches the previously provided value.
> 
> Hmm. Not sure if that's debuggable based on the logcat output. Thoughts?

Possibly not, since I don't know if you log the fact that an assertion is being sent. I am still trying to get access to the server logs so I can see if there's more information available.

Comment 11

[JR Conlin [:jrconlin,:jconlin]]

Ok, looking a bit harder at the logcat info, I see a successful registration at line 680 (note the assertion in the line prior), This results in the deviceid being assigned and secret generated. 
All goes well until line 2095, when a reregistration attempt is made that fails. 

Again the odd part to me is that there's no information for any device with this ID in the production database, nor in the production log information. The data could be erased from the database if the device requested an Erase (it didn't), but there should be numerous records generated even if an unknown device attempts to perform an action.

Comment 12

[JR Conlin [:jrconlin,:jconlin]]

Curiouser and curiouser...
I'm not sure if this is related, but I'm able to look at the ADB logs for my keon, and saw the following:

[==
I/GeckoDump(  502): [findmydevice] findmydevice attempting registration.
I/GeckoDump(  502): [findmydevice] registering: false
W/GeckoConsole(  111): [JavaScript Error: "push.services.mozilla.com : server does not support RFC 5746, see CVE-2009-3555"]
W/GeckoConsole(  111): [JavaScript Error: "NS_ERROR_NOT_CONNECTED: Component returned failure code: 0x804b000c (NS_ERROR_NOT_CONNECT
ED) [nsIWebSocketChannel.sendMsg]" {file: "resource://gre/modules/PushService.jsm" line: 495}]
D/QCRIL_RPC(  117): Enter qcril_cm_srvsys_event_callback
==]

RFC 5746 requires that TLS be secured from renegotiation attacks by allowing a specific handshake sequence. Machines that allow for renegotiation that do not follow that handshake are insecure. Our machines are configured to not allow TLS renegotiation, however the TLS detection code is not accepting that as a valid option. (This is discussed in https://bugzilla.mozilla.org/show_bug.cgi?id=970453)

Oddly, restarting the mobile device allows it to reconnect for a period, then the device turns off network and can't reconnect.

Comment 13

[Andrew Overholt [:overholt]]

No-Jun confirmed with me that this is a regression so 2.1+.

Comment 14

[Marcia Knous [:marcia]]

Jared: For the qawanted, can we please get clarification of what you need from QA?  Thanks.

Comment 15

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

(In reply to Andrew Overholt [:overholt] from comment #13)
> No-Jun confirmed with me that this is a regression so 2.1+.

Hey Andrew - Just FYI, it's not clear if this is a server bug or a client bug.

If it's a bug on the server, then all versions of Gaia would be affected, but we wouldn't need to land code on any of them to fix the bug. I understand if you want to set 2.1+, but thought I should provide a little more context.

Comment 16

[Andrew Overholt [:overholt]]

Thanks, Jared.  Yeah, I know it's still under investigation but we preemptively set 2.1+ in case it is specific to the client on 2.1.

Comment 17

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

(In reply to Marcia Knous [:marcia - use needinfo] from comment #14)
> Jared: For the qawanted, can we please get clarification of what you need
> from QA?  Thanks.

Hi Marcia,

Sure. Would you mind reflashing your device and attempting to erase again, with gaia debug traces enabled, a brand new firefox account, and attach the `adb logcat` output?

Here's my reasoning: I noticed that your attachment included two separate logs. In the first log, registration succeeds, and the track command is repeatedly received , but I don't see any erase command at all, or any errors. In the second log, registration fails repeatedly. The adb log file overwrites itself after it hits a size limit, so I'm concerned that maybe some useful errors were lost in between the time when the first and second logs were generated.

Comment 18

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

(In reply to Marcia Knous [:marcia - use needinfo] from comment #3)
> The behavior I am currently seeing is as follows:
> 
> 1. Initiate Erase Command while logged into the website
> 2. Map briefly shows with "X" through device
> 3. Suddenly I am logged out of the website and the phone is never erased.

Based on these symptoms, I'm inclined to think there is a problem with the FMD website, as the attached adb logs don't show that an erase command was received at all.

Working on reproducing now.

Comment 19

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

I was able to reproduce the same symptoms as Marcia with a freshly flashed Flame: hitting 'erase' never sends an erase command to the device, but does show the device as deleted on the website, then logs me out after 10-15 seconds.

I'll attaching the logcat output. I sent adb logcat's output to a separate file, so it's rather long, contains an alarming number of odd loglines from some location service code, but does have *every* fmd server interaction that happened on device.

What I see is:

- FMD registers successfully with server
- FMD receives track command several times
- FMD sends track responses successfully several times
- after 'erase' was clicked on the website, FMD fails to connect and never receives the erase command

Comment 20

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Attachment: another logcat with traces enabled showing no 'erase' command hits the device

Comment 22

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Just got out of bug triage, JR has found a server bug, reassigning.

Marcia - No need to attempt to repro further, I think. Thanks for your help on this!

Comment 23

[Joshua Mitchell (Inactive)]

striking QA-Wanted then

Comment 24

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Hey JR - I see that a patch has landed against the FMD github repo[1], but I still don't quite understand the root cause of the bug.

We haven't made significant changes to the FMD client that would have introduced this bug. Was there a regression on the server?

Also, the description of the github bug suggests that the problem is that the FMD server isn't waiting long enough to delete the account on the server. But, from the adb logcat output, it looks like the erase command was never sent to the device at all.

What am I missing here?

[1] https://github.com/mozilla-services/FindMyDevice/issues/295

Comment 25

[JR Conlin [:jrconlin,:jconlin]]

So, this turned out to be a race condition. The problem was that the server was adding the command to the outbound device message queue then sending the push update. Since earlier dev versions of the client were not sending an ACK, the server would "guess" when the best time to delete user information was. In most cases, it was the next incoming command from the device. After the client fix was rolled out, this introduced a potential race condition where the device would not always get the erase command, and the server would wipe all record of the device. 

The patch resolves this by only wiping all data after the client ACKs the erase command.

Comment 26

[Marcia Knous [:marcia]]

I think Jared got what he needed for logs so removing my ni.

Comment 27

[Marcia Knous [:marcia]]

Adding qawanted to confirm this now works on both branches.

Comment 28

[bhavana bajaj [:bajaj]]

Looks like server side changes should fix this, so marking this resolved WFM. Marcia, feel free to NI :JR if you see any issues.