Closed Bug 1609162 Opened 4 years ago Closed 3 years ago

Intermittent remote/cdp/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222) [NS_ERROR_SOCKET_ADDRESS_IN_USE]

Categories

(Remote Protocol :: Agent, defect, P2)

All
Linux
defect
Points:
8

Tracking

(firefox88 fixed, firefox89 fixed)

RESOLVED FIXED
89 Branch
Tracking Status
firefox88 --- fixed
firefox89 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

Details

(Keywords: intermittent-failure, Whiteboard: [bidi-m1-mvp][stockwell unknown])

Attachments

(1 file)

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=284860440&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bwnHcUBDSeqEuTIa63_IcA/runs/0/artifacts/public/logs/live_backing.log


[task 2020-01-14T15:53:26.268Z] 15:53:26 INFO - TEST-PASS | remote/test/browser/target/browser_activateTarget.js | activateTarget raised error without an argument -
[task 2020-01-14T15:53:26.268Z] 15:53:26 INFO - CDP client closed
[task 2020-01-14T15:53:26.268Z] 15:53:26 INFO - CDP server stopped
[task 2020-01-14T15:53:26.268Z] 15:53:26 INFO - Leaving test bound raisesWithoutArguments
[task 2020-01-14T15:53:26.268Z] 15:53:26 INFO - Entering test bound raisesWithUnknownTargetId
[task 2020-01-14T15:53:26.269Z] 15:53:26 INFO - CDP server started
[task 2020-01-14T15:53:26.269Z] 15:53:26 INFO - Buffered messages logged at 15:53:25
[task 2020-01-14T15:53:26.269Z] 15:53:26 INFO - CDP client instantiated
[task 2020-01-14T15:53:26.270Z] 15:53:26 INFO - TEST-PASS | remote/test/browser/target/browser_activateTarget.js | activateTarget raised error with unkown target id -
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - CDP client closed
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - CDP server stopped
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - Leaving test bound raisesWithUnknownTargetId
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - Entering test bound selectTabInOtherWindow
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - CDP server started
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - CDP server stopped
[task 2020-01-14T15:53:26.274Z] 15:53:26 INFO - Buffered messages finished
[task 2020-01-14T15:53:26.275Z] 15:53:26 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/target/browser_activateTarget.js | Uncaught exception - [object ProgressEvent]
[task 2020-01-14T15:53:26.275Z] 15:53:26 INFO - Leaving test bound selectTabInOtherWindow
[task 2020-01-14T15:53:26.275Z] 15:53:26 INFO - GECKO(4884) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-01-14T15:53:26.276Z] 15:53:26 INFO - GECKO(4884) | MEMORY STAT | vsize 2847MB | residentFast 354MB | heapAllocated 159MB
[task 2020-01-14T15:53:26.281Z] 15:53:26 INFO - TEST-OK | remote/test/browser/target/browser_activateTarget.js | took 1781ms

Problem here is that the internal httpd client is not able to create the server socket because it is still in use:

[task 2020-01-14T15:53:24.199Z] 15:53:24     INFO - TEST-START | remote/test/browser/target/browser_activateTarget.js
[task 2020-01-14T15:53:25.449Z] 15:53:25     INFO - GECKO(4884) | !!! could not start server on port 9222: [Exception... "Component returned failure code: 0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE) [nsIServerSocket.init]"  nsresult: "0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE)"  location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: _start :: line 570"  data: no]
[task 2020-01-14T15:53:25.451Z] 15:53:25     INFO - GECKO(4884) | 1579017205445	RemoteAgent	ERROR	unable to stop listener: [Exception... "Unexpected error"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: stop :: line 624"  data: no] Stack trace: stop()@HTTPD.jsm:624
[task 2020-01-14T15:53:25.452Z] 15:53:25     INFO - GECKO(4884) | close()@RemoteAgent.jsm:119
[task 2020-01-14T15:53:25.452Z] 15:53:25     INFO - GECKO(4884) | asyncListen()@RemoteAgent.jsm:100
[task 2020-01-14T15:53:25.453Z] 15:53:25     INFO - GECKO(4884) | 1579017205445	RemoteAgent	ERROR	Unable to start remote agent: : [Exception... "Component is not available"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: _start :: line 615"  data: no] Stack trace: _start()@HTTPD.jsm:615
[task 2020-01-14T15:53:25.454Z] 15:53:25     INFO - GECKO(4884) | asyncListen()@RemoteAgent.jsm:93
Summary: Intermittent remote/test/browser/target/browser_activateTarget.js | Uncaught exception - [object ProgressEvent] → Intermittent remote/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222)
Summary: Intermittent remote/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222) → Intermittent remote/cdp/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222)
OS: Unspecified → Linux
Hardware: Unspecified → All

This is actually a Linux-only issue.

Summary: Intermittent remote/cdp/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222) → Intermittent remote/cdp/test/browser/<random> | Uncaught exception - [object ProgressEvent] (could not start server on port 9222) [NS_ERROR_SOCKET_ADDRESS_IN_USE]

There are 29 total failures in the last 7 days on

  • linux1804-64 opt
  • linux1804-64-qr opt
  • linux1804-64-shippable opt
    Recent failure log:

[task 2021-03-06T11:14:26.271Z] 11:14:26 INFO - TEST-START | remote/cdp/test/browser/dom/browser_describeNode.js
[task 2021-03-06T11:14:26.750Z] 11:14:26 INFO - GECKO(1841) | 1615029266740 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
[task 2021-03-06T11:14:26.750Z] 11:14:26 INFO - GECKO(1841) | 1615029266742 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"98e11a8d-5d8c-421c-b93d-323b38861138","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":null}}}
[task 2021-03-06T11:14:26.751Z] 11:14:26 INFO - GECKO(1841) | 1615029266742 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"f2631a45-e4f9-4806-9223-1d80339af13f","type":"browser","attached":false}}}
[task 2021-03-06T11:14:26.751Z] 11:14:26 INFO - GECKO(1841) | 1615029266742 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"adfad258-200c-4b3e-9424-66fd2491a02a","type":"page","title":"","url":"about:blank","attached":true,"browserContextId":null}}}
[task 2021-03-06T11:14:26.752Z] 11:14:26 INFO - GECKO(1841) | 1615029266742 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":1,"result":{}}
[task 2021-03-06T11:14:26.752Z] 11:14:26 INFO - GECKO(1841) | 1615029266744 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":2,"method":"DOM.describeNode","params":{"objectId":null}}
[task 2021-03-06T11:14:26.752Z] 11:14:26 INFO - GECKO(1841) | 1615029266746 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":2,"error":{"message":"objectId: string value expected","data":"describeNode@chrome://remote/content/cdp/domains/content ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:26.753Z] 11:14:26 INFO - GECKO(1841) | 1615029266747 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":3,"method":"DOM.describeNode","params":{"objectId":true}}
[task 2021-03-06T11:14:26.753Z] 11:14:26 INFO - GECKO(1841) | 1615029266747 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":3,"error":{"message":"objectId: string value expected","data":"describeNode@chrome://remote/content/cdp/domains/content ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:26.754Z] 11:14:26 INFO - GECKO(1841) | 1615029266748 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":4,"method":"DOM.describeNode","params":{"objectId":1}}
[task 2021-03-06T11:14:26.756Z] 11:14:26 INFO - GECKO(1841) | 1615029266749 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":4,"error":{"message":"objectId: string value expected","data":"describeNode@chrome://remote/content/cdp/domains/content ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:26.763Z] 11:14:26 INFO - GECKO(1841) | 1615029266756 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":5,"method":"DOM.describeNode","params":{"objectId":[]}}
[task 2021-03-06T11:14:26.763Z] 11:14:26 INFO - GECKO(1841) | 1615029266756 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":5,"error":{"message":"objectId: string value expected","data":"describeNode@chrome://remote/content/cdp/domains/content ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:26.763Z] 11:14:26 INFO - GECKO(1841) | 1615029266757 RemoteAgent TRACE (connection {372d78ae-b26a-47f2-b076-fb28df436176})-> {"id":6,"method":"DOM.describeNode","params":{"objectId":{}}}
[task 2021-03-06T11:14:26.764Z] 11:14:26 INFO - GECKO(1841) | 1615029266758 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"id":6,"error":{"message":"objectId: string value expected","data":"describeNode@chrome://remote/content/cdp/domains/content ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:26.771Z] 11:14:26 INFO - GECKO(1841) | 1615029266765 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetDestroyed","params":{"targetId":"adfad258-200c-4b3e-9424-66fd2491a02a"}}
[task 2021-03-06T11:14:26.791Z] 11:14:26 INFO - GECKO(1841) | 1615029266776 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetDestroyed","params":{"targetId":"98e11a8d-5d8c-421c-b93d-323b38861138"}}
[task 2021-03-06T11:14:26.792Z] 11:14:26 INFO - GECKO(1841) | 1615029266777 RemoteAgent TRACE <-(connection {372d78ae-b26a-47f2-b076-fb28df436176}) {"method":"Target.targetDestroyed","params":{"targetId":"f2631a45-e4f9-4806-9223-1d80339af13f"}}
[task 2021-03-06T11:14:26.809Z] 11:14:26 INFO - GECKO(1841) | !!! could not start server on port 9222: [Exception... "Component returned failure code: 0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE) [nsIServerSocket.init]" nsresult: "0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE)" location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: _start :: line 567" data: no]
[task 2021-03-06T11:14:26.810Z] 11:14:26 INFO - GECKO(1841) | 1615029266803 RemoteAgent ERROR unable to stop listener: [Exception... "Unexpected error" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: stop :: line 621" data: no] Stack trace: stop()@HTTPD.jsm:621
[task 2021-03-06T11:14:26.811Z] 11:14:26 INFO - GECKO(1841) | close()@RemoteAgent.jsm:129
[task 2021-03-06T11:14:26.812Z] 11:14:26 INFO - GECKO(1841) | asyncListen()@RemoteAgent.jsm:110
[task 2021-03-06T11:14:26.813Z] 11:14:26 INFO - GECKO(1841) | 1615029266804 RemoteAgent ERROR Unable to start remote agent: : [Exception... "Component is not available" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: _start :: line 612" data: no] Stack trace: _start()@HTTPD.jsm:612
[task 2021-03-06T11:14:26.814Z] 11:14:26 INFO - GECKO(1841) | asyncListen()@RemoteAgent.jsm:103
[task 2021-03-06T11:14:27.177Z] 11:14:27 INFO - TEST-INFO | started process screentopng
[task 2021-03-06T11:14:27.416Z] 11:14:27 INFO - TEST-INFO | screentopng: exit 0
[task 2021-03-06T11:14:27.417Z] 11:14:27 INFO - Buffered messages logged at 11:14:26
[task 2021-03-06T11:14:27.417Z] 11:14:27 INFO - Entering test bound objectIdInvalidTypes
[task 2021-03-06T11:14:27.418Z] 11:14:27 INFO - CDP server started
[task 2021-03-06T11:14:27.418Z] 11:14:27 INFO - CDP client instantiated
[task 2021-03-06T11:14:27.419Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails with invalid type: null -
[task 2021-03-06T11:14:27.419Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails with invalid type: true -
[task 2021-03-06T11:14:27.420Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails with invalid type: 1 -
[task 2021-03-06T11:14:27.420Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails with invalid type: -
[task 2021-03-06T11:14:27.421Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails with invalid type: [object Object] -
[task 2021-03-06T11:14:27.421Z] 11:14:27 INFO - CDP client closed
[task 2021-03-06T11:14:27.422Z] 11:14:27 INFO - CDP server stopped
[task 2021-03-06T11:14:27.422Z] 11:14:27 INFO - Leaving test bound objectIdInvalidTypes
[task 2021-03-06T11:14:27.423Z] 11:14:27 INFO - Entering test bound objectIdUnknownValue
[task 2021-03-06T11:14:27.423Z] 11:14:27 INFO - CDP server started
[task 2021-03-06T11:14:27.424Z] 11:14:27 INFO - Buffered messages logged at 11:14:27
[task 2021-03-06T11:14:27.424Z] 11:14:27 INFO - CDP server stopped
[task 2021-03-06T11:14:27.425Z] 11:14:27 INFO - Buffered messages finished
[task 2021-03-06T11:14:27.425Z] 11:14:27 INFO - TEST-UNEXPECTED-FAIL | remote/cdp/test/browser/dom/browser_describeNode.js | Uncaught exception - [object ProgressEvent]
[task 2021-03-06T11:14:27.426Z] 11:14:27 INFO - Leaving test bound objectIdUnknownValue
[task 2021-03-06T11:14:27.426Z] 11:14:27 INFO - Entering test bound objectIdIsNotANode
[task 2021-03-06T11:14:27.427Z] 11:14:27 INFO - CDP server started
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - CDP client instantiated
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - GECKO(1841) | 1615029267617 RemoteAgent TRACE (connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f})-> {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - GECKO(1841) | 1615029267617 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"9fa4b6a1-4519-4e65-83e3-a983c3f55004","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":null}}}
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - GECKO(1841) | 1615029267617 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"2ebc1982-ad9f-4e04-9dc4-268836827408","type":"browser","attached":false}}}
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - GECKO(1841) | 1615029267617 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"a03a71df-84ca-48cc-952a-e8b2339c384b","type":"page","title":"","url":"about:blank","attached":true,"browserContextId":null}}}
[task 2021-03-06T11:14:27.624Z] 11:14:27 INFO - GECKO(1841) | 1615029267617 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"id":1,"result":{}}
[task 2021-03-06T11:14:27.661Z] 11:14:27 INFO - GECKO(1841) | 1615029267657 RemoteAgent TRACE (connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f})-> {"id":2,"method":"Runtime.enable","params":{}}
[task 2021-03-06T11:14:27.665Z] 11:14:27 INFO - GECKO(1841) | 1615029267661 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"id":2,"result":{}}
[task 2021-03-06T11:14:27.666Z] 11:14:27 INFO - GECKO(1841) | 1615029267663 RemoteAgent TRACE (connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f})-> {"id":3,"method":"Runtime.evaluate","params":{"expression":"[42]"}}
[task 2021-03-06T11:14:27.669Z] 11:14:27 INFO - GECKO(1841) | 1615029267664 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"about:blank","name":"","auxData":{"isDefault":true,"frameId":"57","type":"default"}}}}
[task 2021-03-06T11:14:27.670Z] 11:14:27 INFO - GECKO(1841) | 1615029267666 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"id":3,"result":{"result":{"objectId":"83605fce-a71b-49e4-8183-fd1f9816ee92","type":"object","subtype":"array"}}}
[task 2021-03-06T11:14:27.706Z] 11:14:27 INFO - GECKO(1841) | 1615029267701 RemoteAgent TRACE (connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f})-> {"id":4,"method":"DOM.describeNode","params":{"objectId":"83605fce-a71b-49e4-8183-fd1f9816ee92"}}
[task 2021-03-06T11:14:27.707Z] 11:14:27 INFO - GECKO(1841) | 1615029267703 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"id":4,"error":{"message":"Object id doesn't reference a Node","data":"describeNode@chrome://remote/content/cdp/domains/cont ... /cdp/domains/DomainCache.jsm:101:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.jsm:84:45\n"}}
[task 2021-03-06T11:14:27.707Z] 11:14:27 INFO - TEST-PASS | remote/cdp/test/browser/dom/browser_describeNode.js | Fails if objectId doesn't reference a DOM node -
[task 2021-03-06T11:14:27.721Z] 11:14:27 INFO - GECKO(1841) | 1615029267710 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetDestroyed","params":{"targetId":"a03a71df-84ca-48cc-952a-e8b2339c384b"}}
[task 2021-03-06T11:14:27.725Z] 11:14:27 INFO - CDP client closed
[task 2021-03-06T11:14:27.729Z] 11:14:27 INFO - GECKO(1841) | 1615029267719 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetDestroyed","params":{"targetId":"9fa4b6a1-4519-4e65-83e3-a983c3f55004"}}
[task 2021-03-06T11:14:27.732Z] 11:14:27 INFO - GECKO(1841) | 1615029267719 RemoteAgent TRACE <-(connection {b8b3e0ed-aac0-43f5-8f69-7f59b807203f}) {"method":"Target.targetDestroyed","params":{"targetId":"2ebc1982-ad9f-4e04-9dc4-268836827408"}}
[task 2021-03-06T11:14:27.736Z] 11:14:27 INFO - CDP server stopped
[task 2021-03-06T11:14:27.736Z] 11:14:27 INFO - Leaving test bound objectIdIsNotANode

Henrik are you working on this?

Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork:owner]

(In reply to Andreea Pavel [:apavel] from comment #56)

Henrik are you working on this?

Not at this point but it looks like we have to take care about it soon. Something caused the number of failures to spike up.

Blocks: 1690252
Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork:owner] → [bidi-m1-mvp][stockwell needswork:owner]
Points: --- → 8

Before bug 1693288 (using clang 12) landed this was mostly a perma failure for ccov builds on Linux. Maybe it helps to reproduce the problem, which now mostly sounds like a race happening especially with slower builds.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED

The underlying problem here seems to be all around the socket as created by the HTTP server (httpd.js). At some point a formerly running server instance seems to not correctly close the socket, and then for the next test a new instance cannot be launched because the port is still taken.

The error message that gets thrown by httpd.js isn't that clear and as such I would propose to actually make it better first. Then we should identify why the socket isn't closed. Given that this only happens for opt builds it might be equivalent to bug 1663533 which causes a crash for debug builds somewhere in the socket library.

To get further information about a possible issue within httpd.js I enabled its debug logging, and pushed another try build. Reproducing the failure was kind hard, bug finally I got it with a CCOV build:

https://treeherder.mozilla.org/logviewer?job_id=333059473&repo=try

Here it can be seen that we correctly close the port 9222, but why the next connection fails it's not clear:

[task 2021-03-12T21:10:25.902Z] 21:10:25     INFO - GECKO(1898) | 1615583425880	RemoteAgent	TRACE	<-(connection {4f134395-8d9d-40d1-8c2d-bf553e23fd82}) {"method":"Target.targetDestroyed","params":{"targetId":"726f3ce6-992f-43c8-8006-7780623391fa"}}
[task 2021-03-12T21:10:25.903Z] 21:10:25     INFO - GECKO(1898) | HTTPD-INFO | >>> stopping listening on port 9222
[task 2021-03-12T21:10:25.904Z] 21:10:25     INFO - GECKO(1898) | HTTPD-INFO | >>> shutting down server on port 9222
[task 2021-03-12T21:10:25.905Z] 21:10:25     INFO - GECKO(1898) | HTTPD-INFO | *** no open connections, notifying async from onStopListening
[task 2021-03-12T21:10:25.906Z] 21:10:25     INFO - GECKO(1898) | HTTPD-INFO | *** _notifyStopped async callback
[task 2021-03-12T21:10:25.906Z] 21:10:25     INFO - GECKO(1898) | 1615583425883	RemoteAgent	DEBUG	Setting recommended pref focusmanager.testmode to true
[task 2021-03-12T21:10:25.913Z] 21:10:25     INFO - GECKO(1898) | 1615583425884	RemoteAgent	DEBUG	Setting recommended pref toolkit.startup.max_resumed_crashes to -1
[task 2021-03-12T21:10:25.915Z] 21:10:25     INFO - GECKO(1898) | 1615583425885	RemoteAgent	DEBUG	Setting recommended pref browser.contentblocking.features.standard to -tp,tpPrivate,cookieBehavior0,-cm,-fp
[task 2021-03-12T21:10:25.917Z] 21:10:25     INFO - GECKO(1898) | 1615583425887	RemoteAgent	DEBUG	Setting recommended pref prompts.contentPromptSubDialog to false
[task 2021-03-12T21:10:25.917Z] 21:10:25     INFO - GECKO(1898) | !!! could not start server on port 9222: [Exception... "Component returned failure code: 0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE) [nsIServerSocket.init]"  nsresult: "0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE)"  location: "JS frame :: chrome://remote/content/server/HTTPD.jsm :: _start :: line 567"  data: no]

Maybe we have some kind of race condition here where the Remote Agent tries to create a new connection whereby the old one hasn't been closed yet.

So what's actually happening here... When the tries to enter the listening state and it cannot start the HTTP server, it currently only logs an entry, and then continues as everything is fine:

https://searchfox.org/mozilla-central/rev/aa9a7136835deb0eeba00c62bb50a4a0e2cdea2d/remote/components/RemoteAgent.jsm#121

Previously, which means before bug 1590828 landed, the code actually throws an error. That error was then picked-up by the Mochitest and following lines weren't executed anymore:

https://searchfox.org/mozilla-central/rev/aa9a7136835deb0eeba00c62bb50a4a0e2cdea2d/remote/cdp/test/browser/head.js#50-51

But now that is the case, and the very first call to any CDP.* command will fail with a XMLHttpRequest error that results in [object ProgressEvent].

As such we should really return an error when the HTTP server cannot be started and put into listening mode. I'm not sure why throwing the error has been removed.

Note that with such a change the underlying issue will not be changed but a proper error be handled / logged.

There have been 40 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • linux1804-64-shippable-qr, linux1804-64-shippable, linux1804-64-ccov
  • linux1804-64 opt, linux1804-64-qr opt

The problem here is that for each and every browser-chrome mochitest we stop and re-initialize the Remote Agent:
https://searchfox.org/mozilla-central/rev/cc4a17cea338fe236626d838ca96e9bf6a775675/remote/cdp/test/browser/head.js#50,95

Interestingly this means that we also start / stop the HTTP server, and drop all the registered websocket connections. Not sure if that is something we actually want to allow for consumers of the RemoteAgent module. Also this would mean that the HTTPd port can change. Here I thought that the port is actually fixed on the value as specified via --remote-debugging-port, and cannot be changed during the whole lifetime of the Firefox process. But locking the port would actually break some tests that check that the Remote Agent can also listen on pre-defined ports. But nevertheless the type of test is wrong here and we would need a harness like Marionette to check that.

I think a discussion is needed how the lifetime of the connection should look like, and if the current behavior is acceptable - especially for BiDi. I'm actually a bit worried here.

As discussed on Elements with :whimboo will take this.
We will try to use a single RemoteAgent instance for a given suite. And we will isolate remote/cdp/test/browser/browser_agent.js which needs to start/stop the RemoteAgent in a separate ini file.

Assignee: hskupin → jdescottes
Pushed by jdescottes@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a3bc2d23debb
[remote] Start remote agent only once in remote mochitests r=remote-protocol-reviewers,whimboo
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 89 Branch

Do you have any objections to uplift this to beta?

Flags: needinfo?(jdescottes)

Uplift to beta should be fine, let me know if there are any merge conflicts.

Flags: needinfo?(jdescottes)
Priority: P5 → P2
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: