Add traces to help tracking subtle timing bugs often causing

underuns and overruns; such bugs are hard to debug with ktrace
or a debugger. They are also handy to debug or monitor code
using aucat.

To enable traces, compile aucat with ``make DEBUG=-DDEBUG'' and
use the -d option multiple times.

ok jakemsr

18 files changed, 2100 insertions, 15 deletions

diff --git a/usr.bin/aucat/Makefile b/usr.bin/aucat/Makefile
index 5aad09ff145..f652c247fed 100644
--- a/usr.bin/aucat/Makefile
+++ b/usr.bin/aucat/Makefile
@@ -1,8 +1,8 @@
-#	$OpenBSD: Makefile,v 1.10 2009/09/27 11:51:20 ratchov Exp $
+#	$OpenBSD: Makefile,v 1.11 2010/01/10 21:47:41 ratchov Exp $
 
 PROG=	aucat
 SRCS=	aucat.c abuf.c aparams.c aproc.c dev.c midi.c file.c headers.c \
-	safile.c miofile.c sock.c pipe.c listen.c opt.c wav.c legacy.c 
+	safile.c miofile.c sock.c pipe.c listen.c opt.c wav.c legacy.c dbg.c
 MAN=	aucat.1 midicat.1
 LINKS=  ${BINDIR}/aucat ${BINDIR}/midicat
 CFLAGS+= -Wall -Wstrict-prototypes -Wundef
diff --git a/usr.bin/aucat/abuf.c b/usr.bin/aucat/abuf.c
index 54f2436c21b..9c39c470dea 100644
--- a/usr.bin/aucat/abuf.c
+++ b/usr.bin/aucat/abuf.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: abuf.c,v 1.16 2009/10/09 16:49:48 ratchov Exp $	*/
+/*	$OpenBSD: abuf.c,v 1.17 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -41,7 +41,40 @@
 #include "aparams.h"
 #include "aproc.h"
 #include "conf.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
+#ifdef DEBUG
+void
+abuf_dbg(struct abuf *buf)
+{
+	if (buf->wproc) {
+		aproc_dbg(buf->wproc);
+	} else {
+		dbg_puts("none");
+	}
+	dbg_puts(buf->inuse ? "=>" : "->");
+	if (buf->rproc) {
+		aproc_dbg(buf->rproc);
+	} else {
+		dbg_puts("none");
+	}
+}
+
+void
+abuf_dump(struct abuf *buf)
+{
+	abuf_dbg(buf);
+	dbg_puts(": used = ");
+	dbg_putu(buf->used);
+	dbg_puts("/");
+	dbg_putu(buf->len);
+	dbg_puts(" start = ");
+	dbg_putu(buf->start);
+	dbg_puts("\n");
+}
+#endif
 
 struct abuf *
 abuf_new(unsigned nfr, struct aparams *par)
@@ -53,7 +86,16 @@ abuf_new(unsigned nfr, struct aparams *par)
 	len = nfr * bpf;
 	buf = malloc(sizeof(struct abuf) + len);
 	if (buf == NULL) {
+#ifdef DEBUG
+		dbg_puts("couldn't allocate abuf of ");
+		dbg_putu(nfr);
+		dbg_puts("fr * ");
+		dbg_putu(bpf);
+		dbg_puts("bpf\n");
+		dbg_panic();
+#else
 		err(1, "malloc");
+#endif
 	}
 	buf->bpf = bpf;
 	buf->cmin = par->cmin;
@@ -80,6 +122,28 @@ abuf_del(struct abuf *buf)
 {
 	if (buf->duplex)
 		buf->duplex->duplex = NULL;
+#ifdef DEBUG
+	if (buf->rproc || buf->wproc) {
+		abuf_dbg(buf);
+		dbg_puts(": can't delete referenced buffer\n");
+		dbg_panic();
+	}
+	if (ABUF_ROK(buf)) {
+		/*
+		 * XXX : we should call abort(), here.
+		 * However, poll() doesn't seem to return POLLHUP,
+		 * so the reader is never destroyed; instead it appears	
+		 * as blocked. Fix file_poll(), if fixable, and add
+		 * a call to abord() here.
+		 */
+		if (debug_level >= 3) {
+			abuf_dbg(buf);
+			dbg_puts(": deleting non-empty buffer, used = ");
+			dbg_putu(buf->used);
+			dbg_puts("\n");
+		}
+	}
+#endif
 	free(buf);
 }
 
@@ -89,6 +153,12 @@ abuf_del(struct abuf *buf)
 void
 abuf_clear(struct abuf *buf)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(buf);
+		dbg_puts(": cleared\n");
+	}
+#endif
 	buf->used = 0;
 	buf->start = 0;
 	buf->abspos = 0;
@@ -108,6 +178,15 @@ abuf_rgetblk(struct abuf *buf, unsigned *rsize, unsigned ofs)
 	used = buf->used - ofs;
 	if (start >= buf->len)
 		start -= buf->len;
+#ifdef DEBUG
+	if (start >= buf->len || used > buf->used) {
+		abuf_dump(buf);
+		dbg_puts(": rgetblk: bad ofs = ");
+		dbg_putu(ofs);
+		dbg_puts("\n");
+		dbg_panic();
+	}
+#endif
 	count = buf->len - start;
 	if (count > used)
 		count = used;
@@ -121,6 +200,15 @@ abuf_rgetblk(struct abuf *buf, unsigned *rsize, unsigned ofs)
 void
 abuf_rdiscard(struct abuf *buf, unsigned count)
 {
+#ifdef DEBUG
+	if (count > buf->used) {
+		abuf_dump(buf);
+		dbg_puts(": rdiscard: bad count = ");
+		dbg_putu(count);
+		dbg_puts("\n");
+		dbg_panic();
+	}
+#endif
 	buf->used -= count;
 	buf->start += count;
 	if (buf->start >= buf->len)
@@ -134,6 +222,15 @@ abuf_rdiscard(struct abuf *buf, unsigned count)
 void
 abuf_wcommit(struct abuf *buf, unsigned count)
 {
+#ifdef DEBUG
+	if (count > (buf->len - buf->used)) {
+		abuf_dump(buf);
+		dbg_puts(": rdiscard: bad count = ");
+		dbg_putu(count);
+		dbg_puts("\n");
+		dbg_panic();
+	}
+#endif
 	buf->used += count;
 }
 
@@ -149,6 +246,15 @@ abuf_wgetblk(struct abuf *buf, unsigned *rsize, unsigned ofs)
 	end = buf->start + buf->used + ofs;
 	if (end >= buf->len)
 		end -= buf->len;
+#ifdef DEBUG
+	if (end >= buf->len) {
+		abuf_dump(buf);
+		dbg_puts(": rgetblk: bad ofs = ");
+		dbg_putu(ofs);
+		dbg_puts("\n");
+		dbg_panic();
+	}
+#endif
 	avail = buf->len - (buf->used + ofs);
 	count = buf->len - end;
 	if (count > avail)
@@ -172,14 +278,36 @@ abuf_flush_do(struct abuf *buf)
 		if (count > buf->used)
 			count = buf->used;
 		if (count == 0) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				abuf_dbg(buf);
+				dbg_puts(": flush: no data to drop\n");
+			}
+#endif
 			return 0;
 		}
 		abuf_rdiscard(buf, count);
 		buf->drop -= count;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(buf);
+			dbg_puts(": flush: dropped ");
+			dbg_putu(count);
+			dbg_puts(", to drop = ");
+			dbg_putu(buf->drop);
+			dbg_puts("\n");
+		}
+#endif
 	} else {
 		p = buf->rproc;
 		if (!p)
 			return 0;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": in\n");
+		}
+#endif
 		if (!p->ops->in(p, buf))
 			return 0;
 	}
@@ -202,16 +330,38 @@ abuf_fill_do(struct abuf *buf)
 		if (count >= buf->silence)
 			count = buf->silence;
 		if (count == 0) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				abuf_dbg(buf);
+				dbg_puts(": fill: no space for silence\n");
+			}
+#endif
 			return 0;
 		}
 		memset(data, 0, count);
 		abuf_wcommit(buf, count);
 		buf->silence -= count;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(buf);
+			dbg_puts(": fill: inerted ");
+			dbg_putu(count);
+			dbg_puts(", remaining silence = ");
+			dbg_putu(buf->silence);
+			dbg_puts("\n");
+		}
+#endif
 		p = buf->wproc;
 	} else {
 		p = buf->wproc;
 		if (!p)
 			return 0;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": out\n");
+		}
+#endif
 		if (!p->ops->out(p, buf)) {
 			return 0;
 		}
@@ -233,6 +383,12 @@ abuf_eof_do(struct abuf *buf)
 		buf->rproc = NULL;
 		LIST_REMOVE(buf, ient);
 		buf->inuse++;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": eof\n");
+		}
+#endif
 		p->ops->eof(p, buf);
 		buf->inuse--;
 	}
@@ -249,6 +405,14 @@ abuf_hup_do(struct abuf *buf)
 	struct aproc *p;
 
 	if (ABUF_ROK(buf)) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			abuf_dbg(buf);
+			dbg_puts(": hup: lost ");
+			dbg_putu(buf->used);
+			dbg_puts(" bytes\n");
+		}
+#endif
 		buf->used = 0;
 	}
 	p = buf->wproc;
@@ -256,6 +420,12 @@ abuf_hup_do(struct abuf *buf)
 		buf->wproc = NULL;
 		LIST_REMOVE(buf, oent);
 		buf->inuse++;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			aproc_dbg(p);
+			dbg_puts(": hup\n");
+		}
+#endif
 		p->ops->hup(p, buf);
 		buf->inuse--;
 	}
@@ -270,6 +440,12 @@ int
 abuf_flush(struct abuf *buf)
 {
 	if (buf->inuse) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(buf);
+			dbg_puts(": flush blocked (inuse)\n");
+		}
+#endif
 	} else {
 		buf->inuse++;
 		for (;;) {
@@ -298,6 +474,12 @@ int
 abuf_fill(struct abuf *buf)
 {
 	if (buf->inuse) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(buf);
+			dbg_puts(": fill blocked (inuse)\n");
+		}
+#endif
 	} else {
 		buf->inuse++;
 		for (;;) {
@@ -327,6 +509,12 @@ abuf_run(struct abuf *buf)
 	int canfill = 1, canflush = 1;
 
 	if (buf->inuse) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(buf);
+			dbg_puts(": run blocked (inuse)\n");
+		}
+#endif
 		return;
 	}
 	buf->inuse++;
@@ -363,6 +551,17 @@ abuf_run(struct abuf *buf)
 void
 abuf_eof(struct abuf *buf)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(buf);
+		dbg_puts(": eof requested\n");
+	}
+	if (buf->wproc == NULL) {
+		abuf_dbg(buf);
+		dbg_puts(": eof, no writer\n");
+		dbg_panic();
+	}
+#endif
 	LIST_REMOVE(buf, oent);
 	buf->wproc = NULL;
 	if (buf->rproc != NULL) {
@@ -373,10 +572,22 @@ abuf_eof(struct abuf *buf)
 			 * Could not flush everything, the reader will
 			 * have a chance to delete the abuf later.
 			 */
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				abuf_dbg(buf);
+				dbg_puts(": eof, blocked (drain)\n");
+			}
+#endif
 			return;
 		}
 	}
 	if (buf->inuse) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			abuf_dbg(buf);
+			dbg_puts(": eof, blocked (inuse)\n");
+		}
+#endif
 		return;
 	}
 	abuf_eof_do(buf);
@@ -389,10 +600,27 @@ abuf_eof(struct abuf *buf)
 void
 abuf_hup(struct abuf *buf)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(buf);
+		dbg_puts(": hup requested\n");
+	}
+	if (buf->rproc == NULL) {
+		abuf_dbg(buf);
+		dbg_puts(": hup, no reader\n");
+		dbg_panic();
+	}
+#endif
 	buf->rproc = NULL;
 	LIST_REMOVE(buf, ient);
 	if (buf->wproc != NULL) {
 		if (buf->inuse) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				abuf_dbg(buf);
+				dbg_puts(": eof, blocked (inuse)\n");
+			}
+#endif
 			return;
 		}
 	}
@@ -409,6 +637,14 @@ abuf_ipos(struct abuf *buf, int delta)
 
 	if (p && p->ops->ipos) {
 		buf->inuse++;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": ipos delta = ");
+			dbg_puti(delta);
+			dbg_puts("\n");
+		}
+#endif
 		p->ops->ipos(p, buf, delta);
 		buf->inuse--;
 	}
@@ -426,6 +662,14 @@ abuf_opos(struct abuf *buf, int delta)
 
 	if (p && p->ops->opos) {
 		buf->inuse++;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": opos delta = ");
+			dbg_puti(delta);
+			dbg_puts("\n");
+		}
+#endif
 		p->ops->opos(p, buf, delta);
 		buf->inuse--;
 	}
diff --git a/usr.bin/aucat/aparams.c b/usr.bin/aucat/aparams.c
index eabdd0a80f4..ad3c2a1abda 100644
--- a/usr.bin/aucat/aparams.c
+++ b/usr.bin/aucat/aparams.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: aparams.c,v 1.9 2009/09/27 11:51:20 ratchov Exp $	*/
+/*	$OpenBSD: aparams.c,v 1.10 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -16,6 +16,9 @@
  */
 
 #include "aparams.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 int aparams_ctltovol[128] = {
 	    0,
@@ -181,6 +184,25 @@ aparams_init(struct aparams *par, unsigned cmin, unsigned cmax, unsigned rate)
 	par->rate = rate;
 }
 
+#ifdef DEBUG
+/*
+ * Print the format/channels/encoding on stderr.
+ */
+void
+aparams_dbg(struct aparams *par)
+{
+	char enc[ENCMAX];
+
+	aparams_enctostr(par, enc);
+	dbg_puts(enc);
+	dbg_puts(",");
+	dbg_putu(par->cmin);
+	dbg_puts(":");
+	dbg_putu(par->cmax);
+	dbg_puts(",");
+	dbg_putu(par->rate);
+}
+#endif
 
 /*
  * Return true if both encodings are the same.
diff --git a/usr.bin/aucat/aproc.c b/usr.bin/aucat/aproc.c
index 1e53a8f6c4d..c0a6010bfb4 100644
--- a/usr.bin/aucat/aproc.c
+++ b/usr.bin/aucat/aproc.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: aproc.c,v 1.41 2010/01/05 10:18:12 ratchov Exp $	*/
+/*	$OpenBSD: aproc.c,v 1.42 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -44,7 +44,100 @@
 #include "conf.h"
 #include "file.h"
 #include "midi.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
+#ifdef DEBUG
+void
+aproc_dbg(struct aproc *p)
+{
+	dbg_puts(p->ops->name);
+	dbg_puts("(");
+	dbg_puts(p->name);
+	dbg_puts(")");
+}
+
+int
+zomb_in(struct aproc *p, struct abuf *ibuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": in: terminated\n");
+	dbg_panic();
+	return 0;
+}
+
+
+int
+zomb_out(struct aproc *p, struct abuf *obuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": out: terminated\n");
+	dbg_panic();
+	return 0;
+}
+
+void
+zomb_eof(struct aproc *p, struct abuf *ibuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": eof: terminated\n");
+	dbg_panic();
+}
+
+void
+zomb_hup(struct aproc *p, struct abuf *obuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": hup: terminated\n");
+	dbg_panic();
+}
+
+void
+zomb_newin(struct aproc *p, struct abuf *ibuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": newin: terminated\n");
+	dbg_panic();
+}
+
+void
+zomb_newout(struct aproc *p, struct abuf *obuf)
+{
+	aproc_dbg(p);
+	dbg_puts(": newout: terminated\n");
+	dbg_panic();
+}
+
+void
+zomb_ipos(struct aproc *p, struct abuf *ibuf, int delta)
+{
+	aproc_dbg(p);
+	dbg_puts(": ipos: terminated\n");
+	dbg_panic();
+}
+
+void
+zomb_opos(struct aproc *p, struct abuf *obuf, int delta)
+{
+	aproc_dbg(p);
+	dbg_puts(": opos: terminated\n");
+	dbg_panic();
+}
+
+struct aproc_ops zomb_ops = {
+	"zomb",
+	zomb_in,
+	zomb_out,
+	zomb_eof,
+	zomb_hup,
+	zomb_newin,
+	zomb_newout,
+	zomb_ipos,
+	zomb_opos,
+	NULL
+};
+#endif
 
 struct aproc *
 aproc_new(struct aproc_ops *ops, char *name)
@@ -69,7 +162,19 @@ aproc_del(struct aproc *p)
 	struct abuf *i;
 
 	if (!(p->flags & APROC_ZOMB)) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			aproc_dbg(p);
+			dbg_puts(": terminating...\n");
+		}
+#endif
 		if (p->ops->done) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": done\n");
+			}
+#endif
 			p->ops->done(p);
 		}
 		while (!LIST_EMPTY(&p->ibuflist)) {
@@ -83,8 +188,21 @@ aproc_del(struct aproc *p)
 		p->flags |= APROC_ZOMB;
 	}
 	if (p->refs > 0) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			aproc_dbg(p);
+			dbg_puts(": free delayed\n");
+			p->ops = &zomb_ops;
+		}
+#endif
 		return;
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": freed\n");
+	}
+#endif
 	free(p);
 }
 
@@ -366,6 +484,14 @@ mix_bzero(struct abuf *obuf, unsigned zcount)
 	short *odata;
 	unsigned ocount;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		abuf_dbg(obuf);
+		dbg_puts(": bzero(");
+		dbg_putu(zcount);
+		dbg_puts(")\n");
+	}
+#endif
 	odata = (short *)abuf_wgetblk(obuf, &ocount, obuf->w.mix.todo);
 	ocount -= ocount % obuf->bpf;
 	if (ocount > zcount)
@@ -385,6 +511,16 @@ mix_badd(struct abuf *ibuf, struct abuf *obuf)
 	unsigned scount, icount, ocount, zcount;
 	int vol;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		abuf_dbg(ibuf);
+		dbg_puts(": badd: todo = ");
+		dbg_putu(obuf->w.mix.todo);
+		dbg_puts("/");
+		dbg_putu(ibuf->r.mix.done);
+		dbg_puts("\n");
+	}
+#endif
 	/*
 	 * Calculate the maximum we can read.
 	 */
@@ -425,6 +561,18 @@ mix_badd(struct abuf *ibuf, struct abuf *obuf)
 	abuf_rdiscard(ibuf, scount * ibuf->bpf);
 	ibuf->r.mix.done += scount * obuf->bpf;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		abuf_dbg(ibuf);
+		dbg_puts(": badd: done = ");
+		dbg_putu(scount);
+		dbg_puts(", todo = ");
+		dbg_putu(ibuf->r.mix.done);
+		dbg_puts("/");
+		dbg_putu(obuf->w.mix.todo);
+		dbg_puts("\n");
+	}
+#endif
 }
 
 /*
@@ -443,12 +591,28 @@ mix_xrun(struct abuf *i, struct abuf *obuf)
 	}
 	mix_bzero(obuf, obuf->len);
 	fdrop = obuf->w.mix.todo / obuf->bpf;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(i);
+		dbg_puts(": underrun, dropping ");
+		dbg_putu(fdrop);
+		dbg_puts(" + ");
+		dbg_putu(i->drop / i->bpf);
+		dbg_puts("\n");
+	}
+#endif
 	i->r.mix.done += fdrop * obuf->bpf;
 	if (i->r.mix.xrun == XRUN_SYNC)
 		i->drop += fdrop * i->bpf;
 	else {
 		abuf_opos(i, -(int)fdrop);
 		if (i->duplex) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				abuf_dbg(i->duplex);
+				dbg_puts(": full-duplex resync\n");
+			}
+#endif
 			i->duplex->drop += fdrop * i->duplex->bpf;
 			abuf_ipos(i->duplex, -(int)fdrop);
 		}
@@ -462,6 +626,20 @@ mix_in(struct aproc *p, struct abuf *ibuf)
 	struct abuf *i, *inext, *obuf = LIST_FIRST(&p->obuflist);
 	unsigned odone;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": used = ");
+		dbg_putu(ibuf->used);
+		dbg_puts("/");
+		dbg_putu(ibuf->len);
+		dbg_puts(", todo = ");
+		dbg_putu(obuf->w.mix.todo);
+		dbg_puts("/");
+		dbg_putu(ibuf->r.mix.done);
+		dbg_puts("\n");
+	}
+#endif
 	if (!ABUF_ROK(ibuf))
 		return 0;
 	odone = obuf->len;
@@ -492,6 +670,20 @@ mix_out(struct aproc *p, struct abuf *obuf)
 	struct abuf *i, *inext;
 	unsigned odone;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": used = ");
+		dbg_putu(obuf->used);
+		dbg_puts("/");
+		dbg_putu(obuf->len);
+		dbg_puts(", todo = ");
+		dbg_putu(obuf->w.mix.todo);
+		dbg_puts("/");
+		dbg_putu(obuf->len);
+		dbg_puts("\n");
+	}
+#endif
 	if (!ABUF_WOK(obuf))
 		return 0;
 	odone = obuf->len;
@@ -540,6 +732,12 @@ mix_eof(struct aproc *p, struct abuf *ibuf)
 	mix_setmaster(p);
 
 	if (!aproc_inuse(p)) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			aproc_dbg(p);
+			dbg_puts(": running other streams\n");
+		}
+#endif
 		/*
 		 * Find a blocked input.
 		 */
@@ -569,6 +767,14 @@ mix_hup(struct aproc *p, struct abuf *obuf)
 void
 mix_newin(struct aproc *p, struct abuf *ibuf)
 {
+#ifdef DEBUG
+	struct abuf *obuf = LIST_FIRST(&p->obuflist);
+
+	if (!obuf || ibuf->cmin < obuf->cmin || ibuf->cmax > obuf->cmax) {
+		dbg_puts("newin: channel ranges mismatch\n");
+		dbg_panic();
+	}
+#endif
 	p->u.mix.idle = 0;
 	ibuf->r.mix.done = 0;
 	ibuf->r.mix.vol = ADATA_UNIT;
@@ -580,12 +786,30 @@ mix_newin(struct aproc *p, struct abuf *ibuf)
 void
 mix_newout(struct aproc *p, struct abuf *obuf)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": newin, will use ");
+		dbg_putu(obuf->len / obuf->bpf);
+		dbg_puts(" fr\n");
+	}
+#endif
 	obuf->w.mix.todo = 0;
 }
 
 void
 mix_opos(struct aproc *p, struct abuf *obuf, int delta)
 {
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": opos: lat = ");
+		dbg_puti(p->u.mix.lat);
+		dbg_puts("/");
+		dbg_puti(p->u.mix.maxlat);
+		dbg_puts(" fr\n");
+	}
+#endif
 	p->u.mix.lat -= delta;
 	if (p->u.mix.ctl)
 		ctl_ontick(p->u.mix.ctl, delta);
@@ -652,6 +876,16 @@ mix_setmaster(struct aproc *p)
 		if (weight > i->r.mix.maxweight)
 			weight = i->r.mix.maxweight;
 		i->r.mix.weight = weight;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			abuf_dbg(i);
+			dbg_puts(": setmaster: ");
+			dbg_puti(i->r.mix.weight);
+			dbg_puts("/");
+			dbg_puti(i->r.mix.maxweight);
+			dbg_puts("\n");
+		}
+#endif
 	}
 }
 
@@ -697,6 +931,14 @@ sub_bcopy(struct abuf *ibuf, struct abuf *obuf)
 	}
 	abuf_wcommit(obuf, scount * obuf->bpf);
 	obuf->w.sub.done += scount * ibuf->bpf;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		abuf_dbg(obuf);
+		dbg_puts(": bcopy ");
+		dbg_putu(scount);
+		dbg_puts(" fr\n");
+	}
+#endif
 }
 
 /*
@@ -714,11 +956,27 @@ sub_xrun(struct abuf *ibuf, struct abuf *i)
 		return 0;
 	}
 	fdrop = ibuf->used / ibuf->bpf;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(i);
+		dbg_puts(": overrun, silence ");
+		dbg_putu(fdrop);
+		dbg_puts(" + ");
+		dbg_putu(i->silence / i->bpf);
+		dbg_puts("\n");
+	}
+#endif
 	if (i->w.sub.xrun == XRUN_SYNC)
 		i->silence += fdrop * i->bpf;
 	else {
 		abuf_ipos(i, -(int)fdrop);
 		if (i->duplex) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				abuf_dbg(i->duplex);
+				dbg_puts(": full-duplex resync\n");
+			}
+#endif
 			i->duplex->silence += fdrop * i->duplex->bpf;
 			abuf_opos(i->duplex, -(int)fdrop);
 		}
@@ -813,6 +1071,12 @@ sub_hup(struct aproc *p, struct abuf *obuf)
 	unsigned idone;
 
 	if (!aproc_inuse(p)) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			aproc_dbg(p);
+			dbg_puts(": running other streams\n");
+		}
+#endif
 		/*
 		 * Find a blocked output.
 		 */
@@ -836,6 +1100,14 @@ sub_hup(struct aproc *p, struct abuf *obuf)
 void
 sub_newout(struct aproc *p, struct abuf *obuf)
 {
+#ifdef DEBUG
+	struct abuf *ibuf = LIST_FIRST(&p->ibuflist);
+
+	if (!ibuf || obuf->cmin < ibuf->cmin || obuf->cmax > ibuf->cmax) {
+		dbg_puts("newout: channel ranges mismatch\n");
+		dbg_panic();
+	}
+#endif
 	p->u.sub.idle = 0;
 	obuf->w.sub.done = 0;
 	obuf->w.sub.xrun = XRUN_IGNORE;
@@ -845,6 +1117,16 @@ void
 sub_ipos(struct aproc *p, struct abuf *ibuf, int delta)
 {
 	p->u.sub.lat += delta;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": ipos: lat = ");
+		dbg_puti(p->u.sub.lat);
+		dbg_puts("/");
+		dbg_puti(p->u.sub.maxlat);
+		dbg_puts(" fr\n");
+	}
+#endif
 	if (p->u.sub.ctl)
 		ctl_ontick(p->u.sub.ctl, delta);
 	aproc_ipos(p, ibuf, delta);
@@ -929,6 +1211,16 @@ resamp_bcopy(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 	/*
 	 * Start conversion.
 	 */
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": resamp starting ifr = ");
+		dbg_putu(ifr);
+		dbg_puts(", ofr = ");
+		dbg_puti(ofr);
+		dbg_puts(" fr\n");
+	}
+#endif
 	for (;;) {
 		if (diff < 0) {
 			if (ifr == 0)
@@ -957,6 +1249,16 @@ resamp_bcopy(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 	}
 	p->u.resamp.diff = diff;
 	p->u.resamp.ctx_start = ctx_start;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": resamp done ifr = ");
+		dbg_putu(ifr);
+		dbg_puts(", ofr = ");
+		dbg_puti(ofr);
+		dbg_puts(" fr\n");
+	}
+#endif
 	/*
 	 * Update FIFO pointers.
 	 */
@@ -1062,6 +1364,16 @@ resamp_new(char *name, unsigned iblksz, unsigned oblksz)
 	p->u.resamp.ctx_start = 0;
 	for (i = 0; i < NCHAN_MAX * RESAMP_NCTX; i++)
 		p->u.resamp.ctx[i] = 0;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": new ");
+		dbg_putu(iblksz);
+		dbg_puts("/");
+		dbg_putu(oblksz);
+		dbg_puts("\n");
+	}
+#endif
 	return p;
 }
 
@@ -1109,6 +1421,14 @@ cmap_bcopy(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 			ctx++;
 		}
 	}
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": bcopy ");
+		dbg_putu(scount);
+		dbg_puts(" fr\n");
+	}
+#endif
 	abuf_rdiscard(ibuf, scount * ibuf->bpf);
 	abuf_wcommit(obuf, scount * obuf->bpf);
 }
@@ -1173,6 +1493,16 @@ cmap_new(char *name, struct aparams *ipar, struct aparams *opar)
 	p = aproc_new(&cmap_ops, name);
 	for (i = 0; i < NCHAN_MAX; i++)
 		p->u.cmap.ctx[i] = 0;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": new ");
+		aparams_dbg(ipar);
+		dbg_puts(" -> ");
+		aparams_dbg(opar);
+		dbg_puts("\n");
+	}
+#endif
 	return p;
 }
 
@@ -1207,6 +1537,16 @@ enc_bcopy(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 		return;
 	scount = (icount < ocount) ? icount : ocount;
 	nch = ibuf->cmax - ibuf->cmin + 1;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": bcopy ");
+		dbg_putu(scount);
+		dbg_puts(" fr * ");
+		dbg_putu(nch);
+		dbg_puts(" ch\n");
+	}
+#endif
 	/*
 	 * Partially copy structures into local variables, to avoid
 	 * unnecessary indirections; this also allows the compiler to
@@ -1315,6 +1655,14 @@ enc_new(char *name, struct aparams *par)
 		p->u.conv.bnext = 1;
 		p->u.conv.snext = 0;
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": new ");
+		aparams_dbg(par);
+		dbg_puts("\n");
+	}
+#endif
 	return p;
 }
 
@@ -1349,6 +1697,16 @@ dec_bcopy(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 		return;
 	scount = (icount < ocount) ? icount : ocount;
 	nch = obuf->cmax - obuf->cmin + 1;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": bcopy ");
+		dbg_putu(scount);
+		dbg_puts(" fr * ");
+		dbg_putu(nch);
+		dbg_puts(" ch\n");
+	}
+#endif
 	/*
 	 * Partially copy structures into local variables, to avoid
 	 * unnecessary indirections; this also allows the compiler to
@@ -1457,5 +1815,13 @@ dec_new(char *name, struct aparams *par)
 		p->u.conv.bnext = 1;
 		p->u.conv.snext = 0;
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": new ");
+		aparams_dbg(par);
+		dbg_puts("\n");
+	}
+#endif
 	return p;
 }
diff --git a/usr.bin/aucat/aucat.c b/usr.bin/aucat/aucat.c
index 6f0861cdd6a..873cd4771ef 100644
--- a/usr.bin/aucat/aucat.c
+++ b/usr.bin/aucat/aucat.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: aucat.c,v 1.77 2010/01/05 10:18:12 ratchov Exp $	*/
+/*	$OpenBSD: aucat.c,v 1.78 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -39,6 +39,9 @@
 #include "midi.h"
 #include "opt.h"
 #include "wav.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 #define MODE_PLAY	1
 #define MODE_REC	2
@@ -46,6 +49,9 @@
 #define PROG_AUCAT	"aucat"
 #define PROG_MIDICAT	"midicat"
 
+#ifdef DEBUG
+int debug_level = 0;
+#endif
 volatile int quit_flag = 0;
 
 /*
@@ -61,6 +67,27 @@ sigint(int s)
 	quit_flag = 1;
 }
 
+#ifdef DEBUG
+/*
+ * Increase debug level on SIGUSR1.
+ */
+void
+sigusr1(int s)
+{
+	if (debug_level < 4)
+		debug_level++;
+}
+
+/*
+ * Decrease debug level on SIGUSR2.
+ */
+void
+sigusr2(int s)
+{
+	if (debug_level > 0)
+		debug_level--;
+}
+#endif
 
 void
 opt_ch(struct aparams *par)
@@ -209,6 +236,14 @@ setsig(void)
 		err(1, "sigaction(term) failed");
 	if (sigaction(SIGHUP, &sa, NULL) < 0)
 		err(1, "sigaction(hup) failed");
+#ifdef DEBUG
+	sa.sa_handler = sigusr1;
+	if (sigaction(SIGUSR1, &sa, NULL) < 0)
+		err(1, "sigaction(usr1) failed");
+	sa.sa_handler = sigusr2;
+	if (sigaction(SIGUSR2, &sa, NULL) < 0)
+		err(1, "sigaction(usr2) failed1n");
+#endif
 }
 
 void
@@ -219,6 +254,12 @@ unsetsig(void)
 	sigfillset(&sa.sa_mask);
 	sa.sa_flags = SA_RESTART;
 	sa.sa_handler = SIG_DFL;
+#ifdef DEBUG
+	if (sigaction(SIGUSR2, &sa, NULL) < 0)
+		err(1, "unsetsig(usr2): sigaction failed");
+	if (sigaction(SIGUSR1, &sa, NULL) < 0)
+		err(1, "unsetsig(usr1): sigaction failed");
+#endif
 	if (sigaction(SIGHUP, &sa, NULL) < 0)
 		err(1, "unsetsig(hup): sigaction failed\n");
 	if (sigaction(SIGTERM, &sa, NULL) < 0)
@@ -291,6 +332,10 @@ aucat_main(int argc, char **argv)
 	while ((c = getopt(argc, argv, "dnb:c:C:e:r:h:x:v:i:o:f:m:lus:U:t:z:")) != -1) {
 		switch (c) {
 		case 'd':
+#ifdef DEBUG
+			if (d_flag)
+				debug_level++;
+#endif
 			d_flag = 1;
 			break;
 		case 'n':
@@ -535,6 +580,10 @@ aucat_main(int argc, char **argv)
 			if (!l_flag)
 				break;
 			if (!suspend) {
+#ifdef DEBUG
+				if (debug_level >= 2)
+					dbg_puts("suspending\n");
+#endif
 				suspend = 1;
 				dev_stop();
 				dev_clear();
@@ -544,6 +593,10 @@ aucat_main(int argc, char **argv)
 		    (dev_sub && dev_sub->u.sub.idle == 0) ||
 		    ((dev_mix || dev_sub) && dev_midi->u.ctl.tstate == CTL_RUN)) {
 			if (suspend) {
+#ifdef DEBUG
+				if (debug_level >= 2)
+					dbg_puts("resuming\n");
+#endif
 				suspend = 0;
 				dev_start();
 			}
@@ -555,6 +608,10 @@ aucat_main(int argc, char **argv)
 			warn("rmdir(\"%s\")", base);
 	}
 	if (suspend) {
+#ifdef DEBUG
+		if (debug_level >= 2)
+			dbg_puts("resuming to drain\n");
+#endif
 		suspend = 0;
 		dev_start();
 	}
@@ -593,6 +650,10 @@ midicat_main(int argc, char **argv)
 	while ((c = getopt(argc, argv, "di:o:lf:U:")) != -1) {
 		switch (c) {
 		case 'd':
+#ifdef DEBUG
+			if (d_flag)
+				debug_level++;
+#endif
 			d_flag = 1;
 			break;
 		case 'i':
diff --git a/usr.bin/aucat/conf.h b/usr.bin/aucat/conf.h
index 00515460cfc..9f23921c760 100644
--- a/usr.bin/aucat/conf.h
+++ b/usr.bin/aucat/conf.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: conf.h,v 1.11 2009/11/03 21:31:37 ratchov Exp $	*/
+/*	$OpenBSD: conf.h,v 1.12 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -17,6 +17,18 @@
 #ifndef CONF_H
 #define CONF_H
 
+#ifdef DEBUG
+/*
+ * Debug trace levels:
+ *
+ * 0 - fatal errors: bugs, asserts, internal errors.
+ * 1 - warnings: bugs in clients, failed allocations, non-fatal errors.
+ * 2 - misc information (hardware parameters, incoming clients)
+ * 3 - structural changes (new aproc structures and files stream params changes)
+ * 4 - data blocks and messages
+ */
+extern int debug_level;
+#endif
 
 /*
  * Number of blocks in the device play/record buffers.  Because Sun API
diff --git a/usr.bin/aucat/dbg.c b/usr.bin/aucat/dbg.c
new file mode 100644
index 00000000000..10cbcd7fff9
--- /dev/null
+++ b/usr.bin/aucat/dbg.c
@@ -0,0 +1,153 @@
+#ifdef DEBUG
+/*
+ * Copyright (c) 2003-2007 Alexandre Ratchov <alex@caoua.org>
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ *
+ * 	- Redistributions of source code must retain the above
+ * 	  copyright notice, this list of conditions and the
+ * 	  following disclaimer.
+ *
+ * 	- Redistributions in binary form must reproduce the above
+ * 	  copyright notice, this list of conditions and the
+ * 	  following disclaimer in the documentation and/or other
+ * 	  materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+ * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+ * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+ * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+ * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+ * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+/*
+ * dbg_xxx() routines are used to quickly store traces into a trace buffer.
+ * This allows trances to be collected during time sensitive operations without
+ * disturbing them. The buffer can be flushed on standard error later, when
+ * slow syscalls are no longer disruptive, e.g. at the end of the poll() loop.
+ */
+#include <stdlib.h>
+#include <unistd.h>
+#include <fcntl.h>
+#include "dbg.h"
+
+/*
+ * size of the buffer where traces are stored
+ */
+#define DBG_BUFSZ	8192
+
+/*
+ * store a character in the trace buffer
+ */
+#define DBG_PUTC(c) do {			\
+	if (dbg_used < DBG_BUFSZ)		\
+		dbg_buf[dbg_used++] = (c);	\
+} while (0)
+
+char dbg_buf[DBG_BUFSZ];	/* buffer where traces are stored */
+unsigned dbg_used = 0;		/* bytes used in the buffer */
+unsigned dbg_sync = 1;		/* if true, flush after each '\n' */
+
+/*
+ * write debug info buffer on stderr
+ */
+void
+dbg_flush(void)
+{
+	if (dbg_used ==  0)
+		return;
+	write(STDERR_FILENO, dbg_buf, dbg_used);
+	dbg_used = 0;
+}
+
+/*
+ * store a string in the debug buffer
+ */
+void
+dbg_puts(char *msg)
+{
+	char *p = msg;
+	int c;
+
+	while ((c = *p++) != '\0') {
+		DBG_PUTC(c);
+		if (dbg_sync && c == '\n')
+			dbg_flush();
+	}
+}
+
+/*
+ * store a hex in the debug buffer
+ */
+void
+dbg_putx(unsigned long num)
+{
+	char dig[sizeof(num) * 2], *p = dig, c;
+	unsigned ndig;
+
+	if (num != 0) {
+		for (ndig = 0; num != 0; ndig++) {
+			*p++ = num & 0xf;
+			num >>= 4;
+		}
+		for (; ndig != 0; ndig--) {
+			c = *(--p);
+			c += (c < 10) ? '0' : 'a' - 10;
+			DBG_PUTC(c);
+		}
+	} else 
+		DBG_PUTC('0');
+}
+
+/*
+ * store a decimal in the debug buffer
+ */
+void
+dbg_putu(unsigned long num)
+{
+	char dig[sizeof(num) * 3], *p = dig;
+	unsigned ndig;
+
+	if (num != 0) {
+		for (ndig = 0; num != 0; ndig++) {
+			*p++ = num % 10;
+			num /= 10;
+		}
+		for (; ndig != 0; ndig--)
+			DBG_PUTC(*(--p) + '0');
+	} else
+		DBG_PUTC('0');
+}
+
+/*
+ * store a signed integer in the trace buffer
+ */
+void
+dbg_puti(long num)
+{
+	if (num < 0) {
+		DBG_PUTC('-');
+		num = -num;
+	}
+	dbg_putu(num);
+}
+
+/*
+ * abort program execution after a fatal error, we should
+ * put code here to backup user data
+ */
+void
+dbg_panic(void)
+{
+	dbg_flush();
+	abort();
+}
+#endif
diff --git a/usr.bin/aucat/dbg.h b/usr.bin/aucat/dbg.h
new file mode 100644
index 00000000000..119aa5d546a
--- /dev/null
+++ b/usr.bin/aucat/dbg.h
@@ -0,0 +1,45 @@
+#ifdef DEBUG
+/*
+ * Copyright (c) 2003-2007 Alexandre Ratchov <alex@caoua.org>
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ *
+ * 	- Redistributions of source code must retain the above
+ * 	  copyright notice, this list of conditions and the
+ * 	  following disclaimer.
+ *
+ * 	- Redistributions in binary form must reproduce the above
+ * 	  copyright notice, this list of conditions and the
+ * 	  following disclaimer in the documentation and/or other
+ * 	  materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+ * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+ * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+ * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+ * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+ * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+
+#ifndef MIDISH_DBG_H
+#define MIDISH_DBG_H
+
+void	 dbg_puts(char *);
+void	 dbg_putx(unsigned long);
+void	 dbg_putu(unsigned long);
+void	 dbg_puti(long);
+void	 dbg_panic(void);
+void	 dbg_flush(void);
+
+extern unsigned dbg_sync;
+
+#endif /* MIDISH_DBG_H */
+#endif /* DEBUG */
diff --git a/usr.bin/aucat/dev.c b/usr.bin/aucat/dev.c
index bdd6366235a..e749531d742 100644
--- a/usr.bin/aucat/dev.c
+++ b/usr.bin/aucat/dev.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: dev.c,v 1.38 2010/01/05 10:18:12 ratchov Exp $	*/
+/*	$OpenBSD: dev.c,v 1.39 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -27,6 +27,9 @@
 #include "miofile.h"
 #include "safile.h"
 #include "midi.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 unsigned dev_bufsz, dev_round, dev_rate;
 struct aparams dev_ipar, dev_opar;
@@ -161,9 +164,23 @@ dev_init(char *devpath,
 	if (f == NULL)
 		return 0;
 	if (dipar) {
+#ifdef DEBUG
+		if (debug_level >= 2) {
+			dbg_puts("hw recording ");
+			aparams_dbg(dipar);
+			dbg_puts("\n");
+		}
+#endif
 		dev_rate = dipar->rate;
 	}
 	if (dopar) {
+#ifdef DEBUG
+		if (debug_level >= 2) {
+			dbg_puts("hw playing ");
+			aparams_dbg(dopar);
+			dbg_puts("\n");
+		}
+#endif
 		dev_rate = dopar->rate;
 	}
 	ibufsz = obufsz = dev_bufsz;
@@ -255,6 +272,15 @@ dev_init(char *devpath,
 		dev_mix = NULL;
 	}
 	dev_bufsz = (dopar) ? obufsz : ibufsz;
+#ifdef DEBUG
+	if (debug_level >= 2) {
+		dbg_puts("device block size is ");
+		dbg_putu(dev_round);
+		dbg_puts(" frames, using ");
+		dbg_putu(dev_bufsz / dev_round);
+		dbg_puts(" blocks\n");
+	}
+#endif
 	dev_start();
 	return 1;
 }
@@ -268,6 +294,10 @@ dev_done(void)
 {
 	struct file *f;
 
+#ifdef DEBUG
+	if (debug_level >= 2) 
+		dbg_puts("closing audio device\n");
+#endif
 	if (dev_mix) {
 		/*
 		 * Put the mixer in ``autoquit'' state and generate
@@ -404,6 +434,12 @@ dev_getep(struct abuf **sibuf, struct abuf **sobuf)
 		ibuf = *sibuf;
 		for (;;) {
 			if (!ibuf || !ibuf->rproc) {
+#ifdef DEBUG
+				if (debug_level >= 3) {
+					abuf_dbg(*sibuf);
+					dbg_puts(": not connected to device\n");
+				}
+#endif
 				return 0;
 			}
 			if (ibuf->rproc == dev_mix)
@@ -416,6 +452,12 @@ dev_getep(struct abuf **sibuf, struct abuf **sobuf)
 		obuf = *sobuf;
 		for (;;) {
 			if (!obuf || !obuf->wproc) {
+#ifdef DEBUG
+				if (debug_level >= 3) {
+					abuf_dbg(*sobuf);
+					dbg_puts(": not connected to device\n");
+				}
+#endif
 				return 0;
 			}
 			if (obuf->wproc == dev_sub)
@@ -457,6 +499,23 @@ dev_sync(struct abuf *ibuf, struct abuf *obuf)
 	    rbuf->bpf * (pbuf->abspos + pbuf->used) -
 	    pbuf->bpf *  rbuf->abspos;
 	delta /= pbuf->bpf * rbuf->bpf;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		dbg_puts("syncing device, delta = ");
+		dbg_putu(delta);
+		dbg_puts(": ");
+		abuf_dbg(pbuf);
+		dbg_puts(" abspos = ");
+		dbg_putu(pbuf->abspos);
+		dbg_puts(" used = ");
+		dbg_putu(pbuf->used);
+		dbg_puts(" <---> ");
+		abuf_dbg(rbuf);
+		dbg_puts(" abspos = ");
+		dbg_putu(rbuf->abspos);
+		dbg_puts("\n");
+	}
+#endif
 	if (delta > 0) {
 		/*
 		 * The play chain is ahead (most cases) drop some of
@@ -510,6 +569,15 @@ dev_getpos(void)
 			rlat -= delta;
 		else if (delta < 0)
 			plat += delta;
+#ifdef DEBUG
+		if (rlat != plat) {
+			dbg_puts("dev_getpos: play/rec out of sync: plat = ");
+			dbg_puti(plat);
+			dbg_puts(", rlat = ");
+			dbg_puti(rlat);
+			dbg_puts("\n");
+		}
+#endif
 	}
 	return dev_mix ? plat : rlat;
 }
@@ -621,6 +689,14 @@ dev_attach(char *name,
 void
 dev_setvol(struct abuf *ibuf, int vol)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		abuf_dbg(ibuf);
+		dbg_puts(": setting volume to ");
+		dbg_putu(vol);
+		dbg_puts("\n");
+	}
+#endif
 	if (!dev_getep(&ibuf, NULL)) {
 		return;
 	}
@@ -637,6 +713,12 @@ dev_clear(void)
 	struct abuf *buf;
 
 	if (dev_mix) {
+#ifdef DEBUG
+		if (!LIST_EMPTY(&dev_mix->ibuflist)) {
+			dbg_puts("play end not idle, can't clear device\n");
+			dbg_panic();	
+		}
+#endif
 		buf = LIST_FIRST(&dev_mix->obuflist);
 		while (buf) {
 			abuf_clear(buf);
@@ -645,6 +727,12 @@ dev_clear(void)
 		mix_clear(dev_mix);
 	}
 	if (dev_sub) {
+#ifdef DEBUG
+		if (!LIST_EMPTY(&dev_sub->obuflist)) {
+			dbg_puts("record end not idle, can't clear device\n");
+			dbg_panic();	
+		}
+#endif
 		buf = LIST_FIRST(&dev_sub->ibuflist);
 		while (buf) {
 			abuf_clear(buf);
diff --git a/usr.bin/aucat/file.c b/usr.bin/aucat/file.c
index 100e597a630..e60f1154e15 100644
--- a/usr.bin/aucat/file.c
+++ b/usr.bin/aucat/file.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: file.c,v 1.14 2009/09/27 11:51:20 ratchov Exp $	*/
+/*	$OpenBSD: file.c,v 1.15 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -57,6 +57,9 @@
 #include "aproc.h"
 #include "conf.h"
 #include "file.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 #define MAXFDS 100
 
@@ -90,6 +93,16 @@ timo_add(struct timo *o, unsigned delta)
 	unsigned val;
 	int diff;
 
+#ifdef DEBUG
+	if (o->set) {
+		dbg_puts("timo_set: already set\n");
+		dbg_panic();
+	}
+	if (delta == 0) {
+		dbg_puts("timo_set: zero timeout is evil\n");
+		dbg_panic();
+	}
+#endif
 	val = timo_abstime + delta;
 	for (i = &timo_queue; *i != NULL; i = &(*i)->next) {
 		diff = (*i)->val - val;
@@ -118,6 +131,10 @@ timo_del(struct timo *o)
 			return;
 		}
 	}
+#ifdef DEBUG
+	if (debug_level >= 4)
+		dbg_puts("timo_del: not found\n");
+#endif
 }
 
 /*
@@ -171,9 +188,40 @@ timo_init(void)
 void
 timo_done(void)
 {
+#ifdef DEBUG
+	if (timo_queue != NULL) {
+		dbg_puts("timo_done: timo_queue not empty!\n");
+		dbg_panic();
+	}
+#endif
 	timo_queue = (struct timo *)0xdeadbeef;
 }
 
+#ifdef DEBUG
+void
+file_dbg(struct file *f)
+{
+	dbg_puts(f->ops->name);
+	dbg_puts("(");
+	dbg_puts(f->name);
+	dbg_puts("|");
+	if (f->state & FILE_ROK)
+		dbg_puts("r");
+	if (f->state & FILE_RINUSE)
+		dbg_puts("R");
+	if (f->state & FILE_WOK)
+		dbg_puts("w");
+	if (f->state & FILE_WINUSE)
+		dbg_puts("W");
+	if (f->state & FILE_EOF)
+		dbg_puts("e");
+	if (f->state & FILE_HUP)
+		dbg_puts("h");
+	if (f->state & FILE_ZOMB)
+		dbg_puts("Z");
+	dbg_puts(")");
+}
+#endif
 
 struct file *
 file_new(struct fileops *ops, char *name, unsigned nfds)
@@ -183,6 +231,12 @@ file_new(struct fileops *ops, char *name, unsigned nfds)
 	LIST_FOREACH(f, &file_list, entry)
 		nfds += f->ops->nfds(f);
 	if (nfds > MAXFDS) {
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			dbg_puts(name);
+			dbg_puts(": too many polled files\n");
+		}
+#endif
 		return NULL;
 	}
 	f = malloc(ops->size);
@@ -194,16 +248,34 @@ file_new(struct fileops *ops, char *name, unsigned nfds)
 	f->rproc = NULL;
 	f->wproc = NULL;
 	LIST_INSERT_HEAD(&file_list, f, entry);
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(f);
+		dbg_puts(": created\n");
+	}
+#endif
 	return f;
 }
 
 void
 file_del(struct file *f)
 {
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(f);
+		dbg_puts(": terminating...\n");
+	}
+#endif
 	if (f->state & (FILE_RINUSE | FILE_WINUSE)) {
 		f->state |= FILE_ZOMB;
 	} else {
 		LIST_REMOVE(f, entry);
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			file_dbg(f);
+			dbg_puts(": destroyed\n");
+		}
+#endif
 		f->ops->close(f);
 		free(f);
 	}
@@ -225,6 +297,11 @@ file_poll(void)
 	 * Fill the pfds[] array with files that are blocked on reading
 	 * and/or writing, skipping those that are just waiting.
 	 */
+#ifdef DEBUG
+	dbg_flush();
+	if (debug_level >= 4) 
+		dbg_puts("poll:");
+#endif
 	nfds = 0;
 	LIST_FOREACH(f, &file_list, entry) {
 		events = 0;
@@ -232,6 +309,12 @@ file_poll(void)
 			events |= POLLIN;
 		if (f->wproc && !(f->state & FILE_WOK))
 			events |= POLLOUT;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			dbg_puts(" ");
+			file_dbg(f);
+		}
+#endif
 		n = f->ops->pollfd(f, pfds + nfds, events);
 		if (n == 0) {
 			f->pfd = NULL;
@@ -240,7 +323,21 @@ file_poll(void)
 		f->pfd = pfds + nfds;
 		nfds += n;
 	}
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		dbg_puts("\npfds[] =");
+		for (n = 0; n < nfds; n++) {
+			dbg_puts(" ");
+			dbg_putx(pfds[n].events);
+		}
+		dbg_puts("\n");
+	}
+#endif
 	if (LIST_EMPTY(&file_list)) {
+#ifdef DEBUG
+		if (debug_level >= 3)
+			dbg_puts("nothing to do...\n");
+#endif
 		return 0;
 	}
 	if (nfds > 0) {
@@ -272,12 +369,24 @@ file_poll(void)
 		revents = f->ops->revents(f, f->pfd);
 		if (!(f->state & FILE_ZOMB) && (revents & POLLIN)) {
 			revents &= ~POLLIN;
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(f);
+				dbg_puts(": rok\n");
+			}
+#endif
 			f->state |= FILE_ROK;
 			f->state |= FILE_RINUSE;
 			for (;;) {
 				p = f->rproc;
 				if (!p)
 					break;
+#ifdef DEBUG
+				if (debug_level >= 4) {
+					aproc_dbg(p);
+					dbg_puts(": in\n");
+				}
+#endif
 				if (!p->ops->in(p, NULL))
 					break;
 			}
@@ -285,33 +394,75 @@ file_poll(void)
 		}
 		if (!(f->state & FILE_ZOMB) && (revents & POLLOUT)) {
 			revents &= ~POLLOUT;
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(f);
+				dbg_puts(": wok\n");
+			}
+#endif
 			f->state |= FILE_WOK;
 			f->state |= FILE_WINUSE;
 			for (;;) {
 				p = f->wproc;
 				if (!p)
 					break;
+#ifdef DEBUG
+				if (debug_level >= 4) {
+					aproc_dbg(p);
+					dbg_puts(": out\n");
+				}
+#endif
 				if (!p->ops->out(p, NULL))
 					break;
 			}
 			f->state &= ~FILE_WINUSE;
 		}
 		if (!(f->state & FILE_ZOMB) && (revents & POLLHUP)) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				file_dbg(f);
+				dbg_puts(": disconnected\n");
+			}
+#endif
 			f->state |= (FILE_EOF | FILE_HUP);
 		}
 		if (!(f->state & FILE_ZOMB) && (f->state & FILE_EOF)) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				file_dbg(f);
+				dbg_puts(": eof\n");
+			}
+#endif
 			p = f->rproc;
 			if (p) {
 				f->state |= FILE_RINUSE;
+#ifdef DEBUG
+				if (debug_level >= 3) {
+					aproc_dbg(p);
+					dbg_puts(": eof\n");
+				}
+#endif
 				p->ops->eof(p, NULL);
 				f->state &= ~FILE_RINUSE;
 			}
 			f->state &= ~FILE_EOF;
 		}
 		if (!(f->state & FILE_ZOMB) && (f->state & FILE_HUP)) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				file_dbg(f);
+				dbg_puts(": hup\n");
+			}
+#endif
 			p = f->wproc;
 			if (p) {
 				f->state |= FILE_WINUSE;
+#ifdef DEBUG
+				if (debug_level >= 3) {
+					aproc_dbg(p);
+					dbg_puts(": hup\n");
+				}
+#endif
 				p->ops->hup(p, NULL);
 				f->state &= ~FILE_WINUSE;
 			}
@@ -323,6 +474,10 @@ file_poll(void)
 		f = fnext;
 	}
 	if (LIST_EMPTY(&file_list)) {
+#ifdef DEBUG
+		if (debug_level >= 3)
+			dbg_puts("no files anymore...\n");
+#endif
 		return 0;
 	}
 	return 1;
@@ -340,11 +495,28 @@ filelist_init(void)
 	LIST_INIT(&file_list);
 	timo_init();
 	gettimeofday(&file_tv, NULL);
+#ifdef DEBUG
+	dbg_sync = 0;
+#endif
 }
 
 void
 filelist_done(void)
 {
+#ifdef DEBUG
+	struct file *f;
+
+	if (!LIST_EMPTY(&file_list)) {
+		LIST_FOREACH(f, &file_list, entry) {
+			dbg_puts("\t");
+			file_dbg(f);
+			dbg_puts("\n");
+		}
+		dbg_panic();
+	}
+	dbg_sync = 1;
+	dbg_flush();
+#endif
 	timo_done();
 }
 
@@ -369,7 +541,31 @@ unsigned
 file_read(struct file *f, unsigned char *data, unsigned count)
 {
 	unsigned n;
+#ifdef DEBUG
+	struct timeval tv0, tv1, dtv;
+	unsigned us;
+
+	gettimeofday(&tv0, NULL);
+	if (!(f->state & FILE_ROK)) {
+		file_dbg(f);
+		dbg_puts(": read: bad state\n");
+		dbg_panic();
+	}
+#endif
 	n = f->ops->read(f, data, count);
+#ifdef DEBUG
+	gettimeofday(&tv1, NULL);
+	timersub(&tv1, &tv0, &dtv);
+	us = dtv.tv_sec * 1000000 + dtv.tv_usec;
+	if (debug_level >= 4 || (debug_level >= 1 && us >= 5000)) {
+		dbg_puts(f->name);
+		dbg_puts(": read ");
+		dbg_putu(n);
+		dbg_puts(" bytes in ");
+		dbg_putu(us);
+		dbg_puts("us\n");
+	}
+#endif
 	return n;
 }
 
@@ -377,7 +573,31 @@ unsigned
 file_write(struct file *f, unsigned char *data, unsigned count)
 {
 	unsigned n;
+#ifdef DEBUG
+	struct timeval tv0, tv1, dtv;
+	unsigned us;
+
+	if (!(f->state & FILE_WOK)) {
+		file_dbg(f);
+		dbg_puts(": write: bad state\n");
+		dbg_panic();
+	}
+	gettimeofday(&tv0, NULL);
+#endif
 	n = f->ops->write(f, data, count);
+#ifdef DEBUG
+	gettimeofday(&tv1, NULL);
+	timersub(&tv1, &tv0, &dtv);
+	us = dtv.tv_sec * 1000000 + dtv.tv_usec;
+	if (debug_level >= 4 || (debug_level >= 1 && us >= 5000)) {
+		dbg_puts(f->name);
+		dbg_puts(": wrote ");
+		dbg_putu(n);
+		dbg_puts(" bytes in ");
+		dbg_putu(us);
+		dbg_puts("us\n");
+	}
+#endif
 	return n;
 }
 
@@ -386,10 +606,22 @@ file_eof(struct file *f)
 {
 	struct aproc *p;
 
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(f);
+		dbg_puts(": eof requested\n");
+	}
+#endif
 	if (!(f->state & (FILE_RINUSE | FILE_WINUSE))) {
 		p = f->rproc;
 		if (p) {
 			f->state |= FILE_RINUSE;
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": eof\n");
+			}
+#endif
 			p->ops->eof(p, NULL);
 			f->state &= ~FILE_RINUSE;
 		}
@@ -406,10 +638,22 @@ file_hup(struct file *f)
 {
 	struct aproc *p;
 
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(f);
+		dbg_puts(": hup requested\n");
+	}
+#endif
 	if (!(f->state & (FILE_RINUSE | FILE_WINUSE))) {
 		p = f->wproc;
 		if (p) {
 			f->state |= FILE_WINUSE;
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": hup\n");
+			}
+#endif
 			p->ops->hup(p, NULL);
 			f->state &= ~FILE_WINUSE;
 		}
@@ -426,16 +670,34 @@ file_close(struct file *f)
 {
 	struct aproc *p;
 
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(f);
+		dbg_puts(": closing\n");
+	}
+#endif
 	if (!(f->state & (FILE_RINUSE | FILE_WINUSE))) {
 		p = f->rproc;
 		if (p) {
 			f->state |= FILE_RINUSE;
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": eof\n");
+			}
+#endif
 			p->ops->eof(p, NULL);
 			f->state &= ~FILE_RINUSE;
 		}
 		p = f->wproc;
 		if (p) {
 			f->state |= FILE_WINUSE;
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": hup\n");
+			}
+#endif
 			p->ops->hup(p, NULL);
 			f->state &= ~FILE_WINUSE;
 		}
diff --git a/usr.bin/aucat/headers.c b/usr.bin/aucat/headers.c
index 20f68d01436..e9a8ed256dc 100644
--- a/usr.bin/aucat/headers.c
+++ b/usr.bin/aucat/headers.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: headers.c,v 1.9 2009/12/12 15:15:34 ratchov Exp $	*/
+/*	$OpenBSD: headers.c,v 1.10 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -164,6 +164,10 @@ wav_readhdr(int fd, struct aparams *par, off_t *datasz, short **map)
 			*datasz = csize;
 			break;
 		} else {
+#ifdef DEBUG
+			if (debug_level >= 1) 
+				warnx("ignoring chuck <%.4s>\n", chunk.id);
+#endif
 		}
 
 		/*
diff --git a/usr.bin/aucat/midi.c b/usr.bin/aucat/midi.c
index 8c8a80698cf..352dcab7543 100644
--- a/usr.bin/aucat/midi.c
+++ b/usr.bin/aucat/midi.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: midi.c,v 1.13 2009/11/03 21:31:37 ratchov Exp $	*/
+/*	$OpenBSD: midi.c,v 1.14 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -32,6 +32,9 @@
 #include "conf.h"
 #include "dev.h"
 #include "midi.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 /*
  * input data rate is XFER / TIMO (in bytes per microsecond),
@@ -80,8 +83,24 @@ thru_flush(struct aproc *p, struct abuf *ibuf, struct abuf *obuf)
 
 	itodo = ibuf->r.midi.used;
 	idata = ibuf->r.midi.msg;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": flushing ");
+		dbg_putu(itodo);
+		dbg_puts(" byte message\n");
+	}
+#endif
 	while (itodo > 0) {
 		if (!ABUF_WOK(obuf)) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				aproc_dbg(p);
+				dbg_puts(": overrun, discarding ");
+				dbg_putu(obuf->used);
+				dbg_puts(" bytes\n");
+			}
+#endif
 			abuf_rdiscard(obuf, obuf->used);
 			if (p->u.thru.owner == ibuf)
 				p->u.thru.owner = NULL;
@@ -108,7 +127,23 @@ thru_rt(struct aproc *p, struct abuf *ibuf, struct abuf *obuf, unsigned c)
 	unsigned ocount;
 	unsigned char *odata;
 
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": ");
+		dbg_putu(c);
+		dbg_puts(": flushing realtime message\n");
+	}
+#endif
 	if (!ABUF_WOK(obuf)) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			aproc_dbg(p);
+			dbg_puts(": overrun, discarding ");
+			dbg_putu(obuf->used);
+			dbg_puts(" bytes\n");
+		}
+#endif
 		abuf_rdiscard(obuf, obuf->used);
 		if (p->u.thru.owner == ibuf)
 			p->u.thru.owner = NULL;
@@ -199,6 +234,12 @@ thru_in(struct aproc *p, struct abuf *ibuf)
 	if (!ABUF_ROK(ibuf))
 		return 0;
 	if (ibuf->tickets == 0) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			abuf_dbg(ibuf);
+			dbg_puts(": out of tickets, blocking\n");
+		}
+#endif
 		return 0;
 	}
 	todo = ibuf->used;
@@ -304,6 +345,42 @@ thru_new(char *name)
 	return p;
 }
 
+#ifdef DEBUG
+void
+ctl_slotdbg(struct aproc *p, int slot)
+{
+	struct ctl_slot *s;
+
+	aproc_dbg(p);
+	if (slot < 0) {
+		dbg_puts("/none");
+	} else {
+		s = p->u.ctl.slot + slot;
+		dbg_puts(s->name);
+		dbg_putu(s->unit);
+		dbg_puts("=");
+		dbg_putu(s->vol);
+		dbg_puts("/");
+		switch (s->tstate) {
+		case CTL_OFF:
+			dbg_puts("off");
+			break;
+		case CTL_RUN:
+			dbg_puts("run");
+			break;
+		case CTL_START:
+			dbg_puts("sta");
+			break;
+		case CTL_STOP:
+			dbg_puts("stp");
+			break;
+		default:
+			dbg_puts("unk");
+			break;
+		}
+	}
+}
+#endif
 
 /*
  * broadcast a message to all output buffers on the behalf of ibuf.
@@ -324,11 +401,27 @@ ctl_sendmsg(struct aproc *p, struct abuf *ibuf, unsigned char *msg, unsigned len
 		idata = msg;
 		while (itodo > 0) {
 			if (!ABUF_WOK(i)) {
+#ifdef DEBUG
+				if (debug_level >= 4) {
+					abuf_dbg(i);
+					dbg_puts(": overrun, discarding ");
+					dbg_putu(i->used);
+					dbg_puts(" bytes\n");
+				}
+#endif
 				abuf_rdiscard(i, i->used);
 			}
 			odata = abuf_wgetblk(i, &ocount, 0);
 			if (ocount > itodo)
 				ocount = itodo;
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				abuf_dbg(i);
+				dbg_puts(": stored ");
+				dbg_putu(ocount);
+				dbg_puts(" bytes\n");
+			}
+#endif
 			memcpy(odata, idata, ocount);
 			abuf_wcommit(i, ocount);
 			itodo -= ocount;
@@ -474,6 +567,15 @@ ctl_getidx(struct aproc *p, char *who)
 		if ((umap & (1 << unit)) == 0)
 			break;
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": new control name is ");
+		dbg_puts(name);
+		dbg_putu(unit);
+		dbg_puts("\n");
+	}
+#endif
 	/*
 	 * find a free controller slot with the same name/unit
 	 */
@@ -481,6 +583,14 @@ ctl_getidx(struct aproc *p, char *who)
 		if (slot->ops == NULL &&
 		    strcmp(slot->name, name) == 0 &&
 		    slot->unit == unit) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				aproc_dbg(p);
+				dbg_puts(": found slot ");
+				dbg_putu(i);
+				dbg_puts("\n");
+			}
+#endif
 			return i;
 		}
 	}
@@ -507,6 +617,14 @@ ctl_getidx(struct aproc *p, char *who)
 	slot->serial = p->u.ctl.serial++;
 	slot->unit = unit;
 	slot->vol = MIDI_MAXCTL;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		aproc_dbg(p);
+		dbg_puts(": overwritten slot ");
+		dbg_putu(bestidx);
+		dbg_puts("\n");
+	}
+#endif
 	return bestidx;
 }
 
@@ -521,12 +639,20 @@ ctl_trystart(struct aproc *p, int caller)
 	struct ctl_slot *s;
 
 	if (p->u.ctl.tstate != CTL_START) {
+#ifdef DEBUG
+		aproc_dbg(p);
+		dbg_puts(": not in starting state\n");
+#endif
 		return 0;
 	}
 	for (i = 0, s = p->u.ctl.slot; i < CTL_NSLOT; i++, s++) {
 		if (!s->ops || i == caller)
 			continue;
 		if (s->tstate != CTL_OFF && s->tstate != CTL_START) {
+#ifdef DEBUG
+			ctl_slotdbg(p, i);
+			dbg_puts(": not ready to start, start delayed\n");
+#endif
 			return 0;
 		}
 	}
@@ -534,6 +660,10 @@ ctl_trystart(struct aproc *p, int caller)
 		if (!s->ops || i == caller)
 			continue;
 		if (s->tstate == CTL_START) {
+#ifdef DEBUG
+			ctl_slotdbg(p, i);
+			dbg_puts(": started\n");
+#endif
 			s->tstate = CTL_RUN;
 			s->ops->start(s->arg);
 		}
@@ -552,6 +682,14 @@ ctl_trystart(struct aproc *p, int caller)
 		p->u.ctl.fps_id = MTC_FPS_24;
 		p->u.ctl.fps = 24;
 	} 
+#ifdef DEBUG
+	ctl_slotdbg(p, caller);
+	dbg_puts(": started server at ");
+	dbg_puti(p->u.ctl.delta);
+	dbg_puts(", ");
+	dbg_puti(p->u.ctl.fps);
+	dbg_puts(" mtc fps\n");
+#endif
 	ctl_full(p);
 	return 1;
 }
@@ -644,6 +782,14 @@ ctl_slotvol(struct aproc *p, int slot, unsigned vol)
 
 	if (p == NULL)
 		return;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		ctl_slotdbg(p, slot);
+		dbg_puts(": changing volume to ");
+		dbg_putu(vol);
+		dbg_puts("\n");
+	}
+#endif
 	p->u.ctl.slot[slot].vol = vol;
 	msg[0] = MIDI_CTL | slot;
 	msg[1] = MIDI_CTLVOL;
@@ -705,6 +851,19 @@ ctl_ev(struct aproc *p, struct abuf *ibuf)
 	unsigned chan;
 	struct ctl_slot *slot;
 	unsigned fps;
+#ifdef DEBUG
+	unsigned i;
+
+	if (debug_level >= 3) {
+		abuf_dbg(ibuf);
+		dbg_puts(": got event:");
+		for (i = 0; i < ibuf->r.midi.idx; i++) {
+			dbg_puts(" ");
+			dbg_putx(ibuf->r.midi.msg[i]);
+		}
+		dbg_puts("\n");
+	}
+#endif
 	if ((ibuf->r.midi.msg[0] & MIDI_CMDMASK) == MIDI_CTL &&
 	    ibuf->r.midi.msg[1] == MIDI_CTLVOL) {
 		chan = ibuf->r.midi.msg[0] & MIDI_CHANMASK;
@@ -724,14 +883,41 @@ ctl_ev(struct aproc *p, struct abuf *ibuf)
 	    ibuf->r.midi.msg[5] == 0xf7) {	/* subtype is mmc */
 		switch (ibuf->r.midi.msg[4]) {
 		case 0x01:	/* mmc stop */
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				abuf_dbg(ibuf);
+				dbg_puts(": mmc stop\n");
+			}
+#endif
 			if (p->u.ctl.tstate == CTL_RUN ||
 		            p->u.ctl.tstate == CTL_START) 
 				p->u.ctl.tstate = CTL_STOP;
+#ifdef DEBUG
+			else {
+				if (debug_level >= 1) {
+					aproc_dbg(p);
+					dbg_puts(": ignored mmc stop\n");
+				}
+			}
+#endif
 			break;
 		case 0x02:	/* mmc start */
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				abuf_dbg(ibuf);
+				dbg_puts(": mmc start\n");
+			}
+#endif
 			if (p->u.ctl.tstate == CTL_STOP) {
 				p->u.ctl.tstate = CTL_START;
 				(void)ctl_trystart(p, -1);
+#ifdef DEBUG
+			} else {
+				if (debug_level >= 1) {
+					abuf_dbg(ibuf);
+					dbg_puts(": ignoring mmc start\n");
+				}
+#endif
 			}
 			break;
 		}
@@ -764,6 +950,14 @@ ctl_ev(struct aproc *p, struct abuf *ibuf)
 		    ibuf->r.midi.msg[9] * MTC_SEC +
 		    ibuf->r.midi.msg[10] * (MTC_SEC / fps) +
 		    ibuf->r.midi.msg[11] * (MTC_SEC / 100 / fps);
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			aproc_dbg(p);
+			dbg_puts(": relocated to ");
+			dbg_putu(p->u.ctl.origin);
+			dbg_puts("\n");
+		}
+#endif
 	}
 }
 
@@ -862,6 +1056,20 @@ ctl_newin(struct aproc *p, struct abuf *ibuf)
 void
 ctl_done(struct aproc *p)
 {
+#ifdef DEBUG
+	unsigned i;
+	struct ctl_slot *s;
+
+	for (i = 0, s = p->u.ctl.slot; i < CTL_NSLOT; i++, s++) {
+		/*
+		 * XXX: shouldn't we abord() here ?
+		 */
+		if (s->ops != NULL) {
+			ctl_slotdbg(p, i);
+			dbg_puts(": still in use\n");
+		}
+	}
+#endif
 }
 
 struct aproc_ops ctl_ops = {
diff --git a/usr.bin/aucat/miofile.c b/usr.bin/aucat/miofile.c
index d8c45125113..f3038c88b47 100644
--- a/usr.bin/aucat/miofile.c
+++ b/usr.bin/aucat/miofile.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: miofile.c,v 1.3 2009/11/05 08:36:48 ratchov Exp $	*/
+/*	$OpenBSD: miofile.c,v 1.4 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -27,6 +27,9 @@
 #include "conf.h"
 #include "file.h"
 #include "miofile.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 struct miofile {
 	struct file file;
@@ -94,8 +97,18 @@ miofile_read(struct file *file, unsigned char *data, unsigned count)
 	if (n == 0) {
 		f->file.state &= ~FILE_ROK;
 		if (mio_eof(f->hdl)) {
+#ifdef DEBUG
+			dbg_puts(f->file.name);
+			dbg_puts(": failed to read from device\n");
+#endif
 			file_eof(&f->file);
 		} else {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": reading blocked\n");
+			}
+#endif
 		}
 		return 0;
 	}
@@ -113,8 +126,18 @@ miofile_write(struct file *file, unsigned char *data, unsigned count)
 	if (n == 0) {
 		f->file.state &= ~FILE_WOK;
 		if (mio_eof(f->hdl)) {
+#ifdef DEBUG
+			dbg_puts(f->file.name);
+			dbg_puts(": failed to write on device\n");
+#endif
 			file_hup(&f->file);
 		} else {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": writing blocked\n");
+			}
+#endif
 		}
 		return 0;
 	}
diff --git a/usr.bin/aucat/opt.c b/usr.bin/aucat/opt.c
index 83dd689bf8e..3c7e8959765 100644
--- a/usr.bin/aucat/opt.c
+++ b/usr.bin/aucat/opt.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: opt.c,v 1.3 2009/11/03 21:31:37 ratchov Exp $	*/
+/*	$OpenBSD: opt.c,v 1.4 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -20,6 +20,9 @@
 
 #include "conf.h"
 #include "opt.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 struct optlist opt_list = SLIST_HEAD_INITIALIZER(&opt_list);
 
@@ -55,6 +58,20 @@ opt_new(char *name,
 	o->rpar = *rpar;
 	o->maxweight = maxweight;
 	o->mmc = mmc;
+#ifdef DEBUG
+	if (debug_level >= 2) {
+		dbg_puts(o->name);
+		dbg_puts(": rec ");
+		aparams_dbg(&o->wpar);
+		dbg_puts(", play ");
+		aparams_dbg(&o->rpar);
+		dbg_puts(", vol ");
+		dbg_putu(o->maxweight);
+		if (o->mmc)
+			dbg_puts(", mmc");
+		dbg_puts("\n");
+	}
+#endif
 	SLIST_INSERT_HEAD(&opt_list, o, entry);
 }
 
@@ -65,9 +82,21 @@ opt_byname(char *name)
 
 	SLIST_FOREACH(o, &opt_list, entry) {
 		if (strcmp(name, o->name) == 0) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				dbg_puts(o->name);
+				dbg_puts(": option found\n");
+			}
+#endif
 			return o;
 		}
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		dbg_puts(name);
+		dbg_puts(": option not found\n");
+	}
+#endif
 	return NULL;
 }
 
diff --git a/usr.bin/aucat/pipe.c b/usr.bin/aucat/pipe.c
index d95afdb4e77..76f98baa832 100644
--- a/usr.bin/aucat/pipe.c
+++ b/usr.bin/aucat/pipe.c
@@ -27,6 +27,9 @@
 
 #include "conf.h"
 #include "pipe.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 struct fileops pipe_ops = {
 	"pipe",
@@ -62,6 +65,12 @@ pipe_read(struct file *file, unsigned char *data, unsigned count)
 	while ((n = read(f->fd, data, count)) < 0) {
 		f->file.state &= ~FILE_ROK;
 		if (errno == EAGAIN) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": reading blocked\n");
+			}
+#endif
 		} else {
 			warn("%s", f->file.name);
 			file_eof(&f->file);
@@ -86,6 +95,12 @@ pipe_write(struct file *file, unsigned char *data, unsigned count)
 	while ((n = write(f->fd, data, count)) < 0) {
 		f->file.state &= ~FILE_WOK;
 		if (errno == EAGAIN) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": writing blocked\n");
+			}
+#endif
 		} else {
 			if (errno != EPIPE)
 				warn("%s", f->file.name);
diff --git a/usr.bin/aucat/safile.c b/usr.bin/aucat/safile.c
index 425c44cec5e..2d5b5516261 100644
--- a/usr.bin/aucat/safile.c
+++ b/usr.bin/aucat/safile.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: safile.c,v 1.19 2009/11/05 08:36:48 ratchov Exp $	*/
+/*	$OpenBSD: safile.c,v 1.20 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -30,6 +30,9 @@
 #include "dev.h"
 #include "file.h"
 #include "safile.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 struct safile {
 	struct file file;
@@ -163,10 +166,20 @@ safile_start(struct file *file)
 	struct safile *f = (struct safile *)file;
 
 	if (!sio_start(f->hdl)) {
+#ifdef DEBUG
+		dbg_puts(f->file.name);
+		dbg_puts(": failed to start device\n");
+#endif
 		file_close(file);
 		return;
 	}
 	f->started = 1;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(&f->file);
+		dbg_puts(": started\n");
+	}
+#endif
 }
 
 void
@@ -176,9 +189,19 @@ safile_stop(struct file *file)
 
 	f->started = 0;
 	if (!sio_eof(f->hdl) && !sio_stop(f->hdl)) {
+#ifdef DEBUG
+		dbg_puts(f->file.name);
+		dbg_puts(": failed to stop device\n");
+#endif
 		file_close(file);
 		return;
 	}
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		file_dbg(&f->file);
+		dbg_puts(": stopped\n");
+	}
+#endif
 }
 
 unsigned
@@ -191,8 +214,18 @@ safile_read(struct file *file, unsigned char *data, unsigned count)
 	if (n == 0) {
 		f->file.state &= ~FILE_ROK;
 		if (sio_eof(f->hdl)) {
+#ifdef DEBUG
+			dbg_puts(f->file.name);
+			dbg_puts(": failed to read from device\n");
+#endif
 			file_eof(&f->file);
 		} else {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": reading blocked\n");
+			}
+#endif
 		}
 		return 0;
 	}
@@ -210,8 +243,18 @@ safile_write(struct file *file, unsigned char *data, unsigned count)
 	if (n == 0) {
 		f->file.state &= ~FILE_WOK;
 		if (sio_eof(f->hdl)) {
+#ifdef DEBUG
+			dbg_puts(f->file.name);
+			dbg_puts(": failed to write on device\n");
+#endif
 			file_hup(&f->file);
 		} else {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				file_dbg(&f->file);
+				dbg_puts(": writing blocked\n");
+			}
+#endif
 		}
 		return 0;
 	}
diff --git a/usr.bin/aucat/sock.c b/usr.bin/aucat/sock.c
index 2fa277bca53..d11ffe0b8ed 100644
--- a/usr.bin/aucat/sock.c
+++ b/usr.bin/aucat/sock.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: sock.c,v 1.36 2010/01/05 10:18:12 ratchov Exp $	*/
+/*	$OpenBSD: sock.c,v 1.37 2010/01/10 21:47:41 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -32,6 +32,9 @@
 #include "midi.h"
 #include "opt.h"
 #include "sock.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 int sock_attach(struct sock *, int);
 int sock_read(struct sock *);
@@ -52,6 +55,27 @@ struct fileops sock_ops = {
 	pipe_revents
 };
 
+#ifdef DEBUG
+void
+sock_dbg(struct sock *f)
+{
+	static char *pstates[] = { "hel", "ini", "sta", "run", "mid" };
+	static char *rstates[] = { "rdat", "rmsg", "rret" };
+	static char *wstates[] = { "widl", "wmsg", "wdat" };
+
+	if (f->slot >= 0 && dev_midi) {
+		dbg_puts(dev_midi->u.ctl.slot[f->slot].name);
+		dbg_putu(dev_midi->u.ctl.slot[f->slot].unit);
+	} else
+		dbg_puts(f->pipe.file.name);
+	dbg_puts("/");
+	dbg_puts(pstates[f->pstate]);
+	dbg_puts("|");
+	dbg_puts(rstates[f->rstate]);
+	dbg_puts("|");
+	dbg_puts(wstates[f->wstate]);
+}
+#endif
 
 void sock_setvol(void *, unsigned);
 void sock_startreq(void *);
@@ -138,6 +162,14 @@ rsock_opos(struct aproc *p, struct abuf *obuf, int delta)
 		return;
 
 	f->delta += delta;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": moved to delta = ");
+		dbg_puti(f->delta);
+		dbg_puts("\n");
+	}
+#endif
 	f->tickpending++;
 	for (;;) {
 		if (!sock_write(f))
@@ -229,6 +261,14 @@ wsock_ipos(struct aproc *p, struct abuf *obuf, int delta)
 		return;
 
 	f->delta += delta;
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		aproc_dbg(p);
+		dbg_puts(": moved to delta = ");
+		dbg_puti(f->delta);
+		dbg_puts("\n");
+	}
+#endif
 	f->tickpending++;
 	for (;;) {
 		if (!sock_write(f))
@@ -302,6 +342,12 @@ sock_freebuf(struct sock *f)
 	struct abuf *rbuf, *wbuf;
 
 	f->pstate = SOCK_INIT;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		sock_dbg(f);
+		dbg_puts(": freeing buffers\n");
+	}
+#endif
 	wbuf = LIST_FIRST(&f->pipe.file.wproc->ibuflist);
 	rbuf = LIST_FIRST(&f->pipe.file.rproc->obuflist);
 	if (rbuf || wbuf)
@@ -331,6 +377,14 @@ sock_allocbuf(struct sock *f)
 	}
 	f->delta = 0;
 	f->tickpending = 0;
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		sock_dbg(f);
+		dbg_puts(": allocating ");
+		dbg_putu(f->bufsz);
+		dbg_puts(" fr buffers\n");
+	}
+#endif
 	f->pstate = SOCK_START;
 	if (!(f->mode & AMSG_PLAY) && ctl_slotstart(dev_midi, f->slot))
 		(void)sock_attach(f, 0);
@@ -348,6 +402,12 @@ sock_setvol(void *arg, unsigned vol)
 	f->vol = vol;
 	rbuf = LIST_FIRST(&f->pipe.file.rproc->obuflist);
 	if (!rbuf) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": no read buffer to set volume yet\n");
+		}
+#endif
 		return;
 	}
 	dev_setvol(rbuf, MIDI_TO_ADATA(vol));
@@ -361,6 +421,13 @@ sock_startreq(void *arg)
 {
 	struct sock *f = (struct sock *)arg;
 
+#ifdef DEBUG
+	if (f->pstate != SOCK_START) {
+		sock_dbg(f);
+		dbg_puts(": not in START state\n");
+		dbg_panic();
+	}
+#endif
 	(void)sock_attach(f, 0);
 }
 
@@ -382,6 +449,12 @@ sock_attach(struct sock *f, int force)
 	if (!force && rbuf && ABUF_WOK(rbuf))
 		return 0;
 
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		sock_dbg(f);
+		dbg_puts(": attaching to device\n");
+	}
+#endif
 	f->pstate = SOCK_RUN;
 
 	/*
@@ -436,6 +509,14 @@ sock_rmsg(struct sock *f)
 
 	while (f->rtodo > 0) {
 		if (!(f->pipe.file.state & FILE_ROK)) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				sock_dbg(f);
+				dbg_puts(": reading message blocked, ");
+				dbg_putu(f->rtodo);
+				dbg_puts(" bytes remaining\n");
+			}
+#endif
 			return 0;
 		}
 		data = (unsigned char *)&f->rmsg;
@@ -445,6 +526,12 @@ sock_rmsg(struct sock *f)
 			return 0;
 		f->rtodo -= count;
 	}
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		sock_dbg(f);
+		dbg_puts(": read full message\n");
+	}
+#endif
 	return 1;
 }
 
@@ -461,6 +548,14 @@ sock_wmsg(struct sock *f, struct amsg *m, unsigned *ptodo)
 
 	while (*ptodo > 0) {
 		if (!(f->pipe.file.state & FILE_WOK)) {
+#ifdef DEBUG
+			if (debug_level >= 4) {
+				sock_dbg(f);
+				dbg_puts(": writing message blocked, ");
+				dbg_putu(*ptodo);
+				dbg_puts(" bytes remaining\n");
+			}
+#endif
 			return 0;
 		}
 		data = (unsigned char *)m;
@@ -470,6 +565,12 @@ sock_wmsg(struct sock *f, struct amsg *m, unsigned *ptodo)
 			return 0;
 		*ptodo -= count;
 	}
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		sock_dbg(f);
+		dbg_puts(": wrote full message\n");
+	}
+#endif
 	return 1;
 }
 
@@ -485,6 +586,13 @@ sock_rdata(struct sock *f)
 	unsigned char *data;
 	unsigned count, n;
 
+#ifdef DEBUG
+	if (f->pstate != SOCK_MIDI && f->rtodo == 0) {
+		sock_dbg(f);
+		dbg_puts(": data block already read\n");
+		dbg_panic();
+	}
+#endif
 	p = f->pipe.file.rproc;
 	obuf = LIST_FIRST(&p->obuflist);
 	if (obuf == NULL)
@@ -517,6 +625,13 @@ sock_wdata(struct sock *f)
 #define ZERO_MAX 0x1000
 	static unsigned char zero[ZERO_MAX];
 
+#ifdef DEBUG
+	if (f->pstate != SOCK_MIDI && f->wtodo == 0) {
+		sock_dbg(f);
+		dbg_puts(": attempted to write zero-sized data block\n");
+		dbg_panic();
+	}
+#endif
 	if (!(f->pipe.file.state & FILE_WOK))
 		return 0;
 	p = f->pipe.file.wproc;
@@ -561,16 +676,42 @@ sock_setpar(struct sock *f)
 
 	if (AMSG_ISSET(p->bits)) {
 		if (p->bits < BITS_MIN || p->bits > BITS_MAX) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": ");
+				dbg_putu(p->bits);
+				dbg_puts(": bits out of bounds\n");
+			}
+#endif
 			return 0;
 		}
 		if (AMSG_ISSET(p->bps)) {
 			if (p->bps < ((p->bits + 7) / 8) || p->bps > 4) {
+#ifdef DEBUG
+				if (debug_level >= 1) {
+					sock_dbg(f);
+					dbg_puts(": ");
+					dbg_putu(p->bps);
+					dbg_puts(": wrong bytes per sample\n");
+				}
+#endif
 				return 0;
 			}
 		} else
 			p->bps = APARAMS_BPS(p->bits);
 		f->rpar.bits = f->wpar.bits = p->bits;
 		f->rpar.bps = f->wpar.bps = p->bps;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using ");
+			dbg_putu(p->bits);
+			dbg_puts("bits, ");
+			dbg_putu(p->bps);
+			dbg_puts(" bytes per sample\n");
+		}
+#endif
 	}
 	if (AMSG_ISSET(p->sig))
 		f->rpar.sig = f->wpar.sig = p->sig ? 1 : 0;
@@ -587,6 +728,16 @@ sock_setpar(struct sock *f)
 		f->wpar.cmax = f->opt->wpar.cmin + p->rchan - 1;
 		if (f->wpar.cmax > f->opt->wpar.cmax)
 			f->wpar.cmax = f->opt->wpar.cmax;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using recording channels ");
+			dbg_putu(f->wpar.cmin);
+			dbg_puts("..");
+			dbg_putu(f->wpar.cmax);
+			dbg_puts("\n");
+		}
+#endif
 	}
 	if (AMSG_ISSET(p->pchan) && (f->mode & AMSG_PLAY)) {
 		if (p->pchan < 1)
@@ -597,6 +748,16 @@ sock_setpar(struct sock *f)
 		f->rpar.cmax = f->opt->rpar.cmin + p->pchan - 1;
 		if (f->rpar.cmax > f->opt->rpar.cmax)
 			f->rpar.cmax = f->opt->rpar.cmax;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using playback channels ");
+			dbg_putu(f->rpar.cmin);
+			dbg_puts("..");
+			dbg_putu(f->rpar.cmax);
+			dbg_puts("\n");
+		}
+#endif
 	}
 	if (AMSG_ISSET(p->rate)) {
 		if (p->rate < RATE_MIN)
@@ -607,23 +768,65 @@ sock_setpar(struct sock *f)
 		f->rpar.rate = f->wpar.rate = p->rate;
 		if (!AMSG_ISSET(p->appbufsz)) {
 			p->appbufsz = dev_bufsz / dev_round * f->round;
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				sock_dbg(f);
+				dbg_puts(": using ");
+				dbg_putu(p->appbufsz);
+				dbg_puts(" fr app buffer size\n");
+			}
+#endif
 		}
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using ");
+			dbg_putu(p->rate);
+			dbg_puts("Hz sample rate, ");
+			dbg_putu(f->round);
+			dbg_puts(" fr block size\n");
+		}
+#endif
 	}
 	if (AMSG_ISSET(p->xrun)) {
 		if (p->xrun != AMSG_IGNORE &&
 		    p->xrun != AMSG_SYNC &&
 		    p->xrun != AMSG_ERROR) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": ");
+				dbg_putx(p->xrun);
+				dbg_puts(": bad xrun policy\n");
+			}
+#endif
 			return 0;
 		}
 		f->xrun = p->xrun;
 		if (f->opt->mmc && f->xrun == AMSG_IGNORE)
 			f->xrun = AMSG_SYNC;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using 0x");
+			dbg_putx(f->xrun);
+			dbg_puts(" xrun policy\n");
+		}
+#endif
 	}
 	if (AMSG_ISSET(p->bufsz)) {
 		/*
 		 * XXX: bufsz will become read-only, but for now
 		 *      allow old library to properly work
 		 */
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			sock_dbg(f);
+			dbg_puts(": legacy client using ");
+			dbg_putx(p->bufsz);
+			dbg_puts("fr total buffer size\n");
+		}
+#endif
 		min = (dev_bufsz / dev_round) * f->round;
 		if (p->bufsz < min)
 			p->bufsz = min;
@@ -642,7 +845,35 @@ sock_setpar(struct sock *f)
 		if (p->appbufsz > max)
 			p->appbufsz = max;
 		f->bufsz = p->appbufsz;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": using ");
+			dbg_putu(f->bufsz);
+			dbg_puts(" buffer size\n");
+		}
+#endif
 	}
+#ifdef DEBUG
+	if (debug_level >= 2) {
+		if (f->slot >= -1 && dev_midi) {
+			dbg_puts(dev_midi->u.ctl.slot[f->slot].name);
+			dbg_putu(dev_midi->u.ctl.slot[f->slot].unit);
+		} else
+			dbg_puts(f->pipe.file.name);
+		dbg_puts(": buffer size = ");
+		dbg_putu(f->bufsz);
+		if (f->mode & AMSG_PLAY) {
+			dbg_puts(", play = ");
+			aparams_dbg(&f->rpar);
+		}
+		if (f->mode & AMSG_REC) {
+			dbg_puts(", rec:");
+			aparams_dbg(&f->wpar);
+		}
+		dbg_puts("\n");
+	}
+#endif
 	return 1;
 }
 
@@ -670,7 +901,27 @@ sock_hello(struct sock *f)
 {
 	struct amsg_hello *p = &f->rmsg.u.hello;
 
+#ifdef DEBUG
+	if (debug_level >= 3) {
+		sock_dbg(f);
+		dbg_puts(": hello from <");
+		dbg_puts(p->who);
+		dbg_puts(">, proto = ");
+		dbg_putx(p->proto);
+		dbg_puts(", ver ");
+		dbg_putu(p->version);
+		dbg_puts("\n");
+	}
+#endif
 	if (p->version != AMSG_VERSION) {
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			sock_dbg(f);
+			dbg_puts(": ");
+			dbg_putu(p->version);
+			dbg_puts(": bad version\n");
+		}
+#endif
 		return 0;
 	}
 	/*
@@ -678,6 +929,14 @@ sock_hello(struct sock *f)
 	 */
 	if (dev_midi && (p->proto & (AMSG_MIDIIN | AMSG_MIDIOUT))) {
 		if (p->proto & ~(AMSG_MIDIIN | AMSG_MIDIOUT)) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": ");
+				dbg_putx(p->proto);
+				dbg_puts(": bad hello protocol\n");
+			}
+#endif
 			return 0;
 		}
 		f->mode = p->proto;
@@ -696,17 +955,37 @@ sock_hello(struct sock *f)
 		f->xrun = AMSG_SYNC;
 	if ((p->proto & ~(AMSG_PLAY | AMSG_REC)) != 0 ||
 	    (p->proto &  (AMSG_PLAY | AMSG_REC)) == 0) {
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			sock_dbg(f);
+			dbg_puts(": ");
+			dbg_putx(p->proto);
+			dbg_puts(": unsupported hello protocol\n");
+		}
+#endif
 		return 0;
 	}
 	f->mode = 0;
 	if (p->proto & AMSG_PLAY) {
 		if (!dev_mix) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": playback not available\n");
+			}
+#endif
 			return 0;
 		}
 		f->mode |= AMSG_PLAY;
 	}
 	if (p->proto & AMSG_REC) {
 		if (!dev_sub) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": recording not available\n");
+			}
+#endif
 			return 0;
 		}
 		f->mode |= AMSG_REC;
@@ -716,6 +995,12 @@ sock_hello(struct sock *f)
 		     p->who, &ctl_sockops, f,
 		     f->opt->mmc);
 		if (f->slot < 0) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": out of mixer slots\n");
+			}
+#endif
 			return 0;
 		}
 	}
@@ -734,28 +1019,70 @@ sock_execmsg(struct sock *f)
 
 	switch (m->cmd) {
 	case AMSG_DATA:
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			sock_dbg(f);
+			dbg_puts(": DATA message\n");
+		}
+#endif
 		if (f->pstate != SOCK_RUN && f->pstate != SOCK_START) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": DATA, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
 		if (!(f->mode & AMSG_PLAY)) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": DATA not allowed in record-only mode\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
 		if (f->pstate == SOCK_START &&
 		    ABUF_FULL(LIST_FIRST(&f->pipe.file.rproc->obuflist))) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": DATA client violates flow control\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
 		f->rstate = SOCK_RDATA;
 		f->rtodo = m->u.data.size;
 		if (f->rtodo == 0) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": zero-length data chunk\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
 		break;
 	case AMSG_START:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": START message\n");
+		}
+#endif
 		if (f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": START, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -764,7 +1091,19 @@ sock_execmsg(struct sock *f)
 		f->rtodo = sizeof(struct amsg);
 		break;
 	case AMSG_STOP:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": STOP message\n");
+		}
+#endif
 		if (f->pstate != SOCK_RUN && f->pstate != SOCK_START) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": STOP, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -778,7 +1117,19 @@ sock_execmsg(struct sock *f)
 		f->rtodo = sizeof(struct amsg);
 		break;
 	case AMSG_SETPAR:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": SETPAR message\n");
+		}
+#endif
 		if (f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": SETPAR, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -790,7 +1141,19 @@ sock_execmsg(struct sock *f)
 		f->rstate = SOCK_RMSG;
 		break;
 	case AMSG_GETPAR:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": GETPAR message\n");
+		}
+#endif
 		if (f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": GETPAR, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -813,7 +1176,19 @@ sock_execmsg(struct sock *f)
 		f->rtodo = sizeof(struct amsg);
 		break;
 	case AMSG_GETCAP:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": GETCAP message\n");
+		}
+#endif
 		if (f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": GETCAP, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -830,12 +1205,30 @@ sock_execmsg(struct sock *f)
 		f->rtodo = sizeof(struct amsg);
 		break;
 	case AMSG_SETVOL:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": SETVOL message\n");
+		}
+#endif
 		if (f->pstate != SOCK_RUN &&
 		    f->pstate != SOCK_START && f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": SETVOL, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
 		if (m->u.vol.ctl > MIDI_MAXCTL) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": SETVOL, volume out of range\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -846,7 +1239,19 @@ sock_execmsg(struct sock *f)
 		f->rstate = SOCK_RMSG;
 		break;
 	case AMSG_HELLO:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": HELLO message\n");
+		}
+#endif
 		if (f->pstate != SOCK_HELLO) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": HELLO, bad state\n");
+			}
+#endif
 			aproc_del(f->pipe.file.rproc);
 			return 0;
 		}
@@ -860,11 +1265,29 @@ sock_execmsg(struct sock *f)
 		f->rtodo = sizeof(struct amsg);
 		break;
 	case AMSG_BYE:
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": BYE message\n");
+		}
+#endif
 		if (f->pstate != SOCK_INIT) {
+#ifdef DEBUG
+			if (debug_level >= 1) {
+				sock_dbg(f);
+				dbg_puts(": BYE, bad state\n");
+			}
+#endif
 		}
 		aproc_del(f->pipe.file.rproc);
 		return 0;
 	default:
+#ifdef DEBUG
+		if (debug_level >= 1) {
+			sock_dbg(f);
+			dbg_puts(": unknown command in message\n");
+		}
+#endif
 		aproc_del(f->pipe.file.rproc);
 		return 0;
 	}
@@ -872,6 +1295,12 @@ sock_execmsg(struct sock *f)
 		if (f->wstate != SOCK_WIDLE ||
 		    !sock_wmsg(f, &f->rmsg, &f->rtodo))
 			return 0;
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": RRET done\n");
+		}
+#endif
 		if (f->pstate == SOCK_MIDI && (f->mode & AMSG_MIDIOUT)) {
 			f->rstate = SOCK_RDATA;
 			f->rtodo = 0;
@@ -893,6 +1322,12 @@ sock_buildmsg(struct sock *f)
 	struct abuf *ibuf;
 
 	if (f->pstate == SOCK_MIDI) {
+#ifdef DEBUG
+		if (debug_level >= 3) {
+			sock_dbg(f);
+			dbg_puts(": switching to MIDI mode\n");
+		}
+#endif
 		f->wstate = SOCK_WDATA;
 		f->wtodo = 0;
 		return 1;
@@ -902,6 +1337,14 @@ sock_buildmsg(struct sock *f)
 	 * If pos changed, build a MOVE message.
 	 */
 	if (f->tickpending) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			sock_dbg(f);
+			dbg_puts(": building POS message, delta = ");
+			dbg_puti(f->delta);
+			dbg_puts("\n");
+		}
+#endif
 		AMSG_INIT(&f->wmsg);
 		f->wmsg.cmd = AMSG_MOVE;
 		f->wmsg.u.ts.delta = f->delta;
@@ -916,6 +1359,14 @@ sock_buildmsg(struct sock *f)
 	 * if volume changed build a SETVOL message
 	 */
 	if (f->pstate >= SOCK_START && f->vol != f->lastvol) {
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			sock_dbg(f);
+			dbg_puts(": building SETVOL message, vol = ");
+			dbg_puti(f->vol);
+			dbg_puts("\n");
+		}
+#endif
 		AMSG_INIT(&f->wmsg);
 		f->wmsg.cmd = AMSG_SETVOL;
 		f->wmsg.u.vol.ctl = f->vol;
@@ -941,6 +1392,12 @@ sock_buildmsg(struct sock *f)
 		f->wstate = SOCK_WMSG;
 		return 1;
 	}
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		sock_dbg(f);
+		dbg_puts(": no messages to build anymore, idling...\n");
+	}
+#endif
 	f->wstate = SOCK_WIDLE;
 	return 0;
 }
@@ -953,6 +1410,16 @@ sock_buildmsg(struct sock *f)
 int
 sock_read(struct sock *f)
 {
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		sock_dbg(f);
+		dbg_puts(": reading, state = ");
+		dbg_putu(f->rstate);
+		dbg_puts(", todo = ");
+		dbg_putu(f->rtodo);
+		dbg_puts("\n");
+	}
+#endif
 	switch (f->rstate) {
 	case SOCK_RMSG:
 		if (!sock_rmsg(f))
@@ -974,6 +1441,12 @@ sock_read(struct sock *f)
 			(void)sock_attach(f, 0);
 		break;
 	case SOCK_RRET:
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			sock_dbg(f);
+			dbg_puts(": blocked by pending RRET message\n");
+		}
+#endif
 		return 0;
 	}
 	return 1;
@@ -990,6 +1463,12 @@ sock_return(struct sock *f)
 	while (f->rstate == SOCK_RRET) {
 		if (!sock_wmsg(f, &f->rmsg, &f->rtodo))
 			return 0;
+#ifdef DEBUG
+		if (debug_level >= 4) {
+			sock_dbg(f);
+			dbg_puts(": sent RRET message\n");
+		}
+#endif
 		if (f->pstate == SOCK_MIDI && (f->mode & AMSG_MIDIOUT)) {
 			f->rstate = SOCK_RDATA;
 			f->rtodo = 0;
@@ -1024,6 +1503,16 @@ sock_return(struct sock *f)
 int
 sock_write(struct sock *f)
 {
+#ifdef DEBUG
+	if (debug_level >= 4) {
+		sock_dbg(f);
+		dbg_puts(": writing, state = ");
+		dbg_putu(f->wstate);
+		dbg_puts(", todo = ");
+		dbg_putu(f->wtodo);
+		dbg_puts("\n");
+	}
+#endif
 	switch (f->wstate) {
 	case SOCK_WMSG:
 		if (!sock_wmsg(f, &f->wmsg, &f->wtodo))
@@ -1050,6 +1539,12 @@ sock_write(struct sock *f)
 		if (!sock_buildmsg(f))
 			return 0;
 		break;
+#ifdef DEBUG
+	default:
+		sock_dbg(f);
+		dbg_puts(": bad writing end state\n");
+		dbg_panic();
+#endif
 	}
 	return 1;
 }
diff --git a/usr.bin/aucat/wav.c b/usr.bin/aucat/wav.c
index 48563ed0ba1..aa6c7670341 100644
--- a/usr.bin/aucat/wav.c
+++ b/usr.bin/aucat/wav.c
@@ -24,6 +24,9 @@
 #include "conf.h"
 #include "dev.h"
 #include "wav.h"
+#ifdef DEBUG
+#include "dbg.h"
+#endif
 
 short wav_ulawmap[256] = {
 	-32124, -31100, -30076, -29052, -28028, -27004, -25980, -24956,
@@ -447,6 +450,12 @@ wav_read(struct file *file, unsigned char *data, unsigned count)
 	if (f->rbytes >= 0 && count > f->rbytes) {
 		count = f->rbytes; /* file->rbytes fits in count */
 		if (count == 0) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				file_dbg(&f->pipe.file);
+				dbg_puts(": read complete\n");
+			}
+#endif
 			file_eof(&f->pipe.file);
 			return 0;
 		}
@@ -472,6 +481,12 @@ wav_write(struct file *file, unsigned char *data, unsigned count)
 	if (f->wbytes >= 0 && count > f->wbytes) {
 		count = f->wbytes; /* wbytes fits in count */
 		if (count == 0) {
+#ifdef DEBUG
+			if (debug_level >= 3) {
+				file_dbg(&f->pipe.file);
+				dbg_puts(": write complete\n");
+			}
+#endif
 			file_hup(&f->pipe.file);
 			return 0;
 		}