Issues with PGSQL-Module | Too much errors

Elastic Stack Beats
1

Hi there,

we recently installed Packetbeat on one of our PostgreSQL-Servers. Basicly it works. It sends things to Elasticsearch and created the Dashboards in Kibana. But in the PGSQL-Performace Dashboard it tells us that about 40% of all requests are errors. And this can definitely not be true as the log of the Postgresql-Server does not tell us anything like this. We are talking about like 500 Errors per Seccond. The Events which are detected as Errors have "Error" as State, but no PGSQL-Errormessage or Errorcode. The Source of the error-Queries are different hosts and can be Select, Insert, Whatever. Additionaly the Log of Packetbeat is spamed with these messages below. Maybe there is some kind of conenction to the irrational high error-rate?

2018-07-26T14:17:04.497+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.501+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.502+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=43, i=12
2018-07-26T14:17:04.504+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.702+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=182, i=2
2018-07-26T14:17:04.702+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.767+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.768+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:04.834+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:05.513+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:05.854+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.854+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.854+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.854+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.855+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.855+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.855+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.855+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.855+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:05.856+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:06.466+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:07.351+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=21, i=7
2018-07-26T14:17:07.418+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=184, i=2
2018-07-26T14:17:08.103+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.375+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.381+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.381+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.382+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.441+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80
2018-07-26T14:17:08.778+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=34, i=6
2018-07-26T14:17:08.778+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:08.779+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 116
2018-07-26T14:17:08.780+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:08.780+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=34, i=6
2018-07-26T14:17:08.781+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:08.846+0200    ERROR   pgsql/parse.go:531      Pgsql invalid column_length=4294967295, buffer_length=34, i=6
2018-07-26T14:17:08.847+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
2018-07-26T14:17:09.188+0200    WARN    pgsql/parse.go:633      Pgsql parser expected extended query message, but received command of type 80

The monitored Network-Interface is configured like this:

packetbeat.interfaces.device: ens192
packetbeat.interfaces.snaplen: 1500
packetbeat.interfaces.type: af_packet
packetbeat.interfaces.buffer_size_mb: 512

Can anybody give us any hints why this is happening?

We are using Packetbeat 6.3.2, Elasticsearch and Kibana 6.3.1, Postgresql 10.4 and Debian 9.4.

Greetings Marco

2

I also switched Packetbeat to debug-Logging and got the Log-Messages around one of these Warnings:

   2018-07-27T08:48:02.174+0200    DEBUG   [pgsql] pgsql/parse.go:20       pgsqlMessageParser, off=0
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:42       parseMessageStart
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:112      Pgsql type Z, length=5
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:35       pgsqlMessageParser return: ok=true, complete=true, off=6
   2018-07-27T08:48:02.174+0200    DEBUG   [sniffer]       sniffer/sniffer.go:192  Packet number: 29517
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:143  decode packet data
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:216  IPv4 packet
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:257  TCP packet
   2018-07-27T08:48:02.174+0200    DEBUG   [tcp]   tcp/tcp.go:160  tcp flow id: 0x0
   2018-07-27T08:48:02.174+0200    DEBUG   [tcp]   tcp/tcp.go:173  pkt.start_seq=1618333947 pkt.last_seq=1618334439 stream.last_seq=1618333947 (len=492)
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/pgsql.go:226      Len data: 492 cap data: 512
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsql] pgsql/parse.go:20       pgsqlMessageParser, off=0
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:42       parseMessageStart
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:112      Pgsql type P, length=243
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:275      Parse
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:293      Parse in an extended query request: update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, $created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:570      parseMessageExtendedQuery
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:35       pgsqlMessageParser return: ok=true, complete=true, off=492
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/pgsql.go:363      Queries (1) :[update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10]
   2018-07-27T08:48:02.174+0200    DEBUG   [sniffer]       sniffer/sniffer.go:192  Packet number: 29518
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:143  decode packet data
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:216  IPv4 packet
   2018-07-27T08:48:02.174+0200    DEBUG   [decoder]       decoder/decoder.go:257  TCP packet
   2018-07-27T08:48:02.174+0200    DEBUG   [tcp]   tcp/tcp.go:160  tcp flow id: 0x0
   2018-07-27T08:48:02.174+0200    DEBUG   [tcp]   tcp/tcp.go:173  pkt.start_seq=1074953350 pkt.last_seq=1074953385 stream.last_seq=1074953350 (len=35)
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/pgsql.go:226      Len data: 35 cap data: 48
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsql] pgsql/parse.go:20       pgsqlMessageParser, off=0
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:42       parseMessageStart
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:112      Pgsql type 1, length=4
   2018-07-27T08:48:02.174+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:305      ParseCompletion
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:315      Parse completion in an extended query response
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:434      parseMessageData
   2018-07-27T08:48:02.175+0200    WARN    pgsql/parse.go:501      Pgsql parser expected data message, but received command of type 110
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:35       pgsqlMessageParser return: ok=false, complete=false, off=10
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsql] pgsql/pgsql.go:252      Ignore Postgresql message. Drop tcp stream. Try parsing with the next segment
   2018-07-27T08:48:02.175+0200    DEBUG   [sniffer]       sniffer/sniffer.go:192  Packet number: 29519
   2018-07-27T08:48:02.175+0200    DEBUG   [decoder]       decoder/decoder.go:143  decode packet data
   2018-07-27T08:48:02.175+0200    DEBUG   [decoder]       decoder/decoder.go:216  IPv4 packet
   2018-07-27T08:48:02.175+0200    DEBUG   [decoder]       decoder/decoder.go:257  TCP packet
   2018-07-27T08:48:02.175+0200    DEBUG   [tcp]   tcp/tcp.go:160  tcp flow id: 0x0
   2018-07-27T08:48:02.175+0200    DEBUG   [tcp]   tcp/tcp.go:173  pkt.start_seq=1618334439 pkt.last_seq=1618334470 stream.last_seq=1618334439 (len=31)
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/pgsql.go:226      Len data: 31 cap data: 48
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsql] pgsql/parse.go:20       pgsqlMessageParser, off=0
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:42       parseMessageStart
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:112      Pgsql type B, length=15
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:35       pgsqlMessageParser return: ok=true, complete=true, off=16
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsql] pgsql/parse.go:20       pgsqlMessageParser, off=0
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:42       parseMessageStart
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:112      Pgsql type E, length=9
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:255      ErrorResponse
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:430
   2018-07-27T08:48:02.175+0200    DEBUG   [pgsqldetailed] pgsql/parse.go:35       pgsqlMessageParser return: ok=true, complete=true, off=10
3

next few lines of the Debug-Log (Sorry for the multiple posts. But I have no other chance to post the log here because of the 7000 character-Limit...)

2018-07-27T08:48:02.176+0200    DEBUG   [publish]       publish/publish.go:154  normalize address for: {"bytes_in":492,"bytes_out":10,"dst":{"IP":"192.168.1.3","Port":5432,"Name":"","Cmdline":"","Proc":""},"method":"UPDATE","pgsql":{"error_code":"","error_message":"","error_severity":"","iserror":true,"num_fields":0,"num_rows":0},"query":"update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10","responsetime":1,"src":{"IP":"192.168.1.213","Port":60052,"Name":"","Cmdline":"","Proc":""},"status":"Error","type":"pgsql"}
   2018-07-27T08:48:02.176+0200    DEBUG   [publish]       publish/publish.go:158  has src: true
   2018-07-27T08:48:02.176+0200    DEBUG   [publish]       publish/publish.go:183  has dst: true
   2018-07-27T08:48:02.176+0200    DEBUG   [publish]       pipeline/processor.go:291       Publish event: {
     "@timestamp": "2018-07-27T06:48:02.118Z",
     "@metadata": {
       "beat": "packetbeat",
       "type": "doc",
       "version": "6.3.2"
     },
     "port": 5432,
     "client_proc": "",
     "method": "UPDATE",
     "query": "update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10",
     "server": "",
     "status": "Error",
     "responsetime": 1,
     "ip": "192.168.1.3",
     "beat": {
       "name": "pg01",
       "hostname": "pg01",
       "version": "6.3.2"
     },
     "pgsql": {
       "num_fields": 0,
       "error_code": "",
       "error_message": "",
       "error_severity": "",
       "iserror": true,
       "num_rows": 0
     },
     "type": "pgsql",
     "bytes_in": 492,
     "client_server": "",
     "bytes_out": 10,
     "client_port": 60052,
     "proc": "",
     "direction": "in",
     "client_ip": "192.168.1.213",
     "host": {
       "name": "pg01"
     }
   }
   2018-07-27T08:48:02.176+0200    DEBUG   [pgsql] pgsql/pgsql.go:439      Postgres transaction completed: {"error_code":"","error_message":"","error_severity":"","iserror":true,"num_fields":0,"num_rows":0}
4

In Kibana, could you go to the Discover app, select the packetbeat-* index pattern and then filter down to documents that match type:"pgsql" and pgsql.iserror:true. Can you post a few documents that match over here, please?

Alternatively, you could run the following curl command, substituting localhost:9200 with your Elasticsearch host and port, and post the results here:

curl 'http://localhost:9200/packetbeat-*/_search?q=type:pgsq+and+pgsql.iserror:true&pretty'
5

Hi, thank you for your response. Sure I can. Here we go:

{
  "_index": "packetbeat-2018.07.30",
  "_type": "doc",
  "_id": "DZHu6WQBOm1UjBziBnkM",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-07-30T06:44:07.656Z",
    "responsetime": 0,
    "bytes_in": 492,
    "query": "update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10",
    "pgsql": {
      "error_code": "",
      "error_message": "",
      "error_severity": "",
      "iserror": true,
      "num_rows": 0,
      "num_fields": 0
    },
    "server": "",
    "method": "UPDATE",
    "client_proc": "",
    "client_ip": "192.168.1.213",
    "bytes_out": 10,
    "proc": "",
    "client_port": 54146,
    "beat": {
      "hostname": "pg01",
      "version": "6.3.2",
      "name": "pg01"
    },
    "port": 5432,
    "client_server": "",
    "type": "pgsql",
    "direction": "in",
    "status": "Error",
    "ip": "192.168.1.3",
    "host": {
      "name": "pg01"
    }
  },
  "fields": {
    "@timestamp": [
      "2018-07-30T06:44:07.656Z"
    ]
  },
  "sort": [
    1532933047656
  ]
}

{
  "_index": "packetbeat-2018.07.30",
  "_type": "doc",
  "_id": "C5Hu6WQBOm1UjBziBnkM",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-07-30T06:44:07.333Z",
    "beat": {
      "name": "pg01",
      "hostname": "pg01",
      "version": "6.3.2"
    },
    "pgsql": {
      "iserror": false,
      "num_rows": 1,
      "num_fields": 1,
      "error_code": "",
      "error_message": "",
      "error_severity": ""
    },
    "direction": "in",
    "query": "SHOW TRANSACTION ISOLATION LEVEL",
    "port": 5432,
    "client_ip": "192.168.1.10",
    "type": "pgsql",
    "client_server": "",
    "client_proc": "",
    "status": "OK",
    "ip": "192.168.1.3",
    "responsetime": 0,
    "bytes_out": 82,
    "bytes_in": 76,
    "host": {
      "name": "pg01"
    },
    "proc": "",
    "client_port": 59834,
    "method": "SHOW",
    "server": ""
  },
  "fields": {
    "@timestamp": [
      "2018-07-30T06:44:07.333Z"
    ]
  },
  "sort": [
    1532933047333
  ]
}

{
  "_index": "packetbeat-2018.07.30",
  "_type": "doc",
  "_id": "CJHu6WQBOm1UjBziBnkM",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-07-30T06:44:07.306Z",
    "bytes_out": 10,
    "client_port": 54146,
    "server": "",
    "query": "update cwd_token set directory_id=$1, entity_name=$2, random_number=$3, identifier_hash=$4, random_hash=$5, created_date=$6, last_accessed_date=$7, last_accessed_time=$8, duration=$9 where id=$10",
    "pgsql": {
      "error_message": "",
      "error_severity": "",
      "iserror": true,
      "num_rows": 0,
      "num_fields": 0,
      "error_code": ""
    },
    "client_ip": "192.168.1.213",
    "direction": "in",
    "status": "Error",
    "responsetime": 0,
    "method": "UPDATE",
    "port": 5432,
    "client_server": "",
    "host": {
      "name": "pg01"
    },
    "ip": "192.168.1.3",
    "type": "pgsql",
    "bytes_in": 492,
    "client_proc": "",
    "proc": "",
    "beat": {
      "hostname": "pg01",
      "version": "6.3.2",
      "name": "pg01"
    }
  },
  "fields": {
    "@timestamp": [
      "2018-07-30T06:44:07.306Z"
    ]
  },
  "sort": [
    1532933047306
  ]
}

{
  "_index": "packetbeat-2018.07.30",
  "_type": "doc",
  "_id": "A5Hu6WQBOm1UjBziBnkM",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-07-30T06:44:06.789Z",
    "proc": "",
    "status": "Error",
    "type": "pgsql",
    "bytes_in": 276,
    "method": "_5",
    "client_port": 49512,
    "direction": "in",
    "ip": "192.168.1.3",
    "client_ip": "192.168.1.173",
    "responsetime": 1,
    "beat": {
      "version": "6.3.2",
      "name": "pg01",
      "hostname": "pg01"
    },
    "client_proc": "",
    "pgsql": {
      "iserror": true,
      "num_rows": 0,
      "num_fields": 0,
      "error_code": "",
      "error_message": "",
      "error_severity": ""
    },
    "bytes_out": 10,
    "port": 5432,
    "host": {
      "name": "pg01"
    },
    "client_server": "",
    "query": "_5",
    "server": ""
  },
  "fields": {
    "@timestamp": [
      "2018-07-30T06:44:06.789Z"
    ]
  },
  "sort": [
    1532933046789
  ]
}

{
  "_index": "packetbeat-2018.07.30",
  "_type": "doc",
  "_id": "_ZHu6WQBOm1UjBziAngR",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-07-30T06:44:06.491Z",
    "client_port": 50552,
    "responsetime": 5,
    "bytes_in": 463,
    "proc": "",
    "server": "",
    "direction": "in",
    "query": "select contentper0_.ID as ID1_15_, contentper0_.CONT_PERM_TYPE as CONT_PER2_15_, contentper0_.CONTENT_ID as CONTENT_3_15_, contentper0_.CREATIONDATE as CREATION4_15_, contentper0_.LASTMODDATE as LASTMODD5_15_ from CONTENT_PERM_SET contentper0_ where contentper0_.CONT_PERM_TYPE=$1 and (contentper0_.CONTENT_ID in ($2 , $3 , $4 , $5))",
    "pgsql": {
      "error_severity": "",
      "iserror": true,
      "num_rows": 0,
      "num_fields": 0,
      "error_code": "",
      "error_message": ""
    },
    "type": "pgsql",
    "beat": {
      "name": "pg01",
      "hostname": "pg01",
      "version": "6.3.2"
    },
    "client_server": "",
    "host": {
      "name": "pg01"
    },
    "bytes_out": 10,
    "client_ip": "192.168.1.173",
    "port": 5432,
    "ip": "192.168.1.3",
    "method": "SELECT",
    "client_proc": "",
    "status": "Error"
  },
  "fields": {
    "@timestamp": [
      "2018-07-30T06:44:06.491Z"
    ]
  },
  "sort": [
    1532933046491
  ]
}
6

Hi shaunak,

did you see my reply? Any updates on this?

Greetings
Marco

7

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