Filebeat postgresql module @timestamp field changed based on timestamp format

[kaiyan-sheng]

Filebeat postgresql module @timestamp field uses current time if timestamp in log doesn't have 3 decimals in seconds. For example, if using log example from #9156 for testing, the output json has current timestamp in @timestamp field instead of the timestamp showed up in log message.

How to reproduce:
Copy and paste the logs shown below into elastic/beats/filebeat/module/postgresql/log/test/postgresql-9.6-multi-core.log:

2018-11-17 03:14:01 EST [835-1] LOG: autovacuum launcher started
2018-11-17 05:01:38 EST [832-1] LOG: checkpoints are occurring too frequently (25 seconds apart)
2018-11-17 05:01:38 EST [832-2] HINT: Consider increasing the configuration parameter "max_wal_size".
2018-11-17 03:13:56 EST [768-1] postgres@postgres FATAL: the database system is starting up
2018-11-17 03:13:57 EST [771-1] postgres@postgres FATAL: the database system is starting up

Then run GENERATE=1 INTEGRATION_TESTS=1 TESTING_FILEBEAT_MODULES=postgresql build/python-env/bin/nosetests -v --nocapture tests/system/test_modules.py and you should see the elastic/beats/filebeat/module/postgresql/log/test/postgresql-9.6-multi-core.log-expected.json file is updated with current timestamp in @timestamp field.

[kaiyan-sheng]

Just curious, in output postgresql log json data, there are several timestamps.
For example, in the example below, there is @timestamp, postgresql.log.timestamp and then in the message itself, it includes the timestamp. So all these should be the same?

{
"@timestamp": "2017-07-31T13:36:43.557Z",
"event.dataset": "log",
"event.module": "postgresql",
"input.type": "log",
"log.offset": 897,
"message": "2017-07-31 13:36:43.557 EST [835-1] LOG: autovacuum launcher started",
"postgresql.log.core_id": "1",
"postgresql.log.level": "LOG",
"postgresql.log.message": "autovacuum launcher started",
"postgresql.log.thread_id": "835",
"postgresql.log.timestamp": "2017-07-31 13:36:43.557",
"postgresql.log.timezone": "EST"
},

[elasticmachine]

Pinging @elastic/infrastructure

[jsoriano]

So all these should be the same?

Yes, I think so. @timestamp should be overwritten with the timestamp found in the log message. I think the expression we have doesn't parse all possible timestamps in postgresql.

We can probably remove postgresql.log.timestamp once it is parsed and copied to @timestamp.
In message the original message is kept, what will include this timestamp, but this is fine.