sound: -EPERM on first mplayer invocation

public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed

* sound: -EPERM on first mplayer invocation
@ 2009-08-02 21:36 Denys Vlasenko
  2009-08-03  6:55 ` Takashi Iwai
  0 siblings, 1 reply; 9+ messages in thread
From: Denys Vlasenko @ 2009-08-02 21:36 UTC (permalink / raw)
  To: Takashi Iwai; +Cc: linux-kernel

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

static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
                              struct snd_ctl_elem_value *control)
{
        struct snd_kcontrol *kctl;
        struct snd_kcontrol_volatile *vd;
        unsigned int index_offset;
        int result;

        down_read(&card->controls_rwsem);
        kctl = snd_ctl_find_id(card, &control->id);
        if (kctl == NULL) {
                result = -ENOENT;
        } else {
                index_offset = snd_ctl_get_ioff(kctl, &control->id);
                vd = &kctl->vd[index_offset];
                if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
                    kctl->put == NULL ||
                    (file && vd->owner && vd->owner != file)) {
 printk("EPERM:\n");
 printk("vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE:%x\n", vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE);
 printk("kctl->put:%p\n", kctl->put);
 printk("file:%p vd->owner:%p\n", file, vd->owner);
                        result = -EPERM;
                } else {

The above printk triggers and prints:

EPERM:
vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE:2
kctl->put:ffffffffa009e8de
file:ffff88007c56a5c0 vd->owner:ffff88007bc34740

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?
-- 
vda

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-02 21:36 sound: -EPERM on first mplayer invocation Denys Vlasenko
@ 2009-08-03  6:55 ` Takashi Iwai
  2009-08-04  9:01   ` Denys Vlasenko
  0 siblings, 1 reply; 9+ messages in thread
From: Takashi Iwai @ 2009-08-03  6:55 UTC (permalink / raw)
  To: Denys Vlasenko; +Cc: linux-kernel

At Sun, 2 Aug 2009 23:36:48 +0200,
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
> 
> static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
>                               struct snd_ctl_elem_value *control)
> {
>         struct snd_kcontrol *kctl;
>         struct snd_kcontrol_volatile *vd;
>         unsigned int index_offset;
>         int result;
> 
>         down_read(&card->controls_rwsem);
>         kctl = snd_ctl_find_id(card, &control->id);
>         if (kctl == NULL) {
>                 result = -ENOENT;
>         } else {
>                 index_offset = snd_ctl_get_ioff(kctl, &control->id);
>                 vd = &kctl->vd[index_offset];
>                 if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
>                     kctl->put == NULL ||
>                     (file && vd->owner && vd->owner != file)) {
>  printk("EPERM:\n");
>  printk("vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE:%x\n", vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE);
>  printk("kctl->put:%p\n", kctl->put);
>  printk("file:%p vd->owner:%p\n", file, vd->owner);
>                         result = -EPERM;
>                 } else {
> 
> The above printk triggers and prints:
> 
> EPERM:
> vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE:2
> kctl->put:ffffffffa009e8de
> file:ffff88007c56a5c0 vd->owner:ffff88007bc34740
> 
> 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*".


Takashi

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-03  6:55 ` Takashi Iwai
@ 2009-08-04  9:01   ` Denys Vlasenko
  2009-08-04  9:16     ` Takashi Iwai
  0 siblings, 1 reply; 9+ messages in thread
From: Denys Vlasenko @ 2009-08-04  9:01 UTC (permalink / raw)
  To: Takashi Iwai; +Cc: linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-04  9:01   ` Denys Vlasenko
@ 2009-08-04  9:16     ` Takashi Iwai
  2009-08-05  2:32       ` Denys Vlasenko
  0 siblings, 1 reply; 9+ messages in thread
From: Takashi Iwai @ 2009-08-04  9:16 UTC (permalink / raw)
  To: Denys Vlasenko; +Cc: linux-kernel

At Tue, 4 Aug 2009 11:01:43 +0200,
Denys Vlasenko wrote:
> 
> 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,

Hm, but according to your debug session, the vd->owner is set
to a different value, right?  Check vd->owner_pid in the error path.
It'll show the pid blocking that control element.


Takashi

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-04  9:16     ` Takashi Iwai
@ 2009-08-05  2:32       ` Denys Vlasenko
  2009-08-05  5:37         ` Takashi Iwai
  0 siblings, 1 reply; 9+ messages in thread
From: Denys Vlasenko @ 2009-08-05  2:32 UTC (permalink / raw)
  To: Takashi Iwai; +Cc: linux-kernel

On Tuesday 04 August 2009 11:16, Takashi Iwai wrote:
> > > > 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,
> 
> Hm, but according to your debug session, the vd->owner is set
> to a different value, right?  Check vd->owner_pid in the error path.
> It'll show the pid blocking that control element.

I modified 2.6.31-rc2 source as follows:

static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
                              struct snd_ctl_elem_value *control)
{
        struct snd_kcontrol *kctl;
        struct snd_kcontrol_volatile *vd;
        unsigned int index_offset;
        int result;

        down_read(&card->controls_rwsem);
        kctl = snd_ctl_find_id(card, &control->id);
        if (kctl == NULL) {
                result = -ENOENT;
        } else {
                index_offset = snd_ctl_get_ioff(kctl, &control->id);
                vd = &kctl->vd[index_offset];
if (file && vd->owner)
 printk("file:%p vd->owner:%p\n", file, vd->owner);
                if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
                    kctl->put == NULL ||
                    (file && vd->owner && vd->owner != file)) {
if (file && vd->owner)
 printk("vd->owner_pid:%d vd->owner->pid:%d file->pid:%d\n", vd->owner_pid, vd->owner->pid, file->pid);
                        result = -EPERM;
                } else {
...

and when I start mplayer, I see this:

dmesg:
file:ffff8800798af940 vd->owner:ffff8800798af940
file:ffff8800798af940 vd->owner:ffff8800798af940

I assume it's some sort of initialization, no EPERM here.
Then I press "lower the volume" key (keypad "/")
in mplayer window, twice:

dmesg:
file:ffff8800798af8c0 vd->owner:ffff8800798af940
vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
file:ffff8800798af740 vd->owner:ffff8800798af940
vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067

mplayer:
alsa-control: error setting left channel, Operation not permitted

The pid is mplayer's pid:

# ps -A | grep mpl
 2067 root       0:01 mplayer The_league_of_extraordinary_gentlemen.avi
 2081 root       0:00 grep mpl

It has one thread, btw, no funky multithreading stuff:

# ls -l /proc/2067/task
dr-xr-xr-x    4 root     root            0 Aug  5 04:28 2067

-- 
vda

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-05  2:32       ` Denys Vlasenko
@ 2009-08-05  5:37         ` Takashi Iwai
  2009-08-05  5:41           ` Takashi Iwai
  0 siblings, 1 reply; 9+ messages in thread
From: Takashi Iwai @ 2009-08-05  5:37 UTC (permalink / raw)
  To: Denys Vlasenko; +Cc: linux-kernel

At Wed, 5 Aug 2009 04:32:34 +0200,
Denys Vlasenko wrote:
> 
> On Tuesday 04 August 2009 11:16, Takashi Iwai wrote:
> > > > > 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,
> > 
> > Hm, but according to your debug session, the vd->owner is set
> > to a different value, right?  Check vd->owner_pid in the error path.
> > It'll show the pid blocking that control element.
> 
> I modified 2.6.31-rc2 source as follows:
> 
> static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
>                               struct snd_ctl_elem_value *control)
> {
>         struct snd_kcontrol *kctl;
>         struct snd_kcontrol_volatile *vd;
>         unsigned int index_offset;
>         int result;
> 
>         down_read(&card->controls_rwsem);
>         kctl = snd_ctl_find_id(card, &control->id);
>         if (kctl == NULL) {
>                 result = -ENOENT;
>         } else {
>                 index_offset = snd_ctl_get_ioff(kctl, &control->id);
>                 vd = &kctl->vd[index_offset];
> if (file && vd->owner)
>  printk("file:%p vd->owner:%p\n", file, vd->owner);
>                 if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
>                     kctl->put == NULL ||
>                     (file && vd->owner && vd->owner != file)) {
> if (file && vd->owner)
>  printk("vd->owner_pid:%d vd->owner->pid:%d file->pid:%d\n", vd->owner_pid, vd->owner->pid, file->pid);
>                         result = -EPERM;
>                 } else {
> ...
> 
> and when I start mplayer, I see this:
> 
> dmesg:
> file:ffff8800798af940 vd->owner:ffff8800798af940
> file:ffff8800798af940 vd->owner:ffff8800798af940
> 
> I assume it's some sort of initialization, no EPERM here.
> Then I press "lower the volume" key (keypad "/")
> in mplayer window, twice:
> 
> dmesg:
> file:ffff8800798af8c0 vd->owner:ffff8800798af940
> vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
> file:ffff8800798af740 vd->owner:ffff8800798af940
> vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067

The file instances are different.  It implies that mplayer opens the
device at each time but doesn't close.
It sounds like a bug in mplayer to me.


Takashi

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-05  5:37         ` Takashi Iwai
@ 2009-08-05  5:41           ` Takashi Iwai
  2009-08-05  8:50             ` Clemens Ladisch
  2009-08-05 22:00             ` Denys Vlasenko
  0 siblings, 2 replies; 9+ messages in thread
From: Takashi Iwai @ 2009-08-05  5:41 UTC (permalink / raw)
  To: Denys Vlasenko; +Cc: linux-kernel

At Wed, 05 Aug 2009 07:37:30 +0200,
I wrote:
> 
> At Wed, 5 Aug 2009 04:32:34 +0200,
> Denys Vlasenko wrote:
> > 
> > On Tuesday 04 August 2009 11:16, Takashi Iwai wrote:
> > > > > > 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,
> > > 
> > > Hm, but according to your debug session, the vd->owner is set
> > > to a different value, right?  Check vd->owner_pid in the error path.
> > > It'll show the pid blocking that control element.
> > 
> > I modified 2.6.31-rc2 source as follows:
> > 
> > static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
> >                               struct snd_ctl_elem_value *control)
> > {
> >         struct snd_kcontrol *kctl;
> >         struct snd_kcontrol_volatile *vd;
> >         unsigned int index_offset;
> >         int result;
> > 
> >         down_read(&card->controls_rwsem);
> >         kctl = snd_ctl_find_id(card, &control->id);
> >         if (kctl == NULL) {
> >                 result = -ENOENT;
> >         } else {
> >                 index_offset = snd_ctl_get_ioff(kctl, &control->id);
> >                 vd = &kctl->vd[index_offset];
> > if (file && vd->owner)
> >  printk("file:%p vd->owner:%p\n", file, vd->owner);
> >                 if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
> >                     kctl->put == NULL ||
> >                     (file && vd->owner && vd->owner != file)) {
> > if (file && vd->owner)
> >  printk("vd->owner_pid:%d vd->owner->pid:%d file->pid:%d\n", vd->owner_pid, vd->owner->pid, file->pid);
> >                         result = -EPERM;
> >                 } else {
> > ...
> > 
> > and when I start mplayer, I see this:
> > 
> > dmesg:
> > file:ffff8800798af940 vd->owner:ffff8800798af940
> > file:ffff8800798af940 vd->owner:ffff8800798af940
> > 
> > I assume it's some sort of initialization, no EPERM here.
> > Then I press "lower the volume" key (keypad "/")
> > in mplayer window, twice:
> > 
> > dmesg:
> > file:ffff8800798af8c0 vd->owner:ffff8800798af940
> > vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
> > file:ffff8800798af740 vd->owner:ffff8800798af940
> > vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
> 
> The file instances are different.  It implies that mplayer opens the
> device at each time but doesn't close.
> It sounds like a bug in mplayer to me.

... or the first control handle keeps opened and blocks it.
A question is how is your PCM configuration and which control element
is locked?  The latter can be seen by adding a printk of kctl->id.name.


Takashi

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-05  5:41           ` Takashi Iwai
@ 2009-08-05  8:50             ` Clemens Ladisch
  2009-08-05 22:00             ` Denys Vlasenko
  1 sibling, 0 replies; 9+ messages in thread
From: Clemens Ladisch @ 2009-08-05  8:50 UTC (permalink / raw)
  To: Takashi Iwai; +Cc: Denys Vlasenko, linux-kernel

Takashi Iwai wrote:
> I wrote:
> > The file instances are different.  It implies that mplayer opens the
> > device at each time but doesn't close.
> > It sounds like a bug in mplayer to me.
> 
> ... or the first control handle keeps opened and blocks it.

mplayer indeed leaks the mixer handle.  This happens if setting the
volume fails, i.e., _after_ this message:
> > > > > > > alsa-control: error setting left channel, Operation not permitted


Best regards,
Clemens

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: sound: -EPERM on first mplayer invocation
  2009-08-05  5:41           ` Takashi Iwai
  2009-08-05  8:50             ` Clemens Ladisch
@ 2009-08-05 22:00             ` Denys Vlasenko
  1 sibling, 0 replies; 9+ messages in thread
From: Denys Vlasenko @ 2009-08-05 22:00 UTC (permalink / raw)
  To: Takashi Iwai, mplayer-users; +Cc: linux-kernel

[Added mplayer-users@mplayerhq.hu to To:]

On Wednesday 05 August 2009 07:41, Takashi Iwai wrote:
> At Wed, 05 Aug 2009 07:37:30 +0200,
> > > I modified 2.6.31-rc2 source as follows:
> > > 
> > > static int snd_ctl_elem_write(struct snd_card *card, struct snd_ctl_file *file,
> > >                               struct snd_ctl_elem_value *control)
> > > {
> > >         struct snd_kcontrol *kctl;
> > >         struct snd_kcontrol_volatile *vd;
> > >         unsigned int index_offset;
> > >         int result;
> > > 
> > >         down_read(&card->controls_rwsem);
> > >         kctl = snd_ctl_find_id(card, &control->id);
> > >         if (kctl == NULL) {
> > >                 result = -ENOENT;
> > >         } else {
> > >                 index_offset = snd_ctl_get_ioff(kctl, &control->id);
> > >                 vd = &kctl->vd[index_offset];
> > > if (file && vd->owner)
> > >  printk("file:%p vd->owner:%p\n", file, vd->owner);
> > >                 if (!(vd->access & SNDRV_CTL_ELEM_ACCESS_WRITE) ||
> > >                     kctl->put == NULL ||
> > >                     (file && vd->owner && vd->owner != file)) {
> > > if (file && vd->owner)
> > >  printk("vd->owner_pid:%d vd->owner->pid:%d file->pid:%d\n", vd->owner_pid, vd->owner->pid, file->pid);
> > >                         result = -EPERM;
> > >                 } else {
> > > ...
> > > 
> > > and when I start mplayer, I see this:
> > > 
> > > dmesg:
> > > file:ffff8800798af940 vd->owner:ffff8800798af940
> > > file:ffff8800798af940 vd->owner:ffff8800798af940
> > > 
> > > I assume it's some sort of initialization, no EPERM here.
> > > Then I press "lower the volume" key (keypad "/")
> > > in mplayer window, twice:
> > > 
> > > dmesg:
> > > file:ffff8800798af8c0 vd->owner:ffff8800798af940
> > > vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
> > > file:ffff8800798af740 vd->owner:ffff8800798af940
> > > vd->owner_pid:0 vd->owner->pid:2067 file->pid:2067
> > 
> > The file instances are different.  It implies that mplayer opens the
> > device at each time but doesn't close.
> > It sounds like a bug in mplayer to me.
> 
> ... or the first control handle keeps opened and blocks it.
> A question is how is your PCM configuration and which control element
> is locked?  The latter can be seen by adding a printk of kctl->id.name.

I see this in dmesg:

file:ffff88007d28e7c0 vd->owner:ffff88007d28e7c0 kctl->id.name:'PCM Playback Volume'
file:ffff88007d28e7c0 vd->owner:ffff88007d28e7c0 kctl->id.name:'PCM Playback Volume'
file:ffff88007d28e740 vd->owner:ffff88007d28e7c0 kctl->id.name:'PCM Playback Volume'
vd->owner_pid:0 vd->owner->pid:2086 file->pid:2086
file:ffff88007d28e5c0 vd->owner:ffff88007d28e7c0 kctl->id.name:'PCM Playback Volume'
vd->owner_pid:0 vd->owner->pid:2086 file->pid:2086

I straced mplayer. I pressed "lower the volume" key
twice within about 3 seconds, then exited mplayer.

I see this in strace (filtered using
"grep -e open -e close -e error -e /dev/ STRACE_LOG"):

...
23:38:19.825798 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.825951 close(6)                = 0
23:38:19.826325 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.826445 close(6)                = 0
23:38:19.826543 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.826870 close(6)                = 0
...
23:38:19.844860 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.844973 close(6)                = 0
23:38:19.845282 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.845390 close(6)                = 0
23:38:19.845500 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.845797 close(6)                = 0
23:38:19.855205 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.855338 close(6)                = 0
23:38:19.855647 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.855755 close(6)                = 0
23:38:19.855848 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.856145 close(6)                = 0
23:38:19.856323 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.856440 close(6)                = 0
23:38:19.856762 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.856870 close(6)                = 0
23:38:19.856964 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.857257 close(6)                = 0
23:38:19.857442 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.857549 close(6)                = 0
23:38:19.857836 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.857943 close(6)                = 0
23:38:19.858038 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.858329 close(6)                = 0
...
23:38:19.874866 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.874977 close(6)                = 0
23:38:19.876461 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.876574 close(6)                = 0
23:38:19.876675 open("/dev/snd/controlC0", O_RDWR) = 6
23:38:19.876977 open("/dev/snd/pcmC0D0p", O_RDWR|O_NONBLOCK) = 7
23:38:19.877202 close(6)                = 0
23:38:19.891060 open("/dev/snd/controlC0", O_RDONLY) = 6
23:38:19.891177 close(6)                = 0
23:38:19.891278 open("/dev/snd/timer", O_RDONLY|O_NONBLOCK) = 6
23:38:19.891781 open("/proc/cpuinfo", O_RDONLY) = 8
23:38:19.892409 close(8)                = 0
23:38:19.892727 open("/dev/snd/controlC0", O_RDONLY) = 8
23:38:19.892834 close(8)                = 0
23:38:19.893166 open("/dev/snd/controlC0", O_RDONLY) = 8
23:38:19.893274 close(8)                = 0
23:38:19.893369 open("/dev/snd/controlC0", O_RDWR) = 8
23:38:19.894819 write(1, "alsa-init: pcm opend in blocking"..., 38) = 38
...
...
	Here I press "lower the volume" key:
23:38:28.343401 open("/dev/snd/controlC0", O_RDONLY) = 9
23:38:28.343530 close(9)                = 0
23:38:28.343630 open("/dev/snd/controlC0", O_RDWR) = 9
23:38:28.354506 close(9)                = 0
23:38:28.354908 open("/dev/snd/controlC0", O_RDONLY) = 9
23:38:28.355024 close(9)                = 0
23:38:28.355119 open("/dev/snd/controlC0", O_RDWR) = 9
23:38:28.365707 write(2, "alsa-control: error setting left"..., 66) = 66
23:38:28.367310 open("/dev/snd/controlC0", O_RDONLY) = 10
23:38:28.367427 close(10)               = 0
23:38:28.367539 open("/dev/snd/controlC0", O_RDWR) = 10
23:38:28.381267 close(10)               = 0
	And again:
23:38:31.503361 open("/dev/snd/controlC0", O_RDONLY) = 10
23:38:31.503489 close(10)               = 0
23:38:31.503589 open("/dev/snd/controlC0", O_RDWR) = 10
23:38:31.514280 close(10)               = 0
23:38:31.514690 open("/dev/snd/controlC0", O_RDONLY) = 10
23:38:31.514805 close(10)               = 0
23:38:31.514899 open("/dev/snd/controlC0", O_RDWR) = 10
23:38:31.525305 write(2, "alsa-control: error setting left"..., 66) = 66
23:38:31.526167 open("/dev/snd/controlC0", O_RDONLY) = 11
23:38:31.526283 close(11)               = 0
23:38:31.526382 open("/dev/snd/controlC0", O_RDWR) = 11
23:38:31.539630 close(11)               = 0
	I press ESC:
23:38:34.385307 close(3)                = 0
23:38:34.403561 close(6)                = 0
23:38:34.403883 close(7)                = 0
23:38:34.404767 close(8)                = 0
23:38:34.404921 write(1, "alsa-uninit: pcm closed\n", 24) = 24
23:38:34.405961 close(5)                = 0

Obviously, mplayer forgets to close fds opened to /dev/snd/controlC0:
first, fd 8; it opens a new one (fd 9) and gets error out of it.
Then, after 1st error, it similarly does not close or reuse fd 9
but opens fd 10.

For mplayer folks: my ~/.mplayer/config is:

msglevel=all=6
ao=alsa
monitoraspect=5:4

And command line is just:

mplayer The_league_of_extraordinary_gentlemen.avi

For completeness, here is unabridged strace from the moment
I press "\" for the 1st time until -EPERM is seen:

23:38:28.342959 read(0, "/", 256)       = 1
23:38:28.343136 stat64("/usr/app/alsa-lib-1.0.17a/share/alsa/alsa.conf", {st_mode=S_IFREG|0644, st_size=9008, ...}) = 0
23:38:28.343401 open("/dev/snd/controlC0", O_RDONLY) = 9
23:38:28.343530 close(9)                = 0
23:38:28.343630 open("/dev/snd/controlC0", O_RDWR) = 9
23:38:28.343736 ioctl(9, USBDEVFS_CONTROL, 0xffd31984) = 0
23:38:28.343846 fcntl64(9, F_GETFL)     = 0x2 (flags O_RDWR)
23:38:28.343984 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
23:38:28.344112 ioctl(9, USBDEVFS_RELEASEINTERFACE, 0xffd31a00) = 0
23:38:28.344214 ioctl(9, USBDEVFS_RELEASEINTERFACE, 0xffd31a00) = 0
23:38:28.344461 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.344606 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.344713 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.344819 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.344916 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.345013 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.345127 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.345226 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.345326 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.345425 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.345535 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.345633 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.345730 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.345830 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.345928 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.346026 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.346123 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.346220 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.346319 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.346417 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.346524 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.346620 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.346717 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.346816 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.346914 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.347012 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.347108 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.347205 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.347304 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.347402 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.347508 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.347604 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.347701 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.347800 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.347898 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.347996 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.348092 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.348188 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.348288 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.348387 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.348493 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.348590 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.348687 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.348787 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.348885 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.348982 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.349079 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.349176 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.349277 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.349373 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.349479 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.349579 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.349677 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.349775 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.349872 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.349969 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.350069 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.350169 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.350269 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.350368 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.350475 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.350573 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.350670 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.350769 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.350866 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.350990 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351091 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.351190 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351286 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351381 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351486 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351586 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.351685 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351780 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.351878 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.351975 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.352072 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.352173 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.352271 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.352369 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.353085 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.353208 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.353330 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.353450 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.353554 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.353653 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.353754 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.353852 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.353953 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.354052 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31760) = 0
23:38:28.354151 ioctl(9, USBDEVFS_IOCTL, 0xffd31320) = 0
23:38:28.354248 ioctl(9, USBDEVFS_IOCTL, 0xffd31330) = 0
23:38:28.354348 ioctl(9, USBDEVFS_DISCONNECT, 0xffd319e8) = 0
23:38:28.354506 close(9)                = 0
23:38:28.354639 stat64("/usr/app/alsa-lib-1.0.17a/share/alsa/alsa.conf", {st_mode=S_IFREG|0644, st_size=9008, ...}) = 0
23:38:28.354908 open("/dev/snd/controlC0", O_RDONLY) = 9
23:38:28.355024 close(9)                = 0
23:38:28.355119 open("/dev/snd/controlC0", O_RDWR) = 9
23:38:28.355226 ioctl(9, USBDEVFS_CONTROL, 0xffd31924) = 0
23:38:28.355321 fcntl64(9, F_GETFL)     = 0x2 (flags O_RDWR)
23:38:28.355415 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
23:38:28.355519 ioctl(9, USBDEVFS_RELEASEINTERFACE, 0xffd319a0) = 0
23:38:28.355620 ioctl(9, USBDEVFS_RELEASEINTERFACE, 0xffd319a0) = 0
23:38:28.355811 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.355913 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.356013 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.356111 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.356208 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.356304 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.356404 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.356511 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.356610 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.356709 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.356809 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.356906 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.357003 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.357104 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.357203 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.357301 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.357398 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.357504 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.357604 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.357702 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.357800 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.357897 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.357993 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.358093 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.358191 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.358289 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.358385 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.358490 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.358590 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.358689 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.358824 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.358921 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.359018 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.359117 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.359215 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.359313 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.359410 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.359515 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.359631 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.359730 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.359827 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.359924 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.360021 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.360121 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.360220 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.360317 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.360414 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.360521 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.360622 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.360719 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.360816 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.360916 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.361014 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.361112 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.361209 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.361307 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.361407 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.361515 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.361616 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.361715 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.361814 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.361971 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.362069 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.362169 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.362266 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.362363 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.362473 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.362572 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.362668 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.362914 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363010 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363112 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.363211 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363307 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363405 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.363511 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.363608 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363744 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.363844 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.363943 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.364040 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.364138 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.364242 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.364342 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.364453 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.364552 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.364652 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.364750 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.364850 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.364948 ioctl(9, USBDEVFS_CONNECTINFO, 0xffd31700) = 0
23:38:28.365046 ioctl(9, USBDEVFS_IOCTL, 0xffd312c0) = 0
23:38:28.365143 ioctl(9, USBDEVFS_IOCTL, 0xffd312d0) = 0
23:38:28.365238 ioctl(9, USBDEVFS_DISCONNECT, 0xffd31988) = 0
23:38:28.365343 ioctl(9, USBDEVFS_IOCTL, 0xffd316b0) = 0
23:38:28.365456 ioctl(9, USBDEVFS_HUB_PORTINFO, 0xffd316b0) = -1 EPERM (Operation not permitted)
23:38:28.365565 ioctl(9, USBDEVFS_IOCTL, 0xffd315b0) = 0
23:38:28.365707 write(2, "alsa-control: error setting left"..., 66) = 66


--
vda

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2009-08-05 21:59 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-08-02 21:36 sound: -EPERM on first mplayer invocation Denys Vlasenko
2009-08-03  6:55 ` Takashi Iwai
2009-08-04  9:01   ` Denys Vlasenko
2009-08-04  9:16     ` Takashi Iwai
2009-08-05  2:32       ` Denys Vlasenko
2009-08-05  5:37         ` Takashi Iwai
2009-08-05  5:41           ` Takashi Iwai
2009-08-05  8:50             ` Clemens Ladisch
2009-08-05 22:00             ` Denys Vlasenko

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox