Fix date parsing in MySQL error fileset (elastic#14130) (elastic#14133)

MySQL error logs can contain timestamps with or without timezones, add date parsers for both cases. Also remove some spurious spaces from parsed messages, and add previously unsupported date patterns. Consider lines without timestamp as part of the previous message. If not, lines without timestamp will appear disordered respect to lines with timestamps in Kibana. And joined lines are always related, at least in the tests cases we have. (cherry picked from commit cf5595a)
jsoriano · Oct 27, 2019 · 17a527d · 17a527d
1 parent edf7ecf
commit 17a527d
Show file tree

Hide file tree

Showing 10 changed files with 1,022 additions and 302 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -46,6 +46,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 
 *Filebeat*
 
+- Fix timezone parsing of MySQL module ingest pipelines. {pull}14130[14130]
 - Improve error message in s3 input when handleSQSMessage failed. {pull}14113[14113]
 
 *Heartbeat*

diff --git a/filebeat/module/mysql/error/config/error.yml b/filebeat/module/mysql/error/config/error.yml
@@ -4,3 +4,12 @@ paths:
  - {{$path}}
 {{ end }}
 exclude_files: [".gz$"]
+
+multiline:
+  # Consider lines without timestamp part of the previous message
+  pattern: '^([0-9]{4}-[0-9]{2}-[0-9]{2}|[0-9]{6})'
+  negate: true
+  match: after
+
+processors:
+- add_locale: ~
diff --git a/filebeat/module/mysql/error/ingest/pipeline.json b/filebeat/module/mysql/error/ingest/pipeline.json
@@ -4,33 +4,55 @@
     "grok": {
         "field": "message",
         "patterns": [
-          "%{LOCALDATETIME:mysql.error.timestamp} (\\[%{DATA:log.level}\\] )?%{GREEDYDATA:message}",
-          "%{DATA:mysql.error.timestamp} %{NUMBER:mysql.thread_id:long} \\[%{DATA:log.level}\\] %{GREEDYDATA:message}",
+          "%{MYSQLDATETIME}%{SPACE}(%{NUMBER:mysql.thread_id:long}%{SPACE})?(\\[%{DATA:log.level}\\]%{SPACE})?%{GREEDYMULTILINE:message}",
           "%{GREEDYDATA:message}"
         ],
         "ignore_missing": true,
         "pattern_definitions": {
-          "LOCALDATETIME": "[0-9]+ %{TIME}"
+          "LOCALDATETIME": "(?:%{YEAR}-%{MONTHNUM}-%{MONTHDAY}|%{NUMBER})%{SPACE}%{TIME}",
+          "MYSQLDATETIME": "(?:%{LOCALDATETIME:_tmp.local_timestamp}|%{TIMESTAMP_ISO8601:_tmp.timestamp})",
+          "GREEDYMULTILINE": "(.|\n)+"
         }
       }
     }, {
-        "rename": {
-            "field": "@timestamp",
-            "target_field": "event.created"
-        }
+      "rename": {
+        "field": "@timestamp",
+        "target_field": "event.created"
+      }
     }, {
       "date": {
-        "field": "mysql.error.timestamp",
-        "target_field": "@timestamp",
+        "if": "ctx._tmp?.local_timestamp != null && ctx.event?.timezone == null",
+        "field": "_tmp.local_timestamp",
         "formats": [
-          "ISO8601",
-          "yyMMdd H:m:s"
-        ],
-        "ignore_failure": true
+          "yyMMdd H:m:s",
+          "yyMMdd  H:m:s",
+          "yyyy-MM-dd H:m:s",
+          "yyyy-MM-dd  H:m:s"
+        ]
+      }
+    }, {
+      "date": {
+        "if": "ctx._tmp?.local_timestamp != null && ctx.event?.timezone != null",
+        "field": "_tmp.local_timestamp",
+        "timezone": "{{ event.timezone }}",
+        "formats": [
+          "yyMMdd H:m:s",
+          "yyMMdd  H:m:s",
+          "yyyy-MM-dd H:m:s",
+          "yyyy-MM-dd  H:m:s"
+        ]
+      }
+    }, {
+      "date": {
+        "if": "ctx._tmp?.timestamp != null",
+        "field": "_tmp.timestamp",
+        "formats": [
+          "ISO8601"
+        ]
       }
     }, {
       "remove":{
-        "field": "mysql.error.timestamp",
+        "field": "_tmp",
         "ignore_missing": true
       }
     }],

diff --git a/filebeat/module/mysql/error/test/error.log-expected.json b/filebeat/module/mysql/error/test/error.log-expected.json
@@ -1,8 +1,9 @@
 [
     {
-        "@timestamp": "2016-12-09T13:08:33.000Z",
+        "@timestamp": "2016-12-09T13:08:33.000-02:00",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.offset": 0,
@@ -13,6 +14,7 @@
         "@timestamp": "2016-12-09T12:08:33.335Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Warning",
@@ -25,6 +27,7 @@
         "@timestamp": "2016-12-09T12:08:33.335Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Warning",
@@ -37,6 +40,7 @@
         "@timestamp": "2016-12-09T12:08:33.336Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Note",
@@ -49,6 +53,7 @@
         "@timestamp": "2016-12-09T12:08:33.345Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Warning",
@@ -61,6 +66,7 @@
         "@timestamp": "2016-12-09T12:08:33.351Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Note",
@@ -73,27 +79,23 @@
         "@timestamp": "2016-12-09T12:08:33.784Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
         "log.level": "Note",
         "log.offset": 832,
-        "message": "/usr/local/Cellar/mysql/5.7.10/bin/mysqld: ready for connections.",
+        "message": "/usr/local/Cellar/mysql/5.7.10/bin/mysqld: ready for connections.\nVersion: '5.7.10'  socket: '/tmp/mysql.sock'  port: 3306  Homebrew",
         "mysql.thread_id": 0,
         "service.type": "mysql"
     },
-    {
-        "event.dataset": "mysql.error",
-        "event.module": "mysql",
-        "fileset.name": "error",
-        "input.type": "log",
-        "log.offset": 935,
-        "message": "Version: '5.7.10'  socket: '/tmp/mysql.sock'  port: 3306  Homebrew",
-        "service.type": "mysql"
-    },
     {
         "@timestamp": "2016-12-09T22:21:02.443Z",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Note",
@@ -103,9 +105,10 @@
         "service.type": "mysql"
     },
     {
-        "@timestamp": "2016-12-09T14:18:50.000Z",
+        "@timestamp": "2016-12-09T14:18:50.000-02:00",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Warning",
@@ -114,9 +117,10 @@
         "service.type": "mysql"
     },
     {
-        "@timestamp": "2016-12-09T14:18:50.000Z",
+        "@timestamp": "2016-12-09T14:18:50.000-02:00",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.level": "Note",
@@ -125,9 +129,10 @@
         "service.type": "mysql"
     },
     {
-        "@timestamp": "2016-12-09T14:18:50.000Z",
+        "@timestamp": "2016-12-09T14:18:50.000-02:00",
         "event.dataset": "mysql.error",
         "event.module": "mysql",
+        "event.timezone": "-02:00",
         "fileset.name": "error",
         "input.type": "log",
         "log.offset": 1422,

diff --git a/filebeat/module/mysql/error/test/mariadb-10.4.8.log b/filebeat/module/mysql/error/test/mariadb-10.4.8.log
@@ -0,0 +1,30 @@
+191015  9:46:45	    13 Query	SHOW /*!50002 GLOBAL */ STATUS
+2019-10-16 17:24:15 0 [Note] InnoDB: Using Linux native AIO
+2019-10-16 17:24:15 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
+2019-10-16 17:24:15 0 [Note] InnoDB: Uses event mutexes
+2019-10-16 17:24:15 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
+2019-10-16 17:24:15 0 [Note] InnoDB: Number of pools: 1
+2019-10-16 17:24:15 0 [Note] InnoDB: Using SSE2 crc32 instructions
+2019-10-16 17:24:15 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
+2019-10-16 17:24:15 0 [Note] InnoDB: Completed initialization of buffer pool
+2019-10-16 17:24:15 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
+2019-10-16 17:24:15 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
+2019-10-16 17:24:15 0 [Note] InnoDB: Creating shared tablespace for temporary tables
+2019-10-16 17:24:15 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
+2019-10-16 17:24:15 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
+2019-10-16 17:24:15 0 [Note] InnoDB: Waiting for purge to start
+2019-10-16 17:24:15 0 [Note] InnoDB: 10.4.8 started; log sequence number 1631101; transaction id 791
+2019-10-16 17:24:15 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysqldata/mysql/ib_buffer_pool
+2019-10-16 17:24:15 0 [Note] Plugin 'FEEDBACK' is disabled.
+2019-10-16 17:24:15 0 [Note] InnoDB: Buffer pool(s) load completed at 191016 17:24:15
+2019-10-16 17:24:15 0 [Note] Server socket created on IP: '::'.
+2019-10-16 17:24:15 0 [Note] Reading of all Master_info entries succeeded
+2019-10-16 17:24:15 0 [Note] Added new Master_info '' to hash table
+2019-10-16 17:24:15 0 [Note] /usr/sbin/mysqld: ready for connections.
+Version: '10.4.8-MariaDB-log'  socket: '/data/mysqldata/mysql.sock'  port: 3306  MariaDB Server
+2019-10-16 17:25:43 11 [Note] Event Scheduler: scheduler thread started with id 11
+2019-10-16 17:25:43 11 [Note] Event Scheduler: Last execution of test.test_error_log. Dropping.
+2019-10-16 17:25:43 12 [Note] Event Scheduler: Dropping test.test_error_log
+2019-10-16 17:25:43 12 [ERROR] Event Scheduler: [root@localhost][test.test_error_log] hi from the error log
+2019-10-16 17:25:43 12 [Note] Event Scheduler: [root@localhost][test.test_error_log] At line 1 in test.test_error_log
+