TEL-6872: Cherry-pick JB statistics race condition fix from SignalWire PR signalwire#2337

Consolidate inline channel variable exports from the jitter buffer hot
path into switch_jb_export_stats(), called at hangup before hangup
hooks run (via switch_core_media_export_jb_stats) and as a safety net
before every switch_jb_destroy() in both switch_rtp_destroy() and the
KILL_JB path in read_rtp_packet().

This prevents a race condition where hangup hooks read stale/missing
JB stats because the jitter buffer was already destroyed or the inline
exports hadn't run recently enough.

Adapted from upstream commit 0388398 — excluded
fast_acceleration, forced_acceleration, and packets_in_buffer fields
which don't exist in our switch_jb struct.

Cherry-picked from signalwire#2337 (Julien Chavanton).

Author: dev-ryanc

src/include/switch_core_media.h

@@ -352,6 +352,7 @@ SWITCH_DECLARE(void) switch_core_media_resume(switch_core_session_t *session);
 SWITCH_DECLARE(void) switch_core_media_init(void);
 SWITCH_DECLARE(void) switch_core_media_deinit(void);
 SWITCH_DECLARE(void) switch_core_media_set_stats(switch_core_session_t *session);
+SWITCH_DECLARE(void) switch_core_media_export_jb_stats(switch_core_session_t *session);
 SWITCH_DECLARE(void) switch_core_media_sync_stats(switch_core_session_t *session);
 SWITCH_DECLARE(void) switch_core_session_wake_video_thread(switch_core_session_t *session);
 SWITCH_DECLARE(void) switch_core_session_clear_crypto(switch_core_session_t *session);

src/include/switch_jitterbuffer.h

@@ -67,6 +67,7 @@ SWITCH_DECLARE(void) switch_jb_set_flag(switch_jb_t *jb, switch_jb_flag_t flag);
 SWITCH_DECLARE(void) switch_jb_clear_flag(switch_jb_t *jb, switch_jb_flag_t flag);
 SWITCH_DECLARE(uint32_t) switch_jb_get_nack_success(switch_jb_t *jb);
 SWITCH_DECLARE(uint32_t) switch_jb_get_packets_per_frame(switch_jb_t *jb);
+SWITCH_DECLARE(void) switch_jb_export_stats(switch_jb_t *jb);
 
 SWITCH_END_EXTERN_C
 #endif

src/include/switch_rtp.h

@@ -552,6 +552,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_debug_jitter_buffer(switch_rtp_t *rtp
 SWITCH_DECLARE(switch_status_t) switch_rtp_deactivate_jitter_buffer(switch_rtp_t *rtp_session);
 SWITCH_DECLARE(switch_status_t) switch_rtp_pause_jitter_buffer(switch_rtp_t *rtp_session, switch_bool_t pause);
 SWITCH_DECLARE(switch_jb_t *) switch_rtp_get_jitter_buffer(switch_rtp_t *rtp_session);
+SWITCH_DECLARE(switch_jb_t *) switch_rtp_get_jitter_buffer_for_stats(switch_rtp_t *rtp_session);
 
 
 

src/switch_core_media.c

@@ -2553,13 +2553,66 @@ SWITCH_DECLARE(void) switch_core_media_sync_stats(switch_core_session_t *session
 
 }
 
+static void set_jb_stats(switch_core_session_t *session, switch_media_type_t type)
+{
+	switch_media_handle_t *smh;
+	switch_rtp_engine_t *engine;
+	switch_jb_t *jb;
+	const char *type_str = (type == SWITCH_MEDIA_TYPE_AUDIO) ? "audio" :
+	                       (type == SWITCH_MEDIA_TYPE_VIDEO) ? "video" : "text";
+
+	if (!(smh = session->media_handle)) {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+			"set_jb_stats(%s): no media handle\n", type_str);
+		return;
+	}
+
+	engine = &smh->engines[type];
+	if (!engine->rtp_session) {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+			"set_jb_stats(%s): no rtp_session\n", type_str);
+		return;
+	}
+
+	/* Use _for_stats variant which bypasses switch_rtp_ready() check
+	 * since RTP session may not be "ready" during hangup but JB still exists */
+	jb = switch_rtp_get_jitter_buffer_for_stats(engine->rtp_session);
+	if (jb) {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO,
+			"set_jb_stats(%s): exporting JB stats\n", type_str);
+		switch_jb_export_stats(jb);
+	} else {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO,
+			"set_jb_stats(%s): no jitter buffer\n", type_str);
+	}
+}
+
+SWITCH_DECLARE(void) switch_core_media_export_jb_stats(switch_core_session_t *session)
+{
+	if (!session->media_handle) {
+		return;
+	}
+
+	switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO,
+		"switch_core_media_export_jb_stats() exporting JB stats before hangup handlers\n");
+
+	/* Export jitter buffer stats so they're available in hangup hooks */
+	set_jb_stats(session, SWITCH_MEDIA_TYPE_AUDIO);
+	set_jb_stats(session, SWITCH_MEDIA_TYPE_VIDEO);
+	set_jb_stats(session, SWITCH_MEDIA_TYPE_TEXT);
+}
+
 SWITCH_DECLARE(void) switch_core_media_set_stats(switch_core_session_t *session)
 {
+	switch_channel_t *channel = switch_core_session_get_channel(session);
 
 	if (!session->media_handle) {
 		return;
 	}
 
+	switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO,
+		"[%s] switch_core_media_set_stats() called\n", switch_channel_get_name(channel));
+
 	switch_core_media_sync_stats(session);
 
 	set_stats(session, SWITCH_MEDIA_TYPE_AUDIO, "audio");

src/switch_core_state_machine.c

@@ -881,6 +881,9 @@ SWITCH_DECLARE(void) switch_core_session_hangup_state(switch_core_session_t *ses
 	switch_channel_set_timestamps(session->channel);
 	switch_channel_set_callstate(session->channel, CCS_HANGUP);
 
+	/* Export JB stats before hangup handlers run, while JB still exists */
+	switch_core_media_export_jb_stats(session);
+
 	STATE_MACRO(hangup, "HANGUP");
 
 	switch_core_media_set_stats(session);

src/switch_jitterbuffer.c

@@ -983,24 +983,11 @@ static inline int check_jb_size(switch_jb_t *jb)
 
 	/* update the stats every x packets */
 	if (target_seq_hs % 50 == 0) {
-		int packet_ms = jb->jitter.samples_per_frame / (jb->jitter.samples_per_second / 1000);
-
 		jb->jitter.stats.estimate_ms = (*jb->jitter.estimate) / jb->jitter.samples_per_second * 1000;
-		if (jb->channel) {
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_max_ms", "%u", jb->jitter.stats.size_max * packet_ms);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_est_ms", "%u", jb->jitter.stats.size_est * packet_ms);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_acceleration_ms", "%u", jb->jitter.stats.acceleration * packet_ms);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_ms", "%u", jb->jitter.stats.expand * packet_ms);
-		}
 
 		if (jb->jitter.stats.jitter_max_ms < jb->jitter.stats.estimate_ms) {
 			jb->jitter.stats.jitter_max_ms = jb->jitter.stats.estimate_ms;
 		}
-
-		if (jb->channel) {
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_max_ms", "%u", jb->jitter.stats.jitter_max_ms);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_est_ms", "%u", jb->jitter.stats.estimate_ms);
-		}
 	}
 
 	if (old) {
@@ -1102,19 +1089,6 @@ SWITCH_DECLARE(void) switch_jb_set_jitter_estimator(switch_jb_t *jb, double *jit
 {
 	if (jb && jitter) {
 		memset(&jb->jitter, 0, sizeof(switch_jb_jitter_t));
-		if (jb->channel) {
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_max_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_acceleration_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_max_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_ms", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_count", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_big", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_missing_frames", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_ts_jump", "%u", 0);
-			switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_error", "%u", 0);
-		}
 
 		jb->jitter.estimate = jitter;
 		jb->jitter.samples_per_frame = samples_per_frame;
@@ -1197,14 +1171,6 @@ SWITCH_DECLARE(void) switch_jb_reset(switch_jb_t *jb)
 {
 	jb->jitter.stats.reset++;
 	jb->jitter.stats.expand_frame_len = 0;
-	if (jb->channel) {
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_count", "%u", jb->jitter.stats.reset);
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_big", "%u", jb->jitter.stats.reset_too_big);
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_expanded", "%u", jb->jitter.stats.reset_too_expanded);
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_missing_frames", "%u", jb->jitter.stats.reset_missing_frames);
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_ts_jump", "%u", jb->jitter.stats.reset_ts_jump);
-		switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_error", "%u", jb->jitter.stats.reset_error);
-	}
 
 	if (jb->type == SJB_VIDEO) {
 		switch_mutex_lock(jb->mutex);
@@ -1378,6 +1344,87 @@ SWITCH_DECLARE(switch_status_t) switch_jb_create(switch_jb_t **jbp, switch_jb_ty
 	return SWITCH_STATUS_SUCCESS;
 }
 
+SWITCH_DECLARE(void) switch_jb_export_stats(switch_jb_t *jb)
+{
+	int packet_ms = 0;
+
+	if (!jb || !jb->channel) {
+		return;
+	}
+
+	switch_mutex_lock(jb->mutex);
+
+	switch_log_printf(SWITCH_CHANNEL_CHANNEL_LOG(jb->channel), SWITCH_LOG_INFO,
+		"switch_jb_export_stats: type=%s elastic=%s reset_count=%u\n",
+		jb->type == SJB_VIDEO ? "video" : (jb->type == SJB_AUDIO ? "audio" : "text"),
+		jb->elastic ? "true" : "false",
+		jb->jitter.stats.reset);
+
+	/* Export jitter buffer configuration */
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_type", "%s",
+		jb->type == SJB_VIDEO ? "video" : (jb->type == SJB_AUDIO ? "audio" : "text"));
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_min_frame_len", "%u", jb->min_frame_len);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_max_frame_len", "%u", jb->max_frame_len);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_cur_frame_len", "%u", jb->frame_len);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_highest_frame_len", "%u", jb->highest_frame_len);
+
+	/* Export buffer state */
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_visible_nodes", "%u", jb->visible_nodes);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_allocated_nodes", "%u", jb->allocated_nodes);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_complete_frames", "%u", jb->complete_frames);
+
+	/* Export miss/hit statistics */
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_period_miss_count", "%u", jb->period_miss_count);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_consec_miss_count", "%u", jb->consec_miss_count);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_period_good_count", "%u", jb->period_good_count);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_consec_good_count", "%u", jb->consec_good_count);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_period_miss_pct", "%.2f", jb->period_miss_pct);
+
+	/* Export jitter estimator statistics */
+	if (jb->jitter.samples_per_frame && jb->jitter.samples_per_second) {
+		packet_ms = jb->jitter.samples_per_frame / (jb->jitter.samples_per_second / 1000);
+	}
+
+	if (jb->jitter.estimate && jb->jitter.samples_per_second) {
+		jb->jitter.stats.estimate_ms = (*jb->jitter.estimate) / jb->jitter.samples_per_second * 1000;
+	}
+
+	if (packet_ms) {
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_max_ms", "%u", jb->jitter.stats.size_max * packet_ms);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_size_est_ms", "%u", jb->jitter.stats.size_est * packet_ms);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_acceleration_ms", "%u", jb->jitter.stats.acceleration * packet_ms);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_ms", "%u", jb->jitter.stats.expand * packet_ms);
+	}
+
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_max_ms", "%u", jb->jitter.stats.jitter_max_ms);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_jitter_est_ms", "%u", jb->jitter.stats.estimate_ms);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffer_size_ms", "%u", jb->jitter.stats.buffer_size_ms);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_expand_frame_len", "%d", jb->jitter.stats.expand_frame_len);
+
+	/* Export reset statistics */
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_count", "%u", jb->jitter.stats.reset);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_big", "%u", jb->jitter.stats.reset_too_big);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_too_expanded", "%u", jb->jitter.stats.reset_too_expanded);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_missing_frames", "%u", jb->jitter.stats.reset_missing_frames);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_ts_jump", "%u", jb->jitter.stats.reset_ts_jump);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_reset_error", "%u", jb->jitter.stats.reset_error);
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_consecutive_miss", "%u", jb->jitter.stats.consecutive_miss);
+
+	/* Export video-specific statistics */
+	if (jb->type == SJB_VIDEO) {
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_nack_saved_the_day", "%u", jb->nack_saved_the_day);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_nack_didnt_save_the_day", "%u", jb->nack_didnt_save_the_day);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_max_packet_len", "%u", jb->max_packet_len);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_packet_count", "%u", jb->packet_count);
+	}
+
+	/* Export elastic buffer info */
+	switch_channel_set_variable_printf(jb->channel, "rtp_jb_elastic", "%s", jb->elastic ? "true" : "false");
+
+	switch_mutex_unlock(jb->mutex);
+}
+
 SWITCH_DECLARE(switch_status_t) switch_jb_destroy(switch_jb_t **jbp)
 {
 	switch_jb_t *jb = *jbp;

src/switch_rtp.c

@@ -5872,6 +5872,17 @@ SWITCH_DECLARE(switch_jb_t *) switch_rtp_get_jitter_buffer(switch_rtp_t *rtp_ses
 	return rtp_session->jb ? rtp_session->jb : rtp_session->vb;
 }
 
+SWITCH_DECLARE(switch_jb_t *) switch_rtp_get_jitter_buffer_for_stats(switch_rtp_t *rtp_session)
+{
+	/* Bypass ready check - used for stats export during shutdown
+	 * when rtp_session may not be "ready" but JB still exists */
+	if (!rtp_session) {
+		return NULL;
+	}
+
+	return rtp_session->jb ? rtp_session->jb : rtp_session->vb;
+}
+
 SWITCH_DECLARE(switch_status_t) switch_rtp_pause_jitter_buffer(switch_rtp_t *rtp_session, switch_bool_t pause)
 {
 	int new_val;
@@ -6399,15 +6410,19 @@ SWITCH_DECLARE(void) switch_rtp_destroy(switch_rtp_t **rtp_session)
 		switch_safe_free(pop);
 	}
 
+	/* Export jitter buffer stats before destroying them */
 	if ((*rtp_session)->jb) {
+		switch_jb_export_stats((*rtp_session)->jb);
 		switch_jb_destroy(&(*rtp_session)->jb);
 	}
 
 	if ((*rtp_session)->vb) {
+		switch_jb_export_stats((*rtp_session)->vb);
 		switch_jb_destroy(&(*rtp_session)->vb);
 	}
 
 	if ((*rtp_session)->vbw) {
+		switch_jb_export_stats((*rtp_session)->vbw);
 		switch_jb_destroy(&(*rtp_session)->vbw);
 	}
 
@@ -7865,15 +7880,19 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t
 	if (rtp_session->flags[SWITCH_RTP_FLAG_KILL_JB]) {
 		rtp_session->flags[SWITCH_RTP_FLAG_KILL_JB] = 0;
 
+		/* Export jitter buffer stats before destroying them */
 		if (rtp_session->jb) {
+			switch_jb_export_stats(rtp_session->jb);
 			switch_jb_destroy(&rtp_session->jb);
 		}
 
 		if (rtp_session->vb) {
+			switch_jb_export_stats(rtp_session->vb);
 			switch_jb_destroy(&rtp_session->vb);
 		}
 
 		if (rtp_session->vbw) {
+			switch_jb_export_stats(rtp_session->vbw);
 			switch_jb_destroy(&rtp_session->vbw);
 		}