Fix additional logging for "test_end for test_* logged while not in progress" in case of crashes

RESOLVED FIXED in Firefox 52

Status

RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: whimboo, Assigned: whimboo)

Tracking

Version 3
mozilla52
Points:
---

Firefox Tracking Flags

(firefox52 fixed)

Details

(Assignee)

Description

2 years ago
In case of crashes we currently get log lines like the following:

> test_end for test_windows.py TestWindows.test_windows logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_windows.TestWindows", "method_name": "test_windows"}, "expected": "PASS", "test": "test_windows.py TestWindows.test_windows", "message": "None", "stack": "Traceback (most recent call last):\n"}

Looks like we mark a test as done somewhere else before, or actually try to log test_end twice?

Here an example:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8bf49aaceb5e&selectedJob=25193906

Log output:
> 14:33:17     INFO - 0x7fffa13c6000 - 0x7fffa13c7fff  linux-gate.so  ???
> 14:33:17     INFO - TEST-PASS | test_windows.py TestWindows.test_windows | took 126882ms
> 14:33:17    ERROR - test_end for test_windows.py TestWindows.test_windows logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_windows.TestWindows", "method_name": "test_windows"}, "expected": "PASS", "test": "test_windows.py TestWindows.test_windows", "message": "None", "stack": "Traceback (most recent call last):\n"}
(Assignee)

Comment 1

2 years ago
So the problematic lines are located here:
https://dxr.mozilla.org/mozilla-central/source/testing/marionette/harness/marionette/runner/base.py#206

When a test runs and it is successful we call `addSuccess()`. With this call the test is also getting marked as finished:

https://dxr.mozilla.org/mozilla-central/source/testing/marionette/harness/marionette/runner/base.py#141

Later when we check for crashes (see first link) and detect one, we reset the result by calling `addError()`. This call will cause the structuredlogger to fail, because it would operate on a not running test.

I will investigate more on Monday.
(Assignee)

Comment 2

2 years ago
I wonder if we really should modify the test status at the end in case a crash happens. For example see the following:

> 21:37:04 INFO - PROCESS-CRASH | test_safe_browsing_notification.py TestSafeBrowsingNotificationBar.test_notification_bar | application crashed [@ mozalloc_abort] 
> 21:37:05 ERROR - test_end for test_safe_browsing_notification.py TestSafeBrowsingNotificationBar.test_notification_bar logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_safe_browsing_notification.TestSafeBrowsingNotificationBar", "method_name": "test_notification_bar"}, "expected": "PASS", "test": "test_safe_browsing_notification.py TestSafeBrowsingNotificationBar.test_notification_bar", "message": "None", "stack": "Traceback (most recent call l 

Sheriffs will file bugs based on the ERROR line which in this case is not the real issue here. Instead the crash should be filed as bug.

That would mean in case of a crash the test could be marked as PASS if all steps actually pass, while we get the PROCESS_CRASH line logged. Only if the crash really affects the status of the test, it would be marked as failure. The downside here would also be that two different failure lines are present and could lead sheriffs to file two independent bug reports for maybe the same issue.

David, I assume the above is not satisfying, or what's your opinion on it? If we clearly want to mark the test as failed we have to refactor `add_test_result()` in base.py to not immediately mark a test as done when the result gets set.
Flags: needinfo?(dburns)
I have spoken to Henrik about this. We are going to update the runner to print out that the error happened in Marionette Runner so that we can track it there.
Flags: needinfo?(dburns)
(Assignee)

Comment 4

2 years ago
(In reply to David Burns :automatedtester from comment #3)
> I have spoken to Henrik about this. We are going to update the runner to
> print out that the error happened in Marionette Runner so that we can track
> it there.

David, we mixed up the bugs in our meeting. What we were actually talking about is the crash reporting scenario and this is bug 1294054.

This bug is about the additional "logged while not in progress." failure we get because we are trying to change the status of a test while it has already been set as finished.
Flags: needinfo?(dburns)
(In reply to Henrik Skupin (:whimboo) from comment #4)
> (In reply to David Burns :automatedtester from comment #3)
> > I have spoken to Henrik about this. We are going to update the runner to
> > print out that the error happened in Marionette Runner so that we can track
> > it there.
> 
> David, we mixed up the bugs in our meeting. What we were actually talking
> about is the crash reporting scenario and this is bug 1294054.
> 
> This bug is about the additional "logged while not in progress." failure we
> get because we are trying to change the status of a test while it has
> already been set as finished.

Is this from Marionette or is this from mozlog?
Flags: needinfo?(dburns)
(Assignee)

Updated

2 years ago
Flags: needinfo?(dburns)
(Assignee)

Comment 7

2 years ago
This might be fixed with my upcoming patch for bug 1299216.
Depends on: 1299216
Flags: needinfo?(dburns)
(Assignee)

Comment 8

2 years ago
My testing while working on bug 1299216 has been shown that this behavior should be fixed now.
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
You need to log in before you can comment on or make changes to this bug.