Index: main/channel.c
===================================================================
--- main/channel.c	(revision 291903)
+++ main/channel.c	(working copy)
@@ -2475,6 +2475,8 @@
 	int res;
 	unsigned int real_rate = rate, max_rate;
 
+	ast_log(LOG_NOTICE, "in ast_settimeout; new timing func will be %p\n", func);
+
 	ast_channel_lock(c);
 
 	if (c->timingfd == -1) {
@@ -2781,17 +2783,25 @@
 		}
 	}
 
+	if (chan->stream) {
+		ast_log(LOG_NOTICE, "streaming; chan->timingfd = %d, chan->fdno = %d\n", chan->timingfd, chan->fdno);
+	}
 	if (chan->timingfd > -1 && chan->fdno == AST_TIMING_FD) {
 		enum ast_timer_event res;
 
 		ast_clear_flag(chan, AST_FLAG_EXCEPTION);
 
+		ast_log(LOG_NOTICE, "calling ast_timer_get_event(%p)\n", chan->timer);
+
 		res = ast_timer_get_event(chan->timer);
 
+		ast_log(LOG_NOTICE, "ast_timer_get_event() returned %d\n", res);
+
 		switch (res) {
 		case AST_TIMING_EVENT_EXPIRED:
 			ast_timer_ack(chan->timer, 1);
 
+			ast_log(LOG_NOTICE, "chan->timingfunc = %p, but we knew that already...\n", chan->timingfunc);
 			if (chan->timingfunc) {
 				/* save a copy of func/data before unlocking the channel */
 				int (*func)(const void *) = chan->timingfunc;
Index: main/features.c
===================================================================
--- main/features.c	(revision 291903)
+++ main/features.c	(working copy)
@@ -1481,9 +1481,12 @@
 		}
 	}
 
+	ast_log(LOG_NOTICE, "doing a feature_request_and_dial for %s and %s\n", transferer->name, transferee->name);
 	newchan = feature_request_and_dial(transferer, transferee, "Local", ast_best_codec(transferer->nativeformats),
 		xferto, atxfernoanswertimeout, &outstate, transferer->cid.cid_num, transferer->cid.cid_name, 1, transferer->language);
 
+	ast_log(LOG_NOTICE, "done with feature_request_and_dial, got %s\n", newchan ? newchan->name : "nothing");
+
 	if (!ast_check_hangup(transferer)) {
 		int hangup_dont = 0;
 
@@ -1515,6 +1518,7 @@
 		if (ast_test_flag(chan, AST_FLAG_BRIDGE_HANGUP_DONT)) {
 			hangup_dont = 1;
 		}
+		ast_log(LOG_NOTICE, "going to bridge %s and %s for attended transfer\n", transferer->name, newchan->name);
 		res = ast_bridge_call(transferer, newchan, &bconfig);
 		if (hangup_dont) {
 			ast_set_flag(chan, AST_FLAG_BRIDGE_HANGUP_DONT);
@@ -1598,8 +1602,10 @@
 			tobj->bconfig.end_bridge_callback_data_fixup(&tobj->bconfig, tobj->peer, tobj->chan);
 		}
 
+		ast_log(LOG_NOTICE, "Going to play transfer sound.\n");
 		if (ast_stream_and_wait(newchan, xfersound, ""))
 			ast_log(LOG_WARNING, "Failed to play transfer sound!\n");
+		ast_log(LOG_NOTICE, "finishing up attended transfer by bridging %s and %s\n", xferchan->name, newchan->name);
 		bridge_call_thread_launch(tobj);
 		return -1;      /* XXX meaning the channel is bridged ? */
 	} else if (!ast_check_hangup(transferee)) {
@@ -2284,6 +2290,7 @@
 			}
 			f = ast_read(chan);
 			if (f == NULL) { /*doh! where'd he go?*/
+				ast_log(LOG_NOTICE, "error reading from %s", chan->name);
 				state = AST_CONTROL_HANGUP;
 				res = 0;
 				break;
@@ -2303,6 +2310,7 @@
 					break;
 				} else if (f->subclass == AST_CONTROL_ANSWER) {
 					/* This is what we are hoping for */
+					ast_log(LOG_NOTICE, "got answer on %s\n", chan->name);
 					state = f->subclass;
 					ast_frfree(f);
 					f = NULL;
@@ -2319,6 +2327,7 @@
 		} else if (caller && (active_channel == caller)) {
 			f = ast_read(caller);
 			if (f == NULL) { /*doh! where'd he go?*/
+				ast_log(LOG_NOTICE, "error reading from caller %s\n", chan->name);
 				if (!igncallerstate) {
 					if (ast_check_hangup(caller) && !ast_check_hangup(chan)) {
 						/* make this a blind transfer */
Index: main/file.c
===================================================================
--- main/file.c	(revision 291903)
+++ main/file.c	(working copy)
@@ -700,14 +700,17 @@
 	struct ast_frame *fr, *new_fr;
 
 	if (!s || !s->fmt) {
+		ast_log(LOG_NOTICE, "the stream is gone?!\n");
 		return NULL;
 	}
 
 	if (!(fr = s->fmt->read(s, whennext))) {
+		ast_log(LOG_NOTICE, "fmt->read is trying to tell us something\n");
 		return NULL;
 	}
 
 	if (!(new_fr = ast_frisolate(fr))) {
+		ast_log(LOG_NOTICE, "ast_frisolate failed?!\n");
 		ast_frfree(fr);
 		return NULL;
 	}
@@ -743,10 +746,12 @@
 		struct ast_frame *fr;
 
 		if (s->orig_chan_name && strcasecmp(s->owner->name, s->orig_chan_name)) {
+			ast_log(LOG_NOTICE, "masquerade?");
 			goto return_failure;
 		}
 
 		fr = read_frame(s, &whennext);
+		ast_log(LOG_NOTICE, "read_frame returned %p, whennext = %d\n", fr, whennext);
 
 		if (!fr /* stream complete */ || ast_write(s->owner, fr) /* error writing */) {
 			if (fr) {
@@ -761,24 +766,30 @@
 		}
 	}
 
+	ast_log(LOG_NOTICE, "whennext = %d, s->lasttimeout = %d\n", whennext, s->lasttimeout);
 	if (whennext != s->lasttimeout) {
 		if (s->owner->timingfd > -1) {
 			float samp_rate = (float) ast_format_rate(s->fmt->format);
 			unsigned int rate;
 
+			ast_log(LOG_NOTICE, "going to do ast_settimeout\n");
+
 			rate = (unsigned int) roundf(samp_rate / ((float) whennext));
 
 			ast_settimeout(s->owner, rate, ast_fsread_audio, s);
 		} else {
+			ast_log(LOG_NOTICE, "going to do ast_sched_add\n");
 			s->owner->streamid = ast_sched_add(s->owner->sched, 
 				whennext / (ast_format_rate(s->fmt->format) / 1000), ast_fsread_audio, s);
 		}
 		s->lasttimeout = whennext;
 		return FSREAD_SUCCESS_NOSCHED;
 	}
+	ast_log(LOG_NOTICE, "going to return now\n");
 	return FSREAD_SUCCESS_SCHED;
 
 return_failure:
+	ast_log(LOG_NOTICE, "I think we are finished streaming\n");
 	s->owner->streamid = -1;
 	ast_settimeout(s->owner, 0, NULL, NULL);
 	return FSREAD_FAILURE;
@@ -789,6 +800,8 @@
 	struct ast_filestream *fs = (struct ast_filestream *)data;
 	enum fsread_res res;
 
+	ast_log(LOG_NOTICE, "in ast_fsread_audio\n");
+
 	res = ast_readaudio_callback(fs);
 
 	if (res == FSREAD_SUCCESS_SCHED)
@@ -1203,9 +1216,13 @@
 		ms = ast_sched_wait(c->sched);
 
 		if (ms < 0 && !c->timingfunc) {
+			ast_log(LOG_NOTICE, "done streaming file\n");
 			ast_stopstream(c);
 			break;
+		} else {
+			ast_log(LOG_NOTICE, "still streaming, ms = %d, c->timingfunc = %p\n", ms, c->timingfunc);
 		}
+
 		if (ms < 0)
 			ms = 1000;
 		if (cmdfd < 0) {
Index: res/res_timing_pthread.c
===================================================================
--- res/res_timing_pthread.c	(revision 291903)
+++ res/res_timing_pthread.c	(working copy)
@@ -250,6 +250,8 @@
 	struct pthread_timer *timer;
 	enum ast_timer_event res = AST_TIMING_EVENT_EXPIRED;
 
+	ast_log(LOG_NOTICE, "in pthread_timer_get_event\n");
+
 	if (!(timer = find_timer(handle, 0))) {
 		return res;
 	}
Index: res/res_timing_dahdi.c
===================================================================
--- res/res_timing_dahdi.c	(revision 291903)
+++ res/res_timing_dahdi.c	(working copy)
@@ -117,6 +117,8 @@
 	int res;
 	int event;
 
+	ast_log(LOG_NOTICE, "in dahdi_timer_get_event\n");
+
 	res = ioctl(handle, DAHDI_GETEVENT, &event);
 
 	if (res) {
Index: res/res_timing_timerfd.c
===================================================================
--- res/res_timing_timerfd.c	(revision 291903)
+++ res/res_timing_timerfd.c	(working copy)
@@ -240,6 +240,8 @@
 		.handle = handle,
 	};
 
+	ast_log(LOG_NOTICE, "in timerfd_timer_get_event\n");
+
 	if (!(our_timer = ao2_find(timerfd_timers, &find_helper, OBJ_POINTER))) {
 		ast_log(LOG_ERROR, "Couldn't find timer with handle %d\n", handle);
 		return -1;
Index: formats/format_gsm.c
===================================================================
--- formats/format_gsm.c	(revision 291903)
+++ formats/format_gsm.c	(working copy)
@@ -57,10 +57,12 @@
 	AST_FRAME_SET_BUFFER(&(s->fr), s->buf, AST_FRIENDLY_OFFSET, GSM_FRAME_SIZE)
 	s->fr.mallocd = 0;
 	if ((res = fread(s->fr.data.ptr, 1, GSM_FRAME_SIZE, s->f)) != GSM_FRAME_SIZE) {
+		ast_log(LOG_NOTICE, "failed fread returned %d\n", res);
 		if (res)
 			ast_log(LOG_WARNING, "Short read (%d) (%s)!\n", res, strerror(errno));
 		return NULL;
 	}
+	ast_log(LOG_NOTICE, "successful fread returned %d\n", res);
 	*whennext = s->fr.samples = GSM_SAMPLES;
 	return &s->fr;
 }
