Closed Bug 1703441 Opened 4 years ago Closed 4 years ago

Intermittent telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process unexpectedly quit without restarting (exit code: 0))

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=335660525&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/R8sVF2tmTo6KfSzCWg1wDg/runs/0/artifacts/public/logs/live_backing.log


[task 2021-04-07T04:16:36.936Z] 04:16:36     INFO - pingserver pings_handler received 'main' ping with reason 'shutdown'
[task 2021-04-07T04:16:36.981Z] 04:16:36     INFO -  1617768996979	Toolkit.Telemetry	INFO	TelemetrySend::_doPing - successfully loaded, status: 200
[task 2021-04-07T04:16:36.981Z] 04:16:36     INFO -  1617768996979	Toolkit.Telemetry	TRACE	TelemetrySend::_onPingRequestFinished - success: true, persisted: true
[task 2021-04-07T04:16:36.982Z] 04:16:36     INFO -  1617768996980	Toolkit.Telemetry	TRACE	TelemetryStorage::removePendingPing - deleting ping with id: 883600a9-89b7-4a7d-8fa9-500d3ba8ca5b, path: Z:\task_1617768576\build\tmpnjdu6g_b.mozrunner\saved-telemetry-pings\883600a9-89b7-4a7d-8fa9-500d3ba8ca5b
[task 2021-04-07T04:16:37.034Z] 04:16:37     INFO -  1617768997032	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0
[task 2021-04-07T04:16:37.047Z] 04:16:37     INFO -  1617768997044	Toolkit.Telemetry	TRACE	TelemetryStorage::loadPingfile - unreadable ping Z:\task_1617768576\build\tmpnjdu6g_b.mozrunner\datareporting\aborted-session-ping: {"operation":"open","path":"Z:\\task_1617768576\\build\\tmpnjdu6g_b.mozrunner\\datareporting\\aborted-session-ping","winLastError":2}
[task 2021-04-07T04:16:37.047Z] 04:16:37     INFO -  1617768997045	Toolkit.Telemetry	TRACE	TelemetryStorage::loadAbortedSessionPing - no such file
[task 2021-04-07T04:16:37.048Z] 04:16:37     INFO -  1617768997045	Toolkit.Telemetry	TRACE	TelemetryController::checkAbortedSessionPing - found aborted-session ping: false
[task 2021-04-07T04:16:37.048Z] 04:16:37     INFO -  1617768997046	Toolkit.Telemetry	TRACE	TelemetrySession::_saveAbortedSessionPing
[task 2021-04-07T04:16:37.048Z] 04:16:37     INFO -  1617768997046	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: aborted-session, clearSubsession: false
[task 2021-04-07T04:16:37.049Z] 04:16:37     INFO -  1617768997048	Toolkit.Telemetry	TRACE	TelemetrySession::assemblePayloadWithMeasurements - reason: aborted-session, submitting subsession data: true
[task 2021-04-07T04:16:37.060Z] 04:16:37     INFO -  1617768997058	Toolkit.Telemetry	TRACE	TelemetryController::saveAbortedSessionPing
[task 2021-04-07T04:16:37.060Z] 04:16:37     INFO -  1617768997059	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
[task 2021-04-07T04:16:37.077Z] 04:16:37     INFO -  1617768997076	Toolkit.Telemetry	TRACE	TelemetryStorage::saveAbortedSessionPing - ping path: Z:\task_1617768576\build\tmpnjdu6g_b.mozrunner\datareporting\aborted-session-ping
[task 2021-04-07T04:16:37.106Z] 04:16:37     INFO -  1617768997105	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-04-07T04:16:37.107Z] 04:16:37     INFO -  1617768997105	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1617768576\build\tmpnjdu6g_b.mozrunner\datareporting\aborted-session-ping
[task 2021-04-07T04:16:37.125Z] 04:16:37     INFO -  1617768997124	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange
[task 2021-04-07T04:16:37.127Z] 04:16:37     INFO -  1617768997126	Toolkit.Telemetry	TRACE	TelemetryScheduler::init
[task 2021-04-07T04:16:37.128Z] 04:16:37     INFO -  1617768997126	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
[task 2021-04-07T04:16:37.128Z] 04:16:37     INFO -  1617768997127	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Wed Apr 07 2021 04:21:37 GMT+0000 (Greenwich Mean Time)
[task 2021-04-07T04:16:37.129Z] 04:16:37     INFO -  1617768997127	Toolkit.Telemetry	TRACE	TelemetryStorage::cleanArchiveTask
[task 2021-04-07T04:16:37.129Z] 04:16:37     INFO -  1617768997128	Toolkit.Telemetry	TRACE	TelemetryStorage::removeFHRDatabase
[task 2021-04-07T04:16:37.143Z] 04:16:37     INFO -  1617768997142	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Starting up.
[task 2021-04-07T04:16:37.144Z] 04:16:37     INFO -  1617768997143	Toolkit.Telemetry	TRACE	TelemetryPrioPing::Starting up.
[task 2021-04-07T04:16:37.144Z] 04:16:37     INFO -  1617768997143	Toolkit.Telemetry	TRACE	TelemetryController::saveUninstallPing
[task 2021-04-07T04:16:37.146Z] 04:16:37     INFO -  1617768997145	Toolkit.Telemetry	INFO	TelemetryController::saveUninstallPing - otherInstalls: 0
[task 2021-04-07T04:16:37.147Z] 04:16:37     INFO -  1617768997145	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type uninstall, aOptions {"addClientId":true,"addEnvironment":true}
[task 2021-04-07T04:16:37.153Z] 04:16:37     INFO -  1617768997152	Toolkit.Telemetry	TRACE	TelemetryStorage::_purgeOldPings
[task 2021-04-07T04:16:37.195Z] 04:16:37     INFO -  1617768997193	Toolkit.Telemetry	TRACE	TelemetryStorage::removeUninstallPings - removing: C:\ProgramData\Mozilla\uninstall_ping_EA1A06E644B47E91_6b31cc9a-940b-4a0e-811b-4366a47af76e.json
[task 2021-04-07T04:16:37.222Z] 04:16:37     INFO -  1617768997221	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanArchive

[task 2021-04-07T04:16:37.262Z] 04:16:37     INFO -  [Child 4508, Main Thread] WARNING: Scrolled rect smaller than scrollport?: file /builds/worker/checkouts/gecko/layout/generic/nsGfxScrollFrame.cpp:7064
[task 2021-04-07T04:16:37.281Z] 04:16:37     INFO -  1617768997279	Toolkit.Telemetry	TRACE	TelemetryStorage::removeUninstallPings - success
[task 2021-04-07T04:16:37.353Z] 04:16:37     INFO -  1617768997351	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: C:\ProgramData\Mozilla\uninstall_ping_EA1A06E644B47E91_baa50418-98b2-4336-b948-77bb17138812.json
[task 2021-04-07T04:16:37.390Z] 04:16:37     INFO -  [2021-04-07T04:16:37Z WARN  neqo_transport::recovery] [LossRecovery] ignoring in-1 from dropped space
[task 2021-04-07T04:16:37.443Z] 04:16:37     INFO -  1617768997442	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanArchive - checking in subdir: Z:\task_1617768576\build\tmpnjdu6g_b.mozrunner\datareporting\archived\2021-04
[task 2021-04-07T04:16:37.459Z] 04:16:37     INFO -  1617768997458	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforceArchiveQuota
[task 2021-04-07T04:19:39.954Z] 04:19:39     INFO -  Exiting due to channel error.
[task 2021-04-07T04:19:43.696Z] 04:19:43     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process unexpectedly quit without restarting (exit code: 0))
[task 2021-04-07T04:19:43.696Z] 04:19:43     INFO - Traceback (most recent call last):
[task 2021-04-07T04:19:43.696Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 214, in run
[task 2021-04-07T04:19:43.696Z] 04:19:43     INFO -     testMethod()
[task 2021-04-07T04:19:43.696Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 51, in test_event_ping
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     payload = self.wait_for_ping(self.restart_browser, EVENT_PING)["payload"]
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 170, in wait_for_ping
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     action_func, ping_filter, 1, ping_server=ping_server
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 156, in wait_for_pings
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     action_func()
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 176, in restart_browser
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     return self.marionette.restart(clean=False, in_app=True)
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     m._handle_socket_failure()
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\marionette.py", line 716, in _handle_socket_failure
[task 2021-04-07T04:19:43.697Z] 04:19:43     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -     raise value.with_traceback(tb)
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -     return func(*args, **kwargs)
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1107, in restart
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -     tb,
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -     raise value.with_traceback(tb)
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1087, in restart
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -     self.raise_for_port(timeout=timeout_restart, check_process_status=False)
[task 2021-04-07T04:19:43.698Z] 04:19:43     INFO -   File "Z:\task_1617768576\build\venv\lib\site-packages\marionette_driver\marionette.py", line 598, in raise_for_port
[task 2021-04-07T04:19:43.699Z] 04:19:43     INFO -     self.host, self.port
[task 2021-04-07T04:19:43.699Z] 04:19:43     INFO - TEST-INFO took 197264ms```
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.