voipmonitor / sniffer

VoIPmonitor sniffer sources
231 stars 107 forks source link

MOS values corrupted? #30

Closed olebowle closed 8 years ago

olebowle commented 8 years ago

Hi,

I'm experiencing out-of-bound (i.e. less than 1.0) MOS values in the database, which shouldn't be possible. I patched the source to see where those values are coming from and they doesn't seem to originate from calculate_mos_fromrtp(). This is the patch I'm using:

diff --git a/rtp.cpp b/rtp.cpp
index a937bfd..efc8264 100644
--- a/rtp.cpp
+++ b/rtp.cpp
@@ -356,6 +356,7 @@ RTP::save_mos_graph(bool delimiter) {
        // reset 10 second MOS stats
        memcpy(channel_fix1->last_interval_loss, channel_fix1->loss, sizeof(unsigned short int) * 128);
        if(mosf1_min > last_interval_mosf1) {
+           if(last_interval_mosf1 != 45) printf("!last_interval_mosf1: %u (ssrc: %x)\n", last_interval_mosf1, getSSRC());
            mosf1_min = last_interval_mosf1;
        }
        mosf1_avg = ((mosf1_avg * mos_counter) + last_interval_mosf1) / (mos_counter + 1);
@@ -377,6 +378,7 @@ RTP::save_mos_graph(bool delimiter) {
        // reset 10 second MOS stats
        memcpy(channel_fix2->last_interval_loss, channel_fix2->loss, sizeof(unsigned short int) * 128);
        if(mosf2_min > last_interval_mosf2) {
+           if(last_interval_mosf2 != 45) printf("!last_interval_mosf2: %u (ssrc: %x)\n", last_interval_mosf2, getSSRC());
            mosf2_min = last_interval_mosf2;
        }
        mosf2_avg = ((mosf2_avg * mos_counter) + last_interval_mosf2) / (mos_counter + 1);
@@ -398,6 +400,7 @@ RTP::save_mos_graph(bool delimiter) {
        // reset 10 second MOS stats
        memcpy(channel_adapt->last_interval_loss, channel_adapt->loss, sizeof(unsigned short int) * 128);
        if(mosAD_min > last_interval_mosAD) {
+           if(last_interval_mosAD != 45) printf("!last_interval_mosAD: %u (ssrc: %x)\n", last_interval_mosAD, getSSRC());
            mosAD_min = last_interval_mosAD;
        }
        mosAD_avg = ((mosAD_avg * mos_counter) + last_interval_mosAD) / (mos_counter + 1);

If I start the application I see those printfs:

$ sudo ./voipmonitor -k -P /tmp/voipmonitor.pid --config-file /etc/voipmonitor.conf 
Loading configuration from file /etc/voipmonitor.conf OK
voipmonitor version 16.0
voipmonitor[25768]: start voipmonitor version 16.0
local time 2016-06-06 11:45:28
voipmonitor[25768]: local time 2016-06-06 11:45:28
voipmonitor[25768]: detected rrdtool version 10408
voipmonitor[25768]: connect - db version 5.5
voipmonitor[25768]: creating and upgrading MySQL schema...
voipmonitor[25768]: create procedure create_partition
voipmonitor[25768]: create procedure create_partition_v2
voipmonitor[25768]: create function getIdOrInsertUA
voipmonitor[25768]: create function getIdOrInsertSIPRES
voipmonitor[25768]: create function getIdOrInsertSIPREQUEST
voipmonitor[25768]: create function getIdOrInsertREASON
voipmonitor[25768]: create function getIdOrInsertCONTENTTYPE
voipmonitor[25768]: create procedure PROCESS_SIP_REGISTER
voipmonitor[25768]: done
voipmonitor[25768]: create cdr partitions - begin
voipmonitor[25768]: create cdr partitions - end
voipmonitor[25768]: create rtp_stat partitions - begin
voipmonitor[25768]: start PreProcessPacket out thread detach/25806
voipmonitor[25768]: start ProcessRtpPacket hash out thread 25807
voipmonitor[25768]: start ProcessRtpPacket hash next thread 25808
voipmonitor[25768]: start ProcessRtpPacket distribute out thread 25809
voipmonitor[25768]: create rtp_stat partitions - end
voipmonitor[25768]: drop old partitions rtp_stat - begin
voipmonitor[25768]: drop old partitions - end
detect oneshot buffer
method 1 success
oneshot buffer: 7f6c28000d50
packet: 7f6c28000d50
device: eno2
offset: 744
voipmonitor[25768]: find oneshot libpcap buffer : success
!last_interval_mosAD: 38 (ssrc: 241cc7cd)
!last_interval_mosf1: 41 (ssrc: 8d48f0)
^C
voipmonitor[25768]: SIGINT received, terminating
voipmonitor[25768]: packetbuffer terminating: pcap_close pcapHandle (eno2)
voipmonitor[25768]: packetbuffer terminating (queue): cleanupBlockStoreTrash
voipmonitor[25768]: terminated - cleanup calls
voipmonitor[25768]: terminated - call cleanup
voipmonitor[25768]: stop PreProcessPacket out thread detach/25806
voipmonitor[25768]: terminated - async
voipmonitor[25768]: terminated - tar - flush queue
voipmonitor[25768]: terminated - tar
voipmonitor[25768]: terminated - sql store 11
voipmonitor[25768]: terminated - sql store 41

However they only partly correspond to the database entries:

MariaDB [(none)]> SELECT ID,calldate,callend,a_mos_min_mult10,a_mos_f1_min_mult10,a_mos_f2_min_mult10,a_mos_adapt_min_mult10,b_mos_min_mult10,b_mos_f1_min_mult10,b_mos_f2_min_mult10,b_mos_adapt_min_mult10 FROM voipmonitor.cdr WHERE connect_duration IS NOT NULL;
+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+
| ID | calldate            | callend             | a_mos_min_mult10 | a_mos_f1_min_mult10 | a_mos_f2_min_mult10 | a_mos_adapt_min_mult10 | b_mos_min_mult10 | b_mos_f1_min_mult10 | b_mos_f2_min_mult10 | b_mos_adapt_min_mult10 |
+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+
|  3 | 2016-06-06 11:48:14 | 2016-06-06 11:49:45 |               45 |                  45 |                  45 |                     45 |               45 |                   1 |                  45 |                     45 |
|  4 | 2016-06-06 11:49:21 | 2016-06-06 11:50:35 |               45 |                  45 |                  45 |                     30 |               45 |                  45 |                  45 |                     45 |
|  6 | 2016-06-06 11:51:06 | 2016-06-06 11:51:36 |               45 |                  45 |                  45 |                     45 |               45 |                  45 |                  45 |                     45 |
|  7 | 2016-06-06 11:49:41 | 2016-06-06 11:51:37 |               45 |                  41 |                  45 |                     45 |               45 |                  45 |                  45 |                     45 |
|  8 | 2016-06-06 11:51:13 | 2016-06-06 11:51:30 |               45 |                   1 |                  45 |                     45 |               45 |                  45 |                  45 |                     45 |
| 10 | 2016-06-06 11:51:49 | 2016-06-06 11:52:26 |               45 |                  45 |                  45 |                     45 |               45 |                  45 |                  45 |                     45 |
+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+
6 rows in set (0.00 sec)

I'm especially curious about the values 1, which would correspond to a MOS value of 0.1! I tried disabling threading, as I thought there might be a race condition, but that didn't help either. Looking at the corresponding *.graph files the MOS values are 45 (0x2d).

BR, Ole

voipmonitor commented 8 years ago

Hi Ole,

we will check it

2016-06-06 12:37 GMT+02:00 Ole Ernst notifications@github.com:

Hi,

I'm experiencing out-of-bound (i.e. less than 1.0) MOS values in the database, which shouldn't be possible. I patched the source to see where those values are coming from and they doesn't seem to originate from calculate_mos_fromrtp(). This is the patch I'm using:

diff --git a/rtp.cpp b/rtp.cpp index a937bfd..efc8264 100644--- a/rtp.cpp+++ b/rtp.cpp@@ -356,6 +356,7 @@ RTP::save_mos_graph(bool delimiter) { // reset 10 second MOS stats memcpy(channel_fix1->last_interval_loss, channel_fix1->loss, sizeof(unsigned short int) * 128); if(mosf1_min > last_interval_mosf1) {+ if(last_interval_mosf1 != 45) printf("!last_interval_mosf1: %u (ssrc: %x)\n", last_interval_mosf1, getSSRC()); mosf1_min = last_interval_mosf1; } mosf1_avg = ((mosf1_avg * mos_counter) + last_interval_mosf1) / (mos_counter + 1);@@ -377,6 +378,7 @@ RTP::save_mos_graph(bool delimiter) { // reset 10 second MOS stats memcpy(channel_fix2->last_interval_loss, channel_fix2->loss, sizeof(unsigned short int) * 128); if(mosf2_min > last_interval_mosf2) {+ if(last_interval_mosf2 != 45) printf("!last_interval_mosf2: %u (ssrc: %x)\n", last_interval_mosf2, getSSRC()); mosf2_min = last_interval_mosf2; } mosf2_avg = ((mosf2_avg * mos_counter) + last_interval_mosf2) / (mos_counter + 1);@@ -398,6 +400,7 @@ RTP::save_mos_graph(bool delimiter) { // reset 10 second MOS stats memcpy(channel_adapt->last_interval_loss, channel_adapt->loss, sizeof(unsigned short int) * 128); if(mosAD_min > last_interval_mosAD) {+ if(last_interval_mosAD != 45) printf("!last_interval_mosAD: %u (ssrc: %x)\n", last_interval_mosAD, getSSRC()); mosAD_min = last_interval_mosAD; } mosAD_avg = ((mosAD_avg * mos_counter) + last_interval_mosAD) / (mos_counter + 1);

If I start the application I see those printfs:

$ sudo ./voipmonitor -k -P /tmp/voipmonitor.pid --config-file /etc/voipmonitor.conf Loading configuration from file /etc/voipmonitor.conf OK voipmonitor version 16.0 voipmonitor[25768]: start voipmonitor version 16.0local time 2016-06-06 11:45:28 voipmonitor[25768]: local time 2016-06-06 11:45:28 voipmonitor[25768]: detected rrdtool version 10408 voipmonitor[25768]: connect - db version 5.5 voipmonitor[25768]: creating and upgrading MySQL schema... voipmonitor[25768]: create procedure create_partition voipmonitor[25768]: create procedure create_partition_v2 voipmonitor[25768]: create function getIdOrInsertUA voipmonitor[25768]: create function getIdOrInsertSIPRES voipmonitor[25768]: create function getIdOrInsertSIPREQUEST voipmonitor[25768]: create function getIdOrInsertREASON voipmonitor[25768]: create function getIdOrInsertCONTENTTYPE voipmonitor[25768]: create procedure PROCESS_SIP_REGISTER voipmonitor[25768]: done voipmonitor[25768]: create cdr partitions - begin voipmonitor[25768]: create cdr partitions - end voipmonitor[25768]: create rtp_stat partitions - begin voipmonitor[25768]: start PreProcessPacket out thread detach/25806 voipmonitor[25768]: start ProcessRtpPacket hash out thread 25807 voipmonitor[25768]: start ProcessRtpPacket hash next thread 25808 voipmonitor[25768]: start ProcessRtpPacket distribute out thread 25809 voipmonitor[25768]: create rtp_stat partitions - end voipmonitor[25768]: drop old partitions rtp_stat - begin voipmonitor[25768]: drop old partitions - end detect oneshot buffer method 1 success oneshot buffer: 7f6c28000d50 packet: 7f6c28000d50 device: eno2 offset: 744 voipmonitor[25768]: find oneshot libpcap buffer : success!last_interval_mosAD: 38 (ssrc: 241cc7cd)!last_interval_mosf1: 41 (ssrc: 8d48f0) ^C voipmonitor[25768]: SIGINT received, terminating voipmonitor[25768]: packetbuffer terminating: pcap_close pcapHandle (eno2) voipmonitor[25768]: packetbuffer terminating (queue): cleanupBlockStoreTrash voipmonitor[25768]: terminated - cleanup calls voipmonitor[25768]: terminated - call cleanup voipmonitor[25768]: stop PreProcessPacket out thread detach/25806 voipmonitor[25768]: terminated - async voipmonitor[25768]: terminated - tar - flush queue voipmonitor[25768]: terminated - tar voipmonitor[25768]: terminated - sql store 11 voipmonitor[25768]: terminated - sql store 41

However they only partly correspond to the database entries:

MariaDB [(none)]> SELECT ID,calldate,callend,a_mos_min_mult10,a_mos_f1_min_mult10,a_mos_f2_min_mult10,a_mos_adapt_min_mult10,b_mos_min_mult10,b_mos_f1_min_mult10,b_mos_f2_min_mult10,b_mos_adapt_min_mult10 FROM voipmonitor.cdr WHERE connect_duration IS NOT NULL;+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+ | ID | calldate | callend | a_mos_min_mult10 | a_mos_f1_min_mult10 | a_mos_f2_min_mult10 | a_mos_adapt_min_mult10 | b_mos_min_mult10 | b_mos_f1_min_mult10 | b_mos_f2_min_mult10 | b_mos_adapt_min_mult10 |+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+ | 3 | 2016-06-06 11:48:14 | 2016-06-06 11:49:45 | 45 | 45 | 45 | 45 | 45 | 1 | 45 | 45 | | 4 | 2016-06-06 11:49:21 | 2016-06-06 11:50:35 | 45 | 45 | 45 | 30 | 45 | 45 | 45 | 45 | | 6 | 2016-06-06 11:51:06 | 2016-06-06 11:51:36 | 45 | 45 | 45 | 45 | 45 | 45 | 45 | 45 | | 7 | 2016-06-06 11:49:41 | 2016-06-06 11:51:37 | 45 | 41 | 45 | 45 | 45 | 45 | 45 | 45 | | 8 | 2016-06-06 11:51:13 | 2016-06-06 11:51:30 | 45 | 1 | 45 | 45 | 45 | 45 | 45 | 45 | | 10 | 2016-06-06 11:51:49 | 2016-06-06 11:52:26 | 45 | 45 | 45 | 45 | 45 | 45 | 45 | 45 |+----+---------------------+---------------------+------------------+---------------------+---------------------+------------------------+------------------+---------------------+---------------------+------------------------+6 rows in set (0.00 sec)

I'm especially curious about the values 1, which would correspond to a MOS value of 0.1! I tried disabling threading, as I thought there might be a race condition, but that didn't help either. Looking at the corresponding *.graph files the MOS values are 45 (0x2d).

BR, Ole

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/voipmonitor/sniffer/issues/30, or mute the thread https://github.com/notifications/unsubscribe/AGt_p8KRMTGRAR7OGEgx-HWfZ2WAkAKjks5qI_higaJpZM4IuxDX .

Best regards Martin Vit

voipmonitor commented 8 years ago

Fixed in 16.0.2