From 83b1d5e01d5e39464e6895265eeb25fd90750ce7 Mon Sep 17 00:00:00 2001
From: Richard Fuchs <rfuchs@sipwise.com>
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 6d1dfab77a9ead8aa7be018c60c453e32a37bae1)
---
 daemon/call.c         |  4 ++--
 daemon/cli.c          |  2 +-
 daemon/codec.c        | 14 +++++++----
 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, 79 insertions(+), 34 deletions(-)

diff --git a/daemon/call.c b/daemon/call.c
index 686c3caf7..46a5ba525 100644
--- a/daemon/call.c
+++ b/daemon/call.c
@@ -268,7 +268,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) {
@@ -491,7 +491,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 a0f089f16..5fb9a84a7 100644
--- a/daemon/cli.c
+++ b/daemon/cli.c
@@ -1162,7 +1162,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 0a212a734..7afd4fa54 100644
--- a/daemon/codec.c
+++ b/daemon/codec.c
@@ -835,7 +835,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) {
@@ -1214,8 +1214,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)
@@ -1231,7 +1233,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);
@@ -2421,8 +2424,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)
@@ -2430,7 +2435,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)
diff --git a/daemon/control_ng.c b/daemon/control_ng.c
index 67e973ed5..ffa9bb582 100644
--- a/daemon/control_ng.c
+++ b/daemon/control_ng.c
@@ -378,7 +378,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 b59a723fa..e5bf567d4 100644
--- a/daemon/control_tcp.c
+++ b/daemon/control_tcp.c
@@ -110,7 +110,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 f5a66aa29..89881a151 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 faaa9c8ff..49937913a 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 d70660ac4..b844c190c 100644
--- a/daemon/media_socket.c
+++ b/daemon/media_socket.c
@@ -2617,7 +2617,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 2b1a1de32..1e51a24e1 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);
@@ -445,6 +447,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 c2a869d09..62cfc031f 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) {
@@ -1991,7 +1989,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 c80206667..ce3b5c0b7 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) {
@@ -57,6 +58,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) {
 }