diff --git a/README.md b/README.md index cd5993eec..4632e06e7 100644 --- a/README.md +++ b/README.md @@ -194,7 +194,9 @@ Usage Userspace Daemon ---------------- -The options are described in detail in the rtpengine(1) man page. +The options are described in detail in the rtpengine(1) man page. If you're +reading this on Github, you can view the current master's man page +[here](https://github.com/sipwise/rtpengine/blob/master/daemon/rtpengine.pod). In-kernel Packet Forwarding --------------------------- diff --git a/daemon/call.c b/daemon/call.c index f6edf8df7..8512188fb 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -777,7 +777,7 @@ static struct call_media *__get_media(struct call_monologue *ml, GList **it, con med = g_hash_table_lookup(ml->media_ids, &sp->media_id); if (med) return med; - ilog(LOG_ERR, "Received trickle ICE SDP fragment with unknown media ID '" + ilogs(ice, LOG_ERR, "Received trickle ICE SDP fragment with unknown media ID '" STR_FORMAT "'", STR_FMT(&sp->media_id)); } @@ -1087,14 +1087,14 @@ int __init_stream(struct packet_stream *ps) { struct crypto_params_sdes *cps = media->sdes_in.head ? media->sdes_in.head->data : NULL; crypto_init(&sfd->crypto, cps ? &cps->params : NULL); - ilog(LOG_DEBUG, "[%s] Initialized incoming SRTP with SDES crypto params: %s%s%s", + ilogs(crypto, LOG_DEBUG, "[%s] Initialized incoming SRTP with SDES crypto params: %s%s%s", endpoint_print_buf(&sfd->socket.local), FMT_M(crypto_params_sdes_dump(cps, ¶msbuf))); } struct crypto_params_sdes *cps = media->sdes_out.head ? media->sdes_out.head->data : NULL; crypto_init(&ps->crypto, cps ? &cps->params : NULL); - ilog(LOG_DEBUG, "[%i] Initialized outgoing SRTP with SDES crypto params: %s%s%s", + ilogs(crypto, LOG_DEBUG, "[%i] Initialized outgoing SRTP with SDES crypto params: %s%s%s", ps->component, FMT_M(crypto_params_sdes_dump(cps, ¶msbuf))); } @@ -1489,7 +1489,7 @@ static void __generate_crypto(const struct sdp_ng_flags *flags, struct call_medi if (flags->sdes_no && g_hash_table_lookup(flags->sdes_no, &crypto_suites[i].name_str)) { - ilog(LOG_DEBUG, "Not offering crypto suite '%s' " + ilogs(crypto, LOG_DEBUG, "Not offering crypto suite '%s' " "due to 'SDES-no' option", crypto_suites[i].name); continue; @@ -1515,14 +1515,14 @@ static void __generate_crypto(const struct sdp_ng_flags *flags, struct call_medi struct crypto_params_sdes *cps_in = cpq_in->head ? cpq_in->head->data : NULL; struct crypto_params_sdes *offered_cps = offered_cpq->head ? offered_cpq->head->data : NULL; if (offered_cps) { - ilog(LOG_DEBUG, "Looking for matching crypto suite to offered %u:%s", offered_cps->tag, + ilogs(crypto, LOG_DEBUG, "Looking for matching crypto suite to offered %u:%s", offered_cps->tag, offered_cps->params.crypto_suite->name); // check if we can do SRTP<>SRTP passthrough. the crypto suite that was accepted // must have been present in what was offered to us for (GList *l = cpq_in->head; l; l = l->next) { struct crypto_params_sdes *check_cps = l->data; if (check_cps->params.crypto_suite == offered_cps->params.crypto_suite) { - ilog(LOG_DEBUG, "Found matching crypto suite %u:%s", check_cps->tag, + ilogs(crypto, LOG_DEBUG, "Found matching crypto suite %u:%s", check_cps->tag, check_cps->params.crypto_suite->name); cps_in = check_cps; break; @@ -1540,7 +1540,7 @@ static void __generate_crypto(const struct sdp_ng_flags *flags, struct call_medi // SRTP<>SRTP passthrough cps->params.session_params = cps_in->params.session_params; // XXX verify crypto_params_copy(&cps->params, &offered_cps->params, 1); - ilog(LOG_DEBUG, "Copied crypto params from %i:%s for SRTP passthrough", + ilogs(crypto, LOG_DEBUG, "Copied crypto params from %i:%s for SRTP passthrough", cps_in->tag, cps_in->params.crypto_suite->name); } else { @@ -1550,14 +1550,14 @@ static void __generate_crypto(const struct sdp_ng_flags *flags, struct call_medi cps->params.crypto_suite->master_salt_len); /* mki = mki_len = 0 */ cps->params.session_params = cps_in->params.session_params; - ilog(LOG_DEBUG, "Creating new SRTP crypto params for %i:%s", + ilogs(crypto, LOG_DEBUG, "Creating new SRTP crypto params for %i:%s", cps->tag, cps->params.crypto_suite->name); } // flush out crypto suites we ended up not using - leave only one #if GLIB_CHECK_VERSION(2,30,0) if (!g_queue_remove(cpq_in, cps_in)) - ilog(LOG_ERR, "BUG: incoming crypto suite not found in queue"); + ilogs(crypto, LOG_ERR, "BUG: incoming crypto suite not found in queue"); #else g_queue_remove(cpq_in, cps_in); #endif @@ -1595,7 +1595,7 @@ static void __sdes_accept(struct call_media *media, const struct sdp_ng_flags *f continue; } - ilog(LOG_DEBUG, "Dropping offered crypto suite '%s' from offer " + ilogs(crypto, LOG_DEBUG, "Dropping offered crypto suite '%s' from offer " "due to 'SDES-no' option", offered_cps->params.crypto_suite->name); @@ -1714,7 +1714,7 @@ static void __fingerprint_changed(struct call_media *m) { if (!m->fingerprint.hash_func || !m->fingerprint.digest_len) return; - ilog(LOG_INFO, "DTLS fingerprint changed, restarting DTLS"); + ilogs(crypto, LOG_INFO, "DTLS fingerprint changed, restarting DTLS"); for (l = m->streams.head; l; l = l->next) { ps = l->data; diff --git a/daemon/cli.c b/daemon/cli.c index dea3f0935..a7341dec3 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -244,7 +244,12 @@ static void cli_incoming_params_start(str *instr, struct cli_writer *cw) { GList *s; struct intf_config *ifa; - cw->cw_printf(cw, "log-level = %d\ntable = %d\nmax-sessions = %d\ntimeout = %d\nsilent-timeout = %d\n" + for (unsigned int i = 0; i < num_log_levels; i++) + cw->cw_printf(cw, "log-level-%s = %d\n", + log_level_names[i], + g_atomic_int_get(&initial_rtpe_config.common.log_levels[i])); + + cw->cw_printf(cw, "table = %d\nmax-sessions = %d\ntimeout = %d\nsilent-timeout = %d\n" "final-timeout = %d\noffer-timeout = %d\n" "delete-delay = %d\nredis-expires = %d\ntos = %d\ncontrol-tos = %d\ngraphite-interval = %d\nredis-num-threads = %d\n" "homer-protocol = %d\nhomer-id = %d\nno-fallback = %d\nport-min = %d\nport-max = %d\nredis = %s:%d/%d\n" @@ -253,7 +258,7 @@ static void cli_incoming_params_start(str *instr, struct cli_writer *cw) { "max-cpu = %.1f\n" "max-load = %.2f\n" "max-bandwidth = %" PRIu64 "\n", - initial_rtpe_config.common.log_level, initial_rtpe_config.kernel_table, initial_rtpe_config.max_sessions, + initial_rtpe_config.kernel_table, initial_rtpe_config.max_sessions, initial_rtpe_config.timeout, initial_rtpe_config.silent_timeout, initial_rtpe_config.final_timeout, initial_rtpe_config.offer_timeout, initial_rtpe_config.delete_delay, initial_rtpe_config.redis_expires_secs, initial_rtpe_config.default_tos, initial_rtpe_config.control_tos, @@ -294,7 +299,12 @@ static void cli_incoming_params_current(str *instr, struct cli_writer *cw) { GList *c; struct intf_config *ifa; - cw->cw_printf(cw, "log-level = %d\ntable = %d\nmax-sessions = %d\ntimeout = %d\nsilent-timeout = %d\n" + for (unsigned int i = 0; i < num_log_levels; i++) + cw->cw_printf(cw, "log-level-%s = %d\n", + log_level_names[i], + g_atomic_int_get(&rtpe_config.common.log_levels[i])); + + cw->cw_printf(cw, "table = %d\nmax-sessions = %d\ntimeout = %d\nsilent-timeout = %d\n" "final-timeout = %d\noffer-timeout = %d\n" "delete-delay = %d\nredis-expires = %d\ntos = %d\ncontrol-tos = %d\ngraphite-interval = %d\nredis-num-threads = %d\n" "homer-protocol = %d\nhomer-id = %d\nno-fallback = %d\nport-min = %d\nport-max = %d\nredis-db = %d\n" @@ -303,7 +313,7 @@ static void cli_incoming_params_current(str *instr, struct cli_writer *cw) { "max-cpu = %.1f\n" "max-load = %.2f\n" "max-bw = %" PRIu64 "\n", - rtpe_config.common.log_level, rtpe_config.kernel_table, rtpe_config.max_sessions, rtpe_config.timeout, + rtpe_config.kernel_table, rtpe_config.max_sessions, rtpe_config.timeout, rtpe_config.silent_timeout, rtpe_config.final_timeout, rtpe_config.offer_timeout, rtpe_config.delete_delay, rtpe_config.redis_expires_secs, rtpe_config.default_tos, rtpe_config.control_tos, rtpe_config.graphite_interval, rtpe_config.redis_num_threads, rtpe_config.homer_protocol, @@ -367,7 +377,10 @@ static void int_diff_print_sz(long long start_param, void* current_param, size_t option_string, cw, option) static void cli_incoming_diff_or_revert(struct cli_writer *cw, char* option) { - int_diff_print(common.log_level, "log-level"); +#define ll(system) \ + int_diff_print(common.log_levels[log_level_index_ ## system], "log-level-" #system); +#include "loglevels.h" +#undef ll int_diff_print(max_sessions, "max-sessions"); int_diff_print(cpu_limit, "max-cpu"); int_diff_print(load_limit, "max-load"); @@ -1081,7 +1094,7 @@ static void cli_incoming_standby(str *instr, struct cli_writer *cw) { } static void cli_incoming(struct streambuf_stream *s) { - ilog(LOG_INFO, "New cli connection from %s", s->addr); + ilogs(control, LOG_INFO, "New cli connection from %s", s->addr); } static void cli_streambuf_printf(struct cli_writer *cw, const char *fmt, ...) { @@ -1099,7 +1112,7 @@ static void cli_stream_readable(struct streambuf_stream *s) { inbuf = streambuf_getline(s->inbuf); if (!inbuf) { if (streambuf_bufsize(s->inbuf) > MAXINPUT) { - ilog(LOG_INFO, "Buffer length exceeded in CLI connection from %s", s->addr); + ilogs(control, LOG_INFO, "Buffer length exceeded in CLI connection from %s", s->addr); streambuf_stream_close(s); } return; @@ -1119,7 +1132,7 @@ static void cli_stream_readable(struct streambuf_stream *s) { } void cli_handle(str *instr, struct cli_writer *cw) { - ilog(LOG_INFO, "Got CLI command: " STR_FORMAT_M, STR_FMT_M(instr)); + ilogs(control, LOG_INFO, "Got CLI command: " STR_FORMAT_M, STR_FMT_M(instr)); cli_handler_do(cli_top_handlers, instr, cw); } @@ -1143,7 +1156,7 @@ struct cli *cli_new(struct poller *p, endpoint_t *ep) { NULL, &c->obj)) { - ilog(LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); + ilogs(control, LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); goto fail; } if (ipv46_any_convert(ep)) { @@ -1153,7 +1166,7 @@ struct cli *cli_new(struct poller *p, endpoint_t *ep) { NULL, &c->obj)) { - ilog(LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); + ilogs(control, LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); goto fail; } } @@ -1170,7 +1183,8 @@ fail: } static void cli_incoming_list_loglevel(str *instr, struct cli_writer *cw) { - cw->cw_printf(cw, "%i\n", get_log_level()); + for (unsigned int i = 0; i < num_log_levels; i++) + cw->cw_printf(cw, "%s = %i\n", log_level_names[i], __get_log_level(i)); } static void cli_incoming_set_loglevel(str *instr, struct cli_writer *cw) { int nl; @@ -1187,7 +1201,8 @@ static void cli_incoming_set_loglevel(str *instr, struct cli_writer *cw) { return; } - g_atomic_int_set(&rtpe_config.common.log_level, nl); + for (unsigned int i = 0; i < num_log_levels; i++) + g_atomic_int_set(&rtpe_config.common.log_levels[i], nl); cw->cw_printf(cw, "Success setting loglevel to %i\n", nl); } diff --git a/daemon/codec.c b/daemon/codec.c index f20c14f92..8b0106d44 100644 --- a/daemon/codec.c +++ b/daemon/codec.c @@ -233,7 +233,7 @@ static struct codec_handler *__handler_new(const struct rtp_payload_type *pt, st static void __make_passthrough(struct codec_handler *handler) { __handler_shutdown(handler); - ilog(LOG_DEBUG, "Using passthrough handler for " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Using passthrough handler for " STR_FORMAT, STR_FMT(&handler->source_pt.encoding_with_params)); if (handler->source_pt.codec_def && handler->source_pt.codec_def->dtmf) handler->func = handler_func_dtmf; @@ -248,7 +248,7 @@ static void __make_passthrough(struct codec_handler *handler) { } static void __make_passthrough_ssrc(struct codec_handler *handler) { __handler_shutdown(handler); - ilog(LOG_DEBUG, "Using passthrough handler with new SSRC for " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Using passthrough handler with new SSRC for " STR_FORMAT, STR_FMT(&handler->source_pt.encoding_with_params)); if (handler->source_pt.codec_def && handler->source_pt.codec_def->dtmf) handler->func = handler_func_dtmf; @@ -280,7 +280,7 @@ static void __make_transcoder(struct codec_handler *handler, struct rtp_payload_ if (handler->func != handler_func_transcode) goto reset; - ilog(LOG_DEBUG, "Leaving transcode context for " STR_FORMAT " -> " STR_FORMAT " intact", + ilogs(codec, LOG_DEBUG, "Leaving transcode context for " STR_FORMAT " -> " STR_FORMAT " intact", STR_FMT(&handler->source_pt.encoding_with_params), STR_FMT(&dest->encoding_with_params)); @@ -298,13 +298,13 @@ reset: // is this DTMF to DTMF? if (dtmf_payload_type != -1 && handler->source_pt.codec_def->dtmf) { - ilog(LOG_DEBUG, "Created DTMF transcode context for " STR_FORMAT " -> PT %i", + ilogs(codec, LOG_DEBUG, "Created DTMF transcode context for " STR_FORMAT " -> PT %i", STR_FMT(&handler->source_pt.encoding_with_params), dtmf_payload_type); handler->dtmf_scaler = 1; } else - ilog(LOG_DEBUG, "Created transcode context for " STR_FORMAT " -> " STR_FORMAT + ilogs(codec, LOG_DEBUG, "Created transcode context for " STR_FORMAT " -> " STR_FORMAT " with DTMF output %i", STR_FMT(&handler->source_pt.encoding_with_params), STR_FMT(&dest->encoding_with_params), dtmf_payload_type); @@ -339,7 +339,7 @@ check_output:; output_handler = g_hash_table_lookup(output_transcoders, GINT_TO_POINTER(dest->payload_type)); if (output_handler) { - ilog(LOG_DEBUG, "Using existing encoder context"); + ilogs(codec, LOG_DEBUG, "Using existing encoder context"); handler->output_handler = output_handler; } else { @@ -361,7 +361,7 @@ struct codec_handler *codec_handler_make_playback(const struct rtp_payload_type handler->ssrc_handler->first_ts = random(); handler->ssrc_handler->rtp_mark = 1; - ilog(LOG_DEBUG, "Created media playback context for " STR_FORMAT " -> " STR_FORMAT "", + ilogs(codec, LOG_DEBUG, "Created media playback context for " STR_FORMAT " -> " STR_FORMAT "", STR_FMT(&src_pt->encoding_with_params), STR_FMT(&dst_pt->encoding_with_params)); @@ -404,7 +404,7 @@ static void __dtmf_dsp_shutdown(struct call_media *sink, int payload_type) { if (handler->dtmf_scaler) continue; - ilog(LOG_DEBUG, "Shutting down DTMF DSP for '" STR_FORMAT "' -> %i (not needed)", + ilogs(codec, LOG_DEBUG, "Shutting down DTMF DSP for '" STR_FORMAT "' -> %i (not needed)", STR_FMT(&handler->source_pt.encoding_with_params), payload_type); handler->dtmf_payload_type = -1; @@ -485,7 +485,7 @@ static struct rtp_payload_type *__check_dest_codecs(struct call_media *receiver, if (first_tc_codec) pref_dest_codec = first_tc_codec; if (pref_dest_codec) - ilog(LOG_DEBUG, "Default sink codec is " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Default sink codec is " STR_FORMAT, STR_FMT(&pref_dest_codec->encoding_with_params)); return pref_dest_codec; @@ -563,11 +563,11 @@ static int __dtmf_payload_type(GHashTable *supplemental_sinks, struct rtp_payloa int dtmf_payload_type = __supp_payload_type(supplemental_sinks, pref_dest_codec, "telephone-event"); if (dtmf_payload_type == -1) - ilog(LOG_INFO, "Not transcoding PCM DTMF tones to telephone-event packets as " + ilogs(codec, LOG_INFO, "Not transcoding PCM DTMF tones to telephone-event packets as " "no payload type with a matching clock rate for '" STR_FORMAT "' was found", STR_FMT(&pref_dest_codec->encoding_with_params)); else - ilog(LOG_DEBUG, "Output DTMF payload type is %i", dtmf_payload_type); + ilogs(codec, LOG_DEBUG, "Output DTMF payload type is %i", dtmf_payload_type); return dtmf_payload_type; } @@ -624,7 +624,7 @@ static void __single_codec(struct call_media *media, const struct sdp_ng_flags * l = l->next; continue; } - ilog(LOG_DEBUG, "Removing codec '" STR_FORMAT "' due to 'single codec' flag", + ilogs(codec, LOG_DEBUG, "Removing codec '" STR_FORMAT "' due to 'single codec' flag", STR_FMT(&pt->encoding_with_params)); codec_touched(pt, media); l = __delete_receiver_codec(media, l); @@ -696,13 +696,13 @@ static void __accept_transcode_codecs(struct call_media *receiver, struct call_m // the existing entry. int new_pt = __unused_pt_number(receiver, sink, existing_pt); if (new_pt < 0) { - ilog(LOG_WARN, "Ran out of RTP payload type numbers while accepting '" + ilogs(codec, LOG_WARN, "Ran out of RTP payload type numbers while accepting '" STR_FORMAT "' due to '" STR_FORMAT "'", STR_FMT(&pt->encoding_with_params), STR_FMT(&existing_pt->encoding_with_params)); continue; } - ilog(LOG_DEBUG, "Renumbering '" STR_FORMAT "' from PT %i to %i due to '" STR_FORMAT "'", + ilogs(codec, LOG_DEBUG, "Renumbering '" STR_FORMAT "' from PT %i to %i due to '" STR_FORMAT "'", STR_FMT(&existing_pt->encoding_with_params), existing_pt->payload_type, new_pt, @@ -713,7 +713,7 @@ static void __accept_transcode_codecs(struct call_media *receiver, struct call_m } //ilog(LOG_DEBUG, "XXXXXXXXXXXXX offered codec %i", pt->for_transcoding); - ilog(LOG_DEBUG, "Accepting offered codec " STR_FORMAT " due to transcoding", + ilogs(codec, LOG_DEBUG, "Accepting offered codec " STR_FORMAT " due to transcoding", STR_FMT(&pt->encoding_with_params)); MEDIA_SET(receiver, TRANSCODE); @@ -769,7 +769,7 @@ static void __eliminate_rejected_codecs(struct call_media *receiver, struct call l = l->next; continue; } - ilog(LOG_DEBUG, "Eliminating asymmetric outbound codec " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Eliminating asymmetric outbound codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); l = __delete_send_codec(receiver, l); } @@ -784,7 +784,7 @@ static GHashTable *__payload_type_queue_hash(GQueue *prefs, GQueue *order) { for (GList *l = prefs->head; l; l = l->next) { struct rtp_payload_type *pt = l->data; if (g_hash_table_lookup(ret, GINT_TO_POINTER(pt->payload_type))) { - ilog(LOG_DEBUG, "Removing duplicate RTP payload type %i", pt->payload_type); + ilogs(codec, LOG_DEBUG, "Removing duplicate RTP payload type %i", pt->payload_type); payload_type_free(pt); continue; } @@ -837,7 +837,7 @@ static void __symmetric_codecs(struct call_media *receiver, struct call_media *s struct rtp_payload_type *send_pt; if (!out_pt || !(send_pt = g_hash_table_lookup(prefs_send, GINT_TO_POINTER(pt->payload_type)))) { // we must transcode after all. - ilog(LOG_DEBUG, "RTP payload type %i is not symmetric and must be transcoded", + ilogs(codec, LOG_DEBUG, "RTP payload type %i is not symmetric and must be transcoded", pt->payload_type); transcoding = 1; continue; @@ -857,7 +857,7 @@ static void __symmetric_codecs(struct call_media *receiver, struct call_media *s continue; // not interesting // add it to the list - ilog(LOG_DEBUG, "Adding force-accepted RTP payload type %i", prefix_pt->payload_type); + ilogs(codec, LOG_DEBUG, "Adding force-accepted RTP payload type %i", prefix_pt->payload_type); g_hash_table_steal(prefs_send, ptype); __rtp_payload_type_add_send(receiver, prefix_pt); // and our receive leg @@ -870,7 +870,7 @@ static void __symmetric_codecs(struct call_media *receiver, struct call_media *s } // add it to the list - ilog(LOG_DEBUG, "Adding symmetric RTP payload type %i", pt->payload_type); + ilogs(codec, LOG_DEBUG, "Adding symmetric RTP payload type %i", pt->payload_type); g_hash_table_steal(prefs_recv, GINT_TO_POINTER(pt->payload_type)); __rtp_payload_type_add_recv(receiver, out_pt, 1); // and our send leg @@ -934,7 +934,7 @@ static void __check_dtmf_injector(const struct sdp_ng_flags *flags, struct call_ const str tp_event = STR_CONST_INIT("telephone-event"); src_pt.codec_def = codec_find(&tp_event, MT_AUDIO); if (!src_pt.codec_def) { - ilog(LOG_ERR, "RTP payload type 'telephone-event' is not defined"); + ilogs(codec, LOG_ERR, "RTP payload type 'telephone-event' is not defined"); return; } @@ -956,14 +956,14 @@ static struct codec_handler *__get_pt_handler(struct call_media *receiver, struc if (handler) { // make sure existing handler matches this PT if (rtp_payload_type_cmp(pt, &handler->source_pt)) { - ilog(LOG_DEBUG, "Resetting codec handler for PT %u", pt->payload_type); + ilogs(codec, LOG_DEBUG, "Resetting codec handler for PT %u", pt->payload_type); handler = NULL; g_atomic_pointer_set(&receiver->codec_handler_cache, NULL); g_hash_table_remove(receiver->codec_handlers, GINT_TO_POINTER(pt->payload_type)); } } if (!handler) { - ilog(LOG_DEBUG, "Creating codec handler for " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Creating codec handler for " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); handler = __handler_new(pt, receiver); g_hash_table_insert(receiver->codec_handlers, @@ -987,7 +987,7 @@ static struct codec_handler *__get_pt_handler(struct call_media *receiver, struc static void __check_t38_decoder(struct call_media *t38_media) { if (t38_media->t38_handler) return; - ilog(LOG_DEBUG, "Creating T.38 packet handler"); + ilogs(codec, LOG_DEBUG, "Creating T.38 packet handler"); t38_media->t38_handler = __handler_new(NULL, t38_media); t38_media->t38_handler->func = handler_func_t38; } @@ -1053,12 +1053,12 @@ static void __check_t38_gateway(struct call_media *pcm_media, struct call_media struct codec_handler *handler = __get_pt_handler(pcm_media, pt); if (!pt->codec_def) { // should not happen - ilog(LOG_WARN, "Unsupported codec " STR_FORMAT " for T.38 transcoding", + ilogs(codec, LOG_WARN, "Unsupported codec " STR_FORMAT " for T.38 transcoding", STR_FMT(&pt->encoding_with_params)); continue; } - ilog(LOG_DEBUG, "Creating T.38 encoder for " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); + ilogs(codec, LOG_DEBUG, "Creating T.38 encoder for " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); __make_transcoder(handler, &pcm_media->t38_gateway->pcm_pt, NULL, -1, 0); @@ -1081,7 +1081,7 @@ static int codec_handler_udptl_update(struct call_media *receiver, struct call_m return 1; } } - ilog(LOG_WARN, "Unsupported non-RTP protocol: " STR_FORMAT "/" STR_FORMAT + ilogs(codec, LOG_WARN, "Unsupported non-RTP protocol: " STR_FORMAT "/" STR_FORMAT " -> " STR_FORMAT "/" STR_FORMAT, STR_FMT(&receiver->type), STR_FMT(&receiver->format_str), STR_FMT(&sink->type), STR_FMT(&sink->format_str)); @@ -1097,7 +1097,7 @@ static int codec_handler_non_rtp_update(struct call_media *receiver, struct call __check_t38_gateway(receiver, sink, sp, flags); return 1; } - ilog(LOG_WARN, "Unsupported non-RTP protocol: " STR_FORMAT "/" STR_FORMAT + ilogs(codec, LOG_WARN, "Unsupported non-RTP protocol: " STR_FORMAT "/" STR_FORMAT " -> " STR_FORMAT "/" STR_FORMAT, STR_FMT(&receiver->type), STR_FMT(&receiver->format_str), STR_FMT(&sink->type), STR_FMT(&sink->format_str)); @@ -1295,7 +1295,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, // stop transcoding if we've determined that we don't need it if (MEDIA_ISSET(sink, TRANSCODE) && !sink_transcoding && !(receiver_transcoding & 0x2)) { - ilog(LOG_DEBUG, "Disabling transcoding engine (not needed)"); + ilogs(codec, LOG_DEBUG, "Disabling transcoding engine (not needed)"); MEDIA_CLEAR(sink, TRANSCODE); } @@ -1332,7 +1332,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, struct rtp_payload_type *recv_pt = g_hash_table_lookup(receiver->codecs_send, &pt->payload_type); if (!recv_pt && !pt->for_transcoding) { - ilog(LOG_DEBUG, "Eliminating transcoded codec " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Eliminating transcoded codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); codec_touched(pt, receiver); @@ -1355,7 +1355,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, // to do. most likely this is an initial offer without a received answer. // we default to forwarding without transcoding. if (!pref_dest_codec) { - ilog(LOG_DEBUG, "No known/supported sink codec for " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "No known/supported sink codec for " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); __make_passthrough_gsl(handler, &passthrough_handlers); goto next; @@ -1412,7 +1412,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, if (dest_pt->ptime && pt->ptime && dest_pt->ptime != pt->ptime) { - ilog(LOG_DEBUG, "Mismatched ptime between source and sink (%i <> %i), " + ilogs(codec, LOG_DEBUG, "Mismatched ptime between source and sink (%i <> %i), " "enabling transcoding", dest_pt->ptime, pt->ptime); goto transcode; @@ -1434,7 +1434,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, goto transcode; // XXX check format parameters as well - ilog(LOG_DEBUG, "Sink supports codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); + ilogs(codec, LOG_DEBUG, "Sink supports codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); __make_passthrough_gsl(handler, &passthrough_handlers); if (pt->codec_def && pt->codec_def->dtmf) __dtmf_dsp_shutdown(sink, pt->payload_type); @@ -1443,7 +1443,7 @@ void codec_handlers_update(struct call_media *receiver, struct call_media *sink, unsupported: // the sink does not support this codec -> transcode - ilog(LOG_DEBUG, "Sink does not support codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); + ilogs(codec, LOG_DEBUG, "Sink does not support codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); dest_pt = pref_dest_codec; if (pt->codec_def->supplemental) transcode_supplemental = 1; @@ -1471,7 +1471,7 @@ next: // the list, as we must expect to potentially receive media in that codec, which we // then could not transcode. if (MEDIA_ISSET(receiver, TRANSCODE)) { - ilog(LOG_INFO, "Enabling transcoding engine"); + ilogs(codec, LOG_INFO, "Enabling transcoding engine"); for (GList *l = receiver->codecs_prefs_recv.head; l; ) { struct rtp_payload_type *pt = l->data; @@ -1482,7 +1482,7 @@ next: continue; } - ilog(LOG_DEBUG, "Stripping unsupported codec " STR_FORMAT " due to active transcoding", + ilogs(codec, LOG_DEBUG, "Stripping unsupported codec " STR_FORMAT " due to active transcoding", STR_FMT(&pt->encoding)); codec_touched(pt, receiver); l = __delete_receiver_codec(receiver, l); @@ -1700,7 +1700,7 @@ static int __handler_func_sequencer(struct media_packet *mp, struct transcode_pa if (packet->dup_func) packet->dup_func(ch, packet, mp); else - ilog(LOG_DEBUG, "Ignoring duplicate RTP packet"); + ilogs(transcoding, LOG_DEBUG, "Ignoring duplicate RTP packet"); __transcode_packet_free(packet); atomic64_inc(&ssrc_in->duplicates); goto out; @@ -1724,7 +1724,7 @@ static int __handler_func_sequencer(struct media_packet *mp, struct transcode_pa packet = packet_sequencer_force_next_packet(&ssrc_in_p->sequencer); if (!packet) break; - ilog(LOG_DEBUG, "Timestamp difference too large (%llu ms) after lost packet, " + ilogs(transcoding, LOG_DEBUG, "Timestamp difference too large (%llu ms) after lost packet, " "forcing next packet", ts_diff_us / 1000); } else @@ -1740,7 +1740,7 @@ static int __handler_func_sequencer(struct media_packet *mp, struct transcode_pa atomic64_set(&ssrc_in->packets_lost, ssrc_in_p->sequencer.lost_count); atomic64_set(&ssrc_in->last_seq, ssrc_in_p->sequencer.ext_seq); - ilog(LOG_DEBUG, "Processing RTP packet: seq %u, TS %lu", + ilogs(transcoding, LOG_DEBUG, "Processing RTP packet: seq %u, TS %lu", packet->p.seq, packet->ts); if (seq_ret == 1) { @@ -1754,7 +1754,7 @@ static int __handler_func_sequencer(struct media_packet *mp, struct transcode_pa func_ret = packet->func(ch, packet, mp); if (func_ret < 0) - ilog(LOG_WARN | LOG_FLAG_LIMIT, "Decoder error while processing RTP packet"); + ilogs(transcoding, LOG_WARN | LOG_FLAG_LIMIT, "Decoder error while processing RTP packet"); next: if (func_ret != 1) __transcode_packet_free(packet); @@ -1829,7 +1829,7 @@ static void __output_rtp(struct media_packet *mp, struct codec_ssrc_handler *ch, ch->output_skew = ch->output_skew * 15 / 16 + ts_diff_us / 16; if (ch->output_skew > 40000 && ts_diff_us > 10000) { // arbitrary value, 40 ms, 10 ms shift - ilog(LOG_DEBUG, "Steady clock skew of %lu.%01lu ms detected, shifting send timer back by 10 ms", + ilogs(transcoding, LOG_DEBUG, "Steady clock skew of %lu.%01lu ms detected, shifting send timer back by 10 ms", ch->output_skew / 1000, (ch->output_skew % 1000) / 100); timeval_add_usec(&p->ttq_entry.when, -10000); @@ -1837,7 +1837,7 @@ static void __output_rtp(struct media_packet *mp, struct codec_ssrc_handler *ch, ch->first_send_ts += ch->encoder_format.clockrate / 100; } - ilog(LOG_DEBUG, "Scheduling to send RTP packet (seq %u TS %lu) in %llu.%01llu ms (at %lu.%06lu)", + ilogs(transcoding, LOG_DEBUG, "Scheduling to send RTP packet (seq %u TS %lu) in %llu.%01llu ms (at %lu.%06lu)", ntohs(rh->seq_num), ts, ts_diff_us / 1000, @@ -1857,11 +1857,11 @@ static struct codec_ssrc_handler *__output_ssrc_handler(struct codec_ssrc_handle } // our encoder is in a different codec handler - ilog(LOG_DEBUG, "Switching context from decoder to encoder"); + ilogs(transcoding, LOG_DEBUG, "Switching context from decoder to encoder"); handler = handler->output_handler; struct codec_ssrc_handler *new_ch = get_ssrc(mp->ssrc_in->parent->h.ssrc, handler->ssrc_hash); if (G_UNLIKELY(!new_ch)) { - ilog(LOG_ERR, "Switched from input to output codec context, but no codec handler present"); + ilogs(transcoding, LOG_ERR, "Switched from input to output codec context, but no codec handler present"); obj_get(&ch->h); return ch; } @@ -1901,7 +1901,7 @@ static void packet_dtmf_fwd(struct codec_ssrc_handler *ch, struct transcode_pack // adjust to output RTP TS unsigned long packet_ts = ts + output_ch->first_ts; - ilog(LOG_DEBUG, "Scaling DTMF packet timestamp and duration: TS %lu -> %lu " + ilogs(transcoding, LOG_DEBUG, "Scaling DTMF packet timestamp and duration: TS %lu -> %lu " "(%u -> %u)", packet->ts, packet_ts, ch->handler->source_pt.clock_rate, ch->handler->dest_pt.clock_rate); @@ -1966,7 +1966,7 @@ static int __handler_func_supplemental(struct codec_handler *h, struct media_pac // create new packet and insert it into sequencer queue - ilog(LOG_DEBUG, "Received %s RTP packet: SSRC %" PRIx32 ", PT %u, seq %u, TS %u, len %i", + ilogs(transcoding, LOG_DEBUG, "Received %s RTP packet: SSRC %" PRIx32 ", PT %u, seq %u, TS %u, len %i", h->source_pt.codec_def->rtpname, ntohl(mp->rtp->ssrc), mp->rtp->m_pt, ntohs(mp->rtp->seq_num), ntohl(mp->rtp->timestamp), mp->payload.len); @@ -1986,7 +1986,7 @@ static int __handler_func_supplemental(struct codec_handler *h, struct media_pac continue; if (sequencer_h->source_pt.codec_def && sequencer_h->source_pt.codec_def->supplemental) continue; - ilog(LOG_DEBUG, "Primary RTP payload type for handling %s is %i", + ilogs(transcoding, LOG_DEBUG, "Primary RTP payload type for handling %s is %i", h->source_pt.codec_def->rtpname, prim_pt); break; @@ -2177,7 +2177,7 @@ static void __dtmf_dsp_callback(void *ptr, int code, int level, int delay) { void codec_add_dtmf_event(struct codec_ssrc_handler *ch, int code, int level, uint64_t ts) { struct dtmf_event *ev = g_slice_alloc(sizeof(*ev)); *ev = (struct dtmf_event) { .code = code, .volume = level, .ts = ts }; - ilog(LOG_DEBUG, "DTMF event state change: code %i, volume %i, TS %lu", + ilogs(transcoding, LOG_DEBUG, "DTMF event state change: code %i, volume %i, TS %lu", ev->code, ev->volume, (unsigned long) ts); g_queue_push_tail(&ch->dtmf_events, ev); } @@ -2194,13 +2194,13 @@ uint64_t codec_encoder_pts(struct codec_ssrc_handler *ch) { } void codec_decoder_skip_pts(struct codec_ssrc_handler *ch, uint64_t pts) { - ilog(LOG_DEBUG, "Skipping next %" PRIu64 " samples", pts); + ilogs(transcoding, LOG_DEBUG, "Skipping next %" PRIu64 " samples", pts); ch->skip_pts += pts; } uint64_t codec_decoder_unskip_pts(struct codec_ssrc_handler *ch) { uint64_t prev = ch->skip_pts; - ilog(LOG_DEBUG, "Un-skipping next %" PRIu64 " samples", prev); + ilogs(transcoding, LOG_DEBUG, "Un-skipping next %" PRIu64 " samples", prev); ch->skip_pts = 0; return prev; } @@ -2268,13 +2268,13 @@ static void __dtx_send_later(struct timerthread_queue *ttq, void *p) { __ssrc_lock_both(mp); if (packet) { - ilog(LOG_DEBUG, "Decoding DTX-buffered RTP packet (TS %lu) now", packet->ts); + ilogs(transcoding, LOG_DEBUG, "Decoding DTX-buffered RTP packet (TS %lu) now", packet->ts); ret = decoder_input_data(ch->decoder, packet->payload, packet->ts, ch->handler->packet_decoded, ch, &dtxe->mp); mp->ssrc_out->parent->seq_diff--; if (ret) - ilog(LOG_WARN | LOG_FLAG_LIMIT, "Decoder error while processing buffered RTP packet"); + ilogs(transcoding, LOG_WARN | LOG_FLAG_LIMIT, "Decoder error while processing buffered RTP packet"); } else { unsigned long dtxe_ts = dtxe->ts; @@ -2288,7 +2288,7 @@ static void __dtx_send_later(struct timerthread_queue *ttq, void *p) { && ssrc_ptr == dtxe->ssrc_ptr && (rtpe_config.max_dtx <= 0 || diff < rtpe_config.max_dtx)) { - ilog(LOG_DEBUG, "RTP media for TS %lu+ missing, triggering DTX", + ilogs(transcoding, LOG_DEBUG, "RTP media for TS %lu+ missing, triggering DTX", dtxe_ts); dtxb_ts += dtxb->tspp; @@ -2299,7 +2299,7 @@ static void __dtx_send_later(struct timerthread_queue *ttq, void *p) { ret = decoder_lost_packet(ch->decoder, dtxe_ts, ch->handler->packet_decoded, ch, &dtxe->mp); if (ret) - ilog(LOG_WARN | LOG_FLAG_LIMIT, "Decoder error handling DTX/lost packet"); + ilogs(transcoding, LOG_WARN | LOG_FLAG_LIMIT, "Decoder error handling DTX/lost packet"); __dtx_add_callback(dtxb, &dtxe->ttq_entry.when, dtxb->ptime * 1000, mp, dtxe_ts, 0, ssrc_ptr); } @@ -2316,11 +2316,11 @@ static void __dtx_send_later(struct timerthread_queue *ttq, void *p) { media_socket_dequeue(mp, NULL); // just free else { if (ps->handler && media_packet_encrypt(ps->handler->out->rtp_crypt, sink, mp)) - ilog(LOG_ERR | LOG_FLAG_LIMIT, "Error encrypting buffered RTP media"); + ilogs(transcoding, LOG_ERR | LOG_FLAG_LIMIT, "Error encrypting buffered RTP media"); mutex_lock(&sink->out_lock); if (media_socket_dequeue(mp, sink)) - ilog(LOG_ERR | LOG_FLAG_LIMIT, "Error sending buffered media to RTP sink"); + ilogs(transcoding, LOG_ERR | LOG_FLAG_LIMIT, "Error sending buffered media to RTP sink"); mutex_unlock(&sink->out_lock); } } @@ -2343,7 +2343,6 @@ static void __dtx_shutdown(struct dtx_buffer *dtxb) { } static void __dtx_free(void *p) { struct dtx_buffer *dtxb = p; - ilog(LOG_DEBUG, "__dtx_free"); __dtx_shutdown(dtxb); mutex_destroy(&dtxb->lock); } @@ -2445,7 +2444,7 @@ static void __silence_detect(struct codec_ssrc_handler *ch, AVFrame *frame) { __silence_detect_int16_t(ch, frame, rtpe_config.silence_detect_int >> 16); break; default: - ilog(LOG_WARN | LOG_FLAG_LIMIT, "Unsupported sample format %i for silence detection", + ilogs(transcoding, LOG_WARN | LOG_FLAG_LIMIT, "Unsupported sample format %i for silence detection", frame->format); } } @@ -2486,13 +2485,13 @@ static struct ssrc_entry *__ssrc_handler_transcode_new(void *p) { struct codec_handler *h = p; if (h->dtmf_scaler) - ilog(LOG_DEBUG, "Creating SSRC DTMF transcoder from %s/%u/%i to " + ilogs(codec, LOG_DEBUG, "Creating SSRC DTMF transcoder from %s/%u/%i to " "PT %i", h->source_pt.codec_def->rtpname, h->source_pt.clock_rate, h->source_pt.channels, h->dtmf_payload_type); else - ilog(LOG_DEBUG, "Creating SSRC transcoder from %s/%u/%i to " + ilogs(codec, LOG_DEBUG, "Creating SSRC transcoder from %s/%u/%i to " "%s/%u/%i", h->source_pt.codec_def->rtpname, h->source_pt.clock_rate, h->source_pt.channels, @@ -2521,11 +2520,11 @@ static struct ssrc_entry *__ssrc_handler_transcode_new(void *p) { goto err; if (h->pcm_dtmf_detect) { - ilog(LOG_DEBUG, "Inserting DTMF DSP for output payload type %i", h->dtmf_payload_type); + ilogs(codec, LOG_DEBUG, "Inserting DTMF DSP for output payload type %i", h->dtmf_payload_type); ch->dtmf_format = (format_t) { .clockrate = 8000, .channels = 1, .format = AV_SAMPLE_FMT_S16 }; ch->dtmf_dsp = dtmf_rx_init(NULL, NULL, NULL); if (!ch->dtmf_dsp) - ilog(LOG_ERR, "Failed to allocate DTMF RX context"); + ilogs(codec, LOG_ERR, "Failed to allocate DTMF RX context"); else dtmf_rx_set_realtime_callback(ch->dtmf_dsp, __dtmf_dsp_callback, ch); } @@ -2544,7 +2543,7 @@ static struct ssrc_entry *__ssrc_handler_transcode_new(void *p) { __dtx_setup(ch); - ilog(LOG_DEBUG, "Encoder created with clockrate %i, %i channels, using sample format %i " + ilogs(codec, LOG_DEBUG, "Encoder created with clockrate %i, %i channels, using sample format %i " "(ptime %i for %i samples per frame and %i samples (%i bytes) per packet, bitrate %i)", ch->encoder_format.clockrate, ch->encoder_format.channels, ch->encoder_format.format, ch->ptime, ch->encoder->samples_per_frame, ch->encoder->samples_per_packet, @@ -2590,7 +2589,7 @@ static int packet_encoded_rtp(encoder_t *enc, void *u1, void *u2) { struct media_packet *mp = u2; //unsigned int seq_off = (mp->iter_out > mp->iter_in) ? 1 : 0; - ilog(LOG_DEBUG, "RTP media successfully encoded: TS %llu, len %i", + ilogs(transcoding, LOG_DEBUG, "RTP media successfully encoded: TS %llu, len %i", (unsigned long long) enc->avpkt.pts, enc->avpkt.size); // run this through our packetizer @@ -2609,7 +2608,7 @@ static int packet_encoded_rtp(encoder_t *enc, void *u1, void *u2) { str_init_len(&inout, payload, payload_len); // and request a packet if (in_pkt) - ilog(LOG_DEBUG, "Adding %i bytes to packetizer", in_pkt->size); + ilogs(transcoding, LOG_DEBUG, "Adding %i bytes to packetizer", in_pkt->size); int ret = ch->handler->dest_pt.codec_def->packetizer(in_pkt, ch->sample_buffer, &inout, enc); @@ -2619,7 +2618,7 @@ static int packet_encoded_rtp(encoder_t *enc, void *u1, void *u2) { break; } - ilog(LOG_DEBUG, "Received packet of %i bytes from packetizer", inout.len); + ilogs(transcoding, LOG_DEBUG, "Received packet of %i bytes from packetizer", inout.len); // check special payloads @@ -2681,11 +2680,11 @@ static void __dtmf_detect(struct codec_ssrc_handler *ch, AVFrame *frame) { AVFrame *dsp_frame = resample_frame(&ch->dtmf_resampler, frame, &ch->dtmf_format); if (!dsp_frame) { - ilog(LOG_ERR | LOG_FLAG_LIMIT, "Failed to resample audio for DTMF DSP"); + ilogs(transcoding, LOG_ERR | LOG_FLAG_LIMIT, "Failed to resample audio for DTMF DSP"); return; } - ilog(LOG_DEBUG, "DTMF detect, TS %lu -> %lu, %u -> %u samples", + ilogs(transcoding, LOG_DEBUG, "DTMF detect, TS %lu -> %lu, %u -> %u samples", (unsigned long) frame->pts, (unsigned long) dsp_frame->pts, frame->nb_samples, @@ -2694,7 +2693,7 @@ static void __dtmf_detect(struct codec_ssrc_handler *ch, AVFrame *frame) { if (dsp_frame->pts > ch->dtmf_ts) dtmf_rx_fillin(ch->dtmf_dsp, dsp_frame->pts - ch->dtmf_ts); else if (dsp_frame->pts < ch->dtmf_ts) - ilog(LOG_ERR | LOG_FLAG_LIMIT, "DTMF TS seems to run backwards (%lu < %lu)", + ilogs(transcoding, LOG_ERR | LOG_FLAG_LIMIT, "DTMF TS seems to run backwards (%lu < %lu)", (unsigned long) dsp_frame->pts, (unsigned long) ch->dtmf_ts); @@ -2703,7 +2702,7 @@ static void __dtmf_detect(struct codec_ssrc_handler *ch, AVFrame *frame) { while (num_samples > 0) { int ret = dtmf_rx(ch->dtmf_dsp, samples, num_samples); if (ret < 0 || ret >= num_samples) { - ilog(LOG_ERR | LOG_FLAG_LIMIT, "DTMF DSP returned error %i", ret); + ilogs(transcoding, LOG_ERR | LOG_FLAG_LIMIT, "DTMF DSP returned error %i", ret); break; } samples += num_samples - ret; @@ -2720,7 +2719,7 @@ static int packet_decoded_common(decoder_t *decoder, AVFrame *frame, void *u1, v struct codec_ssrc_handler *ch = u1; struct media_packet *mp = u2; - ilog(LOG_DEBUG, "RTP media successfully decoded: TS %llu, samples %u", + ilogs(transcoding, LOG_DEBUG, "RTP media successfully decoded: TS %llu, samples %u", (unsigned long long) frame->pts, frame->nb_samples); // switch from input codec context to output context if necessary @@ -2747,12 +2746,12 @@ static int packet_decoded_common(decoder_t *decoder, AVFrame *frame, void *u1, v ch->skip_pts -= frame->nb_samples; else ch->skip_pts = 0; - ilog(LOG_DEBUG, "Discarding %i samples", frame->nb_samples); + ilogs(transcoding, LOG_DEBUG, "Discarding %i samples", frame->nb_samples); goto discard; } if (G_UNLIKELY(!ch->encoder)) { - ilog(LOG_INFO | LOG_FLAG_LIMIT, + ilogs(transcoding, LOG_INFO | LOG_FLAG_LIMIT, "Discarding decoded %i PCM samples due to lack of output encoder", frame->nb_samples); goto discard; @@ -2790,7 +2789,7 @@ static int packet_decode(struct codec_ssrc_handler *ch, struct transcode_packet ch->last_ts = packet->ts; if (ch->dtx_buffer && mp->sfd && mp->ssrc_in && mp->ssrc_out) { - ilog(LOG_DEBUG, "Adding packet to DTX buffer"); + ilogs(transcoding, LOG_DEBUG, "Adding packet to DTX buffer"); struct dtx_buffer *dtxb = ch->dtx_buffer; unsigned long ts = packet->ts; @@ -2816,7 +2815,7 @@ static int packet_decode(struct codec_ssrc_handler *ch, struct transcode_packet ret = 1; } else { - ilog(LOG_DEBUG, "Decoding RTP packet now"); + ilogs(transcoding, LOG_DEBUG, "Decoding RTP packet now"); ret = decoder_input_data(ch->decoder, packet->payload, packet->ts, ch->handler->packet_decoded, ch, mp); ret = ret ? -1 : 0; @@ -2855,7 +2854,7 @@ static int handler_func_transcode(struct codec_handler *h, struct media_packet * // create new packet and insert it into sequencer queue - ilog(LOG_DEBUG, "Received RTP packet: SSRC %" PRIx32 ", PT %u, seq %u, TS %u, len %i", + ilogs(transcoding, LOG_DEBUG, "Received RTP packet: SSRC %" PRIx32 ", PT %u, seq %u, TS %u, len %i", ntohl(mp->rtp->ssrc), mp->rtp->m_pt, ntohs(mp->rtp->seq_num), ntohl(mp->rtp->timestamp), mp->payload.len); @@ -2949,7 +2948,7 @@ static struct rtp_payload_type *codec_add_payload_type(const str *codec, struct { struct rtp_payload_type *pt = codec_make_payload_type_sup(codec, media); if (!pt) { - ilog(LOG_WARN, "Codec '" STR_FORMAT "' requested for transcoding is not supported", + ilogs(codec, LOG_WARN, "Codec '" STR_FORMAT "' requested for transcoding is not supported", STR_FMT(codec)); return NULL; } @@ -2958,7 +2957,7 @@ static struct rtp_payload_type *codec_add_payload_type(const str *codec, struct pt->payload_type = __unused_pt_number(media, other_media, pt); if (pt->payload_type < 0) { - ilog(LOG_WARN, "Ran out of RTP payload type numbers while adding codec '" + ilogs(codec, LOG_WARN, "Ran out of RTP payload type numbers while adding codec '" STR_FORMAT "' for transcoding", STR_FMT(&pt->encoding_with_params)); payload_type_free(pt); @@ -3112,7 +3111,7 @@ static int __revert_codec_strip(GHashTable *stripped, GHashTable *masked, const GQueue *q = g_hash_table_lookup(stripped, codec); if (q) { - ilog(LOG_DEBUG, "Restoring codec '" STR_FORMAT "' from stripped codecs (%u payload types)", + ilogs(codec, LOG_DEBUG, "Restoring codec '" STR_FORMAT "' from stripped codecs (%u payload types)", STR_FMT(codec), q->length); while (q->length) { struct rtp_payload_type *pt = g_queue_pop_head(q); @@ -3124,7 +3123,7 @@ static int __revert_codec_strip(GHashTable *stripped, GHashTable *masked, const q = g_hash_table_lookup(masked, codec); if (q) { - ilog(LOG_DEBUG, "Restoring codec '" STR_FORMAT "' from masked codecs (%u payload types)", + ilogs(codec, LOG_DEBUG, "Restoring codec '" STR_FORMAT "' from masked codecs (%u payload types)", STR_FMT(codec), q->length); while (q->length) { struct rtp_payload_type *pt = g_queue_pop_head(q); @@ -3242,7 +3241,7 @@ void codec_tracker_finish(struct call_media *media) { if (!sct->all_touched && !g_hash_table_lookup(sct->touched, GUINT_TO_POINTER(clockrate))) continue; - ilog(LOG_DEBUG, "Adding supplemental codec " STR_FORMAT " for clock rate %u", STR_FMT(supp_codec), clockrate); + ilogs(codec, LOG_DEBUG, "Adding supplemental codec " STR_FORMAT " for clock rate %u", STR_FMT(supp_codec), clockrate); char *pt_s = g_strdup_printf(STR_FORMAT "/%u", STR_FMT(supp_codec), clockrate); str pt_str; @@ -3272,7 +3271,7 @@ void codec_tracker_finish(struct call_media *media) { GList *link = j->data; struct rtp_payload_type *pt = link->data; - ilog(LOG_DEBUG, "Eliminating supplemental codec " STR_FORMAT " with stray clock rate %u", + ilogs(codec, LOG_DEBUG, "Eliminating supplemental codec " STR_FORMAT " with stray clock rate %u", STR_FMT(&pt->encoding), clockrate); __delete_receiver_codec(media, link); @@ -3376,7 +3375,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ // codec stripping if (__codec_ht_except(strip_all, flags->codec_strip, flags->codec_except, pt)) { - ilog(LOG_DEBUG, "Stripping codec '" STR_FORMAT "'", + ilogs(codec, LOG_DEBUG, "Stripping codec '" STR_FORMAT "'", STR_FMT(&pt->encoding_with_params)); #ifdef WITH_TRANSCODING codec_touched(pt, media); @@ -3392,7 +3391,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ // codec masking if (__codec_ht_except(mask_all, flags->codec_mask, flags->codec_except, pt)) { - ilog(LOG_DEBUG, "Masking codec '" STR_FORMAT "'", + ilogs(codec, LOG_DEBUG, "Masking codec '" STR_FORMAT "'", STR_FMT(&pt->encoding_with_params)); #ifdef WITH_TRANSCODING codec_touched(pt, media); @@ -3409,7 +3408,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ __rtp_payload_type_add_send(other_media, pt); } else if (__codec_ht_except(consume_all, flags->codec_consume, flags->codec_except, pt)) { - ilog(LOG_DEBUG, "Consuming codec '" STR_FORMAT "'", + ilogs(codec, LOG_DEBUG, "Consuming codec '" STR_FORMAT "'", STR_FMT(&pt->encoding_with_params)); #ifdef WITH_TRANSCODING codec_touched(pt, media); @@ -3422,7 +3421,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ __rtp_payload_type_add_send(other_media, pt); } else if (__codec_ht_except(accept_all, flags->codec_accept, NULL, pt)) { - ilog(LOG_DEBUG, "Accepting codec '" STR_FORMAT "'", + ilogs(codec, LOG_DEBUG, "Accepting codec '" STR_FORMAT "'", STR_FMT(&pt->encoding_with_params)); #ifdef WITH_TRANSCODING codec_touched(pt, media); @@ -3449,7 +3448,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ l = l->next; continue; } - ilog(LOG_DEBUG, "Eliminating asymmetric inbound codec " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Eliminating asymmetric inbound codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); l = __delete_receiver_codec(other_media, l); } @@ -3472,7 +3471,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ continue; // also check if maybe the codec was never stripped if (g_hash_table_lookup(media->codec_names_recv, codec)) { - ilog(LOG_DEBUG, "Codec '" STR_FORMAT "' requested for transcoding is already present", + ilogs(codec, LOG_DEBUG, "Codec '" STR_FORMAT "' requested for transcoding is already present", STR_FMT(codec)); continue; } @@ -3484,7 +3483,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ pt->for_transcoding = 1; codec_touched(pt, media); - ilog(LOG_DEBUG, "Codec '" STR_FORMAT "' added for transcoding with payload type %u", + ilogs(codec, LOG_DEBUG, "Codec '" STR_FORMAT "' added for transcoding with payload type %u", STR_FMT(&pt->encoding_with_params), pt->payload_type); __rtp_payload_type_add_recv(media, pt, 1); } @@ -3517,7 +3516,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ assert(pt != NULL); __rtp_payload_type_add_recv(media, pt, 1); - ilog(LOG_DEBUG, "Using default codecs PCMU and PCMA for T.38 gateway"); + ilogs(codec, LOG_DEBUG, "Using default codecs PCMU and PCMA for T.38 gateway"); } } else if (flags->opmode == OP_OFFER) { @@ -3532,7 +3531,7 @@ void codec_rtp_payload_types(struct call_media *media, struct call_media *other_ l = l->next; continue; } - ilog(LOG_DEBUG, "Eliminating unsupported codec " STR_FORMAT, + ilogs(codec, LOG_DEBUG, "Eliminating unsupported codec " STR_FORMAT, STR_FMT(&pt->encoding_with_params)); codec_touched(pt, media); l = __delete_receiver_codec(media, l); diff --git a/daemon/control_ng.c b/daemon/control_ng.c index 090992a47..99e62d4b9 100644 --- a/daemon/control_ng.c +++ b/daemon/control_ng.c @@ -121,7 +121,7 @@ struct control_ng_stats* get_control_ng_stats(const sockaddr_t *addr) { if (!cur) { cur = g_slice_alloc0(sizeof(struct control_ng_stats)); cur->proxy = *addr; - ilog(LOG_DEBUG,"Adding a proxy for control ng stats:%s", sockaddr_print_buf(addr)); + ilogs(control, LOG_DEBUG,"Adding a proxy for control ng stats:%s", sockaddr_print_buf(addr)); for (int i = 0; i < NGC_COUNT; i++) { struct ng_command_stats *c = &cur->cmd[i]; @@ -149,7 +149,7 @@ int control_ng_process(str *buf, const endpoint_t *sin, char *addr, str_chr_str(&data, buf, ' '); if (!data.s || data.s == buf->s) { - ilog(LOG_WARNING, "Received invalid data on NG port (no cookie) from %s: " STR_FORMAT_M, + ilogs(control, LOG_WARNING, "Received invalid data on NG port (no cookie) from %s: " STR_FORMAT_M, addr, STR_FMT_M(buf)); return funcret; } @@ -171,7 +171,7 @@ int control_ng_process(str *buf, const endpoint_t *sin, char *addr, to_send = cookie_cache_lookup(&ng_cookie_cache, &cookie); if (to_send) { - ilog(LOG_INFO, "Detected command from %s as a duplicate", addr); + ilogs(control, LOG_INFO, "Detected command from %s as a duplicate", addr); resp = NULL; goto send_only; } @@ -189,15 +189,15 @@ int control_ng_process(str *buf, const endpoint_t *sin, char *addr, bencode_dictionary_get_str(dict, "call-id", &callid); log_info_str(&callid); - ilog(LOG_INFO, "Received command '"STR_FORMAT"' from %s", STR_FMT(&cmd), addr); + ilogs(control, LOG_INFO, "Received command '"STR_FORMAT"' from %s", STR_FMT(&cmd), addr); - if (get_log_level() >= LOG_DEBUG) { + if (get_log_level(control) >= LOG_DEBUG) { log_str = g_string_sized_new(256); g_string_append_printf(log_str, "Dump for '"STR_FORMAT"' from %s: %s", STR_FMT(&cmd), addr, rtpe_config.common.log_mark_prefix); pretty_print(dict, log_str); g_string_append(log_str, rtpe_config.common.log_mark_suffix); - ilog(LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str); + ilogs(control, LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str); g_string_free(log_str, TRUE); } @@ -325,7 +325,7 @@ int control_ng_process(str *buf, const endpoint_t *sin, char *addr, err_send: if (errstr < magic_load_limit_strings[0] || errstr > magic_load_limit_strings[__LOAD_LIMIT_MAX-1]) { - ilog(LOG_WARNING, "Protocol error in packet from %s: %s [" STR_FORMAT_M "]", + ilogs(control, LOG_WARNING, "Protocol error in packet from %s: %s [" STR_FORMAT_M "]", addr, errstr, STR_FMT_M(&data)); bencode_dictionary_add_string(resp, "result", "error"); bencode_dictionary_add_string(resp, "error-reason", errstr); @@ -342,9 +342,9 @@ send_resp: to_send = &reply; if (cmd.s) { - ilog(LOG_INFO, "Replying to '"STR_FORMAT"' from %s (elapsed time %llu.%06llu sec)", STR_FMT(&cmd), addr, (unsigned long long)cmd_process_time.tv_sec, (unsigned long long)cmd_process_time.tv_usec); + ilogs(control, LOG_INFO, "Replying to '"STR_FORMAT"' from %s (elapsed time %llu.%06llu sec)", STR_FMT(&cmd), addr, (unsigned long long)cmd_process_time.tv_sec, (unsigned long long)cmd_process_time.tv_usec); - if (get_log_level() >= LOG_DEBUG) { + if (get_log_level(control) >= LOG_DEBUG) { dict = bencode_decode_expect_str(&bencbuf, to_send, BENCODE_DICTIONARY); if (dict) { log_str = g_string_sized_new(256); @@ -353,7 +353,7 @@ send_resp: rtpe_config.common.log_mark_prefix); pretty_print(dict, log_str); g_string_append(log_str, rtpe_config.common.log_mark_suffix); - ilog(LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str); + ilogs(control, LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str); g_string_free(log_str, TRUE); } } diff --git a/daemon/control_tcp.c b/daemon/control_tcp.c index 24a38e4f2..2563eb649 100644 --- a/daemon/control_tcp.c +++ b/daemon/control_tcp.c @@ -39,7 +39,7 @@ struct control_tcp { //static void control_stream_closed(int fd, void *p, uintptr_t u) { static void control_stream_closed(struct streambuf_stream *s) { - ilog(LOG_INFO, "Control connection from %s closed", s->addr); + ilogs(control, LOG_INFO, "Control connection from %s closed", s->addr); } @@ -74,11 +74,11 @@ static int control_stream_parse(struct streambuf_stream *s, char *line) { ret = pcre_exec(c->parse_re, c->parse_ree, line, strlen(line), 0, 0, ovec, G_N_ELEMENTS(ovec)); if (ret <= 0) { - ilog(LOG_WARNING, "Unable to parse command line from %s: %s", s->addr, line); + ilogs(control, LOG_WARNING, "Unable to parse command line from %s: %s", s->addr, line); return -1; } - ilog(LOG_INFO, "Got valid command from %s: %s", s->addr, line); + ilogs(control, LOG_INFO, "Got valid command from %s: %s", s->addr, line); pcre_get_substring_list(line, ovec, ret, (const char ***) &out); @@ -127,7 +127,7 @@ static void control_stream_readable(struct streambuf_stream *s) { int ret; while ((line = streambuf_getline(s->inbuf))) { - ilog(LOG_DEBUG, "Got control line from %s: %s", s->addr, line); + ilogs(control, LOG_DEBUG, "Got control line from %s: %s", s->addr, line); ret = control_stream_parse(s, line); free(line); if (ret == 1) { @@ -139,7 +139,7 @@ static void control_stream_readable(struct streambuf_stream *s) { } if (streambuf_bufsize(s->inbuf) > 1024) { - ilog(LOG_WARNING, "Buffer length exceeded in control connection from %s", s->addr); + ilogs(control, LOG_WARNING, "Buffer length exceeded in control connection from %s", s->addr); goto close; } @@ -150,7 +150,7 @@ close: } static void control_incoming(struct streambuf_stream *s) { - ilog(LOG_INFO, "New TCP control connection from %s", s->addr); + ilogs(control, LOG_INFO, "New TCP control connection from %s", s->addr); } @@ -178,7 +178,7 @@ struct control_tcp *control_tcp_new(struct poller *p, endpoint_t *ep) { control_stream_timer, &c->obj)) { - ilog(LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); + ilogs(control, LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); goto fail; } if (ipv46_any_convert(ep)) { @@ -188,7 +188,7 @@ struct control_tcp *control_tcp_new(struct poller *p, endpoint_t *ep) { control_stream_timer, &c->obj)) { - ilog(LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); + ilogs(control, LOG_ERR, "Failed to open TCP control port: %s", strerror(errno)); goto fail; } } diff --git a/daemon/control_udp.c b/daemon/control_udp.c index 620034c1a..cfc1f038a 100644 --- a/daemon/control_udp.c +++ b/daemon/control_udp.c @@ -35,11 +35,11 @@ static void control_udp_incoming(struct obj *obj, str *buf, const endpoint_t *si if (ret <= 0) { ret = pcre_exec(u->fallback_re, NULL, buf->s, buf->len, 0, 0, ovec, G_N_ELEMENTS(ovec)); if (ret <= 0) { - ilog(LOG_WARNING, "Unable to parse command line from udp:%s: %.*s", addr, STR_FMT(buf)); + ilogs(control, LOG_WARNING, "Unable to parse command line from udp:%s: %.*s", addr, STR_FMT(buf)); return; } - ilog(LOG_WARNING, "Failed to properly parse UDP command line '%.*s' from %s, using fallback RE", STR_FMT(buf), addr); + ilogs(control, LOG_WARNING, "Failed to properly parse UDP command line '%.*s' from %s, using fallback RE", STR_FMT(buf), addr); pcre_get_substring_list(buf->s, ovec, ret, (const char ***) &out); @@ -67,14 +67,14 @@ static void control_udp_incoming(struct obj *obj, str *buf, const endpoint_t *si return; } - ilog(LOG_INFO, "Got valid command from udp:%s: %.*s", addr, STR_FMT(buf)); + ilogs(control, LOG_INFO, "Got valid command from udp:%s: %.*s", addr, STR_FMT(buf)); pcre_get_substring_list(buf->s, ovec, ret, (const char ***) &out); str_init(&cookie, (void *) out[RE_UDP_COOKIE]); reply = cookie_cache_lookup(&u->cookie_cache, &cookie); if (reply) { - ilog(LOG_INFO, "Detected command from udp:%s as a duplicate", addr); + ilogs(control, LOG_INFO, "Detected command from udp:%s as a duplicate", addr); socket_sendto(ul, reply->s, reply->len, sin); free(reply); goto out; diff --git a/daemon/crypto.c b/daemon/crypto.c index e4b699b37..d878c3fe2 100644 --- a/daemon/crypto.c +++ b/daemon/crypto.c @@ -424,26 +424,25 @@ int crypto_gen_session_key(struct crypto_context *c, str *out, unsigned char lab prf_n(out, c->params.master_key, c->params.crypto_suite->lib_cipher_ptr, x); - if (rtpe_config.debug_srtp) - ilog(LOG_DEBUG, "Generated session key: master key " - "%02x%02x%02x%02x..., " - "master salt " - "%02x%02x%02x%02x..., " - "label %02x, length %i, result " - "%02x%02x%02x%02x...", - c->params.master_key[0], - c->params.master_key[1], - c->params.master_key[2], - c->params.master_key[3], - c->params.master_salt[0], - c->params.master_salt[1], - c->params.master_salt[2], - c->params.master_salt[3], - label, out->len, - (unsigned char) out->s[0], - (unsigned char) out->s[1], - (unsigned char) out->s[2], - (unsigned char) out->s[3]); + ilogs(internals, LOG_DEBUG, "Generated session key: master key " + "%02x%02x%02x%02x..., " + "master salt " + "%02x%02x%02x%02x..., " + "label %02x, length %i, result " + "%02x%02x%02x%02x...", + c->params.master_key[0], + c->params.master_key[1], + c->params.master_key[2], + c->params.master_key[3], + c->params.master_salt[0], + c->params.master_salt[1], + c->params.master_salt[2], + c->params.master_salt[3], + label, out->len, + (unsigned char) out->s[0], + (unsigned char) out->s[1], + (unsigned char) out->s[2], + (unsigned char) out->s[3]); return 0; } @@ -708,7 +707,7 @@ static void dump_key(struct crypto_context *c, int log_level) { k = g_base64_encode(c->params.master_key, c->params.crypto_suite->master_key_len); s = g_base64_encode(c->params.master_salt, c->params.crypto_suite->master_salt_len); - ilog(log_level, "--- %s key %s%s%s salt %s%s%s", c->params.crypto_suite->name, FMT_M(k), FMT_M(s)); + ilogs(srtp, log_level, "--- %s key %s%s%s salt %s%s%s", c->params.crypto_suite->name, FMT_M(k), FMT_M(s)); g_free(k); g_free(s); @@ -720,12 +719,12 @@ void crypto_dump_keys(struct crypto_context *in, struct crypto_context *out) { if (rtpe_config.log_keys) log_level = LOG_ERROR; - if (get_log_level() < log_level) + if (get_log_level(core) < log_level) return; - ilog(log_level, "SRTP keys, incoming:"); + ilogs(srtp, log_level, "SRTP keys, incoming:"); dump_key(in, log_level); - ilog(log_level, "SRTP keys, outgoing:"); + ilogs(srtp, log_level, "SRTP keys, outgoing:"); dump_key(out, log_level); } diff --git a/daemon/dtls.c b/daemon/dtls.c index e0beaea2b..7ffe8b8ca 100644 --- a/daemon/dtls.c +++ b/daemon/dtls.c @@ -32,7 +32,7 @@ #if DTLS_DEBUG #define __DBG(x...) ilog(LOG_DEBUG, x) #else -#define __DBG(x...) ((void)0) +#define __DBG(x...) ilogs(internals, LOG_DEBUG, x) #endif @@ -140,7 +140,7 @@ static void buf_dump_free(char *buf, size_t len) { else llen = len; - ilog(LOG_DEBUG, "--- %.*s", llen, p); + ilogs(srtp, LOG_DEBUG, "--- %.*s", llen, p); if (!f) break; @@ -156,7 +156,7 @@ static void dump_cert(struct dtls_cert *cert) { char *buf; size_t len; - if (get_log_level() < LOG_DEBUG) + if (get_log_level(core) < LOG_DEBUG) return; /* cert */ @@ -164,7 +164,7 @@ static void dump_cert(struct dtls_cert *cert) { PEM_write_X509(fp, cert->x509); fclose(fp); - ilog(LOG_DEBUG, "Dump of DTLS certificate:"); + ilogs(srtp, LOG_DEBUG, "Dump of DTLS certificate:"); buf_dump_free(buf, len); /* key */ @@ -172,7 +172,7 @@ static void dump_cert(struct dtls_cert *cert) { PEM_write_PrivateKey(fp, cert->pkey, NULL, NULL, 0, 0, NULL); fclose(fp); - ilog(LOG_DEBUG, "Dump of DTLS private key:"); + ilogs(srtp, LOG_DEBUG, "Dump of DTLS private key:"); buf_dump_free(buf, len); } @@ -185,7 +185,7 @@ static int cert_init(void) { X509_NAME *name; struct dtls_cert *new_cert; - ilog(LOG_INFO, "Generating new DTLS certificate"); + ilogs(crypto, LOG_INFO, "Generating new DTLS certificate"); /* objects */ @@ -292,7 +292,7 @@ static int cert_init(void) { return 0; err: - ilog(LOG_ERROR, "Failed to generate DTLS certificate"); + ilogs(crypto, LOG_ERROR, "Failed to generate DTLS certificate"); if (pkey) EVP_PKEY_free(pkey); @@ -452,7 +452,7 @@ int dtls_verify_cert(struct packet_stream *ps) { dtls_hash(media->fingerprint.hash_func, ps->dtls_cert, fp); if (memcmp(media->fingerprint.digest, fp, media->fingerprint.hash_func->num_bytes)) { - ilog(LOG_WARNING, "DTLS: Peer certificate rejected - fingerprint mismatch"); + ilogs(crypto, LOG_WARNING, "DTLS: Peer certificate rejected - fingerprint mismatch"); __DBG("fingerprint expected: %02x%02x%02x%02x%02x%02x%02x%02x received: %02x%02x%02x%02x%02x%02x%02x%02x", media->fingerprint.digest[0], media->fingerprint.digest[1], media->fingerprint.digest[2], media->fingerprint.digest[3], @@ -464,7 +464,7 @@ int dtls_verify_cert(struct packet_stream *ps) { } PS_SET(ps, FINGERPRINT_VERIFIED); - ilog(LOG_INFO, "DTLS: Peer certificate accepted"); + ilogs(crypto, LOG_INFO, "DTLS: Peer certificate accepted"); return 0; } @@ -487,7 +487,7 @@ static int try_connect(struct dtls_connection *d) { ret = 0; switch (code) { case SSL_ERROR_NONE: - ilog(LOG_DEBUG, "DTLS handshake successful"); + ilogs(crypto, LOG_DEBUG, "DTLS handshake successful"); d->connected = 1; ret = 1; break; @@ -498,7 +498,7 @@ static int try_connect(struct dtls_connection *d) { default: ret = ERR_peek_last_error(); - ilog(LOG_ERROR, "DTLS error: %i (%s)", code, ERR_reason_error_string(ret)); + ilogs(crypto, LOG_ERROR, "DTLS error: %i (%s)", code, ERR_reason_error_string(ret)); ret = -1; break; } @@ -519,7 +519,7 @@ int dtls_connection_init(struct dtls_connection *d, struct packet_stream *ps, in d->ptr = ps; - ilog(LOG_DEBUG, "Creating %s DTLS connection context", active ? "active" : "passive"); + ilogs(crypto, LOG_DEBUG, "Creating %s DTLS connection context", active ? "active" : "passive"); #if OPENSSL_VERSION_NUMBER >= 0x10002000L d->ssl_ctx = SSL_CTX_new(active ? DTLS_client_method() : DTLS_server_method()); @@ -591,7 +591,7 @@ error: if (d->ssl_ctx) SSL_CTX_free(d->ssl_ctx); ZERO(*d); - ilog(LOG_ERROR, "Failed to init DTLS connection: %s", ERR_reason_error_string(err)); + ilogs(crypto, LOG_ERROR, "Failed to init DTLS connection: %s", ERR_reason_error_string(err)); return -1; } @@ -641,7 +641,7 @@ found: i += cs->master_salt_len; memcpy(server.master_salt, &keys[i], cs->master_salt_len); - ilog(LOG_INFO, "DTLS-SRTP successfully negotiated"); + ilogs(crypto, LOG_INFO, "DTLS-SRTP successfully negotiated"); if (d->active) { /* we're the client */ @@ -671,9 +671,9 @@ found: error: if (!spp) - ilog(LOG_ERROR, "Failed to set up SRTP after DTLS negotiation: %s", err); + ilogs(crypto, LOG_ERROR, "Failed to set up SRTP after DTLS negotiation: %s", err); else - ilog(LOG_ERROR, "Failed to set up SRTP after DTLS negotiation: %s (profile \"%s\")", + ilogs(crypto, LOG_ERROR, "Failed to set up SRTP after DTLS negotiation: %s (profile \"%s\")", err, spp->name); return -1; } @@ -704,7 +704,7 @@ int dtls(struct stream_fd *sfd, const str *s, const endpoint_t *fsin) { return -1; if (s) { - ilog(LOG_DEBUG, "Processing incoming DTLS packet"); + ilogs(srtp, LOG_DEBUG, "Processing incoming DTLS packet"); BIO_write(d->r_bio, s->s, s->len); /* we understand this as preference of DTLS over SDES */ MEDIA_CLEAR(ps->media, SDES); @@ -712,7 +712,7 @@ int dtls(struct stream_fd *sfd, const str *s, const endpoint_t *fsin) { ret = try_connect(d); if (ret == -1) { - ilog(LOG_ERROR, "DTLS error on local port %u", sfd->socket.local.port); + ilogs(srtp, LOG_ERROR, "DTLS error on local port %u", sfd->socket.local.port); /* fatal error */ dtls_connection_cleanup(d); return 0; @@ -744,7 +744,7 @@ int dtls(struct stream_fd *sfd, const str *s, const endpoint_t *fsin) { break; if (ret > sizeof(buf)) { - ilog(LOG_ERROR, "BIO buffer overflow"); + ilogs(srtp, LOG_ERROR, "BIO buffer overflow"); (void) BIO_reset(d->w_bio); break; } @@ -763,7 +763,7 @@ int dtls(struct stream_fd *sfd, const str *s, const endpoint_t *fsin) { if (!fsin) fsin = &ps->endpoint; - ilog(LOG_DEBUG, "Sending DTLS packet"); + ilogs(srtp, LOG_DEBUG, "Sending DTLS packet"); socket_sendto(&sfd->socket, buf, ret, fsin); } @@ -813,7 +813,7 @@ void dtls_shutdown(struct packet_stream *ps) { void dtls_connection_cleanup(struct dtls_connection *c) { if (c->ssl_ctx || c->ssl) - ilog(LOG_DEBUG, "Resetting DTLS connection context"); + ilogs(crypto, LOG_DEBUG, "Resetting DTLS connection context"); if (c->ssl_ctx) SSL_CTX_free(c->ssl_ctx); diff --git a/daemon/ice.c b/daemon/ice.c index a9ee10276..9042d2bf4 100644 --- a/daemon/ice.c +++ b/daemon/ice.c @@ -21,9 +21,9 @@ #endif #if ICE_DEBUG -#define __DBG(x...) ilog(LOG_DEBUG, x) +#define __DBG(x...) ilogs(ice, LOG_DEBUG, x) #else -#define __DBG(x...) ((void)0) +#define __DBG(x...) ilogs(internals, LOG_DEBUG, x) #endif @@ -135,7 +135,7 @@ static void __all_pairs_list(struct ice_agent *ag) { static void __tree_coll_callback(void *oo, void *nn) { struct ice_candidate_pair *o = oo, *n = nn; - ilog(LOG_WARN | LOG_FLAG_LIMIT, "Priority collision between candidate pairs " PAIR_FORMAT " and " + ilogs(ice, LOG_WARN | LOG_FLAG_LIMIT, "Priority collision between candidate pairs " PAIR_FORMAT " and " PAIR_FORMAT " - ICE will likely fail", PAIR_FMT(o), PAIR_FMT(n)); } @@ -164,7 +164,7 @@ static struct ice_candidate_pair *__pair_candidate(struct stream_fd *sfd, struct g_hash_table_insert(ag->pair_hash, pair, pair); g_tree_insert_coll(ag->all_pairs, pair, pair, __tree_coll_callback); - ilog(LOG_DEBUG, "Created candidate pair "PAIR_FORMAT" between %s and %s%s%s, type %s", PAIR_FMT(pair), + ilogs(ice, LOG_DEBUG, "Created candidate pair "PAIR_FORMAT" between %s and %s%s%s, type %s", PAIR_FMT(pair), sockaddr_print_buf(&sfd->socket.local.address), FMT_M(endpoint_print_buf(&cand->endpoint)), ice_candidate_type_str(cand->type)); @@ -295,7 +295,7 @@ static void __ice_reset(struct ice_agent *ag) { /* if the other side did a restart */ static void __ice_restart(struct ice_agent *ag) { - ilog(LOG_DEBUG, "ICE restart, resetting ICE agent"); + ilogs(ice, LOG_DEBUG, "ICE restart, resetting ICE agent"); ag->ufrag[0] = STR_NULL; ag->pwd[0] = STR_NULL; @@ -361,7 +361,7 @@ void ice_update(struct ice_agent *ag, struct stream_params *sp) { comps = 0; for (l = candidates->head; l; l = l->next) { if (ag->remote_candidates.length >= MAX_ICE_CANDIDATES) { - ilog(LOG_WARNING, "Maxmimum number of ICE candidates exceeded"); + ilogs(ice, LOG_WARNING, "Maxmimum number of ICE candidates exceeded"); break; } @@ -384,7 +384,7 @@ void ice_update(struct ice_agent *ag, struct stream_params *sp) { /* if this is peer reflexive, we've learned it through STUN. * otherwise it's simply one we've seen before. */ if (dup->type == ICT_PRFLX) { - ilog(LOG_DEBUG, "Replacing previously learned prflx ICE candidate with " + ilogs(ice, LOG_DEBUG, "Replacing previously learned prflx ICE candidate with " STR_FORMAT_M ":%lu", STR_FMT_M(&cand->foundation), cand->component_id); } @@ -392,7 +392,7 @@ void ice_update(struct ice_agent *ag, struct stream_params *sp) { /* if the new one has higher priority then the old one, then we * update it, otherwise we just drop it */ if (cand->priority <= dup->priority) { - ilog(LOG_DEBUG, "Dropping new ICE candidate " STR_FORMAT_M + ilogs(ice, LOG_DEBUG, "Dropping new ICE candidate " STR_FORMAT_M " in favour of " STR_FORMAT_M ":%lu", STR_FMT_M(&cand->foundation), @@ -400,7 +400,7 @@ void ice_update(struct ice_agent *ag, struct stream_params *sp) { continue; } - ilog(LOG_DEBUG, "Replacing known ICE candidate " STR_FORMAT_M " with higher " + ilogs(ice, LOG_DEBUG, "Replacing known ICE candidate " STR_FORMAT_M " with higher " "priority " STR_FORMAT_M ":%lu", STR_FMT_M(&dup->foundation), @@ -412,7 +412,7 @@ void ice_update(struct ice_agent *ag, struct stream_params *sp) { recalc += __copy_cand(call, dup, cand); } else { - ilog(LOG_DEBUG, "Learning new ICE candidate " STR_FORMAT_M ":%lu", + ilogs(ice, LOG_DEBUG, "Learning new ICE candidate " STR_FORMAT_M ":%lu", STR_FMT_M(&cand->foundation), cand->component_id); dup = g_slice_alloc(sizeof(*dup)); __copy_cand(call, dup, cand); @@ -477,7 +477,7 @@ void ice_shutdown(struct ice_agent **agp) { struct ice_agent *ag; if (!agp) { - ilog(LOG_ERR, "ice agp is NULL"); + ilogs(ice, LOG_ERR, "ice agp is NULL"); return ; } @@ -492,7 +492,7 @@ void ice_shutdown(struct ice_agent **agp) { } static void __ice_agent_free_components(struct ice_agent *ag) { if (!ag) { - ilog(LOG_ERR, "ice ag is NULL"); + ilogs(ice, LOG_ERR, "ice ag is NULL"); return; } @@ -513,7 +513,7 @@ static void __ice_agent_free(void *p) { struct ice_agent *ag = p; if (!ag) { - ilog(LOG_ERR, "ice ag is NULL"); + ilogs(ice, LOG_ERR, "ice ag is NULL"); return; } @@ -569,7 +569,7 @@ void ice_free(void) { static void __fail_pair(struct ice_candidate_pair *pair) { - ilog(LOG_DEBUG, "Setting ICE candidate pair "PAIR_FORMAT" as failed", PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Setting ICE candidate pair "PAIR_FORMAT" as failed", PAIR_FMT(pair)); PAIR_SET(pair, FAILED); PAIR_CLEAR(pair, IN_PROGRESS); } @@ -618,7 +618,7 @@ static void __do_ice_check(struct ice_candidate_pair *pair) { mutex_unlock(&ag->lock); - ilog(LOG_DEBUG, "Sending %sICE/STUN request for candidate pair "PAIR_FORMAT" from %s to %s%s%s", + ilogs(ice, LOG_DEBUG, "Sending %sICE/STUN request for candidate pair "PAIR_FORMAT" from %s to %s%s%s", PAIR_ISSET(pair, TO_USE) ? "nominating " : "", PAIR_FMT(pair), sockaddr_print_buf(&pair->local_intf->spec->local_address.addr), FMT_M(endpoint_print_buf(&pair->remote_candidate->endpoint))); @@ -656,7 +656,7 @@ static void __nominate_pairs(struct ice_agent *ag) { GList *l; struct ice_candidate_pair *pair; - ilog(LOG_DEBUG, "Start nominating ICE pairs"); + ilogs(ice, LOG_DEBUG, "Start nominating ICE pairs"); AGENT_SET(ag, NOMINATING); ZERO(ag->start_nominating); @@ -665,7 +665,7 @@ static void __nominate_pairs(struct ice_agent *ag) { for (l = complete.head; l; l = l->next) { pair = l->data; - ilog(LOG_DEBUG, "Nominating ICE pair "PAIR_FORMAT, PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Nominating ICE pair "PAIR_FORMAT, PAIR_FMT(pair)); PAIR_CLEAR(pair, IN_PROGRESS); PAIR_SET2(pair, NOMINATED, TO_USE); pair->retransmits = 0; @@ -686,7 +686,7 @@ static void __do_ice_checks(struct ice_agent *ag) { int have_more = 0; if (!ag) { - ilog(LOG_ERR, "ice ag is NULL"); + ilogs(ice, LOG_ERR, "ice ag is NULL"); return; } @@ -797,7 +797,7 @@ check: } static void __agent_shutdown(struct ice_agent *ag) { - ilog(LOG_DEBUG, "Shutting down ICE agent (nothing to do)"); + ilogs(ice, LOG_DEBUG, "Shutting down ICE agent (nothing to do)"); __agent_deschedule(ag); } @@ -886,7 +886,7 @@ out: static void __trigger_check(struct ice_candidate_pair *pair) { struct ice_agent *ag = pair->agent; - ilog(LOG_DEBUG, "Triggering check for "PAIR_FORMAT, PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Triggering check for "PAIR_FORMAT, PAIR_FMT(pair)); mutex_lock(&ag->lock); pair->retransmits = 0; @@ -906,7 +906,7 @@ static void __recalc_pair_prios(struct ice_agent *ag) { GList *l; GQueue nominated, valid, succ, all; - ilog(LOG_DEBUG, "Recalculating all ICE pair priorities"); + ilogs(ice, LOG_DEBUG, "Recalculating all ICE pair priorities"); g_tree_remove_all(&nominated, ag->nominated_pairs); g_tree_remove_all(&succ, ag->succeeded_pairs); @@ -936,7 +936,7 @@ static void __role_change(struct ice_agent *ag, int new_controlling) { else return; - ilog(LOG_DEBUG, "ICE role change, now %s", new_controlling ? "controlling" : "controlled"); + ilogs(ice, LOG_DEBUG, "ICE role change, now %s", new_controlling ? "controlling" : "controlled"); /* recalc priorities and resort list */ @@ -999,7 +999,7 @@ static int __check_valid(struct ice_agent *ag) { int is_complete = 1; if (!ag) { - ilog(LOG_ERR, "ice ag is NULL"); + ilogs(ice, LOG_ERR, "ice ag is NULL"); return 0; } @@ -1011,18 +1011,18 @@ static int __check_valid(struct ice_agent *ag) { is_complete = 0; __get_complete_succeeded_pairs(&all_compos, ag); if (!all_compos.length) { - ilog(LOG_DEBUG, "ICE not completed yet and no usable candidates"); + ilogs(ice, LOG_DEBUG, "ICE not completed yet and no usable candidates"); return 0; } } pair = all_compos.head->data; if (is_complete) { - ilog(LOG_DEBUG, "ICE completed, using pair " PAIR_FORMAT, PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "ICE completed, using pair " PAIR_FORMAT, PAIR_FMT(pair)); AGENT_SET(ag, COMPLETED); } else { - ilog(LOG_DEBUG, "ICE not completed yet, but can use pair " PAIR_FORMAT, PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "ICE not completed yet, but can use pair " PAIR_FORMAT, PAIR_FMT(pair)); AGENT_SET(ag, USABLE); } @@ -1032,7 +1032,7 @@ static int __check_valid(struct ice_agent *ag) { mutex_lock(&ps->out_lock); if (memcmp(&ps->endpoint, &pair->remote_candidate->endpoint, sizeof(ps->endpoint))) { - ilog(LOG_INFO, "ICE negotiated: peer for component %u is %s%s%s", ps->component, + ilogs(ice, LOG_INFO, "ICE negotiated: peer for component %u is %s%s%s", ps->component, FMT_M(endpoint_print_buf(&pair->remote_candidate->endpoint))); ps->endpoint = pair->remote_candidate->endpoint; } @@ -1044,7 +1044,7 @@ static int __check_valid(struct ice_agent *ag) { continue; ps->selected_sfd = sfd; if (ps->component == 1) - ilog(LOG_INFO, "ICE negotiated: local interface %s", + ilogs(ice, LOG_INFO, "ICE negotiated: local interface %s", sockaddr_print_buf(&pair->local_intf->spec->local_address.addr)); break; } @@ -1127,7 +1127,7 @@ int ice_request(struct stream_fd *sfd, const endpoint_t *src, ret = 0; if (attrs->use && !PAIR_SET(pair, NOMINATED)) { - ilog(LOG_DEBUG, "ICE pair "PAIR_FORMAT" has been nominated by peer", PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "ICE pair "PAIR_FORMAT" has been nominated by peer", PAIR_FMT(pair)); mutex_lock(&ag->lock); @@ -1149,7 +1149,7 @@ int ice_request(struct stream_fd *sfd, const endpoint_t *src, err_unlock: mutex_unlock(&ag->lock); - ilog(LOG_NOTICE | LOG_FLAG_LIMIT, "%s (from %s%s%s on interface %s)", err, FMT_M(endpoint_print_buf(src)), + ilogs(ice, LOG_NOTICE | LOG_FLAG_LIMIT, "%s (from %s%s%s on interface %s)", err, FMT_M(endpoint_print_buf(src)), endpoint_print_buf(&sfd->socket.local)); return 0; } @@ -1162,11 +1162,11 @@ static int __check_succeeded_complete(struct ice_agent *ag) { __get_complete_succeeded_pairs(&complete, ag); if (complete.length) { struct ice_candidate_pair *pair = complete.head->data; - ilog(LOG_DEBUG, "Best succeeded ICE pair with all components is "PAIR_FORMAT, PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Best succeeded ICE pair with all components is "PAIR_FORMAT, PAIR_FMT(pair)); ret = 1; } else { - ilog(LOG_DEBUG, "No succeeded ICE pairs with all components yet"); + ilogs(ice, LOG_DEBUG, "No succeeded ICE pairs with all components yet"); ret = 0; } g_queue_clear(&complete); @@ -1208,7 +1208,7 @@ int ice_response(struct stream_fd *sfd, const endpoint_t *src, ifa = pair->local_intf; - ilog(LOG_DEBUG, "Received ICE/STUN response code %u for candidate pair "PAIR_FORMAT" from %s%s%s to %s", + ilogs(ice, LOG_DEBUG, "Received ICE/STUN response code %u for candidate pair "PAIR_FORMAT" from %s%s%s to %s", attrs->error_code, PAIR_FMT(pair), FMT_M(endpoint_print_buf(&pair->remote_candidate->endpoint)), sockaddr_print_buf(&ifa->spec->local_address.addr)); @@ -1242,7 +1242,7 @@ int ice_response(struct stream_fd *sfd, const endpoint_t *src, /* check if we're in the final (controlling) phase */ if (pair->was_nominated && PAIR_CLEAR(pair, TO_USE)) { - ilog(LOG_DEBUG, "Setting nominated ICE candidate pair "PAIR_FORMAT" as valid", PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Setting nominated ICE candidate pair "PAIR_FORMAT" as valid", PAIR_FMT(pair)); PAIR_SET(pair, VALID); g_tree_insert_coll(ag->valid_pairs, pair, pair, __tree_coll_callback); ret = __check_valid(ag); @@ -1252,7 +1252,7 @@ int ice_response(struct stream_fd *sfd, const endpoint_t *src, if (PAIR_SET(pair, SUCCEEDED)) goto out_unlock; - ilog(LOG_DEBUG, "Setting ICE candidate pair "PAIR_FORMAT" as succeeded", PAIR_FMT(pair)); + ilogs(ice, LOG_DEBUG, "Setting ICE candidate pair "PAIR_FORMAT" as succeeded", PAIR_FMT(pair)); g_tree_insert_coll(ag->succeeded_pairs, pair, pair, __tree_coll_callback); if (!ag->start_nominating.tv_sec) { @@ -1279,7 +1279,7 @@ int ice_response(struct stream_fd *sfd, const endpoint_t *src, if (!PAIR_CLEAR(opair, FROZEN)) continue; - ilog(LOG_DEBUG, "Unfreezing related ICE pair "PAIR_FORMAT, PAIR_FMT(opair)); + ilogs(ice, LOG_DEBUG, "Unfreezing related ICE pair "PAIR_FORMAT, PAIR_FMT(opair)); } /* if this was previously nominated by the peer, it's now valid */ @@ -1299,7 +1299,7 @@ err_unlock: mutex_unlock(&ag->lock); err: if (err) - ilog(LOG_NOTICE | LOG_FLAG_LIMIT, "%s (from %s%s%s on interface %s)", + ilogs(ice, LOG_NOTICE | LOG_FLAG_LIMIT, "%s (from %s%s%s on interface %s)", err, FMT_M(endpoint_print_buf(src)), endpoint_print_buf(&sfd->socket.local)); if (pair && attrs->error_code) diff --git a/daemon/log.h b/daemon/log.h index a5f6ff46a..c519a3ad5 100644 --- a/daemon/log.h +++ b/daemon/log.h @@ -52,7 +52,7 @@ void __ilog(int prio, const char *fmt, ...) __attribute__ ((format (printf, 2, 3 #ifdef __DEBUG #define __C_DBG(x...) ilog(LOG_DEBUG, x) #else -#define __C_DBG(x...) ((void)0) +#define __C_DBG(x...) ilogs(internals, LOG_DEBUG, x) #endif diff --git a/daemon/loglevels.h b/daemon/loglevels.h new file mode 100644 index 000000000..500e0a5ab --- /dev/null +++ b/daemon/loglevels.h @@ -0,0 +1,12 @@ +ll(core) +ll(spandsp) +ll(ffmpeg) +ll(transcoding) +ll(codec) +ll(rtcp) +ll(ice) +ll(crypto) +ll(srtp) +ll(internals) +ll(http) +ll(control) diff --git a/daemon/main.c b/daemon/main.c index 536316b6a..6101ee3cc 100644 --- a/daemon/main.c +++ b/daemon/main.c @@ -80,6 +80,11 @@ struct rtpengine_config rtpe_config = { .dtls_rsa_key_size = 2048, .dtls_signature = 256, .max_dtx = 30, + .common = { + .log_levels = { + [log_level_index_internals] = -1, + }, + }, }; static void sighandler(gpointer x) { @@ -107,17 +112,19 @@ static void sighandler(gpointer x) { if (ret == SIGINT || ret == SIGTERM) rtpe_shutdown = 1; else if (ret == SIGUSR1) { - if (get_log_level() > 0) { - g_atomic_int_add(&rtpe_config.common.log_level, -1); - ilog(get_log_level(), "Set log level to %d\n", - get_log_level()); + for (unsigned int i = 0; i < num_log_levels; i++) { + g_atomic_int_add(&rtpe_config.common.log_levels[i], -1); + ilogsn(i, __get_log_level(i), "Decreased '%s' log level to %d\n", + log_level_names[i], + __get_log_level(i)); } } else if (ret == SIGUSR2) { - if (get_log_level() < 7) { - g_atomic_int_add(&rtpe_config.common.log_level, 1); - ilog(get_log_level(), "Set log level to %d\n", - get_log_level()); + for (unsigned int i = 0; i < num_log_levels; i++) { + g_atomic_int_add(&rtpe_config.common.log_levels[i], 1); + ilogsn(i, __get_log_level(i), "Increased '%s' log level to %d\n", + log_level_names[i], + __get_log_level(i)); } } else @@ -382,6 +389,7 @@ static void options(int *argc, char ***argv) { AUTO_CLEANUP_GBUF(dtls_sig); double silence_detect = 0; AUTO_CLEANUP_GVBUF(cn_payload); + int debug_srtp; GOptionEntry e[] = { { "table", 't', 0, G_OPTION_ARG_INT, &rtpe_config.kernel_table, "Kernel table to use", "INT" }, @@ -455,7 +463,7 @@ static void options(int *argc, char ***argv) { { "endpoint-learning",0,0,G_OPTION_ARG_STRING, &endpoint_learning, "RTP endpoint learning algorithm", "delayed|immediate|off|heuristic" }, { "jitter-buffer",0, 0, G_OPTION_ARG_INT, &rtpe_config.jb_length, "Size of jitter buffer", "INT" }, { "jb-clock-drift",0,0, G_OPTION_ARG_NONE, &rtpe_config.jb_clock_drift,"Compensate for source clock drift",NULL }, - { "debug-srtp",0,0, G_OPTION_ARG_NONE, &rtpe_config.debug_srtp,"Log raw encryption details for SRTP", NULL }, + { "debug-srtp",0,0, G_OPTION_ARG_NONE, &debug_srtp, "Log raw encryption details for SRTP", NULL }, { "dtls-rsa-key-size",0, 0, G_OPTION_ARG_INT,&rtpe_config.dtls_rsa_key_size,"Size of RSA key for DTLS", "INT" }, { "dtls-ciphers",0, 0, G_OPTION_ARG_STRING, &rtpe_config.dtls_ciphers,"List of ciphers for DTLS", "STRING" }, { "dtls-signature",0, 0,G_OPTION_ARG_STRING, &dtls_sig, "Signature algorithm for DTLS", "SHA-256|SHA-1" }, @@ -628,6 +636,9 @@ static void options(int *argc, char ***argv) { die("Invalid --log-format option"); } + if (debug_srtp) + rtpe_config.common.log_levels[log_level_index_srtp] = LOG_DEBUG; + if (dtmf_udp_ep) { if (endpoint_parse_any_getaddrinfo_full(&rtpe_config.dtmf_udp_ep, dtmf_udp_ep)) die("Invalid IP or port '%s' (--dtmf-log-dest)", dtmf_udp_ep); @@ -768,7 +779,7 @@ void fill_initial_rtpe_cfg(struct rtpengine_config* ini_rtpe_cfg) { ini_rtpe_cfg->redis_connect_timeout = rtpe_config.redis_connect_timeout; ini_rtpe_cfg->redis_delete_async = rtpe_config.redis_delete_async; ini_rtpe_cfg->redis_delete_async_interval = rtpe_config.redis_delete_async_interval; - ini_rtpe_cfg->common.log_level = rtpe_config.common.log_level; + memcpy(&ini_rtpe_cfg->common.log_levels, &rtpe_config.common.log_levels, sizeof(ini_rtpe_cfg->common.log_levels)); ini_rtpe_cfg->graphite_ep = rtpe_config.graphite_ep; ini_rtpe_cfg->tcp_listen_ep = rtpe_config.tcp_listen_ep; diff --git a/daemon/redis.c b/daemon/redis.c index 3220f57ae..6c3461e03 100644 --- a/daemon/redis.c +++ b/daemon/redis.c @@ -1907,7 +1907,8 @@ int redis_restore(struct redis *r) { if (!r) return 0; - rtpe_config.common.log_level |= LOG_FLAG_RESTORE; + for (unsigned int i = 0; i < num_log_levels; i++) + rtpe_config.common.log_levels[i] |= LOG_FLAG_RESTORE; rlog(LOG_DEBUG, "Restoring calls from Redis..."); @@ -1954,7 +1955,8 @@ int redis_restore(struct redis *r) { freeReplyObject(calls); err: - rtpe_config.common.log_level &= ~LOG_FLAG_RESTORE; + for (unsigned int i = 0; i < num_log_levels; i++) + rtpe_config.common.log_levels[i] &= ~LOG_FLAG_RESTORE; return ret; } diff --git a/daemon/rtcp.c b/daemon/rtcp.c index 1c327db83..67f337193 100644 --- a/daemon/rtcp.c +++ b/daemon/rtcp.c @@ -632,7 +632,7 @@ static int rtcp_xr(struct rtcp_chain_element *el, struct rtcp_process_ctx *log_c if (!hf) goto next; if (rb->bt < G_N_ELEMENTS(min_xr_packet_sizes) && len < min_xr_packet_sizes[rb->bt]) { - ilog(LOG_WARN, "Short RTCP XR block (type %u, %u < %i)", rb->bt, len, + ilogs(rtcp, LOG_WARN, "Short RTCP XR block (type %u, %u < %i)", rb->bt, len, min_xr_packet_sizes[rb->bt]); goto next; } @@ -682,7 +682,7 @@ int rtcp_parse(GQueue *q, struct media_packet *mp) { break; if (hdr->version != 2) { - ilog(LOG_DEBUG, "Unknown RTCP version %u", hdr->version); + ilogs(rtcp, LOG_DEBUG, "Unknown RTCP version %u", hdr->version); goto error; } @@ -690,7 +690,7 @@ int rtcp_parse(GQueue *q, struct media_packet *mp) { if (hdr->pt < G_N_ELEMENTS(min_packet_sizes)) min_packet_size = min_packet_sizes[hdr->pt]; if (len < min_packet_size) { - ilog(LOG_WARN, "Invalid RTCP packet type %u (short: %u < %i)", + ilogs(rtcp, LOG_WARN, "Invalid RTCP packet type %u (short: %u < %i)", hdr->pt, len, min_packet_size); goto error; } @@ -698,19 +698,19 @@ int rtcp_parse(GQueue *q, struct media_packet *mp) { el = rtcp_new_element(hdr, len); if (hdr->pt >= G_N_ELEMENTS(handler_funcs)) { - ilog(LOG_INFO, "Ignoring unknown RTCP packet type %u", hdr->pt); + ilogs(rtcp, LOG_INFO, "Ignoring unknown RTCP packet type %u", hdr->pt); goto next; } func = handler_funcs[hdr->pt]; if (!func) { - ilog(LOG_INFO, "Ignoring unknown RTCP packet type %u", hdr->pt); + ilogs(rtcp, LOG_INFO, "Ignoring unknown RTCP packet type %u", hdr->pt); goto next; } - ilog(LOG_DEBUG, "Calling handler for RTCP packet type %u", hdr->pt); + ilogs(rtcp, LOG_DEBUG, "Calling handler for RTCP packet type %u", hdr->pt); ret = func(el, log_ctx); if (ret) { - ilog(LOG_WARN, "Failed to handle or parse RTCP packet type %u", hdr->pt); + ilogs(rtcp, LOG_WARN, "Failed to handle or parse RTCP packet type %u", hdr->pt); rtcp_ce_free(el); goto error; } @@ -794,7 +794,7 @@ INLINE int check_session_keys(struct crypto_context *c) { return 0; error: - ilog(LOG_ERROR | LOG_FLAG_LIMIT, "%s", err); + ilogs(rtcp, LOG_ERROR | LOG_FLAG_LIMIT, "%s", err); return -1; } @@ -839,7 +839,7 @@ done: *out = rtcp; return 0; error: - ilog(LOG_DEBUG | LOG_FLAG_LIMIT, "Error parsing RTCP header: %s", err); + ilogs(rtcp, LOG_DEBUG | LOG_FLAG_LIMIT, "Error parsing RTCP header: %s", err); return -1; } @@ -951,7 +951,7 @@ int rtcp_savp2avp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) { return 0; error: - ilog(LOG_WARNING | LOG_FLAG_LIMIT, "Discarded invalid SRTCP packet: %s", err); + ilogs(rtcp, LOG_WARNING | LOG_FLAG_LIMIT, "Discarded invalid SRTCP packet: %s", err); return -1; } @@ -1284,7 +1284,7 @@ static void transcode_common(struct rtcp_process_ctx *ctx, struct rtcp_packet *c return; // forward SSRC mapping common->ssrc = htonl(ctx->mp->ssrc_in->ssrc_map_out); - ilog(LOG_DEBUG, "Substituting RTCP header SSRC from %s%x%s to %x", + ilogs(rtcp, LOG_DEBUG, "Substituting RTCP header SSRC from %s%x%s to %x", FMT_M(ctx->scratch_common_ssrc), ctx->mp->ssrc_in->ssrc_map_out); } static void transcode_rr(struct rtcp_process_ctx *ctx, struct report_block *rr) { @@ -1315,7 +1315,7 @@ static void transcode_rr(struct rtcp_process_ctx *ctx, struct report_block *rr) unsigned int dupes = atomic64_get(&input_ctx->duplicates); unsigned int tot_lost = lost - dupes; // can be negative/rollover - ilog(LOG_DEBUG, "Substituting RTCP RR SSRC from %s%x%s to %x: %u packets, %u lost, %u duplicates", + ilogs(rtcp, LOG_DEBUG, "Substituting RTCP RR SSRC from %s%x%s to %x: %u packets, %u lost, %u duplicates", FMT_M(ctx->scratch.rr.ssrc), map_ctx->ssrc_map_out, packets, lost, dupes); @@ -1563,7 +1563,7 @@ void rtcp_send_report(struct call_media *media, struct ssrc_ctx *ssrc_out) { GQueue rrs = G_QUEUE_INIT; rtcp_receiver_reports(&rrs, call->ssrc_hash, ps->media->monologue); - ilog(LOG_DEBUG, "Generating and sending RTCP SR for %x and up to %i source(s)", + ilogs(rtcp, LOG_DEBUG, "Generating and sending RTCP SR for %x and up to %i source(s)", ssrc_out->parent->h.ssrc, rrs.length); struct ssrc_sender_report ssr; diff --git a/daemon/rtpengine.pod b/daemon/rtpengine.pod index a2e73ea78..3e9104ab9 100644 --- a/daemon/rtpengine.pod +++ b/daemon/rtpengine.pod @@ -192,8 +192,11 @@ Default to 30000 and 40000 respectively. =item B<-L>, B<--log-level=>I -Takes an integer as argument and controls the highest log level which -will be sent to syslog. +Takes an integer as argument and controls the highest log level which will be +sent to syslog. This is merely the default log level used for logging +subsystems (see below) that don't explicitly have a separate log level +configured. + The log levels correspond to the ones found in the L man page. The default value is B<6>, equivalent to LOG_INFO. The highest possible value is B<7> (LOG_DEBUG) which will log everything. @@ -201,6 +204,23 @@ The highest possible value is B<7> (LOG_DEBUG) which will log everything. During runtime, the log level can be decreased by sending the signal SIGURS1 to the daemon and can be increased with the signal SIGUSR2. +=item B<--log-level->IB<=>I + +Configures a log level for one of the logging subsystems. A logging subsystem +which doesn't have a log level configured explicitly takes its default value +from the B setting described above, with the exceptino of the +B subsystem which by default has all logging disabled. + +The full list of logging subsystems can be viewed by pulling up the B<--help> +online help. Some (if not all) subsystems are: B, B (messages +generated by SpanDSP itself), B (messages generated by ffmpeg libraries +themselves), B (messages related to RTP/media transcoding), +B (messages related to codec negotiation), B, B, B +(messages related to crypto/SRTP/SDES/DTLS negotiation), B (messages +related to RTP/SRTP en/decryption), B (disabled by default), B +(includes WebSocket), B (messages related to control protocols, +including SDP exchanges). + =item B<--log-facilty=>B|B|...|B|... The syslog facilty to use when sending log messages to the syslog daemon. diff --git a/daemon/t38.c b/daemon/t38.c index a1995293d..95ecf1115 100644 --- a/daemon/t38.c +++ b/daemon/t38.c @@ -84,7 +84,7 @@ static void spandsp_logging_func(SPAN_LOG_ARGS) { level = LOG_WARN; else level = LOG_DEBUG; - ilog(level, "SpanDSP: %s", text); + ilogs(spandsp, level, "SpanDSP: %s", text); } @@ -414,7 +414,7 @@ int t38_gateway_pair(struct call_media *t38_media, struct call_media *pcm_media, logging_state_t *ls = t38_gateway_get_logging_state(tg->gw); my_span_set_log(ls, spandsp_logging_func); - span_log_set_level(ls, span_log_level_map(get_log_level())); + span_log_set_level(ls, span_log_level_map(get_log_level(spandsp))); packet_sequencer_init(&tg->sequencer, (GDestroyNotify) __udptl_packet_free); tg->sequencer.seq = 0; diff --git a/daemon/websocket.c b/daemon/websocket.c index 69f57f509..cb3ba68c3 100644 --- a/daemon/websocket.c +++ b/daemon/websocket.c @@ -156,7 +156,7 @@ void websocket_write_next(struct websocket_conn *wc) { static const char *websocket_echo_process(struct websocket_message *wm) { - ilog(LOG_DEBUG, "Returning %lu bytes websocket echo from %s", (unsigned long) wm->body->len, + ilogs(http, LOG_DEBUG, "Returning %lu bytes websocket echo from %s", (unsigned long) wm->body->len, endpoint_print_buf(&wm->wc->endpoint)); websocket_write_binary(wm->wc, wm->body->str, wm->body->len, 1); return NULL; @@ -164,7 +164,7 @@ static const char *websocket_echo_process(struct websocket_message *wm) { static void websocket_message_push(struct websocket_conn *wc, websocket_message_func_t func) { - ilog(LOG_DEBUG, "Adding HTTP/WS message to processing queue"); + ilogs(http, LOG_DEBUG, "Adding HTTP/WS message to processing queue"); mutex_lock(&wc->lock); @@ -203,7 +203,7 @@ static void websocket_process(void *p, void *up) { mutex_unlock(&wc->lock); if (err) - ilog(LOG_ERR, "Error while processing HTTP/WS message: %s", err); + ilogs(http, LOG_ERR, "Error while processing HTTP/WS message: %s", err); } @@ -223,14 +223,14 @@ static int websocket_dequeue(struct websocket_conn *wc) { size_t to_send = wo->str->len - wo->str_done - LWS_SEND_BUFFER_POST_PADDING; if (to_send) { if (to_send > 500) - ilog(LOG_DEBUG, "Writing %lu bytes to LWS", (unsigned long) to_send); + ilogs(http, LOG_DEBUG, "Writing %lu bytes to LWS", (unsigned long) to_send); else - ilog(LOG_DEBUG, "Writing back to LWS: '%.*s'", + ilogs(http, LOG_DEBUG, "Writing back to LWS: '%.*s'", (int) to_send, wo->str->str + wo->str_done); size_t ret = lws_write(wc->wsi, (unsigned char *) wo->str->str + wo->str_done, to_send, wo->protocol); if (ret != to_send) - ilog(LOG_ERR, "Invalid LWS write: %lu != %lu", + ilogs(http, LOG_ERR, "Invalid LWS write: %lu != %lu", (unsigned long) ret, (unsigned long) to_send); wo->str_done += ret; @@ -283,7 +283,7 @@ int websocket_http_response(struct websocket_conn *wc, int status, const char *c const char *err = websocket_do_http_response(wc, status, content_type, content_length); if (!err) return 0; - ilog(LOG_ERR, "Failed to write HTTP response headers: %s", err); + ilogs(http, LOG_ERR, "Failed to write HTTP response headers: %s", err); return -1; } const char *websocket_http_complete(struct websocket_conn *wc, int status, const char *content_type, @@ -298,7 +298,7 @@ const char *websocket_http_complete(struct websocket_conn *wc, int status, const static const char *websocket_http_ping(struct websocket_message *wm) { - ilog(LOG_DEBUG, "Respoding to GET /ping"); + ilogs(http, LOG_DEBUG, "Respoding to GET /ping"); return websocket_http_complete(wm->wc, 200, "text/plain", 5, "pong\n"); } @@ -310,7 +310,7 @@ static void __g_hash_table_destroy(GHashTable **s) { g_hash_table_destroy(*s); } static const char *websocket_http_metrics(struct websocket_message *wm) { - ilog(LOG_DEBUG, "Respoding to GET /metrics"); + ilogs(http, LOG_DEBUG, "Respoding to GET /metrics"); AUTO_CLEANUP_INIT(GQueue *metrics, statistics_free_metrics, statistics_gather_metrics()); AUTO_CLEANUP_INIT(GString *outp, __g_string_free, g_string_new("")); @@ -361,7 +361,7 @@ static const char *websocket_http_cli(struct websocket_message *wm) { assert(strncmp(wm->uri, "/cli/", 5) == 0); char *uri = wm->uri+5; - ilog(LOG_DEBUG, "Respoding to GET /cli/%s", uri); + ilogs(http, LOG_DEBUG, "Respoding to GET /cli/%s", uri); str uri_cmd; str_init(&uri_cmd, uri); @@ -379,7 +379,7 @@ static const char *websocket_http_cli(struct websocket_message *wm) { static const char *websocket_cli_process(struct websocket_message *wm) { - ilog(LOG_DEBUG, "Processing websocket CLI req '%s'", wm->body->str); + ilogs(http, LOG_DEBUG, "Processing websocket CLI req '%s'", wm->body->str); str uri_cmd; str_init_len(&uri_cmd, wm->body->str, wm->body->len); @@ -405,7 +405,7 @@ static void websocket_ng_send_ws(str *cookie, str *body, const endpoint_t *sin, static void websocket_ng_send_http(str *cookie, str *body, const endpoint_t *sin, void *p1) { struct websocket_conn *wc = p1; if (websocket_http_response(wc, 200, "application/x-rtpengine-ng", cookie->len + 1 + body->len)) - ilog(LOG_WARN, "Failed to write HTTP headers"); + ilogs(http, LOG_WARN, "Failed to write HTTP headers"); websocket_queue_raw(wc, cookie->s, cookie->len); websocket_queue_raw(wc, " ", 1); websocket_queue_raw(wc, body->s, body->len); @@ -415,7 +415,7 @@ static const char *websocket_ng_process(struct websocket_message *wm) { char addr[64]; endpoint_print(&wm->wc->endpoint, addr, sizeof(addr)); - ilog(LOG_DEBUG, "Processing websocket NG req from %s", addr); + ilogs(http, LOG_DEBUG, "Processing websocket NG req from %s", addr); str cmd; str_init_len(&cmd, wm->body->str, wm->body->len); @@ -429,7 +429,7 @@ static const char *websocket_http_ng(struct websocket_message *wm) { endpoint_print(&wm->wc->endpoint, addr, sizeof(addr)); - ilog(LOG_DEBUG, "Respoding to POST /ng from %s", addr); + ilogs(http, LOG_DEBUG, "Respoding to POST /ng from %s", addr); str cmd; str_init_len(&cmd, wm->body->str, wm->body->len); @@ -449,7 +449,7 @@ static int websocket_http_get(struct websocket_conn *wc) { const char *uri = wm->uri; websocket_message_func_t handler = NULL; - ilog(LOG_DEBUG, "HTTP GET from %s: '%s'", endpoint_print_buf(&wc->endpoint), wm->uri); + ilogs(http, LOG_INFO, "HTTP GET from %s: '%s'", endpoint_print_buf(&wc->endpoint), wm->uri); wm->method = M_GET; if (!strcmp(uri, "/ping")) @@ -460,7 +460,7 @@ static int websocket_http_get(struct websocket_conn *wc) { handler = websocket_http_metrics; if (!handler) { - ilog(LOG_WARN, "Unhandled HTTP GET URI: '%s'", uri); + ilogs(http, LOG_WARN, "Unhandled HTTP GET URI: '%s'", uri); websocket_http_complete(wm->wc, 404, "text/plain", 10, "not found\n"); return 0; } @@ -473,33 +473,33 @@ static int websocket_http_get(struct websocket_conn *wc) { static int websocket_http_post(struct websocket_conn *wc) { struct websocket_message *wm = wc->wm; - ilog(LOG_DEBUG, "HTTP POST from %s: '%s'", endpoint_print_buf(&wc->endpoint), wm->uri); + ilogs(http, LOG_INFO, "HTTP POST from %s: '%s'", endpoint_print_buf(&wc->endpoint), wm->uri); wm->method = M_POST; char ct[64]; if (lws_hdr_total_length(wc->wsi, WSI_TOKEN_HTTP_CONTENT_TYPE) >= sizeof(ct)) { - ilog(LOG_WARN, "Too long content-type header, rejecting HTTP POST"); + ilogs(http, LOG_WARN, "Too long content-type header, rejecting HTTP POST"); return -1; } if (lws_hdr_copy(wc->wsi, ct, sizeof(ct)-1, WSI_TOKEN_HTTP_CONTENT_TYPE) <= 0) { - ilog(LOG_WARN, "Failed to get Content-type header, rejecting HTTP POST"); + ilogs(http, LOG_WARN, "Failed to get Content-type header, rejecting HTTP POST"); return -1; } if (lws_hdr_total_length(wc->wsi, WSI_TOKEN_HTTP_CONTENT_LENGTH) <= 0) { - ilog(LOG_WARN, "Failed to get Content-length header, rejecting HTTP POST"); + ilogs(http, LOG_WARN, "Failed to get Content-length header, rejecting HTTP POST"); return -1; } - ilog(LOG_DEBUG, "POST content-type: %s", ct); + ilogs(http, LOG_DEBUG, "POST content-type: %s", ct); if (!strcasecmp(ct, "application/json")) wm->content_type = CT_JSON; else if (!strcasecmp(ct, "application/x-rtpengine-ng")) wm->content_type = CT_NG; else - ilog(LOG_WARN, "Unsupported content-type '%s'", ct); + ilogs(http, LOG_WARN, "Unsupported content-type '%s'", ct); return 0; } @@ -511,23 +511,23 @@ static int websocket_http_body(struct websocket_conn *wc, const char *body, size websocket_message_func_t handler = NULL; if (wm->method != M_POST) { - ilog(LOG_WARN, "Rejecting HTTP body on unsupported method"); + ilogs(http, LOG_WARN, "Rejecting HTTP body on unsupported method"); return -1; } if (len) { - ilog(LOG_DEBUG, "HTTP body: %lu bytes", (unsigned long) len); + ilogs(http, LOG_DEBUG, "HTTP body: %lu bytes", (unsigned long) len); g_string_append_len(wm->body, body, len); return 0; } - ilog(LOG_DEBUG, "HTTP body complete: '%.*s'", (int) wm->body->len, wm->body->str); + ilogs(http, LOG_DEBUG, "HTTP body complete: '%.*s'", (int) wm->body->len, wm->body->str); if (!strcmp(uri, "/ng") && wm->method == M_POST && wm->content_type == CT_NG) handler = websocket_http_ng; if (!handler) { - ilog(LOG_WARN, "Unhandled HTTP POST URI: '%s'", wm->uri); + ilogs(http, LOG_WARN, "Unhandled HTTP POST URI: '%s'", wm->uri); websocket_http_complete(wm->wc, 404, "text/plain", 10, "not found\n"); return 0; } @@ -594,7 +594,7 @@ static void websocket_conn_init(struct lws *wsi, void *p) { int fd = lws_get_socket_fd(wsi); #endif if (getpeername(fd, (struct sockaddr *) &sa, &sl)) - ilog(LOG_ERR, "Failed to get remote address of HTTP/WS connection (fd %i): %s", + ilogs(http, LOG_ERR, "Failed to get remote address of HTTP/WS connection (fd %i): %s", fd, strerror(errno)); else endpoint_parse_sockaddr_storage(&wc->endpoint, &sa); @@ -604,7 +604,7 @@ static void websocket_conn_init(struct lws *wsi, void *p) { static int websocket_do_http(struct lws *wsi, struct websocket_conn *wc, const char *uri) { - ilog(LOG_DEBUG, "HTTP request start: %s", uri); + ilogs(http, LOG_DEBUG, "HTTP request start: %s", uri); websocket_conn_init(wsi, wc); wc->wm->uri = strdup(uri); @@ -614,7 +614,7 @@ static int websocket_do_http(struct lws *wsi, struct websocket_conn *wc, const c if (lws_hdr_total_length(wsi, WSI_TOKEN_POST_URI)) return websocket_http_post(wc); - ilog(LOG_INFO, "Ignoring HTTP request to %s with unsupported method", uri); + ilogs(http, LOG_INFO, "Ignoring HTTP request to %s with unsupported method", uri); return 0; } @@ -622,7 +622,7 @@ static int websocket_do_http(struct lws *wsi, struct websocket_conn *wc, const c static int websocket_http(struct lws *wsi, enum lws_callback_reasons reason, void *user, void *in, size_t len) { - ilog(LOG_DEBUG, "http-only callback %i %p %p", reason, wsi, user); + ilogs(http, LOG_DEBUG, "http-only callback %i %p %p", reason, wsi, user); gettimeofday(&rtpe_now, NULL); @@ -646,10 +646,10 @@ static int websocket_http(struct lws *wsi, enum lws_callback_reasons reason, voi case LWS_CALLBACK_GET_THREAD_ID: return (long int) pthread_self(); case LWS_CALLBACK_WSI_CREATE: - ilog(LOG_DEBUG, "WS client created %p", wsi); + ilogs(http, LOG_DEBUG, "WS client created %p", wsi); break; case LWS_CALLBACK_SERVER_NEW_CLIENT_INSTANTIATED: - ilog(LOG_DEBUG, "New WS client %p", wsi); + ilogs(http, LOG_DEBUG, "New WS client %p", wsi); break; case LWS_CALLBACK_HTTP: return websocket_do_http(wsi, user, in); @@ -660,21 +660,21 @@ static int websocket_http(struct lws *wsi, enum lws_callback_reasons reason, voi case LWS_CALLBACK_HTTP_BODY_COMPLETION: return websocket_http_body(user, NULL, 0); case LWS_CALLBACK_CLOSED_HTTP: - ilog(LOG_DEBUG, "HTTP connection closed %p", wsi); + ilogs(http, LOG_DEBUG, "HTTP connection closed %p", wsi); websocket_conn_cleanup(user); break; case LWS_CALLBACK_WSI_DESTROY: - ilog(LOG_DEBUG, "WS client destroyed %p", wsi); + ilogs(http, LOG_DEBUG, "WS client destroyed %p", wsi); break; case LWS_CALLBACK_ESTABLISHED: case LWS_CALLBACK_RECEIVE: case LWS_CALLBACK_CLOSED: - ilog(LOG_WARN, "Invalid HTTP callback %i", reason); + ilogs(http, LOG_WARN, "Invalid HTTP callback %i", reason); return -1; case LWS_CALLBACK_HTTP_WRITEABLE: return websocket_dequeue(user); default: - ilog(LOG_DEBUG, "Unhandled HTTP callback %i", reason); + ilogs(http, LOG_DEBUG, "Unhandled HTTP callback %i", reason); break; } @@ -687,7 +687,7 @@ static int websocket_protocol(struct lws *wsi, enum lws_callback_reasons reason, { struct websocket_conn *wc = user; - ilog(LOG_DEBUG, "Websocket protocol '%s' callback %i %p %p", name, reason, wsi, wc); + ilogs(http, LOG_DEBUG, "Websocket protocol '%s' callback %i %p %p", name, reason, wsi, wc); gettimeofday(&rtpe_now, NULL); @@ -709,7 +709,7 @@ static int websocket_protocol(struct lws *wsi, enum lws_callback_reasons reason, case LWS_CALLBACK_GET_THREAD_ID: return (long int) pthread_self(); case LWS_CALLBACK_ESTABLISHED: - ilog(LOG_DEBUG, "Websocket protocol '%s' established", name); + ilogs(http, LOG_DEBUG, "Websocket protocol '%s' established", name); websocket_conn_init(wsi, wc); int get_len = lws_hdr_total_length(wsi, WSI_TOKEN_GET_URI); if (get_len > 0) { @@ -723,12 +723,12 @@ static int websocket_protocol(struct lws *wsi, enum lws_callback_reasons reason, } break; case LWS_CALLBACK_CLOSED: - ilog(LOG_DEBUG, "Websocket protocol '%s' closed", name); + ilogs(http, LOG_DEBUG, "Websocket protocol '%s' closed", name); websocket_conn_cleanup(wc); - ilog(LOG_DEBUG, "Websocket protocol '%s' ready for cleanup", name); + ilogs(http, LOG_DEBUG, "Websocket protocol '%s' ready for cleanup", name); break; case LWS_CALLBACK_RECEIVE:; - ilog(LOG_DEBUG, "Websocket protocol '%s' data received for '%s': '%.*s'", + ilogs(http, LOG_DEBUG, "Websocket protocol '%s' data received for '%s': '%.*s'", name, wc->uri, (int) len, (const char *) in); wc->wm->method = M_WEBSOCKET; g_string_append_len(wc->wm->body, in, len); @@ -737,7 +737,7 @@ static int websocket_protocol(struct lws *wsi, enum lws_callback_reasons reason, case LWS_CALLBACK_SERVER_WRITEABLE: return websocket_dequeue(user); default: - ilog(LOG_DEBUG, "Unhandled websocket protocol '%s' callback %i", name, reason); + ilogs(http, LOG_DEBUG, "Unhandled websocket protocol '%s' callback %i", name, reason); break; } @@ -798,7 +798,7 @@ static void websocket_log(int level, const char *line) { level = LOG_INFO; else level = LOG_DEBUG; - ilog(level, "libwebsockets: %s", line); + ilogs(http, level, "libwebsockets: %s", line); } @@ -843,7 +843,7 @@ int websocket_init(void) { for (char **ifp = rtpe_config.http_ifs; ifp && *ifp; ifp++) { char *ifa = *ifp; - ilog(LOG_DEBUG, "Starting HTTP/WS '%s'", ifa); + ilogs(http, LOG_DEBUG, "Starting HTTP/WS '%s'", ifa); endpoint_t ep; err = "Failed to parse address/port"; if (endpoint_parse_any_getaddrinfo(&ep, ifa)) @@ -869,7 +869,7 @@ int websocket_init(void) { goto err; char *ifa = *ifp; - ilog(LOG_DEBUG, "Starting HTTPS/WSS '%s'", ifa); + ilogs(http, LOG_DEBUG, "Starting HTTPS/WSS '%s'", ifa); endpoint_t ep; err = "Failed to parse address/port"; if (endpoint_parse_any_getaddrinfo(&ep, ifa)) @@ -896,17 +896,17 @@ int websocket_init(void) { int num_threads = rtpe_config.http_threads ? : rtpe_config.num_threads; websocket_threads = g_thread_pool_new(websocket_process, NULL, num_threads, FALSE, NULL); - ilog(LOG_DEBUG, "Websocket init complete with %i threads", num_threads); + ilogs(http, LOG_DEBUG, "Websocket init complete with %i threads", num_threads); return 0; err: - ilog(LOG_ERROR, "Failed to start websocket listener: %s", err); + ilogs(http, LOG_ERROR, "Failed to start websocket listener: %s", err); websocket_cleanup(); return -1; } static void websocket_loop(void *p) { - ilog(LOG_INFO, "Websocket listener thread running"); + ilogs(http, LOG_INFO, "Websocket listener thread running"); while (!rtpe_shutdown) lws_service(websocket_context, 100); diff --git a/include/crypto.h b/include/crypto.h index 2d3486c85..d47eef0c1 100644 --- a/include/crypto.h +++ b/include/crypto.h @@ -211,7 +211,7 @@ INLINE void crypto_params_sdes_queue_clear(GQueue *q) { INLINE void crypto_debug_init(int flag) { - if (!rtpe_config.debug_srtp) + if (rtpe_config.common.log_levels[log_level_index_srtp] < LOG_NOTICE) return; if (crypto_debug_string) g_string_free(crypto_debug_string, TRUE); @@ -222,7 +222,7 @@ INLINE void crypto_debug_init(int flag) { } void __crypto_debug_printf(const char *fmt, ...) __attribute__((format(printf,1,2))); #define crypto_debug_printf(f, ...) \ - if (rtpe_config.debug_srtp && crypto_debug_string) \ + if (crypto_debug_string) \ __crypto_debug_printf(f, ##__VA_ARGS__) INLINE void crypto_debug_dump_raw(const char *b, int len) { for (int i = 0; i < len; i++) @@ -232,11 +232,9 @@ INLINE void crypto_debug_dump(const str *s) { crypto_debug_dump_raw(s->s, s->len); } INLINE void crypto_debug_finish(void) { - if (!rtpe_config.debug_srtp) - return; if (!crypto_debug_string) return; - ilog(LOG_NOTICE, "Crypto debug: %.*s", (int) crypto_debug_string->len, crypto_debug_string->str); + ilogs(srtp, LOG_NOTICE, "Crypto debug: %.*s", (int) crypto_debug_string->len, crypto_debug_string->str); g_string_free(crypto_debug_string, TRUE); crypto_debug_string = NULL; } diff --git a/include/main.h b/include/main.h index df6df7407..8dedb7cc1 100644 --- a/include/main.h +++ b/include/main.h @@ -97,7 +97,6 @@ struct rtpengine_config { enum endpoint_learning endpoint_learning; int jb_length; int jb_clock_drift; - int debug_srtp; int dtls_rsa_key_size; char *dtls_ciphers; int dtls_signature; diff --git a/lib/auxlib.c b/lib/auxlib.c index b3d95ad5c..b28ae27da 100644 --- a/lib/auxlib.c +++ b/lib/auxlib.c @@ -134,19 +134,23 @@ void config_load(int *argc, char ***argv, GOptionEntry *app_entries, const char // defaults #ifndef __DEBUG - rtpe_common_config_ptr->log_level = LOG_INFO; + rtpe_common_config_ptr->default_log_level = LOG_INFO; #else - rtpe_common_config_ptr->log_level = LOG_DEBUG; + rtpe_common_config_ptr->default_log_level = LOG_DEBUG; #endif AUTO_CLEANUP(GKeyFile *kf, free_gkeyfile) = g_key_file_new(); +#define ll(system) \ + { "log-level-" #system, 0, 0, G_OPTION_ARG_INT, &rtpe_common_config_ptr->log_levels[log_level_index_ ## system],"Log level for '" #system "'","INT" }, + GOptionEntry shared_options[] = { { "version", 'v', 0, G_OPTION_ARG_NONE, &version, "Print build time and exit", NULL }, { "config-file", 0, 0, G_OPTION_ARG_STRING, &rtpe_common_config_ptr->config_file, "Load config from this file", "FILE" }, { "config-section", 0, 0, G_OPTION_ARG_STRING, &rtpe_common_config_ptr->config_section,"Config file section to use", "STRING" }, { "log-facility", 0, 0, G_OPTION_ARG_STRING, &rtpe_common_config_ptr->log_facility, "Syslog facility to use for logging", "daemon|local0|...|local7"}, - { "log-level", 'L', 0, G_OPTION_ARG_INT, (void *)&rtpe_common_config_ptr->log_level,"Mask log priorities above this level","INT" }, + { "log-level", 'L', 0, G_OPTION_ARG_INT, &rtpe_common_config_ptr->default_log_level,"Default log level", "INT" }, +#include "loglevels.h" { "log-stderr", 'E', 0, G_OPTION_ARG_NONE, &rtpe_common_config_ptr->log_stderr, "Log on stderr instead of syslog", NULL }, { "split-logs", 0, 0, G_OPTION_ARG_NONE, &rtpe_common_config_ptr->split_logs, "Split multi-line log messages", NULL }, { "no-log-timestamps", 0, 0, G_OPTION_ARG_NONE, &rtpe_common_config_ptr->no_log_timestamps,"Drop timestamps from log lines to stderr",NULL }, @@ -157,6 +161,7 @@ void config_load(int *argc, char ***argv, GOptionEntry *app_entries, const char { "thread-stack", 0,0, G_OPTION_ARG_INT, &rtpe_common_config_ptr->thread_stack, "Thread stack size in kB", "INT" }, { NULL, } }; +#undef ll // prepend shared CLI options @@ -320,8 +325,10 @@ out: } } - if ((rtpe_common_config_ptr->log_level < LOG_EMERG) || (rtpe_common_config_ptr->log_level > LOG_DEBUG)) - die("Invalid log level (--log_level)"); + for (unsigned int i = 0; i < num_log_levels; i++) { + if (!rtpe_common_config_ptr->log_levels[i]) + rtpe_common_config_ptr->log_levels[i] = rtpe_common_config_ptr->default_log_level; + } if (rtpe_common_config_ptr->log_stderr) { write_log = log_to_stderr; diff --git a/lib/auxlib.h b/lib/auxlib.h index 16fd73646..a4141cb05 100644 --- a/lib/auxlib.h +++ b/lib/auxlib.h @@ -10,13 +10,15 @@ #define THREAD_BUF_SIZE 64 #define NUM_THREAD_BUFS 8 +#define MAX_LOG_LEVELS 32 struct rtpengine_common_config { char *config_file; char *config_section; char *log_facility; - volatile int log_level; + int default_log_level; + int log_levels[MAX_LOG_LEVELS]; int log_stderr; int split_logs; int no_log_timestamps; diff --git a/lib/codeclib.c b/lib/codeclib.c index c75b8762c..ea0566233 100644 --- a/lib/codeclib.c +++ b/lib/codeclib.c @@ -761,7 +761,7 @@ int decoder_lost_packet(decoder_t *dec, unsigned long ts, static void avlog_ilog(void *ptr, int loglevel, const char *fmt, va_list ap) { char *msg; if (vasprintf(&msg, fmt, ap) <= 0) - ilog(LOG_ERR | LOG_FLAG_LIMIT, "av_log message dropped"); + ilogs(ffmpeg, LOG_ERR | LOG_FLAG_LIMIT, "av_log message dropped"); else { #ifdef AV_LOG_PANIC // translate AV_LOG_ constants to LOG_ levels @@ -784,7 +784,7 @@ static void avlog_ilog(void *ptr, int loglevel, const char *fmt, va_list ap) { else loglevel = LOG_DEBUG; #endif - ilog(loglevel | LOG_FLAG_LIMIT, "av_log: %s", msg); + ilogs(ffmpeg, loglevel | LOG_FLAG_LIMIT, "av_log: %s", msg); free(msg); } } diff --git a/lib/loglib.c b/lib/loglib.c index 888b81425..582d073f5 100644 --- a/lib/loglib.c +++ b/lib/loglib.c @@ -31,6 +31,14 @@ write_log_t *write_log = (write_log_t *) log_both; +#define ll(system) #system, +const char * const log_level_names[] = { +#include "loglevels.h" +NULL +}; + + + static const _fac_code_t _facilitynames[] = { { "auth", LOG_AUTH }, diff --git a/lib/loglib.h b/lib/loglib.h index efecb4262..47e71dae1 100644 --- a/lib/loglib.h +++ b/lib/loglib.h @@ -29,26 +29,46 @@ void __vpilog(int prio, const char *prefix, const char *fmt, va_list); void __ilog_np(int prio, const char *format, ...) __attribute__ ((format (printf, 2, 3))); + +#define ll(system) log_level_index_ ## system, +enum __loglevels { +#include "loglevels.h" + ll(LAST) +}; +#undef ll + +#define num_log_levels log_level_index_LAST + +extern const char * const log_level_names[]; + + #ifndef __DEBUG -#define ilog(prio, fmt, ...) \ +#define ilogsn(system, prio, fmt, ...) \ do { \ - int __loglevel = get_log_level(); \ + int __loglevel = __get_log_level(system); \ if (LOG_LEVEL_MASK((prio)) > LOG_LEVEL_MASK(__loglevel)) \ break; \ if ((__loglevel & LOG_FLAG_RESTORE) && !((prio) & LOG_FLAG_RESTORE)) \ break; \ - __ilog(prio, fmt, ##__VA_ARGS__); \ + __ilog(prio, "[%s] " fmt, log_level_names[system], ##__VA_ARGS__); \ } while (0) #else -#define ilog(prio, fmt, ...) __ilog(prio, fmt, ##__VA_ARGS__) +#define ilogsn(prio, system, fmt, ...) __ilog(prio, "[%s] " fmt, log_level_names[system], ##__VA_ARGS__) #endif -INLINE int get_log_level(void) { +#define ilog(prio, fmt, ...) ilogs(core, prio, fmt, ##__VA_ARGS__) +#define ilogs(system, prio, fmt, ...) ilogsn(log_level_index_ ## system, prio, fmt, ##__VA_ARGS__) + + +INLINE int __get_log_level(unsigned int idx) { if (!rtpe_common_config_ptr) return 8; - return g_atomic_int_get(&rtpe_common_config_ptr->log_level); + if (idx >= MAX_LOG_LEVELS) + return 8; + return g_atomic_int_get(&rtpe_common_config_ptr->log_levels[idx]); } +#define get_log_level(system) __get_log_level(log_level_index_ ## system) diff --git a/recording-daemon/loglevels.h b/recording-daemon/loglevels.h new file mode 100644 index 000000000..6a11806bc --- /dev/null +++ b/recording-daemon/loglevels.h @@ -0,0 +1,2 @@ +ll(core) +ll(ffmpeg) diff --git a/t/loglevels.h b/t/loglevels.h new file mode 100644 index 000000000..500e0a5ab --- /dev/null +++ b/t/loglevels.h @@ -0,0 +1,12 @@ +ll(core) +ll(spandsp) +ll(ffmpeg) +ll(transcoding) +ll(codec) +ll(rtcp) +ll(ice) +ll(crypto) +ll(srtp) +ll(internals) +ll(http) +ll(control)