[asterisk-commits] res pjsip pubsub: Correctly implement persisted subscriptions (asterisk[master])

SVN commits to the Asterisk project asterisk-commits at lists.digium.com
Thu Feb 16 09:48:53 CST 2017


Joshua Colp has submitted this change and it was merged. ( https://gerrit.asterisk.org/4918 )

Change subject: res_pjsip_pubsub:  Correctly implement persisted subscriptions
......................................................................


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
---
M configure
M configure.ac
M include/asterisk/autoconfig.h.in
M res/res_pjsip/pjsip_scheduler.c
M res/res_pjsip_exten_state.c
M res/res_pjsip_pubsub.c
M third-party/pjproject/configure.m4
A third-party/pjproject/patches/0010-evsub-Add-pjsip_evsub_set_uas_timeout.patch
8 files changed, 420 insertions(+), 62 deletions(-)

Approvals:
  Richard Mudgett: Looks good to me, but someone else must approve
  Anonymous Coward #1000019: Verified
  Joshua Colp: Looks good to me, approved



diff --git a/configure b/configure
index 7e72074..2b25ead 100755
--- a/configure
+++ b/configure
@@ -943,6 +943,10 @@
 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_AUTH_CLT_DEINIT 1" >>confdefs.h
 
 
+$as_echo "#define HAVE_PJSIP_EVSUB_SET_UAS_TIMEOUT 1" >>confdefs.h
+
+
 
 
 
@@ -11587,6 +11594,18 @@
 PJSIP_AUTH_CLT_DEINIT_DIR=${PJPROJECT_DIR}
 
 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
 
 
 
@@ -26705,6 +26724,110 @@
 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
 
diff --git a/configure.ac b/configure.ac
index d604d47..63d2b41 100644
--- a/configure.ac
+++ b/configure.ac
@@ -518,6 +518,7 @@
 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 @@
       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
 
diff --git a/include/asterisk/autoconfig.h.in b/include/asterisk/autoconfig.h.in
index e8bd811..41ba613 100644
--- a/include/asterisk/autoconfig.h.in
+++ b/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
diff --git a/res/res_pjsip/pjsip_scheduler.c b/res/res_pjsip/pjsip_scheduler.c
index 27202c6..e4459da 100644
--- a/res/res_pjsip/pjsip_scheduler.c
+++ b/res/res_pjsip/pjsip_scheduler.c
@@ -373,7 +373,7 @@
 	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 @@
 
 	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 @@
 			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 9bb53bf..95a4082 100644
--- a/res/res_pjsip_exten_state.c
+++ b/res/res_pjsip_exten_state.c
@@ -415,8 +415,9 @@
 	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 42f0dc1..709dc66 100644
--- a/res/res_pjsip_pubsub.c
+++ b/res/res_pjsip_pubsub.c
@@ -392,6 +392,13 @@
 	SIP_SUB_TREE_TERMINATED,
 };
 
+static char *sub_tree_state_description[] = {
+	"Normal",
+	"TerminatePending",
+	"TerminateInProgress",
+	"Terminated"
+};
+
 /*!
  * \brief A tree of SIP subscriptions
  *
@@ -428,6 +435,11 @@
 	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;
 };
 
 /*!
@@ -480,6 +492,17 @@
 static const char *sip_subscription_roles_map[] = {
 	[AST_SIP_SUBSCRIBER] = "Subscriber",
 	[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);
@@ -560,13 +583,16 @@
 
 /*! \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;
 
 	if (!sub_tree->persistence) {
 		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 @@
 		 * 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 @@
 	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 @@
 		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 @@
 		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 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 @@
 {
 	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 @@
 
 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 @@
 		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);
@@ -1344,6 +1379,12 @@
 
 	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 @@
 		}
 		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 @@
 				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 @@
 
 	/* 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 @@
 
 	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 @@
 	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);
 	}
 
-	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 @@
 			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 @@
  *           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 @@
  *     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,23 +3507,39 @@
  *
  * 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);
@@ -3443,16 +3563,17 @@
 	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 @@
 				"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,9 +3621,21 @@
 	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
@@ -3499,6 +3645,8 @@
 	if (pjsip_evsub_get_state(sub_tree->evsub) == PJSIP_EVSUB_STATE_TERMINATED) {
 		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. */
@@ -3577,7 +3725,6 @@
 
 	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;
 	}
 
diff --git a/third-party/pjproject/configure.m4 b/third-party/pjproject/configure.m4
index 8294d8e..d5c8531 100644
--- a/third-party/pjproject/configure.m4
+++ b/third-party/pjproject/configure.m4
@@ -62,6 +62,7 @@
 	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])
diff --git a/third-party/pjproject/patches/0010-evsub-Add-pjsip_evsub_set_uas_timeout.patch b/third-party/pjproject/patches/0010-evsub-Add-pjsip_evsub_set_uas_timeout.patch
new file mode 100644
index 0000000..a55aa00
--- /dev/null
+++ b/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 at 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
+

-- 
To view, visit https://gerrit.asterisk.org/4918
To unsubscribe, visit https://gerrit.asterisk.org/settings

Gerrit-MessageType: merged
Gerrit-Change-Id: I8c605fc1e3923f466a74db087d5ab6f90abce68e
Gerrit-PatchSet: 9
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Owner: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Anonymous Coward #1000019
Gerrit-Reviewer: Joshua Colp <jcolp at digium.com>
Gerrit-Reviewer: Mark Michelson <mmichelson at digium.com>
Gerrit-Reviewer: Richard Mudgett <rmudgett at digium.com>



More information about the asterisk-commits mailing list