Refine audio test log

BUG=none
TEST=manually tested

Change-Id: I63381e50849ae85d0fefc997804d9c71f5e0f347
Signed-off-by: Moja Hsu <mojahsu@google.com>
Reviewed-on: https://chromium-review.googlesource.com/263040
Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org>
Tested-by: Hsu Wei-Cheng <mojahsu@chromium.org>
Commit-Queue: Hsu Wei-Cheng <mojahsu@chromium.org>
diff --git a/py/test/audio_utils.py b/py/test/audio_utils.py
index 9053db8..2ed4232 100644
--- a/py/test/audio_utils.py
+++ b/py/test/audio_utils.py
@@ -258,6 +258,8 @@
   """
 
   def __init__(self, config_path=_DEFAULT_CONFIG_PATH):
+    # used for audio config logging.
+    self._audio_config_sn = 0
     self._restore_mixer_control_stack = []
     if os.path.exists(config_path):
       with open(config_path, 'r') as config_file:
@@ -287,18 +289,18 @@
         numid = int(m.group(1))
         break
     if numid == 0:
-      logging.info('Unable to find mixer control %s', name)
+      logging.info('Unable to find mixer control \'%s\'', name)
       return None
 
     output = Spawn(['amixer', '-c%d' % int(card), 'cget', 'numid=%d' % numid],
                    stdout=PIPE)
     lines = output.stdout.read()
-    logging.info('lines: %r', lines)
+    logging.info('lines: %s', lines)
     m = re.search(r'^.*: values=(.*)$', lines, re.MULTILINE)
     if m:
       return m.group(1)
     else:
-      logging.info('Unable to get value for mixer control %s, numid=%d',
+      logging.info('Unable to get value for mixer control \'%s\', numid=%d',
                    name, numid)
       return None
 
@@ -311,17 +313,17 @@
       store: Store the current value so it can be restored later using
         RestoreMixerControls.
     """
-    logging.info('Setting mixer control values on %s', card)
+    logging.info('Setting mixer control values on card %s', card)
     restore_mixer_settings = dict()
     for name, value in mixer_settings.items():
       if store:
         old_value = self.GetMixerControls(name, card)
         restore_mixer_settings[name] = old_value
-        logging.info('Saving %s with value %s on card %s',
+        logging.info('Saving \'%s\' with value %s on card %s',
                      name, old_value, card)
-      logging.info('Setting %s to %s on card %s', name, value, card)
+      logging.info('Setting \'%s\' to %s on card %s', name, value, card)
       command = ['amixer', '-c', card, 'cset', 'name=%r' % name, value]
-      Spawn(command, check_call=True)
+      Spawn(command, check_call=True, log=True)
     if store:
       self._restore_mixer_control_stack.append((restore_mixer_settings, card))
 
@@ -434,7 +436,12 @@
   def ApplyAudioConfig(self, action, card='0'):
     if card in self.audio_config:
       if action in self.audio_config[card]:
+        logging.info('\nvvv-- Do(%d) \'%s\' on card %s Start --vvv',
+                     self._audio_config_sn, action, card)
         self.SetMixerControls(self.audio_config[card][action], card)
+        logging.info('\n^^^-- Do(%d) \'%s\' on card %s End   --^^^',
+                     self._audio_config_sn, action, card)
+        self._audio_config_sn += 1
       else:
         logging.info('Action %s cannot be found in card %s', action, card)
     else:
diff --git a/py/test/pytests/audio_loop/audio_loop.py b/py/test/pytests/audio_loop/audio_loop.py
index 5b91abf..d8e957a 100644
--- a/py/test/pytests/audio_loop/audio_loop.py
+++ b/py/test/pytests/audio_loop/audio_loop.py
@@ -312,8 +312,8 @@
       speaker_channel: 0 is left channel, 1 is right channel
       mic_channel: 0 is left channel, 1 is right channel
     """
-    factory.console.info('Test speaker channel %d and mic channel %d' %
-                         (speaker_channel, mic_channel))
+    factory.console.info('Test speaker channel %d and mic channel %d',
+                         speaker_channel, mic_channel)
     if self._mic_source == MicSource.panel:
       self._audio_util.EnableDmic(self._in_card)
       if mic_channel is 0:
@@ -368,8 +368,8 @@
   def AudioFunTest(self):
     """Setup speaker and microphone test pairs and run audiofuntest program."""
 
-    factory.console.info('Run audiofuntest from %r to %r' % (
-        self._output_device, self._input_device))
+    factory.console.info('Run audiofuntest from %r to %r',
+                         self._output_device, self._input_device)
 
     test_pairs = self._current_test_args.get(
         'test_pairs', _DEFAULT_AUDIOFUN_TEST_PAIRS)
@@ -384,7 +384,9 @@
       num_channels: Number of channels to test
     """
     for channel in xrange(num_channels):
-      record_file_path = '/tmp/record-%d-%s.raw' % (channel, time.time())
+      record_file_path = '/tmp/record-%d-%d-%s.raw' % (
+          self._output_volumes[self._output_volume_index],
+          channel, time.time())
 
       # Play thread has one more second to ensure record process can record
       # entire sine tone
@@ -438,6 +440,7 @@
     record_path = (tempfile.NamedTemporaryFile(delete=False).name if trim
                    else file_path)
 
+    factory.console.info('RecordFile : %s.', file_path)
     rec_cmd = ['arecord', '-D', self._input_device, '-f', 'dat', '-d',
                str(duration), '-t', 'raw', record_path]
     Spawn(rec_cmd, log=True, check_call=True)
@@ -452,10 +455,10 @@
     factory.console.info('Got audio RMS value: %f.', rms_value)
     rms_threshold = self._current_test_args.get(
         'rms_threshold', _DEFAULT_SOX_RMS_THRESHOLD)
-    if (rms_threshold[0] is not None and rms_threshold[0] > rms_value):
+    if rms_threshold[0] is not None and rms_threshold[0] > rms_value:
       self.AppendErrorMessage('Audio RMS value %f too low. Minimum pass is %f.'
                               % (rms_value, rms_threshold[0]))
-    if (rms_threshold[1] is not None and rms_threshold[1] < rms_value):
+    if rms_threshold[1] is not None and rms_threshold[1] < rms_value:
       self.AppendErrorMessage('Audio RMS value %f too high. Maximum pass is %f.'
                               % (rms_value, rms_threshold[1]))
 
@@ -481,10 +484,12 @@
       freq = audio_utils.GetRoughFreq(sox_output)
       freq_threshold = self._current_test_args.get(
           'freq_threshold', _DEFAULT_SINEWAV_FREQ_THRESHOLD)
+      factory.console.info('Extected frequency %r +- %d',
+                           self._freq, freq_threshold)
       if freq is None or (abs(freq - self._freq) > freq_threshold):
         self.AppendErrorMessage('Test Fail at frequency %r' % freq)
       else:
-        factory.console.info('Got frequency %d' % freq)
+        factory.console.info('Got frequency %d', freq)
 
   def MayPassTest(self):
     """Checks if test can pass with result of one output volume.