diff --git a/src/channels/chan_voicemngr.c b/src/channels/chan_voicemngr.c index 3e14c9b08d7ce4da832462d7c8dfaa5a0dc300c7..052d3fec4b921de79a27548661012da11ff53b8a 100644 --- a/src/channels/chan_voicemngr.c +++ b/src/channels/chan_voicemngr.c @@ -67,12 +67,18 @@ #include <libubus.h> #include <libpicoevent.h> +#include "time_logger.h" +#include "timediff.h" #include "voice-types.h" #include "chan_voicemngr.h" #ifndef AST_MODULE #define AST_MODULE "chan_voicemngr" #endif +#define LOGFILE "/tmp/chan_voicemngr.log" +#define BUFLEN 6000000 +#define LOGRATE 100 + static void chan_voicemngr_dialtone_set(struct chan_voicemngr_pvt *p, dialtone_state state); static int chan_voicemngr_signal_dialtone(struct chan_voicemngr_pvt *p); static int chan_voicemngr_in_conference(const struct chan_voicemngr_pvt *p); @@ -3281,6 +3287,14 @@ static void audio_packet_handler(pe_packet_t *p) { struct chan_voicemngr_pvt *pvt; int sip_client_id = -1; unsigned int* packet_buf32 = (unsigned int*)ap->rtp; + unsigned short seqnum_start,seqnum_end; + static struct logbuf_t buff; + struct timeval difference; + static struct timeval earlier = {0,0}; + static struct timeval later = {0,0}; + float d_usec; + + logbuf_init (&buff, LOGFILE, BUFLEN, LOGRATE); // Clear the RTP marker bit if ((payload_type & RTP_MARKER_BIT) && (payload_type < RTCP_SR || payload_type > RTCP_XR)) @@ -3359,6 +3373,31 @@ static void audio_packet_handler(pe_packet_t *p) { //ast_mutex_unlock(&sub->parent->lock); //pvt_unlock(sub->parent); + //Get packet sequence number + seqnum_start = ap->rtp[2]; + seqnum_end = ap->rtp[3]; + + //Get time and time difference + if(later.tv_usec == 0 && later.tv_sec == 0) { + time_delta(&later, &earlier, &difference); + gettimeofday(&later, NULL); + earlier = later; + } else { + gettimeofday(&later, NULL); + time_delta(&later, &earlier, &difference); + earlier = later; + } + + //Write debug data into logbuf + if(payload_type < 200) { + if( difference.tv_usec < 1000) { + d_usec = difference.tv_usec; + logbuf (&buff, "%d:%d:%f\n", payload_type,((seqnum_start << 8) + seqnum_end), ((difference.tv_sec * 1000) + (d_usec / 1000))); + } else { + logbuf (&buff, "%d:%d:%d\n", payload_type,((seqnum_start << 8) + seqnum_end), ((difference.tv_sec * 1000) + (difference.tv_usec / 1000))); + } + } + if (owner) { if (!drop_frame && (ast_channel_state(owner) == AST_STATE_UP || ast_channel_state(owner) == AST_STATE_RING)) { ast_queue_frame(owner, &frame); diff --git a/src/channels/time_logger.h b/src/channels/time_logger.h new file mode 100644 index 0000000000000000000000000000000000000000..ef33082f78762c22ce67949c77f57d8d47bf6615 --- /dev/null +++ b/src/channels/time_logger.h @@ -0,0 +1,96 @@ +#include <sys/types.h> +#include <sys/stat.h> +#include <sys/mman.h> +#include <fcntl.h> +#include <unistd.h> + +#include <stdio.h> +#include <errno.h> +#include <string.h> +#include <stdarg.h> + +#define BUFLEN 6000000 +#define INITED 0xDEADBEEF + +struct logbuf_t +{ + char *dmem; + int dfd; + off_t off; + size_t buflen; + off_t ratelimit; + unsigned int inited; +}; + +int logbuf_init(struct logbuf_t * logbuf, char * fname, off_t bufsize, off_t ratelimit); +void logbuf_flush(struct logbuf_t * logbuf); +int logbuf(struct logbuf_t* logbuf, char *fmt, ...); +int logbuf_close(struct logbuf_t * logbuf); + +int logbuf_init(struct logbuf_t * logbuf, char * fname, off_t bufsize, off_t ratelimit) +{ + int ret; + + if (logbuf->inited == INITED) + return 0; + + logbuf->dfd = open(fname, O_RDWR | O_CREAT, 0666); + if (logbuf->dfd == -1) { + ast_log(LOG_DEBUG, "error opening dest..: %s\n", strerror(errno)); + goto err; + } + ret = ftruncate(logbuf->dfd, bufsize); + if (ret == -1) { + ast_log(LOG_DEBUG, "error truncating dest.: %s\n", strerror(errno)); + goto err; + } + logbuf->dmem = mmap(NULL, bufsize, PROT_WRITE, MAP_SHARED, logbuf->dfd, 0); + if (logbuf->dmem == MAP_FAILED) { + ast_log(LOG_DEBUG, "error mapping dest..: %s\n", strerror(errno)); + goto err; + } + + logbuf->buflen = bufsize; + logbuf->off = 0; + logbuf->ratelimit = ratelimit; + logbuf->inited = INITED; + + return 0; + +err: + return -1; +} + +void logbuf_flush(struct logbuf_t * logbuf) +{ + msync(logbuf->dmem, logbuf->off, MS_SYNC); +} + + +int logbuf(struct logbuf_t* logbuf, char *fmt, ...) +{ + va_list arg_ptr; + + if ( logbuf->dmem == NULL || logbuf->off >= (unsigned int)logbuf->buflen) + return -1; + + va_start(arg_ptr, fmt); + logbuf->off += vsnprintf(logbuf->dmem + logbuf->off, logbuf->buflen, fmt, arg_ptr); + va_end(arg_ptr); + + if ((logbuf->off % logbuf->ratelimit) == 0) + logbuf_flush(logbuf); + + return logbuf->off; +} + +int logbuf_close(struct logbuf_t * logbuf) +{ + int ret; + + ret = munmap(logbuf->dmem, logbuf->buflen); + if (ret == -1) + ast_log(LOG_DEBUG, "error mapping dest..: %s\n", strerror(errno)); + + return close(logbuf->dfd); +} diff --git a/src/channels/timediff.h b/src/channels/timediff.h new file mode 100644 index 0000000000000000000000000000000000000000..1759e4755262096810ee3401790a04de687b749c --- /dev/null +++ b/src/channels/timediff.h @@ -0,0 +1,79 @@ +#include <stdio.h> +#include <sys/time.h> +#include <unistd.h> +#include <time.h> + +int time_delta (struct timeval *new_tm, struct timeval *old_tm, struct timeval *diff); +int time_delta_exceeds (struct timeval *new_tm, struct timeval *old_tm, int delta_ms); +int test_timediff(void); + +int time_delta (struct timeval *new_tm, struct timeval *old_tm, struct timeval *diff) +{ + if (new_tm->tv_usec < old_tm->tv_usec) { + int nsec = (old_tm->tv_usec - new_tm->tv_usec) / 1000000 + 1; + old_tm->tv_usec -= 1000000 * nsec; + old_tm->tv_sec += nsec; + } + if (new_tm->tv_usec - old_tm->tv_usec > 1000000) { + int nsec = (old_tm->tv_usec - new_tm->tv_usec) / 1000000; + old_tm->tv_usec += 1000000 * nsec; + old_tm->tv_sec -= nsec; + } + + diff->tv_sec = new_tm->tv_sec - old_tm->tv_sec; + diff->tv_usec = new_tm->tv_usec - old_tm->tv_usec; + + return new_tm->tv_sec < old_tm->tv_sec; +} + + +int time_delta_exceeds (struct timeval *new_tm, struct timeval *old_tm, int delta_ms) +{ + int delta; + struct timeval diff; + + time_delta (new_tm, old_tm, &diff); + delta = (diff.tv_sec * 1000) + (diff.tv_usec / 1000); + + if (delta > delta_ms) + return delta; + + return 0; +} + +/*int test_timediff(void) +{ + struct timeval difference; + struct timeval earlier; + struct timeval later; + + struct timespec ts = {0, 21000000}; + + int delay; + + earlier.tv_sec=3; + earlier.tv_usec=333333; + + later.tv_sec=3; + later.tv_usec=666333; + + gettimeofday(&earlier, NULL); + + //sleep(1); + + nanosleep(&ts, NULL); + + gettimeofday(&later, NULL); + + time_delta(&later, &earlier, &difference); + + printf("%lu sec, %ld usec\n", difference.tv_sec, difference.tv_usec); + printf ("msec %f\n", (difference.tv_sec * 1000.0) + (difference.tv_usec / 1000.0)); + printf ("msec %ld\n", (difference.tv_sec * 1000) + (difference.tv_usec / 1000)); + + if (delay = time_delta_exceeds(&later, &earlier, 20)) + printf("Delay is %d\n", delay); + + return 0; + +}*/