Filebeat: Add support for ISO8601 dates to system.auth (elastic#12579)

Followup of elastic#12568 for system/auth.

CHANGELOG.next.asciidoc

@@ -201,7 +201,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - `container` and `docker` inputs now support reading of labels and env vars written by docker JSON file logging driver. {issue}8358[8358]
 - Add specific date processor to convert timezones so same pipeline can be used when convert_timezone is enabled or disabled. {pull}12253[12253]
 - Add MSSQL module {pull}12079[12079]
-- Add full ISO8601 date parsing support for system/syslog module. {pull}12568[12568]
+- Add ISO8601 date parsing support for system module. {pull}12568[12568] {pull}12578[12579]
 
 *Heartbeat*
 

filebeat/module/system/auth/ingest/pipeline.json

@@ -6,16 +6,17 @@
                 "field": "message",
                 "ignore_missing": true,
                 "pattern_definitions" : {
-                    "GREEDYMULTILINE" : "(.|\n)*"
+                    "GREEDYMULTILINE" : "(.|\n)*",
+                    "TIMESTAMP": "(?:%{TIMESTAMP_ISO8601}|%{SYSLOGTIMESTAMP})"
                 },
                 "patterns": [
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{DATA:system.auth.ssh.event} %{DATA:system.auth.ssh.method} for (invalid user )?%{DATA:user.name} from %{IPORHOST:source.ip} port %{NUMBER:source.port:long} ssh2(: %{GREEDYDATA:system.auth.ssh.signature})?",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{DATA:system.auth.ssh.event} user %{DATA:user.name} from %{IPORHOST:source.ip}",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: Did not receive identification string from %{IPORHOST:system.auth.ssh.dropped_ip}",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: \\s*%{DATA:user.name} :( %{DATA:system.auth.sudo.error} ;)? TTY=%{DATA:system.auth.sudo.tty} ; PWD=%{DATA:system.auth.sudo.pwd} ; USER=%{DATA:system.auth.sudo.user} ; COMMAND=%{GREEDYDATA:system.auth.sudo.command}",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: new group: name=%{DATA:group.name}, GID=%{NUMBER:group.id}",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: new user: name=%{DATA:user.name}, UID=%{NUMBER:user.id}, GID=%{NUMBER:group.id}, home=%{DATA:system.auth.useradd.home}, shell=%{DATA:system.auth.useradd.shell}$",
-                    "%{SYSLOGTIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname}? %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{GREEDYMULTILINE:system.auth.message}"
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{DATA:system.auth.ssh.event} %{DATA:system.auth.ssh.method} for (invalid user )?%{DATA:user.name} from %{IPORHOST:source.ip} port %{NUMBER:source.port:long} ssh2(: %{GREEDYDATA:system.auth.ssh.signature})?",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{DATA:system.auth.ssh.event} user %{DATA:user.name} from %{IPORHOST:source.ip}",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: Did not receive identification string from %{IPORHOST:system.auth.ssh.dropped_ip}",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: \\s*%{DATA:user.name} :( %{DATA:system.auth.sudo.error} ;)? TTY=%{DATA:system.auth.sudo.tty} ; PWD=%{DATA:system.auth.sudo.pwd} ; USER=%{DATA:system.auth.sudo.user} ; COMMAND=%{GREEDYDATA:system.auth.sudo.command}",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: new group: name=%{DATA:group.name}, GID=%{NUMBER:group.id}",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname} %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: new user: name=%{DATA:user.name}, UID=%{NUMBER:user.id}, GID=%{NUMBER:group.id}, home=%{DATA:system.auth.useradd.home}, shell=%{DATA:system.auth.useradd.shell}$",
+                    "%{TIMESTAMP:system.auth.timestamp} %{SYSLOGHOST:host.hostname}? %{DATA:process.name}(?:\\[%{POSINT:process.pid:long}\\])?: %{GREEDYMULTILINE:system.auth.message}"
                 ]
             }
         },
@@ -44,7 +45,8 @@
                 "target_field": "@timestamp",
                 "formats": [
                     "MMM  d HH:mm:ss",
-                    "MMM dd HH:mm:ss"
+                    "MMM dd HH:mm:ss",
+                    "ISO8601"
                 ],
                 "ignore_failure": true
             }

filebeat/module/system/auth/test/timestamp.log

@@ -0,0 +1,2 @@
+2019-06-14T10:40:20.912134 localhost sudo: pam_unix(sudo-i:session): session opened for user root by userauth3(uid=0)
+2019-06-14T13:01:15.412+01:30 localhost pam: user nobody logged out.

filebeat/module/system/auth/test/timestamp.log-expected.json

@@ -0,0 +1,30 @@
+[
+    {
+        "@timestamp": "2019-06-14T10:40:20.912Z",
+        "event.dataset": "system.auth",
+        "event.module": "system",
+        "event.timezone": "+00:00",
+        "fileset.name": "auth",
+        "host.hostname": "localhost",
+        "input.type": "log",
+        "log.file.path": "timestamp.log",
+        "log.offset": 0,
+        "message": "pam_unix(sudo-i:session): session opened for user root by userauth3(uid=0)",
+        "process.name": "sudo",
+        "service.type": "system"
+    },
+    {
+        "@timestamp": "2019-06-14T11:31:15.412Z",
+        "event.dataset": "system.auth",
+        "event.module": "system",
+        "event.timezone": "+00:00",
+        "fileset.name": "auth",
+        "host.hostname": "localhost",
+        "input.type": "log",
+        "log.file.path": "timestamp.log",
+        "log.offset": 118,
+        "message": "user nobody logged out.",
+        "process.name": "pam",
+        "service.type": "system"
+    }
+]

filebeat/tests/system/test_modules.py

@@ -219,6 +219,13 @@ def clean_keys(obj):
     other_keys = ["log.file.path", "agent.version"]
     # ECS versions change for any ECS release, large or small
     ecs_key = ["ecs.version"]
+    # datasets for which @timestamp is removed due to date missing
+    remove_timestamp = {"icinga.startup", "redis.log", "haproxy.log", "system.auth", "system.syslog"}
+    # dataset + log file pairs for which @timestamp is kept as an exception from above
+    remove_timestamp_exception = {
+        ('system.syslog', 'tz-offset.log'),
+        ('system.auth', 'timestamp.log')
+    }
 
     # Keep source log filename for exceptions
     filename = None
@@ -228,23 +235,16 @@ def clean_keys(obj):
     for key in host_keys + time_keys + other_keys + ecs_key:
         delete_key(obj, key)
 
-    # Remove timestamp for comparison where timestamp is not part of the log line
-    if (obj["event.dataset"] in ["icinga.startup", "redis.log", "haproxy.log", "system.auth"]):
-        delete_key(obj, "@timestamp")
-
-    # HACK: This keeps @timestamp for the tz-offset.log in system.syslog.
-    #
-    # This can't be done for all syslog logs because most of them lack the year
-    # in their timestamp, so Elasticsearch will set it to the current year and
-    # that will cause the tests to fail every new year.
-    #
-    # The log.file.path key needs to be kept so that it is stored in the golden
-    # data, to prevent @timestamp to be removed from it before comparison.
-    if obj["event.dataset"] == "system.syslog":
-        if filename == "tz-offset.log":
-            obj["log.file.path"] = filename
-        else:
+    # Most logs from syslog need their timestamp removed because it doesn't
+    # include a year.
+    if obj["event.dataset"] in remove_timestamp:
+        if not (obj['event.dataset'], filename) in remove_timestamp_exception:
             delete_key(obj, "@timestamp")
+        else:
+            # excluded events need to have their filename saved to the expected.json
+            # so that the exception mechanism can be triggered when the json is
+            # loaded.
+            obj["log.file.path"] = filename
 
 
 def delete_key(obj, key):