core: logging: JSON: add CEE schema support (#2826)

* core: logging: JSON: add CEE schema support

* core: logging: JSON: revise CEE create nested objects

* core: logging: JSON: revise CEE check for pthreads

src/core/dprint.c

@@ -27,6 +27,10 @@
  */
 
 
+#ifdef KSR_PTHREAD_MUTEX_SHARED
+#define HAVE_PTHREAD
+#include <pthread.h>
+#endif
 #include <stdlib.h>
 #include <stdarg.h>
 #include <stdio.h>
@@ -451,6 +455,33 @@ static pv_elem_t *log_prefix_pvs = NULL;
 static char log_prefix_buf[LOG_PREFIX_SIZE];
 static str log_prefix_str = STR_NULL;
 
+void log_init(void)
+{
+	struct addrinfo hints, *info;
+	int gai_result;
+	char hostname[1024];
+
+	hostname[1023] = '\0';
+	gethostname (hostname, 1023);
+
+	memset (&hints, 0, sizeof (hints));
+	hints.ai_family = AF_UNSPEC;    /*either IPV4 or IPV6 */
+	hints.ai_socktype = SOCK_STREAM;
+	hints.ai_flags = AI_CANONNAME;
+
+	if ((gai_result = getaddrinfo (hostname, 0, &hints, &info)) != 0) {
+		log_fqdn = "?";
+	} else if (info == NULL) {
+		log_fqdn = "?";
+	} else {
+		log_fqdn = strdup (info->ai_canonname);
+	}
+
+	freeaddrinfo (info);
+
+	dprint_init_colors();
+}
+
 void log_prefix_init(void)
 {
 	str s;
@@ -611,6 +642,15 @@ static void ksr_slog_json_str_escape(str *s_in, str *s_out, int *emode)
 	" \"" NAME ".line\": %d, \"" NAME ".function\": \"%s\", \"" NAME ".callid\": \"%.*s\", \"" NAME ".logprefix\": \"%.*s\"," \
 	" \"%smessage\": \"%.*s\" }%s"
 
+#ifdef HAVE_PTHREAD
+#define KSR_SLOG_JSON_CEEFMT_TID ",\"tid\":%ju"
+#else
+#define KSR_SLOG_JSON_CEEFMT_TID ""
+#endif
+#define KSR_SLOG_JSON_CEEFMT "{\"time\":\"%s.%09luZ\",\"proc\":{\"id\":\"%d\"" KSR_SLOG_JSON_CEEFMT_TID "},\"pri\":\"%s\",\"subsys\":\"%s\"," \
+        "\"file\":{\"name\":\"%s\",\"line\":%d},\"native\":{\"function\":\"%s\"},\"msg\":\"%s\"," \
+        "\"pname\":\"%s\",\"appname\":\"%s\",\"hostname\":\"%s\"}%s"
+
 void ksr_slog_json(ksr_logdata_t *kld, const char *format, ...)
 {
 	va_list arglist;
@@ -623,6 +663,10 @@ void ksr_slog_json(ksr_logdata_t *kld, const char *format, ...)
 	char *prefmsg;
 	const char *efmt;
 	const char *sfmt;
+#define ISO8601_BUF_SIZE 32
+	char iso8601buf[ISO8601_BUF_SIZE + 1];
+	struct timespec _tp;
+	struct tm _tm;
 
 	va_start(arglist, format);
 	n = vsnprintf(obuf + s_in.len, KSR_SLOG_MAX_SIZE - s_in.len, format, arglist);
@@ -668,7 +712,21 @@ void ksr_slog_json(ksr_logdata_t *kld, const char *format, ...)
 			sfmt = KSR_SLOG_SYSLOG_JSON_FMT;
 		}
 	}
+	ksr_clock_gettime (&_tp);
+	gmtime_r (&_tp.tv_sec, &_tm);
+	strftime (iso8601buf, ISO8601_BUF_SIZE, "%FT%T", &_tm);
 	if (unlikely(log_stderr)) {
+		if (unlikely(log_cee)) {
+			fprintf(stderr, KSR_SLOG_JSON_CEEFMT,
+			iso8601buf, _tp.tv_nsec, my_pid(),
+#ifdef HAVE_PTHREAD
+                        pthread_self(),
+#endif
+                        kld->v_lname,
+			kld->v_mname, kld->v_fname, kld->v_fline, kld->v_func, s_out.s,
+			"kamailio", log_name!=0?log_name:"kamailio", log_fqdn,
+			(_ksr_slog_json_flags & KSR_SLOGJSON_FL_NOLOGNL)?"":"\n");
+		} else {
 		if (unlikely(log_color)) dprint_color(kld->v_level);
 		fprintf(stderr,
 				efmt, process_no, my_pid(),
@@ -677,13 +735,26 @@ void ksr_slog_json(ksr_logdata_t *kld, const char *format, ...)
 				LOGV_PREFIX_LEN, LOGV_PREFIX_STR, prefmsg, s_out.len, s_out.s,
 				(_ksr_slog_json_flags & KSR_SLOGJSON_FL_NOLOGNL)?"":"\n");
 		if (unlikely(log_color)) dprint_color_reset();
+		}
 	} else {
+		if (unlikely(log_cee)) {
+			_km_log_func(kld->v_facility, KSR_SLOG_JSON_CEEFMT,
+			iso8601buf, _tp.tv_nsec, my_pid(),
+#ifdef HAVE_PTHREAD
+                        pthread_self(),
+#endif
+                        kld->v_lname,
+			kld->v_mname, kld->v_fname, kld->v_fline, kld->v_func, s_out.s,
+			"kamailio", log_name!=0?log_name:"kamailio", log_fqdn,
+			(_ksr_slog_json_flags & KSR_SLOGJSON_FL_NOLOGNL)?"":"\n");
+		} else {
 		_km_log_func(kld->v_facility,
 				sfmt,
 				kld->v_lname, kld->v_mname, kld->v_fname, kld->v_fline,
 				kld->v_func, LOGV_CALLID_LEN, LOGV_CALLID_STR,
 				LOGV_PREFIX_LEN, LOGV_PREFIX_STR, prefmsg, s_out.len, s_out.s,
 				(_ksr_slog_json_flags & KSR_SLOGJSON_FL_NOLOGNL)?"":"\n");
+		}
 	}
 	if(emode && s_out.s) {
 		free(s_out.s);
@@ -731,6 +802,9 @@ void ksr_slog_init(char *ename)
 					case 'c':
 						_ksr_slog_json_flags |= KSR_SLOGJSON_FL_CALLID;
 					break;
+					case 'U':
+						log_cee = 1;
+					break;
 				}
 				p++;
 			}

src/core/dprint.h

@@ -138,6 +138,7 @@ extern int my_pid(void);
 extern int log_stderr;
 
 extern int log_color;
+extern int log_cee;
 extern char *log_prefix_fmt;
 extern str *log_prefix_val;
 extern int log_prefix_mode;
@@ -172,6 +173,7 @@ void set_module_debug_facility_cb(get_module_debug_facility_f f);
 #define is_printable(level) (get_debug_level(LOG_MNAME, LOG_MNAME_LEN)>=(level))
 extern struct log_level_info log_level_info[];
 extern char *log_name;
+extern char *log_fqdn;
 
 #ifndef NO_SIG_DEBUG
 /** @brief protection against "simultaneous" printing from signal handlers */
@@ -189,6 +191,7 @@ void dprint_color_update(int level, char f, char b);
 void dprint_init_colors(void);
 void dprint_term_color(char f, char b, str *obuf);
 
+void log_init(void);
 void log_prefix_init(void);
 
 #define LOGV_PREFIX_STR ((log_prefix_val)?log_prefix_val->s:"")

src/main.c

@@ -342,9 +342,11 @@ int dont_fork = 0;
 int dont_daemonize = 0;
 int log_stderr = 0;
 int log_color = 0;
+int log_cee = 0;
 /* set custom app name for syslog printing */
 char *log_name = 0;
 char *log_prefix_fmt = 0;
+char *log_fqdn = 0;
 pid_t creator_pid = (pid_t) -1;
 int config_check = 0;
 /* check if reply first via host==us */
@@ -2039,7 +2041,7 @@ int main(int argc, char** argv)
 	sr_cfgenv_init();
 	daemon_status_init();
 
-	dprint_init_colors();
+	log_init();
 
 	/* command line options */
 	options=  ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:";