Обсуждение: BUG #15446: Crash on ALTER TABLE

The following bug has been logged on the website:

Bug reference:      15446
Logged by:          Dmitry Molotkov
Email address:      aldarund@gmail.com
PostgreSQL version: 11.0
Operating system:   docker
Description:

postgres via docker.
latest tag dont work. 

2018-10-19 23:17:31.272 UTC [1] LOG:  listening on IPv4 address "0.0.0.0",
port 5432
2018-10-19 23:17:31.272 UTC [1] LOG:  listening on IPv6 address "::", port
5432
2018-10-19 23:17:31.280 UTC [1] LOG:  listening on Unix socket
"/var/run/postgresql/.s.PGSQL.5432"
2018-10-19 23:17:31.299 UTC [62] LOG:  database system was shut down at
2018-10-19 23:17:31 UTC
2018-10-19 23:17:31.306 UTC [1] LOG:  database system is ready to accept
connections
2018-10-19 23:17:53.903 UTC [1] LOG:  server process (PID 69) was terminated
by signal 11: Segmentation fault
2018-10-19 23:17:53.903 UTC [1] DETAIL:  Failed process was running: ALTER
TABLE "admin_interface_theme" ALTER COLUMN
"related_modal_background_opacity" TYPE varchar(5) USING
"related_modal_background_opacity"::varchar(5)
2018-10-19 23:17:53.903 UTC [1] LOG:  terminating any other active server
processes
2018-10-19 23:17:53.905 UTC [66] WARNING:  terminating connection because of
crash of another server process
2018-10-19 23:17:53.905 UTC [66] DETAIL:  The postmaster has commanded this
server process to roll back the current transaction and exit, because
another server process exited abnormally and possibly corrupted shared
memory.
2018-10-19 23:17:53.905 UTC [66] HINT:  In a moment you should be able to
reconnect to the database and repeat your command.
2018-10-19 23:17:53.905 UTC [1] LOG:  all server processes terminated;
reinitializing
2018-10-19 23:17:53.931 UTC [70] LOG:  database system was interrupted; last
known up at 2018-10-19 23:17:31 UTC
2018-10-19 23:17:53.940 UTC [71] FATAL:  the database system is in recovery
mode
2018-10-19 23:17:54.139 UTC [70] LOG:  database system was not properly shut
down; automatic recovery in progress
2018-10-19 23:17:54.145 UTC [70] LOG:  redo starts at 0/1651600
2018-10-19 23:17:54.151 UTC [70] LOG:  invalid record length at 0/16C9FE8:
wanted 24, got 0
2018-10-19 23:17:54.151 UTC [70] LOG:  redo done at 0/16C9FC0
2018-10-19 23:17:54.151 UTC [70] LOG:  last completed transaction was at log
time 2018-10-19 23:17:53.888672+00
2018-10-19 23:17:54.228 UTC [1] LOG:  database system is ready to accept
connections

Happens every time with 100% reproducibility. 
Work fine on postgres:10.5 docker tag.
It is just migration from
https://github.com/fabiocaccamo/django-admin-interface package.

Hi,

On 2018-10-19 23:20:10 +0000, PG Bug reporting form wrote:
> The following bug has been logged on the website:
> 
> Bug reference:      15446
> Logged by:          Dmitry Molotkov
> Email address:      aldarund@gmail.com
> PostgreSQL version: 11.0
> Operating system:   docker
> Description:        
> 
> postgres via docker.
> latest tag dont work. 
> 
> 2018-10-19 23:17:53.903 UTC [1] LOG:  server process (PID 69) was terminated
> by signal 11: Segmentation fault
> 2018-10-19 23:17:53.903 UTC [1] DETAIL:  Failed process was running: ALTER
> TABLE "admin_interface_theme" ALTER COLUMN
> "related_modal_background_opacity" TYPE varchar(5) USING
> "related_modal_background_opacity"::varchar(5)

Unfortunately this is not enough information to reproduce the
problem. It'd be very helpful if you could provide a reproducible set of
commands that trigger the crash.  Alternatively, should that prove hard,
the very least we're going to need the table definition of that
admin_interface_theme table, so we can attempt to reproduce the issue
ourselves.

Greetings,

Andres Freund

On 2018-Oct-20, Dmitry Molotkov wrote:

> Reproduce is easy if you can install python 3.
> Here is empty django project that will reproduce it
> https://www.dropbox.com/s/4rw2dlzxvxxb5xf/djangotestpgbug.zip?dl=0
> install requirements from requirements file.
> in djangotestpgbug\settings.py - set postgres user/password/database.
> python manage.py migrate - it will run migration and it will crash
> postgres:latest from docker. Didnt tried without docker. But i dont think
> docker has anything to do with it.
> 
> Here is failing migration
>
https://github.com/fabiocaccamo/django-admin-interface/blob/master/admin_interface/migrations/0008_change_related_modal_background_opacity_type.py

I think the easiest is to turn DDL logging in the server
(log_statement=ddl) and then report exactly what is being sent to the
server, then see if you can construct a reproducer SQL script based on
that.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 2018-Oct-27, Dmitry Molotkov wrote:

> Here is query that make it crash
> 
> BEGIN;
> --
> -- Alter field related_modal_background_opacity on theme
> --
> ALTER TABLE "admin_interface_theme" ALTER COLUMN
> "related_modal_background_opacity" TYPE varchar(5) USING
> "related_modal_background_opacity"::varchar(5);
> COMMIT;

Hmm, that works fine for me :-( Can't debug further right now ...

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 2018-Oct-27, Dmitry Molotkov wrote:

> I just checked with that statement and pgadmin and it still crash the db.
> Its not related to my pc, since i initially encountered it on CI with
> totally different os and setup, and then reproduced it locally.
> https://i.imgur.com/qn1cyOz.png here what happen if i execute that alter
> query in pgadmin

It probably depends on other things in the table -- maybe indexes, or
foreign keys, or something else.  If you can reproduce in psql or
pgadmin starting from an empty database and some DDL, please submit
that.

If not, can you attach a debugger to the process before it crashes, and
get a core file?  There are some instructions here:
https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD

Thanks

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On 2019-01-05 00:01:15 +0300, Dmitry Molotkov wrote:
> That still happens in postgresql 11.1

Well, it's hard for us to fix that problem if we don't have a reliable
reproducer.

Greetings,

Andres Freund

Hi,

Please don't top-quote on postgresql lists.

On 2019-01-05 00:46:54 +0300, Dmitry Molotkov wrote:
> сб, 5 янв. 2019 г. в 00:17, Andres Freund <andres@anarazel.de>:
> > On 2019-01-05 00:01:15 +0300, Dmitry Molotkov wrote:
> > > That still happens in postgresql 11.1
> >
> > Well, it's hard for us to fix that problem if we don't have a reliable
> > reproducer.
> I provided a reliable reproducer that reproduce it in 100% cases. But it
> just involve python script..

Having to download and run code from dropbox is neither trust-inspiring (I'd
have review all the included code before running it), nor low friction... You
might get somebody else to distil that down, but in all likelihood it'll take
longer.  We all have more work than we can handle.

Greetings,

Andres Freund

On Sat, Jan 05, 2019 at 01:41:43AM +0300, Dmitry Molotkov wrote:
> Code is pretty much default empty django project with just with added
> package that cause error.
> I can create a github repo if dropbox not trust-inspiring or low friction
> :)

If you are able to create a reproducer which is made only of Python,
has only light dependencies with say psycopg2, and can be run on a
box, I am ready to buy it as a reproducer.  If you cannot get a simple
thing, you may want to log the queries generated and extract a test
case from that because there should be only SQL involved in this
problem.

Then, please post the reproducer on this mailing list or just attach
it.  This way, it can be seen and fetched again easily just using the
PostgreSQL community mail archives.  If you post it only on github or
dropbox and if the source disappears (because companies go bankrupt
all the time), then we would lose it.  I hope this makes sense.
--
Michael

Dmitry Molotkov <aldarund@gmail.com> writes:
> сб, 5 янв. 2019 г. в 01:25, Andres Freund <andres@anarazel.de>:
>> Having to download and run code from dropbox is neither trust-inspiring
>> (I'd have review all the included code before running it), nor low friction...

> Code is pretty much default empty django project with just with added
> package that cause error.

It's the "django" part of that that is outside my comfort zone, and I'd
guess Andres' as well.  I don't run django, and I'm not interested in
learning about it just to reproduce a bug report.  As Andres said,
this would get looked at a lot quicker if the requirements to reproduce
it were low --- like, say, a small shell or perl or python script.

            regards, tom lane

On Sat, 5 Jan 2019 at 00:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Dmitry Molotkov <aldarund@gmail.com> writes:
> > сб, 5 янв. 2019 г. в 01:25, Andres Freund <andres@anarazel.de>:
> >> Having to download and run code from dropbox is neither trust-inspiring
> >> (I'd have review all the included code before running it), nor low friction...
>
> > Code is pretty much default empty django project with just with added
> > package that cause error.
>
> It's the "django" part of that that is outside my comfort zone, and I'd
> guess Andres' as well.  I don't run django, and I'm not interested in
> learning about it just to reproduce a bug report.  As Andres said,
> this would get looked at a lot quicker if the requirements to reproduce
> it were low --- like, say, a small shell or perl or python script.

Boiling down the queries from the links provided, I can reproduce this
with the following simple test case:

DROP TABLE IF EXISTS foo;
CREATE TABLE foo (a int);
ALTER TABLE foo ADD COLUMN b double precision DEFAULT 0.2;
ALTER TABLE foo ALTER COLUMN b TYPE varchar(5) USING b::varchar(5);

which crashes with the following:

#0  0x00007fca1c77515e in __memcpy_sse2_unaligned () from /lib64/libc.so.6
#1  0x0000000000921a6c in datumCopy (value=35278072, typByVal=false, typLen=-1)
    at datum.c:159
#2  0x0000000000a2a56d in RelationBuildTupleDesc (relation=0x7fca1343bdc8)
    at relcache.c:620
#3  0x0000000000a2b7a0 in RelationBuildDesc (targetRelId=16395, insertIt=false)
    at relcache.c:1157
#4  0x0000000000a2df1c in RelationClearRelation (relation=0x7fca13439c88,
    rebuild=true) at relcache.c:2446
#5  0x0000000000a2e460 in RelationFlushRelation (relation=0x7fca13439c88)
    at relcache.c:2584
#6  0x0000000000a2e572 in RelationCacheInvalidateEntry (relationId=16395)
    at relcache.c:2636
#7  0x0000000000a20fac in LocalExecuteInvalidationMessage (msg=0x2161710)
    at inval.c:587
#8  0x0000000000a20d0c in ProcessInvalidationMessages (hdr=0x21612a0,
    func=0xa20ea9 <LocalExecuteInvalidationMessage>) at inval.c:458
#9  0x0000000000a217dd in CommandEndInvalidationMessages () at inval.c:1093
#10 0x00000000005585c0 in AtCCI_LocalCache () at xact.c:1373
#11 0x0000000000557fd9 in CommandCounterIncrement () at xact.c:955
#12 0x000000000069f819 in ATExecAlterColumnType (tab=0x21a2370,
    rel=0x7fca13439c88, cmd=0x21a34d0, lockmode=8) at tablecmds.c:9642
#13 0x0000000000693af6 in ATExecCmd (wqueue=0x7ffcb60097a8, tab=0x21a2370,
    rel=0x7fca13439c88, cmd=0x21a34d0, lockmode=8) at tablecmds.c:4181
#14 0x00000000006933b1 in ATRewriteCatalogs (wqueue=0x7ffcb60097a8, lockmode=8)
    at tablecmds.c:4025
#15 0x0000000000692b9e in ATController (parsetree=0x21a00c8,
    rel=0x7fca13439c88, cmds=0x21a3528, recurse=true, lockmode=8)
    at tablecmds.c:3691
#16 0x00000000006928db in AlterTable (relid=16395, lockmode=8, stmt=0x21a00c8)
    at tablecmds.c:3365


It looks like the problem was introduced in PG11 by 16828d5c02 (Fast
ALTER TABLE ADD COLUMN with a non-NULL default). The first ALTER TABLE
adds a new column with a non-null default, setting atthasmissing and
attmissingval. Then the second ALTER TABLE changes the type of the new
column, but it fails to update attmissingval to match, and thus it
falls over when trying to re-open the relation because the value in
attmissingval is no longer compatible with the attribute type.

Regards,
Dean

Hi,

On 2019-01-05 12:11:45 +0000, Dean Rasheed wrote:
> It looks like the problem was introduced in PG11 by 16828d5c02 (Fast
> ALTER TABLE ADD COLUMN with a non-NULL default). The first ALTER TABLE
> adds a new column with a non-null default, setting atthasmissing and
> attmissingval. Then the second ALTER TABLE changes the type of the new
> column, but it fails to update attmissingval to match, and thus it
> falls over when trying to re-open the relation because the value in
> attmissingval is no longer compatible with the attribute type.

Paging Dr Dunstan.

Greetings,

Andres Freund

On 1/5/19 12:09 PM, Andres Freund wrote:
> Hi,
>
> On 2019-01-05 12:11:45 +0000, Dean Rasheed wrote:
>> It looks like the problem was introduced in PG11 by 16828d5c02 (Fast
>> ALTER TABLE ADD COLUMN with a non-NULL default). The first ALTER TABLE
>> adds a new column with a non-null default, setting atthasmissing and
>> attmissingval. Then the second ALTER TABLE changes the type of the new
>> column, but it fails to update attmissingval to match, and thus it
>> falls over when trying to re-open the relation because the value in
>> attmissingval is no longer compatible with the attribute type.
> Paging Dr Dunstan.



Investigating with this test case:


    DROP TABLE IF EXISTS foo;
    CREATE TABLE foo (a int);
    ALTER TABLE foo ADD COLUMN b double precision DEFAULT 0.2;
    ALTER TABLE foo ALTER COLUMN b TYPE varchar(5) USING b::varchar(5);


cheers


andrew

-- 
Andrew Dunstan                https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services