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