[svn-commits] murf: branch murf/bug11210 r93535 - in /team/murf/bug11210: channels/ main/

SVN commits to the Digium repositories svn-commits at lists.digium.com
Mon Dec 17 23:50:16 CST 2007


Author: murf
Date: Mon Dec 17 23:50:15 2007
New Revision: 93535

URL: http://svn.digium.com/view/asterisk?view=rev&rev=93535
Log:
Good. the dialog callids change, hadn't known that. Now I do. Unlink and relink in the hash table under new name. Sip works better now.

Modified:
    team/murf/bug11210/channels/chan_sip.c
    team/murf/bug11210/main/sched.c

Modified: team/murf/bug11210/channels/chan_sip.c
URL: http://svn.digium.com/view/asterisk/team/murf/bug11210/channels/chan_sip.c?view=diff&rev=93535&r1=93534&r2=93535
==============================================================================
--- team/murf/bug11210/channels/chan_sip.c (original)
+++ team/murf/bug11210/channels/chan_sip.c Mon Dec 17 23:50:15 2007
@@ -1483,8 +1483,6 @@
 {
 	struct sip_peer *peer = obj, *peer2 = arg;
 
-	ast_log(LOG_NOTICE,"peer %s == peer %s ? %d\n", peer->name, peer2->name, !strcasecmp(peer->name, peer2->name) ? CMP_MATCH : 0);
-	
 	return !strcasecmp(peer->name, peer2->name) ? CMP_MATCH : 0;
 }
 
@@ -1542,7 +1540,6 @@
 {
 	struct sip_user *user = obj, *user2 = arg;
 
-	ast_log(LOG_NOTICE,"user %s == user %s ? %d\n", user->name, user2->name, !strcasecmp(user->name, user2->name) ? CMP_MATCH : 0);
 	return !strcasecmp(user->name, user2->name) ? CMP_MATCH : 0;
 }
 
@@ -1562,7 +1559,8 @@
 static int dialog_cmp_cb(void *obj, void *arg, int flags)
 {
 	struct sip_pvt *pvt = obj, *pvt2 = arg;
-	ast_log(LOG_NOTICE,"dialog %s == obj %s ? %d\n", pvt->callid, pvt2->callid, !strcasecmp(pvt->callid, pvt2->callid) ? CMP_MATCH : 0);
+	ast_log(LOG_NOTICE, "dialog_cmp_cb(%s,%s) ? %d\n", pvt->callid, pvt2->callid, !strcasecmp(pvt->callid, pvt2->callid) ? CMP_MATCH : 0);
+	
 	return !strcasecmp(pvt->callid, pvt2->callid) ? CMP_MATCH : 0;
 }
 
@@ -2109,12 +2107,14 @@
 		dialog->registry = registry_unref(dialog->registry, "delete dialog->registry");
 	}
 	if (dialog->initid > -1) {
+		ast_log(LOG_WARNING,"About to sched_del autocongest for dialog %s in dialog_unlink_all\n", dialog->callid);
 		if (ast_sched_del(sched, dialog->initid)==0)
 			dialog_unref(dialog,"when you delete the initid sched, you should dec the refcount for the stored dialog ptr");
 		dialog->initid = -1;
 	}
 	
 	if (dialog->autokillid > -1) {
+		ast_log(LOG_WARNING,"About to sched_del autokill for dialog %s in dialog_unlink_all\n", dialog->callid);
 		if (ast_sched_del(sched, dialog->autokillid)==0)
 			dialog_unref(dialog,"when you delete the autokillid sched, you should dec the refcount for the stored dialog ptr");
 		dialog->autokillid = -1;
@@ -2483,7 +2483,8 @@
 	struct sip_pkt *pkt = (struct sip_pkt *)data, *prev, *cur = NULL;
 	int reschedule = DEFAULT_RETRANS;
 	int xmitres = 0;
-
+	ast_log(LOG_NOTICE,"SCHED:  Retrans_pkt called---\n");
+	
 	/* Lock channel PVT */
 	sip_pvt_lock(pkt->owner);
 
@@ -2637,6 +2638,7 @@
 
 	if (xmitres == XMIT_ERROR) {	/* Serious network trouble, no need to try again */
 		append_history(pkt->owner, "XmitErr", "%s", pkt->is_fatal ? "(Critical)" : "(Non-critical)");
+		ast_log(LOG_WARNING,"About to sched_del pkt->retransid (%d) in __sip_reliable_xmit\n", pkt->retransid);
 		ast_sched_del(sched, pkt->retransid);	/* No more retransmission */
 		pkt->retransid = -1;
 		return AST_FAILURE;
@@ -2653,6 +2655,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *)data;
 
+	ast_log(LOG_NOTICE,"SCHED:  __sip_autodestruct called--- kill dialog\n");
 	/* If this is a subscription, tell the phone that we got a timeout */
 	if (p->subscribed) {
 		transmit_state_notify(p, AST_EXTENSION_DEACTIVATED, 1, TRUE);	/* Send last notification */
@@ -2674,7 +2677,7 @@
 			p->relatedpeer = unref_peer(p->relatedpeer,"__sip_autodestruct: unref peer p->relatedpeer");	/* Remove link to peer. If it's realtime, make sure it's gone from memory) */
 
 	/* Reset schedule ID */
-	p->autokillid = -1;
+	p->autokillid = -1;  /* HUH? Won't this cause problems? the event is still scheduled? */
 
 	if (p->owner) {
 		ast_log(LOG_WARNING, "Autodestruct on dialog '%s' with owner in place (Method: %s)\n", p->callid, sip_methods[p->method].text);
@@ -2713,6 +2716,7 @@
 	sip_cancel_destroy(p);
 	if (p->do_history)
 		append_history(p, "SchedDestroy", "%d ms", ms);
+	ast_log(LOG_WARNING,"About to sched_add sip_autodestruct for dialog %s in sip_scheddestroy\n", p->callid);
 	p->autokillid = ast_sched_add(sched, ms, __sip_autodestruct, dialog_ref(p,"sip_scheddestroy: setting ref as passing into ast_sched_add"));
 }
 
@@ -2723,7 +2727,9 @@
 static void sip_cancel_destroy(struct sip_pvt *p)
 {
 	if (p->autokillid > -1) {
-		int res3 = ast_sched_del(sched, p->autokillid);
+		int res3;
+		ast_log(LOG_WARNING,"About to sched_del autokillid(%d) for dialog %s in sip_cancel_destroy\n", p->autokillid, p->callid);
+		res3 = ast_sched_del(sched, p->autokillid);
 		append_history(p, "CancelDestroy", "");
 		p->autokillid = -1;
 		if (res3 == 0)
@@ -2759,6 +2765,7 @@
 			if (cur->retransid > -1) {
 				if (sipdebug)
 					ast_debug(4, "** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #%d\n", cur->retransid);
+				ast_log(LOG_WARNING,"About to sched_del retransid=%d in __sip_ack\n", cur->retransid);
 				ast_sched_del(sched, cur->retransid);
 				cur->retransid = -1;
 			}
@@ -2804,6 +2811,7 @@
 			if (cur->retransid > -1) {
 				if (sipdebug)
 					ast_debug(4, "*** SIP TIMER: Cancelling retransmission #%d - %s (got response)\n", cur->retransid, sip_methods[sipmethod].text);
+				ast_log(LOG_WARNING,"About to sched_del retransid=%d in __sip_semi_ack\n", cur->retransid);
 				ast_sched_del(sched, cur->retransid);
 				cur->retransid = -1;
 			}
@@ -3216,9 +3224,11 @@
 		ast_variables_destroy(peer->chanvars);
 		peer->chanvars = NULL;
 	}
-	if (peer->expire > -1)
+	if (peer->expire > -1) {
+		ast_log(LOG_WARNING,"About to sched_del peer->expire = %d in __sip_destroy_peer\n", peer->expire);
 		ast_sched_del(sched, peer->expire);
-
+	}
+	
 	if (peer->pokeexpire > -1)
 		ast_sched_del(sched, peer->pokeexpire);
 	register_peer_exten(peer, FALSE);
@@ -3414,6 +3424,7 @@
 		/* Cache peer */
 		ast_copy_flags(&peer->flags[1],&global_flags[1], SIP_PAGE2_RTAUTOCLEAR|SIP_PAGE2_RTCACHEFRIENDS);
 		if (ast_test_flag(&global_flags[1], SIP_PAGE2_RTAUTOCLEAR)) {
+			ast_log(LOG_WARNING,"About to sched_replace peer->expire = %d in realtime_peer\n", peer->expire);
 			peer->expire = ast_sched_replace(peer->expire, sched, 
 				global_rtautoclear * 1000, expire_register, (void *) peer);
 		}
@@ -3686,11 +3697,14 @@
 		if (!dialog->initreq.headers) {
 			char *c;
 			char *tmpcall = ast_strdupa(dialog->callid);
-
+			/* this sure looks to me like we are going to change the callid on this dialog!! */
 			c = strchr(tmpcall, '@');
 			if (c) {
 				*c = '\0';
+				ao2_unlink(dialogs,dialog,"About to change the callid -- remove the old name");
 				ast_string_field_build(dialog, callid, "%s@%s", tmpcall, peer->fromdomain);
+				ao2_link(dialogs,dialog,"New dialog callid -- inserted back into table");
+				ast_log(LOG_NOTICE,"============================================================Changed Dialog name to %s\n", dialog->callid);
 			}
 		}
 	}
@@ -3798,6 +3812,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *)arg;
 
+	ast_log(LOG_NOTICE,"SCHED:  auto_congest called for dialog %s---\n", p->callid);
 	sip_pvt_lock(p);
 	p->initid = -1;	/* event gone, will not be rescheduled */
 	if (p->owner) {
@@ -3897,6 +3912,7 @@
 		p->invitestate = INV_CALLING;
 	
 		/* Initialize auto-congest time */
+		ast_log(LOG_WARNING,"About to sched_replace autocongest for dialog %s in sip_call\n", p->callid);
 		p->initid = ast_sched_replace(p->initid, sched, p->timer_b, 
 									  auto_congest, dialog_ref(p,"this is a pointer for the autocongest callback to use"));
 	}
@@ -3922,10 +3938,16 @@
 		reg->call = dialog_unref(reg->call,"unref reg->call");
 		/* reg->call = sip_destroy(reg->call); */
 	}
-	if (reg->expire > -1)
+	if (reg->expire > -1) {
+		ast_log(LOG_WARNING,"About to sched_del reg->expire in sip_registry_destroy\n");
 		ast_sched_del(sched, reg->expire);
-	if (reg->timeout > -1)
+	}
+	
+	if (reg->timeout > -1) {
+		ast_log(LOG_WARNING,"About to sched_del reg->timeout in sip_registry_destroy\n");
 		ast_sched_del(sched, reg->timeout);
+	}
+	
 	ast_string_field_free_memory(reg);
 	regobjs--;
 	ast_free(reg);
@@ -3966,15 +3988,21 @@
 	if (p->stateid > -1)
 		ast_extension_state_del(p->stateid, NULL);
 	if (p->waitid > -1)
+	{
+		ast_log(LOG_WARNING,"About to sched_del waitid(%d) for dialog %s in __sip_destroy\n", p->waitid, p->callid);
 		ast_sched_del(sched, p->waitid);
+	}
+	
 
 	if (p->initid > -1) {
 		/* Don't auto congest anymore since we've gotten something useful back */
+		ast_log(LOG_WARNING,"About to sched_del p->initid for dialog %s in __sip_destroy\n", p->callid);
 		if (ast_sched_del(sched, p->initid) == 0)
 			dialog_unref(p,"when you delete the initid sched, you should dec the refcount for the stored dialog ptr");
 		p->initid = -1;
 	}
 	if (p->autokillid > -1) {
+		ast_log(LOG_WARNING,"About to sched_del autokillid(%d) for dialog %s in __sip_destroy\n", p->autokillid, p->callid);
 		if (ast_sched_del(sched, p->autokillid)==0)
 			dialog_unref(p,"when you delete the autokillid sched, you should dec the refcount for the stored dialog ptr");
 		p->autokillid = -1;
@@ -4009,8 +4037,11 @@
 	/* remove all current packets in this dialog */
 	while((cp = p->packets)) {
 		p->packets = p->packets->next;
-		if (cp->retransid > -1)
+		if (cp->retransid > -1) {
+			ast_log(LOG_WARNING,"About to sched_del retransid(%d) in __sip_destroy\n", cp->retransid);
 			ast_sched_del(sched, cp->retransid); /* HUH??? */
+		}
+		
 		cp->owner = dialog_unref(cp->owner,"free cp->owner dialog before freeing the pkt");
 		ast_free(cp);
 	}
@@ -4435,6 +4466,7 @@
 				if ( p->initid != -1 ) {
 					/* channel still up - reverse dec of inUse counter
 					   only if the channel is not auto-congested */
+					ast_log(LOG_WARNING,"About to update_call_counter autocongest for dialog %s in sip_hangup\n", p->callid);
 					update_call_counter(p, INC_CALL_LIMIT);
 				}
 			} else {	/* Incoming call, not up */
@@ -4479,8 +4511,11 @@
 				   but we can't send one while we have "INVITE" outstanding. */
 				ast_set_flag(&p->flags[0], SIP_PENDINGBYE);	
 				ast_clear_flag(&p->flags[0], SIP_NEEDREINVITE);	
-				if (p->waitid)
+				if (p->waitid) {
+					ast_log(LOG_WARNING,"About to sched_del waitid(%d) for dialog %s in sip_hangup\n", p->waitid, p->callid);
 					ast_sched_del(sched, p->waitid);
+				}
+				
 				p->waitid = -1;
 				sip_cancel_destroy(p);
 			}
@@ -5311,7 +5346,6 @@
 {
 	struct sip_pvt *p;
 	struct sip_pvt *p2;
-	int rc;
 
 	ast_log(LOG_NOTICE,"allocating PVT for %s\n", callid);
 	if (!(p = ao2_alloc(sizeof(*p), sip_destroy_fn, "allocate a dialog(pvt) struct")))
@@ -5445,9 +5479,9 @@
 	}
 	
 	ao2_link(dialogs, p, "link pvt into dialogs table");
-	rc = ao2_ref(p, 0,"");
+	ast_log(LOG_NOTICE,"***Just linked %s into dialogs table\n", p->callid);
 	
-	ast_debug(1, "Allocating new SIP dialog for %s - %s (%s)\n", callid ? callid : "(No Call-ID)", sip_methods[intended_method].text, p->rtp ? "With RTP" : "No RTP");
+	ast_debug(1, "Allocating new SIP dialog for %s - %s (%s)\n", callid ? callid : p->callid, sip_methods[intended_method].text, p->rtp ? "With RTP" : "No RTP");
 	return p;
 }
 
@@ -5512,10 +5546,12 @@
 			ast_log(LOG_NOTICE,"Found CALL dialog %s, refcount = %d\n", tmp_dialog.callid, rc);
 			if (!(!pedanticsipchecking || !tag || ast_strlen_zero(sip_pvt_ptr->theirtag) || !strcmp(sip_pvt_ptr->theirtag, tag)))
 			{
+				ast_log(LOG_NOTICE,"Pedantic Zero of dialog %s (1)\n", callid);
+				
 				ao2_ref(sip_pvt_ptr,-1,"pedantic failure, pointer erase"); /* basically, if the extra pedanticssipchecking constraints don't pan out,
 											the the match is defeated. There should be no other entry that matches
 											the callid */
-				sip_pvt_ptr = 0;
+				sip_pvt_ptr = NULL;
 			}
 			/* If we get a new request within an existing to-tag - check the to tag as well */
 			if (pedanticsipchecking && sip_pvt_ptr  && req->method != SIP_RESPONSE) {	/* SIP Request */
@@ -5523,10 +5559,12 @@
 					/* We have no to tag, but they have. Wrong dialog */
 					ao2_ref(sip_pvt_ptr,-1,"pedantic failure, pointer erased 2");
 					sip_pvt_ptr = NULL;
+					ast_log(LOG_NOTICE,"Pedantic Zero of dialog %s (2)\n", callid);
 				} else if (totag[0]) {			/* Both have tags, compare them */
 					if (strcmp(totag, sip_pvt_ptr->tag)) {
 						ao2_ref(sip_pvt_ptr,-1, "pedantic totag failure, pointer erased 3");
 						sip_pvt_ptr = NULL;		/* This is not our packet */
+						ast_log(LOG_NOTICE,"Pedantic Zero of dialog %s (3)\n", callid);
 					}
 				}
 				if (!sip_pvt_ptr)
@@ -5535,6 +5573,19 @@
 		}
 		
 		ast_string_field_free_memory(&tmp_dialog);
+		if (!sip_pvt_ptr) {
+			struct ao2_iterator i;
+			struct sip_pvt *d2;
+			
+			ast_log(LOG_NOTICE,"Dialog %s not found\n", callid);
+			i = ao2_iterator_init(dialogs, 0);
+	
+			while ((d2 = ao2_iterator_next(&i,"iterate thru dialogs "))) {
+				ast_log(LOG_NOTICE, "Dialogs:  %s\n", d2->callid);
+				ao2_ref(d2,-1,"done with d2 pointer");
+			}
+		}
+		
 		if (sip_pvt_ptr) {
 			/* Found the call */
 			sip_pvt_lock(sip_pvt_ptr);
@@ -5556,9 +5607,6 @@
 		} else {
 			/* Ok, time to create a new SIP dialog object, a pvt */
 			if ((p = sip_alloc(callid, sin, 1, intended_method)))  {
-				int rc = ao2_ref(p,0,"");
-				ast_log(LOG_NOTICE,"Couldn't find call %s, so CREATED dialog, refcount = %d\n",
-						callid, rc);
 				/* Ok, we've created a dialog, let's go and process it */
 				sip_pvt_lock(p);
 			} else {
@@ -8503,6 +8551,7 @@
 	/* if we are here, we know that we need to reregister. */
 	struct sip_registry *r= registry_addref((struct sip_registry *) data,"reg_addref from sip_reregister");
 
+	ast_log(LOG_NOTICE,"SCHED:  sip_reregister called---\n");
 	/* if we couldn't get a reference to the registry object, punt */
 	if (!r)
 		return 0;
@@ -8543,6 +8592,7 @@
 	struct sip_pvt *p;
 	int res;
 
+	ast_log(LOG_NOTICE,"SCHED:  sip_reg_timeout called---\n");
 	/* if we couldn't get a reference to the registry object, punt */
 	if (!r)
 		return 0;
@@ -8636,11 +8686,13 @@
 			dialog_unref(p, "unref dialog after unlink_all");
 			/* sip_destroy(p); */
 			if (r->timeout > -1) {
+				ast_log(LOG_WARNING,"About to sched_replace reg timeout(%d) for reg in transmit_register\n", r->timeout);
 				r->timeout = ast_sched_replace(r->timeout, sched, 
 					global_reg_timeout * 1000, sip_reg_timeout, r);
 				ast_log(LOG_WARNING, "Still have a registration timeout for %s@%s (create_addr() error), %d\n", r->username, r->hostname, r->timeout);
 			} else {
 				r->timeout = ast_sched_add(sched, global_reg_timeout*1000, sip_reg_timeout, r);
+				ast_log(LOG_WARNING,"Just did sched_add reg timeout(%d) for reg in transmit_register\n", r->timeout);
 				ast_log(LOG_WARNING, "Probably a DNS error for registration to %s@%s, trying REGISTER again (after %d seconds)\n", r->username, r->hostname, global_reg_timeout);
 			}
 			r->regattempts++;
@@ -8689,6 +8741,7 @@
 	if (auth == NULL)  {
 		if (r->timeout > -1)
 			ast_log(LOG_WARNING, "Still have a registration timeout, #%d - deleting it\n", r->timeout);
+		ast_log(LOG_WARNING,"About to sched_replace reg timeout(%d) for reg in transmit_register\n", r->timeout);
 		r->timeout = ast_sched_replace(r->timeout, sched, global_reg_timeout * 1000, sip_reg_timeout, r);
 		ast_debug(1, "Scheduled a registration timeout for %s id  #%d \n", r->hostname, r->timeout);
 	}
@@ -8995,6 +9048,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 	
+	ast_log(LOG_NOTICE,"SCHED:  expire_register called---\n");
 	if (!peer)		/* Hmmm. We have no peer. Weird. */
 		return 0;
 
@@ -9032,6 +9086,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 
+	ast_log(LOG_NOTICE,"SCHED:  sip_poke_peer_s called---\n");
 	peer->pokeexpire = -1;
 	sip_poke_peer(peer);
 	return 0;
@@ -9085,10 +9140,12 @@
 	peer->addr.sin_port = htons(port);
 	if (sipsock < 0) {
 		/* SIP isn't up yet, so schedule a poke only, pretty soon */
+		ast_log(LOG_WARNING,"About to sched_replace peer pokeexpire(%d) for peer in reg_source_db\n", peer->pokeexpire);
 		peer->pokeexpire = ast_sched_replace(peer->pokeexpire, sched, 
 			ast_random() % 5000 + 1, sip_poke_peer_s, peer);
 	} else
 		sip_poke_peer(peer);
+	ast_log(LOG_WARNING,"About to sched_replace peer expire(%d) for peer in reg_source_db\n", peer->expire);
 	peer->expire = ast_sched_replace(peer->expire, sched, 
 		(expiry + 10) * 1000, expire_register, peer);
 	register_peer_exten(peer, TRUE);
@@ -9203,8 +9260,11 @@
 	} else if (!strcasecmp(curi, "*") || !expiry) {	/* Unregister this peer */
 		/* This means remove all registrations and return OK */
 		memset(&peer->addr, 0, sizeof(peer->addr));
-		if (peer->expire > -1)
+		if (peer->expire > -1) {
+			ast_log(LOG_WARNING,"About to sched_del peer expire(%d) for peer in parse_register_result\n", peer->expire);
 			ast_sched_del(sched, peer->expire);
+		}
+		
 		peer->expire = -1;
 
 		destroy_association(peer);
@@ -9254,6 +9314,7 @@
 		ast_copy_string(peer->username, curi, sizeof(peer->username));
 
 	if (peer->expire > -1) {
+		ast_log(LOG_WARNING,"About to sched_del peer expire(%d) for peer in parse_register_result\n", peer->expire);
 		ast_sched_del(sched, peer->expire);
 		peer->expire = -1;
 	}
@@ -9263,6 +9324,7 @@
 		expiry = min_expiry;
 	peer->expire = peer->is_realtime ? -1 :
 		ast_sched_add(sched, (expiry + 10) * 1000, expire_register, peer);
+	ast_log(LOG_WARNING,"Just did sched_add peer expire(%d) for peer in parse_register_result\n", peer->expire);
 	pvt->expiry = expiry;
 	snprintf(data, sizeof(data), "%s:%d:%d:%s:%s", ast_inet_ntoa(peer->addr.sin_addr), ntohs(peer->addr.sin_port), expiry, peer->username, peer->fullcontact);
 	if (!peer->rt_fromcontact) 
@@ -13219,7 +13281,11 @@
 		/* Recalculate our side, and recalculate Call ID */
 		ast_sip_ouraddrfor(&p->sa.sin_addr, &p->ourip);
 		build_via(p);
+		ast_log(LOG_NOTICE,"====================================About to build callid for %s\n", p->callid);
+		ao2_unlink(dialogs,p,"About to change the callid -- remove the old name");
 		build_callid_pvt(p);
+		ao2_link(dialogs,p,"Linking in new name");
+		ast_log(LOG_NOTICE,"====================================New callid: %s\n", p->callid);
 		ast_cli(a->fd, "Sending NOTIFY of type '%s' to '%s'\n", a->argv[2], a->argv[i]);
 		dialog_ref(p,"bump the count of p, which transmit_sip_request will decrement.");
 		transmit_sip_request(p, &req);
@@ -13821,6 +13887,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *) data;
 
+	ast_log(LOG_NOTICE,"SCHED:  sip_reinvite_retry called---\n");
 	ast_set_flag(&p->flags[0], SIP_NEEDREINVITE);	
 	p->waitid = -1;
 	return 0;
@@ -13849,6 +13916,7 @@
 	/* Acknowledge sequence number - This only happens on INVITE from SIP-call */
 	if (p->initid > -1) {
 		/* Don't auto congest anymore since we've gotten something useful back */
+		ast_log(LOG_WARNING,"About to sched_del initd (autocongest) for dialog %s in handle_response_invite\n", p->callid);
 		if (ast_sched_del(sched, p->initid) == 0)
 			dialog_unref(p,"when you delete the initid sched, you should dec the refcount for the stored dialog ptr");
 		p->initid = -1;
@@ -14129,6 +14197,7 @@
 				 */
 				int wait = 3 + ast_random() % 5;
 				p->waitid = ast_sched_add(sched, wait, sip_reinvite_retry, p); 
+				ast_log(LOG_WARNING,"just did sched_add waitid(%d) for sip_reinvite_retry for dialog %s in handle_response_invite\n", p->waitid, p->callid);
 				ast_debug(2, "Reinvite race. Waiting %d secs before retry\n", wait);
 			}
 		}
@@ -14219,6 +14288,7 @@
 		break;
 	case 403:	/* Forbidden */
 		ast_log(LOG_WARNING, "Forbidden - wrong password on authentication for REGISTER for '%s' to '%s'\n", p->registry->username, p->registry->hostname);
+		ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 403\n", r->timeout);
 		ast_sched_del(sched, r->timeout);
 		r->timeout = -1;
 		r->regstate = REG_STATE_NOAUTH;
@@ -14230,6 +14300,7 @@
 		if (r->call)
 			r->call = dialog_unref(r->call,"unsetting registry->call pointer-- case 404");
 		r->regstate = REG_STATE_REJECTED;
+		ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 404\n", r->timeout);
 		ast_sched_del(sched, r->timeout);
 		r->timeout = -1;
 		break;
@@ -14245,12 +14316,14 @@
 		p->needdestroy = 1;
 		if (r->call)
 			r->call = dialog_unref(r->call,"unsetting registry->call pointer-- case 408");
+		ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 408\n", r->timeout);
 		ast_sched_del(sched, r->timeout);
 		r->timeout = -1;
 		break;
 	case 423:	/* Interval too brief */
 		r->expiry = atoi(get_header(req, "Min-Expires"));
 		ast_log(LOG_WARNING, "Got 423 Interval too brief for service %s@%s, minimum is %d seconds\n", p->registry->username, p->registry->hostname, r->expiry);
+		ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 423\n", r->timeout);
 		ast_sched_del(sched, r->timeout);
 		r->timeout = -1;
 		if (r->call) {
@@ -14273,6 +14346,7 @@
 		if (r->call)
 			r->call = dialog_unref(r->call,"unsetting registry->call pointer-- case 479");
 		r->regstate = REG_STATE_REJECTED;
+		ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 479\n", r->timeout);
 		ast_sched_del(sched, r->timeout);
 		r->timeout = -1;
 		break;
@@ -14290,6 +14364,7 @@
 		ast_debug(1, "Registration successful\n");
 		if (r->timeout > -1) {
 			ast_debug(1, "Cancelling timeout %d\n", r->timeout);
+			ast_log(LOG_WARNING,"About to sched_del registry timeout(%d) for reg in handle_response_register state 200\n", r->timeout);
 			ast_sched_del(sched, r->timeout);
 		}
 		r->timeout=-1;
@@ -14302,8 +14377,11 @@
 		
 		/* set us up for re-registering */
 		/* figure out how long we got registered for */
-		if (r->expire > -1)
+		if (r->expire > -1){
+			ast_log(LOG_WARNING,"About to sched_del registry expire(%d) for reg in handle_response_register state 200\n", r->expire);
 			ast_sched_del(sched, r->expire);
+		}
+		
 		/* according to section 6.13 of RFC, contact headers override
 		   expires headers, so check those first */
 		expires = 0;
@@ -14347,6 +14425,7 @@
 		r->refresh= (int) expires_ms / 1000;
 		
 		/* Schedule re-registration before we expire */
+		ast_log(LOG_WARNING,"About to sched_replace registry expire(%d) for reg in handle_response_register near end\n", r->expire);
 		r->expire = ast_sched_replace(r->expire, sched, expires_ms, sip_reregister, r); 
 		registry_unref(r,"unref registry ptr r"); /* HUH?  if this gets deleted, p->registry will be a bad pointer! */
 		/* shouldn't this be:
@@ -14399,6 +14478,7 @@
 	p->needdestroy = 1;
 
 	/* Try again eventually */
+	ast_log(LOG_WARNING,"About to sched_replace peer pokeexpire(%d) for peer in handle_response_peerpoke\n", peer->pokeexpire);
 	peer->pokeexpire = ast_sched_replace(peer->pokeexpire, sched,
 		is_reachable ? DEFAULT_FREQ_OK : DEFAULT_FREQ_NOTOK,
 		sip_poke_peer_s, peer);
@@ -17357,8 +17437,12 @@
 		}
 		/* Recalculate our side, and recalculate Call ID */
 		ast_sip_ouraddrfor(&p->sa.sin_addr, &p->ourip);
+		ast_log(LOG_NOTICE,"====================================About to build callid for %s\n", p->callid);
 		build_via(p);
+		ao2_unlink(dialogs,p,"About to change the callid -- remove the old name");
 		build_callid_pvt(p);
+		ao2_link(dialogs,p,"Linking in under new name");
+		ast_log(LOG_NOTICE,"====================================New callid: %s\n", p->callid);
 		/* Destroy this session after 32 secs */
 		sip_scheddestroy(p, DEFAULT_TRANS_TIMEOUT);
 	}
@@ -17535,6 +17619,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 	
+	ast_log(LOG_NOTICE,"SCHED:  sip_poke_noanswer called---\n");
 	peer->pokeexpire = -1;
 	if (peer->lastms > -1) {
 		ast_log(LOG_NOTICE, "Peer '%s' is now UNREACHABLE!  Last qualify: %d\n", peer->name, peer->lastms);
@@ -17552,6 +17637,7 @@
 	peer->lastms = -1;
 	ast_device_state_changed("SIP/%s", peer->name);
 	/* Try again quickly */
+	ast_log(LOG_WARNING,"About to sched_replace peer pokeexpire(%d) for peer in sip_poke_noanswer\n", peer->pokeexpire);
 	peer->pokeexpire = ast_sched_replace(peer->pokeexpire, sched, 
 		DEFAULT_FREQ_NOTOK, sip_poke_peer_s, peer);
 	return 0;
@@ -17568,8 +17654,11 @@
 	if (!peer->maxms || !peer->addr.sin_addr.s_addr) {
 		/* IF we have no IP, or this isn't to be monitored, return
 		  imeediately after clearing things out */
-		if (peer->pokeexpire > -1)
+		if (peer->pokeexpire > -1) {
+			ast_log(LOG_WARNING,"About to sched_del peer pokeexpire(%d) for peer in sip_poke_peer\n", peer->pokeexpire);
 			ast_sched_del(sched, peer->pokeexpire);
+		}
+		
 		peer->lastms = 0;
 		peer->pokeexpire = -1;
 		peer->call = NULL;
@@ -17602,12 +17691,19 @@
 		ast_string_field_set(p, tohost, ast_inet_ntoa(peer->addr.sin_addr));
 
 	/* Recalculate our side, and recalculate Call ID */
+	ast_log(LOG_NOTICE,"====================================About to build callid for %s\n", p->callid);
 	ast_sip_ouraddrfor(&p->sa.sin_addr, &p->ourip);
 	build_via(p);
+	ao2_unlink(dialogs,p,"About to change the callid -- remove the old name");
 	build_callid_pvt(p);
-
-	if (peer->pokeexpire > -1)
+	ao2_link(dialogs,p,"Linking in under new name");
+	ast_log(LOG_NOTICE,"====================================New callid: %s\n", p->callid);
+
+	if (peer->pokeexpire > -1) {
+		ast_log(LOG_WARNING,"About to sched_del peer pokeexpire(%d) for peer in sip_poke_peer\n", peer->pokeexpire);
 		ast_sched_del(sched, peer->pokeexpire);
+	}
+	
 	p->relatedpeer = ref_peer(peer,"setting the relatedpeer field in the dialog");
 	ast_set_flag(&p->flags[0], SIP_OUTGOING);
 #ifdef VOCAL_DATA_HACK
@@ -17620,6 +17716,7 @@
 	if (xmitres == XMIT_ERROR)
 		sip_poke_noanswer(peer);	/* Immediately unreachable, network problems */
 	else {
+		ast_log(LOG_WARNING,"About to sched_replace peer pokeexpire(%d) for peer in sip_poke_peer near end\n", peer->pokeexpire);
 		peer->pokeexpire = ast_sched_replace(peer->pokeexpire, sched, 
 			peer->maxms * 2, sip_poke_noanswer, peer);
 	}
@@ -17798,9 +17895,13 @@
 	if (ast_strlen_zero(p->peername) && ext)
 		ast_string_field_set(p, peername, ext);
 	/* Recalculate our side, and recalculate Call ID */
+	ast_log(LOG_NOTICE,"====================================About to build callid for %s\n", p->callid);
 	ast_sip_ouraddrfor(&p->sa.sin_addr, &p->ourip);
 	build_via(p);
+	ao2_unlink(dialogs,p,"About to change the callid -- remove the old name");
 	build_callid_pvt(p);
+	ao2_link(dialogs,p,"Linking in under new name");
+	ast_log(LOG_NOTICE,"====================================New callid: %s\n", p->callid);
 	
 	/* We have an extension to call, don't use the full contact here */
 	/* This to enable dialing registered peers with extension dialling,
@@ -18484,7 +18585,11 @@
 			} else {
 				/* Non-dynamic.  Make sure we become that way if we're not */
 				if (peer->expire > -1)
+				{
+					ast_log(LOG_WARNING,"About to sched_del peer expire(%d) for peer in build_peer near end\n", peer->expire);
 					ast_sched_del(sched, peer->expire);
+				}
+				
 				peer->expire = -1;
 				peer->host_dynamic = FALSE;
 				if (ast_get_ip_or_srv(&peer->addr, v->value, global_srvlookup ? "_sip._udp" : NULL)) {
@@ -19796,6 +19901,7 @@
 
 	while ((peer = ao2_iterator_next(&i, "iterate thru peers table"))) {
 		ms += 100;
+		ast_log(LOG_WARNING,"About to sched_replace peer pokeexpire(%d) for peer in sip_poke_all_peers\n", peer->pokeexpire);
 		peer->pokeexpire = ast_sched_replace(peer->pokeexpire, 
 			sched, ms, sip_poke_peer_s, peer);
 		unref_peer(peer,"toss iterator peer ptr");
@@ -19816,6 +19922,7 @@
 	ASTOBJ_CONTAINER_TRAVERSE(&regl, 1, do {
 		ASTOBJ_WRLOCK(iterator); /* was WRLOCK */
 		ms += regspacing;
+		ast_log(LOG_WARNING,"About to sched_replace reg expire(%d) for reg in sip_send_all_registers\n", iterator->expire);
 		iterator->expire = ast_sched_replace(iterator->expire, 
 			sched, ms, sip_reregister, iterator);
 		ASTOBJ_UNLOCK(iterator);

Modified: team/murf/bug11210/main/sched.c
URL: http://svn.digium.com/view/asterisk/team/murf/bug11210/main/sched.c?view=diff&rev=93535&r1=93534&r2=93535
==============================================================================
--- team/murf/bug11210/main/sched.c (original)
+++ team/murf/bug11210/main/sched.c Mon Dec 17 23:50:15 2007
@@ -236,6 +236,7 @@
 			res = tmp->id;
 		}
 	}
+	ast_log(LOG_ERROR,"SCHED: add schedule entry in %d!  ID=%d\n", when, res);
 #ifdef DUMP_SCHEDULER
 	/* Dump contents of the context while we have the lock so nothing gets screwed up by accident. */
 	if (option_debug)
@@ -268,6 +269,7 @@
 	struct sched *s;
 
 	DEBUG(ast_debug(1, "ast_sched_del()\n"));
+	ast_log(LOG_ERROR,"SCHED: delete schedule entry %d!\n", id);
 	
 	ast_mutex_lock(&con->lock);
 	AST_LIST_TRAVERSE_SAFE_BEGIN(&con->schedq, s, list) {
@@ -292,6 +294,7 @@
 #ifdef DO_CRASH
 		CRASH;
 #endif
+		ast_log(LOG_ERROR,"Attempted to delete nonexistent schedule entry %d!\n", id);
 		return -1;
 	}
 	




More information about the svn-commits mailing list