Properly parse the timezone in PostgreSQL logs

Parse the timezone in PostgreSQL logs as part of the date.
elastic · May 29, 2019 · ba6de6a · ba6de6a
1 parent 7696c04
commit ba6de6a
Show file tree

Hide file tree

Showing 6 changed files with 215 additions and 215 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -106,6 +106,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - Fix goroutine leak caused on initialization failures of log input. {pull}12125[12125]
 - Fix goroutine leak on non-explicit finalization of log input. {pull}12164[12164]
 - Skipping unparsable log entries from docker json reader {pull}12268[12268]
+- Parse timezone in PostgreSQL logs as part of the timestamp {pull}12338[12338]
 
 *Heartbeat*
 

diff --git a/filebeat/module/postgresql/log/ingest/pipeline.json b/filebeat/module/postgresql/log/ingest/pipeline.json
@@ -6,10 +6,10 @@
         "field": "message",
         "ignore_missing": true,
         "patterns": [
-            "^%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:event.timezone} \\[%{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}:  (duration: %{NUMBER:temp.duration:float} ms  statement: %{GREEDYDATA:postgresql.log.query}|%{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}:  (duration: %{NUMBER:temp.duration:float} ms  statement: %{GREEDYDATA:postgresql.log.query}|%{GREEDYDATA:message})"
         ],
         "pattern_definitions": {
-          "LOCALDATETIME": "[-0-9]+ %{TIME}",
+          "DATETIME": "[-0-9]+ %{TIME} %{WORD:event.timezone}",
           "GREEDYDATA": "(.|\n|\t)*",
           "POSTGRESQL_DB_NAME": "[a-zA-Z0-9_]+[a-zA-Z0-9_\\$]*"
         }
@@ -20,9 +20,8 @@
         "field": "postgresql.log.timestamp",
         "target_field": "@timestamp",
         "formats": [
-          "yyyy-MM-dd HH:mm:ss.SSS", "yyyy-MM-dd HH:mm:ss"
-        ],
-        "ignore_failure": true
+          "yyyy-MM-dd HH:mm:ss.SSS zz", "yyyy-MM-dd HH:mm:ss zz"
+        ]
       }
     }, {
       "script": {

diff --git a/filebeat/module/postgresql/log/test/postgresql-9.6-debian-with-slowlog.log-expected.json b/filebeat/module/postgresql/log/test/postgresql-9.6-debian-with-slowlog.log-expected.json
@@ -1,6 +1,6 @@
 [
     {
-        "@timestamp": "2017-07-31T13:36:42.585Z",
+        "@timestamp": "2017-07-31T11:36:42.585Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -10,12 +10,12 @@
         "log.level": "LOG",
         "log.offset": 0,
         "message": "database system was shut down at 2017-06-17 16:58:04 CEST",
-        "postgresql.log.timestamp": "2017-07-31 13:36:42.585",
+        "postgresql.log.timestamp": "2017-07-31 13:36:42.585 CEST",
         "process.pid": 4974,
         "service.type": "postgresql"
     },
     {
-        "@timestamp": "2017-07-31T13:36:42.605Z",
+        "@timestamp": "2017-07-31T11:36:42.605Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -25,12 +25,12 @@
         "log.level": "LOG",
         "log.offset": 100,
         "message": "MultiXact member wraparound protections are now enabled",
-        "postgresql.log.timestamp": "2017-07-31 13:36:42.605",
+        "postgresql.log.timestamp": "2017-07-31 13:36:42.605 CEST",
         "process.pid": 4974,
         "service.type": "postgresql"
     },
     {
-        "@timestamp": "2017-07-31T13:36:42.615Z",
+        "@timestamp": "2017-07-31T11:36:42.615Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -40,12 +40,12 @@
         "log.level": "LOG",
         "log.offset": 198,
         "message": "autovacuum launcher started",
-        "postgresql.log.timestamp": "2017-07-31 13:36:42.615",
+        "postgresql.log.timestamp": "2017-07-31 13:36:42.615 CEST",
         "process.pid": 4978,
         "service.type": "postgresql"
     },
     {
-        "@timestamp": "2017-07-31T13:36:42.616Z",
+        "@timestamp": "2017-07-31T11:36:42.616Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -55,12 +55,12 @@
         "log.level": "LOG",
         "log.offset": 268,
         "message": "database system is ready to accept connections",
-        "postgresql.log.timestamp": "2017-07-31 13:36:42.616",
+        "postgresql.log.timestamp": "2017-07-31 13:36:42.616 CEST",
         "process.pid": 4973,
         "service.type": "postgresql"
     },
     {
-        "@timestamp": "2017-07-31T13:36:42.956Z",
+        "@timestamp": "2017-07-31T11:36:42.956Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -71,13 +71,13 @@
         "log.offset": 357,
         "message": "incomplete startup packet",
         "postgresql.log.database": "unknown",
-        "postgresql.log.timestamp": "2017-07-31 13:36:42.956",
+        "postgresql.log.timestamp": "2017-07-31 13:36:42.956 CEST",
         "process.pid": 4980,
         "service.type": "postgresql",
         "user.name": "unknown"
     },
     {
-        "@timestamp": "2017-07-31T13:36:43.557Z",
+        "@timestamp": "2017-07-31T11:36:43.557Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 37118000,
@@ -93,13 +93,13 @@
         "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.timestamp": "2017-07-31 13:36:43.557",
+        "postgresql.log.timestamp": "2017-07-31 13:36:43.557 CEST",
         "process.pid": 4983,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:36:44.104Z",
+        "@timestamp": "2017-07-31T11:36:44.104Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 2895000,
@@ -115,13 +115,13 @@
         "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.timestamp": "2017-07-31 13:36:44.104",
+        "postgresql.log.timestamp": "2017-07-31 13:36:44.104 CEST",
         "process.pid": 4986,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:36:44.642Z",
+        "@timestamp": "2017-07-31T11:36:44.642Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 2809000,
@@ -137,13 +137,13 @@
         "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.timestamp": "2017-07-31 13:36:44.642",
+        "postgresql.log.timestamp": "2017-07-31 13:36:44.642 CEST",
         "process.pid": 4989,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:39:16.249Z",
+        "@timestamp": "2017-07-31T11:39:16.249Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -154,13 +154,13 @@
         "log.offset": 1727,
         "message": "database \"users\" does not exist",
         "postgresql.log.database": "users",
-        "postgresql.log.timestamp": "2017-07-31 13:39:16.249",
+        "postgresql.log.timestamp": "2017-07-31 13:39:16.249 CEST",
         "process.pid": 5407,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:39:17.945Z",
+        "@timestamp": "2017-07-31T11:39:17.945Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.module": "postgresql",
@@ -171,13 +171,13 @@
         "log.offset": 1818,
         "message": "database \"user\" does not exist",
         "postgresql.log.database": "user",
-        "postgresql.log.timestamp": "2017-07-31 13:39:17.945",
+        "postgresql.log.timestamp": "2017-07-31 13:39:17.945 CEST",
         "process.pid": 5500,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:39:21.025Z",
+        "@timestamp": "2017-07-31T11:39:21.025Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 37598000,
@@ -193,13 +193,13 @@
         "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.timestamp": "2017-07-31 13:39:21.025",
+        "postgresql.log.timestamp": "2017-07-31 13:39:21.025 CEST",
         "process.pid": 5404,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:39:31.619Z",
+        "@timestamp": "2017-07-31T11:39:31.619Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 9482000,
@@ -212,13 +212,13 @@
         "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.timestamp": "2017-07-31 13:39:31.619",
+        "postgresql.log.timestamp": "2017-07-31 13:39:31.619 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:39:40.147Z",
+        "@timestamp": "2017-07-31T11:39:40.147Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 765000,
@@ -231,13 +231,13 @@
         "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.timestamp": "2017-07-31 13:39:40.147",
+        "postgresql.log.timestamp": "2017-07-31 13:39:40.147 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:40:54.310Z",
+        "@timestamp": "2017-07-31T11:40:54.310Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 26082001,
@@ -253,13 +253,13 @@
         "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.timestamp": "2017-07-31 13:40:54.310",
+        "postgresql.log.timestamp": "2017-07-31 13:40:54.310 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:43:22.645Z",
+        "@timestamp": "2017-07-31T11:43:22.645Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 36161999,
@@ -272,13 +272,13 @@
         "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.timestamp": "2017-07-31 13:43:22.645",
+        "postgresql.log.timestamp": "2017-07-31 13:43:22.645 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:46:02.670Z",
+        "@timestamp": "2017-07-31T11:46:02.670Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 10540000,
@@ -291,13 +291,13 @@
         "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.timestamp": "2017-07-31 13:46:02.670",
+        "postgresql.log.timestamp": "2017-07-31 13:46:02.670 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:46:23.016Z",
+        "@timestamp": "2017-07-31T11:46:23.016Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 5156000,
@@ -310,13 +310,13 @@
         "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.timestamp": "2017-07-31 13:46:23.016",
+        "postgresql.log.timestamp": "2017-07-31 13:46:23.016 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"
     },
     {
-        "@timestamp": "2017-07-31T13:46:55.637Z",
+        "@timestamp": "2017-07-31T11:46:55.637Z",
         "ecs.version": "1.0.0",
         "event.dataset": "postgresql.log",
         "event.duration": 25871000,
@@ -329,7 +329,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.timestamp": "2017-07-31 13:46:55.637",
+        "postgresql.log.timestamp": "2017-07-31 13:46:55.637 CEST",
         "process.pid": 5502,
         "service.type": "postgresql",
         "user.name": "postgres"