Parse query steps in postgresql slowlog (#13701)

Slow logs in PostgreSQL can log information per query step. Parse and
collect the query step and the assigned query name if present.

Fix #13496

CHANGELOG.next.asciidoc

@@ -307,6 +307,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - Add timezone information to apache error fileset. {issue}12772[12772] {pull}13304[13304]
 - Add module for ingesting Cisco FTD logs over syslog. {pull}13286[13286]
 - Update CoreDNS module to populate ECS DNS fields. {issue}13320[13320] {pull}13505[13505]
+- Parse query steps in PostgreSQL slowlogs. {issue}13496[13496] {pull}13701[13701]
 
 *Heartbeat*
 

filebeat/docs/fields.asciidoc

@@ -13937,6 +13937,7 @@ type: long
 --
 Name of database
 
+
 example: mydb
 
 --
@@ -13946,10 +13947,31 @@ example: mydb
 --
 Query statement.
 
+
 example: SELECT * FROM users;
 
 --
 
+*`postgresql.log.query_step`*::
++
+--
+Statement step when using extended query protocol (one of statement, parse, bind or execute)
+
+
+example: parse
+
+--
+
+*`postgresql.log.query_name`*::
++
+--
+Name given to a query when using extended query protocol. If it is "<unnamed>", or not present, this field is ignored.
+
+
+example: pdo_stmt_00000001
+
+--
+
 *`postgresql.log.error.code`*::
 +
 --

filebeat/module/postgresql/log/_meta/fields.yml

@@ -13,12 +13,21 @@
         Core id
     - name: database
       example: "mydb"
-      description:
+      description: >
         Name of database
     - name: query
       example: "SELECT * FROM users;"
-      description:
+      description: >
         Query statement.
+    - name: query_step
+      example: "parse"
+      description: >
+        Statement step when using extended query protocol (one of statement, parse, bind or execute)
+    - name: query_name
+      example: "pdo_stmt_00000001"
+      description: >
+        Name given to a query when using extended query protocol. If it is "<unnamed>", or not present,
+        this field is ignored.
 
     - name: error.code
       type: long

filebeat/module/postgresql/log/ingest/pipeline.json

@@ -6,12 +6,13 @@
         "field": "message",
         "ignore_missing": true,
         "patterns": [
-            "^%{DATETIME:postgresql.log.timestamp} \\[%{NUMBER:process.pid:long}(-%{BASE16FLOAT:postgresql.log.core_id:long})?\\] ((\\[%{USERNAME:user.name}\\]@\\[%{POSTGRESQL_DB_NAME:postgresql.log.database}\\]|%{USERNAME:user.name}@%{POSTGRESQL_DB_NAME:postgresql.log.database}) )?%{WORD:log.level}:  (?:%{NUMBER:postgresql.log.error.code:long}|%{SPACE})(duration: %{NUMBER:temp.duration:float} ms  statement: %{GREEDYDATA:postgresql.log.query}|: %{GREEDYDATA:message}|%{GREEDYDATA:message})"
+            "^%{DATETIME:postgresql.log.timestamp} \\[%{NUMBER:process.pid:long}(-%{BASE16FLOAT:postgresql.log.core_id:long})?\\] ((\\[%{USERNAME:user.name}\\]@\\[%{POSTGRESQL_DB_NAME:postgresql.log.database}\\]|%{USERNAME:user.name}@%{POSTGRESQL_DB_NAME:postgresql.log.database}) )?%{WORD:log.level}:  (?:%{NUMBER:postgresql.log.error.code:long}|%{SPACE})(duration: %{NUMBER:temp.duration:float} ms  %{POSTGRESQL_QUERY_STEP}: %{GREEDYDATA:postgresql.log.query}|: %{GREEDYDATA:message}|%{GREEDYDATA:message})"
         ],
         "pattern_definitions": {
           "DATETIME": "[-0-9]+ %{TIME} %{WORD:event.timezone}",
           "GREEDYDATA": "(.|\n|\t)*",
-          "POSTGRESQL_DB_NAME": "[a-zA-Z0-9_]+[a-zA-Z0-9_\\$]*"
+          "POSTGRESQL_DB_NAME": "[a-zA-Z0-9_]+[a-zA-Z0-9_\\$]*",
+          "POSTGRESQL_QUERY_STEP": "%{WORD:postgresql.log.query_step}(?: <unnamed>| %{WORD:postgresql.log.query_name})?"
         }
       }
     },

filebeat/module/postgresql/log/test/postgresql-9.6-debian-with-slowlog.log-expected.json

@@ -87,6 +87,7 @@
         "message": "2017-07-31 13:36:43.557 CEST [4983] postgres@postgres LOG:  duration: 37.118 ms  statement: SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
         "postgresql.log.database": "postgres",
         "postgresql.log.query": "SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:36:43.557 CEST",
         "process.pid": 4983,
         "service.type": "postgresql",
@@ -108,6 +109,7 @@
         "message": "2017-07-31 13:36:44.104 CEST [4986] postgres@postgres LOG:  duration: 2.895 ms  statement: SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
         "postgresql.log.database": "postgres",
         "postgresql.log.query": "SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:36:44.104 CEST",
         "process.pid": 4986,
         "service.type": "postgresql",
@@ -129,6 +131,7 @@
         "message": "2017-07-31 13:36:44.642 CEST [4989] postgres@postgres LOG:  duration: 2.809 ms  statement: SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
         "postgresql.log.database": "postgres",
         "postgresql.log.query": "SELECT d.datname as \"Name\",\n\t       pg_catalog.pg_get_userbyid(d.datdba) as \"Owner\",\n\t       pg_catalog.pg_encoding_to_char(d.encoding) as \"Encoding\",\n\t       d.datcollate as \"Collate\",\n\t       d.datctype as \"Ctype\",\n\t       pg_catalog.array_to_string(d.datacl, E'\\n') AS \"Access privileges\"\n\tFROM pg_catalog.pg_database d\n\tORDER BY 1;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:36:44.642 CEST",
         "process.pid": 4989,
         "service.type": "postgresql",
@@ -182,6 +185,7 @@
         "message": "2017-07-31 13:39:21.025 CEST [5404] postgres@postgres LOG:  duration: 37.598 ms  statement: SELECT n.nspname as \"Schema\",\n\t  c.relname as \"Name\",\n\t  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as \"Type\",\n\t  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\n\tFROM pg_catalog.pg_class c\n\t     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\n\tWHERE c.relkind IN ('r','')\n\t      AND n.nspname <> 'pg_catalog'\n\t      AND n.nspname <> 'information_schema'\n\t      AND n.nspname !~ '^pg_toast'\n\t  AND pg_catalog.pg_table_is_visible(c.oid)\n\tORDER BY 1,2;",
         "postgresql.log.database": "postgres",
         "postgresql.log.query": "SELECT n.nspname as \"Schema\",\n\t  c.relname as \"Name\",\n\t  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as \"Type\",\n\t  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\n\tFROM pg_catalog.pg_class c\n\t     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\n\tWHERE c.relkind IN ('r','')\n\t      AND n.nspname <> 'pg_catalog'\n\t      AND n.nspname <> 'information_schema'\n\t      AND n.nspname !~ '^pg_toast'\n\t  AND pg_catalog.pg_table_is_visible(c.oid)\n\tORDER BY 1,2;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:39:21.025 CEST",
         "process.pid": 5404,
         "service.type": "postgresql",
@@ -200,6 +204,7 @@
         "message": "2017-07-31 13:39:31.619 CEST [5502] postgres@clients LOG:  duration: 9.482 ms  statement: select * from clients;",
         "postgresql.log.database": "clients",
         "postgresql.log.query": "select * from clients;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:39:31.619 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -218,6 +223,7 @@
         "message": "2017-07-31 13:39:40.147 CEST [5502] postgres@clients LOG:  duration: 0.765 ms  statement: select id from clients;",
         "postgresql.log.database": "clients",
         "postgresql.log.query": "select id from clients;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:39:40.147 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -239,6 +245,7 @@
         "message": "2017-07-31 13:40:54.310 CEST [5502] postgres@clients LOG:  duration: 26.082 ms  statement: SELECT n.nspname as \"Schema\",\n\t  c.relname as \"Name\",\n\t  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as \"Type\",\n\t  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\n\tFROM pg_catalog.pg_class c\n\t     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\n\tWHERE c.relkind IN ('r','')\n\t      AND n.nspname <> 'pg_catalog'\n\t      AND n.nspname <> 'information_schema'\n\t      AND n.nspname !~ '^pg_toast'\n\t  AND pg_catalog.pg_table_is_visible(c.oid)\n\tORDER BY 1,2;",
         "postgresql.log.database": "clients",
         "postgresql.log.query": "SELECT n.nspname as \"Schema\",\n\t  c.relname as \"Name\",\n\t  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as \"Type\",\n\t  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\n\tFROM pg_catalog.pg_class c\n\t     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\n\tWHERE c.relkind IN ('r','')\n\t      AND n.nspname <> 'pg_catalog'\n\t      AND n.nspname <> 'information_schema'\n\t      AND n.nspname !~ '^pg_toast'\n\t  AND pg_catalog.pg_table_is_visible(c.oid)\n\tORDER BY 1,2;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:40:54.310 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -257,6 +264,7 @@
         "message": "2017-07-31 13:43:22.645 CEST [5502] postgres@clients LOG:  duration: 36.162 ms  statement: create table cats(name varchar(50) primary key, toy varchar (50) not null, born timestamp not null);",
         "postgresql.log.database": "clients",
         "postgresql.log.query": "create table cats(name varchar(50) primary key, toy varchar (50) not null, born timestamp not null);",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:43:22.645 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -275,6 +283,7 @@
         "message": "2017-07-31 13:46:02.670 CEST [5502] postgres@c$lients LOG:  duration: 10.540 ms  statement: insert into cats(name, toy, born) values('kate', 'ball', now());",
         "postgresql.log.database": "c$lients",
         "postgresql.log.query": "insert into cats(name, toy, born) values('kate', 'ball', now());",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:46:02.670 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -293,6 +302,7 @@
         "message": "2017-07-31 13:46:23.016 CEST [5502] postgres@_clients$db LOG:  duration: 5.156 ms  statement: insert into cats(name, toy, born) values('frida', 'horse', now());",
         "postgresql.log.database": "_clients$db",
         "postgresql.log.query": "insert into cats(name, toy, born) values('frida', 'horse', now());",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:46:23.016 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -311,6 +321,7 @@
         "message": "2017-07-31 13:46:55.637 CEST [5502] postgres@clients_db LOG:  duration: 25.871 ms  statement: create table dogs(name varchar(50) primary key, owner varchar (50) not null, born timestamp not null);",
         "postgresql.log.database": "clients_db",
         "postgresql.log.query": "create table dogs(name varchar(50) primary key, owner varchar (50) not null, born timestamp not null);",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-07-31 13:46:55.637 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
@@ -332,6 +343,7 @@
         "message": "2019-05-06 19:00:04.511 UTC [913763] elastic@opbeans LOG:  duration: 0.753 ms  statement: SELECT p.id, p.sku, p.name, p.stock, t.name AS type_name FROM products p LEFT JOIN product_types t ON p.type_id=t.id\n    FROM orders JOIN customers ON orders.customer_id=customers.id\n    FROM products JOIN product_types ON type_id=product_types.id",
         "postgresql.log.database": "opbeans",
         "postgresql.log.query": "SELECT p.id, p.sku, p.name, p.stock, t.name AS type_name FROM products p LEFT JOIN product_types t ON p.type_id=t.id\n    FROM orders JOIN customers ON orders.customer_id=customers.id\n    FROM products JOIN product_types ON type_id=product_types.id",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2019-05-06 19:00:04.511 UTC",
         "process.pid": 913763,
         "service.type": "postgresql",

filebeat/module/postgresql/log/test/postgresql-9.6-multi-core.log-expected.json

@@ -50,6 +50,7 @@
         "postgresql.log.core_id": 2,
         "postgresql.log.database": "postgres",
         "postgresql.log.query": "SELECT n.nspname as \"Schema\",\n\t  c.relname as \"Name\",\n\t  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as \"Type\",\n\t  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\n\tFROM pg_catalog.pg_class c\n\t     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\n\tWHERE c.relkind IN ('r','')\n\t      AND n.nspname <> 'pg_catalog'\n\t      AND n.nspname <> 'information_schema'\n\t      AND n.nspname !~ '^pg_toast'\n\t  AND pg_catalog.pg_table_is_visible(c.oid)\n\tORDER BY 1,2;",
+        "postgresql.log.query_step": "statement",
         "postgresql.log.timestamp": "2017-04-03 22:35:22.389 CEST",
         "process.pid": 5404,
         "service.type": "postgresql",

filebeat/module/postgresql/log/test/postgresql-query-steps-slowlog.log

@@ -0,0 +1,3 @@
+2019-09-04 15:52:38.004 CEST [31136] user@host LOG:  duration: 12.437 ms  parse <unnamed>: select * from table
+2019-09-04 15:52:38.004 CEST [31136] user@host LOG:  duration: 12.437 ms  execute pdo_stmt_00000002: select * from table
+

filebeat/module/postgresql/log/test/postgresql-query-steps-slowlog.log-expected.json

@@ -0,0 +1,44 @@
+[
+    {
+        "@timestamp": "2019-09-04T13:52:38.004Z",
+        "event.dataset": "postgresql.log",
+        "event.duration": 12437000,
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "LOG",
+        "log.offset": 0,
+        "message": "2019-09-04 15:52:38.004 CEST [31136] user@host LOG:  duration: 12.437 ms  parse <unnamed>: select * from table",
+        "postgresql.log.database": "host",
+        "postgresql.log.query": "select * from table",
+        "postgresql.log.query_step": "parse",
+        "postgresql.log.timestamp": "2019-09-04 15:52:38.004 CEST",
+        "process.pid": 31136,
+        "service.type": "postgresql",
+        "user.name": "user"
+    },
+    {
+        "@timestamp": "2019-09-04T13:52:38.004Z",
+        "event.dataset": "postgresql.log",
+        "event.duration": 12437000,
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "log.level": "LOG",
+        "log.offset": 111,
+        "message": "2019-09-04 15:52:38.004 CEST [31136] user@host LOG:  duration: 12.437 ms  execute pdo_stmt_00000002: select * from table\n",
+        "postgresql.log.database": "host",
+        "postgresql.log.query": "select * from table\n",
+        "postgresql.log.query_name": "pdo_stmt_00000002",
+        "postgresql.log.query_step": "execute",
+        "postgresql.log.timestamp": "2019-09-04 15:52:38.004 CEST",
+        "process.pid": 31136,
+        "service.type": "postgresql",
+        "user.name": "user"
+    }
+]