On 11/20/15 02:12, Alexandre Ratchov wrote:
On Thu, Nov 19, 2015 at 12:48:08PM -0700, luke call wrote:
$cat sndiod-log
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat/aucat0|ini): created
this is very strange, sndiod would have logged all the audio
traffic. Could you check that this is the right file or that
programs are not bypassing sndiod for any reason ?
It's the right file, or at least it was created at that time,
evidently as a direct result of the -ddd switch. I'm not aware
of what else could have created it.
Could sndiod have got into a state where it quits logging
(maybe somehow related to the audio looping w/ the same beep
for a long time)? Or, needs a poke to flush a log buffer
to disk? or more -d's?
Is the error message from timidity (midi-playing client)
relevant?:
io_open() failed
Couldn't open sndio mode (`s')
How would I determine if
something bypasses sndiod? E.g., would some other
client program give more helpful info, at least about what
it's trying to do and how it's trying it, like aucat or
something? Should I be running something akin to
linux's strace to really dig at some angle? (I'm
not remembering the openbsd equivalent.)
the surprising part is the length of the sndiod-log file.
You could try to start sndiod in one window:
doas pkill sndiod
doas sndiod -ddd
then play silence with aucat in another window:
aucat -i /dev/zero
you should see a lot of messages output by sndiod:
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat/aucat0|ini): created
ignored huge clock delta
sock(sock|ini): created
sock,rmsg,widl: AUTH message
sock,rmsg,widl: HELLO message
sock,rmsg,widl: hello from <aucat>, mode = 1, ver 7
sock,rmsg,widl: using snd0 pst=cfg.default, mode = 1
aucat0: overwritten slot 0
snd0 pst=cfg: device requested
sio(rsnd/0|ini): created
snd0 pst=ini: 48000Hz, s16le, play 0:1, rec 0:1, 8 blocks of 960 frames
...
...
they indicate whan aucat is doing with the sound device. If I run
timidity, I get similar messages. I'll look at what timidity does;
meanwhile could you try to make programs not bypass sndiod?
This could be caused by, an AUDIODEVICE environment variable, or
deleted /tmp/aucat/ directory (or bad permissions) or multiple
sndiod processes running
on my machine:
$ pgrep -x sndiod
7941
$ /bin/ls -al /tmp/aucat/
total 8
drwxr-xr-x 2 root wheel 512 Nov 20 10:08 .
drwxrwxrwt 8 root wheel 512 Nov 20 10:03 ..
srw-rw-rw- 1 root wheel 0 Nov 20 10:08 aucat0
and I've no AUDIODEVICE environment variable. Could there some
timidity configuration files or environment variables that force
tell it to bypass sndiod.
Here's what I get. This output shows the switching between the two users
(root and a regular user) who are running the commands:
#pkill sndiod
#sndiod -ddd 2>&1 | tee /tmp/sndiod.log
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat/aucat0|ini): created
[and that's all until i killed it after doing the next audio cmds as
other user]
$aucat -i /dev/zero
[wait several seconds]
^C
$echo $AUDIODEVICE
$ls -ltrd /tmp/aucat
drwx------ 2 root wheel 512B Nov 20 09:39 /tmp/aucat/
$ls -ltr /tmp/aucat
ls: aucat: Permission denied
[and timidity playing a .mid file was working]
[then i killed sndiod with ^C.]
#ls -ltr /tmp/aucat
total 0
srw-rw-rw- 1 root wheel 0 Nov 20 09:39 aucat0
#ls -ltrd /tmp/aucat
drwx------ 2 root wheel 512 Nov 20 09:39 /tmp/aucat
#ps aux|grep -i sndiod
root 22835 0.0 0.0 304 704 p1 R+ 9:47AM 0:00.00 grep
-i sndiod
#umask
0077
#sndiod -ddd 2>&1 | tee /tmp/sndiod.log
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat/aucat0|ini): created
^Z
[1]+ Stopped sndiod -ddd 2>&1 | tee /tmp/sndiod.log
#bg
[1]+ sndiod -ddd 2>&1 | tee /tmp/sndiod.log &
#ps aux|grep -i sndiod
_sndio 30197 0.0 0.0 416 1368 p1 S< 9:52AM 0:00.00 sndiod
-ddd
#ktrace -aid -p 30197
#echo $?
0
#l *out
-rw------- 1 root wheel 63.1K Nov 20 09:53 ktrace.out
$aucat -i /dev/zero
[wait several seconds.]
^C
$timidity *mid
Playing aislean.mid
MIDI file: aislean.mid
Format: 1 Tracks: 3 Divisions: 240
^CTerminated sig=0x02
[the above cmd did play music]
#ktrace -C
#l *out
-rw------- 1 root wheel 63.1K Nov 20 09:53 ktrace.out
#l /tmp/*log
-rw------- 1 root wheel 92B Nov 20 09:53 /tmp/sndiod.log
#cat /tmp/*log
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat/aucat0|ini): created
#
Could the root umask of 0077 be a problem? my /tmp/aucat directory
has different permissions than yours. I set that umask for all
users to avoid forgetfully
bleeding information between accounts. (I've found that the umask
cannot have that restrictive setting for reliably running pkg_add, so
I have a script that sets it back to the default for that purpose when
needed, though it seems like it would be better for packages to
reliably set the permissions they need and not depend on the root
environment -- but perhaps I'm ignorant there.)
Also, in case it matters, I do much of my non-root X work via local
ssh connections. But the audio issues happen with or without ssh.
I have put the above ktrace.out file, & a dump of it, at
ftp://onemodel.org/kdump.out
ftp://onemodel.org/ktrace.out
...in case that helps see why nothing was logged by sndiod. There are
some errors mentioned in it.
Thanks, Alexandre.
Luke
