Backend receive buffer get corrupted with string: NOTICE: table "cleanup_keys" does not exist, skipping
От | Jean-Francois Gauthier |
---|---|
Тема | Backend receive buffer get corrupted with string: NOTICE: table "cleanup_keys" does not exist, skipping |
Дата | |
Msg-id | CAPkuZoWUxH1yRrZpSV32u+sQA_BeB8ZR8ULpmdwRhctkjaK3bQ@mail.gmail.com обсуждение исходный текст |
Ответы |
Re: Backend receive buffer get corrupted with string: NOTICE: table "cleanup_keys" does not exist, skipping
(Tom Lane <tgl@sss.pgh.pa.us>)
|
Список | 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*
В списке pgsql-bugs по дате отправления:
Предыдущее
От: Michael PaquierДата:
Сообщение: Re: got some errors after upgrade poestgresql from 9.5 to 9.6