Open Bug 1115253 Opened 6 years ago Updated 4 days ago

Intermittent gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 300|1200|1800 seconds

Categories

(Core :: Audio/Video: GMP, defect, P3)

x86
macOS
defect

Tracking

()

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled on android][stockwell unknown])

Attachments

(2 files)

No description provided.
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Most (all?) of these times out are in TestNamedPipeService:

 11:34:01     INFO -  TEST-START | TestNamedPipeService.Test
 11:39:01    ERROR -  gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200 seconds
 11:39:02    ERROR - Return code: 1
 11:39:02 ERROR - No tests run or test summary not found
This failure became much more frequent after the changes in bug 1313752. :bsmedberg - just letting you know!
Flags: needinfo?(benjamin)
Depends on: 1322377
gbrown, this bug appears to cover numerous issues that are all lumped together. Would it be possible for you to classify these gtest timeout by the last test that started before the timeout, or whether the timeout happens during shutdown? For instance:

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-esr45&job_id=131509#L29804
This should be TEST-UNEXPECTED-FAIL | gtest | test-shutdown | timed out after 1200 seconds because the timeout happens after we've finished running all the tests and printed the "TEST-PASS | GTest unit test: passed" line.

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=40225283#L7726
This should be TEST-UNEXPECTED-FAIL | gtest | TestNamedPipeService.Test | timed out...
Because the last test was TEST-START | TestNamedPipeService.Test

I filed bug 1322377 specifically for the TestNamedPipeService work.
Flags: needinfo?(benjamin)
Depends on: 1322616
Almost all recent failures are from mozilla-esr45, in GeckoMediaPlugins.GMPTestCodec.
Depends on: 1332352
(In reply to Benjamin Smedberg [:bsmedberg] from comment #128)
> gbrown, this bug appears to cover numerous issues that are all lumped
> together. Would it be possible for you to classify these gtest timeout by
> the last test that started before the timeout, or whether the timeout
> happens during shutdown? 

That's a good idea and I know we do that for most other test types. It looks a little tricky for gtest; it's not obvious to me how to implement for gtest, but I've filed bug 1332352.
Duplicate of this bug: 1367078
Summary: Intermittent gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200 seconds → Intermittent gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200|1800 seconds
This Bug occurred 32 times in the last 7 days on Windows 7 and Linux. It is failing only on debug build type.

Failing tests: debug-gtest

Link to a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=145900700&lineNumber=1504

Part of a log:

11:40:50     INFO -  TEST-START | Moz2D.JobScheduler_Shutdown
15861
11:45:50    ERROR -  gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200 seconds
15862
11:45:50    ERROR - Return code: 1
15863
11:45:50    ERROR - No tests run or test summary not found
15864
11:45:50     INFO - TinderboxPrint: gtest-gtest<br/><em class="testfail">T-FAIL</em>
15865
11:45:50    ERROR - # TBPL FAILURE #
15866
11:45:50  WARNING - setting return code to 2
15867
11:45:50    ERROR - The gtest suite: gtest ran with return status: FAILURE
15868
11:45:50     INFO - Running post-action listener: _package_coverage_data
15869
11:45:50     INFO - Running command: ['zip', '-r', 'Z:\\task_1511091199\\build\\blobber_upload_dir\\code-coverage-gcda.zip', '.'] in c:\users\genericworker\appdata\local\temp\tmpwxmpby
15870
11:45:50     INFO - Copy/paste: zip -r Z:\task_1511091199\build\blobber_upload_dir\code-coverage-gcda.zip .
15871
11:45:50     INFO -  zip error: Nothing to do! (try: zip -r Z:\task_1511091199\build\blobber_upload_dir\code-coverage-gcda.zip . -i .)
15872
11:45:50    ERROR - Return code: 12
15873
11:45:50     INFO - Running command: ['zip', '-r', 'Z:\\task_1511091199\\build\\blobber_upload_dir\\code-coverage-jsvm.zip', '.'] in c:\users\genericworker\appdata\local\temp\tmpjuwroc
15874
11:45:50     INFO - Copy/paste: zip -r Z:\task_1511091199\build\blobber_upload_dir\code-coverage-jsvm.zip .
15875
11:45:50     INFO -    adding: 1511091346-6904-0.info (152 bytes security) (stored 0%)
15876
11:45:50     INFO - Return code: 0
15877
11:45:50     INFO - proxxy config: {}
15878
11:45:50     INFO - trying https://queue.taskcluster.net/v1/task/bhAm7VGnRoqY4_R60i6DEQ/artifacts/public/build/target.code-coverage-gcno.zip
15879
11:45:50     INFO - Downloading https://queue.taskcluster.net/v1/task/bhAm7VGnRoqY4_R60i6DEQ/artifacts/public/build/target.code-coverage-gcno.zip to c:\users\genericworker\appdata\local\temp\tmp40ncpa\target.code-coverage-gcno.zip
15880
11:45:50     INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'https://queue.taskcluster.net/v1/task/bhAm7VGnRoqY4_R60i6DEQ/artifacts/public/build/target.code-coverage-gcno.zip', 'file_name': 'c:\\users\\genericworker\\appdata\\local\\temp\\tmp40ncpa\\target.code-coverage-gcno.zip'}, attempt #1
15881
11:45:52     INFO - Downloaded 116843543 bytes.
15882
11:45:52     INFO - Getting output from command: ['c:\\users\\genericworker\\appdata\\local\\temp\\tmp40ncpa\\grcov', '-t', 'lcov', '-p', 'z:/build/build/src/', '--ignore-dir', 'gcc', 'c:\\users\\genericworker\\appdata\\local\\temp\\tmp40ncpa\\target.code-coverage-gcno.zip', 'Z:\\task_1511091199\\build\\blobber_upload_dir\\code-coverage-gcda.zip', '--llvm']
15883
11:45:52     INFO - Copy/paste: c:\users\genericworker\appdata\local\temp\tmp40ncpa\grcov -t lcov -p z:/build/build/src/ --ignore-dir gcc c:\users\genericworker\appdata\local\temp\tmp40ncpa\target.code-coverage-gcno.zip Z:\task_1511091199\build\blobber_upload_dir\code-coverage-gcda.zip --llvm
15884
11:45:52    ERROR - Errors received:
15885
11:45:52     INFO - Reading from file tmpfile_stderr
15886
11:45:52    ERROR -  thread '<unnamed>' panicked at 'Failed to open ZIP file 'Z:\task_1511091199\build\blobber_upload_dir\code-coverage-gcda.zip'.: Error { repr: Os { code: 2, message: "The system cannot find the file specified." } }', src\libcore\result.rs:906:4
15887
11:45:52    ERROR -  note: Run with `RUST_BACKTRACE=1` for a backtrace.
15888
11:45:52    ERROR - Return code: 0
15889
11:45:52     INFO - Running command: ['zip', 'Z:\\task_1511091199\\build\\blobber_upload_dir\\code-coverage-grcov.zip', 'grcov_lcov_output.info'] in c:\users\genericworker\appdata\local\temp\tmp40ncpa
15890
11:45:52     INFO - Copy/paste: zip Z:\task_1511091199\build\blobber_upload_dir\code-coverage-grcov.zip grcov_lcov_output.info
15891
11:45:52     INFO -    adding: grcov_lcov_output.info (152 bytes security) (stored 0%)
15892
11:45:52     INFO - Return code: 0

Also this bug is blocked by these 2 Bugs: 
 - 1322616 "gtest timeout message does not differentiate between timeout and no-output timeout"
 - 1332352 "Last test seen not part of gtest timeout message"

: Selena Deckelmann could you please take a look?
Flags: needinfo?(sdeckelmann)
Whiteboard: [stockwell needswork]
Many recent failures are windows 10 ccov gtest, which was just enabled in bug 1417436. It looks like there are other complaints in that bug about failures and it may be hidden soon. ni :marco to make sure he is aware of this.
Blocks: 1417436
Flags: needinfo?(mcastelluccio)
The ccov GTest failures will be fixed by bug 1418255.

This bug contains issues that are unrelated to each other. We should probably make GTest fail more verbosely and file separate bugs for each problem.
Flags: needinfo?(mcastelluccio)
No longer blocks: 1417436
No longer depends on: 1322616
See Also: → 1322616
No longer depends on: 1332352
See Also: → 1332352
Depends on: 1419196
Component: General → Graphics
Flags: needinfo?(sdeckelmann)
With changes landing in bug 1322616 today, some (possibly most or even all) failures previously reported here will be reported as "gtest | timed out after 300 seconds without output".
Blocks: 1426037
See Also: → 1473531
Blocks: 1411358
Over the last 7 days there have been 36 failures on this bug, these happen on linux64, windows10-64-ccov.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=186736776&repo=mozilla-central&lineNumber=856

23:19:25    ERROR - shutil error: Destination path 'Z:\task_1530832153\build\application\firefox\gmp-clearkey' already exists
Flags: needinfo?(dbolter)
Maire is gmp-clearkey a media thing?
Flags: needinfo?(dbolter) → needinfo?(mreavy)
Note that most recent failures are on ccov - bug 1473531.
See Also: → 1474254
There are 32 failures in the last 7 days on windows10-64-ccov debug.
There have been 37 failures in the last 7 days:
All the failures occur on the debug build type.
Failures per platform:
-windows10-64-ccov: 35
-linux32: 1
-windows7-32: 1


Recent log file:
https://treeherder.mozilla.org/logviewer.html#?job_id=190059853&repo=mozilla-central&lineNumber=853
(In reply to Andrew Halberstadt [:ahal] from comment #214)
> This is perma-failing on windows10-64-ccov:

...bug 1474254.
Depends on: 1474254
See Also: 1474254
Component: Graphics → Audio/Video: GMP
Flags: needinfo?(mreavy)
No longer blocks: 1411358
Summary: Intermittent gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200|1800 seconds → Intermittent gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 300|1200|1800 seconds

This bug has failed 34 times in the last 7 days. Occurs on linux64-ccov on debug build type.

Recent log:
https://treeherder.mozilla.org/logviewer.html#?job_id=236418885&repo=mozilla-central

There are 43 total failures in the last 7 days on linux64-ccov debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=238572618&repo=mozilla-central&lineNumber=1250

[task 2019-04-06T12:33:52.031Z] 12:33:52 INFO - TEST-START | WebRtcIceConnectTest.TestConnectShutdownOneSide
[task 2019-04-06T12:33:52.034Z] 12:33:52 INFO - Candidate for stream P1:stream0 initialized: candidate:0 1 UDP 2122187007 172.17.0.5 56476 typ host
[task 2019-04-06T12:33:52.034Z] 12:33:52 INFO - Candidate for stream P1:stream0 initialized: candidate:2 1 UDP 2122252543 fd15:4ba5:5a2b:100a:0:242:ac11:5 32971 typ host
[task 2019-04-06T12:33:52.035Z] 12:33:52 INFO - P1 Gathering complete

[task 2019-04-06T12:33:52.057Z] 12:33:52 INFO - P2 ICE connected
[task 2019-04-06T12:33:53.707Z] 12:33:53 ERROR - gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200 seconds
[task 2019-04-06T12:33:59.186Z] 12:33:59 ERROR - Return code: 1
[task 2019-04-06T12:33:59.186Z] 12:33:59 ERROR - No tests run or test summary not found
[task 2019-04-06T12:33:59.187Z] 12:33:59 INFO - TinderboxPrint: gtest-gtest<br/><em class="testfail">T-FAIL</em>
[task 2019-04-06T12:33:59.187Z] 12:33:59 ERROR - # TBPL FAILURE #
[task 2019-04-06T12:33:59.187Z] 12:33:59 WARNING - setting return code to 2
[task 2019-04-06T12:33:59.187Z] 12:33:59 ERROR - The gtest suite: gtest ran with return status: FAILURE
[task 2019-04-06T12:33:59.188Z] 12:33:59 INFO - Running post-action listener: _package_coverage_data

Nils can you assign someone to take a look?

Flags: needinfo?(drno)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

Over the last 7 days there are 32 failure on this bug. These happen on android-em-7-0-x86_64, linux32, linux64-ccov, linux64-ccov

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=240257877&repo=autoland&lineNumber=3914

The android-em-7-0-x86_64 failures began when we started running gtest on that platform. Android test logs usually show ImageBitmapColorUtils as the last running test, but logcats show that MultiWriterQueue is the real culprit.

04-15 11:50:35.890 2402 2417 I gtest : TEST-START | ImageBitmapColorUtils.LabToBGRA32
04-15 11:50:35.890 2402 2417 I gtest : TEST-PASS | ImageBitmapColorUtils.LabToBGRA32 | test completed (time: 0ms)
04-15 11:50:35.890 2402 2417 I gtest : TEST-START | MultiWriterQueue.SingleThreaded
04-15 11:50:35.960 2402 2417 I gtest : TEST-PASS | MultiWriterQueue.SingleThreaded | test completed (time: 70ms)
04-15 11:50:35.960 2402 2417 I gtest : TEST-START | MultiWriterQueue.MultiWriterSingleReader
04-15 11:50:42.310 2402 2417 D Telemetry: MainThreadArmPersistenceTimer

Recent linux64-ccov logs look quite different from the Android case.

I missed this intermittent when enabling Android gtests in bug 1318091. Disable
the failing test on Android only, to green up Android gtest.

Keywords: leave-open
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner] [test disabled on android]
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7d37a22773a0
Disable gtest TestMultiWriterQueue on Android; r=jmaher

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=busted&selectedJob=240393974&revision=7d37a22773a008ecb76f1a01f09f915c2f18f613

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=240394002&repo=autoland&lineNumber=17780

Backout link: https://hg.mozilla.org/integration/autoland/rev/b02881ec59d7df457d97fac800244fe918017425

[task 2019-04-15T17:52:33.317Z] 17:52:33 INFO - make[4]: Entering directory '/builds/worker/workspace/build/src/obj-firefox/dom/media/doctor/gtest'
[task 2019-04-15T17:52:33.319Z] 17:52:33 INFO - /builds/worker/workspace/build/src/sccache2/sccache /builds/worker/workspace/build/src/clang/bin/clang++ --target=arm-linux-androideabi -o Unified_cpp_media_doctor_gtest0.o -c -flto=thin -I/builds/worker/workspace/build/src/obj-firefox/dist/stl_wrappers -I/builds/worker/workspace/build/src/obj-firefox/dist/system_wrappers -include /builds/worker/workspace/build/src/config/gcc_hidden.h -DNDEBUG=1 -DTRIMMED=1 -DOS_POSIX=1 -DOS_LINUX=1 -DSTATIC_EXPORTABLE_JS_API -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -I/builds/worker/workspace/build/src/dom/media/doctor/gtest -I/builds/worker/workspace/build/src/obj-firefox/dom/media/doctor/gtest -I/builds/worker/workspace/build/src/obj-firefox/ipc/ipdl/ipdlheaders -I/builds/worker/workspace/build/src/ipc/chromium/src -I/builds/worker/workspace/build/src/ipc/glue -I/builds/worker/workspace/build/src/dom/media/doctor -I/builds/worker/workspace/build/src/obj-firefox/dist/include -I/builds/worker/workspace/build/src/obj-firefox/dist/include/nspr -I/builds/worker/workspace/build/src/obj-firefox/dist/include/nss -fPIC -DMOZILLA_CLIENT -include /builds/worker/workspace/build/src/obj-firefox/mozilla-config.h -Qunused-arguments -isystem /builds/worker/workspace/build/src/android-ndk/sysroot/usr/include/arm-linux-androideabi -isystem /builds/worker/workspace/build/src/android-ndk/sysroot/usr/include -gcc-toolchain /builds/worker/workspace/build/src/android-ndk/toolchains/arm-linux-androideabi-4.9/prebuilt/linux-x86_64 -D__ANDROID_API_=16 -fstack-protector-strong -Qunused-arguments -Wall -Wbitfield-enum-conversion -Wempty-body -Wignored-qualifiers -Woverloaded-virtual -Wpointer-arith -Wshadow-field-in-constructor-modified -Wsign-compare -Wtype-limits -Wunreachable-code -Wunreachable-code-return -Wwrite-strings -Wno-invalid-offsetof -Wclass-varargs -Wfloat-overflow-conversion -Wfloat-zero-conversion -Wloop-analysis -Wc++1z-compat -Wc++2a-compat -Wcomma -Wimplicit-fallthrough -Werror=non-literal-null-conversion -Wstring-conversion -Wtautological-overlap-compare -Wtautological-unsigned-enum-zero-compare -Wtautological-unsigned-zero-compare -Wno-inline-new-delete -Wno-error=deprecated-declarations -Wno-error=array-bounds -Wno-error=backend-plugin -Wno-error=return-std-move -Wno-error=atomic-alignment -Wformat -Wformat-security -Wno-gnu-zero-variadic-macro-arguments -Wno-unknown-warning-option -Wno-return-type-c-linkage -mno-unaligned-access -fno-sized-deallocation -fno-short-enums -fno-exceptions -stdlib=libstdc++ -I/builds/worker/workspace/build/src/android-ndk/sources/cxx-stl/llvm-libc++/include -I/builds/worker/workspace/build/src/android-ndk/sources/android/support/include -I/builds/worker/workspace/build/src/android-ndk/sources/cxx-stl/llvm-libc++abi/include -march=armv7-a -mthumb -mfpu=neon -mfloat-abi=softfp -fstack-protector-strong -fno-exceptions -fno-strict-aliasing -fno-rtti -ffunction-sections -fdata-sections -fno-exceptions -fno-math-errno -pipe -g -Xclang -load -Xclang /builds/worker/workspace/build/src/obj-firefox/build/clang-plugin/libclang-plugin.so -Xclang -add-plugin -Xclang moz-check -Oz -fno-omit-frame-pointer -funwind-tables -Werror -Wno-error=shadow -MD -MP -MF .deps/Unified_cpp_media_doctor_gtest0.o.pp /builds/worker/workspace/build/src/obj-firefox/dom/media/doctor/gtest/Unified_cpp_media_doctor_gtest0.cpp
[task 2019-04-15T17:52:33.320Z] 17:52:33 INFO - In file included from /builds/worker/workspace/build/src/obj-firefox/dom/media/doctor/gtest/Unified_cpp_media_doctor_gtest0.cpp:2:
[task 2019-04-15T17:52:33.320Z] 17:52:33 INFO - In file included from /builds/worker/workspace/build/src/dom/media/doctor/gtest/TestRollingNumber.cpp:7:
[task 2019-04-15T17:52:33.320Z] 17:52:33 ERROR - /builds/worker/workspace/build/src/dom/media/doctor/RollingNumber.h:73:30: error: use of undeclared identifier 'MaxDiff'
[task 2019-04-15T17:52:33.320Z] 17:52:33 INFO - MOZ_ASSERT(aIncrement <= MaxDiff);
[task 2019-04-15T17:52:33.320Z] 17:52:33 INFO - ^
[task 2019-04-15T17:52:33.321Z] 17:52:33 ERROR - /builds/worker/workspace/build/src/dom/media/doctor/RollingNumber.h:84:30: error: use of undeclared identifier 'MaxDiff'
[task 2019-04-15T17:52:33.321Z] 17:52:33 INFO - MOZ_ASSERT(aDecrement <= MaxDiff);

Flags: needinfo?(gbrown)

I missed this intermittent when enabling Android gtests in bug 1318091. Disable the failing test on Android only, to green up Android gtest.

Attachment #9058353 - Attachment description: Bug 1115253 - Disable dom/media/docter gtests on Android; r=jmaher → Bug 1115253 - Disable dom/media/doctor gtests on Android; r=jmaher
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2d9779f97ccb
Disable dom/media/doctor gtests on Android; r=jmaher
Flags: needinfo?(gbrown)
Whiteboard: [test disabled on android][stockwell disable-recommended] → [stockwell needswork:owner] [test disabled on android]

This bug failed 32 times in the last 7 days. Occurs on linux64-ccov, windows7-32, windows10-64, windows10-aarch64 on debug build types.

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242744985&repo=mozilla-central&lineNumber=1251
,

There are 37 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-27&endday=2019-05-04&tree=trunk&bug=1115253

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244608102&repo=mozilla-central&lineNumber=41997

[task 2019-05-03T23:35:01.165Z] 23:35:01 ERROR - gtest TEST-UNEXPECTED-FAIL | gtest | timed out after 1200 seconds
[task 2019-05-03T23:35:04.986Z] 23:35:04 ERROR - Return code: 1
[task 2019-05-03T23:35:04.986Z] 23:35:04 ERROR - No tests run or test summary not found
[task 2019-05-03T23:35:04.987Z] 23:35:04 INFO - TinderboxPrint: gtest-gtest<br/><em class="testfail">T-FAIL</em>
[task 2019-05-03T23:35:04.987Z] 23:35:04 ERROR - # TBPL FAILURE #
[task 2019-05-03T23:35:04.987Z] 23:35:04 WARNING - setting return code to 2
[task 2019-05-03T23:35:04.987Z] 23:35:04 ERROR - The gtest suite: gtest ran with return status: FAILURE
[task 2019-05-03T23:35:04.988Z] 23:35:04 INFO - Running post-action listener: package_coverage_data
[task 2019-05-03T23:35:05.031Z] 23:35:05 INFO - Getting output from command: ['/builds/worker/fetches/grcov', '-t', 'lcov', '-p', '/builds/worker/workspace/build/src/', '--ignore-dir', 'gcc*', '--ignore-dir', 'vs2017
', '/builds/worker/fetches/target.code-coverage-gcno.zip', '/tmp/tmpJECiGb']
[task 2019-05-03T23:35:05.031Z] 23:35:05 INFO - Copy/paste: /builds/worker/fetches/grcov -t lcov -p /builds/worker/workspace/build/src/ --ignore-dir gcc
--ignore-dir vs2017_* /builds/worker/fetches/target.code-coverage-gcno.zip /tmp/tmpJECiGb
[task 2019-05-03T23:35:43.135Z] 23:35:43 INFO - Running post-action listener: _resource_record_post_action
[task 2019-05-03T23:35:43.135Z] 23:35:43 INFO - Running post-action listener: process_java_coverage_data
[task 2019-05-03T23:35:43.135Z] 23:35:43 INFO - [mozharness: 2019-05-03 23:35:43.135448Z] Finished run-tests step (success)
[task 2019-05-03T23:35:43.135Z] 23:35:43 INFO - Running post-run listener: _resource_record_post_run
[task 2019-05-03T23:35:43.250Z] 23:35:43 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2019-05-03T23:35:43.255Z] 23:35:43 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 22.330197063369415}, {"name": "io_write_bytes", "value": 10843070464}, {"name": "io.read_bytes", "value": 476684288}, {"name": "io_write_time", "value": 1875588}, {"name": "io_read_time", "value": 5984}], "extraOptions": ["taskcluster-m3.xlarge"], "name": "gtest.gtest.overall"}, {"subtests": [{"name": "time", "value": 52.412179946899414}, {"name": "cpu_percent", "value": 25.209134615384617}], "name": "gtest.gtest.install"}, {"subtests": [{"name": "time", "value": 1.6050779819488525}], "name": "gtest.gtest.stage-files"}, {"subtests": [{"name": "time", "value": 1243.031630039215}, {"name": "cpu_percent", "value": 22.204213709677433}], "name": "gtest.gtest.run-tests"}]}
[task 2019-05-03T23:35:43.255Z] 23:35:43 INFO - Total resource usage - Wall time: 1296s; CPU: 22.0%; Read bytes: 476684288; Write bytes: 10843070464; Read time: 5984; Write time: 1875588
[task 2019-05-03T23:35:43.255Z] 23:35:43 INFO - TinderboxPrint: CPU usage<br/>22.2%
[task 2019-05-03T23:35:43.255Z] 23:35:43 INFO - TinderboxPrint: I/O read bytes / time<br/>476,684,288 / 5,984
[task 2019-05-03T23:35:43.255Z] 23:35:43 INFO - TinderboxPrint: I/O write bytes / time<br/>10,843,070,464 / 1,875,588
[task 2019-05-03T23:35:43.256Z] 23:35:43 INFO - TinderboxPrint: CPU idle<br/>3,884.3 (77.2%)
[task 2019-05-03T23:35:43.256Z] 23:35:43 INFO - TinderboxPrint: CPU system<br/>367.0 (7.3%)
[task 2019-05-03T23:35:43.256Z] 23:35:43 INFO - TinderboxPrint: CPU user<br/>735.5 (14.6%)
[task 2019-05-03T23:35:43.256Z] 23:35:43 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2019-05-03T23:35:43.258Z] 23:35:43 INFO - install - Wall time: 52s; CPU: 25.0%; Read bytes: 8192; Write bytes: 2044661760; Read time: 28; Write time: 425576
[task 2019-05-03T23:35:43.259Z] 23:35:43 INFO - stage-files - Wall time: 2s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2019-05-03T23:35:43.273Z] 23:35:43 INFO - run-tests - Wall time: 1243s; CPU: 22.0%; Read bytes: 475602944; Write bytes: 8664330240; Read time: 5948; Write time: 1436824
[task 2019-05-03T23:35:43.695Z] 23:35:43 WARNING - returning nonzero exit status 2
[task 2019-05-03T23:35:43.695Z] WARNING: No valid records found in []
[task 2019-05-03T23:35:43.730Z] cleanup
[task 2019-05-03T23:35:43.731Z] + cleanup
[task 2019-05-03T23:35:43.731Z] + local rv=2
[task 2019-05-03T23:35:43.731Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2019-05-03T23:35:43.731Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2019-05-03T23:35:43.733Z] + true
[task 2019-05-03T23:35:43.733Z] + cleanup_xvfb
[task 2019-05-03T23:35:43.734Z] pidof Xvfb
[task 2019-05-03T23:35:43.734Z] ++ pidof Xvfb
[task 2019-05-03T23:35:43.751Z] + local xvfb_pid=28
[task 2019-05-03T23:35:43.751Z] + local vnc=false
[task 2019-05-03T23:35:43.751Z] + local interactive=false
[task 2019-05-03T23:35:43.753Z] + '[' -n 28 ']'
[task 2019-05-03T23:35:43.753Z] + [[ false == false ]]
[task 2019-05-03T23:35:43.753Z] + [[ false == false ]]
[task 2019-05-03T23:35:43.753Z] + kill 28
[task 2019-05-03T23:35:43.753Z] + screen -XS xvfb quit
[task 2019-05-03T23:35:43.753Z] XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
[task 2019-05-03T23:35:43.753Z] after 10639 requests (10639 known processed) with 0 events remaining.
[task 2019-05-03T23:35:43.753Z] compizconfig - Info: Backend : ini
[task 2019-05-03T23:35:43.753Z] compizconfig - Info: Integration : true
[task 2019-05-03T23:35:43.753Z] compizconfig - Info: Profile : default
[task 2019-05-03T23:35:43.967Z] No screen session found.
[task 2019-05-03T23:35:43.967Z] + true
[task 2019-05-03T23:35:43.967Z] + exit 2
[taskcluster 2019-05-03 23:35:44.419Z] === Task Finished ===
[taskcluster 2019-05-03 23:35:48.072Z] Unsuccessful task run with exit code: 2 completed in 1655.222 seconds

I believe the linux64-ccov perma-fail is because the job is running for too long: should be able to fix by increasing the timeout.

Flags: needinfo?(gbrown)

linux64-ccov gtest has been perma-fail (mozilla-central only) since approximately March 20, 2019.

Depends on: 1549380

I will work on the ccov perma-fail in bug 1549380.

Flags: needinfo?(gbrown)

Recent occurences here are bug 1567921. Conversation about a fix can be found in bug 1486042

In the last 7 days there were 45 failures associated with this bug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-14&endday=2019-08-21&tree=trunk&bug=1115253
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=262243732&repo=mozilla-inbound&lineNumber=1665
Occurs on macosx1014-64 debug build type.
:dbrown any updates on this one?

The macosx debug time-outs are in XPCOMDeadlockDetectorTest.XPCOMSanityDeathTest, which has not been updated recently.

Likely started in this range:

https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=gtest&fromchange=e7ff4966b99e57346c8bff748b0dc06c074cfb00&tochange=5ae16b0b7a440df1b08490d5c4447dee36b2e179

I'm retriggering to narrow that down.

These failures were caused by bug 1035892, which was backed out for causing this failure, mostly reported in bug 1574515.

This bug no longer needs attention; clearing the longstanding ni.

Flags: needinfo?(drno)
Keywords: leave-open
See Also: → 1574515

(In reply to Intermittent Failures Robot from comment #298)
Logcat shows:

04-01 16:43:51.370  3982  3997 I gtest   : TEST-START | ExtractVPXCodecDetails.TestInputData
04-01 16:43:51.370  3982  3997 I Gecko   : [3982, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80070057: file /builds/worker/checkouts/gecko/dom/media/VideoUtils.cpp, line 296
04-01 16:43:51.370  3982  3997 I gtest   : TEST-PASS | ExtractVPXCodecDetails.TestInputData | test completed (time: 0ms)
04-01 16:43:51.370  3982  3997 I gtest   : TEST-START | ExtractVPXCodecDetails.TestParsingOutput
04-01 16:43:51.370  3982  3997 I gtest   : TEST-PASS | ExtractVPXCodecDetails.TestParsingOutput | test completed (time: 0ms)
04-01 16:43:51.370  3982  3997 I gtest   : TEST-START | AudioBuffers.Test
04-01 16:43:51.370  3982  3997 I gtest   : TEST-PASS | AudioBuffers.Test | test completed (time: 0ms)
04-01 16:43:51.370  3982  3997 I gtest   : TEST-START | TestAudioCallbackDriver.StartStop
04-01 16:43:51.570  3982  3997 I gtest   : TEST-UNEXPECTED-FAIL | TestAudioCallbackDriver.StartStop | Value of: driver->ThreadRunning()
04-01 16:43:51.570  3982  3997 I gtest   :   Actual: false
04-01 16:43:51.570  3982  3997 I gtest   : Expected: true
04-01 16:43:51.570  3982  3997 I gtest   : Verify thread is running @ /builds/worker/checkouts/gecko/dom/media/gtest/TestAudioCallbackDriver.cpp:73
04-01 16:43:51.571  3982  3997 I gtest   : TEST-UNEXPECTED-FAIL | TestAudioCallbackDriver.StartStop | Value of: driver->IsStarted()
04-01 16:43:51.571  3982  3997 I gtest   :   Actual: false
04-01 16:43:51.571  3982  3997 I gtest   : Expected: true
04-01 16:43:51.571  3982  3997 I gtest   : Verify thread is started @ /builds/worker/checkouts/gecko/dom/media/gtest/TestAudioCallbackDriver.cpp:74
You need to log in before you can comment on or make changes to this bug.