Cherry-pick #17732 to 7.x: [Filebeat] Add support for v10, v11 and v1…

…2 Postgres logs with duration statement (#18253)
elastic · May 5, 2020 · 2054d3d · 2054d3d
1 parent e0078f2
commit 2054d3d
Show file tree

Hide file tree

Showing 12 changed files with 817 additions and 9 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -379,6 +379,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - Improve ECS categorization field mappings in system module. {issue}16031[16031] {pull}18065[18065]
 - Change the `json.*` input settings implementation to merge parsed json objects with existing objects in the event instead of fully replacing them. {pull}17958[17958]
 - Improve ECS categorization field mappings in osquery module. {issue}16176[16176] {pull}17881[17881]
+- Add support for v10, v11 and v12 logs on Postgres {issue}13810[13810] {pull}17732[17732]
 
 *Heartbeat*
 

diff --git a/filebeat/docs/modules/postgresql.asciidoc b/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[]
 

diff --git a/filebeat/module/postgresql/_meta/docs.asciidoc b/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[]
 

diff --git a/filebeat/module/postgresql/log/ingest/pipeline.yml b/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: |-

diff --git a/filebeat/module/postgresql/log/test/postgresql-10-default.log b/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
+ ;
diff --git a/filebeat/module/postgresql/log/test/postgresql-10-default.log-expected.json b/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"
+ }
+]
diff --git a/filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log b/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
diff --git a/filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log-expected.json b/filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log-expected.json
@@ -0,0 +1,137 @@
+[
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.level": "DETAIL",
+ "log.offset": 0,
+ "message": "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'",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ },
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.duration": 112337000,
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.level": "LOG",
+ "log.offset": 189,
+ "message": "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",
+ "postgresql.log.query": "UPDATE qrtz_TRIGGERS SET TRIGGER_STATE = $1 WHERE SCHED_NAME = 'Scheduler_1' AND TRIGGER_NAME = $2 AND TRIGGER_GROUP = $3 AND TRIGGER_STATE = $4",
+ "postgresql.log.query_name": "S_59",
+ "postgresql.log.query_step": "execute",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ },
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.level": "DETAIL",
+ "log.offset": 400,
+ "message": "parameters: $1 = 'ACQUIRED', $2 = 'surveyInvitation_3Prbn85DiBWe8wHa_158802_77133_1260104', $3 = 'ExecutorsService', $4 = 'WAITING'",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ },
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.duration": 2474306816,
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.level": "LOG",
+ "log.offset": 565,
+ "message": "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",
+ "postgresql.log.query": "SELECT * FROM qrtz_LOCKS WHERE SCHED_NAME = 'Scheduler_1' AND LOCK_NAME = $1 FOR UPDATE",
+ "postgresql.log.query_name": "S_30",
+ "postgresql.log.query_step": "execute",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ },
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.level": "DETAIL",
+ "log.offset": 720,
+ "message": "parameters: $1 = 'TRIGGER_ACCESS'",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ },
+ {
+ "@timestamp": "2019-09-22T06:28:24.000Z",
+ "event.category": [
+ "database"
+ ],
+ "event.dataset": "postgresql.log",
+ "event.duration": 18327000,
+ "event.kind": "event",
+ "event.module": "postgresql",
+ "event.timezone": "UTC",
+ "event.type": [
+ "info"
+ ],
+ "fileset.name": "log",
+ "input.type": "log",
+ "log.flags": [
+ "multiline"
+ ],
+ "log.level": "LOG",
+ "log.offset": 787,
+ "message": "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,\n 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 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 FROM public.rc_audit_log_events AS al\n LEFT JOIN rc_crf_versions AS cv ON cv.id=al.crf_version_id\n LEFT JOIN rc_crfs AS crf ON crf.id=cv.crf_id\n LEFT JOIN ad_lookup_codes AS aet ON aet.id=al.audit_log_event_type_id\n LEFT JOIN rc_study_sites AS ss ON ss.id=al.study_site_id\n LEFT JOIN rc_subjects AS s ON s.id=al.subject_id\n LEFT JOIN rc_study_events AS se ON se.id=al.study_event_id\n LEFT JOIN rc_study_event_definitions AS sed ON sed.id=se.study_event_definition_id\n 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",
+ "postgresql.log.query": "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 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 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 FROM public.rc_audit_log_events AS al\n LEFT JOIN rc_crf_versions AS cv ON cv.id=al.crf_version_id\n LEFT JOIN rc_crfs AS crf ON crf.id=cv.crf_id\n LEFT JOIN ad_lookup_codes AS aet ON aet.id=al.audit_log_event_type_id\n LEFT JOIN rc_study_sites AS ss ON ss.id=al.study_site_id\n LEFT JOIN rc_subjects AS s ON s.id=al.subject_id\n LEFT JOIN rc_study_events AS se ON se.id=al.study_event_id\n LEFT JOIN rc_study_event_definitions AS sed ON sed.id=se.study_event_definition_id\n 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",
+ "postgresql.log.query_name": "S_32",
+ "postgresql.log.query_step": "execute",
+ "postgresql.log.timestamp": "2019-09-22 06:28:24 UTC",
+ "service.type": "postgresql"
+ }
+]