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

Issue 753853 link

Starred by 1 user
Status: Archived
Owner:
█ mzhuo@chromium.org
Last visit > 30 days ago
Closed: Aug 2017
Cc:
ar...@chromium.org
kerl@google.com
█ dtosic@chromium.org
harpreet@chromium.org
█ katierh@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Chrome crash when running telemetry api to start meeting and get_device with PTZ camera connected

Project Member Reported by mzhuo@chromium.org, Aug 9 2017 
Enroll device in crosprqa4.com, use telemetry api to query device or mute/unmute device. It fails. 

Note: is able to use telemetry API to join meeting or start meeting.

------------------------------------------------------------------
1. Version
Google Chrome Version   61.0.3163.38
Platform Version        9765.21.0 (Official Build) dev-channel guado test
Firmware Version        Google_Guado.6301.108.4
Boot Mode       Dev

2. log
========

11:32:19 INFO | autoserv| FAIL	enterprise_CFM_CameraMuteStress	enterprise_CFM_CameraMuteStress	timestamp=1502296339	localtime=Aug 09 11:32:19	Unhandled Exception: RPC error: cfm.mute_mic
11:32:19 INFO | autoserv| Traceback (most recent call last):
11:32:19 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
11:32:19 INFO | autoserv| return func(*params)
11:32:19 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 260, in mute_mic
11:32:19 INFO | autoserv| self.cfmApi.mute_mic()
11:32:19 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 142, in mute_mic
11:32:19 INFO | autoserv| self._execute_telemetry_command('setMicMuted(true)')
11:32:19 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 19, in _execute_telemetry_command
11:32:19 INFO | autoserv| 'window.%s.%s' % (TELEMETRY_API, command))
11:32:19 INFO | autoserv| 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
11:32:19 INFO | autoserv| return func(*args, **kwargs)
11:32:19 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 144, in ExecuteJavaScript
11:32:19 INFO | autoserv| return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
11:32:19 INFO | autoserv| 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
11:32:19 INFO | autoserv| return func(*args, **kwargs)
11:32:19 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
11:32:19 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
11:32:19 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 210, in ExecuteJavaScript
11:32:19 INFO | autoserv| self._runtime.Execute(statement, context_id, timeout)
11:32:19 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 21, in Execute
11:32:19 INFO | autoserv| self.Evaluate(expr + '; 0;', context_id, timeout)
11:32:19 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
11:32:19 INFO | autoserv| description=details.get('exception', {}).get('description'))
11:32:19 INFO | autoserv| EvaluateException: UncaughtTypeError:
11:32:19 INFO | autoserv| TypeError: Cannot read property 'setMicMuted' of undefined
11:32:19 INFO | autoserv| at <anonymous>:1:23
11:32:19 INFO | autoserv| 
11:32:19 INFO | autoserv| Traceback (most recent call last):

1:50:26 INFO | autoserv| Client complete
11:50:26 INFO | autoserv| The test failed with the following exception
11:50:26 INFO | autoserv| Traceback (most recent call last):
11:50:26 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 610, in _exec
11:50:26 INFO | autoserv| _call_test_function(self.execute, *p_args, **p_dargs)
11:50:26 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 824, in _call_test_function
11:50:26 INFO | autoserv| raise error.UnhandledTestFail(e)
11:50:26 INFO | autoserv| UnhandledTestFail: Unhandled Exception: RPC error: cfm.mute_camera
11:50:26 INFO | autoserv| Traceback (most recent call last):
11:50:26 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
11:50:26 INFO | autoserv| return func(*params)
11:50:26 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 383, in mute_camera
11:50:26 INFO | autoserv| self.cfmApi.mute_camera()
11:50:26 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 240, in mute_camera
11:50:26 INFO | autoserv| self._execute_telemetry_command('setCameraMuted(true)')
11:50:26 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 19, in _execute_telemetry_command
11:50:26 INFO | autoserv| 'window.%s.%s' % (TELEMETRY_API, command))
11:50:26 INFO | autoserv| 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
11:50:26 INFO | autoserv| return func(*args, **kwargs)
11:50:26 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 144, in ExecuteJavaScript
11:50:26 INFO | autoserv| return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
11:50:26 INFO | autoserv| 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
11:50:26 INFO | autoserv| return func(*args, **kwargs)
11:50:26 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
11:50:26 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
11:50:26 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 210, in ExecuteJavaScript
11:50:26 INFO | autoserv| self._runtime.Execute(statement, context_id, timeout)
11:50:26 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 21, in Execute
11:50:26 INFO | autoserv| self.Evaluate(expr + '; 0;', context_id, timeout)
11:50:26 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
11:50:26 INFO | autoserv| description=details.get('exception', {}).get('description'))
11:50:26 INFO | autoserv| EvaluateException: UncaughtTypeError:
11:50:26 INFO | autoserv| TypeError: Cannot read property 'setCameraMuted' of undefined
11:50:26 INFO | autoserv| at <anonymous>:1:23

Comment 1 by mzhuo@chromium.org, Aug 9 2017

Cc: dtosic@chromium.org

Comment 2 by mzhuo@chromium.org, Aug 9 2017

Components: Tests>Telemetry

Comment 3 by harpreet@chromium.org, Aug 9 2017

Cc: -dtosic@chromium.org kerl@google.com
Owner: dtosic@chromium.org

Comment 4 by dtosic@chromium.org, Aug 10 2017 

Mute/Unmuting can only be invoked in-call, not on the landing page (and from a testing perspective it's the in-call functionality that matters). Can someone c/p the test code to verify if this is done in-call or on the landing page (I assume enterprise_CFM_CameraMuteStress is not submitted yet)?

There is only a minor set of functions available on the landing page (start, join, isInMeeting) - e.g. a real user can't mute/unmute the mic from the landing page at all.

I do agree get_mic_devices should work though (and other getters) so please open a buganizer bug for such APIs - if they do exist just ping them/update priority :)

Comment 5 by dtosic@chromium.org, Aug 10 2017

Cc: dtosic@chromium.org
Owner: mzhuo@chromium.org

Comment 6 by mzhuo@chromium.org, Aug 10 2017 

dtosic@, I run mute/unmute camera and microphone after joining meeting. 
Not only mute/unmute does not work, get_mic_device also failed. 
Looks like if my device is running meeting mode, there is problem. 

automation script log:
=====================
7:36:59 INFO | autoserv| join thor meeting  <<<<<<<<<<<<<<
17:37:07 INFO | autoserv| meeting joined      <<<<<<<<<<<<<<
17:37:12 INFO | autoserv| mute unmute camera   <<<<<<<<
17:37:12 INFO | autoserv| start mute/umute camera  <<<<<<
17:37:12 INFO | autoserv| Failed RPC 'cfm.mute_camera'((), {}) with status [<type 'exceptions.Exception'>].
17:37:12 INFO | autoserv| Executing /tmp/sysinfo/autoserv-lzchsH/bin/autotest /tmp/sysinfo/autoserv-lzchsH/control phase 0
17:37:13 INFO | autoserv| Entered autotestd_monitor.
17:37:13 INFO | autoserv| Finished launching tail subprocesses.
17:37:13 INFO | autoserv| Finished waiting on autotestd to start.
17:37:13 INFO | autoserv| START	----	----	timestamp=1502404632	localtime=Aug 10 17:37:12
17:37:13 INFO | autoserv| GOOD	----	sysinfo.iteration.after	timestamp=1502404632	localtime=Aug 10 17:37:12
17:37:13 INFO | autoserv| END GOOD	----	----	timestamp=1502404632	localtime=Aug 10 17:37:12
17:37:13 INFO | autoserv| Got lock of exit_code_file.
17:37:13 INFO | autoserv| Released lock of exit_code_file and closed it.
17:37:15 INFO | autoserv| Client complete
17:37:16 INFO | autoserv| The test failed with the following exception
17:37:16 INFO | autoserv| Traceback (most recent call last):
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 610, in _exec
17:37:16 INFO | autoserv| _call_test_function(self.execute, *p_args, **p_dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 824, in _call_test_function
17:37:16 INFO | autoserv| raise error.UnhandledTestFail(e)
17:37:16 INFO | autoserv| UnhandledTestFail: Unhandled Exception: RPC error: cfm.mute_camera
17:37:16 INFO | autoserv| Traceback (most recent call last):
17:37:16 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
17:37:16 INFO | autoserv| return func(*params)
17:37:16 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 385, in mute_camera
17:37:16 INFO | autoserv| self.cfmApi.mute_camera()
17:37:16 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 240, in mute_camera
17:37:16 INFO | autoserv| self._execute_telemetry_command('setCameraMuted(true)')
17:37:16 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 19, in _execute_telemetry_command
17:37:16 INFO | autoserv| 'window.%s.%s' % (TELEMETRY_API, command))
17:37:16 INFO | autoserv| 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
17:37:16 INFO | autoserv| return func(*args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 144, in ExecuteJavaScript
17:37:16 INFO | autoserv| return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
17:37:16 INFO | autoserv| 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
17:37:16 INFO | autoserv| return func(*args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
17:37:16 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 210, in ExecuteJavaScript
17:37:16 INFO | autoserv| self._runtime.Execute(statement, context_id, timeout)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 21, in Execute
17:37:16 INFO | autoserv| self.Evaluate(expr + '; 0;', context_id, timeout)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
17:37:16 INFO | autoserv| description=details.get('exception', {}).get('description'))
17:37:16 INFO | autoserv| EvaluateException: UncaughtTypeError:
17:37:16 INFO | autoserv| TypeError: Cannot read property 'setCameraMuted' of undefined
17:37:16 INFO | autoserv| at <anonymous>:1:23
17:37:16 INFO | autoserv| 
17:37:16 INFO | autoserv| Traceback (most recent call last):
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 818, in _call_test_function
17:37:16 INFO | autoserv| return func(*args, **dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 471, in execute
17:37:16 INFO | autoserv| dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 348, in _call_run_once_with_retry
17:37:16 INFO | autoserv| postprocess_profiled_run, args, dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 381, in _call_run_once
17:37:16 INFO | autoserv| self.run_once(*args, **dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 311, in run_once
17:37:16 INFO | autoserv| self._mute_unmute_camera(0)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 82, in _mute_unmute_camera
17:37:16 INFO | autoserv| self.cfm_facade.mute_camera()
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/cros/multimedia/cfm_facade_adapter.py", line 295, in mute_camera
17:37:16 INFO | autoserv| self._cfm_proxy.mute_camera()
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/cros/multimedia/remote_facade_factory.py", line 52, in __call__
17:37:16 INFO | autoserv| return self.__call_method(self.__name, *args, **dargs)
17:37:16 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/cros/multimedia/remote_facade_factory.py", line 113, in __call_proxy
17:37:16 INFO | autoserv| raise Exception('RPC error: %s\n%s' % (name, value))
17:37:16 INFO | autoserv| Exception: RPC error: cfm.mute_camera
17:37:16 INFO | autoserv| Traceback (most recent call last):
17:37:16 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
17:37:16 INFO | autoserv| return func(*params)
17:37:16 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 385, in mute_camera
17:37:16 INFO | autoserv| self.cfmApi.mute_camera()
17:37:16 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 240, in mute_camera
17:37:16 INFO | autoserv| self._execute_telemetry_command('setCameraMuted(true)')
17:37:16 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 19, in _execute_telemetry_command
17:37:16 INFO | autoserv| 'window.%s.%s' % (TELEMETRY_API, command))
17:37:16 INFO | autoserv| 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
17:37:16 INFO | autoserv| return func(*args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 144, in ExecuteJavaScript
17:37:16 INFO | autoserv| return self._inspector_backend.ExecuteJavaScript(*args, **kwargs)
17:37:16 INFO | autoserv| 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
17:37:16 INFO | autoserv| return func(*args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
17:37:16 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 210, in ExecuteJavaScript
17:37:16 INFO | autoserv| self._runtime.Execute(statement, context_id, timeout)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 21, in Execute
17:37:16 INFO | autoserv| self.Evaluate(expr + '; 0;', context_id, timeout)
17:37:16 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
17:37:16 INFO | autoserv| description=details.get('exception', {}).get('description'))
17:37:16 INFO | autoserv| EvaluateException: UncaughtTypeError:
17:37:16 INFO | autoserv| TypeError: Cannot read property 'setCameraMuted' of undefined
17:37:16 INFO | autoserv| at <anonymous>:1:23
17:37:16 INFO | autoserv| 
17:37:16 INFO | autoserv| 
17:37:17 INFO | autoserv| Executing /tmp/sysinfo/autoserv-lzchsH/bin/autotest /tmp/sysinfo/autoserv-lzchsH/control phase 0
17:37:17 INFO | autoserv| Entered autotestd_monitor.
17:37:17 INFO | autoserv| Finished launching tail subprocesses.
17:37:17 INFO | autoserv| Finished waiting on autotestd to start.
17:37:17 INFO | autoserv| START	----	----	timestamp=1502404637	localtime=Aug 10 17:37:17
17:37:20 INFO | autoserv| GOOD	----	sysinfo.after	timestamp=1502404639	localtime=Aug 10 17:37:19
17:37:20 INFO | autoserv| END GOOD	----	----	timestamp=1502404639	localtime=Aug 10 17:37:19
17:37:20 INFO | autoserv| Got lock of exit_code_file.
17:37:20 INFO | autoserv| Released lock of exit_code_file and closed it.
17:37:22 INFO | autoserv| Killing child processes.
17:37:22 INFO | autoserv| Client complete

Comment 7 by dtosic@chromium.org, Aug 11 2017

Cc: ar...@chromium.org

Comment 8 by dtosic@chromium.org, Aug 11 2017 

I can not repro the issue. Can you add the cl/ for your test so we can take a look at the code? Are failures being seen anywhere else?

Comment 9 by dtosic@chromium.org, Aug 11 2017 

Didi you invoke wait_for_meetings_in_call_page() in your test?

Comment 10 by mzhuo@chromium.org, Aug 11 2017 

dtosic@, I did not add wait_for_meetings_in_call_page() in my script. After joining meeting, script will sleep for a few seconds, and start mute camera or speaker. 

For get_mic_device call after wait_telmetry returns, the call is made to check camera, or speaker, or microphone.

Comment 11 by mzhuo@chromium.org, Aug 11 2017 

BTW, The same script works for device in hangout mode.

Comment 12 by dtosic@chromium.org, Aug 14 2017 

Please provide the test code, without it we're just guessing around here.

Re sleep in script: do NOT use sleep, it is not reliable. Use wait_for_meetings_in_call_page() instead. Note that hangout and meet are different SW products.

Comment 13 by mzhuo@chromium.org, Aug 14 2017 

 dtosic@, I got another error. It is "RPC error: cfm.get_preferred_camera" exception when running cfm.get_preferred_camera.

18:25:04 INFO | autoserv| Failed RPC 'cfm.get_preferred_camera'((), {}) with status [<type 'exceptions.Exception'>].
18:25:04 INFO | autoserv| Exception : RPC error: cfm.get_preferred_camera  <<<<<<<

autotest log:
============
18:24:53 INFO | autoserv| Setup the connection to RPC server, with retries...
18:24:53 INFO | autoserv| Waiting 90 seconds for XMLRPC server to start.
18:24:53 INFO | autoserv| <class 'socket.error'>([Errno 111] Connection refused)
18:24:53 INFO | autoserv| Retrying in 1.408381 seconds...
18:24:54 INFO | autoserv| XMLRPC server started successfully.
18:24:56 INFO | autoserv| wait for telemetry  <==========
18:25:04 INFO | autoserv| thor meeting joined <<<<<<<<<< it is printed right after join meeting
18:25:04 INFO | autoserv| wait for meeting in call page <====== before query device, check whether meeting in call page
18:25:04 INFO | autoserv| meeting is in call page  
18:25:04 INFO | autoserv| Failed RPC 'cfm.get_preferred_camera'((), {}) with status [<type 'exceptions.Exception'>].
18:25:04 INFO | autoserv| Exception : RPC error: cfm.get_preferred_camera  <<<<<<<<<<<
18:25:04 INFO | autoserv| Traceback (most recent call last):
18:25:04 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
18:25:04 INFO | autoserv| return func(*params)
18:25:04 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 364, in get_preferred_camera
18:25:04 INFO | autoserv| return self.cfmApi.get_preferred_camera()
18:25:04 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 219, in get_preferred_camera
18:25:04 INFO | autoserv| return self._evaluate_telemetry_command('getPreferredVideoInDevice()')
18:25:04 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 23, in _evaluate_telemetry_command
18:25:04 INFO | autoserv| 'window.%s.%s' % (TELEMETRY_API, command))
18:25:04 INFO | autoserv| 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
18:25:04 INFO | autoserv| return func(*args, **kwargs)
18:25:04 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 167, in EvaluateJavaScript
18:25:04 INFO | autoserv| return self._inspector_backend.EvaluateJavaScript(*args, **kwargs)
18:25:04 INFO | autoserv| 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
18:25:04 INFO | autoserv| return func(*args, **kwargs)
18:25:04 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 237, in EvaluateJavaScript
18:25:04 INFO | autoserv| return self._EvaluateJavaScript(expression, context_id, timeout)
18:25:04 INFO | autoserv| 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
18:25:04 INFO | autoserv| return func(*args, **kwargs)
18:25:04 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
18:25:04 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
18:25:04 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 501, in _EvaluateJavaScript
18:25:04 INFO | autoserv| return self._runtime.Evaluate(expression, context_id, timeout)
18:25:04 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
18:25:04 INFO | autoserv| description=details.get('exception', {}).get('description'))
18:25:04 INFO | autoserv| EvaluateException: UncaughtTypeError:
18:25:04 INFO | autoserv| TypeError: window.hrTelemetryApi.getPreferredVideoInDevice is not a function  <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
18:25:04 INFO | autoserv| at <anonymous>:1:23


from Chrome log after meeting join after 16:25:03 there are 3 lines:
[2182:2182:0814/162517.220937:INFO:remote_commands_invalidator.cc(45)] Shutdown RemoteCommandsInvalidator.
[2182:2182:0814/162517.221023:INFO:remote_commands_invalidator.cc(68)] Stopping RemoteCommandsInvalidator.
[2182:2182:0814/162517.221063:INFO:remote_commands_invalidator.cc(167)] Unregister RemoteCommandsInvalidator.

Does it indicate something wrong?

chrome log
===================================
[2182:2182:0814/162517.336328:WARNING:pref_notifier_impl.cc(28)] Init observer found at shutdown.

[1:19:0814/162503.127391:WARNING:PushPullFIFO.cpp(182)] PushPullFIFO: underflow while pulling (underflowCount=1, availableFrames=0, requestedFrames=512, fifoLength=8192)
[1:21:0814/162503.170789:WARNING:PushPullFIFO.cpp(182)] PushPullFIFO: underflow while pulling (underflowCount=1, availableFrames=0, requestedFrames=512, fifoLength=8192)
[1:23:0814/162503.206928:ERROR:adm_helpers.cc(62)] Failed to query stereo recording.
[1:23:0814/162503.207591:WARNING:delay_based_bwe.cc(278)] BWE Setting start bitrate to: 300000
[1:22:0814/162503.208888:WARNING:mediasession.cc(373)] Duplicate id found. Reassigning from 104 to 127
[1:22:0814/162503.209021:WARNING:mediasession.cc(373)] Duplicate id found. Reassigning from 103 to 125
[1:23:0814/162503.338989:WARNING:stunport.cc(384)] Jingle:Port[0x26fc0165e400:audio:1:0:local:Net[any:0:0:0:x:x:x:x:x/0:Unknown]]: StunPort: stun host lookup received error 0
[1:23:0814/162503.339159:WARNING:stunport.cc(384)] Jingle:Port[0x26fc0165e400:audio:1:0:local:Net[any:0:0:0:x:x:x:x:x/0:Unknown]]: StunPort: stun host lookup received error 0
[1:23:0814/162503.341136:WARNING:stunport.cc(384)] Jingle:Port[0x26fc0165e400:audio:1:0:local:Net[any:0:0:0:x:x:x:x:x/0:Unknown]]: StunPort: stun host lookup received error 0
[1:23:0814/162503.358611:WARNING:basicportallocator.cc(770)] Discarding candidate because port is already done gathering.
[1:23:0814/162503.387471:WARNING:stunport.cc(384)] Jingle:Port[0x26fc0165e400:audio:1:0:local:Net[any:0:0:0:x:x:x:x:x/0:Unknown]]: StunPort: stun host lookup received error 0
[1:23:0814/162503.388051:WARNING:stunport.cc(384)] Jingle:Port[0x26fc0165e400:audio:1:0:local:Net[any:0:0:0:x:x:x:x:x/0:Unknown]]: StunPort: stun host lookup received error 0
[2182:2182:0814/162517.220937:INFO:remote_commands_invalidator.cc(45)] Shutdown RemoteCommandsInvalidator.
[2182:2182:0814/162517.221023:INFO:remote_commands_invalidator.cc(68)] Stopping RemoteCommandsInvalidator.
[2182:2182:0814/162517.221063:INFO:remote_commands_invalidator.cc(167)] Unregister RemoteCommandsInvalidator.
[2182:2182:0814/162517.336328:WARNING:pref_notifier_impl.cc(28)] Init observer found at shutdown.

def _peripherals_sanity_test(self):
        """Checks for connected peripherals."""
        try:
            logging.info('wait for meeting in call page')
            self.cfm_facade.wait_for_meetings_in_call_page()
            logging.info('meeting is in call page')
            if not self.cfm_facade.get_mic_devices():
               FAILED_TEST_LIST.append('No mic detected')
            if not self.cfm_facade.get_speaker_devices():
               FAILED_TEST_LIST.append('No speaker detected')
            if not self.cfm_facade.get_camera_devices():
               FAILED_TEST_LIST.append('No camera detected')
            if not self.cfm_facade.get_preferred_mic():
               FAILED_TEST_LIST.append('No preferred mic')
            if not self.cfm_facade.get_preferred_speaker():
               FAILED_TEST_LIST.append('No preferred speaker')
            if not self.cfm_facade.get_preferred_camera():
               FAILED_TEST_LIST.append('No preferred camera')
        except Exception as e:
           logging.info('Exception : %s', str(e))       <<<<<<<<<<<<<<<<<<<<
           raise error.TestFail(str(e))

Comment 14 by mzhuo@chromium.org, Aug 14 2017 

@dtosic, this is the part of code which does enrollment, start meeting, and check peripherals. 
   
        self.usb_data = self._cmd_usb_devices()
        if not self.usb_data:
            raise error.TestFail('No usb devices found on DUT.')
        else:
            self.usb_device_list = self._check_peripherals()
            self._kernel_usb_sanity_test()

        factory = remote_facade_factory.RemoteFacadeFactory(
                              host, no_chrome=True)
        self.cfm_facade = factory.create_cfm_facade()
        if clear:
           tpm_utils.ClearTPMOwnerRequest(self.client)

        if self.client.servo:
            self.client.servo.switch_usbkey('dut')
            self.client.servo.set('usb_mux_sel3', 'dut_sees_usbkey')
            time.sleep(SHORT_TIMEOUT)
            self._set_hub_power(True)

        try:
            if clear:
               self.cfm_facade.enroll_device()
               if not self.hangout:
                   self.client.reboot()
               self.cfm_facade.skip_oobe_after_onrollment()
            self.cfm_facade.restart_chrome_for_cfm()
            if self.hangout:
                logging.info('wait for  telemetry ')
                self.cfm_facade.wait_for_telemetry_commands()
            else:
                logging.info('wait for telemetry')
                self.cfm_facade.wait_for_meetings_telemetry_commands()
        except Exception as e:
            raise error.TestFail(str(e))

        failcase = 0
        if self.hangout:
            self.cfm_facade.start_new_hangout_session(self.hangout)
            logging.info('hangout meeting joined')
        else:
            self.cfm_facade.join_meeting_session(self.meet)
            logging.info('thor meeting joined')
        self._peripherals_sanity_test()

Comment 15 by harpreet@chromium.org, Aug 15 2017 

Min, I cleaned up some of the enrollment code in https://chromium-review.googlesource.com/c/612656/ 

Your code in #14 looks ok but you don't need to reboot from within the test anymore. Sync your repo and use the following:

        try:
            if clear:
                self.cfm_facade.enroll_device()
                self.cfm_facade.skip_oobe_after_enrollment()
            if not clear: <<<<<<<<<<< only need to restart the browser if you are no doing new enrollment.
                self.cfm_facade.restart_chrome_for_cfm()
            if self.hangout:
                logging.info('wait for  telemetry ')
                self.cfm_facade.wait_for_hangouts_telemetry_commands()
            else:
                logging.info('wait for telemetry')
                self.cfm_facade.wait_for_meetings_telemetry_commands()
        except Exception as e:
            raise error.TestFail(str(e))



Regarding #13, did you manually check/confirm with dev tools to see if hrTelemetryApi.getPreferredVideoInDevice is available on meeting in call page?

Comment 16 by mzhuo@chromium.org, Aug 15 2017 

Answer to #15, 
I did not maunally check/confirm with dev tools to see if hrTelemetryApi.getPreferredVideoInDevice is available on meeting in call page. 
I make call to check. 
            logging.info('wait for meeting in call page')
            self.cfm_facade.wait_for_meetings_in_call_page()
            logging.info('meeting is in call page')

Comment 17 by mzhuo@chromium.org, Aug 15 2017 

running script and hit the same issue. This time we clearly see chrome crash. 
We need to find out why chrome crash. 
However, for all cases where autotest script fails which complains something like "TypeError: window.hrTelemetryApi.******* is not a function", chrome crash is not observed for all cases. But chrome crash happens quite many times. 


This is kernel log on Guado which shows session_mgr send 
2017-08-15T09:08:35.415978-07:00 INFO session_manager[26417]: [INFO:system_utils_impl.cc(111)] Sending 15 to 26454 as 1000<=============

===========================================================
2017-08-15T09:08:34.140997-07:00 NOTICE ag[29746]: autotest server[stack::check_rsync|run|wrapper] -> ssh_run(rsync --version)
2017-08-15T09:08:34.267838-07:00 NOTICE ag[29751]: autotest server[stack::_install_using_send_file|run|wrapper] -> ssh_run(mkdir -p '/usr/local/autotest/site_tests';touch '/usr/local/autotest/site_tests'/__init__.py;mkdir -p '/usr/local/autotest/tests';touch '/usr/local/autotest/tests'/__init__.py;mkdir -p '/usr/local/autotest/packages';touch '/usr/local/autotest/packages'/__init__.py;mkdir -p '/usr/local/autotest/deps';touch '/usr/local/autotest/deps'/__init__.py;mkdir -p '/usr/local/autotest/profilers';touch '/usr/local/autotest/profilers'/__init__.py)
2017-08-15T09:08:34.387301-07:00 NOTICE ag[29765]: autotest server[stack::run_background|run|wrapper] -> ssh_run(( cd /usr/local/autotest/cros/multimedia; ./multimedia_xmlrpc_server.py > /var/log/multimedia_xmlrpc_server.log 2>&1 ) </dev/null >/dev/null 2>&1 & echo -n $!)
2017-08-15T09:08:34.536100-07:00 INFO sshd[29768]: Accepted publickey for root from 100.123.202.88 port 47026 ssh2: RSA SHA256:Fp1qWjFLyK1cTpiI5rdk7iEJwoK9lcnYAgbQtGC3jzU
2017-08-15T09:08:34.728266-07:00 WARNING minijail0[24509]: libminijail[24509]: child process 24511 received signal 15
2017-08-15T09:08:34.728702-07:00 WARNING kernel: [104302.744267] init: cras main process (24509) terminated with status 143
2017-08-15T09:08:34.728768-07:00 INFO bluetoothd[1210]: Endpoint unregistered: sender=:1.419 path=/org/chromium/Cras/Bluetooth/A2DPSource
2017-08-15T09:08:34.728802-07:00 INFO bluetoothd[1210]: Player unregistered: sender=:1.419 path=/org/chromium/Cras/Bluetooth/DefaultPlayer
2017-08-15T09:08:34.739525-07:00 ERR cras_server[29784]: no ini file /etc/cras/dsp.ini
2017-08-15T09:08:34.739542-07:00 ERR cras_server[29784]: cannot create dsp ini
2017-08-15T09:08:35.168971-07:00 ERR cras_server[29784]: USB card: vendor:18d1, product:8001, serial num:GATRB17130010, checksum:31a5800b
2017-08-15T09:08:35.415967-07:00 INFO session_manager[26417]: [INFO:browser_job.cc(157)] Terminating process:
2017-08-15T09:08:35.415978-07:00 INFO session_manager[26417]: [INFO:system_utils_impl.cc(111)] Sending 15 to 26454 as 1000
2017-08-15T09:08:35.434368-07:00 ERR chrome[26454]: [26454:26454:0815/090835.434315:INFO:remote_commands_invalidator.cc(45)] Shutdown RemoteCommandsInvalidator.
2017-08-15T09:08:35.434530-07:00 ERR chrome[26454]: [26454:26454:0815/090835.434512:INFO:remote_commands_invalidator.cc(68)] Stopping RemoteCommandsInvalidator.
2017-08-15T09:08:35.434610-07:00 ERR chrome[26454]: [26454:26454:0815/090835.434590:INFO:remote_commands_invalidator.cc(167)] Unregister RemoteCommandsInvalidator.
2017-08-15T09:08:35.582140-07:00 INFO bluetoothd[1210]: Endpoint registered: sender=:1.468 path=/org/chromium/Cras/Bluetooth/A2DPSource
2017-08-15T09:08:35.582353-07:00 INFO bluetoothd[1210]: Player registered: sender=:1.468 path=/org/chromium/Cras/Bluetooth/DefaultPlayer
2017-08-15T09:08:35.670170-07:00 INFO session_manager[26417]: [INFO:session_manager_service.cc(464)] SessionManagerService quitting run loop
2017-08-15T09:08:35.670249-07:00 INFO session_manager[26417]: [INFO:session_manager_service.cc(206)] SessionManagerService exiting
2017-08-15T09:08:35.703394-07:00 INFO chapsd[854]: Token at /home/root/fc952d099e4712af06544d9d9d438559676cb7a8/chaps has been removed from slot 1
2017-08-15T09:08:35.733737-07:00 INFO chapsd[854]: Unloaded keys for slot 1
2017-08-15T09:08:35.734570-07:00 INFO kernel: [104303.750156] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2017-08-15T09:08:35.807890-07:00 WARNING chapsd[854]: Unload Token event received for unknown path: /home/root/fc952d099e4712af06544d9d9d438559676cb7a8/chaps
2017-08-15T09:08:35.861242-07:00 ERR imageloader[29927]: Failed to read latest-version file.
2017-08-15T09:08:35.861280-07:00 ERR imageloader[29927]: Failed to verify and mount component.
2017-08-15T09:08:35.877593-07:00 WARNING kernel: [104303.893591] init: imageloader main process (29927) terminated with status 1
2017-08-15T09:08:35.916884-07:00 WARNING session_manager[30026]: [WARNING:chrome_setup.cc(85)] Could not find both paths: /usr/share/chromeos-assets/wallpaper/oem_large.jpg and /usr/share/chromeos-assets/wallpaper/oem_small.jpg
=================================

Autotest script:
11:08:47 INFO | autoserv| thor meeting joined
11:08:47 INFO | autoserv| Failed RPC 'cfm.get_preferred_speaker'((), {}) with status [<type 'exceptions.Exception'>].
11:08:48 INFO | autoserv| Executing /tmp/sysinfo/autoserv-ssozW3/bin/autotest /tmp/sysinfo/autoserv-ssozW3/control phase 0
11:08:48 INFO | autoserv| Entered autotestd_monitor.

11:09:02 INFO | autoserv| Trying to generate stack trace locally for /tmp/test_that_results_1F3zAJ/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170815.090859.30167.dmp
11:09:02 INFO | autoserv| symbol_dir: /mnt/host/source/src/third_party/autotest/files/server/../../../lib/debug
11:09:02 INFO | autoserv| Generated stack trace for dump /tmp/test_that_results_1F3zAJ/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170815.090859.30167.dmp
11:09:02 INFO | autoserv| INFO	----	----	timestamp=1502813342	localtime=Aug 15 11:09:02	Start crashcollection record
11:09:02 INFO | autoserv| INFO	----	New Crash Dump	timestamp=1502813342	localtime=Aug 15 11:09:02	/tmp/test_that_results_1F3zAJ/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170815.090859.30167.dmp
11:09:02 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502813342	localtime=Aug 15 11:09:02	/var/spool/crash/chrome.20170815.090859.30167.dmp
11:09:02 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502813342	localtime=Aug 15 11:09:02	/var/spool/crash/chrome.20170815.090859.30167.log
11:09:02 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502813342	localtime=Aug 15 11:09:02	/var/spool/crash/chrome.20170815.090859.30167.meta
11:09:02 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502813342	localtime=Aug 15 11:09:02	/var/spool/crash/chrome.20170815.090859.30167.core

Comment 18 by mzhuo@chromium.org, Aug 15 2017 

Another script failure caused by chrome crash. Log
7:35:47 INFO | autoserv| tko parser:       return self._runtime.Evaluate(expression, context_id, timeout)
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:       description=details.get('exception', {}).get('description'))
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:   EvaluateException: UncaughtTypeError:
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:   TypeError: window.hrTelemetryApi.getPreferredAudioInDevice is not a function
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:       at <anonymous>:1:23
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser:
17:35:47 INFO | autoserv| 
17:35:47 INFO | autoserv| tko parser: ---------------------------------
17:35:47 INFO | autoserv| tko parser: parsing test enterprise_CFM_CameraMuteStress enterprise_CFM_CameraMuteStress
17:35:47 INFO | autoserv| tko parser: ADD: FAIL
17:35:47 INFO | autoserv| Subdir: enterprise_CFM_CameraMuteStress
17:35:47 INFO | autoserv| Testname: enterprise_CFM_CameraMuteStress
17:35:47 INFO | autoserv| Unhandled Exception: RPC error: cfm.get_preferred_mic
17:35:47 INFO | autoserv| tko parser: parsing test ---- SERVER_JOB
17:35:47 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_LAa9A0ssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
17:35:48 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_0EpIEZssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.dmp...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.dmp...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.meta...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.meta...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.core...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.core...
17:35:49 INFO | autoserv| Collection of /var/spool/crash/chrome.20170815.153546.17383.core skipped:size=476037120, collection_probability=0.1409740148
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.log...
17:35:49 INFO | autoserv| Collecting /var/spool/crash/chrome.20170815.153546.17383.log...
17:35:49 INFO | autoserv| Trying to generate stack trace locally for /tmp/test_that_results_T0fUgg/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170815.153546.17383.dmp
17:35:49 INFO | autoserv| symbol_dir: /mnt/host/source/src/third_party/autotest/files/server/../../../lib/debug

Comment 19 by mzhuo@chromium.org, Aug 15 2017

Components: -Tests>Telemetry Infra>Client>Chrome
Labels: OS-Chrome
Summary: Telemetry api for meet api is broken due to chrome crash which leads to telemetry api is not available. (was: Telemetry api for meet api is not working: get_mic_devices, mute_camera and etc)

Comment 20 by harpreet@chromium.org, Aug 15 2017 

Did you resync your code base as I suggested in the last comment?

Comment 21 by jbudorick@chromium.org, Aug 15 2017

Components: -Infra>Client>Chrome Tests>Telemetry
This looks like the original Tests>Telemetry component was more apt than an Infra>* one.

Comment 23 by mzhuo@chromium.org, Aug 16 2017 

#20, Harpreet, I did "repo sync" just now. I still see crash and telemetry api fail after joining meeting. 

* telemetry api does not fail always
* chrome crash does not happen always.
* When telemetry api fails after meeting, we do not see chrome crash every time. 

Another chrome crash + api failure
==================================
06:54:41 INFO | autoserv| wait for meeting in call page
06:54:42 INFO | autoserv| Failed RPC 'cfm.wait_for_meetings_in_call_page'((), {}) with status [<type 'exceptions.Exception'>].
06:54:42 INFO | autoserv| Exception : RPC error: cfm.wait_for_meetings_in_call_page
06:54:42 INFO | autoserv| Traceback (most recent call last):
06:54:42 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
06:54:42 INFO | autoserv| return func(*params)
06:54:42 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 148, in wait_for_meetings_in_call_page
06:54:42 INFO | autoserv| self.cfmApi.wait_for_meetings_in_call_page()
06:54:42 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 39, in wait_for_meetings_in_call_page
06:54:42 INFO | autoserv| timeout=DEFAULT_TIMEOUT)
06:54:42 INFO | autoserv| 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
06:54:42 INFO | autoserv| return func(*args, **kwargs)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 191, in WaitForJavaScriptCondition
06:54:42 INFO | autoserv| return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
06:54:42 INFO | autoserv| 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
06:54:42 INFO | autoserv| return func(*args, **kwargs)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 274, in WaitForJavaScriptCondition
06:54:42 INFO | autoserv| return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 129, in WaitFor
06:54:42 INFO | autoserv| res = condition()
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 271, in IsJavaScriptExpressionTrue
06:54:42 INFO | autoserv| return self._EvaluateJavaScript(condition, context_id, timeout)
06:54:42 INFO | autoserv| 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
06:54:42 INFO | autoserv| return func(*args, **kwargs)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
06:54:42 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 501, in _EvaluateJavaScript
06:54:42 INFO | autoserv| return self._runtime.Evaluate(expression, context_id, timeout)
06:54:42 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
06:54:42 INFO | autoserv| description=details.get('exception', {}).get('description'))
06:54:42 INFO | autoserv| EvaluateException: UncaughtTypeError:
06:54:42 INFO | autoserv| TypeError: window.hrTelemetryApi.isInMeeting is not a function
06:54:42 INFO | autoserv| at <anonymous>:1:66
06:54:42 INFO | autoserv| 
06:54:42 INFO | autoserv| Executing /tmp/sysinfo/autoserv-BZrjbK/bin/autotest /tmp/sysinfo/autoserv-BZrjbK/control phase 0
06:54:43 INFO | autoserv| Entered autotestd_monitor.
06:54:43 INFO | autoserv| Finished launching tail subprocesses.
06:54:43 INFO | autoserv| Finished waiting on autotestd to start.
06:54:43 INFO | autoserv| START	----	----	timestamp=1502884482	localtime=Aug 16 06:54:42
06:54:43 INFO | autoserv| GOOD	----	sysinfo.iteration.after	timestamp=1502884482	localtime=Aug 16 06:54:42
06:54:43 INFO | autoserv| END GOOD	----	----	timestamp=1502884482	localtime=Aug 16 06:54:42
06:54:43 INFO | autoserv| Got lock of exit_code_file.
06:54:43 INFO | autoserv| Released lock of exit_code_file and closed it.
06:54:45 INFO | autoserv| Client complete
06:54:45 INFO | autoserv| The test failed with the following exception
06:54:45 INFO | autoserv| Traceback (most recent call last):
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 610, in _exec
06:54:45 INFO | autoserv| _call_test_function(self.execute, *p_args, **p_dargs)
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 818, in _call_test_function
06:54:45 INFO | autoserv| return func(*args, **dargs)
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 471, in execute
06:54:45 INFO | autoserv| dargs)
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 348, in _call_run_once_with_retry
06:54:45 INFO | autoserv| postprocess_profiled_run, args, dargs)
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 381, in _call_run_once
06:54:45 INFO | autoserv| self.run_once(*args, **dargs)
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 437, in run_once
06:54:45 INFO | autoserv| self._peripherals_sanity_test()
06:54:45 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 353, in _peripherals_sanity_test
06:54:45 INFO | autoserv| raise error.TestFail(str(e))
06:54:45 INFO | autoserv| TestFail: RPC error: cfm.wait_for_meetings_in_call_page
06:54:45 INFO | autoserv| Traceback (most recent call last):
06:54:45 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
06:54:45 INFO | autoserv| return func(*params)
06:54:45 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 148, in wait_for_meetings_in_call_page
06:54:45 INFO | autoserv| self.cfmApi.wait_for_meetings_in_call_page()
06:54:45 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 39, in wait_for_meetings_in_call_page
06:54:45 INFO | autoserv| timeout=DEFAULT_TIMEOUT)
06:54:45 INFO | autoserv| 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
06:54:45 INFO | autoserv| return func(*args, **kwargs)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 191, in WaitForJavaScriptCondition
06:54:45 INFO | autoserv| return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
06:54:45 INFO | autoserv| 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
06:54:45 INFO | autoserv| return func(*args, **kwargs)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 274, in WaitForJavaScriptCondition
06:54:45 INFO | autoserv| return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 129, in WaitFor
06:54:45 INFO | autoserv| res = condition()
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 271, in IsJavaScriptExpressionTrue
06:54:45 INFO | autoserv| return self._EvaluateJavaScript(condition, context_id, timeout)
06:54:45 INFO | autoserv| 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
06:54:45 INFO | autoserv| return func(*args, **kwargs)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
06:54:45 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 501, in _EvaluateJavaScript
06:54:45 INFO | autoserv| return self._runtime.Evaluate(expression, context_id, timeout)
06:54:45 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
06:54:45 INFO | autoserv| description=details.get('exception', {}).get('description'))
06:54:45 INFO | autoserv| EvaluateException: UncaughtTypeError:
06:54:45 INFO | autoserv| TypeError: window.hrTelemetryApi.isInMeeting is not a function
06:54:45 INFO | autoserv| at <anonymous>:1:66
06:54:45 INFO | autoserv| 
06:54:46 INFO | autoserv| Executing /tmp/sysinfo/autoserv-BZrjbK/bin/autotest /tmp/sysinfo/autoserv-BZrjbK/control phase 0
06:54:46 INFO | autoserv| Entered autotestd_monitor.
06:54:46 INFO | autoserv| Finished launching tail subprocesses.
06:54:46 INFO | autoserv| Finished waiting on autotestd to start.
06:54:47 INFO | autoserv| START	----	----	timestamp=1502884486	localtime=Aug 16 06:54:46
06:54:47 INFO | autoserv| GOOD	----	sysinfo.after	timestamp=1502884486	localtime=Aug 16 06:54:46
06:54:47 INFO | autoserv| END GOOD	----	----	timestamp=1502884486	localtime=Aug 16 06:54:46
06:54:47 INFO | autoserv| Got lock of exit_code_file.
06:54:47 INFO | autoserv| Released lock of exit_code_file and closed it.
06:54:49 INFO | autoserv| Client complete
06:54:52 INFO | autoserv| FAIL	enterprise_CFM_CameraMuteStress	enterprise_CFM_CameraMuteStress	timestamp=1502884492	localtime=Aug 16 06:54:52	RPC error: cfm.wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| Traceback (most recent call last):
06:54:52 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
06:54:52 INFO | autoserv| return func(*params)
06:54:52 INFO | autoserv| File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 148, in wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| self.cfmApi.wait_for_meetings_in_call_page()
06:54:52 INFO | autoserv| File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 39, in wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| timeout=DEFAULT_TIMEOUT)
06:54:52 INFO | autoserv| 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
06:54:52 INFO | autoserv| return func(*args, **kwargs)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 191, in WaitForJavaScriptCondition
06:54:52 INFO | autoserv| return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
06:54:52 INFO | autoserv| 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
06:54:52 INFO | autoserv| return func(*args, **kwargs)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 274, in WaitForJavaScriptCondition
06:54:52 INFO | autoserv| return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 129, in WaitFor
06:54:52 INFO | autoserv| res = condition()
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 271, in IsJavaScriptExpressionTrue
06:54:52 INFO | autoserv| return self._EvaluateJavaScript(condition, context_id, timeout)
06:54:52 INFO | autoserv| 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
06:54:52 INFO | autoserv| return func(*args, **kwargs)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
06:54:52 INFO | autoserv| return func(inspector_backend, *args, **kwargs)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 501, in _EvaluateJavaScript
06:54:52 INFO | autoserv| return self._runtime.Evaluate(expression, context_id, timeout)
06:54:52 INFO | autoserv| File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
06:54:52 INFO | autoserv| description=details.get('exception', {}).get('description'))
06:54:52 INFO | autoserv| EvaluateException: UncaughtTypeError:
06:54:52 INFO | autoserv| TypeError: window.hrTelemetryApi.isInMeeting is not a function
06:54:52 INFO | autoserv| at <anonymous>:1:66
06:54:52 INFO | autoserv| END FAIL	enterprise_CFM_CameraMuteStress	enterprise_CFM_CameraMuteStress	timestamp=1502884492	localtime=Aug 16 06:54:52
06:54:52 INFO | autoserv| Waiting for RPC server "multimedia_xmlrpc_server" shutdown
06:54:52 INFO | autoserv| Shut down RPC server.
06:54:52 INFO | autoserv| Finished processing control file
06:54:52 INFO | autoserv| tko parser: {'drone': 'minzhuo2.svl.corp.google.com', 'user': 'autotest_system', 'job_started': 1502884447, 'hostname': '100.123.171.19', 'status_version': 1, 'experimental': 'False', 'label': 'ad_hoc_build/ad_hoc_suite/enterprise_CFM_CameraMuteStress'}
06:54:52 INFO | autoserv| tko parser: MACHINE NAME: 100.123.171.19
06:54:52 INFO | autoserv| tko parser: Unable to parse host keyval for 100.123.171.19
06:54:52 INFO | autoserv| tko parser: MACHINE GROUP:
06:54:52 INFO | autoserv| tko parser: parsing partial test ---- SERVER_JOB
06:54:52 INFO | autoserv| tko parser: parsing partial test enterprise_CFM_CameraMuteStress enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| tko parser: RUNNING: RUNNING
06:54:52 INFO | autoserv| Subdir: enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| Testname: enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser: update RUNNING reason: RPC error: cfm.wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| tko parser: The following lines were ignored:
06:54:52 INFO | autoserv| tko parser:   Traceback (most recent call last):
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return func(*params)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 148, in wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       self.cfmApi.wait_for_meetings_in_call_page()
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/autotest/common_lib/cros/cfm_meetings_api.py", line 39, in wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       timeout=DEFAULT_TIMEOUT)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     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
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return func(*args, **kwargs)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 191, in WaitForJavaScriptCondition
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     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
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return func(*args, **kwargs)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 274, in WaitForJavaScriptCondition
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 129, in WaitFor
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       res = condition()
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 271, in IsJavaScriptExpressionTrue
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return self._EvaluateJavaScript(condition, context_id, timeout)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     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
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return func(*args, **kwargs)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 36, in inner
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return func(inspector_backend, *args, **kwargs)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 501, in _EvaluateJavaScript
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       return self._runtime.Evaluate(expression, context_id, timeout)
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 54, in Evaluate
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       description=details.get('exception', {}).get('description'))
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:   EvaluateException: UncaughtTypeError:
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:   TypeError: window.hrTelemetryApi.isInMeeting is not a function
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser:       at <anonymous>:1:66
06:54:52 INFO | autoserv| 
06:54:52 INFO | autoserv| tko parser: ---------------------------------
06:54:52 INFO | autoserv| tko parser: parsing test enterprise_CFM_CameraMuteStress enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| tko parser: ADD: FAIL
06:54:52 INFO | autoserv| Subdir: enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| Testname: enterprise_CFM_CameraMuteStress
06:54:52 INFO | autoserv| RPC error: cfm.wait_for_meetings_in_call_page
06:54:52 INFO | autoserv| tko parser: parsing test ---- SERVER_JOB
06:54:52 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_XGNPupssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
06:54:53 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_FRNA0Mssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
06:54:53 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.dmp...
06:54:53 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.dmp...
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.log...
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.log...
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.core...
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.core...
06:54:54 INFO | autoserv| Collection of /var/spool/crash/chrome.20170816.045452.12153.core skipped:size=451817472, collection_probability=0.148530918255
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.meta...
06:54:54 INFO | autoserv| Collecting /var/spool/crash/chrome.20170816.045452.12153.meta...
06:54:54 INFO | autoserv| Trying to generate stack trace locally for /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.045452.12153.dmp
06:54:54 INFO | autoserv| symbol_dir: /mnt/host/source/src/third_party/autotest/files/server/../../../lib/debug
06:54:54 INFO | autoserv| Generated stack trace for dump /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.045452.12153.dmp
06:54:54 INFO | autoserv| INFO	----	----	timestamp=1502884494	localtime=Aug 16 06:54:54	Start crashcollection record
06:54:54 INFO | autoserv| INFO	----	New Crash Dump	timestamp=1502884494	localtime=Aug 16 06:54:54	/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.045452.12153.dmp
06:54:54 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502884494	localtime=Aug 16 06:54:54	/var/spool/crash/chrome.20170816.045452.12153.dmp
06:54:54 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502884494	localtime=Aug 16 06:54:54	/var/spool/crash/chrome.20170816.045452.12153.log
06:54:54 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502884494	localtime=Aug 16 06:54:54	/var/spool/crash/chrome.20170816.045452.12153.core
06:54:54 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502884494	localtime=Aug 16 06:54:54	/var/spool/crash/chrome.20170816.045452.12153.meta
06:54:54 INFO | autoserv| INFO	----	----	timestamp=1502884494	localtime=Aug 16 06:54:54	End crashcollection record
06:54:54 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.045452.12153.meta'
06:54:54 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.045452.12153.meta'
06:54:54 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.045452.12153.meta'
06:54:54 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.045452.12153.meta'
06:54:59 INFO | autoserv| Would report crash on chromeos-base/chromeos-chrome-61.0.3163.38_rc-r1.
06:54:59 INFO | autoserv| Copied /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.045452.12153.dmp.txt to /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/debug/chrome.20170816.045452.12153.dmp.txt
06:54:59 INFO | autoserv| Copied /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.045452.12153.log to /tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/debug/chrome.20170816.045452.12153.log
06:54:59 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_Dgrympssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
06:55:01 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_FPitJRssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.123.171.19'
06:55:01 INFO | autoserv| get_network_stats: at-end RXbytes 219589728 TXbytes 79382505
06:55:05 INFO | autoserv| record_state_duration failed: job_or_task_id=None, hostname=100.123.171.19, status=Running
-------------------------------------------------------------------------------------------------------------------
/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress                                 [  FAILED  ]
/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress                                   FAIL: RPC error: cfm.wait_for_meetings_in_call_page
/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress [  FAILED  ]
/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress   FAIL: RPC error: cfm.wait_for_meetings_in_call_page
/tmp/test_that_results_73pLcM/results-1-enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress   08/16 06:54:42.094 ERROR|remote_facade_fact:0134| Failed RPC 'cfm.wait_for_meetings_in_call_page'((), {}) with status [<type 'exceptions.Exception'>].
-------------------------------------------------------------------------------------------------------------------
Total PASS: 0/2 (0%)


Telemetry api failure without crash. On screen it shows meeting joined. This happens  to one brand-new setup we just built. 
========================================================================
6:56:19 INFO | autoserv| XMLRPC server started successfully.
06:56:21 INFO | autoserv| wait for telemetry
06:56:33 INFO | autoserv| thor meeting joined  <<<<<<<<<<<<<<<<<<<<<<,
06:56:33 INFO | autoserv| wait for meeting in call page  <<<<<<<<<<<<
06:56:34 INFO | autoserv| Failed RPC 'cfm.wait_for_meetings_in_call_page'((), {}) with status [<type 'exceptions.Exception'>].
06:56:34 INFO | autoserv| Exception : RPC error: cfm.wait_for_meetings_in_call_page
06:56:34 INFO | autoserv| Traceback (most recent call last):
06:56:34 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch

One instance shows meeting joined, it is in meeting page, however, get_preferred_mic fails. there is no chrome crash.
=================================
06:54:36 INFO | autoserv| XMLRPC server started successfully.
06:54:39 INFO | autoserv| wait for telemetry
06:54:51 INFO | autoserv| thor meeting joined
06:54:51 INFO | autoserv| wait for meeting in call page
06:54:51 INFO | autoserv| meeting is in call page
06:55:01 INFO | autoserv| preferred speaker selected by hotrod is ['HDA Intel HDMI: HDMI 0:1,3: HP ZR2440w', 'Hangouts Meet speakermic: USB Audio:0,0']
06:55:01 INFO | autoserv| Executing /tmp/sysinfo/autoserv-cRqBRq/bin/autotest /tmp/sysinfo/autoserv-cRqBRq/control phase 0
06:55:02 INFO | autoserv| Entered autotestd_monitor.
06:55:02 INFO | autoserv| Finished launching tail subprocesses.
06:55:02 INFO | autoserv| Finished waiting on autotestd to start.
06:55:02 INFO | autoserv| START	----	----	timestamp=1502884501	localtime=Aug 16 06:55:01
06:55:02 INFO | autoserv| GOOD	----	sysinfo.iteration.after	timestamp=1502884501	localtime=Aug 16 06:55:01
06:55:02 INFO | autoserv| END GOOD	----	----	timestamp=1502884501	localtime=Aug 16 06:55:01
06:55:02 INFO | autoserv| Got lock of exit_code_file.
06:55:02 INFO | autoserv| Released lock of exit_code_file and closed it.
06:55:04 INFO | autoserv| Killing child processes.
06:55:04 INFO | autoserv| Client complete
06:55:05 INFO | autoserv| The test failed with the following exception
06:55:05 INFO | autoserv| Traceback (most recent call last):
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 610, in _exec
06:55:05 INFO | autoserv| _call_test_function(self.execute, *p_args, **p_dargs)
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 824, in _call_test_function
06:55:05 INFO | autoserv| raise error.UnhandledTestFail(e)
06:55:05 INFO | autoserv| UnhandledTestFail: Unhandled AttributeError: 'CFMFacadeRemoteAdapter' object has no attribute 'get_speaker_mic'
06:55:05 INFO | autoserv| Traceback (most recent call last):
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 818, in _call_test_function
06:55:05 INFO | autoserv| return func(*args, **dargs)
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 471, in execute
06:55:05 INFO | autoserv| dargs)
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 348, in _call_run_once_with_retry
06:55:05 INFO | autoserv| postprocess_profiled_run, args, dargs)
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 381, in _call_run_once
06:55:05 INFO | autoserv| self.run_once(*args, **dargs)
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 437, in run_once
06:55:05 INFO | autoserv| self._peripherals_sanity_test()
06:55:05 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 355, in _peripherals_sanity_test
06:55:05 INFO | autoserv| logging.info('preferred mic selected by hotrod is %s', self.cfm_facade.get_speaker_mic())
06:55:05 INFO | autoserv| AttributeError: 'CFMFacadeRemoteAdapter' object has no attribute 'get_speaker_mic'
06:55:05 INFO | autoserv| 
06:55:05 INFO | autoserv| Executing /tmp/sysinfo/autoserv-cRqBRq/bin/autotest /tmp/sysinfo/autoserv-cRqBRq/control phase 0

One more log for same case:
==========================
06:53:59 INFO | autoserv| wait for telemetry
06:54:09 INFO | autoserv| thor meeting joined
06:54:09 INFO | autoserv| wait for meeting in call page
06:54:09 INFO | autoserv| meeting is in call page
06:54:09 INFO | autoserv| preferred speaker selected by hotrod is ['HDA Intel HDMI: HDMI 0:1,3: S277HK', 'Hangouts Meet speakermic: USB Audio:0,0']
06:54:10 INFO | autoserv| Executing /tmp/sysinfo/autoserv-dQrvP1/bin/autotest /tmp/sysinfo/autoserv-dQrvP1/control phase 0
06:54:10 INFO | autoserv| Entered autotestd_monitor.
06:54:10 INFO | autoserv| Finished launching tail subprocesses.
06:54:10 INFO | autoserv| Finished waiting on autotestd to start.
06:54:11 INFO | autoserv| START	----	----	timestamp=1502884450	localtime=Aug 16 06:54:10
06:54:11 INFO | autoserv| GOOD	----	sysinfo.iteration.after	timestamp=1502884450	localtime=Aug 16 06:54:10
06:54:11 INFO | autoserv| END GOOD	----	----	timestamp=1502884450	localtime=Aug 16 06:54:10
06:54:11 INFO | autoserv| Got lock of exit_code_file.
06:54:11 INFO | autoserv| Released lock of exit_code_file and closed it.
06:54:13 INFO | autoserv| Client complete
06:54:13 INFO | autoserv| The test failed with the following exception
06:54:13 INFO | autoserv| Traceback (most recent call last):
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 610, in _exec
06:54:13 INFO | autoserv| _call_test_function(self.execute, *p_args, **p_dargs)
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 824, in _call_test_function
06:54:13 INFO | autoserv| raise error.UnhandledTestFail(e)
06:54:13 INFO | autoserv| UnhandledTestFail: Unhandled AttributeError: 'CFMFacadeRemoteAdapter' object has no attribute 'get_speaker_mic'
06:54:13 INFO | autoserv| Traceback (most recent call last):
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 818, in _call_test_function
06:54:13 INFO | autoserv| return func(*args, **dargs)
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 471, in execute
06:54:13 INFO | autoserv| dargs)
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 348, in _call_run_once_with_retry
06:54:13 INFO | autoserv| postprocess_profiled_run, args, dargs)
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/client/common_lib/test.py", line 381, in _call_run_once
06:54:13 INFO | autoserv| self.run_once(*args, **dargs)
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 437, in run_once
06:54:13 INFO | autoserv| self._peripherals_sanity_test()
06:54:13 INFO | autoserv| File "/mnt/host/source/src/third_party/autotest/files/server/site_tests/enterprise_CFM_CameraMuteStress/enterprise_CFM_CameraMuteStress.py", line 355, in _peripherals_sanity_test
06:54:13 INFO | autoserv| logging.info('preferred mic selected by hotrod is %s', self.cfm_facade.get_speaker_mic())
06:54:13 INFO | autoserv| AttributeError: 'CFMFacadeRemoteAdapter' object has no attribute 'get_speaker_mic'
06:54:13 INFO | autoserv| 
06:54:14 INFO | autoserv| Executing /tmp/sysinfo/autoserv-dQrvP1/bin/autotest /tmp/sysinfo/autoserv-dQrvP1/control phase 0

Comment 24 by mzhuo@chromium.org, Aug 16 2017 

I run script on 4 setups. One of them has PTZ, the other 3 have Huddly. 
The one with PTZ always has chrome crash after starting script, and after meeting joined. 
The other 3 shows RPC error for "RPC error: cfm.get_speaker_volume" at high rate.

Comment 25 by mzhuo@chromium.org, Aug 16 2017

Summary: Chrome crash when running telemetry api to start meeting and get_device with PTZ camera connected (was: Telemetry api for meet api is broken due to chrome crash which leads to telemetry api is not available. )
Update for today's testing ( 8/16/2017) 
=======================================
Chrome crash happens each time running the script on  setup which has PTZ camera. 
Crash happens after joining meeting. 

13:04:23 INFO | autoserv| XMLRPC server started successfully.
13:04:24 INFO | autoserv| wait for telemetry
13:04:32 INFO | autoserv| thor meeting joined
13:04:32 INFO | autoserv| wait for meeting in call page
13:04:32 INFO | autoserv| Failed RPC 'cfm.wait_for_meetings_in_call_page'((), {}) with status [<type 'exceptions.Exception'>].
13:04:32 INFO | autoserv| Exception : RPC error: cfm.wait_for_meetings_in_call_page
13:04:32 INFO | autoserv| Traceback (most recent call last):
13:04:32 INFO | autoserv| File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
13:04:32 INFO | autoserv| return func(*params)
nterprise_CFM_CameraMuteStress/crashinfo.100.123.171.19/chrome.20170816.110443.6220.dmp
13:04:45 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502906685	localtime=Aug 16 13:04:45	/var/spool/crash/chrome.20170816.110443.6220.core
13:04:45 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502906685	localtime=Aug 16 13:04:45	/var/spool/crash/chrome.20170816.110443.6220.log
13:04:45 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502906685	localtime=Aug 16 13:04:45	/var/spool/crash/chrome.20170816.110443.6220.meta
13:04:45 INFO | autoserv| INFO	----	Orphaned Crash Dump	timestamp=1502906685	localtime=Aug 16 13:04:45	/var/spool/crash/chrome.20170816.110443.6220.dmp
13:04:45 INFO | autoserv| INFO	----	----	timestamp=1502906685	localtime=Aug 16 13:04:45	End crashcollection record
13:04:45 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.110443.6220.meta'
13:04:45 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.110443.6220.meta'
13:04:45 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.110443.6220.meta'
13:04:45 INFO | autoserv| Crash detection failed with: [Errno 2] No such file or directory: '/var/spool/crash/chrome.20170816.110443.6220.meta'


Uploaded  chrome-ptz.tar to https://drive.google.com/corp/drive/u/1/folders/0B8sYeJbsz9zKSEJDa1RSanh3TWM.

Comment 26 by mzhuo@chromium.org, Aug 16 2017 

Manually joining meeting and leaving meeting multiple times there is no chrome crash.

Comment 27 by mzhuo@chromium.org, Aug 16 2017 

Break this bug to 2 new bugs, one for chrome crash, the other for RPC error.

Comment 28 by mzhuo@chromium.org, Aug 16 2017

Status: Archived (was: Untriaged)

Comment 29 by dtosic@chromium.org, Aug 17 2017 

For reference, these: are the 2 new bugs:
 https://crbug.com/756166 
 https://crbug.com/756159
►

Sign in to add a comment