1# Copyright 2019 The Chromium OS Authors. All rights reserved. 2# Use of this source code is governed by a BSD-style license that can be 3# found in the LICENSE file. 4 5import datetime 6import dbus 7import logging 8import os 9import re 10import subprocess 11import time 12 13from autotest_lib.client.bin import test 14from autotest_lib.client.bin import utils 15from autotest_lib.client.common_lib import error 16from autotest_lib.client.cros import upstart 17from autotest_lib.client.cros.audio import audio_helper 18from autotest_lib.client.cros.audio import cras_utils 19 20_STREAM_TYPE_INPUT_APM = 0 21_STREAM_TYPE_OUTPUT = 1 22 23class audio_CrasDevSwitchStress(test.test): 24 """ 25 Checks if output buffer will drift to super high level when 26 audio devices switch repeatedly. 27 """ 28 version = 1 29 _LOOP_COUNT = 150 30 _INPUT_BUFFER_LEVEL = '.*?READ_AUDIO.*?dev:(\d+).*hw_level.*?(\d+).*?' 31 _OUTPUT_BUFFER_LEVEL = '.*?FILL_AUDIO.*?dev:(\d+).*hw_level.*?(\d+).*?' 32 _CHECK_PERIOD_TIME_SECS = 0.5 33 _SILENT_OUTPUT_DEV_ID = 2 34 _STREAM_BLOCK_SIZE = 480 35 _AUDIO_LOG_TIME_FMT = '%Y-%m-%dT%H:%M:%S.%f' 36 _last_audio_log = '' 37 38 """ 39 Buffer level of input device should stay between 0 and block size. 40 Buffer level of output device should between 1 to 2 times of block size. 41 Device switching sometimes cause the buffer level to grow more then 42 the ideal range, so we use tripple block size here. 43 """ 44 _INPUT_BUFFER_DRIFT_CRITERIA = 3 * _STREAM_BLOCK_SIZE 45 _OUTPUT_BUFFER_DRIFT_CRITERIA = 3 * _STREAM_BLOCK_SIZE 46 47 def initialize(self): 48 """Initialize the test""" 49 upstart.stop_job('ui') 50 51 def cleanup(self): 52 """Remove all streams for testing.""" 53 if self._streams: 54 # Clean up all streams. 55 while len(self._streams) > 0: 56 self._streams[0].kill() 57 self._streams.remove(self._streams[0]) 58 upstart.restart_job('ui') 59 super(audio_CrasDevSwitchStress, self).cleanup() 60 61 def _new_stream(self, stream_type, node_pinned): 62 """ 63 Runs new stream by cras_test_client. 64 Args: 65 stream_type: _STREAM_TYPE_INPUT_APM or _STREAM_TYPE_OUTPUT 66 node_pinned: if not None then create the new stream that 67 pinned to this node. 68 Returns: 69 New process that runs a CRAS client stream. 70 """ 71 if stream_type == _STREAM_TYPE_INPUT_APM: 72 cmd = ['cras_test_client', '--capture_file', '/dev/null', 73 '--effects', 'aec'] 74 else: 75 cmd = ['cras_test_client', '--playback_file', '/dev/zero'] 76 77 cmd += ['--block_size', str(self._STREAM_BLOCK_SIZE)] 78 79 if node_pinned and node_pinned['Id']: 80 dev_id = node_pinned['Id'] >> 32 81 if stream_type == _STREAM_TYPE_INPUT_APM: 82 if node_pinned['IsInput']: 83 cmd += ['--pin_device', str(dev_id)] 84 elif not node_pinned['IsInput']: 85 cmd += ['--pin_device', str(dev_id)] 86 87 return subprocess.Popen(cmd) 88 89 def _get_time(self, s): 90 """ 91 Parse timespec from the audio log. The format is like 92 2020-07-16T00:36:40.819094632 cras ... 93 94 Args: 95 s: A string to parse. 96 97 Returns: 98 The datetime object created from the given string. 99 """ 100 return datetime.datetime.strptime( 101 s.split(' ')[0][:-3], self._AUDIO_LOG_TIME_FMT) 102 103 def _update_last_log_time(self): 104 """Save the time of the last audio thread logs.""" 105 106 proc = subprocess.Popen(['cras_test_client', '--dump_a'], 107 stdout=subprocess.PIPE) 108 output, err = proc.communicate() 109 self._last_log_time = self._get_time(output.split('\n')[-2]) 110 111 def _get_buffer_level(self, match_str, dev_id): 112 """ 113 Gets a rough number about current buffer level. 114 115 Args: 116 match_str: regular expression to match device buffer level. 117 dev_id: audio device id in CRAS. 118 119 Returns: 120 The current buffer level. 121 """ 122 proc = subprocess.Popen(['cras_test_client', '--dump_a'], 123 stdout=subprocess.PIPE) 124 output, err = proc.communicate() 125 buffer_level = 0 126 lines = output.split('\n') 127 start = False 128 for line in lines: 129 if not line or not start: 130 # The timestamp shows up in later lines. 131 if 'start at' in line: 132 start = True 133 continue 134 time = self._get_time(line) 135 # Filter logs which appeared earlier than the test run. 136 if time <= self._last_log_time: 137 continue 138 search = re.match(match_str, line) 139 if search: 140 if dev_id != int(search.group(1)): 141 continue 142 tmp = int(search.group(2)) 143 if tmp > buffer_level: 144 buffer_level = tmp 145 return buffer_level 146 147 def _check_buffer_level(self, node): 148 """Checks if current buffer level of node stay in criteria.""" 149 if node['IsInput']: 150 match_str = self._INPUT_BUFFER_LEVEL 151 criteria = self._INPUT_BUFFER_DRIFT_CRITERIA 152 else: 153 match_str = self._OUTPUT_BUFFER_LEVEL 154 criteria = self._OUTPUT_BUFFER_DRIFT_CRITERIA 155 156 dev_id = node['Id'] >> 32 157 buffer_level = self._get_buffer_level(match_str, dev_id) 158 159 logging.debug("Max buffer level: %d on dev %d", buffer_level, dev_id) 160 if buffer_level > criteria: 161 audio_helper.dump_audio_diagnostics( 162 os.path.join(self.resultsdir, "audio_diagnostics.txt")) 163 raise error.TestFail('Buffer level %d drift too high on %s node' 164 ' with dev id %d' % 165 (buffer_level, node['Type'], dev_id)) 166 167 def _get_cras_pid(self): 168 """Gets the pid of CRAS, used to check if CRAS crashes and respawn.""" 169 pid = utils.system_output('pgrep cras$ 2>&1', retain_output=True, 170 ignore_status=True).strip() 171 try: 172 pid = int(pid) 173 except ValueError, e: # empty or invalid string 174 raise error.TestFail('CRAS not running') 175 176 def _switch_to_node(self, node): 177 """ 178 Switches CRAS input or output active node to target node. 179 Args: 180 node: if not None switch CRAS input/output active node to it 181 """ 182 if node == None: 183 return 184 if node['IsInput']: 185 cras_utils.set_active_input_node(node['Id']) 186 else: 187 cras_utils.set_active_output_node(node['Id']) 188 189 def run_once(self, type_a=None, type_b=None, pinned_type=None): 190 """ 191 Setup the typical streams used for hangout, one input stream with APM 192 plus an output stream. If pinned_type is not None, set up an additional 193 stream that pinned to the first node of pinned_type. 194 The test repeatedly switch active nodes between the first nodes of 195 type_a and type_b to verify there's no crash and buffer level stay 196 in reasonable range. 197 198 Args: 199 type_a: node type to match a CRAS node 200 type_b: node type to match a CRAS node 201 pinned_type: node type to match a CRAS node 202 """ 203 node_a = None 204 node_b = None 205 node_pinned = None 206 self._streams = [] 207 208 """Store the selected nodes at the start of the test.""" 209 (output_type, input_type) = cras_utils.get_selected_node_types() 210 211 cras_pid = self._get_cras_pid() 212 213 try: 214 nodes = cras_utils.get_cras_nodes() 215 except dbus.DBusException as e: 216 logging.error("Get CRAS nodes failure."); 217 raise error.TestFail("No reply from CRAS for get nodes request.") 218 219 for node in nodes: 220 if type_a and node['Type'] == type_a: 221 node_a = node 222 elif type_b and node['Type'] == type_b: 223 node_b = node 224 225 if pinned_type and node['Type'] == pinned_type: 226 node_pinned = node 227 228 if not (node_a and node_b): 229 raise error.TestNAError("No output nodes pair to switch.") 230 231 self._update_last_log_time(); 232 if node_pinned: 233 if node_pinned['IsInput']: 234 self._streams.append( 235 self._new_stream(_STREAM_TYPE_INPUT_APM, node_pinned)) 236 else: 237 self._streams.append( 238 self._new_stream(_STREAM_TYPE_OUTPUT, node_pinned)) 239 240 self._streams.append(self._new_stream(_STREAM_TYPE_OUTPUT, None)) 241 self._streams.append(self._new_stream(_STREAM_TYPE_INPUT_APM, None)) 242 243 loop_count = 0 244 past_time = time.time() 245 246 try: 247 while loop_count < self._LOOP_COUNT: 248 # Switch active input/output node in each loop. 249 if loop_count % 2 == 0: 250 self._switch_to_node(node_a) 251 else: 252 self._switch_to_node(node_b) 253 254 time.sleep(0.2) 255 now = time.time() 256 257 # Check buffer level. 258 if now - past_time > self._CHECK_PERIOD_TIME_SECS: 259 past_time = now 260 self._check_buffer_level(node_a) 261 self._check_buffer_level(node_b) 262 263 loop_count += 1 264 if cras_pid != self._get_cras_pid(): 265 raise error.TestFail("CRAS crashed and respawned.") 266 except dbus.DBusException as e: 267 logging.exception(e) 268 raise error.TestFail("CRAS may have crashed.") 269 finally: 270 """Restore the nodes at the end of the test.""" 271 cras_utils.set_selected_node_types(output_type, input_type) 272