dsp.c: Improve debug logging in tone_detect().

The debug logging during DSP processing has always been kind
of overwhelming and annoying to troubleshoot. Simplify and
improve the logging in a few ways to aid DSP debugging:

* If we had a DSP hit, don't also emit the previous debug message that
  was always logged. It is duplicated by the hit message, so this can
  reduce the number of debug messages during detection by 50%.
* Include the hit count and required number of hits in the message so
  on partial detections can be more easily troubleshot.
* Use debug level 9 for hits instead of 10, so we can focus on hits
  without all the noise from the per-frame debug message.
* 1-index the hit count in the debug messages. On the first hit, it
  currently logs '0', just as when we are not detecting anything,
  which can be confusing.

Resolves: #1375
(cherry picked from commit 8bfa3be27fe0674ed7fd24a9be756493d4478ad3)

diff --git a/main/dsp.c b/main/dsp.c
index 0955f6667766947c74363c900c719682d932f7cb..0bcce132c1c9f55eb09ec9e114b7dff726fddb49 100644 (file)
--- a/main/dsp.c
+++ b/main/dsp.c
@@ -618,12 +618,14 @@ static int tone_detect(struct ast_dsp *dsp, tone_detect_state_t *s, int16_t *amp
                tone_energy *= 2.0;
                s->energy *= s->block_size;
 
-               ast_debug(10, "%d Hz tone %2d Ew=%.4E, Et=%.4E, s/n=%10.2f\n", s->freq, s->hit_count, tone_energy, s->energy, tone_energy / (s->energy - tone_energy));
-               hit = 0;
+               /* Add 1 to hit_count when logging, since it doesn't get incremented until later in the loop. */
                if (TONE_THRESHOLD <= tone_energy
                        && tone_energy > s->energy * s->threshold) {
-                       ast_debug(10, "%d Hz tone Hit! %2d Ew=%.4E, Et=%.4E, s/n=%10.2f\n", s->freq, s->hit_count, tone_energy, s->energy, tone_energy / (s->energy - tone_energy));
+                       ast_debug(9, "%d Hz tone Hit! [%d/%d] Ew=%.4E, Et=%.4E, s/n=%10.2f\n", s->freq, s->hit_count + 1, s->hits_required, tone_energy, s->energy, tone_energy / (s->energy - tone_energy));
                        hit = 1;
+               } else {
+                       ast_debug(10, "%d Hz tone [%d/%d] Ew=%.4E, Et=%.4E, s/n=%10.2f\n", s->freq, s->hit_count + 1, s->hits_required, tone_energy, s->energy, tone_energy / (s->energy - tone_energy));
+                       hit = 0;
                }
 
                if (s->hit_count) {
@@ -633,11 +635,11 @@ static int tone_detect(struct ast_dsp *dsp, tone_detect_state_t *s, int16_t *amp
                if (hit == s->last_hit) {
                        if (!hit) {
                                /* Two successive misses. Tone ended */
+                               ast_debug(9, "Partial detect expired after %d/%d hits\n", s->hit_count, s->hits_required);
                                s->hit_count = 0;
                        } else if (!s->hit_count) {
                                s->hit_count++;
                        }
-
                }
 
                if (s->hit_count == s->hits_required) {