Merge 52ca18f49d into 5cb74797fe

New function, `void pgsql_handle_set_error_if_not_set(switch_pgsql_handle_t *handle, char **err)` has been added to mod_pgsql module. This function is now called at several points where an error occurred but *err was not yet set.

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/databases/mod_pgsql/mod_pgsql.c

@@ -106,6 +106,22 @@ char * pgsql_handle_get_error(switch_pgsql_handle_t *handle)
 	return err_str;
 }
 
+void pgsql_handle_set_error_if_not_set(switch_pgsql_handle_t *handle, char **err)
+{
+	char *err_str;
+
+	if (err && !(*err)) {
+		err_str = pgsql_handle_get_error(handle);
+
+		if (zstr(err_str)) {
+			switch_safe_free(err_str);
+			err_str = strdup((char *)"SQL ERROR!");
+		}
+
+		*err = err_str;
+	}
+}
+
 static int db_is_up(switch_pgsql_handle_t *handle)
 {
 	int ret = 0;
@@ -553,8 +569,15 @@ switch_status_t pgsql_handle_exec_detailed(const char *file, const char *func, i
 		goto error;
 	}
 
-	return pgsql_finish_results(handle);
+	if (pgsql_finish_results(handle) != SWITCH_STATUS_SUCCESS) {
+		goto error;
+	}
+
+	return SWITCH_STATUS_SUCCESS;
+
 error:
+	pgsql_handle_set_error_if_not_set(handle, err);
+
 	return SWITCH_STATUS_FALSE;
 }
 
@@ -630,6 +653,7 @@ done:
 
 	pgsql_free_result(&result);
 	if (pgsql_finish_results(handle) != SWITCH_STATUS_SUCCESS) {
+		pgsql_handle_set_error_if_not_set(handle, err);
 		sstatus = SWITCH_STATUS_FALSE;
 	}
 
@@ -638,6 +662,7 @@ done:
 error:
 
 	pgsql_free_result(&result);
+	pgsql_handle_set_error_if_not_set(handle, err);
 
 	return SWITCH_STATUS_FALSE;
 }
@@ -1050,6 +1075,8 @@ switch_status_t pgsql_handle_callback_exec_detailed(const char *file, const char
 	return SWITCH_STATUS_SUCCESS;
 error:
 
+	pgsql_handle_set_error_if_not_set(handle, err);
+
 	return SWITCH_STATUS_FALSE;
 }
 

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