add some additional log output and comment cleanup in the registration process (issue...
authorKevin P. Fleming <kpfleming@digium.com>
Mon, 31 Oct 2005 22:01:13 +0000 (22:01 +0000)
committerKevin P. Fleming <kpfleming@digium.com>
Mon, 31 Oct 2005 22:01:13 +0000 (22:01 +0000)
git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@6906 65c4cc65-6c06-0410-ace0-fbb531ad65f3

channels/chan_iax2.c

index 422ccf9..2ff97ca 100755 (executable)
@@ -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)))) {