FS-6805 add support for logging full timestamps with dialplan, defaults to old behavior unless requested

conf/curl/autoload_configs/switch.conf.xml

@@ -18,6 +18,8 @@
   <settings>
     <!--Colorize the Console -->
     <param name="colorize-console" value="true"/>
+    <!--Include full timestamps in dialplan logs -->
+    <param name="dialplan-timestamps" value="false"/>
     <!--Most channels to allow at once -->
     <param name="max-sessions" value="1000"/>
     <!--Most channels to create per second -->

conf/insideout/autoload_configs/switch.conf.xml

@@ -18,6 +18,8 @@
   <settings>
     <!--Colorize the Console -->
     <param name="colorize-console" value="true"/>
+    <!--Include full timestamps in dialplan logs -->
+    <param name="dialplan-timestamps" value="false"/>
     <!--Most channels to allow at once -->
     <param name="max-sessions" value="1000"/>
     <!--Most channels to create per second -->

conf/rayo/autoload_configs/switch.conf.xml

@@ -24,6 +24,9 @@
     <!-- Colorize the Console -->
     <param name="colorize-console" value="true"/>
 
+    <!--Include full timestamps in dialplan logs -->
+    <param name="dialplan-timestamps" value="false"/>
+
     <!-- Run the timer at 20ms by default and drop down as needed unless you set 1m-timer=true which was previous default -->
     <!-- <param name="1ms-timer" value="true"/> -->
 

conf/sbc/autoload_configs/switch.conf.xml

@@ -18,6 +18,8 @@
   <settings>
     <!--Colorize the Console -->
     <param name="colorize-console" value="true"/>
+    <!--Include full timestamps in dialplan logs -->
+    <param name="dialplan-timestamps" value="false"/>
     <!--Most channels to allow at once -->
     <param name="max-sessions" value="1000"/>
     <!--Most channels to create per second -->

conf/vanilla/autoload_configs/switch.conf.xml

@@ -24,6 +24,9 @@
     <!-- Colorize the Console -->
     <param name="colorize-console" value="true"/>
 
+    <!--Include full timestamps in dialplan logs -->
+    <param name="dialplan-timestamps" value="false"/>
+
     <!-- Run the timer at 20ms by default and drop down as needed unless you set 1m-timer=true which was previous default -->
     <!-- <param name="1ms-timer" value="true"/> -->
 

src/include/switch_types.h

@@ -361,7 +361,8 @@ typedef enum {
 	SCF_CORE_NON_SQLITE_DB_REQ = (1 << 20),
 	SCF_DEBUG_SQL = (1 << 21),
 	SCF_API_EXPANSION = (1 << 22),
-	SCF_SESSION_THREAD_POOL = (1 << 23)
+	SCF_SESSION_THREAD_POOL = (1 << 23),
+	SCF_DIALPLAN_TIMESTAMPS = (1 << 24)
 } switch_core_flag_enum_t;
 typedef uint32_t switch_core_flag_t;
 

src/mod/dialplans/mod_dialplan_xml/mod_dialplan_xml.c

@@ -148,10 +148,15 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 			req_nest = switch_true(req_nesta);
 		}
 
+		if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+			switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, 
+						  "%sDialplan: Processing recursive conditions level:%d [%s] require-nested=%s\n", space,
+						  recur, exten_name, req_nest ? "TRUE" : "FALSE");
+		} else {
 			switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG, 
 						  "%sDialplan: Processing recursive conditions level:%d [%s] require-nested=%s\n", space,
 						  recur, exten_name, req_nest ? "TRUE" : "FALSE");
-
+		}
 	} else {
 		if ((tmp = switch_xml_attr(xexten, "name"))) {
 			exten_name = tmp;
@@ -204,16 +209,28 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 		}
 		
 		if (time_match == 1) {
+			if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+				switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+							  "%sDialplan: %s Date/Time Match (PASS) [%s] break=%s\n", space,
+							  switch_channel_get_name(channel), exten_name, do_break_a ? do_break_a : "on-false");
+			} else {
 				switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 							  "%sDialplan: %s Date/Time Match (PASS) [%s] break=%s\n", space,
 							  switch_channel_get_name(channel), exten_name, do_break_a ? do_break_a : "on-false");
+			}
 			anti_action = SWITCH_FALSE;
 			proceed = 1;
 		} else if (time_match == 0) {
+			if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+				switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+							  "%sDialplan: %s Date/TimeMatch (FAIL) [%s] break=%s\n", space,
+							  switch_channel_get_name(channel), exten_name, do_break_a ? do_break_a : "on-false");
+			} else {
 				switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 							  "%sDialplan: %s Date/TimeMatch (FAIL) [%s] break=%s\n", space,
 							  switch_channel_get_name(channel), exten_name, do_break_a ? do_break_a : "on-false");
 			}
+		}
 		
 		
 		if ((regex_rule = (char *) switch_xml_attr(xcond, "regex"))) {
@@ -230,15 +247,27 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 				time_match = switch_xml_std_datetime_check(xregex, tzoff ? &offset : NULL, tzname_);
 				
 				if (time_match == 1) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Date/Time Match (PASS) [%s]\n", space,
+									  switch_channel_get_name(channel), exten_name);
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Date/Time Match (PASS) [%s]\n", space,
 									  switch_channel_get_name(channel), exten_name);
+					}
 					anti_action = SWITCH_FALSE;
 				} else if (time_match == 0) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Date/TimeMatch (FAIL) [%s]\n", space,
+									  switch_channel_get_name(channel), exten_name);
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Date/TimeMatch (FAIL) [%s]\n", space,
 									  switch_channel_get_name(channel), exten_name);
 					}
+				}
 
 
 				if ((xexpression = switch_xml_child(xregex, "expression"))) {
@@ -273,22 +302,40 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 					}
 					
 					if ((proceed = switch_regex_perform(field_data, expression, &re, ovector, sizeof(ovector) / sizeof(ovector[0])))) {
+						if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+							switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+										  "%sDialplan: %s Regex (PASS) [%s] %s(%s) =~ /%s/ match=%s\n", space,
+										  switch_channel_get_name(channel), exten_name, field, field_data, expression, all ? "all" : "any");
+						} else {
 							switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 										  "%sDialplan: %s Regex (PASS) [%s] %s(%s) =~ /%s/ match=%s\n", space,
 										  switch_channel_get_name(channel), exten_name, field, field_data, expression, all ? "all" : "any");
+						}
 						pass++;
 						if (!all && !xor) break;
+					} else {
+						if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+							switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+										  "%sDialplan: %s Regex (FAIL) [%s] %s(%s) =~ /%s/ match=%s\n", space,
+										  switch_channel_get_name(channel), exten_name, field, field_data, expression, all ? "all" : "any");
 						} else {
 							switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 										  "%sDialplan: %s Regex (FAIL) [%s] %s(%s) =~ /%s/ match=%s\n", space,
 										  switch_channel_get_name(channel), exten_name, field, field_data, expression, all ? "all" : "any");
+						}
 						fail++;
 						if (all && !xor) break;
 					}
 				} else if (time_match == -1) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Absolute Condition [%s] match=%s\n", space,
+									  switch_channel_get_name(channel), exten_name, all ? "all" : "any");
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Absolute Condition [%s] match=%s\n", space,
 									  switch_channel_get_name(channel), exten_name, all ? "all" : "any");
+					}
 					pass++;
 					proceed = 1;
 					if (!all && !xor) break;
@@ -367,19 +414,37 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 				}
 
 				if ((proceed = switch_regex_perform(field_data, expression, &re, ovector, sizeof(ovector) / sizeof(ovector[0])))) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Regex (PASS) [%s] %s(%s) =~ /%s/ break=%s\n", space,
+									  switch_channel_get_name(channel), exten_name, field, field_data, expression, do_break_a ? do_break_a : "on-false");
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Regex (PASS) [%s] %s(%s) =~ /%s/ break=%s\n", space,
 									  switch_channel_get_name(channel), exten_name, field, field_data, expression, do_break_a ? do_break_a : "on-false");
+					}
 					anti_action = SWITCH_FALSE;
+				} else {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Regex (FAIL) [%s] %s(%s) =~ /%s/ break=%s\n", space,
+									  switch_channel_get_name(channel), exten_name, field, field_data, expression, do_break_a ? do_break_a : "on-false");
 					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Regex (FAIL) [%s] %s(%s) =~ /%s/ break=%s\n", space,
 									  switch_channel_get_name(channel), exten_name, field, field_data, expression, do_break_a ? do_break_a : "on-false");
 					}
+				}
 			} else if (time_match == -1) {
+				if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+					switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+								  "%sDialplan: %s Absolute Condition [%s]\n", space,
+								  switch_channel_get_name(channel), exten_name);
+				} else {
 					switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 								  "%sDialplan: %s Absolute Condition [%s]\n", space,
 								  switch_channel_get_name(channel), exten_name);
+				}
 				anti_action = SWITCH_FALSE;
 				proceed = 1;
 			}
@@ -427,9 +492,15 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 				}
 
 				for (;loop_count > 0; loop_count--) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s ANTI-Action %s(%s) %s\n", space,
+									  switch_channel_get_name(channel), application, data, xinline ? "INLINE" : "");
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s ANTI-Action %s(%s) %s\n", space,
 									  switch_channel_get_name(channel), application, data, xinline ? "INLINE" : "");
+					}
 
 					if (xinline) {
 						exec_app(session, application, data);
@@ -488,9 +559,15 @@ static int parse_exten(switch_core_session_t *session, switch_caller_profile_t *
 					loop_count = atoi(loop);
 				}
 				for (;loop_count > 0; loop_count--) {
+					if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+									  "%sDialplan: %s Action %s(%s) %s\n", space,
+									  switch_channel_get_name(channel), application, app_data, xinline ? "INLINE" : "");
+					} else {
 						switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 									  "%sDialplan: %s Action %s(%s) %s\n", space,
 									  switch_channel_get_name(channel), application, app_data, xinline ? "INLINE" : "");
+					}
 
 					if (xinline) {
 						exec_app(session, application, app_data);
@@ -607,9 +684,15 @@ SWITCH_STANDARD_DIALPLAN(dialplan_hunt)
 			exten_name = "UNKNOWN";
 		}
 
+		if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+			switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG,
+						  "Dialplan: %s parsing [%s->%s] continue=%s\n",
+						  switch_channel_get_name(channel), caller_profile->context, exten_name, cont ? cont : "false");
+		} else {
 			switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG,
 						  "Dialplan: %s parsing [%s->%s] continue=%s\n",
 						  switch_channel_get_name(channel), caller_profile->context, exten_name, cont ? cont : "false");
+		}
 
 		proceed = parse_exten(session, caller_profile, xexten, &extension, exten_name, 0);
 

src/switch_core.c

@@ -1980,6 +1980,12 @@ static void switch_load_core_config(const char *file)
 					runtime.core_db_inner_pre_trans_execute = switch_core_strdup(runtime.memory_pool, val);
 				} else if (!strcasecmp(var, "core-db-inner-post-trans-execute") && !zstr(val)) {
 					runtime.core_db_inner_post_trans_execute = switch_core_strdup(runtime.memory_pool, val);
+				} else if (!strcasecmp(var, "dialplan-timestamps")) {
+					if (switch_true(val)) {
+						switch_set_flag((&runtime), SCF_DIALPLAN_TIMESTAMPS);
+					} else {
+						switch_clear_flag((&runtime), SCF_DIALPLAN_TIMESTAMPS);
+					}
 				} else if (!strcasecmp(var, "mailer-app") && !zstr(val)) {
 					runtime.mailer_app = switch_core_strdup(runtime.memory_pool, val);
 				} else if (!strcasecmp(var, "mailer-app-args") && val) {

src/switch_core_session.c

@@ -2811,8 +2811,13 @@ SWITCH_DECLARE(switch_status_t) switch_core_session_exec(switch_core_session_t *
 	}
 
 	
+	if ( switch_core_test_flag(SCF_DIALPLAN_TIMESTAMPS) ) {
+		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session), SWITCH_LOG_DEBUG, "EXECUTE %s %s(%s)\n",
+					  switch_channel_get_name(session->channel), app, switch_str_nil(expanded));
+	} else {
 		switch_log_printf(SWITCH_CHANNEL_SESSION_LOG_CLEAN(session), SWITCH_LOG_DEBUG, "EXECUTE %s %s(%s)\n",
 					  switch_channel_get_name(session->channel), app, switch_str_nil(expanded));
+	}
 
 	if ((var = switch_channel_get_variable(session->channel, "verbose_presence")) && switch_true(var)) {
 		char *myarg = NULL;