From fa3a1a0bdd38a42aa5a1e8b9f3a65d535d20dd3f Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Sun, 4 Aug 2013 23:49:33 -0400 Subject: [PATCH 01/12] Added mod_bert module --- build/modules.conf.in | 1 + configure.ac | 1 + src/mod/applications/mod_bert/Makefile.am | 8 ++ src/mod/applications/mod_bert/mod_bert.c | 143 ++++++++++++++++++++++ 4 files changed, 153 insertions(+) create mode 100644 src/mod/applications/mod_bert/Makefile.am create mode 100644 src/mod/applications/mod_bert/mod_bert.c diff --git a/build/modules.conf.in b/build/modules.conf.in index 44b386f151..71ece983ef 100644 --- a/build/modules.conf.in +++ b/build/modules.conf.in @@ -1,5 +1,6 @@ #applications/mod_abstraction #applications/mod_avmd +#applications/mod_bert #applications/mod_blacklist #applications/mod_callcenter #applications/mod_cidlookup diff --git a/configure.ac b/configure.ac index 02b5e7159c..e8f9efade0 100644 --- a/configure.ac +++ b/configure.ac @@ -1455,6 +1455,7 @@ AC_CONFIG_FILES([Makefile src/mod/Makefile src/mod/applications/mod_abstraction/Makefile src/mod/applications/mod_avmd/Makefile + src/mod/applications/mod_bert/Makefile src/mod/applications/mod_blacklist/Makefile src/mod/applications/mod_callcenter/Makefile src/mod/applications/mod_cidlookup/Makefile diff --git a/src/mod/applications/mod_bert/Makefile.am b/src/mod/applications/mod_bert/Makefile.am new file mode 100644 index 0000000000..97fefcce10 --- /dev/null +++ b/src/mod/applications/mod_bert/Makefile.am @@ -0,0 +1,8 @@ +include $(top_srcdir)/build/modmake.rulesam +MODNAME=mod_bert + +mod_LTLIBRARIES = mod_bert.la +mod_bert_la_SOURCES = mod_bert.c +mod_bert_la_CFLAGS = $(AM_CFLAGS) +mod_bert_la_LIBADD = $(switch_builddir)/libfreeswitch.la +mod_bert_la_LDFLAGS = -avoid-version -module -no-undefined -shared diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c new file mode 100644 index 0000000000..db3ac1efff --- /dev/null +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -0,0 +1,143 @@ +/* + * FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application + * Copyright (C) 2005-2011, Anthony Minessale II + * + * Version: MPL 1.1 + * + * The contents of this file are subject to the Mozilla Public License Version + * 1.1 (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * http://www.mozilla.org/MPL/ + * + * Software distributed under the License is distributed on an "AS IS" basis, + * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License + * for the specific language governing rights and limitations under the + * License. + * + * The Original Code is FreeSWITCH Modular Media Switching Software Library / Oreka Recording Module + * + * The Initial Developer of the Original Code is + * Moises Silva + * Portions created by the Initial Developer are Copyright (C) + * the Initial Developer. All Rights Reserved. + * + * Contributor(s): + * Moises Silva + * + * mod_g711_bert -- Naive BERT tester + * + */ + +#include + +SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load); +SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown); +SWITCH_MODULE_DEFINITION(mod_bert, mod_bert_load, mod_bert_shutdown, NULL); + +SWITCH_STANDARD_APP(g711_bert_function) +{ + switch_status_t status; + switch_frame_t *read_frame = NULL, write_frame = { 0 }; + switch_codec_implementation_t read_impl = { 0 }; + switch_channel_t *channel = NULL; + int i = 0; + uint32_t interval = 0; + uint32_t ts = 0; + struct { + uint64_t sync; + uint32_t bytes_since_sync; + uint32_t min_sync_samples; + uint32_t max_sync_err; + uint32_t sync_err; + int16_t tx_sample; + int16_t test_data; + } bert; + + memset(&bert, 0, sizeof(bert)); + channel = switch_core_session_get_channel(session); + + switch_channel_answer(channel); + + switch_core_session_get_read_impl(session, &read_impl); + + interval = read_impl.microseconds_per_packet / 1000; + + write_frame.codec = switch_core_session_get_read_codec(session); + write_frame.data = switch_core_session_alloc(session, SWITCH_RECOMMENDED_BUFFER_SIZE); + write_frame.buflen = SWITCH_RECOMMENDED_BUFFER_SIZE; + + bert.min_sync_samples = (read_impl.samples_per_packet * 40); + bert.max_sync_err = (read_impl.samples_per_packet * 20); + while (switch_channel_ready(channel)) { + int16_t *read_samples = NULL; + int16_t *write_samples = NULL; + status = switch_core_session_read_frame(session, &read_frame, SWITCH_IO_FLAG_NONE, 0); + if (!SWITCH_READ_ACCEPTABLE(status)) { + break; + } + /* BERT Sync */ + read_samples = read_frame->data; + write_samples = write_frame.data; + for (i = 0; i < (read_frame->datalen / 2); i++) { + if (bert.sync < bert.min_sync_samples) { + if (bert.test_data == read_samples[i]) { + bert.sync++; + } + } else { + if (bert.sync == bert.min_sync_samples) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "G.711 synced (%lu)\n", bert.sync); + bert.bytes_since_sync = 0; + bert.sync_err = 0; + } + bert.bytes_since_sync++; + if (bert.test_data != read_samples[i]) { + bert.sync_err++; + if (bert.sync_err >= bert.max_sync_err) { + bert.sync = 0; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "G.711 sync lost (%u)\n", bert.bytes_since_sync); + } + } else { + bert.sync++; + } + } + bert.test_data = (read_samples[i] + 1); + + write_samples[i] = bert.tx_sample++; + } + + write_frame.datalen = read_frame->datalen; + write_frame.samples = i; + write_frame.timestamp = ts; + status = switch_core_session_write_frame(session, &write_frame, SWITCH_IO_FLAG_NONE, 0); + if (!SWITCH_READ_ACCEPTABLE(status)) { + break; + } + ts += read_impl.samples_per_packet; + } +} + +SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load) +{ + switch_application_interface_t *app_interface = NULL; + + *module_interface = switch_loadable_module_create_module_interface(pool, modname); + + SWITCH_ADD_APP(app_interface, "bert_test", "Start BERT Test", "Start BERT Test", g711_bert_function, "", SAF_NONE); + return SWITCH_STATUS_SUCCESS; +} + +SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown) +{ + return SWITCH_STATUS_UNLOAD; +} + +/* For Emacs: + * Local Variables: + * mode:c + * indent-tabs-mode:nil + * tab-width:4 + * c-basic-offset:4 + * End: + * For VIM: + * vim:set softtabstop=4 shiftwidth=4 tabstop=4: + */ From 66a9e12aa8c5e7b75711790442d55eba30da9cbf Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Mon, 5 Aug 2013 01:30:44 -0400 Subject: [PATCH 02/12] Improvements to mod_bert * Calculate sampling error rate over a time window * Create the following variables to control bert testing behavior: bert_timeout_ms - Milliseconds to wait for bert sync before timing out bert_window_ms - Window of time to calculate sampling error rate percentage bert_max_err - Max percentage of error tolerated before going out of sync bert_hangup_on_error - Hangup when error occurs (Timeout or going out of sync) --- src/mod/applications/mod_bert/mod_bert.c | 138 +++++++++++++++++------ 1 file changed, 102 insertions(+), 36 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index db3ac1efff..917edc4cc4 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -24,7 +24,7 @@ * Contributor(s): * Moises Silva * - * mod_g711_bert -- Naive BERT tester + * mod_bert -- Naive BERT tester * */ @@ -34,40 +34,84 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load); SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown); SWITCH_MODULE_DEFINITION(mod_bert, mod_bert_load, mod_bert_shutdown, NULL); -SWITCH_STANDARD_APP(g711_bert_function) +#define BERT_DEFAULT_WINDOW_MS 1000 +#define BERT_DEFAULT_MAX_ERR 10.0 +#define BERT_DEFAULT_TIMEOUT_MS 10000 +SWITCH_STANDARD_APP(bert_test_function) { switch_status_t status; switch_frame_t *read_frame = NULL, write_frame = { 0 }; switch_codec_implementation_t read_impl = { 0 }; switch_channel_t *channel = NULL; + const char *var = NULL; int i = 0; - uint32_t interval = 0; + int synced = 0; uint32_t ts = 0; + int32_t timeout_ms = 0; struct { - uint64_t sync; - uint32_t bytes_since_sync; - uint32_t min_sync_samples; - uint32_t max_sync_err; - uint32_t sync_err; - int16_t tx_sample; - int16_t test_data; + uint32_t processed_samples; + uint32_t err_samples; + uint32_t window_ms; + uint32_t window_samples; + int16_t sequence_sample; + int16_t predicted_sample; + float max_err; + float max_err_hit; + float max_err_ever; + uint8_t in_sync; + uint8_t hangup_on_error; + switch_time_t timeout; } bert; - memset(&bert, 0, sizeof(bert)); channel = switch_core_session_get_channel(session); switch_channel_answer(channel); switch_core_session_get_read_impl(session, &read_impl); - interval = read_impl.microseconds_per_packet / 1000; + memset(&bert, 0, sizeof(bert)); + bert.window_ms = BERT_DEFAULT_WINDOW_MS; + bert.window_samples = switch_samples_per_packet(read_impl.samples_per_second, bert.window_ms); + bert.max_err = BERT_DEFAULT_MAX_ERR; + timeout_ms = BERT_DEFAULT_TIMEOUT_MS; + + /* check if there are user-defined overrides */ + if ((var = switch_channel_get_variable(channel, "bert_window_ms"))) { + int tmp = atoi(var); + if (tmp > 0) { + bert.window_ms = tmp; + bert.window_samples = switch_samples_per_packet(read_impl.samples_per_second, bert.window_ms); + } + } + if ((var = switch_channel_get_variable(channel, "bert_timeout_ms"))) { + int tmp = atoi(var); + if (tmp > 0) { + timeout_ms = tmp; + } + } + if ((var = switch_channel_get_variable(channel, "bert_max_err"))) { + double tmp = atoi(var); + if (tmp > 0) { + bert.max_err = (float)tmp; + } + } + if ((var = switch_channel_get_variable(channel, "bert_hangup_on_error"))) { + if (switch_true(var)) { + bert.hangup_on_error = 1; + } + } + + bert.timeout = (switch_micro_time_now() + (timeout_ms * 1000)); write_frame.codec = switch_core_session_get_read_codec(session); write_frame.data = switch_core_session_alloc(session, SWITCH_RECOMMENDED_BUFFER_SIZE); write_frame.buflen = SWITCH_RECOMMENDED_BUFFER_SIZE; - bert.min_sync_samples = (read_impl.samples_per_packet * 40); - bert.max_sync_err = (read_impl.samples_per_packet * 20); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Window=%ums/%u MaxErr=%f%%\n", bert.window_ms, bert.window_samples, bert.max_err); + if (bert.window_samples <= 0) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to compute BERT window samples!\n"); + goto done; + } while (switch_channel_ready(channel)) { int16_t *read_samples = NULL; int16_t *write_samples = NULL; @@ -79,30 +123,48 @@ SWITCH_STANDARD_APP(g711_bert_function) read_samples = read_frame->data; write_samples = write_frame.data; for (i = 0; i < (read_frame->datalen / 2); i++) { - if (bert.sync < bert.min_sync_samples) { - if (bert.test_data == read_samples[i]) { - bert.sync++; - } - } else { - if (bert.sync == bert.min_sync_samples) { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "G.711 synced (%lu)\n", bert.sync); - bert.bytes_since_sync = 0; - bert.sync_err = 0; - } - bert.bytes_since_sync++; - if (bert.test_data != read_samples[i]) { - bert.sync_err++; - if (bert.sync_err >= bert.max_sync_err) { - bert.sync = 0; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "G.711 sync lost (%u)\n", bert.bytes_since_sync); + if (bert.window_samples == bert.processed_samples) { + /* Calculate error rate */ + float err = ((float)((float)bert.err_samples / (float)bert.processed_samples) * 100.0); + if (err > bert.max_err) { + if (bert.in_sync) { + bert.in_sync = 0; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss\n", err); + if (bert.hangup_on_error) { + switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); + } + } + } else if (!bert.in_sync) { + bert.in_sync = 1; + synced = 1; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "BERT Sync\n"); + bert.timeout = 0; + } + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "Err=%f%% (%u/%u)\n", err, bert.err_samples, bert.processed_samples); + if (synced && err > bert.max_err_hit) { + bert.max_err_hit = err; + } + if (err > bert.max_err_ever) { + bert.max_err_ever = err; + } + bert.processed_samples = 0; + bert.err_samples = 0; + if (bert.timeout && !synced) { + switch_time_t now = switch_micro_time_now(); + if (now >= bert.timeout) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout\n"); + if (bert.hangup_on_error) { + switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); + } } - } else { - bert.sync++; } } - bert.test_data = (read_samples[i] + 1); - - write_samples[i] = bert.tx_sample++; + if (bert.predicted_sample != read_samples[i]) { + bert.err_samples++; + } + bert.predicted_sample = (read_samples[i] + 1); + write_samples[i] = bert.sequence_sample++; + bert.processed_samples++; } write_frame.datalen = read_frame->datalen; @@ -114,6 +176,10 @@ SWITCH_STANDARD_APP(g711_bert_function) } ts += read_impl.samples_per_packet; } + +done: + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Completed. MaxErr=%f%%\n", synced ? bert.max_err_hit : bert.max_err_ever); + } SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load) @@ -122,7 +188,7 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load) *module_interface = switch_loadable_module_create_module_interface(pool, modname); - SWITCH_ADD_APP(app_interface, "bert_test", "Start BERT Test", "Start BERT Test", g711_bert_function, "", SAF_NONE); + SWITCH_ADD_APP(app_interface, "bert_test", "Start BERT Test", "Start BERT Test", bert_test_function, "", SAF_NONE); return SWITCH_STATUS_SUCCESS; } From a60876b165012dcc8ac333661e24ce3a119b5e2f Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Tue, 6 Aug 2013 12:29:26 -0400 Subject: [PATCH 03/12] Use a triangle wave in mod_bert --- src/mod/applications/mod_bert/mod_bert.c | 30 +++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 917edc4cc4..45f911bf4b 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -34,6 +34,19 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load); SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown); SWITCH_MODULE_DEFINITION(mod_bert, mod_bert_load, mod_bert_shutdown, NULL); +static int16_t bert_next_sample(int16_t sample, uint8_t *going_up) +{ + if (sample == INT16_MAX || !(*going_up)) { + *going_up = 0; + return --sample; + } + if (sample == INT16_MIN || *going_up) { + *going_up = 1; + return ++sample; + } + switch_assert(0); +} + #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 #define BERT_DEFAULT_TIMEOUT_MS 10000 @@ -55,11 +68,14 @@ SWITCH_STANDARD_APP(bert_test_function) uint32_t window_samples; int16_t sequence_sample; int16_t predicted_sample; + int16_t previous_sample; float max_err; float max_err_hit; float max_err_ever; uint8_t in_sync; uint8_t hangup_on_error; + uint8_t sequence_going_up; + uint8_t prediction_going_up; switch_time_t timeout; } bert; @@ -73,6 +89,7 @@ SWITCH_STANDARD_APP(bert_test_function) bert.window_ms = BERT_DEFAULT_WINDOW_MS; bert.window_samples = switch_samples_per_packet(read_impl.samples_per_second, bert.window_ms); bert.max_err = BERT_DEFAULT_MAX_ERR; + bert.sequence_going_up = 1; timeout_ms = BERT_DEFAULT_TIMEOUT_MS; /* check if there are user-defined overrides */ @@ -137,7 +154,7 @@ SWITCH_STANDARD_APP(bert_test_function) } else if (!bert.in_sync) { bert.in_sync = 1; synced = 1; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "BERT Sync\n"); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "BERT Sync Success\n"); bert.timeout = 0; } switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "Err=%f%% (%u/%u)\n", err, bert.err_samples, bert.processed_samples); @@ -162,8 +179,15 @@ SWITCH_STANDARD_APP(bert_test_function) if (bert.predicted_sample != read_samples[i]) { bert.err_samples++; } - bert.predicted_sample = (read_samples[i] + 1); - write_samples[i] = bert.sequence_sample++; + if (bert.previous_sample > read_samples[i]) { + bert.prediction_going_up = 0; + } else { + bert.prediction_going_up = 1; + } + bert.predicted_sample = bert_next_sample(read_samples[i], &bert.prediction_going_up); + bert.sequence_sample = bert_next_sample(bert.sequence_sample, &bert.sequence_going_up); + write_samples[i] = bert.sequence_sample; + bert.previous_sample = read_samples[i]; bert.processed_samples++; } From d3b214a67244d8968005420783654bca91b805c9 Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Tue, 13 Aug 2013 17:35:35 -0400 Subject: [PATCH 04/12] Improvements to mod_bert * Use digital milliwatt as the test sequence pattern * Add debug IO files (enabled using bert_debug_io_file variable) --- src/mod/applications/mod_bert/mod_bert.c | 170 +++++++++++++++-------- 1 file changed, 113 insertions(+), 57 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 45f911bf4b..921d8bb821 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -34,18 +34,36 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load); SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown); SWITCH_MODULE_DEFINITION(mod_bert, mod_bert_load, mod_bert_shutdown, NULL); -static int16_t bert_next_sample(int16_t sample, uint8_t *going_up) -{ - if (sample == INT16_MAX || !(*going_up)) { - *going_up = 0; - return --sample; - } - if (sample == INT16_MIN || *going_up) { - *going_up = 1; - return ++sample; - } - switch_assert(0); -} +/* http://en.wikipedia.org/wiki/Digital_milliwatt */ +unsigned char ulaw_digital_milliwatt[8] = { 0x1e, 0x0b, 0x0b, 0x1e, 0x9e, 0x8b, 0x8b, 0x9e }; + +typedef struct { + uint32_t processed_samples; + uint32_t err_samples; + uint32_t window_ms; + uint32_t window_samples; + uint8_t sequence_sample; + uint8_t predicted_sample; + float max_err; + float max_err_hit; + float max_err_ever; + uint8_t in_sync; + uint8_t hangup_on_error; + uint8_t milliwatt_index; + uint8_t milliwatt_prediction_index; + switch_time_t timeout; + FILE *input_debug_f; + FILE *output_debug_f; +} bert_t; + +#define bert_increase_milliwatt_index(index) \ + do { \ + if ((index) == (switch_arraylen(ulaw_digital_milliwatt)-1)) { \ + (index) = 0; \ + } else { \ + (index) = ((index) + 1); \ + } \ + } while (0); #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 @@ -59,25 +77,11 @@ SWITCH_STANDARD_APP(bert_test_function) const char *var = NULL; int i = 0; int synced = 0; - uint32_t ts = 0; + uint32_t write_ts = 0; int32_t timeout_ms = 0; - struct { - uint32_t processed_samples; - uint32_t err_samples; - uint32_t window_ms; - uint32_t window_samples; - int16_t sequence_sample; - int16_t predicted_sample; - int16_t previous_sample; - float max_err; - float max_err_hit; - float max_err_ever; - uint8_t in_sync; - uint8_t hangup_on_error; - uint8_t sequence_going_up; - uint8_t prediction_going_up; - switch_time_t timeout; - } bert; + bert_t bert = { 0 }; + + memset(&bert, 0, sizeof(bert)); channel = switch_core_session_get_channel(session); @@ -85,11 +89,14 @@ SWITCH_STANDARD_APP(bert_test_function) switch_core_session_get_read_impl(session, &read_impl); - memset(&bert, 0, sizeof(bert)); + if (read_impl.ianacode != 0) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "This application only works when using ulaw codec\n"); + goto done; + } + bert.window_ms = BERT_DEFAULT_WINDOW_MS; bert.window_samples = switch_samples_per_packet(read_impl.samples_per_second, bert.window_ms); bert.max_err = BERT_DEFAULT_MAX_ERR; - bert.sequence_going_up = 1; timeout_ms = BERT_DEFAULT_TIMEOUT_MS; /* check if there are user-defined overrides */ @@ -117,6 +124,19 @@ SWITCH_STANDARD_APP(bert_test_function) bert.hangup_on_error = 1; } } + if ((var = switch_channel_get_variable(channel, "bert_debug_io_file"))) { + char debug_file[1024]; + snprintf(debug_file, sizeof(debug_file), "%s.in", var); + bert.input_debug_f = fopen(debug_file, "w"); + if (!bert.input_debug_f) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to open input debug file %s\n", debug_file); + } + snprintf(debug_file, sizeof(debug_file), "%s.out", var); + bert.output_debug_f = fopen(debug_file, "w"); + if (!bert.output_debug_f) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to open output debug file %s\n", debug_file); + } + } bert.timeout = (switch_micro_time_now() + (timeout_ms * 1000)); @@ -124,22 +144,50 @@ SWITCH_STANDARD_APP(bert_test_function) write_frame.data = switch_core_session_alloc(session, SWITCH_RECOMMENDED_BUFFER_SIZE); write_frame.buflen = SWITCH_RECOMMENDED_BUFFER_SIZE; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Window=%ums/%u MaxErr=%f%%\n", bert.window_ms, bert.window_samples, bert.max_err); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Window=%ums/%u, MaxErr=%f%%, Timeout=%dms\n", bert.window_ms, bert.window_samples, bert.max_err, timeout_ms); if (bert.window_samples <= 0) { switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to compute BERT window samples!\n"); goto done; } while (switch_channel_ready(channel)) { - int16_t *read_samples = NULL; - int16_t *write_samples = NULL; + uint8_t *read_samples = NULL; + uint8_t *write_samples = NULL; + status = switch_core_session_read_frame(session, &read_frame, SWITCH_IO_FLAG_NONE, 0); if (!SWITCH_READ_ACCEPTABLE(status)) { break; } - /* BERT Sync */ + + if (bert.timeout && !synced) { + switch_time_t now = switch_micro_time_now(); + if (now >= bert.timeout) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout (read_samples=%d, read_bytes=%d, expected_samples=%d, %s)\n", + read_frame->samples, read_frame->datalen, read_impl.samples_per_packet, switch_core_session_get_uuid(session)); + if (bert.hangup_on_error) { + switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); + } + } + } + + if (!read_frame->datalen) { + continue; + } + + if (read_frame->samples != read_impl.samples_per_packet) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "Only read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); + continue; + } + read_samples = read_frame->data; write_samples = write_frame.data; - for (i = 0; i < (read_frame->datalen / 2); i++) { + if (read_frame->samples) { + if (bert.input_debug_f) { + fwrite(read_frame->data, read_frame->datalen, 1, bert.input_debug_f); + } + } + + /* BERT Sync Loop */ + for (i = 0; i < read_frame->samples; i++) { if (bert.window_samples == bert.processed_samples) { /* Calculate error rate */ float err = ((float)((float)bert.err_samples / (float)bert.processed_samples) * 100.0); @@ -166,44 +214,52 @@ SWITCH_STANDARD_APP(bert_test_function) } bert.processed_samples = 0; bert.err_samples = 0; - if (bert.timeout && !synced) { - switch_time_t now = switch_micro_time_now(); - if (now >= bert.timeout) { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout\n"); - if (bert.hangup_on_error) { - switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); - } - } - } } + if (bert.predicted_sample != read_samples[i]) { bert.err_samples++; + if (!bert.in_sync) { + /* If we're not in sync, we must reset the index on error to start the pattern detection again */ + bert.milliwatt_prediction_index = 0; + } } - if (bert.previous_sample > read_samples[i]) { - bert.prediction_going_up = 0; - } else { - bert.prediction_going_up = 1; - } - bert.predicted_sample = bert_next_sample(read_samples[i], &bert.prediction_going_up); - bert.sequence_sample = bert_next_sample(bert.sequence_sample, &bert.sequence_going_up); + + /* Calculate our next sequence sample to write */ + bert.sequence_sample = ulaw_digital_milliwatt[bert.milliwatt_index]; + //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); + bert_increase_milliwatt_index(bert.milliwatt_index); + //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); write_samples[i] = bert.sequence_sample; - bert.previous_sample = read_samples[i]; + + /* Try to guess what the next sample will be in the milliwatt sequence */ + bert.predicted_sample = ulaw_digital_milliwatt[bert.milliwatt_prediction_index]; + bert_increase_milliwatt_index(bert.milliwatt_prediction_index); + bert.processed_samples++; } write_frame.datalen = read_frame->datalen; write_frame.samples = i; - write_frame.timestamp = ts; + write_frame.timestamp = write_ts; + if (bert.output_debug_f) { + fwrite(write_frame.data, write_frame.datalen, 1, bert.output_debug_f); + } status = switch_core_session_write_frame(session, &write_frame, SWITCH_IO_FLAG_NONE, 0); if (!SWITCH_READ_ACCEPTABLE(status)) { break; } - ts += read_impl.samples_per_packet; + + write_ts += read_impl.samples_per_packet; } done: + if (bert.input_debug_f) { + fclose(bert.input_debug_f); + } + if (bert.output_debug_f) { + fclose(bert.output_debug_f); + } switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Completed. MaxErr=%f%%\n", synced ? bert.max_err_hit : bert.max_err_ever); - } SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load) From a84ce1dd3c68f4b57824f6aa286bdf6fdd08cabb Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Fri, 16 Aug 2013 16:30:10 -0400 Subject: [PATCH 05/12] Improvements to mod_bert * Improve bert input debug * Check for SFF_CNG and ignore those frames --- src/mod/applications/mod_bert/mod_bert.c | 43 +++++++++++++++++------- 1 file changed, 30 insertions(+), 13 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 921d8bb821..cd1b5b12de 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -65,6 +65,25 @@ typedef struct { } \ } while (0); +#define bert_close_debug_streams(bert, session) \ + do { \ + int rc = 0; \ + if (bert.input_debug_f) { \ + rc = fclose(bert.input_debug_f); \ + if (rc) { \ + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to close BERT input debug file!\n"); \ + } \ + bert.input_debug_f = NULL; \ + } \ + if (bert.output_debug_f) { \ + rc = fclose(bert.output_debug_f); \ + if (rc) { \ + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to close BERT output debug file!\n"); \ + } \ + bert.output_debug_f = NULL; \ + } \ + } while (0); + #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 #define BERT_DEFAULT_TIMEOUT_MS 10000 @@ -161,7 +180,7 @@ SWITCH_STANDARD_APP(bert_test_function) if (bert.timeout && !synced) { switch_time_t now = switch_micro_time_now(); if (now >= bert.timeout) { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout (read_samples=%d, read_bytes=%d, expected_samples=%d, %s)\n", + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout (read_samples=%d, read_bytes=%d, expected_samples=%d, session=%s)\n", read_frame->samples, read_frame->datalen, read_impl.samples_per_packet, switch_core_session_get_uuid(session)); if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); @@ -169,20 +188,22 @@ SWITCH_STANDARD_APP(bert_test_function) } } - if (!read_frame->datalen) { + /* Ignore confort noise, TODO: we should probably deal with this and treat it as a full frame of silence?? */ + if (switch_test_flag(read_frame, SFF_CNG) || !read_frame->datalen) { continue; } if (read_frame->samples != read_impl.samples_per_packet) { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "Only read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Only read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); continue; } read_samples = read_frame->data; write_samples = write_frame.data; - if (read_frame->samples) { - if (bert.input_debug_f) { - fwrite(read_frame->data, read_frame->datalen, 1, bert.input_debug_f); + if (bert.input_debug_f) { + size_t ret = fwrite(read_frame->data, read_frame->datalen, 1, bert.input_debug_f); + if (ret != 1) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to write to BERT input debug file!\n"); } } @@ -194,9 +215,10 @@ SWITCH_STANDARD_APP(bert_test_function) if (err > bert.max_err) { if (bert.in_sync) { bert.in_sync = 0; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss\n", err); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss (err_samples=%u, session=%s)\n", err, bert.err_samples, switch_core_session_get_uuid(session)); if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); + bert_close_debug_streams(bert, session); } } } else if (!bert.in_sync) { @@ -253,12 +275,7 @@ SWITCH_STANDARD_APP(bert_test_function) } done: - if (bert.input_debug_f) { - fclose(bert.input_debug_f); - } - if (bert.output_debug_f) { - fclose(bert.output_debug_f); - } + bert_close_debug_streams(bert, session); switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Completed. MaxErr=%f%%\n", synced ? bert.max_err_hit : bert.max_err_ever); } From ef694513df394c684dfc0878c1a6c4194234108c Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Fri, 16 Aug 2013 17:39:18 -0400 Subject: [PATCH 06/12] Improvements to mod_bert * Added BERT stats channel variables * Check if the channel is going down when out of sync to avoid flagging it as out of sync, if the channel is going down it is expected to have some errors --- src/mod/applications/mod_bert/mod_bert.c | 20 ++++++++++++++++++-- 1 file changed, 18 insertions(+), 2 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index cd1b5b12de..2f546f5cdf 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -42,6 +42,7 @@ typedef struct { uint32_t err_samples; uint32_t window_ms; uint32_t window_samples; + uint32_t stats_sync_lost_cnt; uint8_t sequence_sample; uint8_t predicted_sample; float max_err; @@ -84,6 +85,9 @@ typedef struct { } \ } while (0); +#define BERT_STATS_VAR_SYNC_LOST "bert_stats_sync_lost" +#define BERT_STATS_VAR_SYNC_LOST_CNT "bert_stats_sync_lost_count" + #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 #define BERT_DEFAULT_TIMEOUT_MS 10000 @@ -168,6 +172,8 @@ SWITCH_STANDARD_APP(bert_test_function) switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to compute BERT window samples!\n"); goto done; } + switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "0"); + switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "false"); while (switch_channel_ready(channel)) { uint8_t *read_samples = NULL; uint8_t *write_samples = NULL; @@ -210,12 +216,22 @@ SWITCH_STANDARD_APP(bert_test_function) /* BERT Sync Loop */ for (i = 0; i < read_frame->samples; i++) { if (bert.window_samples == bert.processed_samples) { + float err = 0.0; + /* If the channel is going down, then it is expected we'll have errors, ignore them and bail out */ + if (!switch_channel_ready(channel)) { + bert_close_debug_streams(bert, session); + break; + } /* Calculate error rate */ - float err = ((float)((float)bert.err_samples / (float)bert.processed_samples) * 100.0); + err = ((float)((float)bert.err_samples / (float)bert.processed_samples) * 100.0); if (err > bert.max_err) { if (bert.in_sync) { bert.in_sync = 0; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss (err_samples=%u, session=%s)\n", err, bert.err_samples, switch_core_session_get_uuid(session)); + bert.stats_sync_lost_cnt++; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss (count=%u, err_samples=%u, session=%s)\n", + err, bert.stats_sync_lost_cnt, bert.err_samples, switch_core_session_get_uuid(session)); + switch_channel_set_variable_printf(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "%u", bert.stats_sync_lost_cnt); + switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "true"); if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); bert_close_debug_streams(bert, session); From 3248e06b914628d0973386a2bd9b998b795e4d79 Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Mon, 19 Aug 2013 15:43:26 -0400 Subject: [PATCH 07/12] Add timer to mod_bert to avoid relying on remote RTP for timing --- src/mod/applications/mod_bert/mod_bert.c | 69 +++++++++++++++--------- 1 file changed, 44 insertions(+), 25 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 2f546f5cdf..686a0293c5 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -55,6 +55,7 @@ typedef struct { switch_time_t timeout; FILE *input_debug_f; FILE *output_debug_f; + switch_timer_t timer; } bert_t; #define bert_increase_milliwatt_index(index) \ @@ -100,8 +101,11 @@ SWITCH_STANDARD_APP(bert_test_function) const char *var = NULL; int i = 0; int synced = 0; - uint32_t write_ts = 0; int32_t timeout_ms = 0; + int32_t interval = 20; + int32_t samples = 0; + uint8_t *write_samples = NULL; + uint8_t *read_samples = NULL; bert_t bert = { 0 }; memset(&bert, 0, sizeof(bert)); @@ -161,6 +165,16 @@ SWITCH_STANDARD_APP(bert_test_function) } } + /* Setup the timer, so we can send audio at correct time frames even if we do not receive audio */ + interval = read_impl.microseconds_per_packet / 1000; + samples = switch_samples_per_packet(read_impl.samples_per_second, interval); + if (switch_core_timer_init(&bert.timer, "soft", interval, samples, switch_core_session_get_pool(session)) == SWITCH_STATUS_SUCCESS) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Setup timer success interval: %u samples: %u\n", interval, samples); + } else { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Timer Setup Failed. BERT cannot start!\n"); + goto done; + } + bert.timeout = (switch_micro_time_now() + (timeout_ms * 1000)); write_frame.codec = switch_core_session_get_read_codec(session); @@ -174,10 +188,32 @@ SWITCH_STANDARD_APP(bert_test_function) } switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "0"); switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "false"); + write_samples = write_frame.data; while (switch_channel_ready(channel)) { - uint8_t *read_samples = NULL; - uint8_t *write_samples = NULL; + switch_core_timer_next(&bert.timer); + /* Write our frame before anything else happens */ + for (i = 0; i < read_impl.samples_per_packet; i++) { + /* Calculate our next sequence sample to write */ + bert.sequence_sample = ulaw_digital_milliwatt[bert.milliwatt_index]; + //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); + bert_increase_milliwatt_index(bert.milliwatt_index); + //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); + write_samples[i] = bert.sequence_sample; + } + + write_frame.datalen = read_impl.samples_per_packet; + write_frame.samples = read_impl.samples_per_packet; + write_frame.timestamp = bert.timer.samplecount; + if (bert.output_debug_f) { + fwrite(write_frame.data, write_frame.datalen, 1, bert.output_debug_f); + } + status = switch_core_session_write_frame(session, &write_frame, SWITCH_IO_FLAG_NONE, 0); + if (!SWITCH_READ_ACCEPTABLE(status)) { + break; + } + + /* Proceed to read and process the readed frame ... */ status = switch_core_session_read_frame(session, &read_frame, SWITCH_IO_FLAG_NONE, 0); if (!SWITCH_READ_ACCEPTABLE(status)) { break; @@ -191,6 +227,7 @@ SWITCH_STANDARD_APP(bert_test_function) if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); } + bert.timeout = 0; } } @@ -200,12 +237,11 @@ SWITCH_STANDARD_APP(bert_test_function) } if (read_frame->samples != read_impl.samples_per_packet) { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Only read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); continue; } read_samples = read_frame->data; - write_samples = write_frame.data; if (bert.input_debug_f) { size_t ret = fwrite(read_frame->data, read_frame->datalen, 1, bert.input_debug_f); if (ret != 1) { @@ -262,36 +298,19 @@ SWITCH_STANDARD_APP(bert_test_function) } } - /* Calculate our next sequence sample to write */ - bert.sequence_sample = ulaw_digital_milliwatt[bert.milliwatt_index]; - //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); - bert_increase_milliwatt_index(bert.milliwatt_index); - //switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "[%d] 0x%X\n", bert.milliwatt_index, bert.sequence_sample); - write_samples[i] = bert.sequence_sample; - /* Try to guess what the next sample will be in the milliwatt sequence */ bert.predicted_sample = ulaw_digital_milliwatt[bert.milliwatt_prediction_index]; bert_increase_milliwatt_index(bert.milliwatt_prediction_index); bert.processed_samples++; } - - write_frame.datalen = read_frame->datalen; - write_frame.samples = i; - write_frame.timestamp = write_ts; - if (bert.output_debug_f) { - fwrite(write_frame.data, write_frame.datalen, 1, bert.output_debug_f); - } - status = switch_core_session_write_frame(session, &write_frame, SWITCH_IO_FLAG_NONE, 0); - if (!SWITCH_READ_ACCEPTABLE(status)) { - break; - } - - write_ts += read_impl.samples_per_packet; } done: bert_close_debug_streams(bert, session); + if (bert.timer.interval) { + switch_core_timer_destroy(&bert.timer); + } switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "BERT Test Completed. MaxErr=%f%%\n", synced ? bert.max_err_hit : bert.max_err_ever); } From cf2fd15211124274525c8e3885b701e289097544 Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Tue, 27 Aug 2013 21:07:13 -0400 Subject: [PATCH 08/12] Add BERT events for timeout and out of sync in mod_bert --- src/mod/applications/mod_bert/mod_bert.c | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 686a0293c5..df254c0f82 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -89,6 +89,9 @@ typedef struct { #define BERT_STATS_VAR_SYNC_LOST "bert_stats_sync_lost" #define BERT_STATS_VAR_SYNC_LOST_CNT "bert_stats_sync_lost_count" +#define BERT_EVENT_TIMEOUT "mod_bert::timeout" +#define BERT_EVENT_LOST_SYNC "mod_bert::lost_sync" + #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 #define BERT_DEFAULT_TIMEOUT_MS 10000 @@ -98,6 +101,7 @@ SWITCH_STANDARD_APP(bert_test_function) switch_frame_t *read_frame = NULL, write_frame = { 0 }; switch_codec_implementation_t read_impl = { 0 }; switch_channel_t *channel = NULL; + switch_event_t *event = NULL; const char *var = NULL; int i = 0; int synced = 0; @@ -222,12 +226,16 @@ SWITCH_STANDARD_APP(bert_test_function) if (bert.timeout && !synced) { switch_time_t now = switch_micro_time_now(); if (now >= bert.timeout) { + bert.timeout = 0; switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Timeout (read_samples=%d, read_bytes=%d, expected_samples=%d, session=%s)\n", read_frame->samples, read_frame->datalen, read_impl.samples_per_packet, switch_core_session_get_uuid(session)); + if (switch_event_create_subclass(&event, SWITCH_EVENT_CUSTOM, BERT_EVENT_TIMEOUT) == SWITCH_STATUS_SUCCESS) { + switch_channel_event_set_basic_data(channel, event); + switch_event_fire(&event); + } if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); } - bert.timeout = 0; } } @@ -268,6 +276,10 @@ SWITCH_STANDARD_APP(bert_test_function) err, bert.stats_sync_lost_cnt, bert.err_samples, switch_core_session_get_uuid(session)); switch_channel_set_variable_printf(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "%u", bert.stats_sync_lost_cnt); switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "true"); + if (switch_event_create_subclass(&event, SWITCH_EVENT_CUSTOM, BERT_EVENT_LOST_SYNC) == SWITCH_STATUS_SUCCESS) { + switch_channel_event_set_basic_data(channel, event); + switch_event_fire(&event); + } if (bert.hangup_on_error) { switch_channel_hangup(channel, SWITCH_CAUSE_MEDIA_TIMEOUT); bert_close_debug_streams(bert, session); From 58e47748ca621fd3cafcb6f5e8b528fb1279d79d Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Tue, 3 Sep 2013 09:41:51 -0400 Subject: [PATCH 09/12] Only use a timer if bert_timer_name is specified, otherwise time based on input --- src/mod/applications/mod_bert/mod_bert.c | 46 ++++++++++++++++++------ 1 file changed, 35 insertions(+), 11 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index df254c0f82..62d7e319c3 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -110,6 +110,7 @@ SWITCH_STANDARD_APP(bert_test_function) int32_t samples = 0; uint8_t *write_samples = NULL; uint8_t *read_samples = NULL; + const char *timer_name = NULL; bert_t bert = { 0 }; memset(&bert, 0, sizeof(bert)); @@ -168,15 +169,21 @@ SWITCH_STANDARD_APP(bert_test_function) switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to open output debug file %s\n", debug_file); } } + if ((var = switch_channel_get_variable(channel, "bert_timer_name"))) { + timer_name = var; + } /* Setup the timer, so we can send audio at correct time frames even if we do not receive audio */ - interval = read_impl.microseconds_per_packet / 1000; - samples = switch_samples_per_packet(read_impl.samples_per_second, interval); - if (switch_core_timer_init(&bert.timer, "soft", interval, samples, switch_core_session_get_pool(session)) == SWITCH_STATUS_SUCCESS) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Setup timer success interval: %u samples: %u\n", interval, samples); - } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Timer Setup Failed. BERT cannot start!\n"); - goto done; + if (timer_name) { + interval = read_impl.microseconds_per_packet / 1000; + samples = switch_samples_per_packet(read_impl.samples_per_second, interval); + if (switch_core_timer_init(&bert.timer, "soft", interval, samples, switch_core_session_get_pool(session)) == SWITCH_STATUS_SUCCESS) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Setup timer success interval: %u samples: %u\n", interval, samples); + } else { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Timer Setup Failed. BERT cannot start!\n"); + goto done; + } + switch_core_timer_sync(&bert.timer); } bert.timeout = (switch_micro_time_now() + (timeout_ms * 1000)); @@ -193,8 +200,20 @@ SWITCH_STANDARD_APP(bert_test_function) switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "0"); switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "false"); write_samples = write_frame.data; - while (switch_channel_ready(channel)) { - switch_core_timer_next(&bert.timer); + for (;;) { + + if (!switch_channel_ready(channel)) { + break; + } + + switch_ivr_parse_all_events(session); + + if (timer_name) { + if (switch_core_timer_next(&bert.timer) != SWITCH_STATUS_SUCCESS) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Failed to step on timer!\n"); + break; + } + } /* Write our frame before anything else happens */ for (i = 0; i < read_impl.samples_per_packet; i++) { @@ -208,7 +227,11 @@ SWITCH_STANDARD_APP(bert_test_function) write_frame.datalen = read_impl.samples_per_packet; write_frame.samples = read_impl.samples_per_packet; - write_frame.timestamp = bert.timer.samplecount; + if (timer_name) { + write_frame.timestamp = bert.timer.samplecount; + } else { + /* playback() does not set write_frame.timestamp unless a timer is used, what's the catch? */ + } if (bert.output_debug_f) { fwrite(write_frame.data, write_frame.datalen, 1, bert.output_debug_f); } @@ -217,7 +240,8 @@ SWITCH_STANDARD_APP(bert_test_function) break; } - /* Proceed to read and process the readed frame ... */ + /* Proceed to read and process the read frame ... + * Note core_session_read_frame is a blocking operation, we should probably do reathing in another thread like playback() does using switch_core_service_session() */ status = switch_core_session_read_frame(session, &read_frame, SWITCH_IO_FLAG_NONE, 0); if (!SWITCH_READ_ACCEPTABLE(status)) { break; From 557a4a85808cf6c8736295bbfe84b68625a71a9c Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Mon, 14 Apr 2014 01:28:38 -0400 Subject: [PATCH 10/12] Treat CNG as a silent frame in mod_bert --- src/mod/applications/mod_bert/mod_bert.c | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 62d7e319c3..0829786de0 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -34,6 +34,8 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_bert_load); SWITCH_MODULE_SHUTDOWN_FUNCTION(mod_bert_shutdown); SWITCH_MODULE_DEFINITION(mod_bert, mod_bert_load, mod_bert_shutdown, NULL); +#define G711_ULAW_IDLE_OCTET 0xFF + /* http://en.wikipedia.org/wiki/Digital_milliwatt */ unsigned char ulaw_digital_milliwatt[8] = { 0x1e, 0x0b, 0x0b, 0x1e, 0x9e, 0x8b, 0x8b, 0x9e }; @@ -263,12 +265,14 @@ SWITCH_STANDARD_APP(bert_test_function) } } - /* Ignore confort noise, TODO: we should probably deal with this and treat it as a full frame of silence?? */ - if (switch_test_flag(read_frame, SFF_CNG) || !read_frame->datalen) { - continue; + /* Treat CNG as silence */ + if (switch_test_flag(read_frame, SFF_CNG)) { + read_frame->samples = read_impl.samples_per_packet; + read_frame->datalen = read_impl.samples_per_packet; + memset(read_frame->data, G711_ULAW_IDLE_OCTET, read_frame->datalen); } - if (read_frame->samples != read_impl.samples_per_packet) { + if (read_frame->samples != read_impl.samples_per_packet || !read_frame->datalen) { switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_ERROR, "Read %d samples, expected %d!\n", read_frame->samples, read_impl.samples_per_packet); continue; } From 25c6276feaf369f5c5580add6b681ff09f9d3e61 Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Mon, 14 Apr 2014 16:23:05 -0400 Subject: [PATCH 11/12] Added cng counter to the bert test app --- src/mod/applications/mod_bert/mod_bert.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index 0829786de0..d033c80f20 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -45,6 +45,7 @@ typedef struct { uint32_t window_ms; uint32_t window_samples; uint32_t stats_sync_lost_cnt; + uint32_t stats_cng_cnt; uint8_t sequence_sample; uint8_t predicted_sample; float max_err; @@ -270,6 +271,7 @@ SWITCH_STANDARD_APP(bert_test_function) read_frame->samples = read_impl.samples_per_packet; read_frame->datalen = read_impl.samples_per_packet; memset(read_frame->data, G711_ULAW_IDLE_OCTET, read_frame->datalen); + bert.stats_cng_cnt++; } if (read_frame->samples != read_impl.samples_per_packet || !read_frame->datalen) { @@ -300,8 +302,8 @@ SWITCH_STANDARD_APP(bert_test_function) if (bert.in_sync) { bert.in_sync = 0; bert.stats_sync_lost_cnt++; - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss (count=%u, err_samples=%u, session=%s)\n", - err, bert.stats_sync_lost_cnt, bert.err_samples, switch_core_session_get_uuid(session)); + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_WARNING, "BERT Sync Lost: %f%% loss (count=%u, cng_count=%d, err_samples=%u, session=%s)\n", + err, bert.stats_sync_lost_cnt, bert.stats_cng_cnt, bert.err_samples, switch_core_session_get_uuid(session)); switch_channel_set_variable_printf(channel, BERT_STATS_VAR_SYNC_LOST_CNT, "%u", bert.stats_sync_lost_cnt); switch_channel_set_variable(channel, BERT_STATS_VAR_SYNC_LOST, "true"); if (switch_event_create_subclass(&event, SWITCH_EVENT_CUSTOM, BERT_EVENT_LOST_SYNC) == SWITCH_STATUS_SUCCESS) { @@ -317,6 +319,7 @@ SWITCH_STANDARD_APP(bert_test_function) bert.in_sync = 1; synced = 1; switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "BERT Sync Success\n"); + bert.stats_cng_cnt = 0; bert.timeout = 0; } switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "Err=%f%% (%u/%u)\n", err, bert.err_samples, bert.processed_samples); From 89e8e14a9fdb18a2c5fd21dcf24f660374b75f4b Mon Sep 17 00:00:00 2001 From: Moises Silva Date: Mon, 14 Apr 2014 17:18:08 -0400 Subject: [PATCH 12/12] Improvements to mod_bert * Honor the timer name variable * Added mod_bert::in_sync event when the stream is in sync --- src/mod/applications/mod_bert/mod_bert.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/mod/applications/mod_bert/mod_bert.c b/src/mod/applications/mod_bert/mod_bert.c index d033c80f20..0988ffdbb9 100644 --- a/src/mod/applications/mod_bert/mod_bert.c +++ b/src/mod/applications/mod_bert/mod_bert.c @@ -94,6 +94,7 @@ typedef struct { #define BERT_EVENT_TIMEOUT "mod_bert::timeout" #define BERT_EVENT_LOST_SYNC "mod_bert::lost_sync" +#define BERT_EVENT_IN_SYNC "mod_bert::in_sync" #define BERT_DEFAULT_WINDOW_MS 1000 #define BERT_DEFAULT_MAX_ERR 10.0 @@ -180,7 +181,7 @@ SWITCH_STANDARD_APP(bert_test_function) if (timer_name) { interval = read_impl.microseconds_per_packet / 1000; samples = switch_samples_per_packet(read_impl.samples_per_second, interval); - if (switch_core_timer_init(&bert.timer, "soft", interval, samples, switch_core_session_get_pool(session)) == SWITCH_STATUS_SUCCESS) { + if (switch_core_timer_init(&bert.timer, timer_name, interval, samples, switch_core_session_get_pool(session)) == SWITCH_STATUS_SUCCESS) { switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Setup timer success interval: %u samples: %u\n", interval, samples); } else { switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Timer Setup Failed. BERT cannot start!\n"); @@ -321,6 +322,10 @@ SWITCH_STANDARD_APP(bert_test_function) switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_INFO, "BERT Sync Success\n"); bert.stats_cng_cnt = 0; bert.timeout = 0; + if (switch_event_create_subclass(&event, SWITCH_EVENT_CUSTOM, BERT_EVENT_IN_SYNC) == SWITCH_STATUS_SUCCESS) { + switch_channel_event_set_basic_data(channel, event); + switch_event_fire(&event); + } } switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG10, "Err=%f%% (%u/%u)\n", err, bert.err_samples, bert.processed_samples); if (synced && err > bert.max_err_hit) {