diff --git a/src/include/switch_types.h b/src/include/switch_types.h index e213800..db993f0 100644 --- a/src/include/switch_types.h +++ b/src/include/switch_types.h @@ -585,6 +585,21 @@ typedef struct { uint32_t packet_count; uint32_t octet_count; uint32_t peer_ssrc; + + uint32_t last_rpt_ts; /* RTP timestamp at which the last report was generated and sent */ + uint32_t ssrc; /* identifier of the source */ + uint32_t csrc; /* contributing source 0-15 32bit each */ + uint32_t last_pkt_tsdiff; /* Jitter calculation, timestamp difference between the two last received packet */ + uint32_t inter_jitter; /* Jitter calculation, Interarrival jitter */ + uint16_t last_rpt_seq; /* Packet loss calculation, sequence number at the begining of this RTCP report interval */ + uint16_t last_rpt_cycle; /* Packet loss calculation, sequence number cycle at the begining of the current RTCP report interval */ + uint16_t period_pkt_count; /* Packet loss calculation, packet count received during this RTCP report interval */ + uint16_t last_seq; /* Packet loss calculation, last sequence number received and processed for stats */ + uint16_t cycle; /* Packet loss calculation, sequence number cycle of the current RTCP report interval */ + int16_t base_seq; /* Packet loss calculation, first sequence number received */ + uint32_t cum_lost; /* Packet loss calculation, cumulative number of packet lost */ + uint32_t last_recv_lsr_local; /* RTT calculation, When receiving an SR we save our local timestamp in fraction of 65536 seconds */ + uint32_t last_recv_lsr_peer; /* RTT calculation, When receiving an SR we extract the middle 32bits of the remote NTP timestamp to include it in the next SR LSR */ } switch_rtcp_numbers_t; typedef struct { diff --git a/src/switch_rtp.c b/src/switch_rtp.c index acc9946..e89d542 100644 --- a/src/switch_rtp.c +++ b/src/switch_rtp.c @@ -33,6 +33,7 @@ //#define DEBUG_2833 //#define RTP_DEBUG_WRITE_DELTA //#define DEBUG_MISSED_SEQ +#define DEBUG_RTCP #include #include @@ -61,6 +62,7 @@ #define MASTER_KEY_LEN 30 #define RTP_MAGIC_NUMBER 42 #define MAX_SRTP_ERRS 10 +#define NTP_TIME_OFFSET 2208988800UL static switch_port_t START_PORT = RTP_START_PORT; static switch_port_t END_PORT = RTP_END_PORT; @@ -232,6 +234,7 @@ struct switch_rtp { uint32_t conf_samples_per_interval; uint32_t rsamples_per_interval; uint32_t ms_per_packet; + uint16_t rtcp_send_rate; switch_port_t local_port; switch_port_t remote_port; switch_port_t eff_remote_port; @@ -290,7 +293,7 @@ struct switch_rtcp_source { unsigned ssrc1:32; unsigned fraction_lost:8; unsigned cumulative_lost:24; - unsigned hi_seq_recieved:32; + unsigned hi_seq_received:32; unsigned interarrival_jitter:32; unsigned lsr:32; unsigned lsr_delay:32; @@ -1028,13 +1031,159 @@ static uint8_t get_next_write_ts(switch_rtp_t *rtp_session, uint32_t timestamp) return m; } +static int rtcp_generate_sr(switch_rtp_t *rtp_session, struct switch_rtcp_senderinfo *sr) +{ +#ifdef DEBUG_RTCP + switch_core_session_t *session = switch_core_memory_pool_get_data(rtp_session->pool, "__session"); +#endif + switch_rtcp_numbers_t * stats=&rtp_session->stats.rtcp; + uint32_t expected_pkt, pkt_lost, dlsr; + apr_time_t now; + apr_uint32_t sec, ntp_sec, ntp_usec, lsr_now; + apr_time_exp_t now_hr; + now = switch_micro_time_now(); + sec = apr_time_sec(now); /* convert to seconds */ + ntp_sec = sec+NTP_TIME_OFFSET; /* convert to NTP seconds */ + sr->ntp_msw = htonl(ntp_sec); /* store result in "most significant word" */ + ntp_usec = now - (sec*1000000); /* remove seconds to keep only the microseconds */ + sr->ntp_lsw = htonl(ntp_usec*(double)(((uint64_t)1)<<32)*1.0e-6); /* convert microseconds to fraction of 32bits and store result in "least significatn word" */ + +#ifdef DEBUG_RTCP + apr_time_exp_gmt(&now_hr,now); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,"Sending an RTCP packet[%04d-%02d-%02d %02d:%02d:%02d.%d] lsr[%u] msw[%u] lsw[%u] fs_ssrc[%u]\n", + 1900 + now_hr.tm_year, now_hr.tm_mday, now_hr.tm_mon, now_hr.tm_hour, now_hr.tm_min, now_hr.tm_sec, now_hr.tm_usec, + (ntohl(sr->ntp_lsw)&0xffff0000)>>16 | (ntohl(sr->ntp_msw)&0x0000ffff)<<16, + ntohl(sr->ntp_msw),ntohl(sr->ntp_lsw), rtp_session->ssrc + ); +#endif + sr->ts = htonl(rtp_session->last_write_ts); + sr->pc = htonl(rtp_session->stats.outbound.packet_count); + sr->oc = htonl((rtp_session->stats.outbound.raw_bytes - rtp_session->stats.outbound.packet_count * sizeof(srtp_hdr_t))); + + /* Fill stats in sender report */ + sr->sr_source.ssrc1 = htonl(rtp_session->stats.rtcp.peer_ssrc); + + /* Packet loss */ + expected_pkt = (stats->last_seq + (stats->cycle <<16)) - (stats->last_rpt_seq + (stats->last_rpt_cycle <<16)) - stats->base_seq + 1; + pkt_lost = expected_pkt - stats->period_pkt_count; + stats->cum_lost=stats->cum_lost+pkt_lost; + if(expected_pkt > 0) + sr->sr_source.fraction_lost = (uint8_t) (pkt_lost * 256 / expected_pkt); + else + sr->sr_source.fraction_lost = 0; + +#if SWITCH_BYTE_ORDER != __BIG_ENDIAN + /* Reversing byte order for 24bits */ + sr->sr_source.cumulative_lost = (((stats->cum_lost&0x0000FF)<<16) | ((stats->cum_lost&0x00FF00)) | ((stats->cum_lost&0xFF0000)>>16)); +#endif + +#ifdef DEBUG_RTCP + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "rtcp_generate_sr: fs_ssrc[%d] received[%d] expected[%d] cum[%d]lost[%d|%d/256]pkt last_seq[%d]cyc[%d] last_rpt_seq[%d]cyc[%d] ssrc[%d]\n", + ntohs((uint32_t)rtp_session->recv_msg.header.ssrc), stats->period_pkt_count, expected_pkt, + stats->cum_lost, pkt_lost, sr->sr_source.fraction_lost, stats->last_seq, + stats->cycle, stats->last_rpt_seq, stats->last_rpt_cycle, rtp_session->stats.rtcp.peer_ssrc + ); +#endif + sr->sr_source.hi_seq_received = htonl(stats->cycle << 16 | stats->last_seq); + + /* Jitter */ + sr->sr_source.interarrival_jitter = htonl(stats->inter_jitter); + + /* Delay since Last Sender Report (DLSR) : 32bits, 1/65536 seconds */ + lsr_now = (uint32_t)(ntp_usec*0.065536) | (ntp_sec&0x0000ffff)<<16; /* 0.065536 is used for convertion from useconds to fraction of 65536 (x65536/1000000) */ + + if(stats->last_recv_lsr_local){ + dlsr = lsr_now - stats->last_recv_lsr_local; + } + else{ + dlsr = 0; + } + sr->sr_source.lsr = stats->last_recv_lsr_peer; + sr->sr_source.lsr_delay = htonl(dlsr); + + sr->sr_desc_head.v = 0x02; + sr->sr_desc_head.padding = 0; + sr->sr_desc_head.sc = 1; + sr->sr_desc_head.pt = 202; + sr->sr_desc_head.length = htons(5); + sr->sr_desc_ssrc.ssrc = htonl(rtp_session->ssrc); + + /* Prepare next report */ + stats->last_rpt_cycle=stats->cycle; + stats->last_rpt_seq=stats->last_seq; + stats->last_rpt_ts=rtp_session->timer.samplecount; + stats->period_pkt_count=0; + + return 1; +} + +static int rtcp_stats_init(switch_rtp_t *rtp_session) +{ + switch_rtcp_numbers_t * stats=&rtp_session->stats.rtcp; + srtp_hdr_t * hdr = &rtp_session->recv_msg.header; + switch_core_session_t *session = switch_core_memory_pool_get_data(rtp_session->pool, "__session"); + stats->ssrc=hdr->ssrc; + stats->last_rpt_ts=rtp_session->timer.samplecount; + stats->last_rpt_seq=0; + stats->last_rpt_cycle=0; + stats->last_pkt_tsdiff=0; + stats->inter_jitter=0; + stats->cycle=0; + stats->base_seq=ntohs((uint16_t)hdr->seq); + stats->cum_lost=0; + stats->period_pkt_count=0; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "rtcp_stats_init: ssrc[%d] base_seq[%d]",ntohl((uint32_t) stats->ssrc), stats->base_seq); + + return 1; +} + +static int rtcp_stats(switch_rtp_t *rtp_session) +{ +#ifdef DEBUG_RTCP + switch_core_session_t *session = switch_core_memory_pool_get_data(rtp_session->pool, "__session"); +#endif + srtp_hdr_t * hdr = &rtp_session->recv_msg.header; + switch_rtcp_numbers_t * stats=&rtp_session->stats.rtcp; + uint32_t packet_spacing_diff, pkt_tsdiff; + if(stats->last_seq == hdr->seq) + return 0; // no new packet received + + /* Verify that we are on the same stream source (we do not support multiple sources) */ + if(hdr->ssrc != stats->ssrc || !stats->last_rpt_ts){ + rtcp_stats_init(rtp_session); + } + /* Detect sequence number cycle change */ + if( ( stats->last_seq - ntohs((uint16_t)hdr->seq) ) > 1000){ + stats->cycle++; + } + stats->last_seq = (uint16_t) ntohs((uint16_t) rtp_session->recv_msg.header.seq); + stats->period_pkt_count++; +#ifdef DEBUG_RTCP + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "rtcp_stats: period_pkt_count[%d] last_seq[%d]cycle[%d] fs_ssrc[%d] timer.samplecount[%u]\n", + stats->period_pkt_count,stats->last_seq, stats->cycle, rtp_session->ssrc, rtp_session->timer.samplecount); +#endif + /* Interarrival jitter calculation */ + pkt_tsdiff = ntohl(hdr->ts) - rtp_session->timer.samplecount; /* relative transit times for this packet */ + if(stats->last_pkt_tsdiff == 0) + stats->last_pkt_tsdiff = pkt_tsdiff; + packet_spacing_diff = stats->last_pkt_tsdiff - pkt_tsdiff; /* Jitter : difference of relative transit times for the two packets */ + stats->last_pkt_tsdiff = pkt_tsdiff; + /* Interarrival jitter estimation, "J(i) = J(i-1) + ( |D(i-1,i)| - J(i-1) )/16" */ + stats->inter_jitter = (uint32_t)((int32_t)stats->inter_jitter + ((int32_t)(abs((int32_t)packet_spacing_diff) - (int32_t)stats->inter_jitter) /16)); + +#ifdef DEBUG_RTCP + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "rtcp_stats: pkt_ts[%d]local_ts[%d]diff[%d]pkt_spacing[%d]=inter_jitter[%d] seq[%d] fs_ssrc[%d]", + ntohl(hdr->ts), rtp_session->timer.samplecount, pkt_tsdiff, packet_spacing_diff, stats->inter_jitter, ntohs(hdr->seq), rtp_session->ssrc); +#endif + + return 1; +} static int check_srtp_and_ice(switch_rtp_t *rtp_session) { int ret = 0; - if (switch_test_flag(rtp_session, SWITCH_RTP_FLAG_AUTO_CNG) && rtp_session->send_msg.header.ts && rtp_session->timer.samplecount >= (rtp_session->last_write_samplecount + (rtp_session->samples_per_interval * 60))) { uint8_t data[10] = { 0 }; @@ -1052,13 +1201,13 @@ static int check_srtp_and_ice(switch_rtp_t *rtp_session) } } - if (rtp_session->rtcp_sock_output && - switch_test_flag(rtp_session, SWITCH_RTP_FLAG_ENABLE_RTCP) && !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_RTCP_PASSTHRU) && - rtp_session->rtcp_interval && (rtp_session->stats.read_count % rtp_session->rtcp_interval) == 0) { + if (rtp_session->rtcp_sock_output && switch_test_flag(rtp_session, SWITCH_RTP_FLAG_ENABLE_RTCP) && + !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_RTCP_PASSTHRU) && + (rtp_session->timer.samplecount - rtp_session->stats.rtcp.last_rpt_ts >= rtp_session->samples_per_second * rtp_session->rtcp_send_rate) ) { + struct switch_rtcp_senderinfo *sr = (struct switch_rtcp_senderinfo*) rtp_session->rtcp_send_msg.body; const char* str_cname=NULL; - //rtp_msg_t *send_msg = &rtp_session->send_msg; switch_size_t rtcp_bytes; switch_byte_t *ptr = (switch_byte_t *)rtp_session->rtcp_send_msg.body; switch_time_t when = 0; @@ -1070,47 +1219,14 @@ static int check_srtp_and_ice(switch_rtp_t *rtp_session) sr->ssrc = htonl(rtp_session->ssrc); if (!rtp_session->stats.inbound.period_packet_count) { - rtp_session->rtcp_send_msg.header.type = 201; + rtp_session->rtcp_send_msg.header.type = 201; /* Receiver report */ rtcp_bytes = sizeof(switch_rtcp_hdr_t) + 4; ptr += 4; } else { - switch_time_t when; - rtp_session->rtcp_send_msg.header.type = 200; - - if (rtp_session->send_time) { - when = rtp_session->send_time; - } else { - when = switch_micro_time_now(); - } - - sr->ntp_msw = htonl((u_long)(when / 1000000 + 2208988800UL)); - /* - sr->ntp_lsw = htonl((u_long)(when % 1000000 * ((UINT_MAX * 1.0)/ 1000000.0))); - */ - sr->ntp_lsw = htonl((u_long)(rtp_session->send_time % 1000000 * 4294.967296)); - sr->ts = htonl(rtp_session->last_write_ts); - sr->pc = htonl(rtp_session->stats.outbound.packet_count); - sr->oc = htonl((rtp_session->stats.outbound.raw_bytes - rtp_session->stats.outbound.packet_count * sizeof(srtp_hdr_t))); - + rtp_session->rtcp_send_msg.header.type = 200; /* Sender report*/ + rtcp_generate_sr(rtp_session,sr); } - /* TBD need to put more accurate stats here. */ - - sr->sr_source.ssrc1 = htonl(rtp_session->stats.rtcp.peer_ssrc); - sr->sr_source.fraction_lost = 0; - sr->sr_source.cumulative_lost = htonl(rtp_session->stats.inbound.skip_packet_count); - sr->sr_source.hi_seq_recieved = htonl(rtp_session->recv_msg.header.seq); - sr->sr_source.interarrival_jitter = htonl(0); - sr->sr_source.lsr = htonl(0); - sr->sr_source.lsr_delay = htonl(0); - - sr->sr_desc_head.v = 0x02; - sr->sr_desc_head.padding = 0; - sr->sr_desc_head.sc = 1; - sr->sr_desc_head.pt = 202; - sr->sr_desc_head.length = htons(5); - - sr->sr_desc_ssrc.ssrc = htonl(rtp_session->ssrc); sr->sr_desc_ssrc.cname = 0x1; { char bufa[30]; @@ -1167,6 +1283,7 @@ static int check_srtp_and_ice(switch_rtp_t *rtp_session) rtcp_bytes = sbytes; } #endif + if (switch_socket_sendto(rtp_session->rtcp_sock_output, rtp_session->rtcp_remote_addr, 0, (void *)&rtp_session->rtcp_send_msg, &rtcp_bytes ) != SWITCH_STATUS_SUCCESS) { switch_core_session_t *session = switch_core_memory_pool_get_data(rtp_session->pool, "__session"); @@ -2396,6 +2513,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_activate_rtcp(switch_rtp_t *rtp_sessi switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "RTCP send rate is: %d and packet rate is: %d Remote Port: %d\n", send_rate, rtp_session->ms_per_packet, rtp_session->remote_rtcp_port); rtp_session->rtcp_interval = send_rate/(rtp_session->ms_per_packet/1000); + rtp_session->rtcp_send_rate = send_rate/1000; } return enable_local_rtcp_socket(rtp_session, &err) || enable_remote_rtcp_socket(rtp_session, &err); @@ -3005,6 +3123,10 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t } + + if(rtp_session->rtcp_sock_output && switch_test_flag(rtp_session, SWITCH_RTP_FLAG_ENABLE_RTCP) && !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_RTCP_PASSTHRU) && rtp_session->rtcp_interval) + rtcp_stats(rtp_session); + #ifdef DEBUG_MISSED_SEQ if (rtp_session->last_seq && rtp_session->last_seq+1 != seq) { //2012-11-28 18:33:11.799070 [ERR] switch_rtp.c:2883 Missed -65536 RTP frames from sequence [65536] to [-1] (missed). Time since last read [20021] @@ -3218,6 +3340,8 @@ static switch_status_t read_rtcp_packet(switch_rtp_t *rtp_session, switch_size_t *bytes = 0; } + + #ifdef ENABLE_SRTP if (switch_test_flag(rtp_session, SWITCH_RTP_FLAG_SECURE_RECV) && (!rtp_session->ice.ice_user || rtp_session->rtcp_recv_msg.header.version == 2)) { int sbytes = (int) *bytes; @@ -3283,6 +3407,32 @@ static switch_status_t read_rtcp_packet(switch_rtp_t *rtp_session, switch_size_t if (rtp_session->rtcp_recv_msg.header.type == 200) { struct switch_rtcp_senderinfo* sr = (struct switch_rtcp_senderinfo*)rtp_session->rtcp_recv_msg.body; + /* RTCP STATS */ + apr_time_t now; + apr_time_exp_t now_hr; + apr_uint32_t sec, ntp_sec, ntp_usec, lsr_now; + uint32_t lsr; + now = switch_micro_time_now(); /* number of microseconds since 00:00:00 january 1, 1970 UTC */ + sec = apr_time_sec(now); /* converted to second (NTP most significant bits) */ + ntp_sec = sec+NTP_TIME_OFFSET; /* 32bits most significant */ + ntp_usec = now - (sec*1000000); /* micro seconds */ + lsr_now = (uint32_t)(ntp_usec*0.065536) | (ntp_sec&0x0000ffff)<<16; // 0.065536 is used for convertion from useconds to fraction of 16bits (x65536/1000000) + + if(sr->sr_source.lsr){ + apr_time_exp_gmt(&now_hr,now); + /* Calculating RTT = A - DLSR - LSR */ + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, + "Receiving an RTCP packet[%04d-%02d-%02d %02d:%02d:%02d.%d] SSRC[%u]" + "RTT[%f] A[%u] - DLSR[%u] - LSR[%u]\n", + 1900 + now_hr.tm_year, now_hr.tm_mday, now_hr.tm_mon, now_hr.tm_hour, now_hr.tm_min, now_hr.tm_sec, now_hr.tm_usec, + ntohl(sr->ssrc), (double)(lsr_now - ntohl(sr->sr_source.lsr_delay) - ntohl(sr->sr_source.lsr))/65536, + lsr_now, ntohl(sr->sr_source.lsr_delay), ntohl(sr->sr_source.lsr)); + } + /* Extracting LSR from NTP timestamp and save it */ + lsr = (ntohl(sr->ntp_lsw)&0xffff0000)>>16 | (ntohl(sr->ntp_msw)&0x0000ffff)<<16; /* The middle 32 bits out of 64 in the NTP timestamp */ + rtp_session->stats.rtcp.last_recv_lsr_peer = htonl(lsr); /* Save it include it in the next SR */ + rtp_session->stats.rtcp.last_recv_lsr_local = lsr_now; /* Save it to calculate DLSR when generating next SR */ + rtp_session->rtcp_fresh_frame = 1; rtp_session->stats.rtcp.packet_count += ntohl(sr->pc);