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

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

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

[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'MOZ_SOURCE_CHANGESET': '7775ced80e99c60f1231b0b463e07f4da7face81',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'MOZ_SOURCE_REPO': 'https://hg.mozilla.org/mozilla-central',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'MOZ_UPLOAD_DIR': '/builds/worker/workspace/build/blobber_upload_dir',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'NEED_PULSEAUDIO': 'true',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'NEED_WINDOW_MANAGER': 'true',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'OLDPWD': '/builds/worker/workspace',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'PATH': '/builds/worker/workspace/build/venv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/builds/worker/bin',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'PWD': '/builds/worker/workspace',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'RELENGAPI_NAME': '/clever_noyce/relengapi',
[task 2019-04-05T17:44:26.905Z] 17:44:26 INFO - 'RELENGAPI_PORT': 'tcp://172.17.0.2:80',
[task 2019-04-05T17:44:26.906Z] 17:44:26 INFO - 'RELENGAPI_PORT_80_TCP': 'tcp://172.17.0.2:80',
[task 2019-04-05T17:44:26.906Z] 17:44:26 INFO - 'RELENGAPI_PORT_80_TCP_ADDR': '172.17.0.2',
[task 2019-04-05T17:44:26.906Z] 17:44:26 INFO - 'RELENGAPI_PORT_80_TCP_PORT': '80',
[task 2019-04-05T17:44:26.906Z] 17:44:26 INFO - 'RELENGAPI_PORT_80_TCP_PROTO': 'tcp',
[task 2019-04-05T17:44:26.906Z] 17:44:26 INFO - 'RUN_ID': '0',
[task 2019-04-05T17:44:26.907Z] 17:44:26 INFO - 'RUST_BACKTRACE': 'full',
[task 2019-04-05T17:44:26.907Z] 17:44:26 INFO - 'SCCACHE_DISABLE': '1',
[task 2019-04-05T17:44:26.907Z] 17:44:26 INFO - 'SHELL': '/bin/bash',
[task 2019-04-05T17:44:26.907Z] 17:44:26 INFO - 'SHLVL': '1',
[task 2019-04-05T17:44:26.907Z] 17:44:26 INFO - 'STYLO_THREADS': '4',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_INSTANCE_TYPE': 'm3.xlarge',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_NAME': '/clever_noyce/taskcluster',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PORT': 'tcp://172.17.0.4:80',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PORT_80_TCP': 'tcp://172.17.0.4:80',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PORT_80_TCP_ADDR': '172.17.0.4',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PORT_80_TCP_PORT': '80',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PORT_80_TCP_PROTO': 'tcp',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PROXY_URL': 'http://taskcluster',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_PUBLIC_IP': '54.193.56.54',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_ROOT_URL': 'https://taskcluster.net',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_WORKER_GROUP': 'us-west-1',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASKCLUSTER_WORKER_TYPE': 'gecko-t-linux-xlarge',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TASK_ID': 'eRxwU1SiTzOzFjqT2_Qtdg',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TERM': 'xterm',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'TOOLTOOL_CACHE': '/builds/worker/tooltool-cache',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'USER': 'worker',
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - 'WORKING_DIR': '/builds/worker'}
[task 2019-04-05T17:44:26.908Z] 17:44:26 INFO - Calling ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py', '--symbols-path=/builds/worker/workspace/build/symbols', '--test-plugin-path=/builds/worker/workspace/build/application/firefox/plugins', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/xpcshell_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/xpcshell_errorsummary.log', '--utility-path=tests/bin', '--xpcshell=/builds/worker/workspace/build/application/firefox/xpcshell', '--manifest=tests/xpcshell/tests/xpcshell.ini', u'parser/xml/test/unit/test_sanitizer.js'] with output_timeout 1000
[task 2019-04-05T17:44:27.127Z] 17:44:27 INFO - Found node at /usr/local/bin/node
[task 2019-04-05T17:44:27.127Z] 17:44:27 INFO - Found moz-http2 at /builds/worker/workspace/build/tests/xpcshell/moz-http2/moz-http2.js
[task 2019-04-05T17:44:27.566Z] 17:44:27 INFO - Running tests sequentially.
[task 2019-04-05T17:44:27.566Z] 17:44:27 INFO - SUITE-START | Running 1 tests
[task 2019-04-05T17:44:27.567Z] 17:44:27 INFO - profile dir is /tmp/xpcshell/xpcshellprofile
[task 2019-04-05T17:44:27.574Z] 17:44:27 INFO - TEST-START | parser/xml/test/unit/test_sanitizer.js
[task 2019-04-05T17:44:29.971Z] 17:44:29 WARNING - TEST-UNEXPECTED-FAIL | parser/xml/test/unit/test_sanitizer.js | xpcshell return code: -11
[task 2019-04-05T17:44:29.972Z] 17:44:29 INFO - TEST-INFO took 2396ms
[task 2019-04-05T17:44:29.972Z] 17:44:29 INFO - >>>>>>>
[task 2019-04-05T17:44:29.973Z] 17:44:29 INFO - PID 11400 | [CodeCoverage] Setting handlers for process 11400.
[task 2019-04-05T17:44:29.973Z] 17:44:29 INFO - PID 11400 | [11400, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2528

The stack shows this as happening due to places shutdown so moving to places.

Assertion failure: threadOpenedOn == NS_GetCurrentThread(), at /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp:978
#01: mozilla::storage::Connection::isAsyncExecutionThreadAvailable() [mfbt/Assertions.h:38]
#02: mozilla::storage::Connection::synchronousClose() [storage/mozStorageConnection.cpp:1263]
#03: mozilla::storage::Connection::Release() [storage/mozStorageConnection.cpp:532]
#04: nsCOMPtr<mozIStorageAsyncConnection>::~nsCOMPtr() [xpcom/base/nsCOMPtr.h:441]
#05: mozilla::places::ConcurrentStatementsHolder::Release() [memory/mozalloc/mozalloc.h:151]
#06: mozilla::places::History::~History() [mfbt/RefPtr.h:46]
#07: mozilla::places::History::~History() [toolkit/components/places/History.cpp:1472]
#08: mozilla::places::History::Release() [toolkit/components/places/History.cpp:2481]
#09: mozilla::xpcom::StaticModule::SetServiceInstance(already_AddRefed<nsISupports>) const [xpcom/base/StaticPtr.h:167]
#10: nsComponentManagerImpl::FreeServices() [xpcom/components/nsComponentManager.cpp:1286]
#11: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:702]
#12: NS_ShutdownXPCOM [xpcom/build/XPCOMInit.cpp:585]
#13: XRE_XPCShellMain(int, char**, char**, XREShellData const*) [js/xpconnect/src/XPCShellImpl.cpp:1419]
#14: mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) [toolkit/xre/Bootstrap.cpp:54]
#15: main [js/xpconnect/shell/xpcshell.cpp:65]
#16: libc.so.6 + 0x20830
#17: _start

This is similar to bug 1541934 wherein nsPermissionManager is being created after "profile-before-change" which is when nsPermissionManager would normally tear down its database connection. So mozStorage gets cleared as services get destroyed. As I argue in context to that bug, this is a good assertion to fire, so we don't want to fix it, we want to fix the mozStorage consumer.

I think this is likely a similar problem and somewhat endemic to xpcshell test cases, especially as things like https://bugzilla.mozilla.org/show_bug.cgi?id=1505772#c20 are ongoing issues. (Plus some tests not using do_get_profile which is necessary to have the shutdown observer notifications happen.) Places needs to make sure that it cannot be constructed/initialized after the point when it would normally shutdown.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup