3 files changed, 206 insertions, 62 deletions

diff --git a/res/res_pjsip/pjsip_scheduler.c b/res/res_pjsip/pjsip_scheduler.c
index 27202c602..e4459da66 100644
--- a/res/res_pjsip/pjsip_scheduler.c
+++ b/res/res_pjsip/pjsip_scheduler.c
@@ -373,7 +373,7 @@ static char *cli_show_tasks(struct ast_cli_entry *e, int cmd, struct ast_cli_arg
 	struct ast_tm tm;
 	char queued[32];
 	char last_start[32];
-	char last_end[32];
+	char next_start[32];
 	int datelen;
 	struct timeval now = ast_tvnow();
 	const char *separator = "======================================";
@@ -397,19 +397,21 @@ static char *cli_show_tasks(struct ast_cli_entry *e, int cmd, struct ast_cli_arg
 
 	ast_cli(a->fd, "PJSIP Scheduled Tasks:\n\n");
 
-	ast_cli(a->fd, " %1$-24s %2$-8s %3$-9s %4$-7s  %6$-*5$s  %7$-*5$s  %8$-*5$s\n",
+	ast_cli(a->fd, " %1$-24s %2$-9s %3$-9s %4$-5s  %6$-*5$s  %7$-*5$s  %8$-*5$s %9$7s\n",
 		"Task Name", "Interval", "Times Run", "State",
-		datelen, "Queued", "Last Started", "Last Ended");
+		datelen, "Queued", "Last Started", "Next Start", "( secs)");
 
-	ast_cli(a->fd, " %1$-24.24s %2$-8.8s %3$-9.9s %4$-7.7s  %6$-*5$.*5$s  %7$-*5$.*5$s  %8$-*5$.*5$s\n",
+	ast_cli(a->fd, " %1$-24.24s %2$-9.9s %3$-9.9s %4$-5.5s  %6$-*5$.*5$s  %7$-*5$.*5$s  %9$-*8$.*8$s\n",
 		separator, separator, separator, separator,
-		datelen, separator, separator, separator);
+		datelen, separator, separator, datelen + 8, separator);
 
 
 	ao2_ref(tasks, +1);
 	ao2_rdlock(tasks);
 	i = ao2_iterator_init(tasks, 0);
 	while ((schtd = ao2_iterator_next(&i))) {
+		int next_run_sec = ast_sip_sched_task_get_next_run(schtd) / 1000;
+		struct timeval next = ast_tvadd(now, (struct timeval) {next_run_sec, 0});
 
 		ast_localtime(&schtd->when_queued, &tm, NULL);
 		ast_strftime(queued, sizeof(queued), log_format, &tm);
@@ -421,23 +423,17 @@ static char *cli_show_tasks(struct ast_cli_entry *e, int cmd, struct ast_cli_arg
 			ast_strftime(last_start, sizeof(last_start), log_format, &tm);
 		}
 
-		if (ast_tvzero(schtd->last_end)) {
-			if (ast_tvzero(schtd->last_start)) {
-				strcpy(last_end, "not yet started");
-			} else {
-				strcpy(last_end, "running");
-			}
-		} else {
-			ast_localtime(&schtd->last_end, &tm, NULL);
-			ast_strftime(last_end, sizeof(last_end), log_format, &tm);
-		}
+		ast_localtime(&next, &tm, NULL);
+		ast_strftime(next_start, sizeof(next_start), log_format, &tm);
 
-		ast_cli(a->fd, " %1$-24.24s %2$-8.3f %3$-9d %4$-7s  %6$-*5$s  %7$-*5$s  %8$-*5$s\n",
+		ast_cli(a->fd, " %1$-24.24s %2$9.3f %3$9d %4$-5s  %6$-*5$s  %7$-*5$s  %8$-*5$s (%9$5d)\n",
 			schtd->name,
 			schtd->interval / 1000.0,
 			schtd->run_count,
-			schtd->is_running ? "running" : "waiting",
-			datelen, queued, last_start, last_end);
+			schtd->is_running ? "run" : "wait",
+			datelen, queued, last_start,
+			next_start,
+			next_run_sec);
 		ao2_cleanup(schtd);
 	}
 	ao2_iterator_destroy(&i);
diff --git a/res/res_pjsip_exten_state.c b/res/res_pjsip_exten_state.c
index 9bb53bfe3..95a40829e 100644
--- a/res/res_pjsip_exten_state.c
+++ b/res/res_pjsip_exten_state.c
@@ -415,8 +415,9 @@ static int new_subscribe(struct ast_sip_endpoint *endpoint,
 	const char *context = S_OR(endpoint->subscription.context, endpoint->context);
 
 	if (!ast_exists_extension(NULL, context, resource, PRIORITY_HINT, NULL)) {
-		ast_log(LOG_NOTICE, "Extension state subscription failed: Extension %s does not exist in context '%s' or has no associated hint\n",
-			resource, context);
+		ast_log(LOG_NOTICE, "Endpoint '%s' state subscription failed: "
+			"Extension '%s' does not exist in context '%s' or has no associated hint\n",
+			ast_sorcery_object_get_id(endpoint), resource, context);
 		return 404;
 	}
 
diff --git a/res/res_pjsip_pubsub.c b/res/res_pjsip_pubsub.c
index 42f0dc11e..709dc6640 100644
--- a/res/res_pjsip_pubsub.c
+++ b/res/res_pjsip_pubsub.c
@@ -392,6 +392,13 @@ enum sip_subscription_tree_state {
 	SIP_SUB_TREE_TERMINATED,
 };
 
+static char *sub_tree_state_description[] = {
+	"Normal",
+	"TerminatePending",
+	"TerminateInProgress",
+	"Terminated"
+};
+
 /*!
  * \brief A tree of SIP subscriptions
  *
@@ -428,6 +435,11 @@ struct sip_subscription_tree {
 	AST_LIST_ENTRY(sip_subscription_tree) next;
 	/*! Subscription tree state */
 	enum sip_subscription_tree_state state;
+	/*! On asterisk restart, this is the task data used
+	 * to restart the expiration timer if pjproject isn't
+	 * capable of restarting the timer.
+	 */
+	struct ast_sip_sched_task *expiration_task;
 };
 
 /*!
@@ -482,6 +494,17 @@ static const char *sip_subscription_roles_map[] = {
 	[AST_SIP_NOTIFIER] = "Notifier"
 };
 
+enum sip_persistence_update_type {
+	/*! Called from send request */
+	SUBSCRIPTION_PERSISTENCE_SEND_REQUEST = 0,
+	/*! Subscription created from initial client request */
+	SUBSCRIPTION_PERSISTENCE_CREATED,
+	/*! Subscription recreated by asterisk on startup */
+	SUBSCRIPTION_PERSISTENCE_RECREATED,
+	/*! Subscription created from client refresh */
+	SUBSCRIPTION_PERSISTENCE_REFRESHED,
+};
+
 AST_RWLIST_HEAD_STATIC(subscriptions, sip_subscription_tree);
 
 AST_RWLIST_HEAD_STATIC(body_generators, ast_sip_pubsub_body_generator);
@@ -560,7 +583,7 @@ static struct subscription_persistence *subscription_persistence_create(struct s
 
 /*! \brief Function which updates persistence information of a subscription in sorcery */
 static void subscription_persistence_update(struct sip_subscription_tree *sub_tree,
-	pjsip_rx_data *rdata)
+	pjsip_rx_data *rdata, enum sip_persistence_update_type type)
 {
 	pjsip_dialog *dlg;
 
@@ -568,6 +591,9 @@ static void subscription_persistence_update(struct sip_subscription_tree *sub_tr
 		return;
 	}
 
+	ast_debug(3, "Updating persistence for '%s->%s'\n",
+		ast_sorcery_object_get_id(sub_tree->endpoint), sub_tree->root->resource);
+
 	dlg = sub_tree->dlg;
 	sub_tree->persistence->cseq = dlg->local.cseq;
 
@@ -584,12 +610,15 @@ static void subscription_persistence_update(struct sip_subscription_tree *sub_tr
 		 * persistence that is pulled from persistent storage, though, the rdata->pkt_info.packet will
 		 * only ever have a single SIP message on it, and so we base persistence on that.
 		 */
-		if (rdata->msg_info.msg_buf) {
-			ast_copy_string(sub_tree->persistence->packet, rdata->msg_info.msg_buf,
-					MIN(sizeof(sub_tree->persistence->packet), rdata->msg_info.len));
-		} else {
-			ast_copy_string(sub_tree->persistence->packet, rdata->pkt_info.packet,
-					sizeof(sub_tree->persistence->packet));
+		if (type == SUBSCRIPTION_PERSISTENCE_CREATED
+			|| type == SUBSCRIPTION_PERSISTENCE_RECREATED) {
+			if (rdata->msg_info.msg_buf) {
+				ast_copy_string(sub_tree->persistence->packet, rdata->msg_info.msg_buf,
+						MIN(sizeof(sub_tree->persistence->packet), rdata->msg_info.len));
+			} else {
+				ast_copy_string(sub_tree->persistence->packet, rdata->pkt_info.packet,
+						sizeof(sub_tree->persistence->packet));
+			}
 		}
 		ast_copy_string(sub_tree->persistence->src_name, rdata->pkt_info.src_name,
 				sizeof(sub_tree->persistence->src_name));
@@ -986,7 +1015,8 @@ static int build_resource_tree(struct ast_sip_endpoint *endpoint, const struct a
 	struct resources visited;
 
 	if (!has_eventlist_support || !(list = retrieve_resource_list(resource, handler->event_name))) {
-		ast_debug(2, "Subscription to resource %s is not to a list\n", resource);
+		ast_debug(2, "Subscription '%s->%s' is not to a list\n",
+			ast_sorcery_object_get_id(endpoint), resource);
 		tree->root = tree_node_alloc(resource, NULL, 0);
 		if (!tree->root) {
 			return 500;
@@ -994,7 +1024,8 @@ static int build_resource_tree(struct ast_sip_endpoint *endpoint, const struct a
 		return handler->notifier->new_subscribe(endpoint, resource);
 	}
 
-	ast_debug(2, "Subscription to resource %s is a list\n", resource);
+	ast_debug(2, "Subscription '%s->%s' is a list\n",
+		ast_sorcery_object_get_id(endpoint), resource);
 	if (AST_VECTOR_INIT(&visited, AST_VECTOR_SIZE(&list->items))) {
 		return 500;
 	}
@@ -1033,8 +1064,8 @@ static void remove_subscription(struct sip_subscription_tree *obj)
 		if (i == obj) {
 			AST_RWLIST_REMOVE_CURRENT(next);
 			if (i->root) {
-				ast_debug(2, "Removing subscription to resource %s from list of subscriptions\n",
-						ast_sip_subscription_get_resource_name(i->root));
+				ast_debug(2, "Removing subscription '%s->%s' from list of subscriptions\n",
+					ast_sorcery_object_get_id(i->endpoint), ast_sip_subscription_get_resource_name(i->root));
 			}
 			break;
 		}
@@ -1045,7 +1076,8 @@ static void remove_subscription(struct sip_subscription_tree *obj)
 
 static void destroy_subscription(struct ast_sip_subscription *sub)
 {
-	ast_debug(3, "Destroying SIP subscription to resource %s\n", sub->resource);
+	ast_debug(3, "Destroying SIP subscription from '%s->%s'\n",
+		ast_sorcery_object_get_id(sub->tree->endpoint), sub->resource);
 	ast_free(sub->body_text);
 
 	AST_VECTOR_FREE(&sub->children);
@@ -1197,7 +1229,10 @@ static void subscription_tree_destructor(void *obj)
 {
 	struct sip_subscription_tree *sub_tree = obj;
 
-	ast_debug(3, "Destroying subscription tree %p\n", sub_tree);
+	ast_debug(3, "Destroying subscription tree %p '%s->%s'\n",
+		sub_tree,
+		sub_tree->endpoint ? ast_sorcery_object_get_id(sub_tree->endpoint) : "Unknown",
+		sub_tree->root ? sub_tree->root->resource : "Unknown");
 
 	ao2_cleanup(sub_tree->endpoint);
 
@@ -1213,7 +1248,8 @@ static void subscription_tree_destructor(void *obj)
 
 void ast_sip_subscription_destroy(struct ast_sip_subscription *sub)
 {
-	ast_debug(3, "Removing subscription %p reference to subscription tree %p\n", sub, sub->tree);
+	ast_debug(3, "Removing subscription %p '%s->%s' reference to subscription tree %p\n",
+		sub, ast_sorcery_object_get_id(sub->tree->endpoint), sub->resource, sub->tree);
 	ao2_cleanup(sub->tree);
 }
 
@@ -1320,7 +1356,6 @@ static struct sip_subscription_tree *create_subscription_tree(const struct ast_s
 		dlg->local.tag_hval = pj_hash_calc_tolower(0, NULL, &dlg->local.info->tag);
 		pjsip_ua_register_dlg(pjsip_ua_instance(), dlg);
 		dlg->local.cseq = persistence->cseq;
-		dlg->remote.cseq = persistence->cseq;
 	}
 
 	pjsip_evsub_create_uas(dlg, &pubsub_cb, rdata, 0, &sub_tree->evsub);
@@ -1345,6 +1380,12 @@ static struct sip_subscription_tree *create_subscription_tree(const struct ast_s
 	return sub_tree;
 }
 
+/*! Wrapper structure for initial_notify_task */
+struct initial_notify_data {
+	struct sip_subscription_tree *sub_tree;
+	int expires;
+};
+
 static int initial_notify_task(void *obj);
 static int send_notify(struct sip_subscription_tree *sub_tree, unsigned int force_full_state);
 
@@ -1433,9 +1474,12 @@ static int sub_persistence_recreate(void *obj)
 		}
 		pjsip_msg_add_hdr(rdata->msg_info.msg, (pjsip_hdr *) expires_header);
 	}
+
 	expires_header->ivalue = (ast_tvdiff_ms(persistence->expires, ast_tvnow()) / 1000);
 	if (expires_header->ivalue <= 0) {
 		/* The subscription expired since we started recreating the subscription. */
+		ast_debug(3, "Expired subscription retrived from persistent store '%s' %s\n",
+			persistence->endpoint, persistence->tag);
 		ast_sorcery_delete(ast_sip_get_sorcery(), persistence);
 		ao2_ref(endpoint, -1);
 		return 0;
@@ -1456,18 +1500,30 @@ static int sub_persistence_recreate(void *obj)
 				ast_sorcery_delete(ast_sip_get_sorcery(), persistence);
 			}
 		} else {
+			struct initial_notify_data *ind = ast_malloc(sizeof(*ind));
+
+			if (!ind) {
+				pjsip_evsub_terminate(sub_tree->evsub, PJ_TRUE);
+				goto error;
+			}
+
+			ind->sub_tree = ao2_bump(sub_tree);
+			ind->expires = expires_header->ivalue;
+
 			sub_tree->persistence = ao2_bump(persistence);
-			subscription_persistence_update(sub_tree, rdata);
-			if (ast_sip_push_task(sub_tree->serializer, initial_notify_task,
-				ao2_bump(sub_tree))) {
+			subscription_persistence_update(sub_tree, rdata, SUBSCRIPTION_PERSISTENCE_RECREATED);
+			if (ast_sip_push_task(sub_tree->serializer, initial_notify_task, ind)) {
 				/* Could not send initial subscribe NOTIFY */
 				pjsip_evsub_terminate(sub_tree->evsub, PJ_TRUE);
 				ao2_ref(sub_tree, -1);
+				ast_free(ind);
 			}
 		}
 	} else {
 		ast_sorcery_delete(ast_sip_get_sorcery(), persistence);
 	}
+
+error:
 	resource_tree_destroy(&tree);
 	ao2_ref(endpoint, -1);
 
@@ -1485,6 +1541,8 @@ static int subscription_persistence_recreate(void *obj, void *arg, int flags)
 
 	/* If this subscription has already expired remove it */
 	if (ast_tvdiff_ms(persistence->expires, ast_tvnow()) <= 0) {
+		ast_debug(3, "Expired subscription retrived from persistent store '%s' %s\n",
+			persistence->endpoint, persistence->tag);
 		ast_sorcery_delete(ast_sip_get_sorcery(), persistence);
 		return 0;
 	}
@@ -1814,7 +1872,7 @@ static int sip_subscription_send_request(struct sip_subscription_tree *sub_tree,
 
 	res = internal_pjsip_evsub_send_request(sub_tree, tdata);
 
-	subscription_persistence_update(sub_tree, NULL);
+	subscription_persistence_update(sub_tree, NULL, SUBSCRIPTION_PERSISTENCE_SEND_REQUEST);
 
 	ast_test_suite_event_notify("SUBSCRIPTION_STATE_SET",
 		"StateText: %s\r\n"
@@ -2713,21 +2771,45 @@ static int generate_initial_notify(struct ast_sip_subscription *sub)
 	return res;
 }
 
+static int pubsub_on_refresh_timeout(void *userdata);
+
 static int initial_notify_task(void * obj)
 {
-	struct sip_subscription_tree *sub_tree;
+	struct initial_notify_data *ind = obj;
 
-	sub_tree = obj;
-	if (generate_initial_notify(sub_tree->root)) {
-		pjsip_evsub_terminate(sub_tree->evsub, PJ_TRUE);
+	if (generate_initial_notify(ind->sub_tree->root)) {
+		pjsip_evsub_terminate(ind->sub_tree->evsub, PJ_TRUE);
 	} else {
-		send_notify(sub_tree, 1);
+		send_notify(ind->sub_tree, 1);
 		ast_test_suite_event_notify("SUBSCRIPTION_ESTABLISHED",
 			"Resource: %s",
-			sub_tree->root->resource);
+			ind->sub_tree->root->resource);
+	}
+
+	if (ind->expires > -1) {
+		char *name = ast_alloca(strlen("->/ ") +
+			strlen(ind->sub_tree->persistence->endpoint) +
+			strlen(ind->sub_tree->root->resource) +
+			strlen(ind->sub_tree->root->handler->event_name) +
+			ind->sub_tree->dlg->call_id->id.slen + 1);
+
+		sprintf(name, "%s->%s/%s %.*s", ind->sub_tree->persistence->endpoint,
+			ind->sub_tree->root->resource, ind->sub_tree->root->handler->event_name,
+			(int)ind->sub_tree->dlg->call_id->id.slen, ind->sub_tree->dlg->call_id->id.ptr);
+
+		ast_debug(3, "Scheduling timer: %s\n", name);
+		ind->sub_tree->expiration_task = ast_sip_schedule_task(ind->sub_tree->serializer,
+			ind->expires * 1000, pubsub_on_refresh_timeout, name,
+			ind->sub_tree, AST_SIP_SCHED_TASK_FIXED | AST_SIP_SCHED_TASK_DATA_AO2);
+		if (!ind->sub_tree->expiration_task) {
+			ast_log(LOG_ERROR, "Unable to create expiration timer of %d seconds for %s\n",
+				ind->expires, name);
+		}
 	}
 
-	ao2_ref(sub_tree, -1);
+	ao2_ref(ind->sub_tree, -1);
+	ast_free(ind);
+
 	return 0;
 }
 
@@ -2820,12 +2902,25 @@ static pj_bool_t pubsub_on_rx_subscribe_request(pjsip_rx_data *rdata)
 			pjsip_endpt_respond_stateless(ast_sip_get_pjsip_endpoint(), rdata, 500, NULL, NULL, NULL);
 		}
 	} else {
+		struct initial_notify_data *ind = ast_malloc(sizeof(*ind));
+
+		if (!ind) {
+			pjsip_evsub_terminate(sub_tree->evsub, PJ_TRUE);
+			resource_tree_destroy(&tree);
+			return PJ_TRUE;
+		}
+
+		ind->sub_tree = ao2_bump(sub_tree);
+		/* Since this is a normal subscribe, pjproject takes care of the timer */
+		ind->expires = -1;
+
 		sub_tree->persistence = subscription_persistence_create(sub_tree);
-		subscription_persistence_update(sub_tree, rdata);
+		subscription_persistence_update(sub_tree, rdata, SUBSCRIPTION_PERSISTENCE_CREATED);
 		sip_subscription_accept(sub_tree, rdata, resp);
-		if (ast_sip_push_task(sub_tree->serializer, initial_notify_task, ao2_bump(sub_tree))) {
+		if (ast_sip_push_task(sub_tree->serializer, initial_notify_task, ind)) {
 			pjsip_evsub_terminate(sub_tree->evsub, PJ_TRUE);
 			ao2_ref(sub_tree, -1);
+			ast_free(ind);
 		}
 	}
 
@@ -3360,7 +3455,7 @@ static void set_state_terminated(struct ast_sip_subscription *sub)
  *           send_notify ultimately calls pjsip_evsub_send_request
  *               pjsip_evsub_send_request calls evsub's set_state
  *                   set_state calls pubsub_evsub_set_state
- *                       pubsub_evsub_set_state checks state == TERMINATE_IN_PROGRESS
+ *                       pubsub_on_evsub_state checks state == TERMINATE_IN_PROGRESS
  *                       removes the subscriptions
  *                       cleans up references to evsub
  *                       sets state = TERMINATED
@@ -3378,6 +3473,15 @@ static void set_state_terminated(struct ast_sip_subscription *sub)
  *     serialized_pubsub_on_refresh_timeout starts
  *         See (1) Above
  *
+ * * Transmission failure sending NOTIFY or error response from client
+ *     pjproject transaction timer expires or non OK response
+ *         pjproject locks dialog
+ *         calls pubsub_on_evsub_state with event TSX_STATE
+ *             pubsub_on_evsub_state checks event == TSX_STATE
+ *             removes the subscriptions
+ *             cleans up references to evsub
+ *             sets state = TERMINATED
+ *         pjproject unlocks dialog
  *
  * * ast_sip_subscription_notify is called
  *       checks state == NORMAL
@@ -3403,25 +3507,41 @@ static void set_state_terminated(struct ast_sip_subscription *sub)
  *
  * Although this function is called for every state change, we only care
  * about the TERMINATED state, and only when we're actually processing the final
- * notify (SIP_SUB_TREE_TERMINATE_IN_PROGRESS).  In this case, we do all
- * the subscription tree cleanup tasks and decrement the evsub reference.
+ * notify (SIP_SUB_TREE_TERMINATE_IN_PROGRESS) OR when a transmission failure
+ * occurs (PJSIP_EVENT_TSX_STATE).  In this case, we do all the subscription tree
+ * cleanup tasks and decrement the evsub reference.
  */
 static void pubsub_on_evsub_state(pjsip_evsub *evsub, pjsip_event *event)
 {
-	struct sip_subscription_tree *sub_tree;
+	struct sip_subscription_tree *sub_tree =
+		pjsip_evsub_get_mod_data(evsub, pubsub_module.id);
 
-	ast_debug(3, "on_evsub_state called with state %s\n", pjsip_evsub_get_state_name(evsub));
+	ast_debug(3, "evsub %p state %s event %s sub_tree %p sub_tree state %s\n", evsub,
+		pjsip_evsub_get_state_name(evsub), pjsip_event_str(event->type), sub_tree,
+		(sub_tree ? sub_tree_state_description[sub_tree->state] : "UNKNOWN"));
 
-	if (pjsip_evsub_get_state(evsub) != PJSIP_EVSUB_STATE_TERMINATED) {
+	if (!sub_tree || pjsip_evsub_get_state(evsub) != PJSIP_EVSUB_STATE_TERMINATED) {
 		return;
 	}
 
-	sub_tree = pjsip_evsub_get_mod_data(evsub, pubsub_module.id);
-	if (!sub_tree || sub_tree->state != SIP_SUB_TREE_TERMINATE_IN_PROGRESS) {
-		ast_debug(1, "Possible terminate race prevented %p\n", sub_tree);
+	/* It's easier to write this as what we WANT to process, then negate it. */
+	if (!(sub_tree->state == SIP_SUB_TREE_TERMINATE_IN_PROGRESS
+		|| (event->type == PJSIP_EVENT_TSX_STATE && sub_tree->state == SIP_SUB_TREE_NORMAL)
+		)) {
+		ast_debug(3, "Do nothing.\n");
 		return;
 	}
 
+	if (sub_tree->expiration_task) {
+		char task_name[256];
+
+		ast_sip_sched_task_get_name(sub_tree->expiration_task, task_name, sizeof(task_name));
+		ast_debug(3, "Cancelling timer: %s\n", task_name);
+		ast_sip_sched_task_cancel(sub_tree->expiration_task);
+		ao2_cleanup(sub_tree->expiration_task);
+		sub_tree->expiration_task = NULL;
+	}
+
 	remove_subscription(sub_tree);
 
 	pjsip_evsub_set_mod_data(evsub, pubsub_module.id, NULL);
@@ -3443,16 +3563,17 @@ static void pubsub_on_evsub_state(pjsip_evsub *evsub, pjsip_event *event)
 	ao2_ref(sub_tree, -1);
 }
 
-static int serialized_pubsub_on_refresh_timeout(void *userdata)
+static int pubsub_on_refresh_timeout(void *userdata)
 {
 	struct sip_subscription_tree *sub_tree = userdata;
 	pjsip_dialog *dlg = sub_tree->dlg;
 
+	ast_debug(3, "sub_tree %p sub_tree state %s\n", sub_tree,
+		(sub_tree ? sub_tree_state_description[sub_tree->state] : "UNKNOWN"));
+
 	pjsip_dlg_inc_lock(dlg);
 	if (sub_tree->state >= SIP_SUB_TREE_TERMINATE_IN_PROGRESS) {
-		ast_debug(1, "Possible terminate race prevented %p %d\n", sub_tree->evsub, sub_tree->state);
 		pjsip_dlg_dec_lock(dlg);
-		ao2_cleanup(sub_tree);
 		return 0;
 	}
 
@@ -3468,7 +3589,20 @@ static int serialized_pubsub_on_refresh_timeout(void *userdata)
 				"Resource: %s", sub_tree->root->resource);
 
 	pjsip_dlg_dec_lock(dlg);
+
+	return 0;
+}
+
+static int serialized_pubsub_on_refresh_timeout(void *userdata)
+{
+	struct sip_subscription_tree *sub_tree = userdata;
+
+	ast_debug(3, "sub_tree %p sub_tree state %s\n", sub_tree,
+		(sub_tree ? sub_tree_state_description[sub_tree->state] : "UNKNOWN"));
+
+	pubsub_on_refresh_timeout(userdata);
 	ao2_cleanup(sub_tree);
+
 	return 0;
 }
 
@@ -3487,11 +3621,23 @@ static void pubsub_on_rx_refresh(pjsip_evsub *evsub, pjsip_rx_data *rdata,
 	struct sip_subscription_tree *sub_tree;
 
 	sub_tree = pjsip_evsub_get_mod_data(evsub, pubsub_module.id);
+	ast_debug(3, "evsub %p sub_tree %p sub_tree state %s\n", evsub, sub_tree,
+		(sub_tree ? sub_tree_state_description[sub_tree->state] : "UNKNOWN"));
+
 	if (!sub_tree || sub_tree->state != SIP_SUB_TREE_NORMAL) {
-		ast_debug(1, "Possible terminate race prevented %p %d\n", sub_tree, sub_tree ? sub_tree->state : -1 );
 		return;
 	}
 
+	if (sub_tree->expiration_task) {
+		char task_name[256];
+
+		ast_sip_sched_task_get_name(sub_tree->expiration_task, task_name, sizeof(task_name));
+		ast_debug(3, "Cancelling timer: %s\n", task_name);
+		ast_sip_sched_task_cancel(sub_tree->expiration_task);
+		ao2_cleanup(sub_tree->expiration_task);
+		sub_tree->expiration_task = NULL;
+	}
+
 	/* PJSIP will set the evsub's state to terminated before calling into this function
 	 * if the Expires value of the incoming SUBSCRIBE is 0.
 	 */
@@ -3500,6 +3646,8 @@ static void pubsub_on_rx_refresh(pjsip_evsub *evsub, pjsip_rx_data *rdata,
 		sub_tree->state = SIP_SUB_TREE_TERMINATE_PENDING;
 	}
 
+	subscription_persistence_update(sub_tree, rdata, SUBSCRIPTION_PERSISTENCE_REFRESHED);
+
 	if (ast_sip_push_task(sub_tree->serializer, serialized_pubsub_on_refresh_timeout, ao2_bump(sub_tree))) {
 		/* If we can't push the NOTIFY refreshing task...we'll just go with it. */
 		ast_log(LOG_ERROR, "Failed to push task to send NOTIFY.\n");
@@ -3577,7 +3725,6 @@ static void pubsub_on_server_timeout(pjsip_evsub *evsub)
 
 	sub_tree = pjsip_evsub_get_mod_data(evsub, pubsub_module.id);
 	if (!sub_tree || sub_tree->state != SIP_SUB_TREE_NORMAL) {
-		ast_debug(1, "Possible terminate race prevented %p %d\n", sub_tree, sub_tree ? sub_tree->state : -1 );
         return;
 	}