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)
Tracking
(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
Comment hidden (Intermittent Failures Robot) |
Comment 2•4 years ago
|
||
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment 55•3 years ago
|
||
This is actually a Linux-only issue.
Comment 56•3 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 58•3 years ago
|
||
(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.
Updated•3 years ago
|
Comment 59•3 years ago
|
||
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.
Updated•3 years ago
|
Comment 61•3 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment 64•3 years ago
|
||
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.
Comment 65•3 years ago
|
||
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:
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:
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.
Comment hidden (Intermittent Failures Robot) |
Comment 67•3 years ago
|
||
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
Comment hidden (Intermittent Failures Robot) |
Comment 69•3 years ago
|
||
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.
Assignee | ||
Comment 70•3 years ago
|
||
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 | ||
Comment 71•3 years ago
|
||
Comment 72•3 years ago
|
||
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
Comment 73•3 years ago
|
||
bugherder |
Comment 74•3 years ago
|
||
Do you have any objections to uplift this to beta?
Assignee | ||
Comment 75•3 years ago
|
||
Uplift to beta should be fine, let me know if there are any merge conflicts.
Comment 76•3 years ago
|
||
bugherder uplift |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Description
•