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

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);

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) {

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);

daemon/control_ng.c

@@ -398,7 +398,7 @@ send_only:
 
 out:
 	ng_buffer_release(ngbuf);
-	log_info_clear();
+	log_info_pop();
 	return funcret;
 }
 

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;
 }
 

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) {

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);
 }
 

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;

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;
 
 
 

daemon/log_funcs.h

@@ -8,58 +8,90 @@
 #include "ice.h"
 #include "log.h"
 
-INLINE void log_info_clear(void) {
+INLINE void __log_info_release(struct log_info *li) {
-	switch (log_info.e) {
+	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);
 }

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
 

daemon/media_socket.c

@@ -2622,7 +2622,7 @@ strike:
 		redis_update_onekey(ca, rtpe_redis_write);
 	}
 done:
-	log_info_clear();
+	log_info_pop();
 }
 
 

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);

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);
 	}
 

daemon/redis.c

@@ -407,13 +407,11 @@ void on_redis_notification(redisAsyncContext *actx, void *reply, void *privdata)
 	}
 
 err:
-	if (c) {
+	if (c) // because of call_get(..)
-		// 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 {

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;
 

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) {
 }