Closed
Bug 1033035
Opened 11 years ago
Closed 11 years ago
FMD keeps making request from server even if server cmd has timed out.
Categories
(Firefox OS Graveyard :: FindMyDevice, defect)
Firefox OS Graveyard
FindMyDevice
Tracking
(Not tracked)
RESOLVED
WORKSFORME
People
(Reporter: edwong, Assigned: ggp)
Details
1. sign into FMD via these instructions, enable gaia traces: https://wiki.mozilla.org/User_Services/Try_FMD#Get_Find_My_Device_Working
2. on b2g sign into fxa, then enable FMD
2a. start logcat
adb logcat -v time | grep findmydevice
3. find phone via web browser goto fmd.stage.mozaws.net
4. close web browser.
5. leave logcat open
actual: phone keeps making server requests
07-01 14:10:32.033 I/GeckoDump( 1114): [findmydevice] got wake up request
07-01 14:10:32.033 I/GeckoDump( 1114): [findmydevice] enabled, trying to reach the server
07-01 14:10:52.323 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:11:52.323 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:12:52.343 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:13:52.353 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:14:52.753 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:15:32.793 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:15:52.263 I/GeckoDump( 1114): [findmydevice] findmydevice got push notification!
07-01 14:15:53.293 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:16:53.313 I/GeckoDump( 1114): [findmydevice] findmydevice alarm!
07-01 14:17:53.363 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:18:53.363 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:19:53.363 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:19:53.403 I/GeckoDump( 1114): [findmydevice] findmydevice alarm!
07-01 14:20:52.453 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
07-01 14:21:27.763 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 504
07-01 14:22:27.783 I/GeckoDump( 1114): [findmydevice] findmydevice alarm!
07-01 14:24:53.833 I/GeckoDump( 1114): [findmydevice] findmydevice request failed with status: 0
|
||
Updated•11 years ago
|
Assignee: nobody → ggoncalves
|
Assignee | |
Comment 1•11 years ago
|
||
There are a couple of interesting things in this log. For one, note how the device is getting repeated push notifications, presumably after the page is closed. I don't believe this should be happening, and it could be just bug 1030249, or some other server bug.
Aside from that, what I see is that we failed to contact the server a few times, which causes us to retry until we succeed. This is intended behavior, so I think we should focus on why we're getting those push notifications. JR, does anything come to mind?
Flags: needinfo?(jrconlin)
|
||
Comment 2•11 years ago
|
||
I think you're right and that this is related to the concurrency issue. I'll be pushing a version this morning that should address this. I'll be interested to see if this is a continuing problem.
Flags: needinfo?(jrconlin)
|
||
Comment 6•11 years ago
|
||
A lot of console spew, so a bit tricky to decipher. Definitely looks better than before, but I'm still a bit confused over current behavior.
I closed the https://find.firefox.com/ site around 08-05 11:26:05.914 (see logs below), but noticed that it was still POST-ing a couple stray {t:{}} commands around 08-05 11:28:03.024 (2m later).
:ggp and :jrconlin, does that seem right?
```
$ adb logcat -v time | grep -e findmydevice
- waiting for device -
08-05 11:23:04.924 I/GeckoDump( 2629): [findmydevice] updating location to (37.3874939, -122.062256)
08-05 11:23:04.924 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:23:04.924 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[],"command":[]}
08-05 11:23:04.924 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3874939,"lo":-122.062256,"acc":5000,"ti":1407262984877},"has_passcode":false}
08-05 11:23:04.964 I/GeckoDump( 2629): [findmydevice] updating location to (37.3874939, -122.062256)
08-05 11:23:04.964 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:23:04.964 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{}],"command":[]}
08-05 11:23:04.964 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3874939,"lo":-122.062256,"acc":5000,"ti":1407262984877},"has_passcode":false}
08-05 11:23:04.984 I/GeckoDump( 2629): [findmydevice] updating location to (37.3874939, -122.062256)
08-05 11:23:04.984 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{},{}],"command":[]}
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3874939,"lo":-122.062256,"acc":5000,"ti":1407262984877},"has_passcode":false}
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] updating location to (37.3874939, -122.062256)
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{},{},{}],"command":[]}
08-05 11:23:04.994 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3874939,"lo":-122.062256,"acc":5000,"ti":1407262984877},"has_passcode":false}
08-05 11:23:05.354 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:23:05.354 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:23:05.404 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:23:05.404 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:23:05.444 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:23:05.444 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{},{},{}],"command":[]}
08-05 11:23:05.464 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:23:05.464 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{},{}],"command":[]}
08-05 11:23:05.564 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:23:05.564 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{}],"command":[]}
08-05 11:23:05.594 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:23:05.594 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{}],"command":[]}
### OPENING FMD SITE #################################################################
08-05 11:25:05.634 I/GeckoDump( 2629): [findmydevice] findmydevice got push notification!
08-05 11:25:05.634 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:25:05.654 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[],"command":[]}
08-05 11:25:05.654 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"has_passcode":false}
08-05 11:25:05.884 I/GeckoDump( 2629): [findmydevice] successful request, response: {"t":{"d":60}}
08-05 11:25:05.884 I/GeckoDump( 2629): [findmydevice] command t, args [60]
08-05 11:25:05.894 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "command"
08-05 11:25:05.894 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{}],"command":[]}
08-05 11:25:06.044 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:25:06.044 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{}],"command":[{}]}
08-05 11:25:17.734 I/GeckoDump( 2629): [findmydevice] updating location to (37.3873341, -122.0603461)
08-05 11:25:17.734 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:25:17.734 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[],"command":[{}]}
08-05 11:25:17.744 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3873341,"lo":-122.0603461,"acc":100,"ti":1407263117724},"has_passcode":false}
08-05 11:25:17.894 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:25:18.014 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:25:18.014 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{}],"command":[{}]}
### CLOSING FMD SITE #################################################################
08-05 11:26:05.914 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "command"
08-05 11:26:05.914 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[],"command":[{}]}
08-05 11:28:03.024 I/GeckoDump( 2629): [findmydevice] updating location to (37.3871994, -122.0604467)
08-05 11:28:03.024 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:28:03.024 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[],"command":[]}
08-05 11:28:03.024 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3871994,"lo":-122.0604467,"acc":5000,"ti":1407263282991},"has_passcode":false}
08-05 11:28:03.054 I/GeckoDump( 2629): [findmydevice] updating location to (37.3871994, -122.0604467)
08-05 11:28:03.054 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:28:03.054 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{}],"command":[]}
08-05 11:28:03.054 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3871994,"lo":-122.0604467,"acc":5000,"ti":1407263282991},"has_passcode":false}
08-05 11:28:03.074 I/GeckoDump( 2629): [findmydevice] updating location to (37.3871994, -122.0604467)
08-05 11:28:03.074 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:28:03.074 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{},{}],"command":[]}
08-05 11:28:03.084 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3871994,"lo":-122.0604467,"acc":5000,"ti":1407263282991},"has_passcode":false}
08-05 11:28:03.094 I/GeckoDump( 2629): [findmydevice] updating location to (37.3871994, -122.0604467)
08-05 11:28:03.094 I/GeckoDump( 2629): [findmydevice] begin high priority section, reason: "clientLogic"
08-05 11:28:03.094 I/GeckoDump( 2629): [findmydevice] acquiring one wakelock, wakelocks are: {"clientLogic":[{},{},{}],"command":[]}
08-05 11:28:03.094 I/GeckoDump( 2629): [findmydevice] POST-ing to https://find.firefox.com/1/cmd/4a01a1d0407fb0d480a904b15cba861d: {"t":{"ok":true,"la":37.3871994,"lo":-122.0604467,"acc":5000,"ti":1407263282991},"has_passcode":false}
08-05 11:28:03.434 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:28:03.454 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:28:03.454 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:28:03.464 I/GeckoDump( 2629): [findmydevice] successful request, response: {}
08-05 11:28:03.574 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:28:03.574 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{},{},{}],"command":[]}
08-05 11:28:03.604 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:28:03.604 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{},{}],"command":[]}
08-05 11:28:03.644 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:28:03.644 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{},{}],"command":[]}
08-05 11:28:03.654 I/GeckoDump( 2629): [findmydevice] end high priority section, reason: "clientLogic"
08-05 11:28:03.654 I/GeckoDump( 2629): [findmydevice] releasing one wakelock, wakelocks are: {"clientLogic":[{}],"command":[]}
```
(ended because my screen went to sleep which caused my adb lolcat to disconnect and stop the command)
Flags: needinfo?(pdehaan) → needinfo?(ggoncalves)
|
|
Assignee | |
Comment 7•11 years ago
|
||
It's wrong, but not nearly as wrong as comment 1 :)
Comment 1, which prompted the filing of this bug, is clearly a server/push failure, which we haven't seen ever since. Because of that, I believe we should just resolve this bug as invalid.
Comment 6 shows some odd (and arguably undesirable) client-side behavior caused by our naive use of the geolocation API, but that's totally unrelated to the initial issue, and is both unlikely to happen (at least in my experience) and easy to fix, so I suggest filing a separate bug.
Flags: needinfo?(ggoncalves)
|
|
||
Comment 8•11 years ago
|
||
Thanks :ggp
I agree, lets close this as fixed since the core issue was resolved, and I can file a new [and probably poorly worded] bug where we can track <a href="https://bugzilla.mozilla.org/show_bug.cgi?id=1033035#c6">comment 6's</a> output and your comment above.
|
|
Assignee | |
Updated•11 years ago
|
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
|
|
||
Comment 9•11 years ago
|
||
I'm really hoping that edwong blesses the latest production release candidate so that the server that's been running for 28 days now is updated.
You need to log in
before you can comment on or make changes to this bug.
Description
•