From e26a9505d64898e4226386e07532d14ed76be01a Mon Sep 17 00:00:00 2001
From: Mark Stemm <mark.stemm@sysdig.com>
Date: Tue, 9 Apr 2019 09:41:00 -0700
Subject: [PATCH] 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 https://github.com/draios/sysdig/pull/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                   |  7 ++++-
 docker/local/Dockerfile                 |  5 ++++
 docker/stable/Dockerfile                |  5 ++++
 falco.yaml                              |  5 ++++
 test/falco_test.py                      |  5 ++++
 test/falco_tests.yaml                   |  9 ++++++
 userspace/engine/falco_engine_version.h |  4 +--
 userspace/engine/json_evt.cpp           | 14 +++++++++
 userspace/engine/json_evt.h             |  1 +
 userspace/falco/configuration.cpp       |  2 ++
 userspace/falco/configuration.h         |  1 +
 userspace/falco/falco.cpp               |  6 +++-
 userspace/falco/falco_outputs.cpp       | 12 +++++---
 userspace/falco/falco_outputs.h         |  4 ++-
 userspace/falco/logger.cpp              | 39 +++++++++++++++++++++++--
 userspace/falco/logger.h                |  3 ++
 userspace/falco/lua/output.lua          | 23 +++++++++++++--
 17 files changed, 130 insertions(+), 15 deletions(-)

diff --git a/docker/dev/Dockerfile b/docker/dev/Dockerfile
index b8218873fca..c5aa61567c2 100644
--- a/docker/dev/Dockerfile
+++ b/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"]
diff --git a/docker/local/Dockerfile b/docker/local/Dockerfile
index 4f6d91c1444..ac48e8450d8 100644
--- a/docker/local/Dockerfile
+++ b/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.
diff --git a/docker/stable/Dockerfile b/docker/stable/Dockerfile
index 70836d88b62..bf15c909c49 100644
--- a/docker/stable/Dockerfile
+++ b/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
diff --git a/falco.yaml b/falco.yaml
index 9d90e463341..af3b254d979 100644
--- a/falco.yaml
+++ b/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
 
diff --git a/test/falco_test.py b/test/falco_test.py
index a202e4d07ce..8e73e9ee518 100644
--- a/test/falco_test.py
+++ b/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)
diff --git a/test/falco_tests.yaml b/test/falco_tests.yaml
index 7d057d0c6fd..4293bcf85d5 100644
--- a/test/falco_tests.yaml
+++ b/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"
diff --git a/userspace/engine/falco_engine_version.h b/userspace/engine/falco_engine_version.h
index 7d45d3a60a7..c7745f72b3a 100644
--- a/userspace/engine/falco_engine_version.h
+++ b/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"
diff --git a/userspace/engine/json_evt.cpp b/userspace/engine/json_evt.cpp
index 8d8bad2e696..7adc4d953a2 100644
--- a/userspace/engine/json_evt.cpp
+++ b/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;
diff --git a/userspace/engine/json_evt.h b/userspace/engine/json_evt.h
index 29a4779ae3d..e04d73fda70 100644
--- a/userspace/engine/json_evt.h
+++ b/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;
diff --git a/userspace/falco/configuration.cpp b/userspace/falco/configuration.cpp
index bbc7588e564..707727bbd4b 100644
--- a/userspace/falco/configuration.cpp
+++ b/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);
diff --git a/userspace/falco/configuration.h b/userspace/falco/configuration.h
index 854ca9b3ceb..585aea1d02f 100644
--- a/userspace/falco/configuration.h
+++ b/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;
diff --git a/userspace/falco/falco.cpp b/userspace/falco/falco.cpp
index e2f7167d003..fdee94d78b3 100644
--- a/userspace/falco/falco.cpp
+++ b/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)
 		{
diff --git a/userspace/falco/falco_outputs.cpp b/userspace/falco/falco_outputs.cpp
index fa444da6652..ff620581d9a 100644
--- a/userspace/falco/falco_outputs.cpp
+++ b/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)
diff --git a/userspace/falco/falco_outputs.h b/userspace/falco/falco_outputs.h
index 51be58a2e24..016ebb61b9d 100644
--- a/userspace/falco/falco_outputs.h
+++ b/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;
 
diff --git a/userspace/falco/logger.cpp b/userspace/falco/logger.cpp
index 1442b085a57..aef225691a5 100644
--- a/userspace/falco/logger.cpp
+++ b/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());
+		}
 	}
 }
 
diff --git a/userspace/falco/logger.h b/userspace/falco/logger.h
index 82cda156423..7fb78082f18 100644
--- a/userspace/falco/logger.h
+++ b/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;
 };
diff --git a/userspace/falco/lua/output.lua b/userspace/falco/lua/output.lua
index 60092165478..e408ce53f8c 100644
--- a/userspace/falco/lua/output.lua
+++ b/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"],