Support mariadb slowlog (elastic#9731) (elastic#10167)

Add support for MariaDB in the Filebeat module for MySQL. slowlog grok pattern is modified to support more versions of this log file and to make it easier to support more in the future. More example files are added to test this. (cherry picked from commit 4140305) Co-authored-by: Rodrigo Floriano de Souza <rodrigochurrops@gmail.com>
ruflin · Jan 21, 2019 · 107130a · 107130a
1 parent 6be849d
commit 107130a
Show file tree

Hide file tree

Showing 14 changed files with 361 additions and 7 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -135,6 +135,7 @@ https://github.com/elastic/beats/compare/v6.6.0...6.x[Check the HEAD diff]
 - Support mysql 5.7.22 slowlog starting with time information. {issue}7892[7892] {pull}9647[9647]
 - Add support for ssl_request_log in apache2 module. {issue}8088[8088] {pull}9833[9833]
 - Add support for iis 7.5 log format. {issue}9753[9753] {pull}9967[9967]
+- Add support for MariaDB in the `slowlog` fileset of `mysql` module. {pull}9731[9731]
 
 *Heartbeat*
 - Made monitors.d configuration part of the default config. {pull}9004[9004]

diff --git a/filebeat/docs/fields.asciidoc b/filebeat/docs/fields.asciidoc
@@ -4105,6 +4105,16 @@ type: long
 The number of rows scanned by the query.
 
 
+--
+
+*`mysql.slowlog.rows_affected`*::
++
+--
+type: long
+
+The number of rows modified by the query.
+
+
 --
 
 *`mysql.slowlog.timestamp`*::
@@ -4130,7 +4140,117 @@ The slow query.
 --
 type: long
 
-The connection ID for the query.
+The connection or thread ID for the query.
+
+
+--
+
+*`mysql.slowlog.schema`*::
++
+--
+type: keyword
+
+The schema where the slow query was executed.
+
+
+--
+
+*`mysql.slowlog.current_user`*::
++
+--
+type: keyword
+
+Current authenticated user, used to determine access privileges. Can differ from the value for user.
+
+
+--
+
+*`mysql.slowlog.query_cache_hit`*::
++
+--
+type: boolean
+
+Whether the query cache was hit.
+
+
+--
+
+*`mysql.slowlog.tmp_table`*::
++
+--
+type: boolean
+
+Whether a temporary table was used to resolve the query.
+
+
+--
+
+*`mysql.slowlog.tmp_table_on_disk`*::
++
+--
+type: boolean
+
+Whether the query needed temporary tables on disk.
+
+
+--
+
+*`mysql.slowlog.filesort`*::
++
+--
+type: boolean
+
+Whether filesort optimization was used.
+
+
+--
+
+*`mysql.slowlog.filesort_on_disk`*::
++
+--
+type: boolean
+
+Whether filesort optimization was used and it needed temporary tables on disk.
+
+
+--
+
+*`mysql.slowlog.priority_queue`*::
++
+--
+type: boolean
+
+Whether a priority queue was used for filesort.
+
+
+--
+
+*`mysql.slowlog.full_scan`*::
++
+--
+type: boolean
+
+Whether a full table scan was needed for the slow query.
+
+
+--
+
+*`mysql.slowlog.full_join`*::
++
+--
+type: boolean
+
+Whether a full join was needed for the slow query (no indexes were used for joins).
+
+
+--
+
+*`mysql.slowlog.merge_passes`*::
++
+--
+type: long
+
+Number of merge passes executed for the query.
 
 
 --

diff --git a/filebeat/docs/modules/mysql.asciidoc b/filebeat/docs/modules/mysql.asciidoc
@@ -16,7 +16,8 @@ include::../include/what-happens.asciidoc[]
 [float]
 === Compatibility
 
-The  +{modulename}+ module was tested with logs from versions 5.5 and 5.7.
+The  +{modulename}+ module was tested with logs from MySQL 5.5 and 5.7 and
+MariaDB 10.1 and 10.2.
 
 On Windows, the module was tested with MySQL installed from the Chocolatey
 repository.

diff --git a/filebeat/include/fields.go b/filebeat/include/fields.go
diff --git a/filebeat/module/mysql/_meta/docs.asciidoc b/filebeat/module/mysql/_meta/docs.asciidoc
@@ -11,7 +11,8 @@ include::../include/what-happens.asciidoc[]
 [float]
 === Compatibility
 
-The  +{modulename}+ module was tested with logs from versions 5.5 and 5.7.
+The  +{modulename}+ module was tested with logs from MySQL 5.5 and 5.7 and
+MariaDB 10.1 and 10.2.
 
 On Windows, the module was tested with MySQL installed from the Chocolatey
 repository.

diff --git a/filebeat/module/mysql/slowlog/_meta/fields.yml b/filebeat/module/mysql/slowlog/_meta/fields.yml
@@ -29,6 +29,10 @@
       type: long
       description: >
         The number of rows scanned by the query.
+    - name: rows_affected
+      type: long
+      description: >
+        The number of rows modified by the query.
     - name: timestamp
       type: long
       description: >
@@ -39,4 +43,49 @@
     - name: id
       type: long
       description: >
-        The connection ID for the query.
+        The connection or thread ID for the query.
+    - name: schema
+      type: keyword
+      description: >
+        The schema where the slow query was executed.
+    - name: current_user
+      type: keyword
+      description: >
+        Current authenticated user, used to determine access privileges. Can differ from the value for user.
+
+    - name: query_cache_hit
+      type: boolean
+      description: >
+        Whether the query cache was hit.
+    - name: tmp_table
+      type: boolean
+      description: >
+        Whether a temporary table was used to resolve the query.
+    - name: tmp_table_on_disk
+      type: boolean
+      description: >
+        Whether the query needed temporary tables on disk.
+    - name: filesort
+      type: boolean
+      description: >
+        Whether filesort optimization was used.
+    - name: filesort_on_disk
+      type: boolean
+      description: >
+        Whether filesort optimization was used and it needed temporary tables on disk.
+    - name: priority_queue
+      type: boolean
+      description: >
+        Whether a priority queue was used for filesort.
+    - name: full_scan
+      type: boolean
+      description: >
+        Whether a full table scan was needed for the slow query.
+    - name: full_join
+      type: boolean
+      description: >
+        Whether a full join was needed for the slow query (no indexes were used for joins).
+    - name: merge_passes
+      type: long
+      description: >
+        Number of merge passes executed for the query.
diff --git a/filebeat/module/mysql/slowlog/ingest/pipeline.json b/filebeat/module/mysql/slowlog/ingest/pipeline.json
@@ -4,17 +4,40 @@
     "grok": {
       "field": "message",
       "patterns":[
-        "^# User@Host: %{USER:mysql.slowlog.user}(\\[[^\\]]+\\])? @ (%{HOSTNAME:mysql.slowlog.host})? \\[(%{IP:mysql.slowlog.ip})?\\](\\s*Id:\\s* %{NUMBER:mysql.slowlog.id})?\n# Query_time: %{NUMBER:mysql.slowlog.query_time.sec}\\s* Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec}\\s* Rows_sent: %{NUMBER:mysql.slowlog.rows_sent}\\s* Rows_examined: %{NUMBER:mysql.slowlog.rows_examined}\n(SET timestamp=%{NUMBER:mysql.slowlog.timestamp};\n)?%{GREEDYMULTILINE:mysql.slowlog.query}"
+        "^# User@Host: %{USER:mysql.slowlog.user}(\\[%{USER:mysql.slowlog.current_user}\\])? @ %{HOSTNAME:mysql.slowlog.host}? \\[%{IP:mysql.slowlog.ip}?\\](\\s*Id:\\s* %{NUMBER:mysql.slowlog.id})?\n(# Thread_id:%{SPACE}%{NUMBER:mysql.slowlog.id}%{METRICSPACE}Schema: %{WORD:mysql.slowlog.schema}?%{METRICSPACE}QC_hit: %{WORD:mysql.slowlog.query_cache_hit}\n)?%{METRICSPACE}Query_time: %{NUMBER:mysql.slowlog.query_time.sec}%{METRICSPACE}Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec}%{METRICSPACE}Rows_sent: %{NUMBER:mysql.slowlog.rows_sent}%{METRICSPACE}Rows_examined: %{NUMBER:mysql.slowlog.rows_examined}%{METRICSPACE}(Rows_affected: %{NUMBER:mysql.slowlog.rows_affected}%{METRICSPACE})?(Full_scan: %{WORD:mysql.slowlog.full_scan}%{METRICSPACE})?(Full_join: %{WORD:mysql.slowlog.full_join}%{METRICSPACE})?(Tmp_table: %{WORD:mysql.slowlog.tmp_table}%{METRICSPACE})?(Tmp_table_on_disk: %{WORD:mysql.slowlog.tmp_table_on_disk}%{METRICSPACE})?(Filesort: %{WORD:mysql.slowlog.filesort}%{METRICSPACE})?(Filesort_on_disk: %{WORD:mysql.slowlog.filesort_on_disk}%{METRICSPACE})?(Merge_passes: %{NUMBER:mysql.slowlog.merge_passes}%{METRICSPACE})?(Priority_queue: %{WORD:mysql.slowlog.priority_queue}%{METRICSPACE})?%{EXPLAIN}?(use %{WORD:mysql.slowlog.schema};\n)?SET timestamp=%{NUMBER:mysql.slowlog.timestamp};\n%{GREEDYMULTILINE:mysql.slowlog.query}"
         ],
       "pattern_definitions" : {
-        "GREEDYMULTILINE" : "(.|\n)*"
+        "GREEDYMULTILINE": "(.|\n)*",
+        "METRICSPACE": "([ #\n]*)",
+        "EXPLAIN": "(# explain:.*\n|#\\s*\n)*"
       },
       "ignore_missing": true
     }
   }, {
     "remove":{
       "field": "message"
     }
+  }, {
+    "script": {
+      "lang": "painless",
+      "source": "for (field in params.fields) { def v = ctx.mysql.slowlog.get(field); if (v != null) { ctx.mysql.slowlog.put(field, params.mapping.get(v)) } }",
+      "params": {
+         "mapping": {
+           "Yes": true,
+           "No": false
+         },
+         "fields": [
+           "query_cache_hit",
+           "tmp_table",
+           "tmp_table_on_disk",
+           "filesort",
+           "filesort_on_disk",
+           "priority_queue",
+           "full_scan",
+           "full_join"
+         ]
+      }
+    }
   }, {
     "date": {
       "field": "mysql.slowlog.timestamp",

diff --git a/filebeat/module/mysql/slowlog/test/mariadb-10.1.21.log b/filebeat/module/mysql/slowlog/test/mariadb-10.1.21.log
@@ -0,0 +1,6 @@
+# Time: 180613 11:04:36
+# User@Host: root[root] @ localhost [121.0.0.1]
+# Thread_id: 5  Schema:   QC_hit: No
+# Query_time: 2.000652  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
+SET timestamp=1528898676;
+select sleep(2);
diff --git a/filebeat/module/mysql/slowlog/test/mariadb-10.1.21.log-expected.json b/filebeat/module/mysql/slowlog/test/mariadb-10.1.21.log-expected.json
@@ -0,0 +1,26 @@
+[
+    {
+        "@timestamp": "2018-06-13T14:04:36.000Z",
+        "event.dataset": "mysql.slowlog",
+        "fileset.module": "mysql",
+        "fileset.name": "slowlog",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "mysql.slowlog.current_user": "root",
+        "mysql.slowlog.host": "localhost",
+        "mysql.slowlog.id": "5",
+        "mysql.slowlog.ip": "121.0.0.1",
+        "mysql.slowlog.lock_time.sec": "0.000000",
+        "mysql.slowlog.query": "select sleep(2);",
+        "mysql.slowlog.query_cache_hit": false,
+        "mysql.slowlog.query_time.sec": "2.000652",
+        "mysql.slowlog.rows_examined": "0",
+        "mysql.slowlog.rows_sent": "1",
+        "mysql.slowlog.timestamp": "1528898676",
+        "mysql.slowlog.user": "root",
+        "offset": 24,
+        "prospector.type": "log"
+    }
+]
diff --git a/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log b/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log
@@ -0,0 +1,23 @@
+mysqld, Version: 10.2.12-MariaDB-10.2.12+maria~jessie-log (mariadb.org binary distribution). started with:
+Tcp port: 0  Unix socket: /var/run/mysqld/mysqld.sock
+Time                 Id Command    Argument
+mysqld, Version: 10.2.12-MariaDB-10.2.12+maria~jessie-log (mariadb.org binary distribution). started with:
+Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
+Time                 Id Command    Argument
+# Time: 190117 16:04:03
+# User@Host: root[root] @ localhost []
+# Thread_id: 8  Schema:   QC_hit: No
+# Query_time: 2.000227  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
+# Rows_affected: 0
+SET timestamp=1547741043;
+select sleep(2)
+AS foo;
+# Time: 190117 16:04:18
+# User@Host: root[root] @  [192.168.0.10]
+# Thread_id: 25844  Schema: blah  QC_hit: No
+# Query_time: 178.306017  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 53022772
+# Rows_affected: 3062
+# Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
+# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0  Priority_queue: No
+SET timestamp=1547741058;
+call PROC('blah');
diff --git a/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log-expected.json b/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log-expected.json
@@ -0,0 +1,59 @@
+[
+    {
+        "@timestamp": "2019-01-17T16:04:03.000Z",
+        "event.dataset": "mysql.slowlog",
+        "fileset.module": "mysql",
+        "fileset.name": "slowlog",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "mysql.slowlog.current_user": "root",
+        "mysql.slowlog.host": "localhost",
+        "mysql.slowlog.id": "8",
+        "mysql.slowlog.lock_time.sec": "0.000000",
+        "mysql.slowlog.query": "select sleep(2)\nAS foo;",
+        "mysql.slowlog.query_cache_hit": false,
+        "mysql.slowlog.query_time.sec": "2.000227",
+        "mysql.slowlog.rows_affected": "0",
+        "mysql.slowlog.rows_examined": "0",
+        "mysql.slowlog.rows_sent": "1",
+        "mysql.slowlog.timestamp": "1547741043",
+        "mysql.slowlog.user": "root",
+        "offset": 437,
+        "prospector.type": "log"
+    },
+    {
+        "@timestamp": "2019-01-17T16:04:18.000Z",
+        "event.dataset": "mysql.slowlog",
+        "fileset.module": "mysql",
+        "fileset.name": "slowlog",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "mysql.slowlog.current_user": "root",
+        "mysql.slowlog.filesort": true,
+        "mysql.slowlog.filesort_on_disk": false,
+        "mysql.slowlog.full_join": false,
+        "mysql.slowlog.full_scan": true,
+        "mysql.slowlog.id": "25844",
+        "mysql.slowlog.ip": "192.168.0.10",
+        "mysql.slowlog.lock_time.sec": "0.000000",
+        "mysql.slowlog.merge_passes": "0",
+        "mysql.slowlog.priority_queue": false,
+        "mysql.slowlog.query": "call PROC('blah');",
+        "mysql.slowlog.query_cache_hit": false,
+        "mysql.slowlog.query_time.sec": "178.306017",
+        "mysql.slowlog.rows_affected": "3062",
+        "mysql.slowlog.rows_examined": "53022772",
+        "mysql.slowlog.rows_sent": "0",
+        "mysql.slowlog.schema": "blah",
+        "mysql.slowlog.timestamp": "1547741058",
+        "mysql.slowlog.tmp_table": true,
+        "mysql.slowlog.tmp_table_on_disk": false,
+        "mysql.slowlog.user": "root",
+        "offset": 682,
+        "prospector.type": "log"
+    }
+]