Index: main/audiohook.c
===================================================================
--- main/audiohook.c	(revision 363307)
+++ main/audiohook.c	(working copy)
@@ -130,6 +130,8 @@
 	int muteme = 0;
 
 	/* Update last feeding time to be current */
+	ast_debug(5, "[%p] %s %p is getting fed (nom nom nom)\n", audiohook, direction == AST_AUDIOHOOK_DIRECTION_READ ? "Read factory" : "Write factory",
+		direction == AST_AUDIOHOOK_DIRECTION_READ ? &audiohook->read_factory : &audiohook->write_factory);
 	*rwtime = ast_tvnow();
 
 	our_factory_samples = ast_slinfactory_available(factory);
@@ -208,7 +210,10 @@
 
 static struct ast_frame *audiohook_read_frame_both(struct ast_audiohook *audiohook, size_t samples)
 {
-	int i = 0, usable_read, usable_write;
+	int i = 0, usable_read, usable_write, read_comparison, write_comparison;
+	int64_t write_diff, read_diff;
+	struct timeval time_now;
+	unsigned int read_size, write_size;
 	short buf1[samples], buf2[samples], *read_buf = NULL, *write_buf = NULL, *final_buf = NULL, *data1 = NULL, *data2 = NULL;
 	struct ast_frame frame = {
 		.frametype = AST_FRAME_VOICE,
@@ -219,24 +224,40 @@
 	};
 
 	/* Make sure both factories have the required samples */
-	usable_read = (ast_slinfactory_available(&audiohook->read_factory) >= samples ? 1 : 0);
-	usable_write = (ast_slinfactory_available(&audiohook->write_factory) >= samples ? 1 : 0);
+	write_size = ast_slinfactory_available(&audiohook->write_factory);
+	read_size = ast_slinfactory_available(&audiohook->read_factory);
+	usable_read = (read_size >= samples ? 1 : 0);
+	usable_write = (write_size >= samples ? 1 : 0);
 
+	ast_debug(5, "[%p] Got %u and %u samples from the read/write factories %p/%p\n",
+		audiohook, read_size, write_size, &audiohook->read_factory, &audiohook->write_factory);
 	if (!usable_read && !usable_write) {
 		/* If both factories are unusable bail out */
-		ast_debug(1, "Read factory %p and write factory %p both fail to provide %zd samples\n", &audiohook->read_factory, &audiohook->write_factory, samples);
+		ast_debug(1, "[%p] Read factory %p and write factory %p both fail to provide %zd samples\n", audiohook, &audiohook->read_factory, &audiohook->write_factory, samples);
 		return NULL;
 	}
 
 	/* If we want to provide only a read factory make sure we aren't waiting for other audio */
-	if (usable_read && !usable_write && (ast_tvdiff_ms(ast_tvnow(), audiohook->write_time) < (samples/8)*2)) {
-		ast_debug(3, "Write factory %p was pretty quick last time, waiting for them.\n", &audiohook->write_factory);
+	time_now = ast_tvnow();
+	audiohook->read_time.tv_sec = 0;
+	audiohook->read_time.tv_usec = 0;
+	read_diff = ast_tvdiff_ms(time_now, audiohook->read_time);
+	write_diff = ast_tvdiff_ms(time_now, audiohook->write_time);
+	write_comparison = write_diff < (samples/8)*2;
+	read_comparison = read_diff < (samples/8)*2;
+	ast_debug(5, "[%p] Samples: %zu; Sample threshold: %zu; Current time: %ld.%ld; write time: %ld.%ld; write diff: %ld; write compare: %d; read time: %ld.%ld; read_diff: %ld; read compare: %d\n",
+		audiohook, samples, (samples/8)*2, time_now.tv_sec, time_now.tv_usec, audiohook->write_time.tv_sec, audiohook->write_time.tv_usec,
+		write_diff, write_comparison, audiohook->read_time.tv_sec, audiohook->read_time.tv_usec, read_diff, read_comparison);
+	if (usable_read && !usable_write && (ast_tvdiff_ms(ast_tvnow(), audiohook->write_time) < (samples/8)*2)
+		&& !(audiohook->write_time.tv_sec == 0)) {
+		ast_debug(3, "[%p] Write factory %p was pretty quick last time, waiting for them.\n", audiohook, &audiohook->write_factory);
 		return NULL;
 	}
 
 	/* If we want to provide only a write factory make sure we aren't waiting for other audio */
-	if (usable_write && !usable_read && (ast_tvdiff_ms(ast_tvnow(), audiohook->read_time) < (samples/8)*2)) {
-		ast_debug(3, "Read factory %p was pretty quick last time, waiting for them.\n", &audiohook->read_factory);
+	if (usable_write && !usable_read && (ast_tvdiff_ms(ast_tvnow(), audiohook->read_time) < (samples/8)*2)
+		&& !(audiohook->read_time.tv_sec == 0)) {
+		ast_debug(3, "[%p] Read factory %p was pretty quick last time, waiting for them.\n", audiohook, &audiohook->read_factory);
 		return NULL;
 	}
 
@@ -256,8 +277,9 @@
 				}
 			}
 		}
-	} else if (option_debug)
-		ast_log(LOG_DEBUG, "Failed to get %d samples from read factory %p\n", (int)samples, &audiohook->read_factory);
+	} else {
+		ast_debug(1, "[%p] Failed to get %d samples from read factory %p\n", audiohook, (int)samples, &audiohook->read_factory);
+	}
 
 	/* Move on to the write factory... if there are enough samples, read them in */
 	if (usable_write) {
@@ -275,8 +297,9 @@
 				}
 			}
 		}
-	} else if (option_debug)
-		ast_log(LOG_DEBUG, "Failed to get %d samples from write factory %p\n", (int)samples, &audiohook->write_factory);
+	} else {
+		ast_debug(1, "[%p] Failed to get %d samples from write factory %p\n", audiohook, (int)samples, &audiohook->write_factory);
+	}
 
 	/* Basically we figure out which buffer to use... and if mixing can be done here */
 	if (!read_buf && !write_buf)
@@ -308,8 +331,10 @@
 {
 	struct ast_frame *read_frame = NULL, *final_frame = NULL;
 
-	if (!(read_frame = (direction == AST_AUDIOHOOK_DIRECTION_BOTH ? audiohook_read_frame_both(audiohook, samples) : audiohook_read_frame_single(audiohook, samples, direction))))
+	if (!(read_frame = (direction == AST_AUDIOHOOK_DIRECTION_BOTH ? audiohook_read_frame_both(audiohook, samples) : audiohook_read_frame_single(audiohook, samples, direction)))) {
+		ast_debug(5, "[%p] Failed to read frame for audiohook (%zd: %d)\n", audiohook, samples, ast_format_rate(format));
 		return NULL;
+	}
 
 	/* If they don't want signed linear back out, we'll have to send it through the translation path */
 	if (format != AST_FORMAT_SLINEAR) {
