diff --git a/src/switch_apr.c b/src/switch_apr.c index 4c99662f45..3798d6e2dc 100644 --- a/src/switch_apr.c +++ b/src/switch_apr.c @@ -833,7 +833,7 @@ SWITCH_DECLARE(switch_status_t) switch_socket_recvfrom(switch_sockaddr_t *from, */ } - if (r == 35) { + if (r == 35 || r == 730035) { r = SWITCH_STATUS_BREAK; } diff --git a/src/switch_rtp.c b/src/switch_rtp.c index 3ce7a07e60..faf2868f48 100644 --- a/src/switch_rtp.c +++ b/src/switch_rtp.c @@ -32,6 +32,7 @@ */ //#define DEBUG_2833 //#define RTP_DEBUG_WRITE_DELTA +//#define DEBUG_MISSED_SEQ #include #include #undef PACKAGE_NAME @@ -245,6 +246,9 @@ struct switch_rtp { switch_time_t send_time; switch_byte_t auto_adj_used; uint8_t pause_jb; + uint16_t last_seq; + switch_time_t last_read_time; + switch_size_t last_flush_packet_count; }; struct switch_rtcp_senderinfo { @@ -256,6 +260,180 @@ struct switch_rtcp_senderinfo { unsigned oc:32; }; +typedef enum { + RESULT_CONTINUE, + RESULT_GOTO_END, + RESULT_GOTO_RECVFROM, + RESULT_GOTO_TIMERCHECK +} handle_rfc2833_result_t; + +static handle_rfc2833_result_t handle_rfc2833(switch_rtp_t *rtp_session, switch_size_t bytes, int *do_cng) +{ +#ifdef DEBUG_2833 + if (rtp_session->dtmf_data.in_digit_sanity && !(rtp_session->dtmf_data.in_digit_sanity % 100)) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "sanity %d\n", rtp_session->dtmf_data.in_digit_sanity); + } +#endif + + if (rtp_session->dtmf_data.in_digit_sanity && !--rtp_session->dtmf_data.in_digit_sanity) { + rtp_session->dtmf_data.last_digit = 0; + rtp_session->dtmf_data.in_digit_ts = 0; + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Failed DTMF sanity check.\n"); + } + + /* RFC2833 ... like all RFC RE: VoIP, guaranteed to drive you to insanity! + We know the real rules here, but if we enforce them, it's an interop nightmare so, + we put up with as much as we can so we don't have to deal with being punished for + doing it right. Nice guys finish last! + */ + if (bytes > rtp_header_len && !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_PROXY_MEDIA) && + !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_PASS_RFC2833) && rtp_session->recv_te && rtp_session->recv_msg.header.pt == rtp_session->recv_te) { + switch_size_t len = bytes - rtp_header_len; + unsigned char *packet = (unsigned char *) rtp_session->recv_msg.body; + int end; + uint16_t duration; + char key; + uint16_t in_digit_seq; + uint32_t ts; + + if (!(packet[0] || packet[1] || packet[2] || packet[3]) && len >= 8) { + packet += 4; + len -= 4; + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "DTMF payload offset by 4 bytes.\n"); + } + + if (!(packet[0] || packet[1] || packet[2] || packet[3])) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Failed DTMF payload check.\n"); + rtp_session->dtmf_data.last_digit = 0; + rtp_session->dtmf_data.in_digit_ts = 0; + } + + end = packet[1] & 0x80 ? 1 : 0; + duration = (packet[2] << 8) + packet[3]; + key = switch_rfc2833_to_char(packet[0]); + in_digit_seq = ntohs((uint16_t) rtp_session->recv_msg.header.seq); + ts = htonl(rtp_session->recv_msg.header.ts); + + if (in_digit_seq < rtp_session->dtmf_data.in_digit_seq) { + if (rtp_session->dtmf_data.in_digit_seq - in_digit_seq > 100) { + rtp_session->dtmf_data.in_digit_seq = 0; + } + } +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "packet[%d]: %02x %02x %02x %02x\n", (int) len, (unsigned) packet[0], (unsigned) + packet[1], (unsigned) packet[2], (unsigned) packet[3]); +#endif + + if (in_digit_seq > rtp_session->dtmf_data.in_digit_seq) { + + rtp_session->dtmf_data.in_digit_seq = in_digit_seq; +#ifdef DEBUG_2833 + + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "read: %c %u %u %u %u %d %d %s\n", + key, in_digit_seq, rtp_session->dtmf_data.in_digit_seq, + ts, duration, rtp_session->recv_msg.header.m, end, end && !rtp_session->dtmf_data.in_digit_ts ? "ignored" : ""); +#endif + + if (!rtp_session->dtmf_data.in_digit_queued && (rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION) && + rtp_session->dtmf_data.in_digit_ts) { + switch_dtmf_t dtmf = { key, switch_core_min_dtmf_duration(0) }; +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Early Queuing digit %c:%d\n", dtmf.digit, dtmf.duration / 8); +#endif + switch_rtp_queue_rfc2833_in(rtp_session, &dtmf); + rtp_session->dtmf_data.in_digit_queued = 1; + } + + /* only set sanity if we do NOT ignore the packet */ + if (rtp_session->dtmf_data.in_digit_ts) { + rtp_session->dtmf_data.in_digit_sanity = 2000; + } + + if (rtp_session->dtmf_data.last_duration > duration && + rtp_session->dtmf_data.last_duration > 0xFC17 && ts == rtp_session->dtmf_data.in_digit_ts) { + rtp_session->dtmf_data.flip++; + } + + if (end) { + if (rtp_session->dtmf_data.in_digit_ts) { + switch_dtmf_t dtmf = { key, duration }; + + if (ts > rtp_session->dtmf_data.in_digit_ts) { + dtmf.duration += (ts - rtp_session->dtmf_data.in_digit_ts); + } + if (rtp_session->dtmf_data.flip) { + dtmf.duration += rtp_session->dtmf_data.flip * 0xFFFF; + rtp_session->dtmf_data.flip = 0; +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "you're welcome!\n"); +#endif + } +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "done digit=%c ts=%u start_ts=%u dur=%u ddur=%u\n", + dtmf.digit, ts, rtp_session->dtmf_data.in_digit_ts, duration, dtmf.duration); +#endif + + if (!(rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION) && !rtp_session->dtmf_data.in_digit_queued) { +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Queuing digit %c:%d\n", dtmf.digit, dtmf.duration / 8); +#endif + switch_rtp_queue_rfc2833_in(rtp_session, &dtmf); + } + + rtp_session->dtmf_data.last_digit = rtp_session->dtmf_data.first_digit; + + rtp_session->dtmf_data.in_digit_ts = 0; + rtp_session->dtmf_data.in_digit_sanity = 0; + rtp_session->dtmf_data.in_digit_queued = 0; + *do_cng = 1; + } else { + if (!switch_rtp_ready(rtp_session)) { + return RESULT_GOTO_END; + } + switch_cond_next(); + return RESULT_GOTO_RECVFROM; + } + + } else if (!rtp_session->dtmf_data.in_digit_ts) { + rtp_session->dtmf_data.in_digit_ts = ts; + rtp_session->dtmf_data.first_digit = key; + rtp_session->dtmf_data.in_digit_sanity = 2000; + } + + rtp_session->dtmf_data.last_duration = duration; + } else { +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "drop: %c %u %u %u %u %d %d\n", + key, in_digit_seq, rtp_session->dtmf_data.in_digit_seq, ts, duration, rtp_session->recv_msg.header.m, end); +#endif + switch_cond_next(); + return RESULT_GOTO_RECVFROM; + } + } + + if (bytes && rtp_session->dtmf_data.in_digit_ts) { + if (!switch_rtp_ready(rtp_session)) { + return RESULT_GOTO_END; + } + + if (!rtp_session->dtmf_data.in_interleaved && rtp_session->recv_msg.header.pt != rtp_session->recv_te) { + /* Drat, they are sending audio still as well as DTMF ok fine..... *sigh* */ + rtp_session->dtmf_data.in_interleaved = 1; + } + + if (rtp_session->dtmf_data.in_interleaved || (rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION)) { + if (rtp_session->recv_msg.header.pt == rtp_session->recv_te) { + return RESULT_GOTO_RECVFROM; + } + } else { + *do_cng = 1; + return RESULT_GOTO_TIMERCHECK; + } + } + + return RESULT_CONTINUE; +} + static int global_init = 0; static int rtp_common_write(switch_rtp_t *rtp_session, rtp_msg_t *send_msg, void *data, uint32_t datalen, switch_payload_t payload, uint32_t timestamp, switch_frame_flag_t *flags); @@ -2157,6 +2335,15 @@ static void do_flush(switch_rtp_t *rtp_session) bytes = sizeof(rtp_msg_t); status = switch_socket_recvfrom(rtp_session->from_addr, rtp_session->sock_input, 0, (void *) &rtp_session->recv_msg, &bytes); if (bytes) { + int do_cng = 0; + + /* Make sure to handle RFC2833 packets, even if we're flushing the packets */ + if (bytes > rtp_header_len && rtp_session->recv_te && rtp_session->recv_msg.header.pt == rtp_session->recv_te) { + handle_rfc2833(rtp_session, bytes, &do_cng); +#ifdef DEBUG_2833 + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "*** RTP packet handled in flush loop ***\n"); +#endif + } flushed++; @@ -2195,7 +2382,52 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t *bytes = sizeof(rtp_msg_t); status = switch_socket_recvfrom(rtp_session->from_addr, rtp_session->sock_input, 0, (void *) &rtp_session->recv_msg, bytes); ts = ntohl(rtp_session->recv_msg.header.ts); - + + if (*bytes ) { + uint16_t seq = ntohs((uint16_t) rtp_session->recv_msg.header.seq); + + if (rtp_session->last_seq && rtp_session->last_seq+1 != seq) { +#ifdef DEBUG_MISSED_SEQ + switch_size_t flushed_packets_diff = rtp_session->stats.inbound.flush_packet_count - rtp_session->last_flush_packet_count; + switch_size_t num_missed = (switch_size_t)seq - (rtp_session->last_seq+1); + + if (num_missed == 1) { /* We missed one packet */ + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Missed one RTP frame with sequence [%d]%s. Time since last read [%d]\n", + rtp_session->last_seq+1, (flushed_packets_diff == 1) ? " (flushed by FS)" : " (missed)", + rtp_session->last_read_time ? switch_micro_time_now()-rtp_session->last_read_time : 0); + } else { /* We missed multiple packets */ + if (flushed_packets_diff == 0) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, + "Missed %d RTP frames from sequence [%d] to [%d] (missed). Time since last read [%d]\n", + num_missed, rtp_session->last_seq+1, seq-1, + rtp_session->last_read_time ? switch_micro_time_now()-rtp_session->last_read_time : 0); + } else if (flushed_packets_diff == num_missed) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, + "Missed %d RTP frames from sequence [%d] to [%d] (flushed by FS). Time since last read [%d]\n", + num_missed, rtp_session->last_seq+1, seq-1, + rtp_session->last_read_time ? switch_micro_time_now()-rtp_session->last_read_time : 0); + } else if (num_missed > flushed_packets_diff) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, + "Missed %d RTP frames from sequence [%d] to [%d] (%d packets flushed by FS, %d packets missed)." + " Time since last read [%d]\n", + num_missed, rtp_session->last_seq+1, seq-1, + flushed_packets_diff, num_missed-flushed_packets_diff, + rtp_session->last_read_time ? switch_micro_time_now()-rtp_session->last_read_time : 0); + } else { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, + "Missed %d RTP frames from sequence [%d] to [%d] (%d packets flushed by FS). Time since last read [%d]\n", + num_missed, rtp_session->last_seq+1, seq-1, + flushed_packets_diff, rtp_session->last_read_time ? switch_micro_time_now()-rtp_session->last_read_time : 0); + } + } +#endif + } + rtp_session->last_seq = seq; + } + + rtp_session->last_flush_packet_count = rtp_session->stats.inbound.flush_packet_count; + rtp_session->last_read_time = switch_micro_time_now(); + if (*bytes && (!rtp_session->recv_te || rtp_session->recv_msg.header.pt != rtp_session->recv_te) && ts && !rtp_session->jb && !rtp_session->pause_jb && ts == rtp_session->last_cng_ts) { /* we already sent this frame..... */ @@ -2836,173 +3068,20 @@ static int rtp_common_read(switch_rtp_t *rtp_session, switch_payload_t *payload_ bytes = sbytes; } -#ifdef DEBUG_2833 - if (rtp_session->dtmf_data.in_digit_sanity && !(rtp_session->dtmf_data.in_digit_sanity % 100)) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "sanity %d\n", rtp_session->dtmf_data.in_digit_sanity); - } -#endif - if (rtp_session->dtmf_data.in_digit_sanity && !--rtp_session->dtmf_data.in_digit_sanity) { - rtp_session->dtmf_data.last_digit = 0; - rtp_session->dtmf_data.in_digit_ts = 0; - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Failed DTMF sanity check.\n"); - } - - /* RFC2833 ... like all RFC RE: VoIP, guaranteed to drive you to insanity! - We know the real rules here, but if we enforce them, it's an interop nightmare so, - we put up with as much as we can so we don't have to deal with being punished for - doing it right. Nice guys finish last! - */ - if (bytes > rtp_header_len && !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_PROXY_MEDIA) && - !switch_test_flag(rtp_session, SWITCH_RTP_FLAG_PASS_RFC2833) && rtp_session->recv_msg.header.pt == rtp_session->recv_te) { - switch_size_t len = bytes - rtp_header_len; - unsigned char *packet = (unsigned char *) rtp_session->recv_msg.body; - int end; - uint16_t duration; - char key; - uint16_t in_digit_seq; - uint32_t ts; - - - if (!(packet[0] || packet[1] || packet[2] || packet[3]) && len >= 8) { - packet += 4; - len -= 4; - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "DTMF payload offset by 4 bytes.\n"); - } - - if (!(packet[0] || packet[1] || packet[2] || packet[3])) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Failed DTMF payload check.\n"); - rtp_session->dtmf_data.last_digit = 0; - rtp_session->dtmf_data.in_digit_ts = 0; - } - - end = packet[1] & 0x80 ? 1 : 0; - duration = (packet[2] << 8) + packet[3]; - key = switch_rfc2833_to_char(packet[0]); - in_digit_seq = ntohs((uint16_t) rtp_session->recv_msg.header.seq); - ts = htonl(rtp_session->recv_msg.header.ts); - - if (in_digit_seq < rtp_session->dtmf_data.in_digit_seq) { - if (rtp_session->dtmf_data.in_digit_seq - in_digit_seq > 100) { - rtp_session->dtmf_data.in_digit_seq = 0; - } - } -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "packet[%d]: %02x %02x %02x %02x\n", (int) len, (unsigned) packet[0], (unsigned) - packet[1], (unsigned) packet[2], (unsigned) packet[3]); -#endif - - if (in_digit_seq > rtp_session->dtmf_data.in_digit_seq) { - - rtp_session->dtmf_data.in_digit_seq = in_digit_seq; -#ifdef DEBUG_2833 - - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "read: %c %u %u %u %u %d %d %s\n", - key, in_digit_seq, rtp_session->dtmf_data.in_digit_seq, - ts, duration, rtp_session->recv_msg.header.m, end, end && !rtp_session->dtmf_data.in_digit_ts ? "ignored" : ""); -#endif - - if (!rtp_session->dtmf_data.in_digit_queued && (rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION) && - rtp_session->dtmf_data.in_digit_ts) { - switch_dtmf_t dtmf = { key, switch_core_min_dtmf_duration(0) }; -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Early Queuing digit %c:%d\n", dtmf.digit, dtmf.duration / 8); -#endif - switch_rtp_queue_rfc2833_in(rtp_session, &dtmf); - rtp_session->dtmf_data.in_digit_queued = 1; - } - - /* only set sanity if we do NOT ignore the packet */ - if (rtp_session->dtmf_data.in_digit_ts) { - rtp_session->dtmf_data.in_digit_sanity = 2000; - } - - if (rtp_session->dtmf_data.last_duration > duration && - rtp_session->dtmf_data.last_duration > 0xFC17 && ts == rtp_session->dtmf_data.in_digit_ts) { - rtp_session->dtmf_data.flip++; - } - - if (end) { - if (rtp_session->dtmf_data.in_digit_ts) { - switch_dtmf_t dtmf = { key, duration }; - - if (ts > rtp_session->dtmf_data.in_digit_ts) { - dtmf.duration += (ts - rtp_session->dtmf_data.in_digit_ts); - } - if (rtp_session->dtmf_data.flip) { - dtmf.duration += rtp_session->dtmf_data.flip * 0xFFFF; - rtp_session->dtmf_data.flip = 0; -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "you're welcome!\n"); -#endif - } -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "done digit=%c ts=%u start_ts=%u dur=%u ddur=%u\n", - dtmf.digit, ts, rtp_session->dtmf_data.in_digit_ts, duration, dtmf.duration); -#endif - - if (!(rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION) && !rtp_session->dtmf_data.in_digit_queued) { -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Queuing digit %c:%d\n", dtmf.digit, dtmf.duration / 8); -#endif - switch_rtp_queue_rfc2833_in(rtp_session, &dtmf); - } - - rtp_session->dtmf_data.last_digit = rtp_session->dtmf_data.first_digit; - - rtp_session->dtmf_data.in_digit_ts = 0; - rtp_session->dtmf_data.in_digit_sanity = 0; - rtp_session->dtmf_data.in_digit_queued = 0; - do_cng = 1; - } else { - if (!switch_rtp_ready(rtp_session)) { - goto end; - } - switch_cond_next(); - goto recvfrom; - } - - } else if (!rtp_session->dtmf_data.in_digit_ts) { - rtp_session->dtmf_data.in_digit_ts = ts; - rtp_session->dtmf_data.first_digit = key; - rtp_session->dtmf_data.in_digit_sanity = 2000; - } - - rtp_session->dtmf_data.last_duration = duration; - } else { -#ifdef DEBUG_2833 - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "drop: %c %u %u %u %u %d %d\n", - key, in_digit_seq, rtp_session->dtmf_data.in_digit_seq, ts, duration, rtp_session->recv_msg.header.m, end); -#endif - switch_cond_next(); - goto recvfrom; - } - } - - if (rtp_session->dtmf_data.in_digit_ts) { - - } - - - if (bytes && rtp_session->dtmf_data.in_digit_ts) { - if (!switch_rtp_ready(rtp_session)) { - goto end; - } - - if (!rtp_session->dtmf_data.in_interleaved && rtp_session->recv_msg.header.pt != rtp_session->recv_te) { - /* Drat, they are sending audio still as well as DTMF ok fine..... *sigh* */ - rtp_session->dtmf_data.in_interleaved = 1; - } - - if (rtp_session->dtmf_data.in_interleaved || (rtp_session->rtp_bugs & RTP_BUG_IGNORE_DTMF_DURATION)) { - if (rtp_session->recv_msg.header.pt == rtp_session->recv_te) { - goto recvfrom; - } - } else { - return_cng_frame(); - } + /* Handle incoming RFC2833 packets */ + switch (handle_rfc2833(rtp_session, bytes, &do_cng)) { + case RESULT_GOTO_END: + goto end; + case RESULT_GOTO_RECVFROM: + goto recvfrom; + case RESULT_GOTO_TIMERCHECK: + goto timer_check; + case RESULT_CONTINUE: + goto result_continue; } + result_continue: timer_check: if (do_cng) {