watchdog timed out, no audio output

From: Rasmus Steinke <rasi_at_xssn.at>
Date: Tue Jul 17 2018 - 08:25:03 CEST
Hi, I installed sndiod on my arch linux machine and whenever a client 
tries to send sound, all I get is
"aucat0: watchdog timed out", there is no sound to be heard. Debug 
output of daemon and client below:

##### aucat output:

alarm@alarm ~ > aucat -dddi /dev/urandom
/dev/urandom,pst=cfg: play, chan 0:1, 48000Hz, s16le, vol 32768
default: 48000Hz, play 0:1, 18 blocks of 960 frames
/dev/urandom,pst=cfg: allocated 17280 frame buffer
cmap: nch = 2, ostart = 0, onext = 0, istart = 0, inext = 0
/dev/urandom,pst=ini: chain initialized
/dev/urandom,pst=run: started
started
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: cycle, prime = 18
cmap: adding 960 frames
default: audio device gone, stopping
/dev/urandom,pst=ini: stopped
stopped
/dev/urandom,pst=ini: closed


###### aucat output:

alarm@alarm ~ > sndiod -dddd -L 192.168.0.164
snd0 pst=cfg.default: rec=0:1 play=0:1 vol=23170 dup
listen(/tmp/aucat-1000/aucat0|ini): created
listen(192.168.0.164|ini): created
poll: listen: 1 listen: 1
listen(192.168.0.164|ini): processed in 1us
sock(sock|ini): created
listen(/tmp/aucat-1000/aucat0|ini): processed in 93us
sock,rmsg,widl: no messages to build anymore, idling...
poll: sock: 1 listen: 1 listen: 1
sock,rmsg,widl: reading 40 todo
sock,rmsg,widl: read full message
sock,rmsg,widl: AUTH message
sock,rmsg,widl: reading 40 todo
sock,rmsg,widl: read blocked
sock(sock|ini): processed in 113us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
sock,rmsg,widl: no messages to build anymore, idling...
poll: sock: 1 listen: 1 listen: 1
sock,rmsg,widl: reading 40 todo
sock,rmsg,widl: read full message
sock,rmsg,widl: HELLO message
sock,rmsg,widl: hello from <aucat>, mode = 1, ver 7
aucat0: overwritten slot 0
snd0 pst=cfg: device requested
sio(rsnd/default|ini): created
snd0 pst=ini: 48000Hz, s16le, play 0:1, rec 0:1, 8 blocks of 960 frames
midi0: sending: f0 7d 7f 23 1 0 0 61 75 63 61 74 30 0 0 0 0 f7
midi0: sending: b0 7 7f
aucat0 vol=127,pst=ini: using snd0 pst=ini.default, mode = 1
aucat0 vol=127,pst=ini,rret,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: copied RRET message
aucat0 vol=127,pst=ini,rmsg,wmsg: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: read blocked
sock(sock|ini): processed in 9681us
listen(192.168.0.164|ini): processed in 1us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
poll: sio: sock: 5 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 34us
aucat0 vol=127,pst=ini,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=ini,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=ini,rmsg,widl: writing
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
sock(sock|ini): processed in 218us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 22us
aucat0 vol=127,pst=ini,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,widl: read full message
aucat0 vol=127,pst=ini,rmsg,widl: SETPAR message
aucat0 vol=127,pst=ini,rmsg,widl: playback channels 0:1 -> 0:1
aucat0 vol=127,pst=ini,rmsg,widl: 48000Hz sample rate, 960 frame blocks
aucat0 vol=127,pst=ini,rmsg,widl: 9600 frame buffer
aucat0 vol=127,pst=ini,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,widl: read full message
aucat0 vol=127,pst=ini,rmsg,widl: GETPAR message
aucat0 vol=127,pst=ini,rret,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: copied RRET message
aucat0 vol=127,pst=ini,rmsg,wmsg: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: read blocked
sock(sock|ini): processed in 192us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
poll: sio: sock: 5 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 19us
aucat0 vol=127,pst=ini,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=ini,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=ini,rmsg,widl: writing
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
sock(sock|ini): processed in 810us
listen(192.168.0.164|ini): processed in 1us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 34us
aucat0 vol=127,pst=ini,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,widl: read full message
aucat0 vol=127,pst=ini,rmsg,widl: GETPAR message
aucat0 vol=127,pst=ini,rret,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: copied RRET message
aucat0 vol=127,pst=ini,rmsg,wmsg: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,wmsg: read blocked
sock(sock|ini): processed in 76us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
poll: sio: sock: 5 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 28us
aucat0 vol=127,pst=ini,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=ini,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=ini,rmsg,widl: writing
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
sock(sock|ini): processed in 41us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=ini,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 13us
aucat0 vol=127,pst=ini,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=ini,rmsg,widl: read full message
aucat0 vol=127,pst=ini,rmsg,widl: START message
aucat0 vol=127,pst=ini: playing s16le -> s16le
cmap: nch = 2, ostart = 0, onext = 0, istart = 0, inext = 0
aucat0 vol=127,pst=ini: allocated 9600/17280 fr buffers
aucat0 vol=127,pst=sta: 48000Hz, s16le, play 0:1, 10 blocks of 960 
frames
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read blocked
sock(sock|ini): processed in 119us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rmsg,widl: building FLOWCTL message, count = 
9600, rmax -> 38400
poll: sio: sock: 5 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 16us
aucat0 vol=127,pst=sta,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=sta,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=sta,rmsg,widl: writing
aucat0 vol=127,pst=sta,rmsg,widl: building SETVOL message, vol = 127
aucat0 vol=127,pst=sta,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=sta,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=sta,rmsg,widl: writing
aucat0 vol=127,pst=sta,rmsg,widl: no messages to build anymore, 
idling...
sock(sock|ini): processed in 60us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 13us
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read blocked
sock(sock|ini): processed in 141us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rdat,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 26us
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read blocked
sock(sock|ini): processed in 72us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 17us
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read blocked
sock(sock|ini): processed in 82us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 17us
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read blocked
sock(sock|ini): processed in 67us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=sta,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 12us
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=sta,rmsg,widl: read full message
aucat0 vol=127,pst=sta,rmsg,widl: DATA message
aucat0 vol=127,pst=sta,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=sta,rdat,widl: read complete block
aucat0 vol=127,pst=sta: switching to READY state
snd0 pst=ini: device started
snd0 pst=run: started
aucat0 vol=127,pst=rdy: attached at -7680, delta = 0
aucat0 vol=127,pst=rdy: set weight: 23170/23170
aucat0 vol=127,pst=run,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=run,rmsg,widl: read blocked
sock(sock|ini): processed in 1688us
listen(192.168.0.164|ini): processed in 1us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 7680
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 151us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 6720
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 58us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 5760
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 50us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 4800
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 49us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 3840
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 46us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 2880
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 44us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 1920
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 33us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: empty cycle, prime = 960
snd0 pst=run: wrote 3840 bytes, todo 0/3840
sio(rsnd/default|ini): processed in 145us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
snd0 pst=run: tick, delta = 0
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 29 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: tick, delta = 964
snd0 pst=run: read 3840: bytes, todo 0/3840
snd0 pst=run: full cycle: delta = 4, poffs = 7680
aucat0 vol=127,pst=run: running, skip = 0
cmap: adding 960 frames
aucat0 vol=127,pst=run,rmsg,widl: fill, rmax -> 0, pending -> 960
snd0 pst=run: wrote 240 bytes, todo 3600/3840
sio(rsnd/default|ini): processed in 420us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: building FLOWCTL message, count = 960, 
rmax -> 3840
poll: sio: 2c 29 sock: 5 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 26us
aucat0 vol=127,pst=run,rmsg,wmsg: writing todo = 40
aucat0 vol=127,pst=run,rmsg,wmsg: wrote full message
aucat0 vol=127,pst=run,rmsg,widl: writing
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
sock(sock|ini): processed in 62us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 34us
aucat0 vol=127,pst=run,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=run,rmsg,widl: read full message
aucat0 vol=127,pst=run,rmsg,widl: DATA message
aucat0 vol=127,pst=run,rdat,widl: reading 3840 todo
aucat0 vol=127,pst=run,rdat,widl: read complete block
aucat0 vol=127,pst=run,rmsg,widl: reading 40 todo
aucat0 vol=127,pst=run,rmsg,widl: read blocked
sock(sock|ini): processed in 91us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
sio(rsnd/default|ini): processed in 605us
sock(sock|ini): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
aucat0 vol=127,pst=run,rmsg,widl: no messages to build anymore, 
idling...
poll: sio: 2c 29 sock: 1 listen: 1 listen: 1
snd0 pst=run: watchdog timeout
snd0 pst=run: closing
aucat0 vol=127,pst=run,rmsg,widl: exit
aucat0 vol=127,pst=run,rmsg,widl: closing
aucat0 vol=127,pst=run: stopping
snd0 pst=cfg: device released
sock(sock|zom): destroyed
snd0 pst=cfg: closed
timo_del: not found
sio(rsnd/default|zom): destroyed
sio(rsnd/default|zom): processed in 2us
sock(sock|zom): processed in 0us
listen(192.168.0.164|ini): processed in 0us
listen(/tmp/aucat-1000/aucat0|ini): processed in 0us
poll: listen: 1 listen: 1
Received on Tue, 17 Jul 2018 08:25:03 +0200

This archive was generated by hypermail 2.1.8 : Wed Jul 18 2018 - 01:32:13 CEST