# Postgres logs not properly parsed by filebeat **URL:** \ **Category:** Beats\ **Tags:** filebeat\ **Created:** [June 26, 2018, 6:19am UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371 "2018-06-26T06:19:11Z")\ **Posts on this page:** 12\ **Page:** 1
**Author:** ![amitphulera](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/amitphulera/32/31821_2.png) [@amitphulera](https://discuss.elastic.co/u/amitphulera)\ **Post date:** [June 26, 2018, 6:19am UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/1 "2018-06-26T06:19:12Z")
Hi, I have started with Elastic Stack recently. My use case is to monitor multiple raspberry pis with Beats module and visualize the data in Kibana Dashboards. I tried to set up Metricbeat and filebeat on Raspi 3, it was built and was running successfully. Now when I enabled the Postgres module, the data is still sent to elasticsearch but with the error message. Separate fields which are mentioned [here](https://www.elastic.co/guide/en/beats/filebeat/master/exported-fields-postgresql.html) Here is the single packet { "\_index": "filebeat-6.2.4-2018.06.25", "\_type": "doc", "\_id": "2NIFN2QBZiKLCXbASBWN", "\_version": 1, "\_score": null, "\_source": { "@timestamp": "2018-06-25T12:57:28.853Z", "offset": 5585, "beat": { "hostname": "RedisT1", "name": "RedisT1", "version": "6.2.4" }, "prospector": { "type": "log" }, "source": "/var/log/postgresql/postgresql-9.4-main.log.1", "message": "1970-01-01 09:00:08 +09 [620-1] LOG: autovacuum launcher started", "fileset": { "module": "postgresql", "name": "log" }, "error": { **"message": "Provided Grok expressions do not match field value: [1970-01-01 09:00:08 +09 [620-1] LOG: autovacuum launcher started]"** } }, "fields": { "@timestamp": [ "2018-06-25T12:57:28.853Z" ] }, "highlight": { "fileset.module": [ "@kibana-highlighted-field@postgresql@/kibana-highlighted-field@" ] }, "sort": [ 1529931448853 ] } I don't know the reason why filebeat is not able to parse the logs. I searched over internet but did not find anything that could be of use. Thanks. ---
**Author:** ![pierhugues](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/pierhugues/32/48383_2.png) [@pierhugues](https://discuss.elastic.co/u/pierhugues)\ **Post date:** [June 26, 2018, 2:44pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/2 "2018-06-26T14:44:42Z")
> [@amitphulera](#): > > 1970-01-01 09:00:08 +09 [620-1] LOG: autovacuum launcher started The above log format is a bit weird since its coming from 1970? You might want to configure NTP on your raspberry pi to make sure the time is correct. I haven't seen reports that ingest would fails when parsing a time. So I think we should fix the time on the machine first and we can move to ingest after if the problem persists. ---
**Author:** ![amitphulera](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/amitphulera/32/31821_2.png) [@amitphulera](https://discuss.elastic.co/u/amitphulera)\ **Post date:** [June 27, 2018, 6:05am UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/3 "2018-06-27T06:05:29Z")
Hi @pierhugues, Thanks for looking into the issue. The same is observed with other devices whose NTP is configured properly. I am unable to find the reason behind it. Can you please tell me what configuration/setting should I look into or share with you to debug this issue? Thanks. [EDIT] After fixing NTP also on same raspi the issue persists. Below is the data packet. { "\_index": "filebeat-6.2.4-2018.06.27", "\_type": "doc", "\_id": "vkyQQGQBovNMyNKZ2A7p", "\_version": 1, "\_score": null, "\_source": { "@timestamp": "2018-06-27T09:26:30.905Z", "offset": 191, "beat": { "hostname": "RedisT1", "name": "RedisT1", "version": "6.2.4" }, "prospector": { "type": "log" }, "source": "/var/log/postgresql/postgresql-9.4-main.log", "message": "2018-06-27 18:26:29 +09 [7484-2] LOG: MultiXact member wraparound protections are now enabled", "fileset": { "module": "postgresql", "name": "log" }, "error": { "message": "Provided Grok expressions do not match field value: [2018-06-27 18:26:29 +09 [7484-2] LOG: MultiXact member wraparound protections are now enabled]" } }, "fields": { "@timestamp": [ "2018-06-27T09:26:30.905Z" ] }, "highlight": { "fileset.module": [ "@kibana-highlighted-field@postgresql@/kibana-highlighted-field@" ] }, "sort": [ 1530091590905 ] } ---
**Author:** ![pierhugues](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/pierhugues/32/48383_2.png) [@pierhugues](https://discuss.elastic.co/u/pierhugues)\ **Post date:** [June 27, 2018, 1:01pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/4 "2018-06-27T13:01:39Z")
I've looked at the test cases that we have, we seem to support the format from postgresql 9.5 and 9.5, if you look closely the timezone values is different between the two format. ```auto 2017-07-31 13:36:42.585 CEST [4974] LOG: database system was shut down at 2017-06-17 16:58:04 CEST ``` CEST vs -09 The current regexp for the timezone trip for this value and cause the grok error. This look like a bug to me, we should support both format, I will create an issue. I don't know if there is a way to configuration postgresql 9.4 to emit the other format. ---
**Author:** ![pierhugues](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/pierhugues/32/48383_2.png) [@pierhugues](https://discuss.elastic.co/u/pierhugues)\ **Post date:** [June 27, 2018, 1:12pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/5 "2018-06-27T13:12:14Z")
I've created the following issue on our bug tracker. > ---
**Author:** ![amitphulera](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/amitphulera/32/31821_2.png) [@amitphulera](https://discuss.elastic.co/u/amitphulera)\ **Post date:** [June 29, 2018, 8:37am UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/6 "2018-06-29T08:37:03Z")
Hi @pierhugues Thanks for raising the issue. Now I have prepared a new Raspberry with Postgres 9.6 and the fields are populated correctly. I enabled syslogs module and it is also throwing the grok error. Below is the sample of system.auth. ` { "_index": "filebeat-6.2.4-2018.06.29", "_type": "doc", "_id": "ZFRASmQBuENH-QPg9rXP", "_version": 1, "_score": null, "_source": { "@timestamp": "2018-06-29T06:35:15.949Z", "offset": 589338, "beat": { "hostname": "JOULEBOX_OFFICE_DEVKIT", "name": "JOULEBOX_OFFICE_DEVKIT", "version": "6.2.4" }, "prospector": { "type": "log" }, "source": "/var/log/auth.log", "message": "Jun 29 01:45:01 JOULEBOX_OFFICE_DEVKIT CRON[9553]: pam_unix(cron:session): session opened for user root by (uid=0)", "fileset": { "module": "system", "name": "auth" }, "error": { "message": "Provided Grok expressions do not match field value: [Jun 29 01:45:01 JOULEBOX_OFFICE_DEVKIT CRON[9553]: pam_unix(cron:session): session opened for user root by (uid=0)]" } }, "fields": { "@timestamp": [ "2018-06-29T06:35:15.949Z" ] }, "sort": [ "/var/log/auth.log" ] } ` Now in case of system.syslog error is not thrown but log is not parsed correctly. ` { "_index": "filebeat-6.2.4-2018.06.29", "_type": "doc", "_id": "hlRBSmQBuENH-QPgdd7Q", "_version": 1, "_score": null, "_source": { "@timestamp": "2018-06-29T06:17:36.000Z", "system": { "syslog": { "message": "JOULEBOX_OFFICE_DEVKIT kernel: [58695.590145] w1_master_driver w1_bus_master1: Family 0 for 00.162000000000.81 is not registered.", "timestamp": "Jun 29 06:17:36" } }, "offset": 1854019, "beat": { "hostname": "JOULEBOX_OFFICE_DEVKIT", "name": "JOULEBOX_OFFICE_DEVKIT", "version": "6.2.4" }, "prospector": { "type": "log" }, "source": "/var/log/messages", "fileset": { "module": "system", "name": "syslog" } }, "fields": { "@timestamp": [ "2018-06-29T06:17:36.000Z" ] }, "highlight": { "source": [ "@kibana-highlighted-field@/var/log/messages@/kibana-highlighted-field@" ] }, "sort": [ "/var/log/messages" ] } ` Note that system.syslog contains message and timestamp only but it should be having other fields like user, pi, process which are there in fields.yml. ---
**Author:** ![pierhugues](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/pierhugues/32/48383_2.png) [@pierhugues](https://discuss.elastic.co/u/pierhugues)\ **Post date:** [June 29, 2018, 12:44pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/7 "2018-06-29T12:44:09Z")
> [@amitphulera](#): > > JOULEBOX\_OFFICE\_DEVKIT This is the hostname of your raspberry pi correct? A quick look at the syslog ingest pipeline, using`_` is not a valid hostname for the pipeline. ---
**Author:** ![amitphulera](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/amitphulera/32/31821_2.png) [@amitphulera](https://discuss.elastic.co/u/amitphulera)\ **Post date:** [June 29, 2018, 1:19pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/8 "2018-06-29T13:19:13Z")
Oh! Thanks @pierhugues. I was totally unaware of that. Is there any workaround for it? Where can I find the pattern for SYSLOGHOST which is mentioned in module/system/syslog/ingest/pipeline.json ? Are all these patterns predefined or they can be configured? ---
**Author:** ![pierhugues](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/pierhugues/32/48383_2.png) [@pierhugues](https://discuss.elastic.co/u/pierhugues)\ **Post date:** [June 29, 2018, 1:43pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/9 "2018-06-29T13:43:32Z")
@amitphulera I think you have 2 options: 1. Rename the raspberry pi host to remove '\_' 2. Update the ingest pipeline with a custom regular expression for the host. The `SYSLOGHOST` is coming from the default grok patterns shipped with elasticsearch, you have to follow a few levels of indirection, I think the problem is the 'HOSTNAME' defined in > You cannot change the patterns shipped with Elasticsearch without a PR, since `_` isn't really valid I don't think it will get merged. But you can define grok pattern only valid for a specific ingest pipeline and use that pipeline instead of the default that we ship with the syslog module. This is an extract of the Syslog ingest pipeline, you can see that we use one custom pattern. > ---
**Author:** ![amitphulera](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/amitphulera/32/31821_2.png) [@amitphulera](https://discuss.elastic.co/u/amitphulera)\ **Post date:** [June 30, 2018, 6:05am UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/10 "2018-06-30T06:05:02Z")
Thank you @pierhugues for the detailed answer. It cleared all my doubts 🙂 So renaming the host seems to be the most sensible thing for me to do. ---
**Author:** ![basilmusa](https://avatars.discourse-cdn.com/v4/letter/b/9f8e36/32.png) [@basilmusa](https://discuss.elastic.co/u/basilmusa)\ **Post date:** [July 1, 2018, 8:25pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/11 "2018-07-01T20:25:07Z")
I have this edge case shown below in my log file: ``` 2018-07-01 19:41:51.234 UTC [16015] replica@[unknown] ERROR: requested WAL segment 000000010000000000000008 has already been removed ``` This is failing at `replica@[unknown]` with the error `Provided Grok expressions do not match field value:` Filebeats is already handling the case `[user]@[db_name]` and `user@db_name` correctly. But `user@[unknown]` is not handled correctly and is failing to parse. I went to check the `postgresql.conf` at `/etc/postgresql/9.5/main` and it is showing the typical `log_line_prefix` (so nothing fishy there): ``` log_line_prefix = '%m [%p] %q%u@%d ' ``` So it seems the `[unknown]` is returned from PostgreSQL hardcoded in it's source code including the square brackets. Filebeat is failing because once the hostname is extracted as `[unknown]` it fails to match the regular expression of the `HOSTNAME` which is `\b(?:[0-9A-Za-z][0-9A-Za-z-]{0,62})(?:\.(?:[0-9A-Za-z][0-9A-Za-z-]{0,62}))*(\.?|\b)` The only way to handle this is to report it as an issue in filebeat and fix it by modifying the regular expression as: **Modified:** Notice the `USERNAME` and `POSTGRESQL_DB_NAME` are matched separately. `"^%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] ((\\[%{USERNAME:postgresql.log.user}\\]|%{USERNAME:postgresql.log.user})@(\\[%{POSTGRESQL_DB_NAME:postgresql.log.database}\\]|%{POSTGRESQL_DB_NAME:postgresql.log.database}) )?%{WORD:postgresql.log.level}: (duration: %{NUMBER:postgresql.log.duration} ms statement: %{GREEDYDATA:postgresql.log.query}|%{GREEDYDATA:postgresql.log.message})"` **Originally it was:** `"^%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] ((\\[%{USERNAME:postgresql.log.user}\\]@\\[%{POSTGRESQL_DB_NAME:postgresql.log.database}\\]|%{USERNAME:postgresql.log.user}@%{POSTGRESQL_DB_NAME:postgresql.log.database}) )?%{WORD:postgresql.log.level}: (duration: %{NUMBER:postgresql.log.duration} ms statement: %{GREEDYDATA:postgresql.log.query}|%{GREEDYDATA:postgresql.log.message})"` **The Difference Being This Part** : `((\\[%{USERNAME:postgresql.log.user}\\]|%{USERNAME:postgresql.log.user})@(\\[%{POSTGRESQL_DB_NAME:postgresql.log.database}\\]|%{POSTGRESQL_DB_NAME:postgresql.log.database}) )?%{WORD:postgresql.log.level}:` **Another Alternative Is:** `((\\[)?%{USERNAME:postgresql.log.user}(\\])?@((\\[)?%{POSTGRESQL_DB_NAME:postgresql.log.database}(\\])? )?%{WORD:postgresql.log.level}:` Also the following line should be added to the test cases: `2018-07-01 20:23:19.011 UTC [16848] replica@[unknown] ERROR: requested WAL segment 000000010000000000000008 has already been removed` The test case file should be: `beats/filebeat/module/postgresql/log/test/postgresql-ubuntu-9.5.log` What do you think? ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [July 29, 2018, 8:25pm UTC](https://discuss.elastic.co/t/postgres-logs-not-properly-parsed-by-filebeat/137371/12 "2018-07-29T20:25:16Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.