Closed Bug 1153709 Opened 5 years ago Closed 4 years ago

[Marionette-webapi] emulator_cmd doesn't get response until sending a `timed out` error to client

Categories

(Firefox OS Graveyard :: Emulator, defect)

x86_64
Linux
defect
Not set

Tracking

(tracking-b2g:backlog)

RESOLVED DUPLICATE of bug 1207039
tracking-b2g backlog

People

(Reporter: edgar, Assigned: edgar)

References

Details

Attachments

(1 file)

Snippet of log:
> 04-10 16:21:01.139 I/Gecko   (   44): 1428682861146	Marionette	DEBUG	conn402 emulator <- ({emulator_cmd:"sensor set orientation 0:-180:0", id:54})
// Sending emulator command, but get no response

> 04-10 16:22:52.590 I/Gecko   (   44): 1428682972596	Marionette	DEBUG	conn402 client <- ({from:"0", status:28, sessionId:"{b45d849c-23b7-4a25-860d-dc8e8168154a}", error:{message:"timed out", stacktrace:null, status:28}})
// Test script is timed out. Sending `timed out` error to client.

> 04-10 16:22:52.639 I/Gecko   (   44): 1428682972645	Marionette	DEBUG	conn402 -> ({result:["OK"], to:"0", name:"emulatorCmdResult", id:54})
// The response of emulator command suddenly back.

Some intermittent script time out was caused by this, 
- https://treeherder.mozilla.org/logviewer.html#?job_id=6300850&repo=try
- https://treeherder.mozilla.org/logviewer.html#?job_id=6300858&repo=try
Summary: [Marionette-webapi] emulator_cmd doesn't response until send a `timed out` error to client → [Marionette-webapi] emulator_cmd doesn't get response until sending a `timed out` error to client
Try runs with debugging enabled in devtools to see if we can get some clues:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b80d27623c54&exclusion_profile=false
[Tracking Requested - why for this release]:
https://treeherder.mozilla.org/logviewer.html#?job_id=6477703&repo=try

Snippet of the log with debugging enabled in devtools:
>  04-13 15:52:26.090 I/Gecko   (   44): 1428940346095	Marionette	DEBUG	conn408 emulator <- ({"emulator_cmd":"sensor set orientation 180:0:-90","id":113})
>  04-13 15:52:26.100 I/GeckoDump(   44): DBG-SERVER: Writing JSON packet
>  04-13 15:54:00.200 I/Gecko   (   44): 1428940440204	Marionette	DEBUG	conn408 client <- ({"from":"0","status":28,"sessionId":"{bee27991-ca8a-4281-b7a7-77ce0fbfaf3c}","error":{"message":"timed out","stacktrace":null,"status":28}})
>  04-13 15:54:00.241 I/GeckoDump(   44): DBG-SERVER: Data available: 72
>  04-13 15:54:00.241 I/GeckoDump(   44): DBG-SERVER: Creating a new packet from incoming
>  04-13 15:54:00.241 I/GeckoDump(   44): DBG-SERVER: Starting delimited read for : up to 200 bytes
>  04-13 15:54:00.249 I/GeckoDump(   44): DBG-SERVER: Header read: 69:
>  04-13 15:54:00.249 I/GeckoDump(   44): DBG-SERVER: Found packet header successfully: 69:
>  04-13 15:54:00.269 I/GeckoDump(   44): DBG-SERVER: Header matches JSON packet
>  04-13 15:54:00.269 I/GeckoDump(   44): DBG-SERVER: Existing packet incomplete, keep reading
>  04-13 15:54:00.269 I/GeckoDump(   44): DBG-SERVER: Reading JSON packet
>  04-13 15:54:00.279 I/GeckoDump(   44): DBG-SERVER: Reading JSON data: _l: 69 dL: 0 sA: 69
>  04-13 15:54:00.289 I/GeckoDump(   44): DBG-SERVER: Got: {
>  04-13 15:54:00.289 I/GeckoDump(   44):   "result": [
>  04-13 15:54:00.289 I/GeckoDump(   44):     "OK"
>  04-13 15:54:00.289 I/GeckoDump(   44):   ],
>  04-13 15:54:00.289 I/GeckoDump(   44):   "to": "0",
>  04-13 15:54:00.289 I/GeckoDump(   44):   "name": "emulatorCmdResult",
>  04-13 15:54:00.289 I/GeckoDump(   44):   "id": 113
>  04-13 15:54:00.289 I/GeckoDump(   44): }
>  04-13 15:54:00.309 I/GeckoDump(   44): DBG-SERVER: Writing JSON packet
>  04-13 15:54:00.339 I/Gecko   (   44): 1428940440342	Marionette	DEBUG	conn408 -> ({"result":["OK"],"to":"0","name":"emulatorCmdResult","id":113})
>  04-13 15:54:00.350 I/GeckoDump(   44): DBG-SERVER: Data available: 88
>  04-13 15:54:00.350 I/GeckoDump(   44): DBG-SERVER: Creating a new packet from incoming
>  04-13 15:54:00.350 I/GeckoDump(   44): DBG-SERVER: Starting delimited read for : up to 200 bytes
>  04-13 15:54:00.359 I/GeckoDump(   44): DBG-SERVER: Header read: 85:
>  04-13 15:54:00.359 I/GeckoDump(   44): DBG-SERVER: Found packet header successfully: 85:
>  04-13 15:54:00.359 I/GeckoDump(   44): DBG-SERVER: Header matches JSON packet
>  04-13 15:54:00.359 I/GeckoDump(   44): DBG-SERVER: Existing packet incomplete, keep reading
>  04-13 15:54:00.369 I/GeckoDump(   44): DBG-SERVER: Reading JSON packet
>  04-13 15:54:00.369 I/GeckoDump(   44): DBG-SERVER: Reading JSON data: _l: 85 dL: 0 sA: 85
>  04-13 15:54:00.379 I/GeckoDump(   44): DBG-SERVER: Got: {
>  04-13 15:54:00.379 I/GeckoDump(   44):   "to": "0",
>  04-13 15:54:00.379 I/GeckoDump(   44):   "sessionId": "{bee27991-ca8a-4281-b7a7-77ce0fbfaf3c}",
>  04-13 15:54:00.379 I/GeckoDump(   44):   "name": "getLogs"
>  04-13 15:54:00.379 I/GeckoDump(   44): }
>  04-13 15:54:00.399 I/Gecko   (   44): MARIONETTE TEST RESULT:TEST-PASS | test_sensor_orientation.js | Emulator response: ["OK"] - true was true, expected true
>  04-13 15:54:00.529 I/Gecko   (   44): 1428940440535	Marionette	DEBUG	conn408 -> ({"to":"0","sessionId":"{bee27991-ca8a-4281-b7a7-77ce0fbfaf3c}","name":"getLogs"})
See Also: → 1154215
I added more log in nsSocketTransport2.cpp trying to debug this, but I cannot reproduce this issue after applying the debug patch (over 130+ retriggers, https://treeherder.mozilla.org/#/jobs?repo=try&revision=74365e5cb51a&exclusion_profile=false). :(
Blocks: 1081529
Maybe related to https://android-review.googlesource.com/#/c/169681/? Not sure, but we can give it a shot. (Thanks to Samael finding this)
(In reply to Edgar Chen [:edgar][:echen] from comment #6)
> Try runs with possible fix, cross fingers ...
> 
> https://treeherder.allizom.org/#/jobs?repo=try&revision=6d36f26b6c91&exclusion_profile=false&group_state=expanded

The result looks pretty good, only 4 failure over 130+ retriggers and none of them are caused by the issue we reported in this bug (comment #0).

Comparing with the try runs without the fix: https://treeherder.allizom.org/#/jobs?repo=try&revision=7a080cf8c2ed&exclusion_profile=false&group_state=expanded. I can see 6+ failure with same symptom as comment #0 in 100+ retriggers.

It seems the patches in comment #5 works.
Depends on: 1207039
Blocks: 1212262
I didn't see same issue (comment #0) any more with applying the fix patch of bug 1207039: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8ccd09f7dfa4&exclusion_profile=false&group_state=expanded
Assignee: nobody → echen
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1207039
You need to log in before you can comment on or make changes to this bug.