TT#30150 add option for different logging styles

closes #442

Change-Id: I338afc58e10b056718e086dbcd232f3324984bf0

README.md

@@ -189,6 +189,7 @@ option and which are reproduced below:
 	  --log-facility=daemon|local0|... Syslog facility to use for logging
 	  --log-facility-cdr=local0|...    Syslog facility to use for logging CDRs
 	  --log-facility-rtcp=local0|...   Syslog facility to use for logging RTCP data (take care of traffic amount)
+	  --log-format=default|parsable    Log prefix format
 	  -E, --log-stderr                 Log on stderr instead of syslog
 	  -x, --xmlrpc-format=INT          XMLRPC timeout request format to use. 0: SEMS DI, 1: call-id only
 	  --num-threads=INT                Number of worker threads to create
@@ -345,6 +346,13 @@ The options are described in more detail below.
 	Same as --log-facility with the difference that only RTCP data is written to this log facility.
 	Be careful with this parameter since there may be a lot of information written to it.
 
+* --log-format=default|parsable
+
+	Selects between multiple log output styles. The default is to prefix log lines with a description
+	of the relevant entity, such as `[CALLID]` or `[CALLID port 12345]`. The `parsable` output style
+	is similar, but makes the ID easier to parse by enclosing it in quotes, such as `[ID="CALLID"]`
+	or `[ID="CALLID" port="12345"]`.
+
 * -E, --log-stderr
 
 	Log to stderr instead of syslog. Only useful in combination with `--foreground`.

daemon/log.c

@@ -8,6 +8,7 @@
 #include "poller.h"
 #include "ice.h"
 #include "loglib.h"
+#include "main.h"
 
 
 
@@ -17,46 +18,101 @@ struct log_info __thread log_info;
 int _log_facility_cdr = 0;
 int _log_facility_rtcp = 0;
 
+typedef void (ilog_prefix_func)(char *prefix, size_t prefix_len);
 
+static ilog_prefix_func ilog_prefix_default;
+static ilog_prefix_func ilog_prefix_parsable;
+
+static ilog_prefix_func *ilog_prefix = ilog_prefix_default;
+
+static ilog_prefix_func * const ilog_prefix_funcs[__LF_LAST] = {
+	[LF_DEFAULT] = ilog_prefix_default,
+	[LF_PARSABLE] = ilog_prefix_parsable,
+};
 
-void __ilog(int prio, const char *fmt, ...) {
-	char prefix[300];
-	va_list ap;
 
+
+static void ilog_prefix_default(char *prefix, size_t prefix_len) {
 	switch (log_info.e) {
 		case LOG_INFO_NONE:
 			prefix[0] = 0;
 			break;
 		case LOG_INFO_CALL:
-			snprintf(prefix, sizeof(prefix), "["STR_FORMAT"]: ",
+			snprintf(prefix, prefix_len, "["STR_FORMAT"]: ",
 					STR_FMT(&log_info.u.call->callid));
 			break;
 		case LOG_INFO_STREAM_FD:
 			if (log_info.u.stream_fd->call)
-				snprintf(prefix, sizeof(prefix), "["STR_FORMAT" port %5u]: ",
+				snprintf(prefix, prefix_len, "["STR_FORMAT" port %5u]: ",
 						STR_FMT(&log_info.u.stream_fd->call->callid),
 						log_info.u.stream_fd->socket.local.port);
 			break;
 		case LOG_INFO_STR:
-			snprintf(prefix, sizeof(prefix), "["STR_FORMAT"]: ",
+			snprintf(prefix, prefix_len, "["STR_FORMAT"]: ",
 					STR_FMT(log_info.u.str));
 			break;
 		case LOG_INFO_C_STRING:
-			snprintf(prefix, sizeof(prefix), "[%s]: ", log_info.u.cstr);
+			snprintf(prefix, prefix_len, "[%s]: ", log_info.u.cstr);
 			break;
 		case LOG_INFO_ICE_AGENT:
-			snprintf(prefix, sizeof(prefix), "["STR_FORMAT"/"STR_FORMAT"/%u]: ",
+			snprintf(prefix, prefix_len, "["STR_FORMAT"/"STR_FORMAT"/%u]: ",
 					STR_FMT(&log_info.u.ice_agent->call->callid),
 					STR_FMT(&log_info.u.ice_agent->media->monologue->tag),
 					log_info.u.ice_agent->media->index);
 			break;
 	}
+}
+
+static void ilog_prefix_parsable(char *prefix, size_t prefix_len) {
+	switch (log_info.e) {
+		case LOG_INFO_NONE:
+			prefix[0] = 0;
+			break;
+		case LOG_INFO_CALL:
+			snprintf(prefix, prefix_len, "[ID=\""STR_FORMAT"\"]: ",
+					STR_FMT(&log_info.u.call->callid));
+			break;
+		case LOG_INFO_STREAM_FD:
+			if (log_info.u.stream_fd->call)
+				snprintf(prefix, prefix_len, "[ID=\""STR_FORMAT"\" port=\"%5u\"]: ",
+						STR_FMT(&log_info.u.stream_fd->call->callid),
+						log_info.u.stream_fd->socket.local.port);
+			break;
+		case LOG_INFO_STR:
+			snprintf(prefix, prefix_len, "[ID=\""STR_FORMAT"\"]: ",
+					STR_FMT(log_info.u.str));
+			break;
+		case LOG_INFO_C_STRING:
+			snprintf(prefix, prefix_len, "[ID=\"%s\"]: ", log_info.u.cstr);
+			break;
+		case LOG_INFO_ICE_AGENT:
+			snprintf(prefix, prefix_len, "[ID=\""STR_FORMAT"\" tag=\""STR_FORMAT"\" index=\"%u\"]: ",
+					STR_FMT(&log_info.u.ice_agent->call->callid),
+					STR_FMT(&log_info.u.ice_agent->media->monologue->tag),
+					log_info.u.ice_agent->media->index);
+			break;
+	}
+}
+
+void __ilog(int prio, const char *fmt, ...) {
+	char prefix[300];
+	va_list ap;
+
+	ilog_prefix(prefix, sizeof(prefix));
 
 	va_start(ap, fmt);
 	__vpilog(prio, prefix, fmt, ap);
 	va_end(ap);
 }
 
+void log_format(enum log_format f) {
+	if (f < 0 || f >= __LF_LAST)
+		die("Invalid log format enum");
+	ilog_prefix = ilog_prefix_funcs[f];
+	if (!ilog_prefix)
+		die("Invalid log format enum");
+}
+
 void cdrlog(const char* cdrbuffer) {
 	if (_log_facility_cdr) {
 		syslog(LOG_INFO | _log_facility_cdr, "%s", cdrbuffer);

daemon/log.h

@@ -10,6 +10,7 @@
 struct call;
 struct stream_fd;
 struct ice_agent;
+enum log_format;
 
 struct log_info {
 	union {
@@ -42,6 +43,7 @@ void cdrlog(const char* cdrbuffer);
 void rtcplog(const char* cdrbuffer);
 
 
+void log_format(enum log_format);
 void __ilog(int prio, const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
 
 

daemon/main.c

@@ -238,6 +238,7 @@ static void options(int *argc, char ***argv) {
 	char *redisps_write = NULL;
 	char *log_facility_cdr_s = NULL;
 	char *log_facility_rtcp_s = NULL;
+	char *log_format = NULL;
 	int sip_source = 0;
 	char *homerp = NULL;
 	char *homerproto = NULL;
@@ -270,6 +271,7 @@ static void options(int *argc, char ***argv) {
 		{ "b2b-url",	'b', 0, G_OPTION_ARG_STRING,	&rtpe_config.b2b_url,	"XMLRPC URL of B2B UA"	,	"STRING"	},
 		{ "log-facility-cdr",0,  0, G_OPTION_ARG_STRING, &log_facility_cdr_s, "Syslog facility to use for logging CDRs", "daemon|local0|...|local7"},
 		{ "log-facility-rtcp",0,  0, G_OPTION_ARG_STRING, &log_facility_rtcp_s, "Syslog facility to use for logging RTCP", "daemon|local0|...|local7"},
+		{ "log-format",	0, 0,	G_OPTION_ARG_STRING,	&log_format,	"Log prefix format",		"default|parsable"},
 		{ "xmlrpc-format",'x', 0, G_OPTION_ARG_INT,	&rtpe_config.fmt,	"XMLRPC timeout request format to use. 0: SEMS DI, 1: call-id only",	"INT"	},
 		{ "num-threads",  0, 0, G_OPTION_ARG_INT,	&rtpe_config.num_threads,	"Number of worker threads to create",	"INT"	},
 		{ "delete-delay",  'd', 0, G_OPTION_ARG_INT,    &rtpe_config.delete_delay,  "Delay for deleting a session from memory.",    "INT"   },
@@ -398,6 +400,15 @@ static void options(int *argc, char ***argv) {
 		}
 	}
 
+	if (log_format) {
+		if (!strcmp(log_format, "default"))
+			rtpe_config.log_format = LF_DEFAULT;
+		else if (!strcmp(log_format, "parsable"))
+			rtpe_config.log_format = LF_PARSABLE;
+		else
+			die("Invalid --log-format option");
+	}
+
 	if (!sip_source)
 		trust_address_def = 1;
 }
@@ -449,6 +460,7 @@ static void init_everything() {
 	struct timespec ts;
 
 	log_init("rtpengine");
+	log_format(rtpe_config.log_format);
 	recording_fs_init(rtpe_config.spooldir, rtpe_config.rec_method, rtpe_config.rec_format);
 	clock_gettime(CLOCK_REALTIME, &ts);
 	srandom(ts.tv_sec ^ ts.tv_nsec);

daemon/main.h

@@ -11,6 +11,12 @@ enum xmlrpc_format {
 	XF_SEMS = 0,
 	XF_CALLID,
 };
+enum log_format {
+	LF_DEFAULT = 0,
+	LF_PARSABLE,
+
+	__LF_LAST
+};
 
 struct rtpengine_config {
 	/* everything below protected by config_lock */
@@ -30,6 +36,7 @@ struct rtpengine_config {
 	int			default_tos;
 	int			control_tos;
 	enum xmlrpc_format	fmt;
+	enum log_format		log_format;
 	endpoint_t		graphite_ep;
 	int			graphite_interval;
 	int			redis_num_threads;