Merge 52ca18f49d into 3b58ebc5f3

We observed that the new Poly phones (formerly known as Polycom) were not getting sent a SIP UPDATE in certain circumstances (example: retrieving a parked call, and therefore, Caller ID would not show the parked caller). I renamed Polycom to Poly which will catch all Poly AND Polycom UA's. I also added Acrobits, and Ringotel to extend such functionality to those UA's. There were also other minor compatibility issues with the new Poly phones which have been resolved with tweaking the UA recognition on the code.

Co-authored-by: Joseph <junction1153@gmail.com>

src/include/private/switch_core_pvt.h

@@ -170,6 +170,8 @@ struct switch_core_session {
 	switch_buffer_t *text_line_buffer;
 	switch_mutex_t *text_mutex;
 	const char *external_id;
+
+	packet_stats_t stats;
 };
 
 struct switch_media_bug {

src/include/switch_core.h

@@ -90,6 +90,30 @@ typedef struct device_uuid_node_s {
 	struct device_uuid_node_s *next;
 } switch_device_node_t;
 
+typedef struct packet_stats_io_info {
+	const char* in_callid;
+	char* in_codec;
+	uint32_t in_ssrc;
+	switch_sockaddr_t *in_remote_addr;
+	switch_sockaddr_t *in_local_addr;
+	const char* out_callid;
+	char* out_codec;
+	uint32_t out_ssrc;
+	switch_sockaddr_t *out_remote_addr;
+	switch_sockaddr_t *out_local_addr;
+	uint32_t count; // count of packets going out
+} packet_stats_io_info_t;
+
+typedef struct packet_stats {
+	int max;
+	float average;
+	uint32_t in_count;
+	uint32_t in_plc;
+	uint32_t count;
+	packet_stats_io_info_t io_info;
+	switch_bool_t reported;
+} packet_stats_t;
+
 typedef struct switch_device_stats_s {
 	uint32_t total;
 	uint32_t total_in;
@@ -255,6 +279,10 @@ static inline void *switch_must_realloc(void *_b, size_t _z)
 ///\{
 
 
+SWITCH_DECLARE(void) switch_core_session_increment_read(switch_core_session_t *session);
+SWITCH_DECLARE(void) switch_core_session_increment_plc(switch_core_session_t *session);
+SWITCH_DECLARE(void) packet_stats_print(switch_core_session_t *session);
+SWITCH_DECLARE(void) switch_core_session_set_io_stats(switch_core_session_t *session, packet_stats_io_info_t *packet_stats_io_info);
 SWITCH_DECLARE(void) switch_core_screen_size(int *x, int *y);
 SWITCH_DECLARE(void) switch_core_session_sched_heartbeat(switch_core_session_t *session, uint32_t seconds);
 SWITCH_DECLARE(void) switch_core_session_unsched_heartbeat(switch_core_session_t *session);

src/include/switch_frame.h

@@ -87,6 +87,7 @@ typedef struct switch_frame_geometry {
 	payload_map_t *pmap;
 	switch_image_t *img;
 	struct switch_frame_geometry geometry;
+	switch_time_t received_ts;
 };
 
 SWITCH_END_EXTERN_C

src/include/switch_rtp.h

@@ -57,6 +57,7 @@ typedef struct {
 	char body[SWITCH_RTP_MAX_BUF_LEN+4+sizeof(char *)];
 	switch_rtp_hdr_ext_t *ext;
 	char *ebody;
+	switch_time_t received_ts;
 } switch_rtp_packet_t;
 
 typedef enum {

src/mod/endpoints/mod_sofia/mod_sofia.c

@@ -254,7 +254,7 @@ char *generate_pai_str(private_object_t *tech_pvt)
 	callee_number = switch_sanitize_number(switch_core_session_strdup(session, callee_number));
 	callee_name = switch_sanitize_number(switch_core_session_strdup(session, callee_name));
 
-	if (!zstr(callee_number) && (zstr(ua) || !switch_stristr("polycom", ua))) {
+	if (!zstr(callee_number) && (zstr(ua) || !switch_stristr("poly", ua))) {
 		callee_number = switch_core_session_sprintf(session, "sip:%s@%s", callee_number, host);
 	}
 
@@ -2075,13 +2075,15 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi
 							nua_info(tech_pvt->nh, SIPTAG_CONTENT_TYPE_STR("message/sipfrag"),
 									 TAG_IF(!zstr(tech_pvt->user_via), SIPTAG_VIA_STR(tech_pvt->user_via)), SIPTAG_PAYLOAD_STR(message), TAG_END());
 						} else if (update_allowed && ua && (switch_channel_var_true(tech_pvt->channel, "update_ignore_ua") ||
-									  switch_stristr("polycom", ua) ||
+									  switch_stristr("poly", ua) ||
 									  (switch_stristr("aastra", ua) && !switch_stristr("Intelligate", ua)) ||
 									  (switch_stristr("cisco/spa50", ua) ||
 									  switch_stristr("cisco/spa525", ua)) ||
 									  switch_stristr("cisco/spa30", ua) ||
 									  switch_stristr("Fanvil", ua) ||
 									  switch_stristr("Grandstream", ua) ||
+									  switch_stristr("Ringotel", ua) ||
+									  switch_stristr("Groundwire", ua) ||									  
 									  switch_stristr("Yealink", ua) ||
 									  switch_stristr("Mitel", ua) ||
 									  switch_stristr("Panasonic", ua))) {
@@ -2152,7 +2154,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi
 								 SIPTAG_PAYLOAD_STR(message),
 								 TAG_IF(!zstr(session_id_header), SIPTAG_HEADER_STR(session_id_header)),
 								 TAG_END());
-					} else if (ua && switch_stristr("polycom", ua)) {
+					} else if (ua && switch_stristr("poly", ua)) {
 						snprintf(message, sizeof(message), "P-Asserted-Identity: \"%s\" <%s>", msg->string_arg, tech_pvt->caller_profile->destination_number);
 						nua_update(tech_pvt->nh,
 								   NUTAG_SESSION_TIMER(tech_pvt->session_timeout),

src/mod/endpoints/mod_sofia/sofia.c

@@ -10476,7 +10476,7 @@ void sofia_handle_sip_i_invite(switch_core_session_t *session, nua_t *nua, sofia
 		(!is_tcp && !is_tls && (zstr(network_ip) || !switch_check_network_list_ip(network_ip, profile->local_network)) &&
 		 profile->server_rport_level >= 2 && sip->sip_user_agent &&
 		 sip->sip_user_agent->g_string &&
-		 (!strncasecmp(sip->sip_user_agent->g_string, "Polycom", 7) || !strncasecmp(sip->sip_user_agent->g_string, "KIRK Wireless Server", 20)))
+		 (!strncasecmp(sip->sip_user_agent->g_string, "Poly", 4) || !strncasecmp(sip->sip_user_agent->g_string, "KIRK Wireless Server", 20)))
 		) {
 		if (sip->sip_via) {
 			const char *port = sip->sip_via->v_port;

src/mod/endpoints/mod_sofia/sofia_presence.c

@@ -2501,7 +2501,7 @@ static char *gen_pidf(char *user_agent, char *id, char *url, char *open, char *r
 {
 	char *ret = NULL;
 
-	if (switch_stristr("polycom", user_agent)) {
+	if (switch_stristr("poly", user_agent)) {
 		*ct = "application/xpidf+xml";
 
 		/* If unknown/none prpid is provided, just show the user as online. */

src/mod/endpoints/mod_sofia/sofia_reg.c

@@ -1661,7 +1661,7 @@ uint8_t sofia_reg_handle_register_token(nua_t *nua, sofia_profile_t *profile, nu
 			if (!is_tcp && !is_tls && (zstr(network_ip) || !switch_check_network_list_ip(network_ip, profile->local_network)) &&
 				profile->server_rport_level >= 2 && sip->sip_user_agent &&
 				sip->sip_user_agent->g_string &&
-				( !strncasecmp(sip->sip_user_agent->g_string, "Polycom", 7) ||
+				( !strncasecmp(sip->sip_user_agent->g_string, "Poly", 4) ||
 				  !strncasecmp(sip->sip_user_agent->g_string, "KIRK Wireless Server", 20) ||
 				  !strncasecmp(sip->sip_user_agent->g_string, "ADTRAN_Total_Access", 19) )) {
 				if (sip->sip_via) {

src/mod/languages/mod_lua/mod_lua_wrap.cpp

@@ -10744,6 +10744,9 @@ SWIG_PropagateClientData(void) {
           if (equiv->type && !equiv->type->clientdata)
             SWIG_TypeClientData(equiv->type, swig_module.types[i]->clientdata);
         }
+        if (equiv == equiv->next) {
+            break;
+        }
         equiv = equiv->next;
       }
     }

src/switch_core_media.c

@@ -35,6 +35,7 @@
 #include <switch_stun.h>
 #include <switch_nat.h>
 #include "private/switch_core_pvt.h"
+#include <fspr_network_io.h>
 #include <switch_curl.h>
 #include <errno.h>
 #include <sofia-sip/sdp.h>
@@ -274,6 +275,71 @@ struct switch_media_handle_s {
 
 };
 
+void packet_stats_init(packet_stats_t *stats, int latency, int count) {
+	stats->max = latency;
+	stats->average = latency;
+	stats->count = count;
+}
+#define _VOR1(v) ((v)?(v):1)
+void packet_stats_update(packet_stats_t *stats, int latency)
+{
+	if (stats->count >= UINT32_MAX)
+		return;
+	stats->count++;
+
+	if (stats->count == 1)
+		packet_stats_init(stats, latency, 1);
+	if (stats->max < latency)
+		stats->max = latency;
+
+	if (stats->count > 1) {
+		float delta;
+		delta = latency - stats->average;
+		stats->average += delta/_VOR1(stats->count);
+	}
+}
+
+void packet_stats_print(switch_core_session_t *session) {
+	if (session->stats.io_info.in_remote_addr && session->stats.io_info.out_local_addr
+		       && !session->stats.reported) {
+		char in_ipbuf[48];
+		char in_l_ipbuf[48];
+		char out_ipbuf[48];
+		char out_l_ipbuf[48];
+		const char *v=NULL;
+
+		switch_channel_set_variable_printf(session->channel, "packet_stats_report",
+			"{"
+			"\"in\" : { \"ssrc\": \"0x%08X\", \"remote_socket\": \"%s:%u\", \"local_socket\": \"%s:%u\""
+			", \"codec\": \"%s\", \"count\": %u, \"plc\": %u}"
+			","
+			"\"out\" : { \"ssrc\": \"0x%08X\", \"remote_socket\": \"%s:%u\", \"local_socket\": \"%s:%u\""
+			", \"codec\": \"%s\", \"count\": %u, \"max\": %d, \"avg\": %.2f }}",
+			session->stats.io_info.in_ssrc,
+               switch_get_addr(in_ipbuf, sizeof(in_ipbuf), session->stats.io_info.in_remote_addr),
+               session->stats.io_info.in_remote_addr->port,
+               switch_get_addr(in_l_ipbuf, sizeof(in_ipbuf), session->stats.io_info.in_local_addr),
+               session->stats.io_info.in_local_addr->port,
+			session->stats.io_info.in_codec,
+			session->stats.in_count,
+			session->stats.in_plc,
+			session->stats.io_info.out_ssrc,
+               switch_get_addr(out_ipbuf, sizeof(out_ipbuf), session->stats.io_info.out_remote_addr),
+               session->stats.io_info.out_local_addr->port,
+               switch_get_addr(out_l_ipbuf, sizeof(out_ipbuf), session->stats.io_info.out_local_addr),
+               session->stats.io_info.out_remote_addr->port,
+			session->stats.io_info.out_codec,
+			session->stats.count,
+			session->stats.max,
+			session->stats.average
+		);
+		v = switch_channel_get_variable_dup(session->channel,"packet_stats_report", SWITCH_FALSE, -1);
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "[packet_stats_report] %s\n", v);
+		session->stats.reported = true;
+
+	}
+}
+
 switch_srtp_crypto_suite_t SUITES[CRYPTO_INVALID] = {
 	{ "AEAD_AES_256_GCM_8", "", AEAD_AES_256_GCM_8, 44, 12},
 	{ "AEAD_AES_256_GCM", "", AEAD_AES_256_GCM, 44, 12},
@@ -15800,7 +15866,6 @@ SWITCH_DECLARE(switch_msrp_session_t *) switch_core_media_get_msrp_session(switc
 	return session->media_handle->msrp_session;
 }
 
-
 SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_session_t *session, switch_frame_t *frame, switch_io_flag_t flags,
 																int stream_id)
 {
@@ -16159,6 +16224,7 @@ SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_sess
 		goto done;
 	}
 
+	write_frame->received_ts = frame->received_ts;
 	if (session->write_codec) {
 		if (!ptime_mismatch && write_frame->codec && write_frame->codec->implementation &&
 			write_frame->codec->implementation->decoded_bytes_per_packet == session->write_impl.decoded_bytes_per_packet) {
@@ -16434,6 +16500,16 @@ SWITCH_DECLARE(switch_status_t) switch_core_session_write_frame(switch_core_sess
 	}
 
   error:
+	if (frame->received_ts > 0) {
+		int64_t d = (switch_micro_time_now() - frame->received_ts)/1000;
+		if (d > 2000) {
+			switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "excessive delay[%ld]-[%ld]=[%ldms] seq[%u]ssrc[0x%08X]\n",
+					(int64_t)(switch_micro_time_now()/1000), (int64_t)(frame->received_ts/1000), d, ntohs(frame->seq), frame->ssrc);
+		}
+		packet_stats_update(&session->stats, d);
+	}
+	session->stats.io_info.out_codec = write_frame->codec->implementation->iananame;
+	session->stats.io_info.in_codec = frame->codec->implementation->iananame;
 
 	switch_mutex_unlock(session->write_codec->mutex);
 	switch_mutex_unlock(frame->codec->mutex);

src/switch_core_session.c

@@ -36,11 +36,43 @@
 #include "switch.h"
 #include "switch_core.h"
 #include "private/switch_core_pvt.h"
+#include <fspr_network_io.h>
 
 #define DEBUG_THREAD_POOL
 
 struct switch_session_manager session_manager;
 
+SWITCH_DECLARE(void) switch_core_session_increment_plc(switch_core_session_t *session)
+{
+	session->stats.in_plc++;
+}
+
+SWITCH_DECLARE(void) switch_core_session_increment_read(switch_core_session_t *session)
+{
+	session->stats.in_count++;
+}
+
+SWITCH_DECLARE(void) switch_core_session_set_io_stats(switch_core_session_t *session, packet_stats_io_info_t *packet_stats_io_info)
+{
+	if ((session->stats.io_info.out_ssrc != 0 && session->stats.io_info.out_ssrc != packet_stats_io_info->out_ssrc)
+	 || (session->stats.io_info.in_ssrc != 0 && session->stats.io_info.in_ssrc != packet_stats_io_info->in_ssrc)) {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "SSRC change[%u][%u] [%u][%u]\n",
+				session->stats.io_info.out_ssrc, packet_stats_io_info->out_ssrc,
+				session->stats.io_info.in_ssrc, packet_stats_io_info->in_ssrc
+				);
+		packet_stats_print(session);
+		memset(&session->stats, '\0', sizeof(packet_stats_t));
+	}
+	session->stats.io_info.out_remote_addr = packet_stats_io_info->out_remote_addr;
+	session->stats.io_info.out_local_addr = packet_stats_io_info->out_local_addr;
+	session->stats.io_info.out_ssrc = packet_stats_io_info->out_ssrc;
+	session->stats.io_info.out_callid = packet_stats_io_info->out_callid;
+	session->stats.io_info.in_remote_addr = packet_stats_io_info->in_remote_addr;
+	session->stats.io_info.in_local_addr = packet_stats_io_info->in_local_addr;
+	session->stats.io_info.in_ssrc = packet_stats_io_info->in_ssrc;
+	session->stats.io_info.in_callid = packet_stats_io_info->in_callid;
+}
+
 SWITCH_DECLARE(void) switch_core_session_set_dmachine(switch_core_session_t *session, switch_ivr_dmachine_t *dmachine, switch_digit_action_target_t target)
 {
 	int i = (int) target;
@@ -1497,6 +1529,7 @@ SWITCH_DECLARE(void) switch_core_session_signal_state_change(switch_core_session
 			}
 		}
 	}
+	packet_stats_print(session);
 	switch_core_session_kill_channel(session, SWITCH_SIG_BREAK);
 }
 

src/switch_ivr_bridge.c

@@ -814,6 +814,14 @@ static void *audio_bridge_thread(switch_thread_t *thread, void *obj)
 				continue;
 			}
 
+			if (switch_test_flag((read_frame), SFF_PLC)) {
+				read_frame->received_ts = 0;
+				switch_core_session_increment_plc(session_b);
+			} else {
+				if (read_frame->packetlen > 0)
+					switch_core_session_increment_read(session_b);
+			}
+
 			if (status != SWITCH_STATUS_BREAK && !switch_channel_test_flag(chan_a, CF_HOLD) && !switch_channel_test_flag(chan_b, CF_LEG_HOLDING)) {
 				if (switch_core_session_write_frame(session_b, read_frame, SWITCH_IO_FLAG_NONE, stream_id) != SWITCH_STATUS_SUCCESS) {
 					switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session_a), SWITCH_LOG_DEBUG,

src/switch_jitterbuffer.c

@@ -60,6 +60,7 @@ typedef struct switch_jb_node_s {
 
 typedef struct switch_jb_stats_s {
 	uint32_t reset_too_big;
+	uint32_t reset_too_expanded;
 	uint32_t reset_missing_frames;
 	uint32_t reset_ts_jump;
 	uint32_t reset_error;
@@ -67,8 +68,13 @@ typedef struct switch_jb_stats_s {
 	uint32_t size_max;
 	uint32_t size_est;
 	uint32_t acceleration;
+	uint32_t fast_acceleration;
+	uint32_t forced_acceleration;
 	uint32_t expand;
+	uint32_t consecutive_miss;
+	int32_t expand_frame_len;
 	uint32_t jitter_max_ms;
+	uint32_t buffering_skip;
 	int estimate_ms;
 	int buffer_size_ms;
 } switch_jb_stats_t;
@@ -134,6 +140,7 @@ struct switch_jb_s {
 	uint32_t buffer_lag;
 	uint32_t flush;
 	uint32_t packet_count;
+	int32_t packets_in_buffer;
 	uint32_t max_packet_len;
 	uint32_t period_len;
 	uint32_t nack_saved_the_day;
@@ -784,8 +791,8 @@ static inline void increment_seq(switch_jb_t *jb)
 
 static inline void decrement_seq(switch_jb_t *jb)
 {
-	jb->last_target_seq = jb->target_seq;
 	jb->target_seq = htons((ntohs(jb->target_seq) - 1));
+	jb->last_target_seq = htons((ntohs(jb->target_seq) - 1));
 }
 
 static inline void set_read_seq(switch_jb_t *jb, uint16_t seq)
@@ -930,9 +937,14 @@ static inline int check_jb_size(switch_jb_t *jb)
 
 		seq_hs = ntohs(np->packet.header.seq);
 		if (target_seq_hs > seq_hs) {
-			hide_node(np, SWITCH_FALSE);
-			old++;
-			continue;
+			const int MAX_DROPOUT = 3000;
+			uint16_t udelta = target_seq_hs - seq_hs;
+			if (udelta > 1 && udelta < MAX_DROPOUT) {
+				// not a sequence id roll-over, this is an old packet, we can hide it
+				hide_node(np, SWITCH_FALSE);
+				old++;
+				continue;
+			}
 		}
 
 		if (count == 0) {
@@ -969,6 +981,9 @@ static inline int check_jb_size(switch_jb_t *jb)
 			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_fast_acceleration_ms", "%u", jb->jitter.stats.fast_acceleration * packet_ms);
+			switch_channel_set_variable_printf(jb->channel, "rtp_jb_forced_acceleration_ms", "%u", jb->jitter.stats.forced_acceleration * 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_expand_ms", "%u", jb->jitter.stats.expand * packet_ms);
 		}
 
@@ -1004,10 +1019,33 @@ static inline switch_status_t jb_next_packet_by_seq_with_acceleration(switch_jb_
 	   select packet to drop/accelerate. */
 
 	if (jb->elastic && jb->jitter.estimate && (jb->visible_nodes * jb->jitter.samples_per_frame) > 0 && jb->jitter.samples_per_second) {
-		int visible_not_old = check_jb_size(jb);
+		jb->packets_in_buffer = check_jb_size(jb);
 
 		jb->jitter.stats.estimate_ms = (int)((*jb->jitter.estimate) / ((jb->jitter.samples_per_second)) * 1000);
-		jb->jitter.stats.buffer_size_ms = (int)((visible_not_old * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000));
+		jb->jitter.stats.buffer_size_ms = (int)((jb->packets_in_buffer * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000));
+
+		/* If the jitter buffer size is above the its max size, we force accelerate */
+		if (jb->packets_in_buffer >= jb->max_frame_len) {
+			if (packet_vad(jb, packet, len) == SWITCH_FALSE) {
+				jb_debug(jb, SWITCH_LOG_ALERT, "JITTER_BUFFER above max size: [%d>%d] inactive fast acceleration\n", jb->packets_in_buffer, jb->max_frame_len);
+				jb->jitter.drop_gap = 3;
+				jb->jitter.stats.acceleration++;
+				jb->jitter.stats.expand_frame_len--;
+				jb->jitter.stats.fast_acceleration++;
+				return jb_next_packet_by_seq(jb, nodep);
+			} else {
+				if (jb->jitter.drop_gap > 0) {
+					jb->jitter.drop_gap--;
+				} else {
+					jb_debug(jb, SWITCH_LOG_ALERT, "JITTER_BUFFER above max size: [%d>%d] forced acceleration\n", jb->packets_in_buffer, jb->max_frame_len);
+					jb->jitter.drop_gap = 10;
+					jb->jitter.stats.acceleration++;
+					jb->jitter.stats.expand_frame_len--;
+					jb->jitter.stats.forced_acceleration++;
+					return jb_next_packet_by_seq(jb, nodep);
+				}
+			}
+		}
 
 		/* We try to accelerate in order to remove delay when the jitter buffer is 3x larger than the estimation. */
 		if (jb->jitter.stats.buffer_size_ms > (3 * jb->jitter.stats.estimate_ms) && jb->jitter.stats.buffer_size_ms > 60) {
@@ -1025,14 +1063,15 @@ static inline switch_status_t jb_next_packet_by_seq_with_acceleration(switch_jb_
 				if (status != SWITCH_STATUS_SUCCESS || packet_vad(jb, packet, len) == SWITCH_FALSE) {
 					jb->jitter.drop_gap = 3;
 					if (status != SWITCH_STATUS_SUCCESS) {
-						jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation n/a buffersize %d/%d %dms seq:%u [drop-missing/no-plc]\n",
+						jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation n/a buffersize %d/%d %dms seq:%u [drop-missing/no-plc]\n",
 								 jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, seq);
 					} else {
-						jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation %dms buffersize %d/%d %dms seq:%u ACCELERATE [drop]\n",
+						jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation %dms buffersize %d/%d %dms seq:%u ACCELERATE [drop]\n",
 								 jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms, seq);
 					}
 
 					jb->jitter.stats.acceleration++;
+					jb->jitter.stats.expand_frame_len--;
 
 					return jb_next_packet_by_seq(jb, nodep);
 				} else {
@@ -1084,6 +1123,9 @@ SWITCH_DECLARE(void) switch_jb_set_jitter_estimator(switch_jb_t *jb, double *jit
 			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_fast_acceleration_ms", "%u", 0);
+			switch_channel_set_variable_printf(jb->channel, "rtp_jb_forced_acceleration_ms", "%u", 0);
+			switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%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);
@@ -1174,12 +1216,15 @@ SWITCH_DECLARE(void) switch_jb_debug_level(switch_jb_t *jb, uint8_t level)
 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);
+		switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip);
 	}
 
 	if (jb->type == SJB_VIDEO) {
@@ -1582,12 +1627,14 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
 		switch_goto_status(SWITCH_STATUS_BREAK, end);
 	}
 
-	if (jb->complete_frames < jb->frame_len) {
+	if (!jb->elastic && (jb->complete_frames < jb->frame_len)) {
 
 		switch_jb_poll(jb);
 
 		if (!jb->flush) {
 			jb_debug(jb, 2, "BUFFERING %u/%u\n", jb->complete_frames , jb->frame_len);
+			jb->jitter.stats.buffering_skip++;
+			switch_channel_set_variable_printf(jb->channel, "rtp_jb_buffering_skip", "%u", jb->jitter.stats.buffering_skip);
 			switch_goto_status(SWITCH_STATUS_MORE_DATA, end);
 		}
 	}
@@ -1695,16 +1742,31 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
 					switch_goto_status(SWITCH_STATUS_RESTART, end);
 				} else {
 					if (jb->elastic) {
-						int visible_not_old = check_jb_size(jb);
-
 						jb->jitter.stats.estimate_ms = (int)((*jb->jitter.estimate) / ((jb->jitter.samples_per_second)) * 1000);
-						jb->jitter.stats.buffer_size_ms = (int)((visible_not_old * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000));
+						jb->jitter.stats.buffer_size_ms = (int)((jb->packets_in_buffer * jb->jitter.samples_per_frame) / (jb->jitter.samples_per_second / 1000));
 						/* When playing PLC, we take the oportunity to expand the buffer if the jitter buffer is smaller than the 3x the estimated jitter. */
-						if (jb->jitter.stats.buffer_size_ms < (3 * jb->jitter.stats.estimate_ms)) {
-							jb_debug(jb, SWITCH_LOG_INFO, "JITTER estimation %dms buffersize %d/%d %dms EXPAND [plc]\n",
-									 jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms);
+						if (jb->jitter.stats.expand_frame_len < 0) jb->jitter.stats.expand_frame_len = 0;
+
+						if (jb->jitter.stats.expand_frame_len > jb->max_frame_len) {
+							jb_debug(jb, SWITCH_LOG_ALERT, "JITTER  estimation %dms buffersize %d/%d %dms RESET TOO BIG [%d>%d] target seq[%u]\n",
+							   jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms,
+							   jb->jitter.stats.expand_frame_len, jb->max_frame_len, ntohs(jb->target_seq));
+							jb->jitter.stats.reset_too_expanded++;
+							jb->jitter.stats.expand_frame_len=0;
+							switch_jb_reset(jb);
+							switch_goto_status(SWITCH_STATUS_RESTART, end);
+						} else if (jb->jitter.stats.buffer_size_ms < (3 * jb->jitter.stats.estimate_ms)) {
+							jb_debug(jb, SWITCH_LOG_ALERT, "JITTER estimation %dms buffersize %d/%d %dms EXPAND [plc] target_seq[%u] expand[%d] now[%ld]\n",
+									 jb->jitter.stats.estimate_ms, jb->complete_frames, jb->frame_len, jb->jitter.stats.buffer_size_ms,
+									 ntohs(jb->target_seq), jb->jitter.stats.expand_frame_len, (int64_t)(switch_micro_time_now()/1000));
 							jb->jitter.stats.expand++;
+							jb->jitter.stats.expand_frame_len++;
 							decrement_seq(jb);
+						} else if (jb->jitter.stats.expand_frame_len >= jb->max_frame_len) {
+							jb->jitter.stats.reset_error++;
+							jb->jitter.stats.expand_frame_len=0;
+							switch_jb_reset(jb);
+							switch_goto_status(SWITCH_STATUS_RESTART, end);
 						} else {
 							jb_debug(jb, 2, "%s", "Frame not found suggest PLC\n");
 						}
@@ -1712,6 +1774,16 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
 						jb_debug(jb, 2, "%s", "Frame not found suggest PLC\n");
 					}
 
+					if (jb->elastic) {
+						jb->jitter.stats.consecutive_miss++;
+						if (jb->jitter.stats.consecutive_miss > 100) {
+								jb->jitter.stats.reset_missing_frames++;
+								jb->jitter.stats.consecutive_miss=0;
+								jb->elastic = SWITCH_FALSE;
+								switch_jb_reset(jb);
+								switch_goto_status(SWITCH_STATUS_RESTART, end);
+						}
+					}
 					plc = 1;
 					switch_goto_status(SWITCH_STATUS_NOTFOUND, end);
 				}
@@ -1742,6 +1814,8 @@ SWITCH_DECLARE(switch_status_t) switch_jb_get_packet(switch_jb_t *jb, switch_rtp
 
 		packet->header.seq = seq;
 		packet->header.ts = ts;
+	} else {
+		jb->jitter.stats.consecutive_miss=0;
 	}
 
 	switch_mutex_unlock(jb->mutex);

src/switch_rtp.c

@@ -113,6 +113,7 @@ typedef struct {
 	char body[SWITCH_RTP_MAX_BUF_LEN+4+sizeof(char *)];
 	switch_rtp_hdr_ext_t *ext;
 	char *ebody;
+	switch_time_t received_ts;
 } rtp_msg_t;
 
 #define RTP_BODY(_s) (char *) (_s->recv_msg.ebody ? _s->recv_msg.ebody : _s->recv_msg.body)
@@ -491,6 +492,7 @@ struct switch_rtp {
 	uint32_t last_max_vb_frames;
 	int skip_timer;
 	uint32_t prev_nacks_inflight;
+	switch_bool_t packet_stats_io_info_set;
 };
 
 struct switch_rtcp_report_block {
@@ -706,6 +708,7 @@ static handle_rfc2833_result_t handle_rfc2833(switch_rtp_t *rtp_session, switch_
 				}
 
 				if (rtp_session->jb && (rtp_session->rtp_bugs & RTP_BUG_FLUSH_JB_ON_DTMF)) {
+					switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "jb_reset : RTP_BUG_FLUSH_JB_ON_DTMF - ssrc[0x%.8X]\n", rtp_session->ssrc);
 					switch_jb_reset(rtp_session->jb);
 				}
 
@@ -2983,6 +2986,7 @@ SWITCH_DECLARE(void) switch_rtp_reset_jb(switch_rtp_t *rtp_session)
 {
 	if (switch_rtp_ready(rtp_session)) {
 		if (rtp_session->jb) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SWITCH RESET - ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->jb);
 		}
 	}
@@ -4454,11 +4458,32 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_change_interval(switch_rtp_t *rtp_ses
 	return status;
 }
 
+static void reset_packet_stats_io_info(switch_rtp_t *rtp_session) {
+	switch_channel_t *channel = switch_core_session_get_channel(rtp_session->session);
+	const char *uuid=NULL;
+	switch_core_session_t *b_session=NULL;
+	switch_rtp_t *b_rtp_session=NULL;
+
+	rtp_session->packet_stats_io_info_set = SWITCH_FALSE;
+	if (channel) {
+		uuid = switch_channel_get_variable_dup(channel,"bridge_uuid", SWITCH_FALSE, -1);
+	}
+	if (uuid) {
+		b_session = switch_core_session_locate(uuid);
+	}
+	if (b_session) {
+		b_rtp_session = switch_core_media_get_rtp_session(b_session, SWITCH_MEDIA_TYPE_AUDIO);
+		b_rtp_session->packet_stats_io_info_set = SWITCH_FALSE;
+		switch_core_session_rwunlock(b_session);
+	}
+	switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_INFO, ">>>> PACKET STATS IO INFO UNSET <<<<\n");
+}
+
 SWITCH_DECLARE(switch_status_t) switch_rtp_set_ssrc(switch_rtp_t *rtp_session, uint32_t ssrc)
 {
 	rtp_session->ssrc = ssrc;
 	rtp_session->send_msg.header.ssrc = htonl(rtp_session->ssrc);
-
+	reset_packet_stats_io_info(rtp_session);
 	return SWITCH_STATUS_SUCCESS;
 }
 
@@ -4466,6 +4491,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_set_remote_ssrc(switch_rtp_t *rtp_ses
 {
 	rtp_session->remote_ssrc = ssrc;
 	rtp_session->flags[SWITCH_RTP_FLAG_DETECT_SSRC] = 0;
+	reset_packet_stats_io_info(rtp_session);
 	return SWITCH_STATUS_SUCCESS;
 }
 
@@ -4737,10 +4763,12 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_pause_jitter_buffer(switch_rtp_t *rtp
 
 	if (rtp_session->pause_jb && !pause) {
 		if (rtp_session->jb) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset PAUSE - ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->jb);
 		}
 
 		if (rtp_session->vb) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset PAUSE VB - ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->vb);
 		}
 	}
@@ -5414,6 +5442,7 @@ SWITCH_DECLARE(void) switch_rtp_set_flag(switch_rtp_t *rtp_session, switch_rtp_f
 
 
 		if (rtp_session->jb) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SET FLAG - ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->jb);
 		}
 	} else if (flag == SWITCH_RTP_FLAG_NOBLOCK && rtp_session->sock_input) {
@@ -5707,6 +5736,7 @@ static switch_size_t do_flush(switch_rtp_t *rtp_session, int force, switch_size_
 		}
 
 		if (rtp_session->vbw) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset VBW - ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->vbw);
 		}
 
@@ -5841,6 +5871,46 @@ static int get_recv_payload(switch_rtp_t *rtp_session)
 	return r;
 }
 
+
+
+static void set_packet_stats_io_info(switch_rtp_t *rtp_session) {
+	switch_channel_t *channel = switch_core_session_get_channel(rtp_session->session);
+	const char *uuid=NULL;
+	switch_core_session_t *b_session=NULL;
+	switch_rtp_t *b_rtp_session=NULL;
+	switch_channel_t *b_channel=NULL;
+	if (rtp_session->packet_stats_io_info_set)
+		return;
+	if (channel) {
+		uuid = switch_channel_get_variable_dup(channel,"bridge_uuid", SWITCH_FALSE, -1);
+	}
+	if (uuid) {
+		b_session = switch_core_session_locate(uuid);
+	}
+	if (b_session) {
+		b_rtp_session = switch_core_media_get_rtp_session(b_session, SWITCH_MEDIA_TYPE_AUDIO);
+		b_channel = switch_core_session_get_channel(b_session);
+		switch_core_session_rwunlock(b_session);
+
+		if (b_rtp_session && b_channel) {
+			packet_stats_io_info_t packet_stats_io_info;
+			packet_stats_io_info.out_ssrc = b_rtp_session->ssrc;
+			packet_stats_io_info.out_codec = '\0';
+			packet_stats_io_info.out_remote_addr = b_rtp_session->remote_addr;
+			packet_stats_io_info.out_local_addr = b_rtp_session->local_addr;
+
+			packet_stats_io_info.in_ssrc = rtp_session->remote_ssrc;
+			packet_stats_io_info.in_codec = '\0';
+			packet_stats_io_info.in_remote_addr = rtp_session->remote_addr;
+			packet_stats_io_info.in_local_addr = rtp_session->local_addr;
+			if (rtp_session->remote_ssrc && b_rtp_session->ssrc)
+				rtp_session->packet_stats_io_info_set = SWITCH_TRUE;
+			switch_core_session_set_io_stats(b_rtp_session->session, &packet_stats_io_info);
+		}
+	}
+
+}
+
 #define return_cng_frame() do_cng = 1; goto timer_check
 
 static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t *bytes, switch_frame_flag_t *flags,
@@ -5860,8 +5930,9 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t
 
 	tries++;
 
-	if (tries > 20) {
+	if (tries > 20 && !(switch_channel_var_true(switch_core_session_get_channel(rtp_session->session), "rtp_jitter_buffer_accelerate"))) {
 		if (rtp_session->jb && !rtp_session->pause_jb && jb_valid(rtp_session)) {
+			switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset TRIES > 20 ssrc[0x%.8X]\n", rtp_session->ssrc);
 			switch_jb_reset(rtp_session->jb);
 		}
 		rtp_session->punts++;
@@ -5909,6 +5980,9 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t
 
 	if (poll_status == SWITCH_STATUS_SUCCESS) {
 		status = switch_socket_recvfrom(rtp_session->from_addr, rtp_session->sock_input, 0, (void *) &rtp_session->recv_msg, bytes);
+		if (*bytes) {
+			rtp_session->recv_msg.received_ts = switch_micro_time_now();
+		}
 	} else {
 		*bytes = 0;
 	}
@@ -6431,6 +6505,7 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t
 
 		if (rtp_session->jb && jb_valid(rtp_session)) {
 			if (rtp_session->last_jb_read_ssrc && rtp_session->last_jb_read_ssrc != read_ssrc) {
+				switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "switch_jb_reset SSRC change - ssrc[0x%.8X]\n", rtp_session->ssrc);
 				switch_jb_reset(rtp_session->jb);
 			}
 
@@ -6547,7 +6622,7 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t
 			}
 		}
 	}
-
+	set_packet_stats_io_info(rtp_session);
 	return status;
 }
 
@@ -8081,6 +8156,8 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_zerocopy_read_frame(switch_rtp_t *rtp
 			switch_set_flag(frame, SFF_RFC2833);
 		}
 		frame->timestamp = ntohl(rtp_session->last_rtp_hdr.ts);
+
+		frame->received_ts = rtp_session->recv_msg.received_ts;
 		frame->seq = (uint16_t) ntohs((uint16_t) rtp_session->last_rtp_hdr.seq);
 		frame->ssrc = ntohl(rtp_session->last_rtp_hdr.ssrc);
 		frame->m = rtp_session->last_rtp_hdr.m ? SWITCH_TRUE : SWITCH_FALSE;
@@ -8488,7 +8565,7 @@ static int rtp_common_write(switch_rtp_t *rtp_session,
 		rtp_session->seq += delta;
 
 		send_msg->header.seq = htons(rtp_session->seq);
-		
+
 		if (rtp_session->flags[SWITCH_RTP_FLAG_BYTESWAP] && send_msg->header.pt == rtp_session->payload) {
 			switch_swap_linear((int16_t *)send_msg->body, (int) datalen);
 		}