Debugging underruns, needs cleanup

examples/loopback.py

@@ -1,5 +1,5 @@
 #!/usr/bin/env python3
-# -*- mode: python; indent-tabs-mode: t; c-basic-offset: 4; tab-width: 4 -*-
+# -*- mode: python; indent-tabs-mode: t; c-basic-offset: 4; tab-width: 4; python-indent: 4 -*-
 
 import sys
 import select
@@ -43,6 +43,10 @@ state_names = {
 	PCM_STATE_SUSPENDED: 'PCM_STATE_SUSPENDED'
 }
 
+type NamedProcess = tuple[str, subprocess.Popen]
+
+cmd_process : NamedProcess = None
+
 def poll_desc(mask):
 	return '|'.join([poll_names[bit] for bit, name in poll_names.items() if mask & bit])
 
@@ -108,20 +112,30 @@ class Loopback(object):
 	@staticmethod
 	def run_command(cmd):
 		if cmd:
-			rc = subprocess.run(cmd)
+			global cmd_process
+			cmd_process = (cmd, subprocess.Popen(cmd))
+
+	@staticmethod
+	def check_command_idle_handler():
+		# an idle handler to watch the process created above
+		if cmd_process:
+			rc = cmd_process[1].poll()
+			if rc:
 				if rc.returncode:
-				logging.warning(f'run {cmd}, return code {rc.returncode}')
+					logging.warning(f'run {cmd_process[0]}, return code {rc.returncode}')
 				else:
-				logging.info(f'run {cmd}, return code {rc.returncode}')
+					logging.info(f'run {cmd_process[0]}, return code {rc.returncode}')
+				cmd_process = None
 
 	def register(self, reactor):
+		reactor.register_idle_handler(self.check_command_idle_handler)
 		reactor.register_idle_handler(self.idle_handler)
 		reactor.register(self.capture_pd, self)
 
 	def start(self):
 		assert self.state == None, "start must only be called once"
 		# start reading data
-		size, data = self.capture.read()
+		size, _ = self.capture.read()
 		if size:
 			logging.warning(f'initial data discarded ({size} bytes)')
 
@@ -187,10 +201,10 @@ class Loopback(object):
 		if eventmask & select.POLLERR == select.POLLERR:
 			# This is typically an underrun caused by the external command being run synchronously
    			# (on the same thread)
-			logging.warning(f'POLLERR for capture device: {state_names[self.capture.state()]}')
+			state = self.capture.state()
+			if state == PCM_STATE_XRUN:
 				self.capture.drop()
-			self.capture.read()
-			return False
+				logging.warning(f'POLLERR for capture device: {state_names[state]}')
 
 		'''called when data is available for reading'''
 		self.last_capture_event = datetime.now()
@@ -208,12 +222,15 @@ class Loopback(object):
 
 			# turn off playback after idle_close_timeout when there was only silence
 			if datetime.now() - self.silence_start > timedelta(seconds=idle_close_timeout):
+				logging.debug('silence')
 				self.set_state(LoopbackState.LISTENING)
 				return False
 		else:
 			self.silence_start = None
 
-		if self.set_state(LoopbackState.PLAYING) != LoopbackState.PLAYING:
+		loop_state = self.set_state(LoopbackState.PLAYING)
+		if loop_state != LoopbackState.PLAYING:
+			logging.warning(f'setting state PLAYING failed: {str(loop_state)}')
 			return False
 
 		if data:
@@ -235,7 +252,7 @@ class Loopback(object):
 		if fd == self.capture_pd.fd:
 			real_mask = self.capture.polldescriptors_revents([self.capture_pd.as_tuple()])
 			if real_mask:
-				return self.handle_capture_event(eventmask, name)
+				return self.handle_capture_event(real_mask, name)
 			else:
 				logging.debug('null capture event')
 				return False

src/alsaaudio.c

@@ -106,6 +106,9 @@ typedef struct {
 
 	snd_pcm_t *handle;
 
+	// Debug logging
+	int state;
+
 	// Configurable parameters
 	unsigned int channels;
 	unsigned int rate;
@@ -360,6 +363,40 @@ alsapcm_list(PyObject *self, PyObject *args, PyObject *kwds)
 	return result;
 }
 
+const char* state_name(int state) {
+	switch (state) {
+		case SND_PCM_STATE_OPEN:
+			return "SND_PCM_STATE_OPEN";
+		case SND_PCM_STATE_SETUP:
+			return "SND_PCM_STATE_SETUP";
+		case SND_PCM_STATE_PREPARED:
+			return "SND_PCM_STATE_PREPARED";
+		case SND_PCM_STATE_RUNNING:
+			return "SND_PCM_STATE_RUNNING";
+		case SND_PCM_STATE_XRUN:
+			return "SND_PCM_STATE_XRUN";
+		case SND_PCM_STATE_DISCONNECTED:
+			return "SND_PCM_STATE_DISCONNECTED";
+		case SND_PCM_STATE_DRAINING:
+			return "SND_PCM_STATE_DRAINING";
+		case SND_PCM_STATE_PAUSED:
+			return "SND_PCM_STATE_PAUSED";
+		case SND_PCM_STATE_SUSPENDED:
+			return "SND_PCM_STATE_SUSPENDED";
+		default:
+			return "invalid PCM state";
+	}
+}
+
+void print_state(alsapcm_t *self)
+{
+	int state = snd_pcm_state(self->handle);
+	if (state != self->state) {
+		printf("[%s %s] %s->%s\n", self->cardname, self->pcmtype == SND_PCM_STREAM_CAPTURE ? "capture" : "playback", state_name(self->state), state_name(state));
+		self->state = state;
+	}
+}
+
 static int alsapcm_setup(alsapcm_t *self)
 {
 	int res,dir;
@@ -405,6 +442,8 @@ static int alsapcm_setup(alsapcm_t *self)
 
 	self->framesize = self->channels * snd_pcm_format_physical_width(self->format)/8;
 
+	self->state = snd_pcm_state(self->handle);
+
 	return res;
 }
 
@@ -1347,7 +1386,6 @@ static PyObject *
 alsapcm_read(alsapcm_t *self, PyObject *args)
 {
 	snd_pcm_state_t state;
-	int res;
 	int size = self->framesize * self->periodsize;
 	int sizeout = 0;
 	PyObject *buffer_obj, *tuple_obj, *res_obj;
@@ -1380,11 +1418,19 @@ alsapcm_read(alsapcm_t *self, PyObject *args)
 	buffer = PyBytes_AS_STRING(buffer_obj);
 #endif
 
+	int res = 0;
+
+	print_state(self);
+
 	// After drop() and drain(), we need to prepare the stream again.
 	// Note that fresh streams are already prepared by snd_pcm_hw_params().
 	state = snd_pcm_state(self->handle);
-	if ((state != SND_PCM_STATE_SETUP) ||
-		!(res = snd_pcm_prepare(self->handle))) {
+	if (state == SND_PCM_STATE_SETUP) {
+		res = snd_pcm_prepare(self->handle);
+		printf("[%s] called snd_pcm_prepare: %d\n", self->cardname, res);
+	}
+
+	if (res == 0) {
 
 		Py_BEGIN_ALLOW_THREADS
 		res = snd_pcm_readi(self->handle, buffer, self->periodsize);
@@ -1488,6 +1534,8 @@ static PyObject *alsapcm_write(alsapcm_t *self, PyObject *args)
 		return NULL;
 	}
 
+	print_state(self);
+
 	int res;
 	// After drop() and drain(), we need to prepare the stream again.
 	// Note that fresh streams are already prepared by snd_pcm_hw_params().
@@ -1577,6 +1625,9 @@ static PyObject *alsapcm_pause(alsapcm_t *self, PyObject *args)
 
 		return NULL;
 	}
+
+	print_state(self);
+
 	return PyLong_FromLong(res);
 }
 
@@ -1599,6 +1650,8 @@ static PyObject *alsapcm_drop(alsapcm_t *self)
 		return NULL;
 	}
 
+	print_state(self);
+
 	return PyLong_FromLong(res);
 }
 
@@ -1623,6 +1676,8 @@ static PyObject *alsapcm_drain(alsapcm_t *self)
 		return NULL;
 	}
 
+	print_state(self);
+
 	return PyLong_FromLong(res);
 }