Re: Question about ALTER TABLE DROP CONSTRAINT on 9.1 -- psql crashes

---

From: Greg Williamson <gwilliamson39@yahoo.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: "pgsql-admin@postgresql.org" <pgsql-admin@postgresql.org>
Sent: Thursday, August 9, 2012 5:35 PM
Subject: Re: [ADMIN] Question about ALTER TABLE DROP CONSTRAINT on 9.1 -- psql crashes

Tom --

---

><...>

>> 
>> WTF?  That should certainly not happen.  Have you perhaps got a script
>> that runs around sending SIGTERM to backends that it thinks are blocking
>> something?  Does anything show up in the postmaster log when this
>> happens?
>
> No, we have processes that kill IDLE IN TRANSACTIONs ruthlessly, but nothing that kills any other processes. There is an outside chance that this ran at just the

> same time that a cronjob ran the REINDEX command for the table (unlikely but I am going to shut off the cronjob and try this again).

> 

> It does not log an ERROR to the log file; I can wade intio the log and see what else it says but it will take a little while (about 800 megs per hour) to answer that.
> 
> Thanks, and I'll report back soon.

This was as all run as user postgres, unlike everything else so here is everyhting in the logsw:

2012-08-09 16:50:25.398 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,2,"authentication",2012-08-09 16:50:25 PDT,19/61906190,0,LOG,00000,"connection authorized: user=postgres database=gusher",,,,,,,,,""

2012-08-09 16:50:41.206 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,3,"SELECT",2012-08-09 16:50:25 PDT,19/0,0,LOG,00000,"duration: 3.437 ms  statement: SELECT c.oid,

2012-08-09 16:50:41.212 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,4,"SELECT",2012-08-09 16:50:25 PDT,19/0,0,LOG,00000,"duration: 4.461 ms  statement: SELECT a.attname,

2012-08-09 16:50:59.238 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,5,"ALTER TABLE",2012-08-09 16:50:25 PDT,19/61906197,1518480799,LOG,00000,"duration: 4.612 ms  statement: ALTER TABLE ourcodes ADD CONSTRAINT ourcodes_pkey PRIMARY KEY (id);",,,,,,,,,"psql"

2012-08-09 16:51:01.808 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,6,"idle in transaction",2012-08-09 16:50:25 PDT,19/61906197,1518480799,FATAL,57P01,"terminating connection due to administrator command",,,,,,,,,"psql"

2012-08-09 16:51:01.859 PDT,"postgres","gusher",13873,"[local]",50244cc1.3631,7,"idle in transaction",2012-08-09 16:50:25 PDT,,0,LOG,00000,"disconnection: session time: 0:00:36.458 user=postgres database=gusher host=[local]",,,,,,,,,"psql"

2012-08-09 16:51:02.309 PDT,"postgres","gusher",14000,"[local]",50244ce6.36b0,2,"authentication",2012-08-09 16:51:02 PDT,19/61906206,0,LOG,00000,"connection authorized: user=postgres database=gusher",,,,,,,,,""

2012-08-09 16:51:18.551 PDT,"postgres","gusher",14000,"[local]",50244ce6.36b0,3,"SELECT",2012-08-09 16:51:02 PDT,19/0,0,LOG,00000,"duration: 3.979 ms  statement: SELECT a.attname,

2012-08-09 16:51:18.556 PDT,"postgres","gusher",14000,"[local]",50244ce6.36b0,4,"SELECT",2012-08-09 16:51:02 PDT,19/0,0,LOG,00000,"duration: 5.255 ms  statement: SELECT c2.relname, i.indisprimary, i.indisunique, i.indisclustered, i.indisvalid, pg_catalog.pg_get_indexdef(i.indexrelid, 0, true),

2012-08-09 16:59:34.443 PDT,"postgres","gusher",14000,"[local]",50244ce6.36b0,5,"idle",2012-08-09 16:51:02 PDT,,0,LOG,00000,"disconnection: session time: 0:08:32.135 user=postgres database=gusher host=[local]",,,,,,,,,"psql"

Every minute on the minute there is a cronjob that kills IDLE IN CONNECTION procs older than 3 seconds ... possibly that process killed the process I was running, but to me the user it seemed as if the COMMIT came before the disconnect.

We have had some issues on this box so I probably won't test this much more today; I'll post more if I can get a reproducible case.

Thanks,

Greg