Merge "res_pjsip_pubsub: Correctly implement persisted subscriptions"

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)) {
+		ast_localtime(&next, &tm, NULL);
-			if (ast_tvzero(schtd->last_start)) {
+		ast_strftime(next_start, sizeof(next_start), log_format, &tm);
-				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_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",
+			schtd->is_running ? "run" : "wait",
-			datelen, queued, last_start, last_end);
+			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",
+		ast_log(LOG_NOTICE, "Endpoint '%s' state subscription failed: "
-			resource, context);
+			"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) {
+		if (type == SUBSCRIPTION_PERSISTENCE_CREATED
-			ast_copy_string(sub_tree->persistence->packet, rdata->msg_info.msg_buf,
+			|| type == SUBSCRIPTION_PERSISTENCE_RECREATED) {
-					MIN(sizeof(sub_tree->persistence->packet), rdata->msg_info.len));
+			if (rdata->msg_info.msg_buf) {
-		} else {
+				ast_copy_string(sub_tree->persistence->packet, rdata->msg_info.msg_buf,
-			ast_copy_string(sub_tree->persistence->packet, rdata->pkt_info.packet,
+						MIN(sizeof(sub_tree->persistence->packet), rdata->msg_info.len));
-					sizeof(sub_tree->persistence->packet));
+			} 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_debug(2, "Removing subscription '%s->%s' from list of subscriptions\n",
-						ast_sip_subscription_get_resource_name(i->root));
+					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);
+			subscription_persistence_update(sub_tree, rdata, SUBSCRIPTION_PERSISTENCE_RECREATED);
-			if (ast_sip_push_task(sub_tree->serializer, initial_notify_task,
+			if (ast_sip_push_task(sub_tree->serializer, initial_notify_task, ind)) {
-				ao2_bump(sub_tree))) {
 				/* 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(ind->sub_tree->root)) {
-	if (generate_initial_notify(sub_tree->root)) {
+		pjsip_evsub_terminate(ind->sub_tree->evsub, PJ_TRUE);
-		pjsip_evsub_terminate(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);
 	}
 
-	ao2_ref(sub_tree, -1);
+	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(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
+ * notify (SIP_SUB_TREE_TERMINATE_IN_PROGRESS) OR when a transmission failure
- * the subscription tree cleanup tasks and decrement the evsub reference.
+ * 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);
+	/* It's easier to write this as what we WANT to process, then negate it. */
-	if (!sub_tree || sub_tree->state != SIP_SUB_TREE_TERMINATE_IN_PROGRESS) {
+	if (!(sub_tree->state == SIP_SUB_TREE_TERMINATE_IN_PROGRESS
-		ast_debug(1, "Possible terminate race prevented %p\n", sub_tree);
+		|| (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
+