audio/alsa_record_playback_automated failed

I can confirm this is happening, but I doubt it's anything to do with the mic volume:

>>> ubuntu@201105-8051:~$ pacmd set-source-volume 1 65537
Welcome to PulseAudio! Use "help" for usage information.
>>> >>> ubuntu@201105-8051:~$ pacmd list-sources
Welcome to PulseAudio! Use "help" for usage information.
>>> 2 source(s) available.
    index: 0
 name: <alsa_output.pci-0000_00_1b.0.analog-stereo.monitor>
 driver: <module-alsa-card.c>
 flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
 state: SUSPENDED
 suspend cause: IDLE
 priority: 1950
 volume: 0: 10% 1: 10%
         0: -60.00 dB 1: -60.00 dB
         balance 0.00
 base volume: 100%
              0.00 dB
 volume steps: 65537
 muted: no
 current latency: 0.00 ms
 max rewind: 0 KiB
 sample spec: s16le 2ch 44100Hz
 channel map: front-left,front-right
              Stereo
 used by: 0
 linked by: 0
 configured latency: 0.00 ms; range is 0.50 .. 371.52 ms
 monitor_of: 0
 card: 0 <alsa_card.pci-0000_00_1b.0>
 module: 4
 properties:
  device.description = "Monitor of Built-in Audio Analog Stereo"
  device.class = "monitor"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xf7f00000 irq 55"
  alsa.driver_name = "snd_hda_intel"
  device.bus_path = "pci-0000:00:1b.0"
  sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
  device.bus = "pci"
  device.vendor.id = "8086"
  device.vendor.name = "Intel Corporation"
  device.product.name = "6 Series/C200 Series Chipset Family High Definition Audio Controller"
  device.form_factor = "internal"
  device.string = "0"
  module-udev-detect.discovered = "1"
  device.icon_name = "audio-card-pci"
  * index: 1
 name: <alsa_input.pci-0000_00_1b.0.analog-stereo>
 driver: <module-alsa-card.c>
 flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
 state: RUNNING
 suspend cause:
 priority: 9959
 volume: 0: 100% 1: 100%
         0: 0.00 dB 1: 0.00 dB
         balance 0.00
 base volume: 79%
              -6.00 dB
 volume steps: 65537
 muted: no
 current latency: 0.00 ms
 max rewind: 0 KiB
 sample spec: s16le 2ch 44100Hz
 channel map: front-left,front-right
              Stereo
 used by: 1
 linked by: 1
 configured latency: 20.00 ms; range is 1.00 .. 371.52 ms
 card: 0 <alsa_card.pci-0000_00_1b.0>
 module: 4
 properties:
  alsa.resolution_bits = "16"
  device.api = "alsa"
  device.class = "sound"
  alsa.class = "generic"
  alsa.subclass = "generic-mix"
  alsa.name = "CONEXANT Analog"
  alsa.id = "CONEXANT Analog"
  alsa.subdevice = "0"
  alsa.subdevice_name = "subdevice #0"
  alsa.device = "0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xf7f00000 irq 55"
  alsa.driver_name = "snd_hda_intel"
  device.bus_path = "pci-0000:00:1b.0"
  sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
  device.bus = "pci"
  device.vendor.id = "8086"
  device.vendor.name = "Intel Corporation"
  device.product.name = "6 Series/C200 Series Chipset Family High Definition Audio Controller"
  device.form_factor = "internal"
  device.string = "front:0"
  device.buffering.buffer_size = "65536"
  device.buffering.fragment_size = "32768"
  device.access_mode = ...

Here is what is actually recorded

And here is the corresponding spectrum data. Comparing that to a successful run of the test (on my laptop) shows that there should be a brief spike into the -30's or so in the magnitude column. No such spike occurs here. It seems the mic is muffling the audio somehow.

Well, attaching it would have been a good idea :)

Thanks!

On the recording the control frequency is there but is very muffled by the buzzing noise, which sounds like usual lab noise (fans mainly). What this tells me is that this laptop's speaker is a bit quiet. A thing to do would be increasing the speaker volume. One thing we could try is setting it at the current level (70%), then if the test fails, retrying at a higher volume (80%-90%).

If you look at spectrum data, you will see the small peak at ~7 kHz, so the test frequency *is* present. The detection algorithm is very simplistic; it just looks at a peak higher than the average for the entire sampling range. So what's happening here is that the fan noise at lower frequencies is "overpowering" the control frequency and that's why the algorithm fails to identify it.

However, the frequency is there; you can see the small peak, and you can hear the control frequency on the audio recording. So the other thing to do (better IMHO) would be improving the detection algorithm to maybe look for local peaks instead of only those that surpass the average.

Some experimentation/thinking is needed, because (it has happened) it may be possible for a signal to be so faint that a human can't hear it, but for the computer to detect it. This would pass the test but would be pretty useless for a normal person, so care must be taken if doing this. Maybe looking at the actual dB levels and comparing that with microphone gain can help come up with a reasonable heuristic of whether the recorded signal is too faint for a human.

I'll set this as triaged as at this point it's just a matter of getting to work on the problem. I'll also grab the bug for myself if you don't mind :)

Tested with 0.16.4+bzr1981+201307031634~precise1.
But the result is still failing.

modern911@jeffrey-Audi15:~/source/checkbox$ /usr/lib/checkbox/bin/audio_test -d
DEBUG:root:autoaudiosrc
        ! queue
        ! level message=true
        ! audioconvert
        ! audio/x-raw, channels=1, rate=(int)44100
        ! audioresample
        ! spectrum interval=100000000 bands = 256
        ! wavenc
        ! filesink location=/dev/null
DEBUG:root:audiotestsrc wave=sine freq=7278 ! audioconvert ! audioresample ! autoaudiosink
INFO:root:Using PulseAudio identifier 6 (alsa_input.pci-0000_00_1b.0.analog-stereo) for input
INFO:root:Using PulseAudio identifier 4 (alsa_output.pci-0000_00_1b.0.analog-stereo) for output
DEBUG:root:Registering message handler: <bound method GStreamerMessageHandler.bus_message_handler of <__main__.GStreamerMessageHandler object at 0x1bf1450>>
INFO:root:Player: Starting
INFO:root:Recorder: Starting
DEBUG:root:Peak level: -350.00, volume: 0%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 0 samples
DEBUG:root:Sampling, recorded 1 samples
DEBUG:root:Peak level: -78.27, volume: 5%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 2 samples
DEBUG:root:Peak level: -70.31, volume: 10%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 3 samples
DEBUG:root:Peak level: -60.21, volume: 15%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 4 samples
DEBUG:root:Peak level: -53.53, volume: 20%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 5 samples
DEBUG:root:Peak level: -48.73, volume: 25%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 6 samples
DEBUG:root:Peak level: -42.70, volume: 30%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 7 samples
DEBUG:root:Peak level: -38.85, volume: 35%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 8 samples
DEBUG:root:Peak level: -32.68, volume: 40%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 9 samples
DEBUG:root:Peak level: -33.53, volume: 45%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 10 samples
DEBUG:root:Peak level: -30.05, volume: 50%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 11 samples
DEBUG:root:Sampling, recorded 12 samples
DEBUG:root:Peak level: -26.49, volume: 55%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 13 samples
DEBUG:root:Peak level: -25.53, volume: 60%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 14 samples
DEBUG:root:Peak level: -22.41, volume: 65%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 15 samples
DEBUG:root:Peak level: -20.45, volume: 70%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 16 samples
DEBUG:root:Peak level: -20.30, volume: 75%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 17 samples
DEBUG:root:Peak level: -12.99, volume: 80%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 18 samples
DEBUG:root:Peak level: -8.67, volume: 85%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 19 samples
INFO:root:Sampling complete, ending process
INFO:root:Player: Stopping
INFO:root:Recorder: Stopping
DEBUG:root:Band (86.13,172.27) contains a magnitude peak
INFO:root:FAIL: Test frequency of 7278.22265625 is not in one o...

another result with higher recording volume

modern911@jeffrey-Audi15:~/source/checkbox$ /usr/lib/checkbox/bin/audio_test -d -u spectrum.log
DEBUG:root:autoaudiosrc
        ! queue
        ! level message=true
        ! audioconvert
        ! audio/x-raw, channels=1, rate=(int)44100
        ! audioresample
        ! spectrum interval=100000000 bands = 256
        ! wavenc
        ! filesink location=/dev/null
DEBUG:root:audiotestsrc wave=sine freq=7278 ! audioconvert ! audioresample ! autoaudiosink
INFO:root:Using PulseAudio identifier 6 (alsa_input.pci-0000_00_1b.0.analog-stereo) for input
INFO:root:Using PulseAudio identifier 4 (alsa_output.pci-0000_00_1b.0.analog-stereo) for output
DEBUG:root:Registering message handler: <bound method GStreamerMessageHandler.bus_message_handler of <__main__.GStreamerMessageHandler object at 0x21e5450>>
INFO:root:Player: Starting
INFO:root:Recorder: Starting
DEBUG:root:Peak level: -350.00, volume: 0%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 0 samples
DEBUG:root:Sampling, recorded 1 samples
DEBUG:root:Peak level: -78.27, volume: 5%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 2 samples
DEBUG:root:Peak level: -67.39, volume: 10%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 3 samples
DEBUG:root:Peak level: -58.27, volume: 15%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 4 samples
DEBUG:root:Peak level: -50.05, volume: 20%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 5 samples
DEBUG:root:Peak level: -45.40, volume: 25%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 6 samples
DEBUG:root:Peak level: -40.43, volume: 30%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 7 samples
DEBUG:root:Peak level: -36.90, volume: 35%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 8 samples
DEBUG:root:Peak level: -33.92, volume: 40%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 9 samples
DEBUG:root:Peak level: -31.76, volume: 45%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 10 samples
DEBUG:root:Peak level: -27.72, volume: 50%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 11 samples
DEBUG:root:Sampling, recorded 12 samples
DEBUG:root:Peak level: -24.40, volume: 55%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 13 samples
DEBUG:root:Peak level: -21.19, volume: 60%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 14 samples
DEBUG:root:Peak level: -19.41, volume: 65%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 15 samples
DEBUG:root:Peak level: -17.03, volume: 70%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 16 samples
DEBUG:root:Peak level: -15.38, volume: 75%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 17 samples
DEBUG:root:Peak level: -13.63, volume: 80%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 18 samples
DEBUG:root:Peak level: -12.19, volume: 85%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 19 samples
INFO:root:Sampling complete, ending process
INFO:root:Player: Stopping
INFO:root:Recorder: Stopping
DEBUG:root:Band (86.13,172.27) contains a magnitude peak
INFO:root:FAIL: Test frequency of 7278.22265625 is not in one of the bands with magni...

Test with external MIC on same hardware generate different result - PASSed.

modern911@jeffrey-Audi15:~$ /usr/lib/checkbox/bin/audio_test -d
DEBUG:root:autoaudiosrc
        ! queue
        ! level message=true
        ! audioconvert
        ! audio/x-raw, channels=1, rate=(int)44100
        ! audioresample
        ! spectrum interval=100000000 bands = 256
        ! wavenc
        ! filesink location=/dev/null
DEBUG:root:audiotestsrc wave=sine freq=7278 ! audioconvert ! audioresample ! autoaudiosink
INFO:root:Using PulseAudio identifier 6 (alsa_input.pci-0000_00_1b.0.analog-stereo) for input
INFO:root:Using PulseAudio identifier 4 (alsa_output.pci-0000_00_1b.0.analog-stereo) for output
DEBUG:root:Registering message handler: <bound method GStreamerMessageHandler.bus_message_handler of <__main__.GStreamerMessageHandler object at 0x252b410>>
INFO:root:Player: Starting
INFO:root:Recorder: Starting
DEBUG:root:Peak level: -350.00, volume: 0%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 0 samples
DEBUG:root:Sampling, recorded 1 samples
DEBUG:root:Peak level: -73.41, volume: 5%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 2 samples
DEBUG:root:Peak level: -59.68, volume: 10%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 3 samples
DEBUG:root:Peak level: -49.72, volume: 15%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 4 samples
DEBUG:root:Peak level: -42.53, volume: 20%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 5 samples
DEBUG:root:Peak level: -36.14, volume: 25%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 6 samples
DEBUG:root:Peak level: -38.85, volume: 30%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 7 samples
DEBUG:root:Peak level: -36.45, volume: 35%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 8 samples
DEBUG:root:Peak level: -36.24, volume: 40%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 9 samples
DEBUG:root:Peak level: -31.24, volume: 45%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 10 samples
DEBUG:root:Peak level: -31.67, volume: 50%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 11 samples
DEBUG:root:Sampling, recorded 12 samples
DEBUG:root:Peak level: -29.36, volume: 55%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 13 samples
DEBUG:root:Peak level: -27.31, volume: 60%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 14 samples
DEBUG:root:Peak level: -26.02, volume: 65%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 15 samples
DEBUG:root:Peak level: -18.78, volume: 70%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 16 samples
DEBUG:root:Peak level: -22.59, volume: 75%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 17 samples
DEBUG:root:Peak level: -20.88, volume: 80%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 18 samples
DEBUG:root:Peak level: -18.38, volume: 85%, Volume change: 5.000000%
DEBUG:root:Sampling, recorded 19 samples
INFO:root:Sampling complete, ending process
INFO:root:Player: Stopping
INFO:root:Recorder: Stopping
DEBUG:root:Band (7235.16,7321.29) contains a magnitude peak
INFO:root:PASS: Test frequency of 7278.22265625 in band (7235.16, 7321.29) which c...

Hi Jeffrey:

Adjusting the recording volume won't help, since the test script modifies that itself to get a good recording. This may not be working as intended :/

Since the report says there's a magnitude peak at (86, 172), I think it's just picking up background noise which is drowning out the control frequency. Fortunately, there's a way to tell for sure.

Could you please run the audio_test script with

- u /tmp/spectrum.csv -a /tmp/audio.wav

and attach those two files for analysis? This will let us see exactly what the script is detecting and perhaps tweak it to get a good result.

The first file contains the spectrum data points, you can plot them with e.g. quickplot, there should be a peak at about 7 kHz, this may be too small for the script to consider a valid signal.

The second file is exactly what the test script is "hearing". If you play that back and can't hear the high-pitched control sound, a volume setting may be too low somewhere.

Anyway, please send those files my way and we can find a solution.

could not hear any high pitch sound at all.
And can see a peak in spectrum.csv

Hi Jeffrey,

It looks like the microphone is catching a lot of noise, and the control frequency is very faint on this system.

I played the .wav file at a very high volume with headphones (careful when doing this!) and at the very end I can faintly hear the high-pitched sound.

Also, as you mention, it *is* present in the .csv file showing the spectrum analysis.

But here's the problem: the script has a sensitivity parameter, so it requires the "peak" from the control frequency to be at least 2.5 dB higher than the base level in the recording.

In this case, the base level is at -60.0 dB, so the peak would have to have a magnitude of -57.5 or higher (higher as in "less negative").

However, looking at the data, the peak is too small, here are the relevant data points:

7149.0234375,-60.0
7235.15625,-59.795244979858396 <- this is the one for the control frequency
7321.2890625,-59.99746189117432
7407.421875,-60.0

Since it's only 0.21 dB higher, it's not being considered as a valid peak.

Jeffrey, I'm attaching a tweaked version of the audio_test script, it will use a higher volume and "listen" for longer so it has a better chance of getting a good signal.

Could you please run it (audio_test_1070776 -d -u /tmp/spectrum.csv -a /tmp/audio.wav), post the output and attach both spectrum.csv and audio.wav files? Also, of course, please check whether the script succeeds this time.

Hopefully if these tweaks help solve the problem I can incorporate them into the release version of the script.

Thanks!

Hi Daniel

I think this new script does help a little bit.
I can sometimes see PASS result with no command line parameters, 2 out of 10 runs.

Wondering if there's any reason that we have to run with 8000Hz?
Tried a few different frequency, and found 5000Hz is much more stable on hardware.
Not sure if my on-board MIC recorded too much fan noise, so high pitch sound was not recorded.
Using external MIC can also always get PASS result with default setting.
Any comment?

Hi Jeffrey,

So if you change the frequency to 5000 Hz, what's the pass percentage? (i.e. if you do 10 runs, how many will pass?).

7000 Hz was chosen more or less arbitrarily, it's high enough to be unaffected by most ambient noise, while not too high that the system's speakers are unable to handle it. We can certainly change this to something closer to 5000 Hz if you think it will work better for you.

I'm thinking the on-board microphone on that system is a bit undersensitive. One thing you could try is running the audio test and speaking while it's running, if you can then attach the audio file so we can compare the relative magnitude of speech versus the control frequency that would be interesting.

Once we have that sample and your report on using 5000 Hz and how it behaves, we can decide whether to incorporate these changes into the script.

Thanks!

For 5000, pass 5 out of 5.
I would try to find more system that failed currently, and see if the result will be different with 5000.
And my hardware is not a production version, but recording my voice seems ok, didn't distort.

Hi Jeffrey,

OK, so it looks like the microphone is heavily optimized for human voice frequency ranges, 7 kHz is outside that range.

One last test before I make a proposal with these changes. Could you run the original script with the 5 KHz frequency and tell me the pass rate you get? The difference is that the original script uses a lower volume, I prefer to do this to avoid damaging the system's speakers, instead of using the 90% volume from the modified script.

1 - Run /usr/local/checkbox/scripts/audio_test -f 5000, try running this maybe 5-10 times and let me know the pass rate
2 - Run /usr/local/checkbox/scripts/audio_test -f 5000 -u /tmp/spectrum5.csv -a /tmp/audio5.wav
3 - Attach the above generated files (just so we can listen and compare what the microphone is getting in both cases).
4 - Finally a torture test: plug in a set of headphones, wrap the headphones with a jacket or something to muffle the sound, keep them away from the built-in microphone then run the script as in the first step. The script should FAIL in this case, as it will not pick the sound from the headphones. Try this a few times, they should all fail.

This should be the last set of tests I'll ask you to do, once we have this information we should be OK to change to 5kHz if all works well.

Thanks!

Hi Daniel

After check tens of recent test result from ODM images, it seems the result are mostly ok.
Only some old platform, mine test platform, or some old report get failed.

I'm satisfied with current status, not sure if kernel or alsa update has anything to do with that.
If it's ok, could you mark this as fix committed?

New set of changes have been proposed, once they're merged I can mark as fix committed.

Thanks!