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

Issue 756185 link

Starred by 1 user
Status: Assigned
Owner:
brandstrom@chromium.org
Cc:
█ itspeter@chromium.org
hychao@chromium.org
█ katierh@chromium.org
cychiang@chromium.org
chromeos-audio-bugs@google.com
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux
Pri: 2
Type: Bug



Sign in to add a comment

cras_server reports ERROR/FAILURE

Project Member Reported by mzhuo@chromium.org, Aug 16 2017 
Chrome Version: (copy from chrome://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

What steps will reproduce the problem?
(1) When running volume test or  mute/unmute testing "cras_test_client" is run each time when setting volume


What is the expected result?
cras_test_client returns correct output

What happens instead?
======================
seems cras_server does not reply.

log
====

06:29:53 INFO | autoserv| cmd : cras_test_client --dump_server_info | awk '/Output Nodes:/,/Input Devices:/' | grep -E 'USB' | grep '*Hangouts Meet speakermic' |  awk -v N=2 '{print $N}'

06:29:54 INFO | autoserv| [stderr] cras_test_client: cras_client: server connect failed: Resource temporarily unavailable

06:29:55 INFO | autoserv| [stderr] cras_test_client: cras_client: Connect server failed: Connection timed out


During same period when autotest script reports  "cras_client: server connect failed: Resource temporarily unavailable", /var/log/message shows:
============================================================
2017-08-16T04:29:03.671661-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:03.671722-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:08.775676-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:08.775739-07:00 ERR cras_server[3675]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:08.775747-07:00 ERR cras_server[3675]: Init device retry failed
2017-08-16T04:29:13.879728-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:13.879801-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:18.983586-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:18.983675-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:24.087459-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:24.087484-07:00 ERR cras_server[3675]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:24.087487-07:00 ERR cras_server[3675]: Init device retry failed
2017-08-16T04:29:29.191674-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:29.191757-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:34.359652-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 1, format: 2
2017-08-16T04:29:35.387179-07:00 ERR cras_server[3675]: fetch err: -32 for 40000
2017-08-16T04:29:38.797182-07:00 ERR cras_server[3675]: fetch err: -32 for 20000
2017-08-16T04:29:39.463534-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 1, format: 2
2017-08-16T04:29:39.463587-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:44.567506-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:44.567557-07:00 ERR cras_server[3675]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:44.567566-07:00 ERR cras_server[3675]: Init device retry failed
2017-08-16T04:29:49.671455-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 1, format: 2
2017-08-16T04:29:49.671486-07:00 ERR cras_server[3675]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
2017-08-16T04:29:49.671490-07:00 ERR cras_server[3675]: Init device retry failed
2017-08-16T04:29:54.775450-07:00 ERR cras_server[3675]: hw_params: Input/output error: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2017-08-16T04:29:54.775490-07:00 ERR cras_server[3675]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -5
debug-logs_20170816-140002.tgz
9.5 MB Download

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

Cc: katierh@chromium.org

Comment 2 by pprabhu@chromium.org, Aug 17 2017

Components: -Infra>Client>ChromeOS OS>Kernel>Audio
This is not an infra issue.
Redirecting to OS>Kernel>Audio as best guess.

Comment 3 by choonc@google.com, Aug 22 2017

Cc: -istpeter@google.com hychao@chromium.org ar...@chromium.org
Owner: itspeter@chromium.org
Peter, Hsin-yu, can you guys take a stab at it?

Comment 4 by itspeter@chromium.org, Aug 23 2017

Cc: itspeter@chromium.org
Owner: mzhuo@chromium.org
Status: Assigned (was: Untriaged)
Yes. Let me try to reproduce it once our Bluestreak unit arrived.

Min, do you forget to provide the 
1. Script running muted/ unmted.
2. The atuotest name ?

Comment 5 by mzhuo@chromium.org, Sep 18 2017

Labels: M-61

Comment 6 by mzhuo@chromium.org, Dec 16 2017

Labels: M-63
Got it reproduced with R63-10032.71.1.

autotest name is enterprise_CFM_Test.test.

log
---
2017-12-15T19:43:06.542658-08:00 ERR cras_server[1407]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -2
2017-12-15T19:43:06.545949-08:00 ERR cras_server[1407]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -2
2017-12-15T19:43:06.658262-08:00 ERR chrome[961]: [961:961:1215/194306.658232:INFO:app_launch_controller.cc(364)] App window created, closing splash screen.
2017-12-15T19:43:06.902125-08:00 ERR chrome[961]: [961:961:1215/194306.902088:INFO:remote_commands_invalidator.cc(32)] Initialize RemoteCommandsInvalidator.
2017-12-15T19:43:07.543408-08:00 ERR cras_server[1407]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -2
2017-12-15T19:43:07.543433-08:00 ERR cras_server[1407]: Init device retry failed
2017-12-15T19:43:08.291174-08:00 ERR cras_server[1407]: Init Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -2
2017-12-15T19:43:09.243115-08:00 ERR chrome[961]: [961:961:1215/194309.243062:INFO:remote_commands_invalidator.cc(45)] Shutdown RemoteCommandsInvalidator.
2017-12-15T19:43:09.243182-08:00 ERR chrome[961]: [961:961:1215/194309.243165:INFO:remote_commands_invalidator.cc(68)] Stopping RemoteCommandsInvalidator.
2017-12-15T19:43:09.243210-08:00 ERR chrome[961]: [961:961:1215/194309.243197:INFO:remote_commands_invalidator.cc(32)] Initialize RemoteCommandsInvalidator.
2017-12-15T19:43:09.292606-08:00 ERR cras_server[1407]: Enable Hangouts Meet speakermic: USB Audio:0,0 failed, rc = -2
2017-12-15T19:43:09.292632-08:00 ERR cras_server[1407]: Init device retry failed


it happens after the following tests run by scripts. 
mzhuo@minzhuo2:~/chromiumos/chroot$ grep -E "Start_test|bsd ring|Verification_fail|skip|Skip|Init device retry failed" tmp/R63-10032.71.1/100.107.146.22/debug/test_that.INFO 
12/15 22:18:25.720 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:18:47.222 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:19:14.552 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:19:33.920 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:19:54.317 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:20:34.815 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 22:20:34.816 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:21:12.057 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:22:17.283 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:23:20.819 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 22:23:20.820 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:24:37.022 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:25:51.016 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:26:20.851 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:27:05.066 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:27:41.451 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:28:16.991 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:28:56.382 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 22:28:56.383 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:29:41.653 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:30:42.827 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:31:43.153 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 22:31:43.154 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:32:29.520 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:33:24.575 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:34:49.519 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:35:32.093 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:36:01.399 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:37:08.928 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:38:25.496 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 22:38:25.496 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:38:51.797 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:39:57.228 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:40:21.486 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 22:40:21.487 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:41:27.655 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:42:03.304 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:43:04.961 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:43:48.589 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:44:31.891 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:45:02.097 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:45:54.364 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 22:45:54.364 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:46:21.759 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:47:34.163 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:48:36.735 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 22:49:49.099 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:50:17.941 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:51:24.700 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:52:31.135 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 22:52:46.632 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:53:31.056 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 22:54:16.605 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 22:54:16.605 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:55:08.871 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:56:03.237 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 22:56:21.731 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 22:56:21.731 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 22:57:18.976 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:58:39.736 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 22:59:52.979 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 23:00:18.413 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 23:01:21.872 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 23:02:17.409 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 23:03:31.875 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 23:03:31.876 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 23:04:17.129 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 23:04:39.489 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_camera_test.
12/15 23:05:55.990 INFO | test_runner_utils:0199| autoserv| Start_test:gpio_test.
12/15 23:05:55.990 INFO | test_runner_utils:0199| autoserv| Skip reboot CfM test
12/15 23:06:30.235 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 23:07:14.896 INFO | test_runner_utils:0199| autoserv| Start_test:meeting_test.
12/15 23:08:26.882 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 23:09:05.339 INFO | test_runner_utils:0199| autoserv| Start_test:speaker_volume_test.
12/15 23:10:18.038 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 23:11:01.598 INFO | test_runner_utils:0199| autoserv| Start_test:mute_unmute_mic_test.
12/15 23:11:37.001 INFO | test_runner_utils:0199| autoserv| Start_test:reboot_test.
12/15 23:12:47.656 INFO | test_runner_utils:0199| autoserv| ---Error_Found:in_log_file:messages:2017-12-15T21:11:53.401865-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.656 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:55.292591-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.657 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:53.401865-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.658 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:55.292591-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.659 INFO | test_runner_utils:0199| autoserv| 100.107.146.22:Verification_fail:check_audio_errorlog:Error_Found:in_log_file:messages:2017-12-15T21:11:53.401865-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.659 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:55.292591-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.660 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:53.401865-08:00 ERR cras_server[2007]: Init device retry failed
12/15 23:12:47.661 INFO | test_runner_utils:0199| autoserv| 2017-12-15T21:11:55.292591-08:00 ERR cras_server[2007]: Init device retry failed
mzhuo@minzhuo2:
100.107.146.22.debug-logs_20171215-214730.tgz
8.8 MB Download

Comment 7 by tovep@chromium.org, Dec 20 2017

Owner: brandstrom@chromium.org
brandstrom, Do you think these -5 error messages originates from the Atrus?

Comment 8 by tovep@chromium.org, Jan 11 2018

Labels: -M-61 -M-63 M-64

Comment 9 by tovep@chromium.org, Jan 16 2018

Labels: -M-64 M-65

Comment 10 by brandstrom@google.com, May 28 2018 

Is this still an issue?

Comment 11 by ar...@chromium.org, Oct 8

Cc: -ar...@chromium.org
►

Sign in to add a comment