res_pjsip_pubsub: Correctly implement persisted subscriptions

This patch fixes 2 original issues and more that those 2 exposed.

* When we send a NOTIFY, and the client either doesn't respond or
  responds with a non OK, pjproject only calls our
  pubsub_on_evsub_state callback, no others.  Since
  pubsub_on_evsub_state (which does the sub_tree cleanup) does not
  expect to be called back without the other callbacks being called
  first, it just returns leaving the sub_tree orphaned.  Now
  pubsub_on_evsub_state checks the event for PJSIP_EVENT_TSX_STATE
  which is what pjproject will set to tell us that it was the
  transaction that timed out or failed and not the subscription
  itself timing our or being terminated by the client. If is
  TSX_STATE, pubsub_on_evsub_state now does the proper cleanup
  regardless of the state of the subscription.

* When a client renews a subscription, we don't update the
  persisted subscription with the new expires timestamp.  This causes
  subscription_persistence_recreate to prune the subscription if/when
  asterisk restarts.  Now, pubsub_on_rx_refresh calls
  subscription_persistence_update to apply the new expires timestamp.
  This exposed other issues however...

* When creating a dialog from rdata (which sub_persistence_recreate
  does from the packet buffer) there must NOT be a tag on the To
  header (which there will be when a client refreshes a
  subscription).  If there is one, pjsip_dlg_create_uas will fail.
  To address this, subscription_persistence_update now accepts a flag
  that indicates that the original packet buffer must not be updated.
  New subscribes don't set the flag and renews do.  This makes sure
  that when the rdata is recreated on asterisk startup, it's done
  from the original subscribe packet which won't have the tag on To.

* When creating a dialog from rdata, we were setting the dialog's
  remote (SUBSCRIBE) cseq to be the same as the local (NOTIFY) cseq.
  When the client tried to resubscribe after a restart with the
  correct cseq, we'd reject the request with an Invalid CSeq error.

* The acts of creating a dialog and evsub by themselves when
  recreating a subscription does NOT restart pjproject's subscription
  timer.  The result was that even if we did correctly recreate the
  subscription, we never removed it if the client happened to go away
  or send a non-OK response to a NOTIFY.  However, there is no
  pjproject function exposed to just set the timer on an evsub that
  wasn't created by an incoming subscribe request.  To address this,
  we create our own timer using ast_sip_schedule_task.  This timer is
  used only for re-establishing subscriptions after a restart.

  An earlier approach was to add support for setting pjproject's
  timer (via a pjproject patch) and while that patch is still included
  here, we don't use that call at the moment.

While addressing these issues, additional debugging was added and
some existing messages made more useful.  A few formatting changes
were also made to 'pjsip show scheduled tasks' to make displaying
the subscription timers a little more friendly.

ASTERISK-26696
ASTERISK-26756

Change-Id: I8c605fc1e3923f466a74db087d5ab6f90abce68e

configure

@@ -943,6 +943,10 @@ PBX_POPT
 POPT_DIR
 POPT_INCLUDE
 POPT_LIB
+PBX_PJSIP_EVSUB_SET_UAS_TIMEOUT
+PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR
+PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE
+PJSIP_EVSUB_SET_UAS_TIMEOUT_LIB
 PBX_PJSIP_AUTH_CLT_DEINIT
 PJSIP_AUTH_CLT_DEINIT_DIR
 PJSIP_AUTH_CLT_DEINIT_INCLUDE
@@ -9399,6 +9403,9 @@ $as_echo "#define HAVE_PJSIP_INV_SESSION_REF 1" >>confdefs.h
 $as_echo "#define HAVE_PJSIP_AUTH_CLT_DEINIT 1" >>confdefs.h
 
 
+$as_echo "#define HAVE_PJSIP_EVSUB_SET_UAS_TIMEOUT 1" >>confdefs.h
+
+
 
 
 
@@ -11593,6 +11600,18 @@ PBX_PJSIP_AUTH_CLT_DEINIT=0
 
 
 
+
+PJSIP_EVSUB_SET_UAS_TIMEOUT_DESCRIP="PJSIP EVSUB Set UAS Timeout support"
+PJSIP_EVSUB_SET_UAS_TIMEOUT_OPTION=pjsip
+PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR=${PJPROJECT_DIR}
+
+PBX_PJSIP_EVSUB_SET_UAS_TIMEOUT=0
+
+
+
+
+
+
 fi
 
 
@@ -26705,6 +26724,110 @@ _ACEOF
 fi
 
 
+
+if test "x${PBX_PJSIP_EVSUB_SET_UAS_TIMEOUT}" != "x1" -a "${USE_PJSIP_EVSUB_SET_UAS_TIMEOUT}" != "no"; then
+   pbxlibdir=""
+   # if --with-PJSIP_EVSUB_SET_UAS_TIMEOUT=DIR has been specified, use it.
+   if test "x${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}" != "x"; then
+      if test -d ${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}/lib; then
+         pbxlibdir="-L${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}/lib"
+      else
+         pbxlibdir="-L${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}"
+      fi
+   fi
+   pbxfuncname="pjsip_evsub_set_uas_timeout"
+   if test "x${pbxfuncname}" = "x" ; then   # empty lib, assume only headers
+      AST_PJSIP_EVSUB_SET_UAS_TIMEOUT_FOUND=yes
+   else
+      ast_ext_lib_check_save_CFLAGS="${CFLAGS}"
+      CFLAGS="${CFLAGS} $PJPROJECT_CFLAGS"
+      as_ac_Lib=`$as_echo "ac_cv_lib_pjsip_${pbxfuncname}" | $as_tr_sh`
+{ $as_echo "$as_me:${as_lineno-$LINENO}: checking for ${pbxfuncname} in -lpjsip" >&5
+$as_echo_n "checking for ${pbxfuncname} in -lpjsip... " >&6; }
+if eval \${$as_ac_Lib+:} false; then :
+  $as_echo_n "(cached) " >&6
+else
+  ac_check_lib_save_LIBS=$LIBS
+LIBS="-lpjsip ${pbxlibdir} $PJPROJECT_LIB $LIBS"
+cat confdefs.h - <<_ACEOF >conftest.$ac_ext
+/* end confdefs.h.  */
+
+/* Override any GCC internal prototype to avoid an error.
+   Use char because int might match the return type of a GCC
+   builtin and then its argument prototype would still apply.  */
+#ifdef __cplusplus
+extern "C"
+#endif
+char ${pbxfuncname} ();
+int
+main ()
+{
+return ${pbxfuncname} ();
+  ;
+  return 0;
+}
+_ACEOF
+if ac_fn_c_try_link "$LINENO"; then :
+  eval "$as_ac_Lib=yes"
+else
+  eval "$as_ac_Lib=no"
+fi
+rm -f core conftest.err conftest.$ac_objext \
+    conftest$ac_exeext conftest.$ac_ext
+LIBS=$ac_check_lib_save_LIBS
+fi
+eval ac_res=\$$as_ac_Lib
+	       { $as_echo "$as_me:${as_lineno-$LINENO}: result: $ac_res" >&5
+$as_echo "$ac_res" >&6; }
+if eval test \"x\$"$as_ac_Lib"\" = x"yes"; then :
+  AST_PJSIP_EVSUB_SET_UAS_TIMEOUT_FOUND=yes
+else
+  AST_PJSIP_EVSUB_SET_UAS_TIMEOUT_FOUND=no
+fi
+
+      CFLAGS="${ast_ext_lib_check_save_CFLAGS}"
+   fi
+
+   # now check for the header.
+   if test "${AST_PJSIP_EVSUB_SET_UAS_TIMEOUT_FOUND}" = "yes"; then
+      PJSIP_EVSUB_SET_UAS_TIMEOUT_LIB="${pbxlibdir} -lpjsip $PJPROJECT_LIB"
+      # if --with-PJSIP_EVSUB_SET_UAS_TIMEOUT=DIR has been specified, use it.
+      if test "x${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}" != "x"; then
+         PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE="-I${PJSIP_EVSUB_SET_UAS_TIMEOUT_DIR}/include"
+      fi
+      PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE="${PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE} $PJPROJECT_CFLAGS"
+      if test "xpjsip.h" = "x" ; then	# no header, assume found
+         PJSIP_EVSUB_SET_UAS_TIMEOUT_HEADER_FOUND="1"
+      else				# check for the header
+         ast_ext_lib_check_saved_CPPFLAGS="${CPPFLAGS}"
+         CPPFLAGS="${CPPFLAGS} ${PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE}"
+         ac_fn_c_check_header_mongrel "$LINENO" "pjsip.h" "ac_cv_header_pjsip_h" "$ac_includes_default"
+if test "x$ac_cv_header_pjsip_h" = xyes; then :
+  PJSIP_EVSUB_SET_UAS_TIMEOUT_HEADER_FOUND=1
+else
+  PJSIP_EVSUB_SET_UAS_TIMEOUT_HEADER_FOUND=0
+fi
+
+
+         CPPFLAGS="${ast_ext_lib_check_saved_CPPFLAGS}"
+      fi
+      if test "x${PJSIP_EVSUB_SET_UAS_TIMEOUT_HEADER_FOUND}" = "x0" ; then
+         PJSIP_EVSUB_SET_UAS_TIMEOUT_LIB=""
+         PJSIP_EVSUB_SET_UAS_TIMEOUT_INCLUDE=""
+      else
+         if test "x${pbxfuncname}" = "x" ; then		# only checking headers -> no library
+            PJSIP_EVSUB_SET_UAS_TIMEOUT_LIB=""
+         fi
+         PBX_PJSIP_EVSUB_SET_UAS_TIMEOUT=1
+         cat >>confdefs.h <<_ACEOF
+#define HAVE_PJSIP_EVSUB_SET_UAS_TIMEOUT 1
+_ACEOF
+
+      fi
+   fi
+fi
+
+
    fi
 fi
 

configure.ac

@@ -518,6 +518,7 @@ AST_EXT_LIB_SETUP_OPTIONAL([PJSIP_TLS_TRANSPORT_PROTO], [PJSIP TLS Transport pro
 AST_EXT_LIB_SETUP_OPTIONAL([PJSIP_EVSUB_GRP_LOCK], [PJSIP EVSUB Group Lock support], [PJPROJECT], [pjsip])
 AST_EXT_LIB_SETUP_OPTIONAL([PJSIP_INV_SESSION_REF], [PJSIP INVITE Session Reference Count support], [PJPROJECT], [pjsip])
 AST_EXT_LIB_SETUP_OPTIONAL([PJSIP_AUTH_CLT_DEINIT], [pjsip_auth_clt_deinit support], [PJPROJECT], [pjsip])
+AST_EXT_LIB_SETUP_OPTIONAL([PJSIP_EVSUB_SET_UAS_TIMEOUT], [PJSIP EVSUB Set UAS Timeout support], [PJPROJECT], [pjsip])
 fi
 
 AST_EXT_LIB_SETUP([POPT], [popt], [popt])
@@ -2241,6 +2242,7 @@ if test "$USE_PJPROJECT" != "no" ; then
       AST_EXT_LIB_CHECK([PJSIP_EVSUB_GRP_LOCK], [pjsip], [pjsip_evsub_add_ref], [pjsip.h], [$PJPROJECT_LIB], [$PJPROJECT_CFLAGS])
       AST_EXT_LIB_CHECK([PJSIP_INV_SESSION_REF], [pjsip], [pjsip_inv_add_ref], [pjsip.h], [$PJPROJECT_LIB], [$PJPROJECT_CFLAGS])
       AST_EXT_LIB_CHECK([PJSIP_AUTH_CLT_DEINIT], [pjsip], [pjsip_auth_clt_deinit], [pjsip.h], [$PJPROJECT_LIB], [$PJPROJECT_CFLAGS])
+      AST_EXT_LIB_CHECK([PJSIP_EVSUB_SET_UAS_TIMEOUT], [pjsip], [pjsip_evsub_set_uas_timeout], [pjsip.h], [$PJPROJECT_LIB], [$PJPROJECT_CFLAGS])
    fi
 fi
 

include/asterisk/autoconfig.h.in

@@ -602,6 +602,10 @@
 /* Define to 1 if PJPROJECT has the PJSIP EVSUB Group Lock support feature. */
 #undef HAVE_PJSIP_EVSUB_GRP_LOCK
 
+/* Define to 1 if PJPROJECT has the PJSIP EVSUB Set UAS Timeout support
+   feature. */
+#undef HAVE_PJSIP_EVSUB_SET_UAS_TIMEOUT
+
 /* Define to 1 if PJPROJECT has the PJSIP External Resolver Support feature.
    */
 #undef HAVE_PJSIP_EXTERNAL_RESOLVER

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);

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;
 	}
 

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;
 	}
 

third-party/pjproject/configure.m4

@@ -62,6 +62,7 @@ AC_DEFUN([_PJPROJECT_CONFIGURE],
 	AC_DEFINE([HAVE_PJSIP_EVSUB_GRP_LOCK], 1, [Define if your system has PJSIP_EVSUB_GRP_LOCK])
 	AC_DEFINE([HAVE_PJSIP_INV_SESSION_REF], 1, [Define if your system has PJSIP_INV_SESSION_REF])
 	AC_DEFINE([HAVE_PJSIP_AUTH_CLT_DEINIT], 1, [Define if your system has pjsip_auth_clt_deinit declared.])
+	AC_DEFINE([HAVE_PJSIP_EVSUB_SET_UAS_TIMEOUT], 1, [Define if your system has pjsip_evsub_set_uas_timeout declared.])
 
 	AC_SUBST([PJPROJECT_BUNDLED])
 	AC_SUBST([PJPROJECT_DIR])

third-party/pjproject/patches/0010-evsub-Add-pjsip_evsub_set_uas_timeout.patch

@@ -0,0 +1,84 @@
+From b7af9e6639f29feb4db6d0866c98e552b025ec96 Mon Sep 17 00:00:00 2001
+From: George Joseph <gjoseph@digium.com>
+Date: Mon, 6 Feb 2017 15:39:29 -0700
+Subject: [PATCH] evsub:  Add pjsip_evsub_set_uas_timeout.
+
+A UAS which needs to recreate incoming subscriptions from a persistent
+store can call pjsip_dlg_create_uas_and_inc_lock and
+pjsip_evsub_create_uas as long as they've persisted the
+correct data but since the timer is triggered by an incoming subscribe,
+it's never set and the subscription never expires.
+
+* Add pjsip_evsub_set_uas_timeout which is just a wrapper around
+  evsub.c:set_timeout(sub, TIMER_TYPE_UAS_TIMEOUT, seconds)
+
+* Also, fixed copy-paste error in pjsip_sub_state_hdr_print when
+  printing retry-after parameter.
+---
+ pjsip/include/pjsip-simple/evsub.h | 14 ++++++++++++++
+ pjsip/src/pjsip-simple/evsub.c     | 10 ++++++++++
+ pjsip/src/pjsip-simple/evsub_msg.c |  2 +-
+ 3 files changed, 25 insertions(+), 1 deletion(-)
+
+diff --git a/pjsip/include/pjsip-simple/evsub.h b/pjsip/include/pjsip-simple/evsub.h
+index 82e0a7c..45e6411 100644
+--- a/pjsip/include/pjsip-simple/evsub.h
++++ b/pjsip/include/pjsip-simple/evsub.h
+@@ -511,6 +511,20 @@ PJ_DEF(pj_status_t) pjsip_evsub_add_ref(pjsip_evsub *sub);
+ PJ_DEF(pj_status_t) pjsip_evsub_dec_ref(pjsip_evsub *sub);
+ 
+ 
++/**
++ * Sets, resets or cancels the UAS subscription timeout.
++ *
++ * If there is an existing timer, it is cancelled before any
++ * other action.
++ *
++ * A timeout of 0 is ignored except that any existing timer
++ * is cancelled.
++ *
++ * @param sub           The server subscription instance.
++ * @param seconds       The new timeout.
++ */
++PJ_DEF(void) pjsip_evsub_set_uas_timeout(pjsip_evsub *sub, pj_int32_t seconds);
++
+ 
+ PJ_END_DECL
+ 
+diff --git a/pjsip/src/pjsip-simple/evsub.c b/pjsip/src/pjsip-simple/evsub.c
+index 3fe4b49..6918a8c 100644
+--- a/pjsip/src/pjsip-simple/evsub.c
++++ b/pjsip/src/pjsip-simple/evsub.c
+@@ -530,6 +530,16 @@ static void set_timer( pjsip_evsub *sub, int timer_id,
+ 
+ 
+ /*
++ * Set event subscription UAS timout.
++ */
++PJ_DEF(void) pjsip_evsub_set_uas_timeout(pjsip_evsub *sub, pj_int32_t seconds)
++{
++    PJ_ASSERT_RETURN(sub != NULL, PJ_EINVAL);
++    set_timer(sub, TIMER_TYPE_UAS_TIMEOUT, seconds);
++}
++
++
++/*
+  * Destructor.
+  */
+ static void evsub_on_destroy(void *obj)
+diff --git a/pjsip/src/pjsip-simple/evsub_msg.c b/pjsip/src/pjsip-simple/evsub_msg.c
+index b44a715..b37db1c 100644
+--- a/pjsip/src/pjsip-simple/evsub_msg.c
++++ b/pjsip/src/pjsip-simple/evsub_msg.c
+@@ -179,7 +179,7 @@ static int pjsip_sub_state_hdr_print(pjsip_sub_state_hdr *hdr,
+     }
+     if (hdr->retry_after >= 0) {
+ 	pj_memcpy(p, ";retry-after=", 13);
+-	p += 9;
++	p += 13;
+ 	printed = pj_utoa(hdr->retry_after, p);
+ 	p += printed;
+     }
+-- 
+2.9.3
+