SPAN_DECLARE(int) span_log_buf(logging_state_t *s, int level, const char *tag, const uint8_t *buf, int len)
{
char msg[1024];
int i;
int msg_len;
if (span_log_test(s, level))
{
msg_len = 0;
if (tag)
msg_len += snprintf(msg + msg_len, 1024 - msg_len, "%s", tag);
for (i = 0; i < len && msg_len < 800; i++)
msg_len += snprintf(msg + msg_len, 1024 - msg_len, " %02x", buf[i]);
msg_len += snprintf(msg + msg_len, 1024 - msg_len, "\n");
return span_log(s, level, msg);
}
return 0;
}
SPAN_DECLARE(int) span_log(logging_state_t *s, int level, const char *format, ...)
{
char msg[1024 + 1];
va_list arg_ptr;
int len;
struct tm *tim;
struct timeval nowx;
time_t now;
if (span_log_test(s, level))
{
va_start(arg_ptr, format);
len = 0;
if ((level & SPAN_LOG_SUPPRESS_LABELLING) == 0)
{
if ((s->level & SPAN_LOG_SHOW_DATE))
{
gettimeofday(&nowx, NULL);
now = nowx.tv_sec;
tim = gmtime(&now);
len += snprintf(msg + len,
1024 - len,
"%04d/%02d/%02d %02d:%02d:%02d.%03d ",
tim->tm_year + 1900,
tim->tm_mon + 1,
tim->tm_mday,
tim->tm_hour,
tim->tm_min,
tim->tm_sec,
(int) nowx.tv_usec/1000);
}
/*endif*/
if ((s->level & SPAN_LOG_SHOW_SAMPLE_TIME))
{
now = s->elapsed_samples/s->samples_per_second;
tim = gmtime(&now);
len += snprintf(msg + len,
1024 - len,
"%02d:%02d:%02d.%03d ",
tim->tm_hour,
tim->tm_min,
tim->tm_sec,
(int) (s->elapsed_samples%s->samples_per_second)*1000/s->samples_per_second);
}
/*endif*/
if ((s->level & SPAN_LOG_SHOW_SEVERITY) && (level & SPAN_LOG_SEVERITY_MASK) <= SPAN_LOG_DEBUG_3)
len += snprintf(msg + len, 1024 - len, "%s ", severities[level & SPAN_LOG_SEVERITY_MASK]);
/*endif*/
if ((s->level & SPAN_LOG_SHOW_PROTOCOL) && s->protocol)
len += snprintf(msg + len, 1024 - len, "%s ", s->protocol);
/*endif*/
if ((s->level & SPAN_LOG_SHOW_TAG) && s->tag)
len += snprintf(msg + len, 1024 - len, "%s ", s->tag);
/*endif*/
}
/*endif*/
len += vsnprintf(msg + len, 1024 - len, format, arg_ptr);
if (s->span_error && level == SPAN_LOG_ERROR)
s->span_error(msg);
else if (__span_error && level == SPAN_LOG_ERROR)
__span_error(msg);
else if (s->span_message)
s->span_message(level, msg);
else if (__span_message)
__span_message(level, msg);
/*endif*/
va_end(arg_ptr);
return 1;
}
/*endif*/
return 0;
}
SPAN_DECLARE(int) dtmf_rx(dtmf_rx_state_t *s, const int16_t amp[], int samples)
{
#if defined(SPANDSP_USE_FIXED_POINT)
int32_t row_energy[4];
int32_t col_energy[4];
int16_t xamp;
float famp;
#else
float row_energy[4];
float col_energy[4];
float xamp;
float famp;
#endif
float v1;
int i;
int j;
int sample;
int best_row;
int best_col;
int limit;
uint8_t hit;
hit = 0;
for (sample = 0; sample < samples; sample = limit)
{
/* The block length is optimised to meet the DTMF specs. */
if ((samples - sample) >= (DTMF_SAMPLES_PER_BLOCK - s->current_sample))
limit = sample + (DTMF_SAMPLES_PER_BLOCK - s->current_sample);
else
limit = samples;
/* The following unrolled loop takes only 35% (rough estimate) of the
time of a rolled loop on the machine on which it was developed */
for (j = sample; j < limit; j++)
{
xamp = amp[j];
if (s->filter_dialtone)
{
famp = xamp;
/* Sharp notches applied at 350Hz and 440Hz - the two common dialtone frequencies.
These are rather high Q, to achieve the required narrowness, without using lots of
sections. */
v1 = 0.98356f*famp + 1.8954426f*s->z350[0] - 0.9691396f*s->z350[1];
famp = v1 - 1.9251480f*s->z350[0] + s->z350[1];
s->z350[1] = s->z350[0];
s->z350[0] = v1;
v1 = 0.98456f*famp + 1.8529543f*s->z440[0] - 0.9691396f*s->z440[1];
famp = v1 - 1.8819938f*s->z440[0] + s->z440[1];
s->z440[1] = s->z440[0];
s->z440[0] = v1;
xamp = famp;
}
xamp = goertzel_preadjust_amp(xamp);
#if defined(SPANDSP_USE_FIXED_POINT)
s->energy += ((int32_t) xamp*xamp);
#else
s->energy += xamp*xamp;
#endif
goertzel_samplex(&s->row_out[0], xamp);
goertzel_samplex(&s->col_out[0], xamp);
goertzel_samplex(&s->row_out[1], xamp);
goertzel_samplex(&s->col_out[1], xamp);
goertzel_samplex(&s->row_out[2], xamp);
goertzel_samplex(&s->col_out[2], xamp);
goertzel_samplex(&s->row_out[3], xamp);
goertzel_samplex(&s->col_out[3], xamp);
}
if (s->duration < INT_MAX - (limit - sample))
s->duration += (limit - sample);
s->current_sample += (limit - sample);
if (s->current_sample < DTMF_SAMPLES_PER_BLOCK)
continue;
/* We are at the end of a DTMF detection block */
/* Find the peak row and the peak column */
row_energy[0] = goertzel_result(&s->row_out[0]);
best_row = 0;
col_energy[0] = goertzel_result(&s->col_out[0]);
best_col = 0;
for (i = 1; i < 4; i++)
{
row_energy[i] = goertzel_result(&s->row_out[i]);
if (row_energy[i] > row_energy[best_row])
best_row = i;
col_energy[i] = goertzel_result(&s->col_out[i]);
if (col_energy[i] > col_energy[best_col])
best_col = i;
}
hit = 0;
/* Basic signal level test and the twist test */
if (row_energy[best_row] >= s->threshold
&&
col_energy[best_col] >= s->threshold)
{
if (col_energy[best_col] < row_energy[best_row]*s->reverse_twist
&&
col_energy[best_col]*s->normal_twist > row_energy[best_row])
{
/* Relative peak test ... */
for (i = 0; i < 4; i++)
{
if ((i != best_col && col_energy[i]*DTMF_RELATIVE_PEAK_COL > col_energy[best_col])
||
(i != best_row && row_energy[i]*DTMF_RELATIVE_PEAK_ROW > row_energy[best_row]))
{
break;
}
}
/* ... and fraction of total energy test */
if (i >= 4
&&
(row_energy[best_row] + col_energy[best_col]) > DTMF_TO_TOTAL_ENERGY*s->energy)
{
/* Got a hit */
hit = dtmf_positions[(best_row << 2) + best_col];
}
}
if (span_log_test(&s->logging, SPAN_LOG_FLOW))
{
/* Log information about the quality of the signal, to aid analysis of detection problems */
/* Logging at this point filters the total no-hoper frames out of the log, and leaves
anything which might feasibly be a DTMF digit. The log will then contain a list of the
total, row and coloumn power levels for detailed analysis of detection problems. */
span_log(&s->logging,
SPAN_LOG_FLOW,
"Potentially '%c' - total %.2fdB, row %.2fdB, col %.2fdB, duration %d - %s\n",
dtmf_positions[(best_row << 2) + best_col],
log10f(s->energy)*10.0f - DTMF_POWER_OFFSET + DBM0_MAX_POWER,
log10f(row_energy[best_row]/DTMF_TO_TOTAL_ENERGY)*10.0f - DTMF_POWER_OFFSET + DBM0_MAX_POWER,
log10f(col_energy[best_col]/DTMF_TO_TOTAL_ENERGY)*10.0f - DTMF_POWER_OFFSET + DBM0_MAX_POWER,
s->duration,
(hit) ? "hit" : "miss");
}
}
/* The logic in the next test should ensure the following for different successive hit patterns:
-----ABB = start of digit B.
----B-BB = start of digit B
----A-BB = start of digit B
BBBBBABB = still in digit B.
BBBBBB-- = end of digit B
BBBBBBC- = end of digit B
BBBBACBB = B ends, then B starts again.
BBBBBBCC = B ends, then C starts.
BBBBBCDD = B ends, then D starts.
This can work with:
- Back to back differing digits. Back-to-back digits should
not happen. The spec. says there should be a gap between digits.
However, many real phones do not impose a gap, and rolling across
the keypad can produce little or no gap.
- It tolerates nasty phones that give a very wobbly start to a digit.
- VoIP can give sample slips. The phase jumps that produces will cause
the block it is in to give no detection. This logic will ride over a
single missed block, and not falsely declare a second digit. If the
hiccup happens in the wrong place on a minimum length digit, however
we would still fail to detect that digit. Could anything be done to
deal with that? Packet loss is clearly a no-go zone.
Note this is only relevant to VoIP using A-law, u-law or similar.
Low bit rate codecs scramble DTMF too much for it to be recognised,
and often slip in units larger than a sample. */
if (hit != s->in_digit && s->last_hit != s->in_digit)
{
/* We have two successive indications that something has changed. */
/* To declare digit on, the hits must agree. Otherwise we declare tone off. */
hit = (hit && hit == s->last_hit) ? hit : 0;
if (s->realtime_callback)
{
/* Avoid reporting multiple no digit conditions on flaky hits */
if (s->in_digit || hit)
{
i = (s->in_digit && !hit) ? -99 : lfastrintf(log10f(s->energy)*10.0f - DTMF_POWER_OFFSET + DBM0_MAX_POWER);
s->realtime_callback(s->realtime_callback_data, hit, i, s->duration);
s->duration = 0;
}
}
else
{
if (hit)
{
if (s->current_digits < MAX_DTMF_DIGITS)
{
s->digits[s->current_digits++] = (char) hit;
s->digits[s->current_digits] = '\0';
if (s->digits_callback)
{
s->digits_callback(s->digits_callback_data, s->digits, s->current_digits);
s->current_digits = 0;
}
}
else
{
s->lost_digits++;
}
}
}
s->in_digit = hit;
}
s->last_hit = hit;
#if defined(SPANDSP_USE_FIXED_POINT)
s->energy = 0;
#else
s->energy = 0.0f;
#endif
s->current_sample = 0;
}
if (s->current_digits && s->digits_callback)
{
s->digits_callback(s->digits_callback_data, s->digits, s->current_digits);
s->digits[0] = '\0';
s->current_digits = 0;
}
return 0;
}
int main(int argc, char *argv[])
{
logging_state_t *log;
int i;
uint8_t buf[1000];
struct timespec delay;
/* Set up a logger */
if ((log = span_log_init(NULL, 123, "TAG")) == NULL)
{
fprintf(stderr, "Failed to initialise log.\n");
exit(2);
}
/* Try it */
span_log_set_level(log, SPAN_LOG_SHOW_SEVERITY | SPAN_LOG_SHOW_PROTOCOL | SPAN_LOG_SHOW_TAG | SPAN_LOG_FLOW);
if (span_log(log, SPAN_LOG_FLOW, "Logging to fprintf, as simple as %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
/* Now set a custom log handler */
span_log_set_message_handler(log, &message_handler, NULL);
span_log_set_sample_rate(log, 44100);
/* Try the different logging elements */
span_log_set_level(log, SPAN_LOG_SHOW_TAG | SPAN_LOG_FLOW);
if (span_log(log, SPAN_LOG_FLOW, "Log with tag %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
span_log_set_level(log, SPAN_LOG_SHOW_PROTOCOL | SPAN_LOG_FLOW);
if (span_log(log, SPAN_LOG_FLOW, "Log with protocol %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
span_log_set_level(log, SPAN_LOG_SHOW_SEVERITY | SPAN_LOG_FLOW);
if (span_log(log, SPAN_LOG_ERROR, "Log with severity log %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
span_log_set_level(log, SPAN_LOG_SHOW_SEVERITY | SPAN_LOG_SHOW_PROTOCOL | SPAN_LOG_SHOW_TAG | SPAN_LOG_FLOW);
span_log_set_tag(log, "NewTag");
if (span_log(log, SPAN_LOG_FLOW, "Log with new tag %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
span_log_set_protocol(log, "Protocol");
if (span_log(log, SPAN_LOG_FLOW, "Log with protocol %d %d %d\n", 1, 2, 3))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
/* Test logging of buffer contents */
for (i = 0; i < 1000; i++)
buf[i] = i;
if (span_log_buf(log, SPAN_LOG_FLOW, "Buf", buf, 10))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
if (span_log_buf(log, SPAN_LOG_FLOW, "Buf", buf, 1000))
fprintf(stderr, "Logged.\n");
else
fprintf(stderr, "Not logged.\n");
/* Test the correct severities will be logged */
for (i = 0; i < 10; i++)
{
if (!span_log_test(log, i))
{
if (i != 6)
tests_failed = true;
break;
}
}
/* Check timestamping by samples */
span_log_set_level(log, SPAN_LOG_SHOW_SEVERITY | SPAN_LOG_SHOW_PROTOCOL | SPAN_LOG_SHOW_TAG | SPAN_LOG_FLOW | SPAN_LOG_SHOW_SAMPLE_TIME);
for (i = 0; i < 10; i++)
{
span_log(log, SPAN_LOG_FLOW, "Time tagged log %d %d %d\n", 1, 2, 3);
span_log_bump_samples(log, 441*2);
}
/* Check timestamping by current date and time */
span_log_set_message_handler(log, &message_handler2, NULL);
span_log_set_level(log, SPAN_LOG_SHOW_SEVERITY | SPAN_LOG_SHOW_PROTOCOL | SPAN_LOG_SHOW_TAG | SPAN_LOG_FLOW | SPAN_LOG_SHOW_DATE);
for (i = 0; i < 10; i++)
{
span_log(log, SPAN_LOG_FLOW, "Date/time tagged log %d %d %d\n", 1, 2, 3);
delay.tv_sec = 0;
delay.tv_nsec = 20000000;
nanosleep(&delay, NULL);
}
if (tests_failed || !msg_done)
{
printf("Tests failed - %d %d.\n", tests_failed, msg_done);
return 2;
}
span_log_set_message_handler(log, &message_handler, NULL);
printf("Tests passed.\n");
return 0;
}
