add some additional log output and comment cleanup in the registration process (issue #5534)

git-svn-id: http://svn.digium.com/svn/asterisk/trunk@6906 f38db490-d61c-443f-a65b-d21fe96a405b

1 files changed, 31 insertions, 6 deletions

diff --git a/channels/chan_iax2.c b/channels/chan_iax2.c
index 422ccf9d5..2ff97ca2b 100755
--- a/channels/chan_iax2.c
+++ b/channels/chan_iax2.c
@@ -2607,7 +2607,13 @@ static struct iax2_peer *realtime_peer(const char *peername, struct sockaddr_in
 		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);
 		}
 	}
 
@@ -4968,6 +4974,7 @@ static int authenticate_verify(struct chan_iax2_pvt *p, struct iax_ies *ies)
 	return res;
 }
 
+/*! \brief Verify inbound registration */
 static int register_verify(int callno, struct sockaddr_in *sin, struct iax_ies *ies)
 {
 	char requeststr[256] = "";
@@ -5002,6 +5009,7 @@ static int register_verify(int callno, struct sockaddr_in *sin, struct iax_ies *
 	/* 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]);
 
@@ -5383,6 +5391,7 @@ static int complete_transfer(int callno, struct iax_ies *ies)
 	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;
@@ -5520,6 +5529,8 @@ static void prune_peers(void);
 static int expire_registry(void *data)
 {
 	struct iax2_peer *p = data;
+
+	ast_log(LOG_DEBUG, "Expiring registration for peer '%s'\n", p->name);
 	/* Reset the address */
 	memset(&p->addr, 0, sizeof(p->addr));
 	/* Reset expire notice */
@@ -5595,6 +5606,7 @@ static int update_registry(char *name, struct sockaddr_in *sin, int callno, char
 
 	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;
@@ -5685,6 +5697,7 @@ static int registry_authrequest(char *name, int callno)
 {
 	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));
@@ -7321,7 +7334,7 @@ retryowner2:
 					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;
@@ -7596,7 +7609,7 @@ static int iax2_do_register(struct iax2_registry *reg)
 	/* 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));
@@ -7876,7 +7889,7 @@ static void *network_thread(void *ignore)
 {
 	/* 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);
@@ -7885,6 +7898,7 @@ static void *network_thread(void *ignore)
 		   sent, and scheduling retransmissions if appropriate */
 		ast_mutex_lock(&iaxq.lock);
 		f = iaxq.head;
+		count = 0;
 		while(f) {
 			freeme = NULL;
 			if (!f->sentyet) {
@@ -7892,6 +7906,7 @@ static void *network_thread(void *ignore)
 				/* 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 */
@@ -7917,12 +7932,20 @@ static void *network_thread(void *ignore)
 				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;
@@ -9242,12 +9265,14 @@ static int iax2_devicestate(void *data)
 	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)))) {