From 2054d3d87d5f1066057a7d3e21fb89a0ea56022e Mon Sep 17 00:00:00 2001 From: Mario Castro Date: Wed, 6 May 2020 00:50:13 +0200 Subject: [PATCH] Cherry-pick #17732 to 7.x: [Filebeat] Add support for v10, v11 and v12 Postgres logs with duration statement (#18253) --- CHANGELOG.next.asciidoc | 1 + filebeat/docs/modules/postgresql.asciidoc | 4 +- .../module/postgresql/_meta/docs.asciidoc | 4 +- .../module/postgresql/log/ingest/pipeline.yml | 6 +- .../log/test/postgresql-10-default.log | 20 ++ .../postgresql-10-default.log-expected.json | 155 ++++++++++++ .../postgresql-10-min-duration-statement.log | 17 ++ ...0-min-duration-statement.log-expected.json | 137 ++++++++++ .../log/test/postgresql-12-default.log | 10 + .../postgresql-12-default.log-expected.json | 212 ++++++++++++++++ .../postgresql-12-min-duration-statement.log | 21 ++ ...2-min-duration-statement.log-expected.json | 239 ++++++++++++++++++ 12 files changed, 817 insertions(+), 9 deletions(-) create mode 100644 filebeat/module/postgresql/log/test/postgresql-10-default.log create mode 100644 filebeat/module/postgresql/log/test/postgresql-10-default.log-expected.json create mode 100644 filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log create mode 100644 filebeat/module/postgresql/log/test/postgresql-10-min-duration-statement.log-expected.json create mode 100644 filebeat/module/postgresql/log/test/postgresql-12-default.log create mode 100644 filebeat/module/postgresql/log/test/postgresql-12-default.log-expected.json create mode 100644 filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log create mode 100644 filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log-expected.json diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index 026aaa98f30..a43dfd7a187 100644 --- 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 index 4392af35aa2..fad5132d40a 100644 --- 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 index 3aa5e02c227..ef7f3a25a5e 100644 --- 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 index bd7fbd69e7d..bd208d1eb72 100644 --- 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 new file mode 100644 index 00000000000..9d7ef78f5eb --- /dev/null +++ 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 new file mode 100644 index 00000000000..3f1f0fe1d58 --- /dev/null +++ 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" + } +] \ No newline at end of file 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 new file mode 100644 index 00000000000..1cc9817b195 --- /dev/null +++ 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 new file mode 100644 index 00000000000..d179a88067c --- /dev/null +++ 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" + } +] \ No newline at end of file diff --git a/filebeat/module/postgresql/log/test/postgresql-12-default.log b/filebeat/module/postgresql/log/test/postgresql-12-default.log new file mode 100644 index 00000000000..770f384134b --- /dev/null +++ b/filebeat/module/postgresql/log/test/postgresql-12-default.log @@ -0,0 +1,10 @@ +2020-04-16 11:45:11.844 CEST [26953] LOG: starting PostgreSQL 12.2 on x86_64-pc-linux-gnu, compiled by gcc (Arch Linux 9.3.0-1) 9.3.0, 64-bit +2020-04-16 11:45:11.844 CEST [26953] LOG: listening on IPv6 address "::1", port 5432 +2020-04-16 11:45:11.844 CEST [26953] LOG: listening on IPv4 address "127.0.0.1", port 5432 +2020-04-16 11:45:11.846 CEST [26953] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" +2020-04-16 11:45:11.861 CEST [26954] LOG: database system was shut down at 2020-04-16 11:45:01 CEST +2020-04-16 11:45:11.864 CEST [26953] LOG: database system is ready to accept connections +2020-04-16 12:22:22.579 CEST [26953] LOG: received smart shutdown request +2020-04-16 12:22:22.582 CEST [26953] LOG: background worker "logical replication launcher" (PID 26960) exited with exit code 1 +2020-04-16 12:22:22.582 CEST [26955] LOG: shutting down +2020-04-16 12:22:22.596 CEST [26953] LOG: database system is shut down diff --git a/filebeat/module/postgresql/log/test/postgresql-12-default.log-expected.json b/filebeat/module/postgresql/log/test/postgresql-12-default.log-expected.json new file mode 100644 index 00000000000..96918abc842 --- /dev/null +++ b/filebeat/module/postgresql/log/test/postgresql-12-default.log-expected.json @@ -0,0 +1,212 @@ +[ + { + "@timestamp": "2020-04-16T09:45:11.844Z", + "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": "starting PostgreSQL 12.2 on x86_64-pc-linux-gnu, compiled by gcc (Arch Linux 9.3.0-1) 9.3.0, 64-bit", + "postgresql.log.timestamp": "2020-04-16 11:45:11.844 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T09:45:11.844Z", + "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": 143, + "message": "listening on IPv6 address \"::1\", port 5432", + "postgresql.log.timestamp": "2020-04-16 11:45:11.844 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T09:45:11.844Z", + "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": 229, + "message": "listening on IPv4 address \"127.0.0.1\", port 5432", + "postgresql.log.timestamp": "2020-04-16 11:45:11.844 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T09:45:11.846Z", + "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": 321, + "message": "listening on Unix socket \"/tmp/.s.PGSQL.5432\"", + "postgresql.log.timestamp": "2020-04-16 11:45:11.846 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T09:45:11.861Z", + "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": 410, + "message": "database system was shut down at 2020-04-16 11:45:01 CEST", + "postgresql.log.timestamp": "2020-04-16 11:45:11.861 CEST", + "process.pid": 26954, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T09:45:11.864Z", + "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": 511, + "message": "database system is ready to accept connections", + "postgresql.log.timestamp": "2020-04-16 11:45:11.864 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:22:22.579Z", + "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": 601, + "message": "received smart shutdown request", + "postgresql.log.timestamp": "2020-04-16 12:22:22.579 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:22:22.582Z", + "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": 676, + "message": "background worker \"logical replication launcher\" (PID 26960) exited with exit code 1", + "postgresql.log.timestamp": "2020-04-16 12:22:22.582 CEST", + "process.pid": 26953, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:22:22.582Z", + "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": 804, + "message": "shutting down", + "postgresql.log.timestamp": "2020-04-16 12:22:22.582 CEST", + "process.pid": 26955, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:22:22.596Z", + "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": 861, + "message": "database system is shut down", + "postgresql.log.timestamp": "2020-04-16 12:22:22.596 CEST", + "process.pid": 26953, + "service.type": "postgresql" + } +] \ No newline at end of file diff --git a/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log b/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log new file mode 100644 index 00000000000..0d92eeb4122 --- /dev/null +++ b/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log @@ -0,0 +1,21 @@ +2020-04-16 12:48:36.677 CEST [34492] LOG: duration: 0.327 ms statement: select 1; +2020-04-16 12:48:40.316 CEST [34492] LOG: duration: 0.320 ms statement: select version(); +2020-04-16 12:48:44.696 CEST [34492] ERROR: column "name" does not exist at character 8 +2020-04-16 12:48:44.696 CEST [34492] STATEMENT: select name from user; +2020-04-16 12:49:16.871 CEST [34492] LOG: duration: 3.431 ms statement: CREATE TABLE weather ( + city varchar(80), + temp_lo int, + temp_hi int, + prcp real, + date date + ); +2020-04-16 12:49:19.866 CEST [34492] ERROR: relation "weather" already exists +2020-04-16 12:49:54.907 CEST [34492] LOG: duration: 3.039 ms statement: SELECT pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c WHERE c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(c.relname),1,2)='we' AND pg_catalog.pg_table_is_visible(c.oid) AND c.relnamespace <> (SELECT oid FROM pg_catalog.pg_namespace WHERE nspname = 'pg_catalog') + UNION + SELECT pg_catalog.quote_ident(n.nspname) || '.' FROM pg_catalog.pg_namespace n WHERE substring(pg_catalog.quote_ident(n.nspname) || '.',1,2)='we' AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) > 1 + UNION + SELECT pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c, pg_catalog.pg_namespace n WHERE c.relnamespace = n.oid AND c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname),1,2)='we' AND substring(pg_catalog.quote_ident(n.nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(n.nspname))+1) AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) = 1 + LIMIT 1000 +2020-04-16 12:49:55.464 CEST [34492] LOG: duration: 0.179 ms statement: select * From weather ; +2020-04-16 12:50:05.322 CEST [34492] LOG: duration: 1.661 ms statement: INSERT INTO weather VALUES ('San Francisco', 46, 50, 0.25, '1994-11-27'); +2020-04-16 12:50:06.741 CEST [34492] LOG: duration: 0.144 ms statement: select * From weather ; diff --git a/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log-expected.json b/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log-expected.json new file mode 100644 index 00000000000..74961ac0e74 --- /dev/null +++ b/filebeat/module/postgresql/log/test/postgresql-12-min-duration-statement.log-expected.json @@ -0,0 +1,239 @@ +[ + { + "@timestamp": "2020-04-16T10:48:36.677Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 327000, + "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": "2020-04-16 12:48:36.677 CEST [34492] LOG: duration: 0.327 ms statement: select 1;", + "postgresql.log.query": "select 1;", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:48:36.677 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:48:40.316Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 320000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.level": "LOG", + "log.offset": 84, + "message": "2020-04-16 12:48:40.316 CEST [34492] LOG: duration: 0.320 ms statement: select version();", + "postgresql.log.query": "select version();", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:48:40.316 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:48:44.696Z", + "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": 176, + "message": "column \"name\" does not exist at character 8", + "postgresql.log.timestamp": "2020-04-16 12:48:44.696 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:48:44.696Z", + "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": "STATEMENT", + "log.offset": 265, + "message": "select name from user;", + "postgresql.log.timestamp": "2020-04-16 12:48:44.696 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:49:16.871Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 3431000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.flags": [ + "multiline" + ], + "log.level": "LOG", + "log.offset": 337, + "message": "2020-04-16 12:49:16.871 CEST [34492] LOG: duration: 3.431 ms statement: CREATE TABLE weather (\n\t city varchar(80),\n\t temp_lo int,\n\t temp_hi int,\n\t prcp real,\n\t date date\n\t);", + "postgresql.log.query": "CREATE TABLE weather (\n\t city varchar(80),\n\t temp_lo int,\n\t temp_hi int,\n\t prcp real,\n\t date date\n\t);", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:49:16.871 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:49:19.866Z", + "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": 577, + "message": "relation \"weather\" already exists", + "postgresql.log.timestamp": "2020-04-16 12:49:19.866 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:49:54.907Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 3039000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.flags": [ + "multiline" + ], + "log.level": "LOG", + "log.offset": 656, + "message": "2020-04-16 12:49:54.907 CEST [34492] LOG: duration: 3.039 ms statement: SELECT pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c WHERE c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(c.relname),1,2)='we' AND pg_catalog.pg_table_is_visible(c.oid) AND c.relnamespace <> (SELECT oid FROM pg_catalog.pg_namespace WHERE nspname = 'pg_catalog')\n\tUNION\n\tSELECT pg_catalog.quote_ident(n.nspname) || '.' FROM pg_catalog.pg_namespace n WHERE substring(pg_catalog.quote_ident(n.nspname) || '.',1,2)='we' AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) > 1\n\tUNION\n\tSELECT pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c, pg_catalog.pg_namespace n WHERE c.relnamespace = n.oid AND c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname),1,2)='we' AND substring(pg_catalog.quote_ident(n.nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(n.nspname))+1) AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) = 1\n\tLIMIT 1000", + "postgresql.log.query": "SELECT pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c WHERE c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(c.relname),1,2)='we' AND pg_catalog.pg_table_is_visible(c.oid) AND c.relnamespace <> (SELECT oid FROM pg_catalog.pg_namespace WHERE nspname = 'pg_catalog')\n\tUNION\n\tSELECT pg_catalog.quote_ident(n.nspname) || '.' FROM pg_catalog.pg_namespace n WHERE substring(pg_catalog.quote_ident(n.nspname) || '.',1,2)='we' AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) > 1\n\tUNION\n\tSELECT pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c, pg_catalog.pg_namespace n WHERE c.relnamespace = n.oid AND c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname),1,2)='we' AND substring(pg_catalog.quote_ident(n.nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(n.nspname))+1) AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,2) = substring('we',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) = 1\n\tLIMIT 1000", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:49:54.907 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:49:55.464Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 179000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.level": "LOG", + "log.offset": 2066, + "message": "2020-04-16 12:49:55.464 CEST [34492] LOG: duration: 0.179 ms statement: select * From weather ;", + "postgresql.log.query": "select * From weather ;", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:49:55.464 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:50:05.322Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 1661000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.level": "LOG", + "log.offset": 2164, + "message": "2020-04-16 12:50:05.322 CEST [34492] LOG: duration: 1.661 ms statement: INSERT INTO weather VALUES ('San Francisco', 46, 50, 0.25, '1994-11-27');", + "postgresql.log.query": "INSERT INTO weather VALUES ('San Francisco', 46, 50, 0.25, '1994-11-27');", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:50:05.322 CEST", + "process.pid": 34492, + "service.type": "postgresql" + }, + { + "@timestamp": "2020-04-16T10:50:06.741Z", + "event.category": [ + "database" + ], + "event.dataset": "postgresql.log", + "event.duration": 144000, + "event.kind": "event", + "event.module": "postgresql", + "event.timezone": "CEST", + "event.type": [ + "info" + ], + "fileset.name": "log", + "input.type": "log", + "log.level": "LOG", + "log.offset": 2312, + "message": "2020-04-16 12:50:06.741 CEST [34492] LOG: duration: 0.144 ms statement: select * From weather ;", + "postgresql.log.query": "select * From weather ;", + "postgresql.log.query_step": "statement", + "postgresql.log.timestamp": "2020-04-16 12:50:06.741 CEST", + "process.pid": 34492, + "service.type": "postgresql" + } +] \ No newline at end of file