[Filebeat] Add support for v10, v11 and v12 Postgres logs with duration statement

CHANGELOG.next.asciidoc

@@ -282,6 +282,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - Add config option to select a different azure cloud env in the azure-eventhub input and azure module. {issue}17649[17649] {pull}17659[17659]
 - Added new Checkpoint Syslog filebeat module. {pull}17682[17682]
 - Improve ECS categorization field mappings for nats module. {issue}16173[16173] {pull}17550[17550]
+- Add support for v10, v11 and v12 logs on Postgres {issue}13810[13810] {pull}17732[17732]
 - Enhance `elasticsearch/server` fileset to handle ECS-compatible logs emitted by Elasticsearch. {issue}17715[17715] {pull}17714[17714]
 - Add support for Google Application Default Credentials to the Google Pub/Sub input and Google Cloud modules. {pull}15668[15668]
 - Enhance `elasticsearch/deprecation` fileset to handle ECS-compatible logs emitted by Elasticsearch. {issue}17715[17715] {pull}17728[17728]

filebeat/docs/modules/postgresql.asciidoc

@@ -18,8 +18,8 @@ include::../include/gs-link.asciidoc[]
 [float]
 === Compatibility
 
-The +{modulename}+ module was tested with logs from versions 9.5 on Ubuntu and 9.6
-on Debian.
+The +{modulename}+ module was tested with logs from versions 9.5 on Ubuntu, 9.6
+on Debian, and finally 10.11, 11.4 and 12.2 on Arch Linux 9.3.
 
 include::../include/configuring-intro.asciidoc[]
 

filebeat/module/postgresql/_meta/docs.asciidoc

@@ -13,8 +13,8 @@ include::../include/gs-link.asciidoc[]
 [float]
 === Compatibility
 
-The +{modulename}+ module was tested with logs from versions 9.5 on Ubuntu and 9.6
-on Debian.
+The +{modulename}+ module was tested with logs from versions 9.5 on Ubuntu, 9.6
+on Debian, and finally 10.11, 11.4 and 12.2 on Arch Linux 9.3.
 
 include::../include/configuring-intro.asciidoc[]
 

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

@@ -4,11 +4,7 @@ processors:
     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  %{POSTGRESQL_QUERY_STEP}: %{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: |-

filebeat/module/postgresql/log/test/postgresql-10-default.log

@@ -0,0 +1,20 @@
+2020-04-15 12:02:55.244 CEST [23922] LOG:  database system was shut down at 2020-04-15 12:02:52 CEST
+2020-04-15 12:02:55.247 CEST [23920] LOG:  database system is ready to accept connections
+2020-04-15 12:04:45.416 CEST [24981] FATAL:  password authentication failed for user "root"
+2020-04-15 12:04:45.416 CEST [24981] DETAIL:  Role "root" does not exist.
+	Connection matched pg_hba.conf line 80: "local   all             all                                     md5"
+2020-04-15 12:04:45.416 CEST [24981] LOG:  could not send data to client: Broken pipe
+2020-04-15 12:06:36.719 CEST [25143] ERROR:  syntax error at or near "l" at character 1
+2020-04-15 12:56:29.569 CEST [25143] STATEMENT:  SELECT al.id, al.tenant_id, al.created_by_id, al.create_ip, al.audit_date, al.audit_table, al.entity_id, al.entity_name, al.reason_for_change, al.audit_log_event_type_id,
+	        aet.lookup_code, al.old_value, al.new_value, al.event_crf_id, al.event_crf_version_id, al.study_id, al.study_site_id, ss.rc_oid, al.subject_id, s.unique_identifier,
+	        al.study_event_id, sed.name AS studyEventName, al.user_id, al.value_index, al.crf_version_id, al.global_logs, cv.version_name, crf.id AS crfId, crf.name AS crfName
+	         FROM public.rc_audit_log_events AS al
+	        LEFT JOIN rc_crf_versions AS cv ON cv.id=al.crf_version_id
+	            LEFT JOIN rc_crfs AS crf ON crf.id=cv.crf_id
+	            LEFT JOIN ad_lookup_codes AS aet ON aet.id=al.audit_log_event_type_id
+	            LEFT JOIN rc_study_sites AS ss ON ss.id=al.study_site_id
+	            LEFT JOIN rc_subjects AS s ON s.id=al.subject_id
+	            LEFT JOIN rc_study_events AS se ON se.id=al.study_event_id
+	            LEFT JOIN rc_study_event_definitions AS sed ON sed.id=se.study_event_definition_id
+	            WHERE al.tenant_id=$1 AND al.study_id=$2  AND aet.lookup_code IN ($3, $4, $5, $6) AND al.audit_date >= $7 ORDER BY al.id DESC  limit $8
+	;

filebeat/module/postgresql/log/test/postgresql-10-default.log-expected.json

@@ -0,0 +1,155 @@
+[
+    {
+        "@timestamp": "2020-04-15T10:02:55.244Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "LOG",
+        "log.offset": 0,
+        "message": "database system was shut down at 2020-04-15 12:02:52 CEST",
+        "postgresql.log.timestamp": "2020-04-15 12:02:55.244 CEST",
+        "process.pid": 23922,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:02:55.247Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "LOG",
+        "log.offset": 101,
+        "message": "database system is ready to accept connections",
+        "postgresql.log.timestamp": "2020-04-15 12:02:55.247 CEST",
+        "process.pid": 23920,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:04:45.416Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "FATAL",
+        "log.offset": 191,
+        "message": "password authentication failed for user \"root\"",
+        "postgresql.log.timestamp": "2020-04-15 12:04:45.416 CEST",
+        "process.pid": 24981,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:04:45.416Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "log.level": "DETAIL",
+        "log.offset": 283,
+        "message": "Role \"root\" does not exist.\n\tConnection matched pg_hba.conf line 80: \"local   all             all                                     md5\"",
+        "postgresql.log.timestamp": "2020-04-15 12:04:45.416 CEST",
+        "process.pid": 24981,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:04:45.416Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "LOG",
+        "log.offset": 468,
+        "message": "could not send data to client: Broken pipe",
+        "postgresql.log.timestamp": "2020-04-15 12:04:45.416 CEST",
+        "process.pid": 24981,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:06:36.719Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.level": "ERROR",
+        "log.offset": 554,
+        "message": "syntax error at or near \"l\" at character 1",
+        "postgresql.log.timestamp": "2020-04-15 12:06:36.719 CEST",
+        "process.pid": 25143,
+        "service.type": "postgresql"
+    },
+    {
+        "@timestamp": "2020-04-15T10:56:29.569Z",
+        "event.category": [
+            "database"
+        ],
+        "event.dataset": "postgresql.log",
+        "event.kind": "event",
+        "event.module": "postgresql",
+        "event.timezone": "CEST",
+        "event.type": [
+            "info"
+        ],
+        "fileset.name": "log",
+        "input.type": "log",
+        "log.flags": [
+            "multiline"
+        ],
+        "log.level": "STATEMENT",
+        "log.offset": 642,
+        "message": "SELECT al.id, al.tenant_id, al.created_by_id, al.create_ip, al.audit_date, al.audit_table, al.entity_id, al.entity_name, al.reason_for_change, al.audit_log_event_type_id,\n\t        aet.lookup_code, al.old_value, al.new_value, al.event_crf_id, al.event_crf_version_id, al.study_id, al.study_site_id, ss.rc_oid, al.subject_id, s.unique_identifier,\n\t        al.study_event_id, sed.name AS studyEventName, al.user_id, al.value_index, al.crf_version_id, al.global_logs, cv.version_name, crf.id AS crfId, crf.name AS crfName\n\t         FROM public.rc_audit_log_events AS al\n\t        LEFT JOIN rc_crf_versions AS cv ON cv.id=al.crf_version_id\n\t            LEFT JOIN rc_crfs AS crf ON crf.id=cv.crf_id\n\t            LEFT JOIN ad_lookup_codes AS aet ON aet.id=al.audit_log_event_type_id\n\t            LEFT JOIN rc_study_sites AS ss ON ss.id=al.study_site_id\n\t            LEFT JOIN rc_subjects AS s ON s.id=al.subject_id\n\t            LEFT JOIN rc_study_events AS se ON se.id=al.study_event_id\n\t            LEFT JOIN rc_study_event_definitions AS sed ON sed.id=se.study_event_definition_id\n\t            WHERE al.tenant_id=$1 AND al.study_id=$2  AND aet.lookup_code IN ($3, $4, $5, $6) AND al.audit_date >= $7 ORDER BY al.id DESC  limit $8\n\t;",
+        "postgresql.log.timestamp": "2020-04-15 12:56:29.569 CEST",
+        "process.pid": 25143,
+        "service.type": "postgresql"
+    }
+]

filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log

@@ -0,0 +1,17 @@
+2019-09-22 06:28:24 UTC DETAIL:  parameters: $1 = '86', $2 = '575', $3 = 'Item Inserted', $4 = 'Item Updated', $5 = 'Subject Updated', $6 = 'Subject Created', $7 = '2019-01-22 00:00:00+00'
+2019-09-22 06:28:24 UTC LOG:  duration: 112.337 ms  execute S_59: UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = $1 WHERE SCHED_NAME = 'Scheduler_1' AND TRIGGER_NAME = $2 AND TRIGGER_GROUP = $3 AND TRIGGER_STATE = $4
+2019-09-22 06:28:24 UTC DETAIL:  parameters: $1 = 'ACQUIRED', $2 = 'surveyInvitation_3Prbn85DiBWe8wHa_158802_77133_1260104', $3 = 'ExecutorsService', $4 = 'WAITING'
+2019-09-22 06:28:24 UTC LOG:  duration: 2474.307 ms  execute S_30: SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'Scheduler_1' AND LOCK_NAME = $1 FOR UPDATE
+2019-09-22 06:28:24 UTC DETAIL:  parameters: $1 = 'TRIGGER_ACCESS'
+2019-09-22 06:28:24 UTC LOG:  duration: 18.327 ms  execute S_32: SELECT al.id, al.tenant_id, al.created_by_id, al.create_ip, al.audit_date, al.audit_table, al.entity_id, al.entity_name, al.reason_for_change, al.audit_log_event_type_id,
+        aet.lookup_code, al.old_value, al.new_value, al.event_crf_id, al.event_crf_version_id, al.study_id, al.study_site_id, ss.rc_oid, al.subject_id, s.unique_identifier,
+        al.study_event_id, sed.name AS studyEventName, al.user_id, al.value_index, al.crf_version_id, al.global_logs, cv.version_name, crf.id AS crfId, crf.name AS crfName
+         FROM public.rc_audit_log_events AS al
+        LEFT JOIN rc_crf_versions AS cv ON cv.id=al.crf_version_id
+            LEFT JOIN rc_crfs AS crf ON crf.id=cv.crf_id
+            LEFT JOIN ad_lookup_codes AS aet ON aet.id=al.audit_log_event_type_id
+            LEFT JOIN rc_study_sites AS ss ON ss.id=al.study_site_id
+            LEFT JOIN rc_subjects AS s ON s.id=al.subject_id
+            LEFT JOIN rc_study_events AS se ON se.id=al.study_event_id
+            LEFT JOIN rc_study_event_definitions AS sed ON sed.id=se.study_event_definition_id
+            WHERE al.tenant_id=$1 AND al.study_id=$2  AND aet.lookup_code IN ($3, $4, $5, $6) AND al.audit_date >= $7 ORDER BY al.id DESC  limit $8