diff --git a/daemon/call.c b/daemon/call.c index 7bf77f850..769184f60 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -182,7 +182,7 @@ static void call_timer_iterator(void *key, void *val, void *ptr) { rwlock_lock_r(&cm->conf.config_lock); // final timeout applicable to all calls (own and foreign) - if (cm->conf.final_timeout && poller_now >= (c->created + cm->conf.final_timeout)) { + if (cm->conf.final_timeout && poller_now >= (c->created.tv_sec + cm->conf.final_timeout)) { ilog(LOG_INFO, "Closing call due to final timeout"); tmp_t_reason = FINAL_TIMEOUT; for (it = c->monologues.head; it; it = it->next) { @@ -1845,66 +1845,91 @@ void call_destroy(struct call *c) { rwlock_lock_w(&c->master_lock); /* at this point, no more packet streams can be added */ - if (IS_OWN_CALL(c)) { - ilog(LOG_INFO, "Final packet stats:"); + if (!IS_OWN_CALL(c)) + goto no_stats_output; + + ilog(LOG_INFO, "Final packet stats:"); - for (l = c->monologues.head; l; l = l->next) { - ml = l->data; + for (l = c->monologues.head; l; l = l->next) { + ml = l->data; - ilog(LOG_INFO, "--- Tag '"STR_FORMAT"', created " - "%u:%02u ago for branch '"STR_FORMAT"', in dialogue with '"STR_FORMAT"'", - STR_FMT(&ml->tag), - (unsigned int) (poller_now - ml->created) / 60, - (unsigned int) (poller_now - ml->created) % 60, - STR_FMT(&ml->viabranch), - ml->active_dialogue ? ml->active_dialogue->tag.len : 6, - ml->active_dialogue ? ml->active_dialogue->tag.s : "(none)"); + ilog(LOG_INFO, "--- Tag '"STR_FORMAT"', created " + "%u:%02u ago for branch '"STR_FORMAT"', in dialogue with '"STR_FORMAT"'", + STR_FMT(&ml->tag), + (unsigned int) (poller_now - ml->created) / 60, + (unsigned int) (poller_now - ml->created) % 60, + STR_FMT(&ml->viabranch), + ml->active_dialogue ? ml->active_dialogue->tag.len : 6, + ml->active_dialogue ? ml->active_dialogue->tag.s : "(none)"); - for (k = ml->medias.head; k; k = k->next) { - md = k->data; + for (k = ml->medias.head; k; k = k->next) { + md = k->data; - rtp_pt = __rtp_stats_codec(md); + rtp_pt = __rtp_stats_codec(md); #define MLL_PREFIX "------ Media #%u ("STR_FORMAT" over %s) using " /* media log line prefix */ #define MLL_COMMON /* common args */ \ - md->index, \ - STR_FMT(&md->type), \ - md->protocol ? md->protocol->name : "(unknown)" - if (!rtp_pt) - ilog(LOG_INFO, MLL_PREFIX "unknown codec", MLL_COMMON); - else - ilog(LOG_INFO, MLL_PREFIX STR_FORMAT, MLL_COMMON, - STR_FMT(&rtp_pt->encoding_with_params)); - - for (o = md->streams.head; o; o = o->next) { - ps = o->data; - - if (PS_ISSET(ps, FALLBACK_RTCP)) - continue; - - char *addr = sockaddr_print_buf(&ps->endpoint.address); - char *local_addr = ps->selected_sfd ? sockaddr_print_buf(&ps->selected_sfd->socket.local.address) : "0.0.0.0"; - - ilog(LOG_INFO, "--------- Port %15s:%-5u <> %15s:%-5u%s, SSRC %" PRIu32 ", " - ""UINT64F" p, "UINT64F" b, "UINT64F" e, "UINT64F" last_packet", - local_addr, - (unsigned int) (ps->selected_sfd ? ps->selected_sfd->socket.local.port : 0), - addr, ps->endpoint.port, - (!PS_ISSET(ps, RTP) && PS_ISSET(ps, RTCP)) ? " (RTCP)" : "", - ps->ssrc_in ? ps->ssrc_in->parent->ssrc : 0, - atomic64_get(&ps->stats.packets), - atomic64_get(&ps->stats.bytes), - atomic64_get(&ps->stats.errors), - atomic64_get(&ps->last_packet)); - - statistics_update_totals(m,ps); + md->index, \ + STR_FMT(&md->type), \ + md->protocol ? md->protocol->name : "(unknown)" + if (!rtp_pt) + ilog(LOG_INFO, MLL_PREFIX "unknown codec", MLL_COMMON); + else + ilog(LOG_INFO, MLL_PREFIX STR_FORMAT, MLL_COMMON, + STR_FMT(&rtp_pt->encoding_with_params)); - } + for (o = md->streams.head; o; o = o->next) { + ps = o->data; + + if (PS_ISSET(ps, FALLBACK_RTCP)) + continue; + + char *addr = sockaddr_print_buf(&ps->endpoint.address); + char *local_addr = ps->selected_sfd ? sockaddr_print_buf(&ps->selected_sfd->socket.local.address) : "0.0.0.0"; + + ilog(LOG_INFO, "--------- Port %15s:%-5u <> %15s:%-5u%s, SSRC %" PRIu32 ", " + ""UINT64F" p, "UINT64F" b, "UINT64F" e, "UINT64F" ts", + local_addr, + (unsigned int) (ps->selected_sfd ? ps->selected_sfd->socket.local.port : 0), + addr, ps->endpoint.port, + (!PS_ISSET(ps, RTP) && PS_ISSET(ps, RTCP)) ? " (RTCP)" : "", + ps->ssrc_in ? ps->ssrc_in->parent->ssrc : 0, + atomic64_get(&ps->stats.packets), + atomic64_get(&ps->stats.bytes), + atomic64_get(&ps->stats.errors), + g_now.tv_sec - atomic64_get(&ps->last_packet)); + + statistics_update_totals(m,ps); - ice_shutdown(&md->ice_agent); } + + ice_shutdown(&md->ice_agent); } } + k = g_hash_table_get_values(c->ssrc_hash->ht); + for (l = k; l; l = l->next) { + struct ssrc_entry *se = l->data; + + if (!se->stats_blocks.length || !se->lowest_mos || !se->highest_mos) + continue; + + ilog(LOG_INFO, "--- SSRC %" PRIu32 "", se->ssrc); + ilog(LOG_INFO, "------ Average MOS %i.%i, lowest MOS %i.%i (at %u:%02u), " + "highest MOS %i.%i (at %u:%02u)", + (int) (se->mos_sum / se->stats_blocks.length / 10), + abs(se->mos_sum / se->stats_blocks.length % 10), + se->lowest_mos->mos / 10, + abs(se->lowest_mos->mos % 10), + (unsigned int) (timeval_diff(&se->lowest_mos->reported, &c->created) / 1000000) / 60, + (unsigned int) (timeval_diff(&se->lowest_mos->reported, &c->created) / 1000000) % 60, + se->highest_mos->mos / 10, + abs(se->highest_mos->mos % 10), + (unsigned int) (timeval_diff(&se->highest_mos->reported, &c->created) / 1000000) / 60, + (unsigned int) (timeval_diff(&se->highest_mos->reported, &c->created) / 1000000) % 60); + } + g_list_free(k); + +no_stats_output: statistics_update_oneway(c); cdr_update_entry(c); @@ -2033,7 +2058,7 @@ static struct call *call_create(const str *callid, struct callmaster *m) { c->tags = g_hash_table_new(str_hash, str_equal); c->viabranches = g_hash_table_new(str_hash, str_equal); call_str_cpy(c, &c->callid, callid); - c->created = poller_now; + c->created = g_now; c->dtls_cert = dtls_cert(); c->tos = m->conf.default_tos; c->ssrc_hash = create_ssrc_hash(); diff --git a/daemon/call.h b/daemon/call.h index d1e7bf186..be41e8982 100644 --- a/daemon/call.h +++ b/daemon/call.h @@ -372,7 +372,7 @@ struct call { struct ssrc_hash *ssrc_hash; str callid; - time_t created; + struct timeval created; time_t last_signal; time_t deleted; time_t ml_deleted; diff --git a/daemon/call_interfaces.c b/daemon/call_interfaces.c index f13feb6b9..85277a39f 100644 --- a/daemon/call_interfaces.c +++ b/daemon/call_interfaces.c @@ -427,9 +427,9 @@ static void call_status_iterator(struct call *c, struct control_stream *s) { // m = c->callmaster; // mutex_lock(&c->master_lock); - control_stream_printf(s, "session "STR_FORMAT" - - - - %i\n", + control_stream_printf(s, "session "STR_FORMAT" - - - - %lli\n", STR_FMT(&c->callid), - (int) (poller_now - c->created)); + timeval_diff(&g_now, &c->created) / 1000000); /* XXX restore function */ @@ -1021,7 +1021,8 @@ void ng_call_stats(struct call *call, const str *fromtag, const str *totag, benc call_bencode_hold_ref(call, output); - bencode_dictionary_add_integer(output, "created", call->created); + bencode_dictionary_add_integer(output, "created", call->created.tv_sec); + bencode_dictionary_add_integer(output, "created_us", call->created.tv_usec); bencode_dictionary_add_integer(output, "last signal", call->last_signal); tags = bencode_dictionary_add_dictionary(output, "tags"); diff --git a/daemon/cli.c b/daemon/cli.c index 4afba45af..503e71e11 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -283,7 +283,7 @@ static void cli_incoming_list_callid(char* buffer, int len, struct callmaster* m } printlen = snprintf (replybuffer,(outbufend-replybuffer), "\ncallid: %60s | deletionmark:%4s | created:%12i | proxy:%s | tos:%u | last_signal:%llu | redis_keyspace:%i | foreign:%s\n\n", - c->callid.s , c->ml_deleted?"yes":"no", (int)c->created, c->created_from, (unsigned int)c->tos, (unsigned long long)c->last_signal, c->redis_hosted_db, IS_FOREIGN_CALL(c)?"yes":"no"); + c->callid.s , c->ml_deleted?"yes":"no", (int)c->created.tv_sec, c->created_from, (unsigned int)c->tos, (unsigned long long)c->last_signal, c->redis_hosted_db, IS_FOREIGN_CALL(c)?"yes":"no"); ADJUSTLEN(printlen,outbufend,replybuffer); for (l = c->monologues.head; l; l = l->next) { @@ -417,7 +417,7 @@ static void cli_incoming_list_sessions(char* buffer, int len, struct callmaster* break; } - printlen = snprintf(replybuffer, outbufend-replybuffer, "callid: %60s | deletionmark:%4s | created:%12i | proxy:%s | redis_keyspace:%i | foreign:%s\n", ptrkey->s, call->ml_deleted?"yes":"no", (int)call->created, call->created_from, call->redis_hosted_db, IS_FOREIGN_CALL(call)?"yes":"no"); + printlen = snprintf(replybuffer, outbufend-replybuffer, "callid: %60s | deletionmark:%4s | created:%12i | proxy:%s | redis_keyspace:%i | foreign:%s\n", ptrkey->s, call->ml_deleted?"yes":"no", (int)call->created.tv_sec, call->created_from, call->redis_hosted_db, IS_FOREIGN_CALL(call)?"yes":"no"); ADJUSTLEN(printlen,outbufend,replybuffer); } rwlock_unlock_r(&m->hashlock); diff --git a/daemon/recording.c b/daemon/recording.c index a0db96d41..391fbe661 100644 --- a/daemon/recording.c +++ b/daemon/recording.c @@ -369,7 +369,7 @@ static int pcap_meta_finish_file(struct call *call) { // Print start timestamp and end timestamp // YYYY-MM-DDThh:mm:ss - time_t start = call->created; + time_t start = call->created.tv_sec; time_t end = g_now.tv_sec; char timebuffer[20]; struct tm *timeinfo; diff --git a/daemon/redis.c b/daemon/redis.c index 9aa60c795..f066e7f89 100644 --- a/daemon/redis.c +++ b/daemon/redis.c @@ -797,8 +797,15 @@ static atomic64 strtoa64(const char *c, char **endp, int base) { atomic64_set_na(&ret, u); return ret; } +static struct timeval strtotimeval(const char *c, char **endp, int base) { + long long ll = strtoll(c, endp, base); + struct timeval ret; + timeval_from_us(&ret, ll); + return ret; +} define_get_int_type(time_t, time_t, strtoull); +define_get_int_type(timeval, struct timeval, strtotimeval); define_get_int_type(int, int, strtol); define_get_int_type(unsigned, unsigned int, strtol); //define_get_int_type(u16, u_int16_t, strtol); @@ -1427,7 +1434,7 @@ static void json_restore_call(struct redis *r, struct callmaster *m, const str * goto err7; err = "missing 'created' timestamp"; - if (redis_hash_get_time_t(&c->created, &call, "created")) + if (redis_hash_get_timeval(&c->created, &call, "created")) goto err8; err = "missing 'last signal' timestamp"; if (redis_hash_get_time_t(&c->last_signal, &call, "last_signal")) @@ -1697,7 +1704,7 @@ char* redis_encode_json(struct call *c) { json_builder_begin_object (builder); { - JSON_SET_SIMPLE("created","%ld",(long int) c->created); + JSON_SET_SIMPLE("created","%lli", timeval_us(&c->created)); JSON_SET_SIMPLE("last_signal","%ld",(long int) c->last_signal); JSON_SET_SIMPLE("tos","%u",(int) c->tos); JSON_SET_SIMPLE("deleted","%ld",(long int) c->deleted); diff --git a/daemon/ssrc.c b/daemon/ssrc.c index a39ad11ec..573ebed87 100644 --- a/daemon/ssrc.c +++ b/daemon/ssrc.c @@ -41,7 +41,7 @@ static void free_ssrc_entry(void *p) { static void mos_calc(struct ssrc_stats_block *ssb) { // as per https://www.pingman.com/kb/article/how-is-mos-calculated-in-pingplotter-pro-50.html int eff_rtt = ssb->rtt / 1000 + ssb->jitter * 2 + 10; - double r; + double r; // XXX can this be done with int math? if (eff_rtt < 160) r = 93.2 - eff_rtt / 40.0; else @@ -211,8 +211,26 @@ found: // got a new stats block, add it to reporting ssrc e = get_ssrc(rr->from, c->ssrc_hash); + mutex_lock(&e->lock); + + // discard stats block if last has been received less than a second ago + if (G_LIKELY(e->stats_blocks.length > 0)) { + struct ssrc_stats_block *last_ssb = g_queue_peek_tail(&e->stats_blocks); + if (G_UNLIKELY(timeval_diff(tv, &last_ssb->reported) < 1000000)) { + free_stats_block(ssb); + goto out; + } + } + g_queue_push_tail(&e->stats_blocks, ssb); + + if (G_UNLIKELY(!e->lowest_mos) || ssb->mos < e->lowest_mos->mos) + e->lowest_mos = ssb; + if (G_UNLIKELY(!e->highest_mos) || ssb->mos > e->highest_mos->mos) + e->highest_mos = ssb; + e->mos_sum += ssb->mos; + goto out; out: diff --git a/daemon/ssrc.h b/daemon/ssrc.h index f289e6529..950460cef 100644 --- a/daemon/ssrc.h +++ b/daemon/ssrc.h @@ -37,6 +37,9 @@ struct ssrc_entry { output_ctx; GQueue sender_reports; // as received via RTCP GQueue stats_blocks; // calculated + struct ssrc_stats_block *lowest_mos, + *highest_mos; + u_int64_t mos_sum; int payload_type; // to determine the clock rate for jitter calculations unsigned int last_rtt; // last calculated raw rtt without rtt from opposide side };