Incorrect Postgres Timestamp with Filebeat & ES

I've been knocking my head on this one for days and can't seem to debug what is happening.. I've setup the filebeat module to stream postgres-13 csv logs into ES - everything works great except the time is out of sync (currently 10 hours behind).. was hoping to it is a simple UTC/Timezone issue but can't seem to find the issue and all the timezones are correct.

Any suggestions/guidance would be greatly appreciated as i can't seem to crack this problem..

--The filebeat log snippet

{
  "@timestamp": "2021-08-01T12:49:20.417Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.13.4",
    "pipeline": "filebeat-7.13.4-postgresql-log-pipeline"
  },
  "fileset": {
    "name": "log"
  },
  "service": {
    "type": "postgresql"
  },
  "ecs": {
    "version": "1.9.0"
  },
  "log": {
    "offset": 114988517,
    "file": {
      "path": "/var/log/postgres/postgresql-Sun.csv"
    }
  },
  "message": "2021-08-01 13:49:20.231 BST,\"fraud\",\"fraud\",570299,\"192.168.111.102:44950\",61069426.8b3bb,941,\"INSERT\",2021-08-01 13:31:34 BST,68/174016,3977209,ERROR,23505,\"duplicate key value violates unique constraint \"\"sourcedcompanieshouseofficerappointment_idx\"\"\",\"Key (sourced_companies_house_company_officer_appointment_entity_id)=(10639050) already exists.\",,,,,\"insert into sourced_companies_house_company_officer_appointment_address (version, address_line1, address_line2, care_of, country, date_ceased, date_confirmed, locality, marked_as_undeliverable, po_box, postal_code, premises, region, sourced_companies_house_company_officer_appointment_entity_id, entity_id) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15)\",,,\"PostgreSQL JDBC Driver\",\"client backend\"",
  "host": {
    "mac": [
      "00:15:5d:6f:d7:07"
    ],
    "name": "core.server",
    "hostname": "core.server",
    "architecture": "x86_64",
    "os": {
      "name": "CentOS Linux",
      "kernel": "4.18.0-305.10.2.el8_4.x86_64",
      "type": "linux",
      "platform": "centos",
      "version": "8",
      "family": "redhat"
    },
    "id": "86320bc600094cc8b450cbb158ed6e11",
    "containerized": false,
    "ip": [
      "192.168.111.100",
      "fe80::9a6f:eb68:6919:1f25"
    ]
  },
  "agent": {
    "version": "7.13.4",
    "hostname": "core.server",
    "ephemeral_id": "9d69e005-02bd-4bf7-bcf4-30bf7e94d4f8",
    "id": "1725d785-4c85-4179-8eb2-162e64887342",
    "name": "core.server",
    "type": "filebeat"
  },
  "input": {
    "type": "log"
  },
  "event": {
    "module": "postgresql",
    "dataset": "postgresql.log"
  }
}

--- The ES document for this log entry

{
  "_index": "filebeat-7.13.4-2021.07.30-000001",
  "_type": "_doc",
  "_id": "1GvCAXsBaNnAt8IX_nsR",
  "_version": 1,
  "_score": null,
  "fields": {
    "event.category": [
      "database"
    ],
    "host.os.name.text": [
      "CentOS Linux"
    ],
    "host.hostname": [
      "core.server"
    ],
    "process.pid": [
      570299
    ],
    "host.mac": [
      "00:15:5d:6f:d7:07"
    ],
    "service.type": [
      "postgresql"
    ],
    "host.os.version": [
      "8"
    ],
    "postgresql.log.sql_state_code": [
      "23505"
    ],
    "host.os.name": [
      "CentOS Linux"
    ],
    "log.level": [
      "ERROR"
    ],
    "agent.name": [
      "core.server"
    ],
    "host.name": [
      "core.server"
    ],
    "event.kind": [
      "event"
    ],
    "postgresql.log.query": [
      "insert into sourced_companies_house_company_officer_appointment_address (version, address_line1, address_line2, care_of, country, date_ceased, date_confirmed, locality, marked_as_undeliverable, po_box, postal_code, premises, region, sourced_companies_house_company_officer_appointment_entity_id, entity_id) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15)"
    ],
    "host.os.type": [
      "linux"
    ],
    "fileset.name": [
      "log"
    ],
    "input.type": [
      "log"
    ],
    "log.offset": [
      114988517
    ],
    "agent.hostname": [
      "core.server"
    ],
    "related.user": [
      "fraud"
    ],
    "postgresql.log.backend_type": [
      "client backend"
    ],
    "host.architecture": [
      "x86_64"
    ],
    "postgresql.log.detail": [
      "Key (sourced_companies_house_company_officer_appointment_entity_id)=(10639050) already exists."
    ],
    "agent.id": [
      "1725d785-4c85-4179-8eb2-162e64887342"
    ],
    "host.containerized": [
      false
    ],
    "ecs.version": [
      "1.9.0"
    ],
    "agent.version": [
      "7.13.4"
    ],
    "host.os.family": [
      "redhat"
    ],
    "postgresql.log.session_start_time": [
      "2021-08-01T02:31:34.000Z"
    ],
    "user.name": [
      "fraud"
    ],
    "postgresql.log.virtual_transaction_id": [
      "68/174016"
    ],
    "host.ip": [
      "192.168.111.100",
      "fe80::9a6f:eb68:6919:1f25"
    ],
    "agent.type": [
      "filebeat"
    ],
    "postgresql.log.transaction_id": [
      3977209
    ],
    "event.module": [
      "postgresql"
    ],
    "postgresql.log.timestamp": [
      "2021-08-01 13:49:20.231 BST"
    ],
    "postgresql.log.session_id": [
      "61069426.8b3bb"
    ],
    "host.os.kernel": [
      "4.18.0-305.10.2.el8_4.x86_64"
    ],
    "host.id": [
      "86320bc600094cc8b450cbb158ed6e11"
    ],
    "event.timezone": [
      "BST"
    ],
    "postgresql.log.client_addr": [
      "192.168.111.102"
    ],
    "postgresql.log.database": [
      "fraud"
    ],
    "postgresql.log.error.code": [
      "23505"
    ],
    "message": [
      "duplicate key value violates unique constraint \"sourcedcompanieshouseofficerappointment_idx\""
    ],
    "postgresql.log.command_tag": [
      "INSERT"
    ],
    "event.ingested": [
      "2021-08-01T12:49:21.424Z"
    ],
    "@timestamp": [
      "2021-08-01T02:49:20.231Z"
    ],
    "postgresql.log.application_name": [
      "PostgreSQL JDBC Driver"
    ],
    "host.os.platform": [
      "centos"
    ],
    "event.type": [
      "error"
    ],
    "log.file.path": [
      "/var/log/postgres/postgresql-Sun.csv"
    ],
    "agent.ephemeral_id": [
      "9d69e005-02bd-4bf7-bcf4-30bf7e94d4f8"
    ],
    "postgresql.log.client_port": [
      "44950"
    ],
    "event.dataset": [
      "postgresql.log"
    ],
    "user.name.text": [
      "fraud"
    ]
  },
  "highlight": {
    "agent.ephemeral_id": [
      "@kibana-highlighted-field@9d69e005-02bd-4bf7-bcf4-30bf7e94d4f8@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1627786160231
  ]
}

Did you try to play with add_locale processor? Docs: Add the local time zone | Filebeat Reference [7.13] | Elastic

1 Like

Thanks Marcin, I added this and it now prints it into the message however the issue is still the same.

I'm feel that this isn't a timezone issue as the offset is incorrect by 11 hours from BST (UTC+1) - my system timezone is Europe/London on both the postgres/filebeat server and the ES/Kibana server. My client machine (browser) is also Europe/London .

If you see the FIlebeat message packet - it is correct and none of the incorrect time are reflected in this packet but are when ingested by ES. The ES document also has the correct times but not for the timestamp or the session time.

Its 'like' ES is incorrectly parsing the timestamp or getting lost with the 24 hour structure? I'm lost with this issue as i've did 2 full re-installs and the issue still appears

--- Filebeat message

{
  "@timestamp": "2021-08-02T11:24:22.023Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.13.4",
    "pipeline": "filebeat-7.13.4-postgresql-log-pipeline"
  },
  "host": {
    "containerized": false,
    "ip": [
      "192.168.111.100",
      "fe80::9a6f:eb68:6919:1f25"
    ],
    "mac": [
      "00:15:5d:6f:d7:07"
    ],
    "hostname": "core.server",
    "architecture": "x86_64",
    "name": "core.server",
    "os": {
      "type": "linux",
      "platform": "centos",
      "version": "8",
      "family": "redhat",
      "name": "CentOS Linux",
      "kernel": "4.18.0-193.el8.x86_64"
    },
    "id": "86320bc600094cc8b450cbb158ed6e11"
  },
  "agent": {
    "ephemeral_id": "83fe60f5-00c0-4153-b7b2-60098f0ac5e8",
    "id": "01a6f728-d573-4058-b6a8-acaeffe848fc",
    "name": "core.server",
    "type": "filebeat",
    "version": "7.13.4",
    "hostname": "core.server"
  },
  "ecs": {
    "version": "1.9.0"
  },
  "log": {
    "offset": 3022396,
    "file": {
      "path": "/var/log/postgres/postgresql-Mon.csv"
    }
  },
  "message": "2021-08-02 12:23:40.437 BST,\"fraud\",\"fraud\",405011,\"192.168.111.103:37244\",6107ced6.62e13,1,\"SELECT\",2021-08-02 11:54:14 BST,19/51010,0,LOG,00000,\"duration: 850.784 ms  execute S_12: select companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_0_, companyadd0_.entity_id as entity_i1_16_0_, companyadd0_.entity_id as entity_i1_16_1_, companyadd0_.version as version2_16_1_, companyadd0_.address_line1 as address_3_16_1_, companyadd0_.address_line2 as address_4_16_1_, companyadd0_.care_of as care_of5_16_1_, companyadd0_.country as country6_16_1_, companyadd0_.date_ceased as date_cea7_16_1_, companyadd0_.date_confirmed as date_con8_16_1_, companyadd0_.locality as locality9_16_1_, companyadd0_.marked_as_undeliverable as marked_10_16_1_, companyadd0_.po_box as po_box11_16_1_, companyadd0_.postal_code as postal_12_16_1_, companyadd0_.premises as premise13_16_1_, companyadd0_.region as region14_16_1_, companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_1_ from sourced_companies_house_company_address companyadd0_ where companyadd0_.sourced_companies_house_company_entity_id=$1\",\"parameters: $1 = '223923314'\",,,,,,,,\"PostgreSQL JDBC Driver\",\"client backend\"",
  "service": {
    "type": "postgresql"
  },
  "input": {
    "type": "log"
  },
  "event": {
    "module": "postgresql",
    "dataset": "postgresql.log",
    "timezone": "+01:00"
  },
  "fileset": {
    "name": "log"
  }
}

--ES Document

{
  "_index": "filebeat-7.13.4-2021.07.30-000001",
  "_type": "_doc",
  "_id": "QjCbBnsBaNnAt8IXoHrw",
  "_score": 1,
  "fields": {
    "postgresql.log.query_name": [
      "S_12"
    ],
    "event.category": [
      "database"
    ],
    "host.os.name.text": [
      "CentOS Linux"
    ],
    "host.hostname": [
      "core.server"
    ],
    "process.pid": [
      405011
    ],
    "host.mac": [
      "00:15:5d:6f:d7:07"
    ],
    "service.type": [
      "postgresql"
    ],
    "host.os.version": [
      "8"
    ],
    "postgresql.log.sql_state_code": [
      "00000"
    ],
    "host.os.name": [
      "CentOS Linux"
    ],
    "log.level": [
      "LOG"
    ],
    "agent.name": [
      "core.server"
    ],
    "host.name": [
      "core.server"
    ],
    "event.kind": [
      "event"
    ],
    "host.os.type": [
      "linux"
    ],
    "fileset.name": [
      "log"
    ],
    "input.type": [
      "log"
    ],
    "log.offset": [
      3022396
    ],
    "agent.hostname": [
      "core.server"
    ],
    "related.user": [
      "fraud"
    ],
    "postgresql.log.backend_type": [
      "client backend"
    ],
    "host.architecture": [
      "x86_64"
    ],
    "postgresql.log.detail": [
      "parameters: $1 = '223923314'"
    ],
    "agent.id": [
      "01a6f728-d573-4058-b6a8-acaeffe848fc"
    ],
    "host.containerized": [
      false
    ],
    "ecs.version": [
      "1.9.0"
    ],
    "agent.version": [
      "7.13.4"
    ],
    "host.os.family": [
      "redhat"
    ],
    "postgresql.log.session_start_time": [
      "2021-08-02T00:54:14.000Z"
    ],
    "user.name": [
      "fraud"
    ],
    "postgresql.log.query_step": [
      "execute"
    ],
    "postgresql.log.virtual_transaction_id": [
      "19/51010"
    ],
    "host.ip": [
      "192.168.111.100",
      "fe80::9a6f:eb68:6919:1f25"
    ],
    "agent.type": [
      "filebeat"
    ],
    "postgresql.log.transaction_id": [
      0
    ],
    "event.module": [
      "postgresql"
    ],
    "postgresql.log.timestamp": [
      "2021-08-02 12:23:40.437 BST"
    ],
    "postgresql.log.session_id": [
      "6107ced6.62e13"
    ],
    "host.os.kernel": [
      "4.18.0-193.el8.x86_64"
    ],
    "host.id": [
      "86320bc600094cc8b450cbb158ed6e11"
    ],
    "event.timezone": [
      "BST"
    ],
    "postgresql.log.client_addr": [
      "192.168.111.103"
    ],
    "postgresql.log.database": [
      "fraud"
    ],
    "postgresql.log.error.code": [
      "00000"
    ],
    "message": [
      "select companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_0_, companyadd0_.entity_id as entity_i1_16_0_, companyadd0_.entity_id as entity_i1_16_1_, companyadd0_.version as version2_16_1_, companyadd0_.address_line1 as address_3_16_1_, companyadd0_.address_line2 as address_4_16_1_, companyadd0_.care_of as care_of5_16_1_, companyadd0_.country as country6_16_1_, companyadd0_.date_ceased as date_cea7_16_1_, companyadd0_.date_confirmed as date_con8_16_1_, companyadd0_.locality as locality9_16_1_, companyadd0_.marked_as_undeliverable as marked_10_16_1_, companyadd0_.po_box as po_box11_16_1_, companyadd0_.postal_code as postal_12_16_1_, companyadd0_.premises as premise13_16_1_, companyadd0_.region as region14_16_1_, companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_1_ from sourced_companies_house_company_address companyadd0_ where companyadd0_.sourced_companies_house_company_entity_id=$1"
    ],
    "event.duration": [
      850784000
    ],
    "postgresql.log.command_tag": [
      "SELECT"
    ],
    "event.ingested": [
      "2021-08-02T11:24:27.759Z"
    ],
    "@timestamp": [
      "2021-08-02T01:23:40.437Z"
    ],
    "postgresql.log.application_name": [
      "PostgreSQL JDBC Driver"
    ],
    "host.os.platform": [
      "centos"
    ],
    "event.type": [
      "info"
    ],
    "log.file.path": [
      "/var/log/postgres/postgresql-Mon.csv"
    ],
    "agent.ephemeral_id": [
      "83fe60f5-00c0-4153-b7b2-60098f0ac5e8"
    ],
    "postgresql.log.client_port": [
      "37244"
    ],
    "event.dataset": [
      "postgresql.log"
    ],
    "user.name.text": [
      "fraud"
    ]
  }
}

-- filebeat/postgres server

[root@core bin]# timedatectl
               Local time: Mon 2021-08-02 12:45:06 BST
           Universal time: Mon 2021-08-02 11:45:06 UTC
                 RTC time: Mon 2021-08-02 11:45:05
                Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

--es server

[root@monitoring ~]# timedatectl
               Local time: Mon 2021-08-02 12:46:29 BST
           Universal time: Mon 2021-08-02 11:46:29 UTC
                 RTC time: Mon 2021-08-02 11:46:29
                Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
[root@monitoring ~]#

---raw postgres CSV log line

2021-08-02 12:23:40.437 BST,"fraud","fraud",405011,"192.168.111.103:37244",6107ced6.62e13,1,"SELECT",2021-08-02 11:54:14 BST,19/51010,0,LOG,00000,"duration: 850.784 ms  execute S_12: select companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_0_, companyadd0_.entity_id as entity_i1_16_0_, companyadd0_.entity_id as entity_i1_16_1_, companyadd0_.version as version2_16_1_, companyadd0_.address_line1 as address_3_16_1_, companyadd0_.address_line2 as address_4_16_1_, companyadd0_.care_of as care_of5_16_1_, companyadd0_.country as country6_16_1_, companyadd0_.date_ceased as date_cea7_16_1_, companyadd0_.date_confirmed as date_con8_16_1_, companyadd0_.locality as locality9_16_1_, companyadd0_.marked_as_undeliverable as marked_10_16_1_, companyadd0_.po_box as po_box11_16_1_, companyadd0_.postal_code as postal_12_16_1_, companyadd0_.premises as premise13_16_1_, companyadd0_.region as region14_16_1_, companyadd0_.sourced_companies_house_company_entity_id as sourced15_16_1_ from sourced_companies_house_company_address companyadd0_ where companyadd0_.sourced_companies_house_company_entity_id=$1","parameters: $1 = '223923314'",,,,,,,,"PostgreSQL JDBC Driver","client backend"

How are you getting this filebeat message? It is not parsed, I do not think this is the full event that is being sent to elasticsearch.

Which of your times are wrong? It could be a timezone issue, timezone abbreviations are ambiguous, BST is not only British Summer Time (UTC+1), it is also Bangladesh Standard Time (UTC + 6) and Bougainville Standard Time (UTC+11).

The postgresql module use these processors pipelines, in your case the pipeline.yml and the pipeline-csv.yml

For what I could understand from those processors pipeline, the add_locale option will add a field named event.timezone with your timezone, +01:00 in this case, but this field is only used in the date filter for the @timestamp field, all the other fields will use the provided timezone.

What it seems to be happening is that BST is being interpreted as Bougainville Standard Time, which will give you a 11 hours offset from UTC.

I think you will need to manually edit those pipelines to fix this issue, but can you share the time fields that are wrong and what is the expected value?

Thanks @leandrojmp. i'm getting the filebeat output from running the command filebeat -e -d "*" and copying the payload from the stdout..

On the ES document - the following times are wrong (along with what is reported from filebeats log)- the time is correct except the hours has shifted by -11 hours. Below shows the correct time being the second timestamp (the first timestamp is the incorrect time in ES)

postgresql.log.session_start_time "2021-08-02T00:54:14.000Z" vs "2021-08-02 11:54:14 BST" (-11 Hours)
@timestamp -"2021-08-02T01:23:40.437Z" vs "2021-08-02 12:23:40.437 BST" (-11 hours)

My Timezone is Europe/Londonwith the current daylight saving is BST and this is what is reported by postgres but i've not made any customisations to either ES or filebeat however what you say about Bougainville Standard Time is very interesting as that would align with the offset that i'm seeing (UTC-11) - this is an avenue i'll explore further - thanks @leandrojmp !

I think that this is the reason, filebeat is picking the wrong BST.

In elasticsearch all date time values are stored in UTC.

This time for the @timestamp field is in UTC: 2021-08-02T01:23:40.437Z, the Z at the end means that this time is in Zulu Time, which is another name for UTC + 0.

The same time in BST could be one of the following:

  • 2021-08-02 02:23:40.437 BST, British Summer Time, UTC + 1
  • 2021-08-02 07:23:40.437 BST, Bangladesh Standard Time, UTC + 6
  • 2021-08-02 12:23:40.437 BST, Bougainville Standard Time, UTC + 11

Filebeat seems to be picking the last one when applying the offset.

Abbreviated timezones can be confusing, there was a similar issue with IST a couple of days ago as IST could be Irish Standard Time, Israel Standard Time or India Standard Time, each one of them will give you different offsets.

The best way to deal with things like that is to ignore the abbeviated timezone and apply the correct offset, but you would need to edit the pipeline files.

Its working @leandrojmp - thanks very much. to change it in beats wasn't trivial (not with my knowledge anyway) so i changed postgres to log in UTC and boom - all works as expected.. I am surprised that with me simply using the default postgres module in Filebeat then this isn't more common issue - i found this that seems to be the same issue but the solution doesn't work for me.

Thanks again for pointing in me in the right direction..

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