Closed Bug 1527806 Opened 6 years ago Closed 6 years ago

Intermittent testing/firefox-ui/tests/functional/security/test_security_notification.py TestSecurityNotification.test_secure_website | UnknownException: Reached error page: about:neterror?e=nssFailure2&u=https%3A//extended-validation.badssl.com/&c=UTF-8&f

Categories

(Testing :: Firefox UI Tests, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

#[markdown(off)]
Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=228296129&repo=mozilla-beta

https://queue.taskcluster.net/v1/task/W2ZK2bIlRgeUpxQ4IDrRlg/runs/0/artifacts/public/logs/live_backing.log

[task 2019-02-14T01:30:27.951Z] 01:30:27 INFO - JavaScript error: resource:///actors/NetErrorChild.jsm, line 692: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIStringBundle.GetStringFromName]
[task 2019-02-14T01:30:27.991Z] 01:30:27 INFO - 1550107827989 Marionette TRACE [27917287425] Received DOM event DOMContentLoaded for about:neterror?e=nssFailure2&u=https%3A//extended-validation.badssl.com/&c=UTF-8&f=regular&d=The%20connection%20to%20extended-validation.badssl.com%20was%20interrupted%20while%20the%20page%20was%20loading.
[task 2019-02-14T01:30:28.032Z] 01:30:28 INFO - 1550107828026 Marionette DEBUG 15 <- [1,77,{"error":"unknown error","message":"Reached error page: about:neterror?e=nssFailure2&u=https%3A//extended-validation.ba ... eadyState@chrome://marionette/content/listener.js:276:21\nhandleEvent@chrome://marionette/content/listener.js:244:9\n"},null]
[task 2019-02-14T01:30:28.048Z] 01:30:28 INFO - 1550107828041 Marionette DEBUG 15 -> [0,78,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-02-14T01:30:28.048Z] 01:30:28 INFO - 1550107828044 Marionette DEBUG 15 <- [1,78,null,{"value":null}]
[task 2019-02-14T01:30:28.056Z] 01:30:28 INFO - 1550107828052 Marionette DEBUG 15 -> [0,79,"Marionette:GetContext",{}]
[task 2019-02-14T01:30:28.060Z] 01:30:28 INFO - 1550107828055 Marionette DEBUG 15 <- [1,79,null,{"value":"chrome"}]
[task 2019-02-14T01:30:28.068Z] 01:30:28 INFO - 1550107828062 Marionette DEBUG 15 -> [0,80,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-02-14T01:30:28.069Z] 01:30:28 INFO - 1550107828064 Marionette DEBUG 15 <- [1,80,null,{"value":null}]
[task 2019-02-14T01:30:28.070Z] 01:30:28 INFO - 1550107828067 Marionette DEBUG 15 -> [0,81,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2019-02-14T01:30:28.086Z] 01:30:28 INFO - [Parent 856, Main Thread] WARNING: Remote iframe not rendered: file /builds/worker/workspace/build/src/layout/ipc/RenderFrame.cpp, line 271
[task 2019-02-14T01:30:28.135Z] 01:30:28 INFO - 1550107828129 Marionette DEBUG 15 <- [1,81,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd348V933wcS4r9f+IRNVIiVL5ieRIaVWpFxZSG1+EKEos ... AAAAAAMCYAAQAAAGBMAAIAAADAmAAEAAAAgDEBCAAAAABjAhAAAAAAxgQgAAAAAIwJQAAAAAAYE4AAAAAAMCYAAQAAAGAsxjMr2OGy5g4AAAAASUVORK5CYII="}]
[task 2019-02-14T01:30:28.144Z] 01:30:28 INFO - 1550107828138 Marionette DEBUG 15 -> [0,82,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-02-14T01:30:28.145Z] 01:30:28 INFO - 1550107828142 Marionette DEBUG 15 <- [1,82,null,{"value":null}]
[task 2019-02-14T01:30:28.155Z] 01:30:28 INFO - 1550107828150 Marionette DEBUG 15 -> [0,83,"Marionette:GetContext",{}]
[task 2019-02-14T01:30:28.157Z] 01:30:28 INFO - 1550107828152 Marionette DEBUG 15 <- [1,83,null,{"value":"chrome"}]
[task 2019-02-14T01:30:28.158Z] 01:30:28 INFO - 1550107828154 Marionette DEBUG 15 -> [0,84,"Marionette:SetContext",{"value":"content"}]
[task 2019-02-14T01:30:28.159Z] 01:30:28 INFO - 1550107828157 Marionette DEBUG 15 <- [1,84,null,{"value":null}]
[task 2019-02-14T01:30:28.168Z] 01:30:28 INFO - 1550107828161 Marionette DEBUG 15 -> [0,85,"WebDriver:GetPageSource",{}]
[task 2019-02-14T01:30:28.180Z] 01:30:28 INFO - 1550107828170 Marionette DEBUG 15 <- [1,85,null,{"value":"<html xmlns=\"http://www.w3.org/1999/xhtml\">\n <head>\n <meta http-equiv=\"Content-Security-Policy\ ... n </body>\n <script type=\"application/javascript\" src=\"chrome://browser/content/aboutNetError.js\"></script>\n</html>"}]
[task 2019-02-14T01:30:28.180Z] 01:30:28 INFO - 1550107828173 Marionette DEBUG 15 -> [0,86,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-02-14T01:30:28.180Z] 01:30:28 INFO - 1550107828175 Marionette DEBUG 15 <- [1,86,null,{"value":null}]
[task 2019-02-14T01:30:28.207Z] 01:30:28 INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/security/test_security_notification.py TestSecurityNotification.test_secure_website | UnknownException: Reached error page: about:neterror?e=nssFailure2&u=https%3A//extended-validation.badssl.com/&c=UTF-8&f=regular&d=The%20connection%20to%20extended-validation.badssl.com%20was%20interrupted%20while%20the%20page%20was%20loading.
[task 2019-02-14T01:30:28.207Z] 01:30:28 INFO - stacktrace:
[task 2019-02-14T01:30:28.208Z] 01:30:28 INFO - WebDriverError@chrome://marionette/content/error.js:179:5
[task 2019-02-14T01:30:28.209Z] 01:30:28 INFO - UnknownError@chrome://marionette/content/error.js:484:5
[task 2019-02-14T01:30:28.210Z] 01:30:28 INFO - handleReadyState@chrome://marionette/content/listener.js:276:21
[task 2019-02-14T01:30:28.211Z] 01:30:28 INFO - handleEvent@chrome://marionette/content/listener.js:244:9
[task 2019-02-14T01:30:28.212Z] 01:30:28 INFO - Traceback (most recent call last):
[task 2019-02-14T01:30:28.213Z] 01:30:28 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-02-14T01:30:28.214Z] 01:30:28 INFO - testMethod()
[task 2019-02-14T01:30:28.215Z] 01:30:28 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/security/test_security_notification.py", line 50, in test_secure_website
[task 2019-02-14T01:30:28.216Z] 01:30:28 INFO - self.marionette.navigate(self.urls[1])
[task 2019-02-14T01:30:28.217Z] 01:30:28 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1633, in navigate
[task 2019-02-14T01:30:28.217Z] 01:30:28 INFO - {"url": url})
[task 2019-02-14T01:30:28.218Z] 01:30:28 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-02-14T01:30:28.219Z] 01:30:28 INFO - return func(*args, **kwargs)
[task 2019-02-14T01:30:28.220Z] 01:30:28 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 764, in _send_message
[task 2019-02-14T01:30:28.222Z] 01:30:28 INFO - self._handle_error(err)
[task 2019-02-14T01:30:28.223Z] 01:30:28 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 784, in _handle_error
[task 2019-02-14T01:30:28.223Z] 01:30:28 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2019-02-14T01:30:28.224Z] 01:30:28 INFO - TEST-INFO took 16177ms

There was most likely a problem with badssl.com serving the data:

[task 2019-02-14T01:30:27.991Z] 01:30:27 INFO - 1550107827989 Marionette TRACE [27917287425] Received DOM event DOMContentLoaded for about:neterror?e=nssFailure2&u=https%3A//extended-validation.badssl.com/&c=UTF-8&f=regular&d=The%20connection%20to%20extended-validation.badssl.com%20was%20interrupted%20while%20the%20page%20was%20loading.

April, is there something you might be able to see in the logs for this specific request? The workers public IP address is 13.56.247.220.

Flags: needinfo?(april)

I am seeing a ton of errors from around that timeframe, and I'm investigating.

I was wrong, it appears the errors didn't happen until a bit later:

13.56.247.220 - - [14/Feb/2019:01:28:39 +0000] "GET / HTTP/1.1" 200 408 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:28:40 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://extended-validation.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:28:40 +0000] "GET /icons/icon-green.png HTTP/1.1" 200 3289 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:28:40 +0000] "GET /icons/favicon-green.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:28:42 +0000] "GET / HTTP/1.1" 200 408 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:28:43 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://extended-validation.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:45 +0000] "GET / HTTP/1.1" 200 440 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:45 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://mozilla-intermediate.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:46 +0000] "GET /icons/icon-yellow.png HTTP/1.1" 200 3994 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:46 +0000] "GET /icons/favicon-yellow.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:47 +0000] "GET /icons/favicon-yellow.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:50 +0000] "GET / HTTP/1.1" 200 408 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:51 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://extended-validation.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:52 +0000] "GET /icons/favicon-green.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:57 +0000] "GET / HTTP/1.1" 200 371 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:57 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://mixed.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:57 +0000] "GET /icons/icon-yellow.png HTTP/1.1" 200 3994 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:57 +0000] "GET /icons/favicon-yellow.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:59 +0000] "GET /image.jpg HTTP/1.1" 301 194 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:29:59 +0000] "GET /image.jpg HTTP/1.1" 200 20998 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:07 +0000] "GET / HTTP/1.1" 200 303 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:07 +0000] "GET /style.css HTTP/1.1" 200 1367 "http://http.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:07 +0000] "GET /icons/icon-red.png HTTP/1.1" 200 3858 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:07 +0000] "GET /icons/favicon-red.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:32 +0000] "GET / HTTP/1.1" 200 310 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:32 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://tls-v1-0.badssl.com:1010/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:32 +0000] "GET /icons/icon-red.png HTTP/1.1" 200 3858 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:32 +0000] "GET /icons/favicon-red.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:36 +0000] "GET / HTTP/1.1" 200 453 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:36 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://mixed-form.badssl.com/" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:36 +0000] "GET /icons/icon-yellow.png HTTP/1.1" 200 3994 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:36 +0000] "GET /icons/favicon-yellow.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:37 +0000] "POST /resources/form-submitted.html HTTP/1.1" 200 121 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:01:30:37 +0000] "GET /favicon.ico HTTP/1.1" 404 152 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:05 +0000] "GET / HTTP/1.1" 200 408 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:05 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://extended-validation.badssl.com/" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:05 +0000] "GET /icons/icon-green.png HTTP/1.1" 200 3289 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:05 +0000] "GET /icons/favicon-green.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:06 +0000] "GET / HTTP/1.1" 200 408 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:43:06 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://extended-validation.badssl.com/" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:44:46 +0000] "GET / HTTP/1.1" 200 440 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:44:46 +0000] "GET /style.css HTTP/1.1" 200 1367 "https://mozilla-intermediate.badssl.com/" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:44:46 +0000] "GET /icons/icon-yellow.png HTTP/1.1" 200 3994 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
13.56.247.220 - - [14/Feb/2019:02:44:46 +0000] "GET /icons/favicon-yellow.ico HTTP/1.1" 200 5430 "-" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"

It looks to me like all the requests returned 200 OK. Nothing in the error log from them.

Flags: needinfo?(april)

The first four log entries (/, style.css, icon-green.png, and favicon-green.ico) are the only resources for the page, so I'm not entirely sure why DOMContentLoaded didn't fire.

Strange. I wonder if there is something wrong with the datetime as set on one of those machines. Here another line:

[task 2019-02-14T01:30:09.293Z] 01:30:09 INFO - 1550107809288 Marionette DEBUG 14 -> [0,77,"WebDriver:Navigate",{"url":"https://expired.badssl.com"}]

This is not a request which I can see in your pasted log. So maybe the excerpt above is not the one for the referenced test job.

I'm pretty sure the log is right, as it otherwise matches up with what you've got.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.