Change log timestamp to ISO8601 w/ timezone (#518)

* Add option to display times in ISO 8601 UTC

ISO 8601 time is useful when, say, running falco in a container, which
may have a different /etc/localtime than the host system.

A new config option time_format_iso_8601 controls whether log message
and event times are displayed in ISO 8601 in UTC or in local time. The
default is false (display times in local time).

This option is passed to logger init as well as outputs. For outputs it
eventually changes the time format field from %evt.time/%jevt.time to
%evt.time.iso8601/%jevt.time.iso8601.

Adding this field changes the falco engine version so increment it.

This depends on draios/sysdig#1317.

* Unit test for ISO 8601 output

A unit test for ISO 8601 output ensures that both the log and event time
is in ISO 8601 format.

* Use ISO 8601 output by default in containers

Now that we have an option that controls iso 8601 output, use it by
default in containers. We do this by changing the value of
time_format_iso_8601 in falco.yaml in the container.

* Handle errors in strftime/asctime/gmtime

A placeholder "N/A" is used in log messages instead.

docker/dev/Dockerfile

@@ -82,6 +82,11 @@ RUN curl -s https://s3.amazonaws.com/download.draios.com/DRAIOS-GPG-KEY.public |
  && apt-get clean \
  && rm -rf /var/lib/apt/lists/*
 
+# Change the falco config within the container to enable ISO 8601
+# output.
+RUN sed -e 's/time_format_iso_8601: false/time_format_iso_8601: true/' < /etc/falco/falco.yaml > /etc/falco/falco.yaml.new \
+ && mv /etc/falco/falco.yaml.new /etc/falco/falco.yaml
+
 # Some base images have an empty /lib/modules by default
 # If it's not empty, docker build will fail instead of
 # silently overwriting the existing directory
@@ -101,4 +106,4 @@ COPY ./docker-entrypoint.sh /
 
 ENTRYPOINT ["/docker-entrypoint.sh"]
 
-CMD ["/usr/bin/falco"]
+CMD ["/usr/bin/falco", "-o", "time_format_iso_8601=true"]

docker/local/Dockerfile

@@ -83,6 +83,11 @@ RUN rm -df /lib/modules \
 ADD falco-${FALCO_VERSION}-x86_64.deb /
 RUN dpkg -i /falco-${FALCO_VERSION}-x86_64.deb
 
+# Change the falco config within the container to enable ISO 8601
+# output.
+RUN sed -e 's/time_format_iso_8601: false/time_format_iso_8601: true/' < /etc/falco/falco.yaml > /etc/falco/falco.yaml.new \
+ && mv /etc/falco/falco.yaml.new /etc/falco/falco.yaml
+
 # debian:unstable head contains binutils 2.31, which generates
 # binaries that are incompatible with kernels < 4.16. So manually
 # forcibly install binutils 2.30-22 instead.

docker/stable/Dockerfile

@@ -81,6 +81,11 @@ RUN curl -s https://s3.amazonaws.com/download.draios.com/DRAIOS-GPG-KEY.public |
  && apt-get clean \
  && rm -rf /var/lib/apt/lists/*
 
+# Change the falco config within the container to enable ISO 8601
+# output.
+RUN sed -e 's/time_format_iso_8601: false/time_format_iso_8601: true/' < /etc/falco/falco.yaml > /etc/falco/falco.yaml.new \
+ && mv /etc/falco/falco.yaml.new /etc/falco/falco.yaml
+
 # Some base images have an empty /lib/modules by default
 # If it's not empty, docker build will fail instead of
 # silently overwriting the existing directory

falco.yaml

@@ -34,6 +34,11 @@ rules_file:
  - /etc/falco/k8s_audit_rules.yaml
  - /etc/falco/rules.d
 
+# If true, the times displayed in log messages and output messages
+# will be in ISO 8601. By default, times are displayed in the local
+# time zone, as governed by /etc/localtime.
+time_format_iso_8601: false
+
 # Whether to output events in json or text
 json_output: false
 

test/falco_test.py

@@ -183,6 +183,8 @@ def setUp(self):
         if self.run_tags == '':
             self.run_tags=[]
 
+        self.time_iso_8601 = self.params.get('time_iso_8601', '*', default=False)
+
     def tearDown(self):
         if self.package != 'None':
             self.uninstall_package()
@@ -409,6 +411,9 @@ def test(self):
         if self.all_events:
             cmd += ' -A'
 
+        if self.time_iso_8601:
+            cmd += ' -o time_format_iso_8601=true'
+
         self.falco_proc = process.SubProcess(cmd)
 
         res = self.falco_proc.run(timeout=180, sig=9)

test/falco_tests.yaml

@@ -840,3 +840,12 @@ trace_files: !mux
     stdout_not_contains:
       - "Falco internal: syscall event drop"
 
+  time_iso_8601:
+    time_iso_8601: true
+    detect: True
+    detect_level: WARNING
+    rules_file:
+      - rules/single_rule.yaml
+    trace_file: trace_files/cat_write.scap
+    stdout_contains: "2016-08-04T16:17:57.882054739\\+0000: Warning An open was seen"
+    stderr_contains: "^\\d\\d\\d\\d-\\d\\d-\\d\\dT\\d\\d:\\d\\d:\\d\\d\\+0000"

userspace/engine/falco_engine_version.h

@@ -19,9 +19,9 @@ limitations under the License.
 
 // The version of rules/filter fields/etc supported by this falco
 // engine.
-#define FALCO_ENGINE_VERSION (2)
+#define FALCO_ENGINE_VERSION (3)
 
 // This is the result of running "falco --list -N | sha256sum" and
 // represents the fields supported by this version of falco. It's used
 // at build time to detect a changed set of fields.
-#define FALCO_FIELDS_CHECKSUM "32a91c003ab34f198dcb4c3100fbfb22bf402ad36549f193afa43d73f1f2eba3"
+#define FALCO_FIELDS_CHECKSUM "b1bf297373fd08c91ffc978dbff5b349ec9338e25b54f70f23e40a609d47924b"

userspace/engine/json_evt.cpp

@@ -278,6 +278,7 @@ std::string json_event_filter_check::extract(json_event *evt)
 }
 
 std::string jevt_filter_check::s_jevt_time_field = "jevt.time";
+std::string jevt_filter_check::s_jevt_time_iso_8601_field = "jevt.time.iso8601";
 std::string jevt_filter_check::s_jevt_rawtime_field = "jevt.rawtime";
 std::string jevt_filter_check::s_jevt_value_field = "jevt.value";
 std::string jevt_filter_check::s_jevt_obj_field = "jevt.obj";
@@ -288,6 +289,7 @@ jevt_filter_check::jevt_filter_check()
 		  "generic ways to access json events",
 		  {
 			  {s_jevt_time_field, "json event timestamp as a string that includes the nanosecond part"},
+			  {s_jevt_time_iso_8601_field, "json event timestamp in ISO 8601 format, including nanoseconds and time zone offset (in UTC)"},
 			  {s_jevt_rawtime_field, "absolute event timestamp, i.e. nanoseconds from epoch."},
 			  {s_jevt_value_field, "General way to access single property from json object. The syntax is [<json pointer expression>]. The property is returned as a string"},
 			  {s_jevt_obj_field, "The entire json object, stringified"}
@@ -301,6 +303,12 @@ jevt_filter_check::~jevt_filter_check()
 
 int32_t jevt_filter_check::parse_field_name(const char *str, bool alloc_state, bool needed_for_filtering)
 {
+	if(strncmp(s_jevt_time_iso_8601_field.c_str(), str, s_jevt_time_iso_8601_field.size()) == 0)
+	{
+		m_field = s_jevt_time_iso_8601_field;
+		return s_jevt_time_iso_8601_field.size();
+	}
+
 	if(strncmp(s_jevt_time_field.c_str(), str, s_jevt_time_field.size()) == 0)
 	{
 		m_field = s_jevt_time_field;
@@ -361,6 +369,12 @@ uint8_t* jevt_filter_check::extract(gen_event *evt, uint32_t* len, bool sanitize
 		*len = m_tstr.size();
 		return (uint8_t *) m_tstr.c_str();
 	}
+	else if(m_field == s_jevt_time_iso_8601_field)
+	{
+		sinsp_utils::ts_to_iso_8601(evt->get_ts(), &m_tstr);
+		*len = m_tstr.size();
+		return (uint8_t *) m_tstr.c_str();
+	}
 	else if(m_field == s_jevt_obj_field)
 	{
 		json_event *jevt = (json_event *) evt;

userspace/engine/json_evt.h

@@ -200,6 +200,7 @@ class jevt_filter_check : public json_event_filter_check
 private:
 
 	static std::string s_jevt_time_field;
+	static std::string s_jevt_time_iso_8601_field;
 	static std::string s_jevt_rawtime_field;
 	static std::string s_jevt_obj_field;
 	static std::string s_jevt_value_field;

userspace/falco/configuration.cpp

@@ -31,6 +31,7 @@ using namespace std;
 
 falco_configuration::falco_configuration()
 	: m_buffered_outputs(false),
+	  m_time_format_iso_8601(false),
 	  m_webserver_enabled(false),
 	  m_webserver_listen_port(8765),
 	  m_webserver_k8s_audit_endpoint("/k8s_audit"),
@@ -173,6 +174,7 @@ void falco_configuration::init(string conf_filename, list<string> &cmdline_optio
 	m_min_priority = (falco_common::priority_type) (it - falco_common::priority_names.begin());
 
 	m_buffered_outputs = m_config->get_scalar<bool>("buffered_outputs", false);
+	m_time_format_iso_8601 = m_config->get_scalar<bool>("time_format_iso_8601", false);
 
 	falco_logger::log_stderr = m_config->get_scalar<bool>("log_stderr", false);
 	falco_logger::log_syslog = m_config->get_scalar<bool>("log_syslog", true);

userspace/falco/configuration.h

@@ -205,6 +205,7 @@ class falco_configuration
 	falco_common::priority_type m_min_priority;
 
 	bool m_buffered_outputs;
+	bool m_time_format_iso_8601;
 
 	bool m_webserver_enabled;
 	uint32_t m_webserver_listen_port;

userspace/falco/falco.cpp

@@ -713,12 +713,15 @@ int falco_init(int argc, char **argv)
 		if (conf_filename.size())
 		{
 			config.init(conf_filename, cmdline_options);
+			falco_logger::set_time_format_iso_8601(config.m_time_format_iso_8601);
+
 			// log after config init because config determines where logs go
 			falco_logger::log(LOG_INFO, "Falco initialized with configuration file " + conf_filename + "\n");
 		}
 		else
 		{
 			config.init(cmdline_options);
+			falco_logger::set_time_format_iso_8601(config.m_time_format_iso_8601);
 			falco_logger::log(LOG_INFO, "Falco initialized. No configuration file found, proceeding with defaults\n");
 		}
 
@@ -834,7 +837,8 @@ int falco_init(int argc, char **argv)
 		outputs->init(config.m_json_output,
 			      config.m_json_include_output_property,
 			      config.m_notifications_rate, config.m_notifications_max_burst,
-			      config.m_buffered_outputs);
+			      config.m_buffered_outputs,
+			      config.m_time_format_iso_8601);
 
 		if(!all_events)
 		{

userspace/falco/falco_outputs.cpp

@@ -37,7 +37,8 @@ falco_outputs::falco_outputs(falco_engine *engine)
 	: m_falco_engine(engine),
 	  m_initialized(false),
 	  m_buffered(true),
-	  m_json_output(false)
+	  m_json_output(false),
+	  m_time_format_iso_8601(false)
 {
 
 }
@@ -70,7 +71,8 @@ falco_outputs::~falco_outputs()
 
 void falco_outputs::init(bool json_output,
 			 bool json_include_output_property,
-			 uint32_t rate, uint32_t max_burst, bool buffered)
+			 uint32_t rate, uint32_t max_burst, bool buffered,
+			 bool time_format_iso_8601)
 {
 	// The engine must have been given an inspector by now.
 	if(! m_inspector)
@@ -94,13 +96,14 @@ void falco_outputs::init(bool json_output,
 	m_notifications_tb.init(rate, max_burst);
 
 	m_buffered = buffered;
+	m_time_format_iso_8601 = time_format_iso_8601;
 
 	m_initialized = true;
 }
 
 void falco_outputs::add_output(output_config oc)
 {
-	uint8_t nargs = 2;
+	uint8_t nargs = 3;
 	lua_getglobal(m_ls, m_lua_add_output.c_str());
 
 	if(!lua_isfunction(m_ls, -1))
@@ -109,11 +112,12 @@ void falco_outputs::add_output(output_config oc)
 	}
 	lua_pushstring(m_ls, oc.name.c_str());
 	lua_pushnumber(m_ls, (m_buffered ? 1 : 0));
+	lua_pushnumber(m_ls, (m_time_format_iso_8601 ? 1 : 0));
 
 	// If we have options, build up a lua table containing them
 	if (oc.options.size())
 	{
-		nargs = 3;
+		nargs = 4;
 		lua_createtable(m_ls, 0, oc.options.size());
 
 		for (auto it = oc.options.cbegin(); it != oc.options.cend(); ++it)

userspace/falco/falco_outputs.h

@@ -56,7 +56,8 @@ class falco_outputs : public falco_common
 
 	void init(bool json_output,
 		  bool json_include_output_property,
-		  uint32_t rate, uint32_t max_burst, bool buffered);
+		  uint32_t rate, uint32_t max_burst, bool buffered,
+		  bool time_format_iso_8601);
 
 	void add_output(output_config oc);
 
@@ -88,6 +89,7 @@ class falco_outputs : public falco_common
 	token_bucket m_notifications_tb;
 
 	bool m_buffered;
+	bool m_time_format_iso_8601;
 
 	bool m_json_output;
 

userspace/falco/logger.cpp

@@ -30,12 +30,18 @@ const static struct luaL_reg ll_falco [] =
 };
 
 int falco_logger::level = LOG_INFO;
+bool falco_logger::time_format_iso_8601 = false;
 
 void falco_logger::init(lua_State *ls)
 {
 	luaL_openlib(ls, "falco", ll_falco, 0);
 }
 
+void falco_logger::set_time_format_iso_8601(bool val)
+{
+	falco_logger::time_format_iso_8601 = val;
+}
+
 void falco_logger::set_level(string &level)
 {
 	if(level == "emergency")
@@ -123,9 +129,36 @@ void falco_logger::log(int priority, const string msg)
 		}
 
 		std::time_t result = std::time(nullptr);
-		string tstr = std::asctime(std::localtime(&result));
-		tstr = tstr.substr(0, 24);// remove trailling newline
-		fprintf(stderr, "%s: %s", tstr.c_str(), copy.c_str());
+		if(falco_logger::time_format_iso_8601)
+		{
+			char buf[sizeof "YYYY-MM-DDTHH:MM:SS-0000"];
+			struct tm *gtm = std::gmtime(&result);
+			if(gtm == NULL ||
+			   (strftime(buf, sizeof(buf), "%FT%T%z", gtm) == 0))
+			{
+				sprintf(buf, "N/A");
+			}
+			else
+			{
+				fprintf(stderr, "%s: %s", buf, msg.c_str());
+			}
+		}
+		else
+		{
+			struct tm *ltm = std::localtime(&result);
+			char *atime = (ltm ? std::asctime(ltm) : NULL);
+			string tstr;
+			if(atime)
+			{
+				tstr = atime;
+				tstr = tstr.substr(0, 24);// remove trailling newline
+			}
+			else
+			{
+				tstr = "N/A";
+			}
+			fprintf(stderr, "%s: %s", tstr.c_str(), msg.c_str());
+		}
 	}
 }
 

userspace/falco/logger.h

@@ -33,6 +33,8 @@ class falco_logger
  public:
 	static void init(lua_State *ls);
 
+	static void set_time_format_iso_8601(bool val);
+
 	// Will throw exception if level is unknown.
 	static void set_level(string &level);
 
@@ -44,4 +46,5 @@ class falco_logger
 	static int level;
 	static bool log_stderr;
 	static bool log_syslog;
+	static bool time_format_iso_8601;
 };

userspace/falco/lua/output.lua

@@ -159,10 +159,26 @@ function output_event(event, rule, source, priority, priority_num, format)
       format = format:sub(2)
    end
 
+   -- time_format_iso_8601 will be the same for all output channels
+   time_format_iso_8601 = 0
+
+   for index,o in ipairs(outputs) do
+      time_format_iso_8601 = o.options.time_format_iso_8601
+      break
+   end
+
    if source == "syscall" then
-      format = "*%evt.time: "..priority.." "..format
+      if time_format_iso_8601 == 1 then
+	 format = "*%evt.time.iso8601: "..priority.." "..format
+      else
+	 format = "*%evt.time: "..priority.." "..format
+      end
    else
-      format = "*%jevt.time: "..priority.." "..format
+      if time_format_iso_8601 == 1 then
+	 format = "*%jevt.time.iso8601: "..priority.." "..format
+      else
+	 format = "*%jevt.time: "..priority.." "..format
+      end
    end
 
    msg = formats.format_event(event, rule, source, priority, format)
@@ -191,7 +207,7 @@ function output_reopen()
    end
 end
 
-function add_output(output_name, buffered, options)
+function add_output(output_name, buffered, time_format_iso_8601, options)
    if not (type(mod[output_name]) == 'function') then
       error("rule_loader.add_output(): invalid output_name: "..output_name)
    end
@@ -207,6 +223,7 @@ function add_output(output_name, buffered, options)
    end
 
    options.buffered = buffered
+   options.time_format_iso_8601 = time_format_iso_8601
 
    table.insert(outputs, {output = mod[output_name],
 			  cleanup = mod[output_name.."_cleanup"],