Re: sound: -EPERM on first mplayer invocation

[Denys Vlasenko <vda.linux@googlemail.com>]

On Monday 03 August 2009 08:55, Takashi Iwai wrote:
> Denys Vlasenko wrote:
> > Hi,
> > 
> > For a long time I observe the following nuisance:
> > when I run mplayer for the very first time after boot,
> > I can't adjust the volume. mplayer spews this to stderr:
> > 
> > alsa-control: error setting left channel, Operation not permitted
> > 
> > This happens even if I login as root and run mplayer as root.
> > 
> > I tracked it down to snd_ctl_elem_write in sound/core/control.c
> > 
...
> > 
> > Thus, vd->owner != file.
> > 
> > As I said, it only happens on very first run of mplayer,
> > and it isn't a recent change, I think I saw it at least
> > for one year with different kernels.
> > 
> > Takashi, any idea what might be happening here?
> > How can I help you more with tracking it down?
> 
> This implies that another process (e.g. a sound daemon like PA)
> already opened the device and locked this specific control element.
> If so, this is no bug but the right behavior.
> Check "fuser /dev/snd/controlC*".

Nothing uses them:

shadow:~# lsof -nP | grep '/dev/.*control'
shadow:~# fuser /dev/snd/controlC*
shadow:~#

I tried running bare X with only xterm and mplayer,
and I see the same symptoms when I try to adjust volume:

...
[Mixer] No hardware mixing, inserting volume filter.
[libaf] Adding filter volume
[dummy] Was reinitialized: 48000Hz/2ch/s16le
alsa-control: error setting left channel, Operation not permitted0 78%
alsa-control: error setting left channel, Operation not permitted0 77%
alsa-control: error setting left channel, Operation not permitted0 76%
alsa-control: error setting left channel, Operation not permitted0 75%
...

Here is the list of processes just before I started mplayer.
AFAICS, no sound daemons:

PID   USER     TIME   COMMAND
    1 root       0:00 /bin/sh /init 
    2 root       0:00 [kthreadd]
    3 root       0:00 [migration/0]
    4 root       0:00 [ksoftirqd/0]
    5 root       0:00 [watchdog/0]
    6 root       0:00 [events/0]
    7 root       0:00 [khelper]
   13 root       0:00 [async/mgr]
  184 root       0:00 [kblockd/0]
  186 root       0:00 [kacpid]
  187 root       0:00 [kacpi_notify]
  188 root       0:00 [kacpi_hotplug]
  284 root       0:00 [ata/0]
  285 root       0:00 [ata_aux]
  289 root       0:00 [ksuspend_usbd]
  293 root       0:00 [khubd]
  296 root       0:00 [kseriod]
  298 root       0:00 [kgameportd]
  356 root       0:00 [khungtaskd]
  357 root       0:00 [pdflush]
  358 root       0:00 [pdflush]
  359 root       0:00 [kswapd0]
  360 root       0:00 [aio/0]
  361 root       0:00 [nfsiod]
  362 root       0:00 [crypto/0]
  551 root       0:00 [scsi_eh_0]
  553 root       0:00 [scsi_eh_1]
  555 root       0:00 [scsi_eh_2]
  557 root       0:00 [scsi_eh_3]
  612 root       0:00 [bnx2x]
  670 root       0:00 [mlx4]
  688 root       0:00 [netxen]
  691 root       0:00 [sfc_refill/0]
  692 root       0:00 [sfc_reset]
  709 root       0:00 [kpsmoused]
  715 root       0:00 [rpciod/0]
  765 root       0:00 [kjournald]
  783 root       0:00 udevd 
  800 root       0:00 [reiserfs/0]
  807 1          0:00 rpc.portmap 
  866 root       0:00 runsvdir -P /var/service _____________________________________________ 
  867 root       0:00 sleep 32000 
  868 root       0:00 runsv fw 
  869 root       0:00 runsv gpm 
  870 root       0:00 runsv ntp 
  871 root       0:00 runsv top 
  872 root       0:00 runsv klog 
  873 logger     0:00 svlogd -tt /var/log/service/ntp 
  876 root       0:00 gpm -D -2 -m /dev/psaux -t ps2 
  880 root       0:00 top 
  884 root       0:00 runsv once 
  885 root       0:00 runsv tftp 
  903 root       0:00 runsv sshd 
  904 root       0:00 runsv vpnc 
  905 root       0:00 runsv ora_db_test1st 
  906 root       0:00 runsv dhcp_if 
  911 logger     0:00 svlogd -tt /var/log/service/klog 
  913 root       0:00 socklog ucspi 
  932 root       0:00 runsv httpd 
  933 root       0:00 runsv httpd_ssl 
  934 root       0:00 runsv vsftp 
  935 root       0:00 runsv proxy-2222-to-22 
  948 root       0:00 runsv ftpd_bbox 
  949 root       0:00 runsv ora_listener 
  950 root       0:00 runsv nfs_v3 
  951 root       0:00 runsv nmeter 
  952 root       0:00 runsv getty_gay 
  953 root       0:00 runsv telnetd_bbox 
  954 root       0:00 runsv clock_server 
  955 root       0:00 runsv getty_tty1 
  966 time       0:00 taiclockd 
  975 root       0:00 runsv getty_tty2 
  976 root       0:00 runsv getty_tty3 
  977 root       0:00 nmeter %t %c x %x p%p f %f b %b m %m if%[nif] 
  994 logger     0:00 svlogd -tt /var/log/service/dhcp_if 
  996 root       0:00 ./udhcpc -vv --hostname=null --foreground --interface=if --pidfile=/.local/var/service/dhcp_if/udhcpc.pid --script=/.local/var/service/dhcp_if/dhcp_handler 
 1004 logger     0:00 svlogd -tt /var/log/service/ora_db_test1st 
 1007 logger     0:00 svlogd -tt /var/log/service/tftp 
 1009 root       0:00 udpsvd -v -c 10 -l localhost 0 69 tftpd /pub/tftp 
 1011 root       0:00 -bash 
 1022 root       0:00 runsv getty_tty4 
 1024 root       0:00 runsv getty_tty5 
 1025 logger     0:00 svlogd -tt /var/log/service/vsftp 
 1028 logger     0:00 svlogd -tt /var/log/service/httpd 
 1035 root       0:00 runsv getty_tty6 
 1036 root       0:00 runsv getty_tty7 
 1037 root       0:00 runsv getty_tty8 
 1038 root       0:00 runsv httpd_bbox 
 1039 root       0:00 runsv syslog 
 1040 root       0:00 runsv tidy_tmp 
 1041 root       0:00 runsv dnscache_int 
 1042 root       0:00 runsv automount 
 1043 root       0:00 runsv crond_bbox 
 1044 root       0:00 runsv dhcpd_if 
 1045 root       0:00 runsv inetd_bbox 
 1046 root       0:00 runsv dhcp_if_pinger 
 1047 logger     0:00 svlogd -tt /var/log/service/sshd 
 1049 logger     0:00 svlogd -tt /var/log/service/httpd_ssl 
 1051 logger     0:00 svlogd -tt /var/log/service/vpnc 
 1053 root       0:00 tcpserver -v -R -H -l 0 -c 40 0.0.0.0 80 setuidgid root httpd -f /.local/var/service/httpd/httpd.conf 
 1055 root       0:00 getty 38400 /dev/tty3 linux 
 1059 root       0:00 getty 38400 /dev/tty8 linux 
 1061 logger     0:00 svlogd -tt /var/log/service/inetd_bbox 
 1075 root       0:00 tcpserver -v -R -H -l 0 -c 40 0.0.0.0 443 stunnel -f -p ../host.pem -l setuidgid -- setuidgid root httpd -f /.local/var/service/httpd_ssl/httpd.conf 
 1077 root       0:00 tcpsvd -vE -l 0 -c 40 0 22 /usr/bin/sshd -i -D -e -p22 -u0 
 1090 logger     0:00 svlogd -tt /var/log/service/automount 
 1092 root       0:00 automount -f -s -v --timeout 15 /.local/mnt/auto program /.local/var/service/automount/mapper.sh 
 1103 root       0:00 getty 38400 /dev/tty5 linux 
 1110 logger     0:00 svlogd -tt /var/log/service/telnetd_bbox 
 1112 logger     0:00 svlogd /var/log/service/syslog 
 1113 logger     0:00 svlogd -tt /var/log/service/tidy_tmp 
 1122 root       0:00 sleep 1260 
 1127 root       0:00 getty 38400 /dev/tty7 linux 
 1157 logger     0:00 svlogd -tt /var/log/service/httpd_bbox 
 1159 root       0:00 tcpserver -v -R -H -l 0 -c 40 0.0.0.0 81 setuidgid root ./busybox httpd -vvv -i -h /.1/video 
 1166 root       0:00 getty 38400 /dev/tty6 linux 
 1171 logger     0:00 svlogd -tt /var/log/service/dnscache_int 
 1173 logger     0:00 svlogd -tt /var/log/service/crond_bbox 
 1179 root       0:00 crond -f -d7 
 1190 root       0:00 syslogd -m 0 -n -S -s 99 -b 9 -O /.local/var/service/syslog/syslog 
 1200 root       0:00 getty 38400 /dev/tty4 linux 
 1205 logger     0:00 svlogd -tt /var/log/service/ora_listener 
 1225 logger     0:00 svlogd -tt /var/log/service/proxy-2222-to-22 
 1229 logger     0:00 svlogd -tt /var/log/service/dhcpd_if 
 1234 logger     0:00 svlogd -tt /var/log/service/ftpd_bbox 
 1236 root       0:00 tcpsvd -vE -l 0 -c 40 0.0.0.0 21 setuidgid root ./busybox ftpd -vv -t10 /.1/video 
 1733 root       0:00 [hd-audio0]
 1741 dns        0:00 dnscache 
 2292 root       0:00 xinit 
 2293 root       0:00 X :0 
 2297 root       0:00 xterm -geometry +1+1 -n login 
 2298 root       0:00 bash 
 2302 root       0:00 ps -A 


When I exit mplayer and start it again, it works.

What can I try next?
-- 
vda