From e17c1aca82cccd2fe47493e0779ac1ce3f78bacd Mon Sep 17 00:00:00 2001 From: Richard Fuchs Date: Fri, 4 Feb 2022 10:29:48 -0500 Subject: [PATCH] TT#14008 convert logging context to stack This is useful for functions which are used both from a timer and from other callers. These functions would reset the logging context at their end to free the reference held by the logging context, which would wrongly reset the logging context when the same function was called from a different code path. Using a stack with push/pop semantics makes it safe to use these functions from any code path. Additionally introduce an explicit reset function that clears the entire stack regardless of context. This reset function is called at the end of every work iteration in every worker thread, just in case not everything was popped from the stack. Change-Id: I0e2c142b95806b26473c65a882737e39d161d24d (cherry picked from commit bb26e4b522037e6afffeab7ed2eedb9abb6abda1) --- daemon/call.c | 4 ++-- daemon/cli.c | 2 +- daemon/codec.c | 19 ++++++++------- daemon/control_ng.c | 2 +- daemon/control_tcp.c | 2 +- daemon/control_udp.c | 2 +- daemon/ice.c | 2 +- daemon/log.c | 1 + daemon/log.h | 1 + daemon/log_funcs.h | 56 +++++++++++++++++++++++++++++++++---------- daemon/media_player.c | 6 ++--- daemon/media_socket.c | 2 +- daemon/mqtt.c | 1 + daemon/poller.c | 3 +++ daemon/redis.c | 8 +++---- daemon/timerthread.c | 3 +++ t/log_funcs.h | 4 +++- 17 files changed, 81 insertions(+), 37 deletions(-) diff --git a/daemon/call.c b/daemon/call.c index c18c7f795..159383e92 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -266,7 +266,7 @@ delete: out: rwlock_unlock_r(&rtpe_config.config_lock); rwlock_unlock_r(&c->master_lock); - log_info_clear(); + log_info_pop(); } void xmlrpc_kill_calls(void *p) { @@ -489,7 +489,7 @@ destroy: call_destroy(ca); obj_put(ca); list = g_slist_delete_link(list, list); - log_info_clear(); + log_info_pop(); if (dup_tags) g_hash_table_destroy(dup_tags); diff --git a/daemon/cli.c b/daemon/cli.c index 422043def..c67808958 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -1237,7 +1237,7 @@ static void cli_stream_readable(struct streambuf_stream *s) { free(inbuf); streambuf_stream_shutdown(s); - log_info_clear(); + log_info_reset(); } void cli_handle(str *instr, struct cli_writer *cw) { diff --git a/daemon/codec.c b/daemon/codec.c index 3f2920135..814e6fa5d 100644 --- a/daemon/codec.c +++ b/daemon/codec.c @@ -922,7 +922,7 @@ static void __rtcp_timer_run(struct codec_timer *ct) { } out: - log_info_clear(); + log_info_pop(); } // master lock held in W static void __codec_rtcp_timer(struct call_media *receiver) { @@ -1358,8 +1358,10 @@ static void __mqtt_timer_run(struct codec_timer *ct) { struct mqtt_timer *mqt = (struct mqtt_timer *) ct; struct call *call = mqt->call; - if (call) + if (call) { rwlock_lock_w(&call->master_lock); + log_info_call(call); + } if (!*mqt->self) { if (call) @@ -1375,7 +1377,8 @@ static void __mqtt_timer_run(struct codec_timer *ct) { mqtt_timer_run(call, mqt->media); out: - log_info_clear(); + if (call) + log_info_pop(); } static void __codec_mqtt_timer_schedule(struct mqtt_timer *mqt) { timeval_add_usec(&mqt->ct.next, rtpe_config.mqtt_publish_interval * 1000); @@ -2732,11 +2735,10 @@ out: if (call) { rwlock_unlock_r(&call->master_lock); obj_put(call); + log_info_pop(); } if (dframe) delay_frame_free(dframe); - - log_info_clear(); } @@ -3041,8 +3043,10 @@ static void __dtx_send_later(struct codec_timer *ct) { rwlock_unlock_r(&call->master_lock); out: - if (call) + if (call) { obj_put(call); + log_info_pop(); + } if (ch) obj_put(&ch->h); if (input_ch) @@ -3050,7 +3054,6 @@ out: if (dtxp) dtx_packet_free(dtxp); media_packet_release(&mp_copy); - log_info_clear(); } static void __dtx_shutdown(struct dtx_buffer *dtxb) { if (dtxb->csh) @@ -4768,7 +4771,7 @@ static void __codec_timer_callback_fire(struct codec_timer *ct) { log_info_call(cb->call); cb->func(cb->call, cb->ptr); codec_timer_stop(&ct); - log_info_clear(); + log_info_pop(); } void codec_timer_callback(struct call *c, void (*func)(struct call *, void *), void *p, uint64_t delay) { struct timer_callback *cb = obj_alloc0("codec_timer_callback", sizeof(*cb), __codec_timer_callback_free); diff --git a/daemon/control_ng.c b/daemon/control_ng.c index 9fa31f0ac..6d3c02b2e 100644 --- a/daemon/control_ng.c +++ b/daemon/control_ng.c @@ -398,7 +398,7 @@ send_only: out: ng_buffer_release(ngbuf); - log_info_clear(); + log_info_pop(); return funcret; } diff --git a/daemon/control_tcp.c b/daemon/control_tcp.c index f7513d1eb..9c50bb46e 100644 --- a/daemon/control_tcp.c +++ b/daemon/control_tcp.c @@ -108,7 +108,7 @@ static int control_stream_parse(struct streambuf_stream *s, char *line) { } pcre_free(out); - log_info_clear(); + log_info_pop(); return 1; } diff --git a/daemon/control_udp.c b/daemon/control_udp.c index e4e33c16c..a48fb7fc6 100644 --- a/daemon/control_udp.c +++ b/daemon/control_udp.c @@ -130,7 +130,7 @@ static void control_udp_incoming(struct obj *obj, struct udp_buffer *udp_buf) { out: pcre_free(out); - log_info_clear(); + log_info_pop(); } void control_udp_free(void *p) { diff --git a/daemon/ice.c b/daemon/ice.c index d538ffe4b..5f81efa81 100644 --- a/daemon/ice.c +++ b/daemon/ice.c @@ -1322,7 +1322,7 @@ static void ice_agents_timer_run(void *ptr) { __do_ice_checks(ag); /* finally, release our reference and start over */ - log_info_clear(); + log_info_pop(); rwlock_unlock_r(&call->master_lock); } diff --git a/daemon/log.c b/daemon/log.c index 8e0cac068..9667591d3 100644 --- a/daemon/log.c +++ b/daemon/log.c @@ -14,6 +14,7 @@ __thread struct log_info log_info; +__thread GSList *log_info_stack; int _log_facility_cdr = 0; int _log_facility_rtcp = 0; diff --git a/daemon/log.h b/daemon/log.h index 376d27eb7..5f9d5263a 100644 --- a/daemon/log.h +++ b/daemon/log.h @@ -37,6 +37,7 @@ extern int _log_facility_dtmf; extern __thread struct log_info log_info; +extern __thread GSList *log_info_stack; diff --git a/daemon/log_funcs.h b/daemon/log_funcs.h index cfea369e1..3d8992e28 100644 --- a/daemon/log_funcs.h +++ b/daemon/log_funcs.h @@ -8,58 +8,90 @@ #include "ice.h" #include "log.h" -INLINE void log_info_clear(void) { - switch (log_info.e) { +INLINE void __log_info_release(struct log_info *li) { + switch (li->e) { case LOG_INFO_NONE: return; case LOG_INFO_CALL: - obj_put(log_info.u.call); + obj_put(li->u.call); break; case LOG_INFO_STREAM_FD: - obj_put(log_info.u.stream_fd); + obj_put(li->u.stream_fd); break; case LOG_INFO_ICE_AGENT: - obj_put(&log_info.u.ice_agent->tt_obj); + obj_put(&li->u.ice_agent->tt_obj); break; case LOG_INFO_STR: case LOG_INFO_C_STRING: break; } - log_info.e = LOG_INFO_NONE; - log_info.u.ptr = NULL; } +INLINE void __log_info_push(void) { + struct log_info *copy = g_slice_alloc(sizeof(*copy)); + *copy = log_info; + log_info_stack = g_slist_prepend(log_info_stack, copy); + ZERO(log_info); +} + +// should be paired with any invocation of log_info_X() +INLINE void log_info_pop(void) { + __log_info_release(&log_info); + + if (!log_info_stack) { + ZERO(log_info); + return; + } + + struct log_info *next = log_info_stack->data; + log_info = *next; + g_slice_free1(sizeof(*next), next); + log_info_stack = g_slist_delete_link(log_info_stack, log_info_stack); +} +// clears current log context and entire stack +INLINE void log_info_reset(void) { + __log_info_release(&log_info); + ZERO(log_info); + + while (log_info_stack) { + struct log_info *element = log_info_stack->data; + __log_info_release(element); + g_slice_free1(sizeof(*element), element); + log_info_stack = g_slist_delete_link(log_info_stack, log_info_stack); + } +} + INLINE void log_info_call(struct call *c) { - log_info_clear(); if (!c) return; + __log_info_push(); log_info.e = LOG_INFO_CALL; log_info.u.call = obj_get(c); } INLINE void log_info_stream_fd(struct stream_fd *sfd) { - log_info_clear(); if (!sfd) return; + __log_info_push(); log_info.e = LOG_INFO_STREAM_FD; log_info.u.stream_fd = obj_get(sfd); } INLINE void log_info_str(const str *s) { - log_info_clear(); if (!s || !s->s) return; + __log_info_push(); log_info.e = LOG_INFO_STR; log_info.u.str = s; } INLINE void log_info_c_string(const char *s) { - log_info_clear(); if (!s) return; + __log_info_push(); log_info.e = LOG_INFO_C_STRING; log_info.u.cstr = s; } INLINE void log_info_ice_agent(struct ice_agent *ag) { - log_info_clear(); if (!ag) return; + __log_info_push(); log_info.e = LOG_INFO_ICE_AGENT; log_info.u.ice_agent = obj_get(&ag->tt_obj); } diff --git a/daemon/media_player.c b/daemon/media_player.c index 81b9d5596..251d175bb 100644 --- a/daemon/media_player.c +++ b/daemon/media_player.c @@ -236,7 +236,7 @@ static void send_timer_send_lock(struct send_timer *st, struct codec_packet *cp) __send_timer_send_common(st, cp); rwlock_unlock_r(&call->master_lock); - log_info_clear(); + log_info_pop(); } // st->stream->out_lock (or call->master_lock/W) must be held already @@ -249,7 +249,7 @@ static void send_timer_send_nolock(struct send_timer *st, struct codec_packet *c __send_timer_send_common(st, cp); - log_info_clear(); + log_info_pop(); } @@ -737,7 +737,7 @@ static void media_player_run(void *ptr) { mutex_unlock(&mp->lock); rwlock_unlock_r(&call->master_lock); - log_info_clear(); + log_info_pop(); } #endif diff --git a/daemon/media_socket.c b/daemon/media_socket.c index 4496b231e..edf1e40c3 100644 --- a/daemon/media_socket.c +++ b/daemon/media_socket.c @@ -2622,7 +2622,7 @@ strike: redis_update_onekey(ca, rtpe_redis_write); } done: - log_info_clear(); + log_info_pop(); } diff --git a/daemon/mqtt.c b/daemon/mqtt.c index 0d4c32666..8e310c9b5 100644 --- a/daemon/mqtt.c +++ b/daemon/mqtt.c @@ -458,6 +458,7 @@ void mqtt_timer_run(struct call *call, struct call_media *media) { mqtt_media_stats(media, json); rwlock_unlock_r(&call->master_lock); + log_info_pop(); } json_builder_end_object(json); diff --git a/daemon/poller.c b/daemon/poller.c index 8702e9dd4..c717707fa 100644 --- a/daemon/poller.c +++ b/daemon/poller.c @@ -19,6 +19,7 @@ #include "aux.h" #include "obj.h" +#include "log_funcs.h" @@ -365,6 +366,7 @@ static void poller_timers_run(struct poller *p) { for (l = p->timers; l; l = l->next) { ti = l->data; ti->func(ti->obj_ptr); + log_info_reset(); } mutex_lock(&p->timers_add_del_lock); @@ -443,6 +445,7 @@ int poller_poll(struct poller *p, int timeout) { next: obj_put(it); + log_info_reset(); mutex_lock(&p->lock); } diff --git a/daemon/redis.c b/daemon/redis.c index 96ba95535..77d9aedf5 100644 --- a/daemon/redis.c +++ b/daemon/redis.c @@ -407,13 +407,11 @@ void on_redis_notification(redisAsyncContext *actx, void *reply, void *privdata) } err: - if (c) { - // because of call_get(..) + if (c) // because of call_get(..) obj_put(c); - log_info_clear(); - } mutex_unlock(&r->lock); + log_info_reset(); } void redis_delete_async_context_connect(const redisAsyncContext *redis_delete_async_context, int status) { @@ -2000,7 +1998,7 @@ err1: } if (c) obj_put(c); - log_info_clear(); + log_info_reset(); } struct thread_ctx { diff --git a/daemon/timerthread.c b/daemon/timerthread.c index bc8fc4c4e..28d837383 100644 --- a/daemon/timerthread.c +++ b/daemon/timerthread.c @@ -1,5 +1,6 @@ #include "timerthread.h" #include "aux.h" +#include "log_funcs.h" static int tt_obj_cmp(const void *a, const void *b) { @@ -61,6 +62,8 @@ void timerthread_run(void *p) { tt->func(tt_obj); obj_put(tt_obj); + log_info_reset(); + mutex_lock(&tt->lock); continue; diff --git a/t/log_funcs.h b/t/log_funcs.h index fdb0048b3..5ce34a8a1 100644 --- a/t/log_funcs.h +++ b/t/log_funcs.h @@ -8,7 +8,9 @@ struct call; struct stream_fd; struct ice_agent; -INLINE void log_info_clear(void) { +INLINE void log_info_reset(void) { +} +INLINE void log_info_pop(void) { } INLINE void log_info_call(struct call *c) { }