Postgres logs not properly parsed by filebeat

Elastic Stack Beats
1

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
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.

1 Like
2

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.

3

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
]
}

4

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.

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.

5

I've created the following issue on our bug tracker.

6

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.

7

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.

1 Like
8

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?

9

@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.

1 Like
10

Thank you @pierhugues for the detailed answer. It cleared all my doubts :slight_smile:

So renaming the host seems to be the most sensible thing for me to do.

11

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?

12

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.