Closed Bug 1572142 Opened 3 years ago Closed 3 years ago

Intermittent Exception: nss cert db creation command failed to complete

Categories

(Testing :: Raptor, defect, P5)

Version 3
defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 unaffected, firefox69 unaffected, firefox70 wontfix, firefox71 fixed)

RESOLVED FIXED
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox69 --- unaffected
firefox70 --- wontfix
firefox71 --- fixed

People

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

Details

(Keywords: intermittent-failure, regression, Whiteboard: [Comment 37][stockwell disable-recommended][chase-intermittents])

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=260365813&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/WrTQAvR8QcG6jVRXavFklw/runs/0/artifacts/public/logs/live_backing.log


task 2019-08-07T14:29:09.570Z] 14:29:09 INFO - raptor-main Info: removing test folder for raptor: /sdcard/raptor
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - adb shell_output: adb -s HT86B1A00982 wait-for-device shell rm -r /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - adb shell_bool: adb -s HT86B1A00982 wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - raptor-control-server Info: shutting down control server
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - raptor-main Info: finished
[task 2019-08-07T14:29:13.937Z] 14:29:09 ERROR - Traceback (most recent call last):
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 1261, in <module>
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - main()
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 1229, in main
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 961, in run_tests
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - return super(RaptorAndroid, self).run_tests(tests, test_names)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 185, in run_tests
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.run_test(test, timeout=int(test.get('page_timeout')))
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 991, in run_test
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.__run_test_cold(test, timeout)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 1041, in __run_test_cold
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.start_playback(test)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/tests/raptor/raptor/raptor.py", line 454, in start_playback
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.playback.start()
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm.py", line 124, in start
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.setup()
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm.py", line 381, in setup
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.install_mitmproxy_cert(self.browser_path)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm.py", line 465, in install_mitmproxy_cert
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - self.create_cert_db(cert_db_location)
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - File "/builds/task_1565188028/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm.py", line 516, in create_cert_db
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - raise Exception("nss cert db creation command failed to complete")
[task 2019-08-07T14:29:13.937Z] 14:29:09 INFO - Exception: nss cert db creation command failed to complete
[task 2019-08-07T14:29:13.937Z] 14:29:11 ERROR - Return code: 1
[task 2019-08-07T14:29:13.937Z] 14:29:11 WARNING - setting return code to 1
[task 2019-08-07T14:29:13.937Z] 14:29:11 INFO - Killing logcat pid 527.
[task 2019-08-07T14:29:13.937Z] 14:29:11 INFO - copying raptor results to upload dir:
[task 2019-08-07T14:29:13.937Z] 14:29:11 INFO - /builds/task_1565188028/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-07T14:29:13.937Z] 14:29:11 INFO - copying raptor results from /builds/task_1565188028/workspace/build/raptor.json to /builds/task_1565188028/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-07T14:29:13.937Z] 14:29:11 CRITICAL - Error copying results /builds/task_1565188028/workspace/build/raptor.json to upload dir /builds/task_1565188028/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-07T14:29:13.937Z] 14:29:11 INFO - [Errno 2] No such file or directory: u'/builds/task_1565188028/workspace/build/raptor.json'

Robert, Bob could you please take a look over what's going on here? It fails only on raptor-tp6m-geckoview-cold pgo builds and all on android-hw.
I'm doing some retriggers and backfills to see if smthg in tree related but so far no success.
In two days it has 82 fails already. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-02&endday=2019-08-09&tree=trunk&bug=1572142

Flags: needinfo?(rwood)
Flags: needinfo?(bob)

Moritz, could you please take a look over this bug? Could your changes here https://hg.mozilla.org/integration/autoland/rev/6fd90712ba26011a010a0fa8f882b62c08a939f4#l6.1 have triggered this?

Flags: needinfo?(mbirghan)

Will do. I'm looking into the retries issue at the moment. I'll look into this one as well.

This appears to have improved recently but it's not clear that the situation has been completely resolved. This error is thrown when the certutil command does not return with the certutil_sleep_seconds which is 10 if not local. We don't get any other indication of what is going wrong and don't appear to terminate the running certutil process.

bebe: You were recently in this code. Do you have any insights? What would you say to getting some stdout/stderr from the certutil process and making sure it is terminated if we raise an error?

Flags: needinfo?(bob) → needinfo?(fstrugariu)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Flags: needinfo?(rwood)

This occurred 138 times in the last 7 days. All occurrences were on Android, build types pgo and opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263150627&repo=autoland&lineNumber=1390

[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - adb shell_output: adb -s HT7BH1A05438 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - adb shell_bool: adb -s HT7BH1A05438 wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - raptor-control-server Info: shutting down control server
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - raptor-main Info: finished
[task 2019-08-23T13:14:13.255Z] 13:14:10 ERROR - Traceback (most recent call last):
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 1223, in <module>
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - main()
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 1191, in main
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 919, in run_tests
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - return super(RaptorAndroid, self).run_tests(tests, test_names)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 185, in run_tests
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.run_test(test, timeout=int(test.get('page_timeout')))
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 949, in run_test
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.__run_test_cold(test, timeout)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 999, in __run_test_cold
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.start_playback(test)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/tests/raptor/raptor/raptor.py", line 413, in start_playback
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.playback.start()
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 124, in start
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.setup()
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 425, in setup
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.install_mitmproxy_cert(self.browser_path)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 509, in install_mitmproxy_cert
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - self.create_cert_db(cert_db_location)
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - File "/builds/task_1566565927/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 560, in create_cert_db
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - raise Exception("nss cert db creation command failed to complete")
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - Exception: nss cert db creation command failed to complete
[task 2019-08-23T13:14:13.255Z] 13:14:10 ERROR - Return code: 1
[task 2019-08-23T13:14:13.255Z] 13:14:10 WARNING - setting return code to 1
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - Killing logcat pid 551.
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - copying raptor results to upload dir:
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - /builds/task_1566565927/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-23T13:14:13.255Z] 13:14:10 INFO - copying raptor results from /builds/task_1566565927/workspace/build/raptor.json to /builds/task_1566565927/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-23T13:14:13.255Z] 13:14:10 CRITICAL - Error copying results /builds/task_1566565927/workspace/build/raptor.json to upload dir /builds/task_1566565927/workspace/build/blobber_upload_dir/perfherder-data.json

There are 101 total failures in the last 7 days on android-hw-g5-7-0-arm7-api-16 pgo and opt, android-hw-p2-8-0-android-aarch64 pgo and opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263997729&repo=mozilla-inbound&lineNumber=1390

[task 2019-08-29T05:54:39.909Z] 05:54:39 INFO - raptor-main Info: starting test: raptor-tp6m-wikipedia-geckoview-cold
[task 2019-08-29T05:54:39.909Z] 05:54:39 INFO - raptor-main Info: starting raptor test: raptor-tp6m-wikipedia-geckoview-cold
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-main Info: test settings: {'expected_browser_cycles': 15, 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitm4-pixel2-fennec-wikipedia.manifest', 'browser_cycles': '15', 'alert_on': ['fcp', 'loadtime'], 'here': '/builds/task_1567057990/workspace/build/tests/raptor/raptor/tests/tp6/mobile', 'expected': 'pass', 'measure': ['fnbpaint', 'fcp', 'dcf', 'loadtime'], 'path': '/builds/task_1567057990/workspace/build/tests/raptor/raptor/tests/tp6/mobile/raptor-tp6m-wikipedia-geckoview-cold', 'cold': True, 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'unit': 'ms', 'ancestor-manifest': '/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.ini', 'name': 'raptor-tp6m-wikipedia-geckoview-cold', 'playback_upstream_cert': 'false', 'playback_recordings': 'mitm4-pixel2-fennec-wikipedia.mp', 'page_cycles': 1, 'apps': 'geckoview', 'test_url': 'https://en.m.wikipedia.org/wiki/Main_Page', 'manifest': '/builds/task_1567057990/workspace/build/tests/raptor/raptor/tests/tp6/mobile/raptor-tp6m-cold-7.ini', 'page_timeout': '60000', 'playback_version': '4.0.4', 'playback': 'mitmproxy-android', 'browser_cycle': 1, 'lower_is_better': 'true', 'type': 'pageload', 'relpath': 'tests/tp6/mobile/raptor-tp6m-wikipedia-geckoview-cold'}
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-main Info: raptor config: {'binary': 'org.mozilla.geckoview_example', 'local_profile_dir': '/tmp/tmpfwrPB3.mozrunner', 'symbols_path': 'https://queue.taskcluster.net/v1/task/CHnmQLmvSkuN12VJTtTdAw/artifacts/public/build/target.crashreporter-symbols.zip', 'memory_test': False, 'cpu_test': False, 'enable_control_server_wait': False, 'e10s': True, 'app': 'geckoview', 'gecko_profile_entries': None, 'power_test': False, 'run_local': False, 'platform': 'linux', 'host': '127.0.0.1', 'is_release_build': False, 'intent': 'android.intent.action.MAIN', 'enable_webrender': False, 'activity': 'org.mozilla.geckoview_example.GeckoViewActivity', 'gecko_profile_interval': None, 'processor': 'x86_64', 'gecko_profile': False, 'obj_path': None}
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-gen-test-config Info: finished writing test config to /builds/task_1567057990/workspace/build/tests/raptor/webext/raptor/auto_gen_test_config.js
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-main Info: installing webext /builds/task_1567057990/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-08-29T05:54:41.659Z] 05:54:39 INFO - raptor-main Info: making the raptor control server port available to device
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - adb command_output: adb -s FA79D1A07331 wait-for-device reverse tcp:45725 tcp:45725, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - raptor-main Info: making the raptor playback server port available to device
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - adb command_output: adb -s FA79D1A07331 wait-for-device reverse tcp:8080 tcp:8080, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - raptor-main Info: clearing org.mozilla.geckoview_example app data
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - raptor-main Info: setting debug-app flag for org.mozilla.geckoview_example
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - raptor-main Info: test uses playback tool: mitmproxy-android
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - mozproxy mozproxy_dir used for mitmproxy downloads and exe files: /builds/task_1567057990/workspace/testing/mozproxy
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - mozproxy create mitmproxy 4.0.4 dir
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - mozproxy downloading mitmproxy binary
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - mozproxy INFO - File mitmproxy-4.0.4-linux.tar.gz not present in local cache folder /builds/tooltool_cache
[task 2019-08-29T05:54:41.659Z] 05:54:40 INFO - mozproxy INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - File mitmproxy-4.0.4-linux.tar.gz fetched from https://tooltool.mozilla-releng.net/ as /builds/task_1567057990/workspace/testing/mozproxy/mitmdump-4.0.4/tmpugcZSI
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - File integrity verified, renaming tmpugcZSI to mitmproxy-4.0.4-linux.tar.gz
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - Updating local cache /builds/tooltool_cache...
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - Local cache /builds/tooltool_cache updated with mitmproxy-4.0.4-linux.tar.gz
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - untarring "mitmproxy-4.0.4-linux.tar.gz"
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy downloading mitmproxy pageset
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - File mitm4-pixel2-fennec-wikipedia.zip not present in local cache folder /builds/tooltool_cache
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - File mitm4-pixel2-fennec-wikipedia.zip fetched from https://tooltool.mozilla-releng.net/ as /builds/task_1567057990/workspace/testing/mozproxy/tmpMTtaPM
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - File integrity verified, renaming tmpMTtaPM to mitm4-pixel2-fennec-wikipedia.zip
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - Updating local cache /builds/tooltool_cache...
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - Local cache /builds/tooltool_cache updated with mitm4-pixel2-fennec-wikipedia.zip
[task 2019-08-29T05:54:41.659Z] 05:54:41 INFO - mozproxy INFO - unzipping "mitm4-pixel2-fennec-wikipedia.zip"
[task 2019-08-29T05:55:10.569Z] 05:54:41 INFO - mozproxy mitmdump path: /builds/task_1567057990/workspace/testing/mozproxy/mitmdump-4.0.4/mitmdump
[task 2019-08-29T05:55:10.569Z] 05:54:41 INFO - mozproxy browser path: org.mozilla.geckoview_example
[task 2019-08-29T05:55:10.569Z] 05:54:41 INFO - mozproxy No upstream certificate sniffing
[task 2019-08-29T05:55:10.569Z] 05:54:41 INFO - mozproxy Starting mitmproxy playback using env path: :/builds/task_1567057990/workspace/build/venv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/builds/worker/bin:/usr/local/bin:/builds/worker/android-sdk-linux/platform-tools:/builds/worker/android-sdk-linux/platform-tools/bin:/builds/worker/android-sdk-linux/tools:/builds/worker/android-sdk-linux/tools/bin:/builds/worker/android-sdk-linux/build-tools/27.0.3:/builds/worker/android-sdk-linux/tools/bin:/builds/worker/android-sdk-linux/platform-tools
[task 2019-08-29T05:55:10.569Z] 05:54:41 INFO - mozproxy Starting mitmproxy playback using command: /builds/task_1567057990/workspace/testing/mozproxy/mitmdump-4.0.4/mitmdump --set upstream_cert=false -v --set websocket=false --set server_replay_files=/builds/task_1567057990/workspace/testing/mozproxy/mitm4-pixel2-fennec-wikipedia.mp --scripts /builds/task_1567057990/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/scripts/alternate-server-replay-4.0.4.py
[task 2019-08-29T05:55:10.569Z] 05:54:42 INFO - mozproxy Mitmproxy playback successfully started as pid 754
[task 2019-08-29T05:55:10.569Z] 05:54:42 INFO - mozproxy downloading certutil binary (hostutils)
[task 2019-08-29T05:55:10.570Z] 05:54:42 INFO - mozproxy downloading: https://hg.mozilla.org/integration/mozilla-inbound/raw-file/d08cf6ecb122743ab3eb567c52f37df956721f92/testing/config/tooltool-manifests/linux64/hostutils.manifest to /builds/task_1567057990/workspace/testing/mozproxy/hostutils.manifest
[task 2019-08-29T05:55:10.570Z] 05:54:43 INFO - mozproxy INFO - File host-utils-68.0a1.en-US.linux-x86_64.tar.gz not present in local cache folder /builds/tooltool_cache
[task 2019-08-29T05:55:10.570Z] 05:54:43 INFO - mozproxy INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
[task 2019-08-29T05:55:10.570Z] 05:54:46 INFO - mozproxy INFO - File host-utils-68.0a1.en-US.linux-x86_64.tar.gz fetched from https://tooltool.mozilla-releng.net/ as /builds/task_1567057990/workspace/testing/mozproxy/tmp3PNLxn
[task 2019-08-29T05:55:10.570Z] 05:54:48 INFO - mozproxy INFO - File integrity verified, renaming tmp3PNLxn to host-utils-68.0a1.en-US.linux-x86_64.tar.gz
[task 2019-08-29T05:55:10.570Z] 05:54:48 INFO - mozproxy INFO - Updating local cache /builds/tooltool_cache...
[task 2019-08-29T05:55:10.570Z] 05:54:48 INFO - mozproxy INFO - Local cache /builds/tooltool_cache updated with host-utils-68.0a1.en-US.linux-x86_64.tar.gz
[task 2019-08-29T05:55:10.570Z] 05:54:48 INFO - mozproxy INFO - untarring "host-utils-68.0a1.en-US.linux-x86_64.tar.gz"
[task 2019-08-29T05:55:10.570Z] 05:54:50 INFO - mozproxy certutil is found at: /builds/task_1567057990/workspace/testing/mozproxy/host-utils-68.0a1.en-US.linux-x86_64/certutil
[task 2019-08-29T05:55:10.570Z] 05:54:50 INFO - mozproxy checking if the nss cert db already exists in the android browser profile
[task 2019-08-29T05:55:10.570Z] 05:54:50 INFO - certutil: function failed: SEC_ERROR_BAD_DATABASE: security library: bad database.
[task 2019-08-29T05:55:10.570Z] 05:54:50 INFO - mozproxy nss cert db doesn't exist yet. Note: certutil error is expected!!!
[task 2019-08-29T05:55:10.570Z] 05:55:00 INFO - mozproxy creating nss cert database using command: /builds/task_1567057990/workspace/testing/mozproxy/host-utils-68.0a1.en-US.linux-x86_64/certutil -d sql:/tmp/tmpfwrPB3.mozrunner/ -N --empty-password
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - mozproxy Stopping mitmproxy playback, killing process 754
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - mozproxy Successfully killed the mitmproxy playback process
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - raptor-main Info: removing reverse socket connections
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - adb command_output: adb -s FA79D1A07331 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - raptor-main Info: skipping check_for_crashes: application has not been launched
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - raptor-main Info: removing webext /builds/task_1567057990/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - raptor-main Info: removing test folder for raptor: /sdcard/raptor
[task 2019-08-29T05:55:10.570Z] 05:55:10 INFO - adb shell_output: adb -s FA79D1A07331 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - adb shell_output: adb -s FA79D1A07331 wait-for-device shell rm -r /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - adb shell_output: adb -s FA79D1A07331 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - adb shell_bool: adb -s FA79D1A07331 wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - raptor-control-server Info: shutting down control server
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - raptor-main Info: finished
[task 2019-08-29T05:55:13.867Z] 05:55:10 ERROR - Traceback (most recent call last):
[task 2019-08-29T05:55:13.867Z] 05:55:10 ERROR - Traceback (most recent call last):
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 1384, in <module>
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - main()
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 1352, in main
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 1073, in run_tests
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - return super(RaptorAndroid, self).run_tests(tests, test_names)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 200, in run_tests
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.run_test(test, timeout=int(test.get('page_timeout')))
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 1103, in run_test
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.__run_test_cold(test, timeout)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 1153, in __run_test_cold
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.start_playback(test)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/tests/raptor/raptor/raptor.py", line 529, in start_playback
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.playback.start()
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 124, in start
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.setup()
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 425, in setup
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.install_mitmproxy_cert(self.browser_path)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 509, in install_mitmproxy_cert
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - self.create_cert_db(cert_db_location)
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - File "/builds/task_1567057990/workspace/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/mitm.py", line 560, in create_cert_db
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - raise Exception("nss cert db creation command failed to complete")
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - Exception: nss cert db creation command failed to complete
[task 2019-08-29T05:55:13.867Z] 05:55:10 ERROR - Return code: 1
[task 2019-08-29T05:55:13.867Z] 05:55:10 WARNING - setting return code to 1
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - Killing logcat pid 553.
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - copying raptor results to upload dir:
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - /builds/task_1567057990/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - copying raptor results from /builds/task_1567057990/workspace/build/raptor.json to /builds/task_1567057990/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-29T05:55:13.867Z] 05:55:10 CRITICAL - Error copying results /builds/task_1567057990/workspace/build/raptor.json to upload dir /builds/task_1567057990/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-29T05:55:13.867Z] 05:55:10 INFO - [Errno 2] No such file or directory: u'/builds/task_1567057990/workspace/build/raptor.json'

Florin can you please take a look at this and possibly work on a fix? Also, please check Bob's comment (comment 9)

Also, Moritz can you check Cosmin's comment above? (comment 4) https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-30&endday=2019-08-29&tree=trunk&bug=1572142

Flags: needinfo?(mbirghan)
Flags: needinfo?(fstrugariu)
Flags: needinfo?(mbirghan)
Flags: needinfo?(fstrugariu)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

the only way I can make the certutil db creation hang is when running the command when we have a existing db which will trigger a "Enter a password which will be used to encrypt your keys."

but we check if the db exists before we generate the new db so this should not be a issue.

I will test this some more and try to figure out a way so we can make this more stable

Flags: needinfo?(fstrugariu)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner][Comment 20]
Whiteboard: [Comment 20][stockwell disable-recommended] → [stockwell needswork:owner][Comment 20]

This has failed 91 times in the last 7 days only on android opt and pgo build types.

Florin,do you have any updates?

Flags: needinfo?(fstrugariu)

My patch improves a function that is used to for a certificate viewer.
As far as I can tell this does not interfere with the nss cert db creation.

Flags: needinfo?(mbirghan)

I added a patch that cleans up the way we are using certutil hopefully this will make things more clear

Flags: needinfo?(fstrugariu)

The proposed patch seems better, but we are still not capturing the certutil call outputs (stderr, stdout)

If we use Popen.communicate(), this will ensure that we wait for the termination of the process and provide the full output,
and if the exit code is not zero, we might have more insight if we add in the logs the command output. (also, we can add -v)

see https://docs.python.org/3/library/subprocess.html#subprocess.Popen.communicate

Whiteboard: [Comment 20][stockwell disable-recommended] → [Comment 20][stockwell disable-recommended][chase-intermittents]

Hi Florin, this is making a lot of noise on the trees, there are 476 total failures in the last 30 days. Did you get a chance to take a look at Tarek's comment above? Are there any updates here that might decrease the failure rate?
Thank you.

Flags: needinfo?(fstrugariu)
Assignee: nobody → fstrugariu
Flags: needinfo?(fstrugariu)

@apavel me and Tarek are working on a patch in: https://phabricator.services.mozilla.com/D45163
Hopefully it will fix the issue

(In reply to Florin Strugariu [:Bebe] (needinfo me) from comment #37)

@apavel me and Tarek are working on a patch in: https://phabricator.services.mozilla.com/D45163
Hopefully it will fix the issue

Thank you!

Whiteboard: [Comment 20][stockwell disable-recommended][chase-intermittents] → [Comment 37][stockwell disable-recommended][chase-intermittents]
Pushed by fstrugariu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/01323c607091
Intermittent Exception: nss cert db creation command failed to complete r=tarek
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71

(In reply to Florin Strugariu [:Bebe] (needinfo me) from comment #43)

Looking at intermittent view and it seems this is fixed
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-21&endday=2019-09-20&tree=all&bug=1572142

No failures since the patch reached central.

Yes to fix the issues there it should.
Thanks

Flags: needinfo?(fstrugariu) → needinfo?(apavel)

Ryan can this land with test-only or is an uplift request necessary?

Flags: needinfo?(apavel) → needinfo?(ryanvm)

Sure

Flags: needinfo?(ryanvm)

Oh, I'd marked this wontfix because it didn't graft cleanly and didn't seem worth rebasing. If someone wants to uplift this to Beta, it'll need a revised patch.

You need to log in before you can comment on or make changes to this bug.