Обсуждение: amcheck assert failure

Поиск
Список
Период
Сортировка

amcheck assert failure

От
Grigory Smolkin
Дата:
Hello, everyone!
I was running some automated tests with amcheck on PG11 and encountered 
following assertion failure:

TRAP: FailedAssertion("!((( (&(itup)->t_tid)->ip_posid ) & 0xF000) == 
0)", File: "nbtutils.c", Line: 2168)
2019-04-20 01:03:37 GMT [17923]: [1-1] LOG:  connection received: 
host=[local]
2019-04-20 01:03:37 GMT [17923]: [2-1] LOG:  connection authorized: 
user=gsmol database=db1
2019-04-20 01:03:37 GMT [17886]: [9-1] LOG:  server process (PID 17922) 
was terminated by signal 6: Aborted
2019-04-20 01:03:37 GMT [17886]: [10-1] DETAIL:  Failed process was 
running: SELECT public.bt_index_check('pgbench_accounts_pkey', false);


1. pgbench setup in question was initialized with scale_factor 5. 
bt_index_check() was launched right after initialization.
2. pg_config:
BINDIR = /home/gsmol/task/11/bin
DOCDIR = /home/gsmol/task/11/share/doc/postgresql
HTMLDIR = /home/gsmol/task/11/share/doc/postgresql
INCLUDEDIR = /home/gsmol/task/11/include
PKGINCLUDEDIR = /home/gsmol/task/11/include/postgresql
INCLUDEDIR-SERVER = /home/gsmol/task/11/include/postgresql/server
LIBDIR = /home/gsmol/task/11/lib
PKGLIBDIR = /home/gsmol/task/11/lib/postgresql
LOCALEDIR = /home/gsmol/task/11/share/locale
MANDIR = /home/gsmol/task/11/share/man
SHAREDIR = /home/gsmol/task/11/share/postgresql
SYSCONFDIR = /home/gsmol/task/11/etc/postgresql
PGXS = /home/gsmol/task/11/lib/postgresql/pgxs/src/makefiles/pgxs.mk
CONFIGURE = '--prefix=/home/gsmol/task/11' '--enable-debug' 
'--enable-cassert' 'CFLAGS=-g3 -O0' '--with-python'
CC = gcc
CPPFLAGS = -D_GNU_SOURCE
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Wendif-labels -Wmissing-format-attribute 
-Wformat-security -fno-strict-aliasing -fwrapv 
-fexcess-precision=standard -g -g3 -O0
CFLAGS_SL = -fPIC
LDFLAGS = -Wl,--as-needed 
-Wl,-rpath,'/home/gsmol/task/11/lib',--enable-new-dtags
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lpthread -lz -lreadline -lrt -lcrypt -ldl -lm
VERSION = PostgreSQL 11.2

3. PG configuration:
listen_addresses = '127.0.0.1'
max_worker_processes = 10
port = 21387
fsync = off
log_statement = 'all'
max_replication_slots = 10
hot_standby = on
wal_keep_segments = 20
wal_level = 'replica'
max_connections = 100
shared_buffers = 10MB
fsync = off
wal_level = logical
hot_standby = off
log_line_prefix = '%t [%p]: [%l-1] '
log_statement = none
log_duration = on
log_min_duration_statement = 0
log_connections = on
log_disconnections = on
max_wal_senders = 10

P.S. If some additional information will be needed, I`d be glad to help.

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company




Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Fri, Apr 19, 2019 at 6:15 PM Grigory Smolkin
<g.smolkin@postgrespro.ru> wrote:
> Hello, everyone!
> I was running some automated tests with amcheck on PG11 and encountered
> following assertion failure:
>
> TRAP: FailedAssertion("!((( (&(itup)->t_tid)->ip_posid ) & 0xF000) ==
> 0)", File: "nbtutils.c", Line: 2168)

Was the assertion failure on Postgres Pro's fork? I understand that
there are differences in this exact area on the forked version,
because it has to deal with two representations -- the fork had
INCLUDE indexes before the community version, which explicitly
represents the number of attributes in pivot tuples.

I wouldn't usually ask this, but the failure is very basic. It's hard
to believe that it would take this long to notice it.

I also note that you have "fsync = off". I suppose that that might be
relevant, too.
-- 
Peter Geoghegan



Re: amcheck assert failure

От
Grigory Smolkin
Дата:
Hello!

On 04/20/2019 04:30 AM, Peter Geoghegan wrote:

> On Fri, Apr 19, 2019 at 6:15 PM Grigory Smolkin
> <g.smolkin@postgrespro.ru> wrote:
>> Hello, everyone!
>> I was running some automated tests with amcheck on PG11 and encountered
>> following assertion failure:
>>
>> TRAP: FailedAssertion("!((( (&(itup)->t_tid)->ip_posid ) & 0xF000) ==
>> 0)", File: "nbtutils.c", Line: 2168)
> Was the assertion failure on Postgres Pro's fork? I understand that
> there are differences in this exact area on the forked version,
> because it has to deal with two representations -- the fork had
> INCLUDE indexes before the community version, which explicitly
> represents the number of attributes in pivot tuples.
No, it`s vanilla PG11:
db2=# select version();
version
--------------------------------------------------------------------------------------------------------
  PostgreSQL 11.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 6.3.1 
20161221 (Red Hat 6.3.1-1), 64-bit
(1 row)
>
> I wouldn't usually ask this, but the failure is very basic. It's hard
> to believe that it would take this long to notice it.
Maybe it wasn't noticed because binaries, shipped to users, usually 
compiled without '--cassert-enable'.
> I also note that you have "fsync = off". I suppose that that might be
> relevant, too.
It`s automated test, instance get inited, filled with data, subjected 
with various tests and deleted in span of several seconds. And no crash 
has happened during this time.

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company




Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Sat, Apr 20, 2019 at 2:08 AM Grigory Smolkin
<g.smolkin@postgrespro.ru> wrote:
> It`s automated test, instance get inited, filled with data, subjected
> with various tests and deleted in span of several seconds. And no crash
> has happened during this time.

Can you send me a raw binary dump of the page using pageinspect?
Something like the following command line recipe will do it:

$ psql -XAtc "SELECT encode(get_raw_page('pgbench_pkey',
42),'base64')" | base64 -d > dump_block_42.page

Obviously you'll need to figure out which block number the problem
page is located in before you do this, but that shouldn't be hard --
get a coredump and inspect the state from amcheck a few frames down.

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Sat, Apr 20, 2019 at 2:00 PM Peter Geoghegan <pg@bowt.ie> wrote:
> Obviously you'll need to figure out which block number the problem
> page is located in before you do this, but that shouldn't be hard --
> get a coredump and inspect the state from amcheck a few frames down.

Alternatively, you could dump the page image from within gdb. Go to
the frame for _bt_check_natts() (e.g., enter "f 1"), and then dump the
contents of the page to file:

(gdb) dump binary memory /tmp/dump_block.page page (page + 8192)

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Sat, Apr 20, 2019 at 2:37 PM Peter Geoghegan <pg@bowt.ie> wrote:
> Alternatively, you could dump the page image from within gdb. Go to
> the frame for _bt_check_natts() (e.g., enter "f 1"), and then dump the
> contents of the page to file:

I was inspired to do a write-up on this for the Wiki:


https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

Seems like a good idea to centralize knowledge of backend
instrumentation that's useful for bug reports, even beyond GDB.

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Grigory Smolkin
Дата:
I`m sorry for a delay, was away from PC during weekend.

On 04/21/2019 02:06 AM, Peter Geoghegan wrote:
> On Sat, Apr 20, 2019 at 2:37 PM Peter Geoghegan <pg@bowt.ie> wrote:
>> Alternatively, you could dump the page image from within gdb. Go to
>> the frame for _bt_check_natts() (e.g., enter "f 1"), and then dump the
>> contents of the page to file:
> I was inspired to do a write-up on this for the Wiki:
>
>
https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB
>
> Seems like a good idea to centralize knowledge of backend
> instrumentation that's useful for bug reports, even beyond GDB.
>

Wow, that` neat, thank you for a dump instruction!
Attached.

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company


Вложения

Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Mon, Apr 22, 2019 at 9:03 AM Grigory Smolkin
<g.smolkin@postgrespro.ru> wrote:
> Wow, that` neat, thank you for a dump instruction!
> Attached.

This looks like it was deliberately corrupted. Line pointer 255 is an
LP_REDIRECT, line pointer, while line pointer 256 and 257 are
LP_UNUSED, which should never happen.

The ascii string "blablahblah" has been overwritten at byte offset
1040 (from the beginning of the page). I would take a closer look at
what those tests do. Either the problem is in the tests, or your
database is haunted, which is outside my area of expertise.

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Grigory Smolkin
Дата:
On 04/22/2019 09:05 PM, Peter Geoghegan wrote:
> On Mon, Apr 22, 2019 at 9:03 AM Grigory Smolkin
> <g.smolkin@postgrespro.ru> wrote:
>> Wow, that` neat, thank you for a dump instruction!
>> Attached.
> This looks like it was deliberately corrupted. Line pointer 255 is an
> LP_REDIRECT, line pointer, while line pointer 256 and 257 are
> LP_UNUSED, which should never happen.
>
> The ascii string "blablahblah" has been overwritten at byte offset
> 1040 (from the beginning of the page). I would take a closer look at
> what those tests do. Either the problem is in the tests, or your
> database is haunted, which is outside my area of expertise.
>
I`m so stupid >.<
It`s data corruption test, but I`ve forgot to turn checksums on.
I`m sorry for wasting your time.

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company




Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Mon, Apr 22, 2019 at 12:48 PM Grigory Smolkin
<g.smolkin@postgrespro.ru> wrote:
> I`m so stupid >.<
> It`s data corruption test, but I`ve forgot to turn checksums on.
> I`m sorry for wasting your time.

Don't worry about it - everyone makes stupid mistakes.

I got a laugh out of it, and it caused me to document the process for
dumping out page images within GDB, so there was some benefit.

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Tom Lane
Дата:
Grigory Smolkin <g.smolkin@postgrespro.ru> writes:
> On 04/22/2019 09:05 PM, Peter Geoghegan wrote:
>> The ascii string "blablahblah" has been overwritten at byte offset
>> 1040 (from the beginning of the page). I would take a closer look at
>> what those tests do. Either the problem is in the tests, or your
>> database is haunted, which is outside my area of expertise.

> It`s data corruption test, but I`ve forgot to turn checksums on.
> I`m sorry for wasting your time.

Nonetheless ... do we really want an assertion failure rather than
some more-mundane error report?  Seems like the point of amcheck
is to detect data corruption, so I'd rather get an ERROR than an
assertion (which would not fire in production builds anyway).

            regards, tom lane



Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Mon, Apr 22, 2019 at 12:51 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Nonetheless ... do we really want an assertion failure rather than
> some more-mundane error report?  Seems like the point of amcheck
> is to detect data corruption, so I'd rather get an ERROR than an
> assertion (which would not fire in production builds anyway).

(Apologies for sending this a second time, Tom -- somehow failed to CC
the list the first time)

I think that the size cross-check must have failed to catch the problem:

        /*
         * lp_len should match the IndexTuple reported length exactly, since
         * lp_len is completely redundant in indexes, and both sources of
         * tuple length are MAXALIGN()'d.  nbtree does not use lp_len all that
         * frequently, and is surprisingly tolerant of corrupt lp_len fields.
         */
        if (tupsize != ItemIdGetLength(itemid))
            ereport(ERROR,
                    (errcode(ERRCODE_INDEX_CORRUPTED),
                     errmsg("index tuple size does not equal lp_len in
index \"%s\"",
                            RelationGetRelationName(state->rel)),
                     errdetail_internal("Index tid=(%u,%u) tuple
size=%zu lp_len=%u page lsn=%X/%X.",
                                        state->targetblock, offset,
                                        tupsize, ItemIdGetLength(itemid),
                                        (uint32) (state->targetlsn >> 32),
                                        (uint32) state->targetlsn),
                     errhint("This could be a torn page problem.")));

It seems like the length from tupsize (IndexTupleSize()) happened to
match the redundant ItemIdGetLength()-reported size from the line
pointer. No idea how that could actually be possible, since the value
returned by ItemIdGetLength() would be 12592. What are the chances of
that accidentally matching what the wild itup pointer reported as its
IndexTupleSize()?

The only explanation I can think of is that the assertion failure was
from the core code -- _bt_check_natts() is itself called within core
code assertions, so it's just about possible that that was how this
happened, before amcheck was even called. Doesn't seem like a very
good explanation. Do you think that that's possible, Grigory?

In any case, you're clearly right that amcheck could be more defensive
here. My pg_hexedit tool detected that there was an LP_UNUSED item
pointer with storage (i.e. whose lp_len > 0), which is a check that
amcheck can and should perform, but doesn't. Especially because it
would prevent a deference of a likely-wild pointer (IndexTuple).

We could:

* Throw an error when any line item reports lp_len == 0.

* Throw an error when there is a line item that's either LP_UNUSED, or
LP_REDIRECT. The corrupt page sent by Grigory had both.

What do you think of the idea of committing some simple checks to do
this with contrib/amcheck on v12?

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Tom Lane
Дата:
Peter Geoghegan <pg@bowt.ie> writes:
> On Mon, Apr 22, 2019 at 12:51 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Nonetheless ... do we really want an assertion failure rather than
>> some more-mundane error report?  Seems like the point of amcheck
>> is to detect data corruption, so I'd rather get an ERROR than an
>> assertion (which would not fire in production builds anyway).

> The only explanation I can think of is that the assertion failure was
> from the core code

That's what I guessed.  It might be impractical for amcheck to prevent it,
but we should try to find out.

> We could:
> * Throw an error when any line item reports lp_len == 0.
> * Throw an error when there is a line item that's either LP_UNUSED, or
> LP_REDIRECT. The corrupt page sent by Grigory had both.
> What do you think of the idea of committing some simple checks to do
> this with contrib/amcheck on v12?

No objection here, as long as it doesn't add an unreasonable amount
of complexity.  (If it does, we might have to think harder about
what to do.)

            regards, tom lane



Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Mon, Apr 22, 2019 at 1:35 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > The only explanation I can think of is that the assertion failure was
> > from the core code
>
> That's what I guessed.  It might be impractical for amcheck to prevent it,
> but we should try to find out.

On second thought, amcheck is very unlikely to have accessed a corrupt
system catalog index or something at the same time the pgbench_pkey
index was also corrupt. The page image did appear to be from
pgbench_pkey, so it would take two corrupt indexes at the same time
for the assertion failure to be from the core code, outside of
amcheck.

A slightly less insane theory is that this has something to do with
undefined behavior. Hard to imagine how that could make amcheck's test
go away, but I've heard horror stories that were at least
superficially similar to what I have in mind.

In any case, it will be possible to make amcheck avoid undefined
behavior when a page image is corrupt. That seems like a worthy goal,
regardless of the specifics of this case, because amcheck's charter is
to absolutely distrust on-disk state.

> No objection here, as long as it doesn't add an unreasonable amount
> of complexity.  (If it does, we might have to think harder about
> what to do.)

I want to do some basic sanity checking of the line pointer against
the page header, to ensure that any index tuple pointer actually
points to memory that it's safe to do a load from (i.e. from the temp
BLCKSZ buffer). I'll add another check to that list:

* Make sure that each line pointer is "lp_off < pd_special". Note that
pg_special is already verified-sane for each page.

These checks are simple and low risk in my opinion. I will come up
with a patch in the next few days.

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Grigory Smolkin
Дата:

On 04/22/2019 11:31 PM, Peter Geoghegan wrote:
> On Mon, Apr 22, 2019 at 12:51 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Nonetheless ... do we really want an assertion failure rather than
>> some more-mundane error report?  Seems like the point of amcheck
>> is to detect data corruption, so I'd rather get an ERROR than an
>> assertion (which would not fire in production builds anyway).
> (Apologies for sending this a second time, Tom -- somehow failed to CC
> the list the first time)
>
> I think that the size cross-check must have failed to catch the problem:
>
>          /*
>           * lp_len should match the IndexTuple reported length exactly, since
>           * lp_len is completely redundant in indexes, and both sources of
>           * tuple length are MAXALIGN()'d.  nbtree does not use lp_len all that
>           * frequently, and is surprisingly tolerant of corrupt lp_len fields.
>           */
>          if (tupsize != ItemIdGetLength(itemid))
>              ereport(ERROR,
>                      (errcode(ERRCODE_INDEX_CORRUPTED),
>                       errmsg("index tuple size does not equal lp_len in
> index \"%s\"",
>                              RelationGetRelationName(state->rel)),
>                       errdetail_internal("Index tid=(%u,%u) tuple
> size=%zu lp_len=%u page lsn=%X/%X.",
>                                          state->targetblock, offset,
>                                          tupsize, ItemIdGetLength(itemid),
>                                          (uint32) (state->targetlsn >> 32),
>                                          (uint32) state->targetlsn),
>                       errhint("This could be a torn page problem.")));
>
> It seems like the length from tupsize (IndexTupleSize()) happened to
> match the redundant ItemIdGetLength()-reported size from the line
> pointer. No idea how that could actually be possible, since the value
> returned by ItemIdGetLength() would be 12592. What are the chances of
> that accidentally matching what the wild itup pointer reported as its
> IndexTupleSize()?
>
> The only explanation I can think of is that the assertion failure was
> from the core code -- _bt_check_natts() is itself called within core
> code assertions, so it's just about possible that that was how this
> happened, before amcheck was even called. Doesn't seem like a very
> good explanation. Do you think that that's possible, Grigory?

No, it was definitely amcheck:
https://pastebin.postgrespro.ru/?2c8ddf5254b2c625#PTbr+jbxFPu2wfy5SFDWdiqaqPN/N5WX8t6mo5rDpmo=

>
> In any case, you're clearly right that amcheck could be more defensive
> here. My pg_hexedit tool detected that there was an LP_UNUSED item
> pointer with storage (i.e. whose lp_len > 0), which is a check that
> amcheck can and should perform, but doesn't. Especially because it
> would prevent a deference of a likely-wild pointer (IndexTuple).
>
> We could:
>
> * Throw an error when any line item reports lp_len == 0.
>
> * Throw an error when there is a line item that's either LP_UNUSED, or
> LP_REDIRECT. The corrupt page sent by Grigory had both.
>
> What do you think of the idea of committing some simple checks to do
> this with contrib/amcheck on v12?
>

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company




Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Wed, Apr 24, 2019 at 1:50 AM Grigory Smolkin
<g.smolkin@postgrespro.ru> wrote:
> No, it was definitely amcheck:
> https://pastebin.postgrespro.ru/?2c8ddf5254b2c625#PTbr+jbxFPu2wfy5SFDWdiqaqPN/N5WX8t6mo5rDpmo=

Please just post the stack trace to the list in future. We value
having that directly available from the archives.

It looks like the assertion failure happens at the point where the
next tuple is being compared to the current one, in respect of the
next tuple. The assertion failure occurs in the core code,
technically, though it is pretty much under the direct control of
amcheck at the time.

This means that my exotic explanation was wrong, and the actual
explanation is quite simple. (I told you that everyone makes stupid
mistakes.)

-- 
Peter Geoghegan



Re: amcheck assert failure

От
Peter Geoghegan
Дата:
On Mon, Apr 22, 2019 at 1:35 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> No objection here, as long as it doesn't add an unreasonable amount
> of complexity.  (If it does, we might have to think harder about
> what to do.)

Attached is a draft patch that adds a PageGetItemId() wrapper called
PageGetItemIdCareful(), and has amcheck use it consistently. This does
two basic sanity checks that seem very likely to avoid the kind of
misbehaviors that result in a crash (including assertion failures)
when amcheck is used.

This is a bit more complicated than I'd hoped, because it is necessary
to call PageGetItemIdCareful() before _bt_compare() and other core
code in a way that wouldn't quite look right with raw PageGetItemId()
calls. _bt_compare() will do its own PageGetItemId(), and will itself
assert !bt_check_natts() (which was the issue in Grigory's problem
report), so we need to make sure that that will be safe ahead of time.
Even still, it doesn't seem too complicated to me.

-- 
Peter Geoghegan

Вложения