New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 774737 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Last visit > 30 days ago
Closed: Nov 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Show actual failure reason instead of RPC error for failing autotests

Project Member Reported by harpreet@chromium.org, Oct 14 2017

Issue description

Autotests that use xmlrpc server to execute commands on the client via a server-side test report RPC error as the failure reason instead of the actual failure reason. Examples below...


https://wmatrix.googleplex.com/failures/unfiltered?suites=hotrod&days_back=30&builds=R63-9997.0.0&releases=tot&platforms=tricky&hide_missing=True

Failure reason: Unhandled Exception: RPC error: cfm_main_screen.start_new_hangout_session


Actual failure reason (from test DEBUG file): TestFail: Not able to start session.

 
Status: Started (was: Assigned)
Project Member

Comment 2 by bugdroid1@chromium.org, Oct 24 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/1e7843adcc8076371111c27575468c22ccf296e8

commit 1e7843adcc8076371111c27575468c22ccf296e8
Author: Wai-Hong Tam <waihong@google.com>
Date: Tue Oct 24 19:57:46 2017

multimedia: Raise the exception from client during a RPC call

When calling a RPC, any exception from client is lost. The
exception is converted to a string value. We used to raise
a general exception with messages of the call name.

This change parses the exception string value, and then
raises a proper exception, like TestFail, such that in the
test report, we can group tests together by their failures.

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Ic9eeb3881f25f708d1c51c0f3a696e54b8beb1c0
Reviewed-on: https://chromium-review.googlesource.com/733849
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
Reviewed-by: Denis Tosic <dtosic@chromium.org>

[modify] https://crrev.com/1e7843adcc8076371111c27575468c22ccf296e8/server/cros/multimedia/remote_facade_factory.py

Status: Fixed (was: Started)
Labels: M-64 Merge-Request-63 Merge-Request-62 M-62 M-63
Project Member

Comment 5 by sheriffbot@chromium.org, Oct 24 2017

Labels: -Merge-Request-62 Merge-Review-62 Hotlist-Merge-Review
This bug requires manual review: Request affecting a post-stable build
Please contact the milestone owner if you have questions.
Owners: amineer@(Android), cmasso@(iOS), bhthompson@(ChromeOS), abdulsyed@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Labels: -Hotlist-Merge-Review -Merge-Request-63 -Merge-Review-62 Merge-Approved-62 Merge-Approved-63
Approved for 62 and 63.
Project Member

Comment 7 by bugdroid1@chromium.org, Oct 25 2017

Labels: merge-merged-release-R63-10032.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/d8e43a7d24e6fb9a72886cdc56244e1fe46946b9

commit d8e43a7d24e6fb9a72886cdc56244e1fe46946b9
Author: Wai-Hong Tam <waihong@google.com>
Date: Wed Oct 25 18:46:33 2017

multimedia: Raise the exception from client during a RPC call

When calling a RPC, any exception from client is lost. The
exception is converted to a string value. We used to raise
a general exception with messages of the call name.

This change parses the exception string value, and then
raises a proper exception, like TestFail, such that in the
test report, we can group tests together by their failures.

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Ic9eeb3881f25f708d1c51c0f3a696e54b8beb1c0
Reviewed-on: https://chromium-review.googlesource.com/733849
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
Reviewed-by: Denis Tosic <dtosic@chromium.org>
(cherry picked from commit 1e7843adcc8076371111c27575468c22ccf296e8)
Reviewed-on: https://chromium-review.googlesource.com/736892
Commit-Queue: Harpreet Grewal <harpreet@chromium.org>
Tested-by: Harpreet Grewal <harpreet@chromium.org>
Trybot-Ready: Harpreet Grewal <harpreet@chromium.org>

[modify] https://crrev.com/d8e43a7d24e6fb9a72886cdc56244e1fe46946b9/server/cros/multimedia/remote_facade_factory.py

Project Member

Comment 8 by bugdroid1@chromium.org, Oct 25 2017

Labels: merge-merged-release-R62-9901.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/aa082489a43b8ab4a395f352b55bb4b4fe885cdf

commit aa082489a43b8ab4a395f352b55bb4b4fe885cdf
Author: Wai-Hong Tam <waihong@google.com>
Date: Wed Oct 25 18:46:39 2017

multimedia: Raise the exception from client during a RPC call

When calling a RPC, any exception from client is lost. The
exception is converted to a string value. We used to raise
a general exception with messages of the call name.

This change parses the exception string value, and then
raises a proper exception, like TestFail, such that in the
test report, we can group tests together by their failures.

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Ic9eeb3881f25f708d1c51c0f3a696e54b8beb1c0
Reviewed-on: https://chromium-review.googlesource.com/733849
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
Reviewed-by: Denis Tosic <dtosic@chromium.org>
(cherry picked from commit 1e7843adcc8076371111c27575468c22ccf296e8)
Reviewed-on: https://chromium-review.googlesource.com/736893
Commit-Queue: Harpreet Grewal <harpreet@chromium.org>
Tested-by: Harpreet Grewal <harpreet@chromium.org>
Trybot-Ready: Harpreet Grewal <harpreet@chromium.org>

[modify] https://crrev.com/aa082489a43b8ab4a395f352b55bb4b4fe885cdf/server/cros/multimedia/remote_facade_factory.py

Labels: -Merge-Approved-62 -Merge-Approved-63
Status: Started (was: Fixed)
waihong@ - looks like this needs to be expanded to raise all exceptions from the client and not only TestFail / TestError. 

Example: Most of the tests returning "RPC error: cfm_main_screen.enroll_device" as the failure reason (link below) are actually failing with timeoutexception https://wmatrix.googleplex.com/failures/unfiltered?suites=bluestreak%2Chotrod&days_back=15&builds=R64-10065.0.0&releases=tot&platforms=guado&hide_missing=true


Here is the log output:

10/25 03:30:41.164 DEBUG|             utils:0280| [client] 03:30:27 DEBUG| sent [{
10/25 03:30:41.164 DEBUG|             utils:0280| [client]   "id": 44, 
10/25 03:30:41.164 DEBUG|             utils:0280| [client]   "method": "Runtime.evaluate", 
10/25 03:30:41.164 DEBUG|             utils:0280| [client]   "params": {
10/25 03:30:41.164 DEBUG|             utils:0280| [client]     "expression": "document.getElementById(\"identifierId\") != null", 
10/25 03:30:41.165 DEBUG|             utils:0280| [client]     "returnByValue": true
10/25 03:30:41.165 DEBUG|             utils:0280| [client]   }
10/25 03:30:41.165 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.165 DEBUG|             utils:0280| [client] 03:30:27 DEBUG| got [{
10/25 03:30:41.165 DEBUG|             utils:0280| [client]   "id": 44, 
10/25 03:30:41.165 DEBUG|             utils:0280| [client]   "result": {
10/25 03:30:41.166 DEBUG|             utils:0280| [client]     "result": {
10/25 03:30:41.166 DEBUG|             utils:0280| [client]       "type": "boolean", 
10/25 03:30:41.166 DEBUG|             utils:0280| [client]       "value": false
10/25 03:30:41.166 DEBUG|             utils:0280| [client]     }
10/25 03:30:41.166 DEBUG|             utils:0280| [client]   }
10/25 03:30:41.166 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.167 DEBUG|             utils:0280| [client] 03:30:29 DEBUG| sent [{
10/25 03:30:41.167 DEBUG|             utils:0280| [client]   "id": 45, 
10/25 03:30:41.167 DEBUG|             utils:0280| [client]   "method": "Console.enable"
10/25 03:30:41.167 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.167 DEBUG|             utils:0280| [client] 03:30:29 DEBUG| got [{
10/25 03:30:41.168 DEBUG|             utils:0280| [client]   "id": 45, 
10/25 03:30:41.168 DEBUG|             utils:0280| [client]   "result": {}
10/25 03:30:41.168 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.168 DEBUG|             utils:0280| [client] 03:30:39 DEBUG| sent [{
10/25 03:30:41.168 DEBUG|             utils:0280| [client]   "id": 46, 
10/25 03:30:41.168 DEBUG|             utils:0280| [client]   "method": "Console.disable"
10/25 03:30:41.169 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.169 DEBUG|             utils:0280| [client] 03:30:39 DEBUG| got [{
10/25 03:30:41.169 DEBUG|             utils:0280| [client]   "id": 46, 
10/25 03:30:41.169 DEBUG|             utils:0280| [client]   "result": {}
10/25 03:30:41.169 DEBUG|             utils:0280| [client] }]
10/25 03:30:41.169 DEBUG|             utils:0280| [client] 127.0.0.1 - - [25/Oct/2017 03:30:39] "POST /RPC2 HTTP/1.1" 200 -
10/25 03:30:41.172 DEBUG|remote_facade_fact:0126| RPC 'cfm_main_screen.enroll_device'((), {}) returns 'Traceback (most recent call last):\n  File "./multimedia_xmlrpc_server.py", line 92, in _dispatch\n    return func(*params)\n  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 51, in enroll_device\n    self._PWD)\n  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 41, in RemoraEnrollment\n    for_user_triggered_enrollment=False)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 89, in NavigateGaiaLogin\n    self._NavigateGaiaLogin(username, password, enterprise_enroll)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 106, in _NavigateGaiaLogin\n    py_utils.WaitFor(_GetGaiaFunction, 20)(self, username, password)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 125, in _NavigateWebViewLogin\n    self._NavigateWebViewEntry(\'identifierId\', username, \'identifierNext\')\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 131, in _NavigateWebViewEntry\n    self._WaitForField(field)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 155, in _WaitForField\n    field=field, timeout=20)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 239, in WaitForJavaScriptCondition\n    return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function\n    return func(*args, **kwargs)\n  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 302, in WaitForJavaScriptCondition\n    e.message + \'\\n\' + debug_message)\nTimeoutException: Timed out while waiting 20s for IsJavaScriptExpressionTrue.\nConsole output:\n\n'.
10/25 03:30:41.173 ERROR|remote_facade_fact:0170| Failed RPC 'cfm_main_screen.enroll_device'((), {}) with status [<type 'exceptions.Exception'>].
10/25 03:30:41.173 ERROR|enterprise_CFM_Per:0570| Exception during test, raising TestFail
Traceback (most recent call last):
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_Perf/enterprise_CFM_Perf.py", line 559, in run_once
    self.enroll_device_and_start_hangout()
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_Perf/enterprise_CFM_Perf.py", line 76, in enroll_device_and_start_hangout
    self.cfm_facade.enroll_device()
  File "/usr/local/autotest/server/cros/multimedia/cfm_facade_adapter.py", line 49, in enroll_device
    self._cfm_proxy.enroll_device()
  File "/usr/local/autotest/server/cros/multimedia/remote_facade_factory.py", line 59, in __call__
    return self.__call_method(self.__name, *args, **dargs)
  File "/usr/local/autotest/server/cros/multimedia/remote_facade_factory.py", line 165, in __call_proxy
    return call_rpc_with_log()
  File "/usr/local/autotest/server/cros/multimedia/remote_facade_factory.py", line 141, in call_rpc_with_log
    raise Exception('RPC error: %s\n%s' % (name, value))
Exception: RPC error: cfm_main_screen.enroll_device
Traceback (most recent call last):
  File "./multimedia_xmlrpc_server.py", line 92, in _dispatch
    return func(*params)
  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 51, in enroll_device
    self._PWD)
  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 41, in RemoraEnrollment
    for_user_triggered_enrollment=False)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 89, in NavigateGaiaLogin
    self._NavigateGaiaLogin(username, password, enterprise_enroll)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 106, in _NavigateGaiaLogin
    py_utils.WaitFor(_GetGaiaFunction, 20)(self, username, password)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 125, in _NavigateWebViewLogin
    self._NavigateWebViewEntry('identifierId', username, 'identifierNext')
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 131, in _NavigateWebViewEntry
    self._WaitForField(field)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 155, in _WaitForField
    field=field, timeout=20)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 239, in WaitForJavaScriptCondition
    return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 302, in WaitForJavaScriptCondition
    e.message + '\n' + debug_message)
TimeoutException: Timed out while waiting 20s for IsJavaScriptExpressionTrue.
Console output:

It'll actually be better to raise an exception that includes both the RPC error (indicating which RPC call failed) along with the exception message from the client. This will be more helpful with debugging.
The current approach needs to convert the exception string embedded in the RPC result to a real exception. Besides the TimeoutException, what other exceptions need to convert?
Cc: ar...@chromium.org mzhuo@chromium.org
We'll need to go through the test failures to come up with a complete list of exceptions we have seen in the past. 


Here is one that we have seen frequently "DevtoolsTargetCrashException"


09/26 04:48:36.572 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_mic_devices'((), {}) returns ['Jabra SPEAK 410', 'HD Pro Webcam C920: USB Audio:0,0'].
09/26 04:48:36.714 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_speaker_devices'((), {}) returns ['Jabra SPEAK 410'].
09/26 04:48:36.874 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_camera_devices'((), {}) returns ['HD Pro Webcam C920 (046d:082d)'].
09/26 04:48:37.031 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_preferred_mic'((), {}) returns 'Jabra SPEAK 410'.
09/26 04:48:37.192 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_preferred_speaker'((), {}) returns 'Jabra SPEAK 410'.
09/26 04:48:37.355 DEBUG|remote_facade_fact:0114| RPC 'cfm_main_screen.get_preferred_camera'((), {}) returns 'HD Pro Webcam C920 (046d:082d)'.
09/26 04:48:37.687 ERROR|remote_facade_fact:0134| Failed RPC 'cfm_main_screen.end_hangout_session'((), {}) with status [<type 'exceptions.Exception'>].
09/26 04:48:37.688 DEBUG|              test:0389| Test failed due to RPC error: cfm_main_screen.end_hangout_session
Traceback (most recent call last):
  File "./multimedia_xmlrpc_server.py", line 92, in _dispatch
    return func(*params)
  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 206, in end_hangout_session
    self._cfmApi.end_hangout_session()
  File "/usr/local/autotest/common_lib/cros/cfm_hangouts_api.py", line 102, in end_hangout_session
    self._webview_context.ExecuteJavaScript("window.hrHangupCallForTest()")
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 192, in ExecuteJavaScript
    return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 37, in Inner
    return func(inspector_backend, *args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 219, in ExecuteJavaScript
    self._runtime.Execute(statement, context_id, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 20, in Execute
    self.Evaluate(expr + '; 0;', context_id, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 44, in Evaluate
    res = self._inspector_websocket.SyncRequest(request, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 116, in SyncRequest
    res = self._Receive(timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 172, in _Receive
    self._HandleNotification(result)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 185, in _HandleNotification
    self._domain_handlers[domain_name](result)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 454, in _HandleInspectorDomainNotification
    raise exception
DevtoolsTargetCrashException: Devtools target crashed
********************************************************************************
(/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:507 _AddDebuggingInformation) Received a socket error in the browser connection and the tab no longer exists. The tab probably crashed.
********************************************************************************
(/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:508 _AddDebuggingInformation) Debugger url: ws://127.0.0.1:36258/devtools/page/fcaaeeef-0d96-4ad9-8815-4c39926b88a2
Found Minidump: False
Stack Trace:
********************************************************************************
	Cannot get stack trace on CrOS
********************************************************************************
Standard output:
********************************************************************************
	Cannot get standard output on CrOS
********************************************************************************
Project Member

Comment 14 by bugdroid1@chromium.org, Oct 31 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/ac0eac12bb6317dc8dc9350d939d14cd23c598a0

commit ac0eac12bb6317dc8dc9350d939d14cd23c598a0
Author: Wai-Hong Tam <waihong@google.com>
Date: Tue Oct 31 06:21:32 2017

multimedia: Append the RPC name on the exception message from client

Append the RPC name on the exception message (TestFail or TestError)
from client. It is helpful with debugging. An example is like:
  FAIL: Failed to set mirrored (RPC: display.set_mirrored)

Also make other exceptions with similar messages, like:
  FAIL: Unhandled Exception: DevtoolsTargetCrashException: Devtools
  target crashed (RPC: cfm_main_screen.end_hangout_session)

If the original exception type is failed to be parsed, raise the
default one, like:
  FAIL: Unhandled Exception: Exception from client (RPC:
  cfm_main_screen.enroll_device)

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Icb5d779d994702af65af646e6cb801321e439647
Reviewed-on: https://chromium-review.googlesource.com/744522
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>

[modify] https://crrev.com/ac0eac12bb6317dc8dc9350d939d14cd23c598a0/server/cros/multimedia/remote_facade_factory.py

Looks like the last line in traceback is Console output: instead of TimeoutException: this results in the failure reasons being something like:

Unhandled Exception: Console output: (RPC: cfm_main_screen.enroll_device)
Console output: (RPC: cfm_main_screen.enroll_device)

https://wmatrix.googleplex.com/failures/unfiltered?suites=bluestreak%2Chotrod&days_back=15&builds=R64-10090.0.0&releases=tot&platforms=rikku&hide_missing=true

Looks like some exceptions are added more messages afterward, instead of a single line. 
https://cs.corp.google.com/github/catapult-project/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py?q=inspector_backend.py&dr&l=295

Will add more handling code.
The following (link below) is raising a default exception instead of more meaningful "DevtoolsTargetCrashException: Devtools target crashed" that's in the trace since it does not satisfy this check https://cs.corp.google.com/chromeos_public/src/third_party/autotest/files/server/cros/multimedia/remote_facade_factory.py?l=133



https://wmatrix.googleplex.com/failures/unfiltered?suites=bluestreak%2Chotrod&tests=enterprise_CFM_SessionStress&days_back=15&builds=R64-10093.0.0&releases=64&platforms=guado&hide_missing=true


11/03 04:52:43.761 DEBUG|             utils:0280| [client] 04:52:39 DEBUG| sent [{
11/03 04:52:43.761 DEBUG|             utils:0280| [client]   "id": 712, 
11/03 04:52:43.761 DEBUG|             utils:0280| [client]   "method": "Runtime.evaluate", 
11/03 04:52:43.762 DEBUG|             utils:0280| [client]   "params": {
11/03 04:52:43.762 DEBUG|             utils:0280| [client]     "expression": "window.hrHangupCallForTest(); 0;", 
11/03 04:52:43.762 DEBUG|             utils:0280| [client]     "returnByValue": true
11/03 04:52:43.762 DEBUG|             utils:0280| [client]   }
11/03 04:52:43.762 DEBUG|             utils:0280| [client] }]
11/03 04:52:43.762 DEBUG|             utils:0280| [client] 04:52:42 DEBUG| got [{
11/03 04:52:43.762 DEBUG|             utils:0280| [client]   "method": "Inspector.targetCrashed", 
11/03 04:52:43.762 DEBUG|             utils:0280| [client]   "params": {}
11/03 04:52:43.762 DEBUG|             utils:0280| [client] }]
11/03 04:52:43.762 DEBUG|             utils:0280| [client] 127.0.0.1 - - [03/Nov/2017 04:52:43] "POST /RPC2 HTTP/1.1" 200 -
11/03 04:52:43.764 DEBUG|remote_facade_fact:0126| RPC 'cfm_main_screen.end_hangout_session'((), {}) returns 'Traceback (most recent call last):
  File "./multimedia_xmlrpc_server.py", line 92, in _dispatch
    return func(*params)
  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 279, in end_hangout_session
    self._cfmApi.end_hangout_session()
  File "/usr/local/autotest/common_lib/cros/cfm_hangouts_api.py", line 102, in end_hangout_session
    self._webview_context.ExecuteJavaScript("window.hrHangupCallForTest()")
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 192, in ExecuteJavaScript
    return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 38, in Inner
    return func(inspector_backend, *args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 225, in ExecuteJavaScript
    self._runtime.Execute(statement, context_id, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 20, in Execute
    self.Evaluate(expr + \'; 0;\', context_id, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 44, in Evaluate
    res = self._inspector_websocket.SyncRequest(request, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 116, in SyncRequest
    res = self._Receive(timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 172, in _Receive
    self._HandleNotification(result)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 185, in _HandleNotification
    self._domain_handlers[domain_name](result)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 460, in _HandleInspectorDomainNotification
    raise exception
DevtoolsTargetCrashException: Devtools target crashed
********************************************************************************
(/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:513 _AddDebuggingInformation) Received a socket error in the browser connection and the tab no longer exists. The tab probably crashed.
********************************************************************************
(/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:514 _AddDebuggingInformation) Debugger url: ws://127.0.0.1:47991/devtools/page/(6AF7B1359413B488E778F665D8EEDFE9)
Found Minidump: False
Stack Trace:
********************************************************************************
\tCannot get stack trace on CrOS
********************************************************************************
Standard output:
********************************************************************************
\tCannot get standard output on CrOS
********************************************************************************
System log:
(Not implemented)
'.
11/03 04:52:43.764 ERROR|remote_facade_fact:0175| Failed RPC 'cfm_main_screen.end_hangout_session'((), {}) with status [<type 'exceptions.Exception'>].
11/03 04:52:43.764 DEBUG|              test:0389| Test failed due to Exception from client (RPC: cfm_main_screen.end_hangout_session)

Labels: meeting-rooms-sheriff
Let's try this fix.
  https://chromium-review.googlesource.com/755253/

If still some exceptions not being parsed, may try to whitelist them one by one.
Project Member

Comment 20 by bugdroid1@chromium.org, Nov 7 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/4716d50ef89450be971cf4edfa2ce8f857e4583d

commit 4716d50ef89450be971cf4edfa2ce8f857e4583d
Author: Wai-Hong Tam <waihong@google.com>
Date: Tue Nov 07 23:25:23 2017

multimedia: Parse the exception message to find the exception keyword

Some exception adds more debug info to its message. Checking the
last line doesn't always correct. Have to use a regular expression
to search the keyword one line by one line from the last.

BUG= chromium:774737 
TEST=Ran enterprise_CFM_SessionStress and got the error:
Unhandled Exception: TimeoutException: Timed out while waiting 20s for
IsJavaScriptExpressionTrue. (RPC: cfm_main_screen.enroll_device)
It used to get a wrong error:
Unhandled Exception: Console output:  (RPC: cfm_main_screen.enroll_device)

Change-Id: Ibbd037b1528f0be3b7654d2bdc4febb9c80744af
Reviewed-on: https://chromium-review.googlesource.com/755253
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Denis Tosic <dtosic@chromium.org>

[modify] https://crrev.com/4716d50ef89450be971cf4edfa2ce8f857e4583d/server/cros/multimedia/remote_facade_factory.py

Great. I am cherry-picking the changes.
Project Member

Comment 23 by bugdroid1@chromium.org, Nov 10 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/2fc414cd8b4c21e9a1cf97572f852b1140ce4aad

commit 2fc414cd8b4c21e9a1cf97572f852b1140ce4aad
Author: Wai-Hong Tam <waihong@google.com>
Date: Fri Nov 10 17:44:51 2017

multimedia: Append the RPC name on the exception message from client

Append the RPC name on the exception message (TestFail or TestError)
from client. It is helpful with debugging. An example is like:
  FAIL: Failed to set mirrored (RPC: display.set_mirrored)

Also make other exceptions with similar messages, like:
  FAIL: Unhandled Exception: DevtoolsTargetCrashException: Devtools
  target crashed (RPC: cfm_main_screen.end_hangout_session)

If the original exception type is failed to be parsed, raise the
default one, like:
  FAIL: Unhandled Exception: Exception from client (RPC:
  cfm_main_screen.enroll_device)

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Icb5d779d994702af65af646e6cb801321e439647
Reviewed-on: https://chromium-review.googlesource.com/744522
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
(cherry picked from commit ac0eac12bb6317dc8dc9350d939d14cd23c598a0)
Reviewed-on: https://chromium-review.googlesource.com/764248
Reviewed-by: Wai-Hong Tam <waihong@google.com>
Commit-Queue: Wai-Hong Tam <waihong@google.com>
Trybot-Ready: Wai-Hong Tam <waihong@google.com>

[modify] https://crrev.com/2fc414cd8b4c21e9a1cf97572f852b1140ce4aad/server/cros/multimedia/remote_facade_factory.py

Project Member

Comment 24 by bugdroid1@chromium.org, Nov 10 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/cf52ba5bcdeff2c7d3ab644f185f423dc20bb527

commit cf52ba5bcdeff2c7d3ab644f185f423dc20bb527
Author: Wai-Hong Tam <waihong@google.com>
Date: Fri Nov 10 17:44:55 2017

multimedia: Append the RPC name on the exception message from client

Append the RPC name on the exception message (TestFail or TestError)
from client. It is helpful with debugging. An example is like:
  FAIL: Failed to set mirrored (RPC: display.set_mirrored)

Also make other exceptions with similar messages, like:
  FAIL: Unhandled Exception: DevtoolsTargetCrashException: Devtools
  target crashed (RPC: cfm_main_screen.end_hangout_session)

If the original exception type is failed to be parsed, raise the
default one, like:
  FAIL: Unhandled Exception: Exception from client (RPC:
  cfm_main_screen.enroll_device)

BUG= chromium:774737 
TEST=Ran a test using RPC and checked the exception raised.

Change-Id: Icb5d779d994702af65af646e6cb801321e439647
Reviewed-on: https://chromium-review.googlesource.com/744522
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
(cherry picked from commit ac0eac12bb6317dc8dc9350d939d14cd23c598a0)
Reviewed-on: https://chromium-review.googlesource.com/764247
Reviewed-by: Wai-Hong Tam <waihong@google.com>
Commit-Queue: Wai-Hong Tam <waihong@google.com>
Trybot-Ready: Wai-Hong Tam <waihong@google.com>

[modify] https://crrev.com/cf52ba5bcdeff2c7d3ab644f185f423dc20bb527/server/cros/multimedia/remote_facade_factory.py

Project Member

Comment 25 by bugdroid1@chromium.org, Nov 10 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/d8ce2e3dcc89cd9e9c001d2a4f8983d23446ab94

commit d8ce2e3dcc89cd9e9c001d2a4f8983d23446ab94
Author: Wai-Hong Tam <waihong@google.com>
Date: Fri Nov 10 18:10:00 2017

multimedia: Parse the exception message to find the exception keyword

Some exception adds more debug info to its message. Checking the
last line doesn't always correct. Have to use a regular expression
to search the keyword one line by one line from the last.

BUG= chromium:774737 
TEST=Ran enterprise_CFM_SessionStress and got the error:
Unhandled Exception: TimeoutException: Timed out while waiting 20s for
IsJavaScriptExpressionTrue. (RPC: cfm_main_screen.enroll_device)
It used to get a wrong error:
Unhandled Exception: Console output:  (RPC: cfm_main_screen.enroll_device)

Change-Id: Ibbd037b1528f0be3b7654d2bdc4febb9c80744af
Reviewed-on: https://chromium-review.googlesource.com/755253
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Denis Tosic <dtosic@chromium.org>
(cherry picked from commit 4716d50ef89450be971cf4edfa2ce8f857e4583d)
Reviewed-on: https://chromium-review.googlesource.com/764251
Reviewed-by: Wai-Hong Tam <waihong@google.com>
Commit-Queue: Wai-Hong Tam <waihong@google.com>
Trybot-Ready: Wai-Hong Tam <waihong@google.com>

[modify] https://crrev.com/d8ce2e3dcc89cd9e9c001d2a4f8983d23446ab94/server/cros/multimedia/remote_facade_factory.py

Project Member

Comment 26 by bugdroid1@chromium.org, Nov 10 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/f4ee87025d018a3b82206c592957d9d3e880af9c

commit f4ee87025d018a3b82206c592957d9d3e880af9c
Author: Wai-Hong Tam <waihong@google.com>
Date: Fri Nov 10 18:10:04 2017

multimedia: Parse the exception message to find the exception keyword

Some exception adds more debug info to its message. Checking the
last line doesn't always correct. Have to use a regular expression
to search the keyword one line by one line from the last.

BUG= chromium:774737 
TEST=Ran enterprise_CFM_SessionStress and got the error:
Unhandled Exception: TimeoutException: Timed out while waiting 20s for
IsJavaScriptExpressionTrue. (RPC: cfm_main_screen.enroll_device)
It used to get a wrong error:
Unhandled Exception: Console output:  (RPC: cfm_main_screen.enroll_device)

Change-Id: Ibbd037b1528f0be3b7654d2bdc4febb9c80744af
Reviewed-on: https://chromium-review.googlesource.com/755253
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Denis Tosic <dtosic@chromium.org>
(cherry picked from commit 4716d50ef89450be971cf4edfa2ce8f857e4583d)
Reviewed-on: https://chromium-review.googlesource.com/764250
Reviewed-by: Wai-Hong Tam <waihong@google.com>
Commit-Queue: Wai-Hong Tam <waihong@google.com>
Trybot-Ready: Wai-Hong Tam <waihong@google.com>

[modify] https://crrev.com/f4ee87025d018a3b82206c592957d9d3e880af9c/server/cros/multimedia/remote_facade_factory.py

Status: Fixed (was: Started)
Status: Verified (was: Fixed)

Sign in to add a comment