Index: chan_iax2.c
===================================================================
RCS file: /usr/cvsroot/asterisk/channels/chan_iax2.c,v
retrieving revision 1.364
diff -u -r1.364 chan_iax2.c
--- chan_iax2.c	27 Oct 2005 02:19:37 -0000	1.364
+++ chan_iax2.c	28 Oct 2005 12:29:07 -0000
@@ -2607,7 +2607,13 @@
 		if ((nowtime - regseconds) > IAX_DEFAULT_REG_EXPIRE) {
 			memset(&peer->addr, 0, sizeof(peer->addr));
 			if (option_debug)
-				ast_log(LOG_DEBUG, "Bah, we're expired (%ld/%ld/%ld)!\n", nowtime - regseconds, regseconds, nowtime);
+				ast_log(LOG_DEBUG, "realtime_peer: Bah, '%s' is expired (%ld/%ld/%ld)!\n",
+						peername, nowtime - regseconds, regseconds, nowtime);
+		}
+		else {
+			if (option_debug)
+				ast_log(LOG_DEBUG, "realtime_peer: Registration for '%s' still active (%ld/%ld/%ld)!\n",
+						peername, nowtime - regseconds, regseconds, nowtime);
 		}
 	}
 
@@ -4971,6 +4980,7 @@
 	return res;
 }
 
+/*! \brief Verify inbound registration */
 static int register_verify(int callno, struct sockaddr_in *sin, struct iax_ies *ies)
 {
 	char requeststr[256] = "";
@@ -5005,6 +5015,7 @@
 	/* We release the lock for the call to prevent a deadlock, but it's okay because
 	   only the current thread could possibly make it go away or make changes */
 	ast_mutex_unlock(&iaxsl[callno]);
+	/* SLD: first call to lookup peer during registration */
 	p = find_peer(peer, 1);
 	ast_mutex_lock(&iaxsl[callno]);
 
@@ -5386,6 +5397,7 @@
 	return 0; 
 }
 
+/*! \brief Acknowledgment received for OUR registration */
 static int iax2_ack_registry(struct iax_ies *ies, struct sockaddr_in *sin, int callno)
 {
 	struct iax2_registry *reg;
@@ -5523,6 +5535,7 @@
 static int expire_registry(void *data)
 {
 	struct iax2_peer *p = data;
+	ast_log(LOG_WARNING, "Expiring registration for peer '%s'\n", p->name);
 	/* Reset the address */
 	memset(&p->addr, 0, sizeof(p->addr));
 	/* Reset expire notice */
@@ -5598,6 +5611,7 @@
 
 	memset(&ied, 0, sizeof(ied));
 
+	/* SLD: Another find_peer call during registration - this time when we are really updating our registration */
 	if (!(p = find_peer(name, 1))) {
 		ast_log(LOG_WARNING, "No such peer '%s'\n", name);
 		return -1;
@@ -5687,6 +5703,7 @@
 {
 	struct iax_ie_data ied;
 	struct iax2_peer *p;
+	/* SLD: third call to find_peer in registration */
 	p = find_peer(name, 1);
 	if (p) {
 		memset(&ied, 0, sizeof(ied));
@@ -7323,7 +7340,7 @@
 					ast_log(LOG_DEBUG, "Destroying call %d\n", fr.callno);
 				break;
 			case IAX_COMMAND_VNAK:
-				ast_log(LOG_DEBUG, "Sending VNAK\n");
+				ast_log(LOG_DEBUG, "Received VNAK: resending outstanding frames\n");
 				/* Force retransmission */
 				vnak_retransmit(fr.callno, fr.iseqno);
 				break;
@@ -7598,7 +7615,7 @@
 	/* Schedule the next registration attempt */
 	if (reg->expire > -1)
 		ast_sched_del(sched, reg->expire);
-	/* Setup the registration a little early */
+	/* Setup the next registration a little early */
 	reg->expire  = ast_sched_add(sched, (5 * reg->refresh / 6) * 1000, iax2_do_register_s, reg);
 	/* Send the request */
 	memset(&ied, 0, sizeof(ied));
@@ -7878,7 +7895,7 @@
 {
 	/* Our job is simple: Send queued messages, retrying if necessary.  Read frames 
 	   from the network, and queue them for delivery to the channels */
-	int res;
+	int res, count;
 	struct iax_frame *f, *freeme;
 	if (timingfd > -1)
 		ast_io_add(io, timingfd, timing_read, AST_IO_IN | AST_IO_PRI, NULL);
@@ -7887,6 +7904,7 @@
 		   sent, and scheduling retransmissions if appropriate */
 		ast_mutex_lock(&iaxq.lock);
 		f = iaxq.head;
+		count = 0;
 		while(f) {
 			freeme = NULL;
 			if (!f->sentyet) {
@@ -7894,6 +7912,7 @@
 				/* Send a copy immediately -- errors here are ok, so don't bother locking */
 				if (iaxs[f->callno]) {
 					send_packet(f);
+					count++;
 				} 
 				if (f->retries < 0) {
 					/* This is not supposed to be retransmitted */
@@ -7919,12 +7938,20 @@
 				iax_frame_free(freeme);
 		}
 		ast_mutex_unlock(&iaxq.lock);
+		if (count >= 20)
+			ast_log(LOG_WARNING, "chan_iax2: Sent %d queued outbound frames all at once\n", count);
+
+		/* Now do the IO, and run scheduled tasks */
 		res = ast_sched_wait(sched);
 		if ((res > 1000) || (res < 0))
 			res = 1000;
 		res = ast_io_wait(io, res);
 		if (res >= 0) {
-			ast_sched_runq(sched);
+			if (res >= 20)
+				ast_log(LOG_WARNING, "chan_iax2: ast_io_wait ran %d I/Os all at once\n", res);
+			count = ast_sched_runq(sched);
+			if (count >= 20)
+				ast_log(LOG_WARNING, "chan_iax2: ast_sched_runq ran %d scheduled tasks all at once\n", count);
 		}
 	}
 	return NULL;
@@ -9244,12 +9277,14 @@
 	if (option_debug > 2)
 		ast_log(LOG_DEBUG, "Checking device state for device %s\n", dest);
 
+	/* SLD: FIXME: second call to find_peer during registration */
 	p = find_peer(host, 1);
 	if (p) {
 		found++;
 		res = AST_DEVICE_UNAVAILABLE;
 		if (option_debug > 2) 
-			ast_log(LOG_DEBUG, "Found peer. Now checking device state for peer %s\n", host);
+			ast_log(LOG_DEBUG, "iax2_devicestate(%s): Found peer. What's device state of %s? addr=%d, defaddr=%d maxms=%d, lastms=%d\n",
+				host, dest, p->addr.sin_addr.s_addr, p->defaddr.sin_addr.s_addr, p->maxms, p->lastms);
 
 		if ((p->addr.sin_addr.s_addr || p->defaddr.sin_addr.s_addr) &&
 		    (!p->maxms || ((p->lastms > -1) && (p->historicms <= p->maxms)))) {