Backend receive buffer get corrupted with string: NOTICE: table "cleanup_keys" does not exist, skipping - Mailing list pgsql-bugs

This is about libpq and postgres backend protocol(3) version(90601)

Hi,

I have an application (multi thread) that send a lot of query on multiple
connections to postgres executable backend using libpq client library. One
connection per thread.
Since the problem is very hard to reproduce, I cannot give you a sample sql
file to reproduce it because it will require multiple sql files to run in
parallel.

The symptom is: I get the following error message: *invalid frontend
message type 78*
*Please, don't stop reading here and tell me I have a memory corruption in
my application. It is not the case. I did my home work !*

Summary:
1. On thread #1: DROP TABLE IF EXISTS cleanup_keys
2. On thread #2: SELECT name, alert_query FROM filter WHERE (filter_key =
$1) AND (alert_query != '')
3. On thread #2: receive error: invalid frontend message type 78

Please, notice that 78 is the ASCII code for 'N', the first letter of the
message: "NOTICE: table \"%s\" does not exist, skipping"
On the backend (postgres), this message is generated from the file
tablecmds.c, function: DropErrorMsgNonExistent, line 763: ereport(NOTICE,
(errmsg(rentry->skipping_msg, rel->relname)));

Somehow, the string "NOTICE: table "cleanup_keys" does not exist, skipping"
is copied in the variable PqRecvBuffer (ref: pqcomm.c, line 123)
To find out this, I had to modify the backend and add the content of
PqRecvBuffer to the error message. You can see the result in the following
log file (postgres backend).

More details about threads sending sql commands (thread #1 = TH-1 and
thread #2 = TH-2)

*TH-1*
TH-1.1: SET TIME ZONE 'America/New_York'
TH-1.2: SELECT schema_version from config
TH-1.3:SELECT name, view_query FROM filter WHERE (filter_key = $1) AND
(view_query != '')                                 with parameters: $1 =
'28'
TH-1.4: DROP TABLE IF EXISTS cleanup_keys
TH-1.5: CREATE TEMPORARY TABLE cleanup_keys (log_key bigint, PRIMARY KEY
(log_key))
TH-1.6: DELETE FROM cleanup_keys
TH-1.7: INSERT INTO cleanup_keys SELECT log.log_key AS pkey FROM log  JOIN
"windex" AS "W1" ON "W1"."log_key"="log"."log_key"  JOIN "windex" AS "W2"
ON "W2"."log_key"="log"."log_key"  WHERE   (timestamp <= LOCALTIMESTAMP -
interval '1 minute')  AND  "log_priority" IN (10)  AND  "W1"."word" =
8947959883223794304  AND  "W2"."word" = 5456998344637285215  LIMIT 1000
TH-1.8: DELETE FROM log WHERE log.log_key IN (SELECT log_key FROM
cleanup_keys ORDER BY log_key)
TH-1.9: DROP TABLE IF EXISTS cleanup_keys


*TH-2*
TH-2.1 SET TIME ZONE 'America/New_York'
TH-2.2 SELECT name, alert_query FROM filter WHERE (filter_key = $1) AND
(alert_query != '')


*Here is the log of postgres backend:*
2016-11-22 20:00:00.227 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: SET TIME ZONE 'America/New_York'
2016-11-22 20:00:00.228 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: SELECT schema_version from config
2016-11-22 20:00:00.229 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: SELECT name, view_query FROM filter WHERE (filter_key =
$1) AND (view_query != '')
2016-11-22 20:00:00.229 EST 19312 [unknown] 127.0.0.1(43990)
stprime24DETAIL:  parameters: $1 = '28'
2016-11-22 20:00:00.229 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: DROP TABLE IF EXISTS cleanup_keys
2016-11-22 20:00:00.230 EST 19044 [unknown] 127.0.0.1(43765)
stprime24FATAL:  invalid frontend message type 78 buffer:(OTICE:  table
"cleanup_keys" does not exist, skipping?)
2016-11-22 20:00:00.230 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: CREATE TEMPORARY TABLE cleanup_keys (log_key bigint,
PRIMARY KEY (log_key))
2016-11-22 20:00:00.237 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: DELETE FROM cleanup_keys
2016-11-22 20:00:00.238 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: INSERT INTO cleanup_keys SELECT log.log_key AS pkey
FROM log  JOIN "windex" AS "W1" ON "W1"."log_key"="log"."log_key"  JOIN
"windex" AS "W2" ON "W2"."log_key"="log"."log_key"  WHERE   (timestamp <=
LOCALTIMESTAMP - interval '1 minute')  AND  "log_priority" IN (10)  AND
 "W1"."word" = 8947959883223794304  AND  "W2"."word" = 5456998344637285215
 LIMIT 1000
2016-11-22 20:00:00.259 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: DELETE FROM log WHERE log.log_key IN (SELECT log_key
FROM cleanup_keys ORDER BY log_key)
2016-11-22 20:00:00.271 EST 19312 [unknown] 127.0.0.1(43990) stprime24LOG:
 execute <unnamed>: DROP TABLE IF EXISTS cleanup_keys


*libpq log for TH-1*
To backend> Msg P
To backend> ""
To backend> "SET TIME ZONE 'America/New_York'"
To backend (2#)> 0
To backend> Msg complete, length 41
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> S
From backend (#4)> 30
From backend> "TimeZone"
From backend> "America/New_York"
pqSaveParameterStatus: 'TimeZone' = 'America/New_York'
From backend> C
From backend (#4)> 8
From backend> "SET"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "SELECT schema_version from config"
To backend (2#)> 0
To backend> Msg complete, length 42
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> T
From backend (#4)> 39
From backend (#2)> 1
From backend> "schema_version"
From backend (#4)> 17142
From backend (#2)> 1
From backend (#4)> 21
From backend (#2)> 2
From backend (#4)> -1
From backend (#2)> 1
From backend> D
From backend (#4)> 12
From backend (#2)> 1
From backend (#4)> 2
From backend (2)>
From backend> C
From backend (#4)> 13
From backend> "SELECT 1"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "SELECT name, view_query FROM filter WHERE (filter_key = $1)
AND (view_query != '')"
To backend (2#)> 0
To backend> Msg complete, length 91
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 1
To backend (2#)> 1
To backend (2#)> 1
To backend (4#)> 8
To backend>
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 29
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 2
From backend (#4)> 4
From backend> T
From backend (#4)> 58
From backend (#2)> 2
From backend> "name"
From backend (#4)> 17201
From backend (#2)> 3
From backend (#4)> 1043
From backend (#2)> 65535
From backend (#4)> 49
From backend (#2)> 1
From backend> "view_query"
From backend (#4)> 17201
From backend (#2)> 8
From backend (#4)> 1043
From backend (#2)> 65535
From backend (#4)> 8196
From backend (#2)> 1
From backend> D
From backend (#4)> 320
From backend (#2)> 2
From backend (#4)> 22
From backend (22)> Cleanup logger up/down
From backend (#4)> 284
From backend (284)>  JOIN "windex" AS "W1" ON
"W1"."log_key"="log"."log_key"  JOIN "windex" AS "W2" ON
"W2"."log_key"="log"."log_key"  WHERE   (timestamp <= LOCALTIMESTAMP -
interval '1 minute')  AND  "log_priority" IN (10)  AND  "W1"."word" =
8947959883223794304  AND  "W2"."word" = 5456998344637285215
From backend> C
From backend (#4)> 13
From backend> "SELECT 1"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "DROP TABLE IF EXISTS cleanup_keys"
To backend (2#)> 0
To backend> Msg complete, length 42
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> N
From backend (#4)> 118
From backend> S
From backend> "NOTICE"
From backend> V
From backend> "NOTICE"
From backend> C
From backend> "00000"
From backend> M
From backend> "table "cleanup_keys" does not exist, skipping"
From backend> F
From backend> "tablecmds.c"
From backend> L
From backend> "763"
From backend> R
From backend> "DropErrorMsgNonExistent"
From backend>
From backend> C
From backend (#4)> 15
From backend> "DROP TABLE"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "CREATE TEMPORARY TABLE cleanup_keys (log_key bigint, PRIMARY
KEY (log_key))"
To backend (2#)> 0
To backend> Msg complete, length 84
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> C
From backend (#4)> 17
From backend> "CREATE TABLE"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "DELETE FROM cleanup_keys"
To backend (2#)> 0
To backend> Msg complete, length 33
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> C
From backend (#4)> 13
From backend> "DELETE 0"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "INSERT INTO cleanup_keys SELECT log.log_key AS pkey FROM log
 JOIN "windex" AS "W1" ON "W1"."log_key"="log"."log_key"  JOIN "windex" AS
"W2" ON "W2"."log_key"="log"."log_key"  WHERE   (timestamp <=
LOCALTIMESTAMP - interval '1 minute')  AND  "log_priority" IN (10)  AND
 "W1"."word" = 8947959883223794304  AND  "W2"."word" = 5456998344637285215
 LIMIT 1000"
To backend (2#)> 0
To backend> Msg complete, length 365
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> C
From backend (#4)> 15
From backend> "INSERT 0 2"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "DELETE FROM log WHERE log.log_key IN (SELECT log_key FROM
cleanup_keys ORDER BY log_key)"
To backend (2#)> 0
To backend> Msg complete, length 97
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> C
From backend (#4)> 13
From backend> "DELETE 2"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg P
To backend> ""
To backend> "DROP TABLE IF EXISTS cleanup_keys"
To backend (2#)> 0
To backend> Msg complete, length 42
To backend> Msg B
To backend> ""
To backend> ""
To backend (2#)> 0
To backend (2#)> 0
To backend (2#)> 1
To backend (2#)> 1
To backend> Msg complete, length 15
To backend> Msg D
To backend> P
To backend> ""
To backend> Msg complete, length 7
To backend> Msg E
To backend> ""
To backend (4#)> 0
To backend> Msg complete, length 10
To backend> Msg S
To backend> Msg complete, length 5
From backend> 1
From backend (#4)> 4
From backend> 2
From backend (#4)> 4
From backend> n
From backend (#4)> 4
From backend> C
From backend (#4)> 15
From backend> "DROP TABLE"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
To backend> Msg X
To backend> Msg complete, length 5



*libpq log for TH-2*
To backend> Msg P
To backend> ""
To backend> "SELECT name, alert_query FROM filter WHERE (filter_key = $1)
AND (alert_query != '')"
To backend (2#)> 0
To backend> Msg complete, length 93
To backend> Msg S
To backend> Msg complete, length 5
From backend> E
From backend (#4)> 156
From backend> S
From backend> "FATAL"
From backend> V
From backend> "FATAL"
From backend> C
From backend> "08P01"
From backend> M
From backend> "invalid frontend message type 78 buffer:(OTICE:  table
"cleanup_keys" does not exist, skipping?)"
From backend> F
From backend> "postgres.c"
From backend> L
From backend> "474"
From backend> R
From backend> "SocketBackend"
From backend> ^@


*Jean-Francois Gauthier*
*jfgauthier@apsolab.com <Gauthierjfgauthier@apsolab.com>*
T +1 450.723.0711 | M +1 438.275.5148
*Apsolab Inc. **www.apsolab.com <http://www.apsolab.com>* *CP 354 SUCC
Bureau Chef*
*St-Bruno Qc J3V 5G8*