[BUGS] BUG #14529: Missing non pk data for "before image" in logical decoding - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      14529
Logged by:          Philippe BEAUDOIN
Email address:      philippe.beaudoin@dalibo.com
PostgreSQL version: 9.6.1
Operating system:   Linux
Description:

I am currently studying the logical decoding mechanism as an alternative to
log triggers for the E-Maj extension.
Using pg_recvlogical and pgbench, I have been able to reproduce an issue
that I met.

In short, I initialize the pgbench environment and set the REPLICA IDENTITY
to FULL on  pgbench tables. Then I inject just 2 pgbench transactions and
collect the changes by pg_recvlogical, using the 'test_logical' output
plugin. The pg_recvlogical output shows the INSERT and the 3 UPDATEs of each
transaction. But for 2 of these UPDATEs, one only gets the value of the pkey
columns. The other columns are missing despite the REPLICA IDENTITY set to
FULL.

Using pg_xlogdump to look at the wal, I remarked that the faulting UPDATES
are "HOT_UPDATE", while the usual "UPDATE" are OK. 

Here is a simple test case script:

#-------------------------------------------------------------------------------
#!/bin/sh

export PGHOST=localhost
export PGPORT=5496
export PGUSER=postgres
export PGDATABASE=testdb

echo "*** -----------------------------"
echo "*** Initializing testdb database"
echo "*** -----------------------------"
dropdb testdb
createdb testdb

pgbench -i --foreign-keys

psql <<EOF1
-- show specific GUC parameters
show wal_level;
show max_wal_senders;
show max_replication_slots;

-- set all table with replica identity full to get all data for old row in
UPDATE or DELETE verbs
alter table pgbench_tellers replica identity full;
alter table pgbench_accounts replica identity full;
alter table pgbench_branches replica identity full;
alter table pgbench_history replica identity full;

-- check the replica identity is effectively set
select relname, relreplident from pg_class where relname like 'pgbench%' and
relkind = 'r';
\d+ pgbench_tellers
\d+ pgbench_accounts
\d+ pgbench_branches
\d+ pgbench_history
EOF1

echo "*** -----------------------------"
echo "*** Start pg_recvlogical using the test_decoding output plugin"
echo "*** -----------------------------"
pg_recvlogical -d testdb -h localhost -p 5496 --create-slot --slot
test_logical --plugin test_decoding --no-loop
pg_recvlogical -d testdb -h localhost -p 5496 --start --slot test_logical -f
bug_decoding.log &

echo "*** -----------------------------"
echo "*** Generate load"
echo "*** -----------------------------"
pgbench --transactions 2

echo "*** -----------------------------"
echo "*** Stop pg_recvlogical"
echo "*** -----------------------------"
sleep 1
kill $!
pg_recvlogical -d testdb -h localhost -p 5496 --slot test_logical
--drop-slot

echo "*** -----------------------------"
echo "*** Looking at the end of report"
echo "*** !!! UPDATEs on pgbench_tellers and pgbench_branches show truncated
old rows (only pk columns are displayed),"
echo "*** while pgbench_account is processed correctly and REPLICA IDENTITY
is correctly set to FULL for all tables."
echo "*** also true with the SQL interface."
echo "*** -----------------------------"
tail -n 12 bug_decoding.log
#-------------------------------------------------------------------------------

Here is the output I got:
#-------------------------------------------------------------------------------
postgres@postgres-VirtualBox:~/proj/divers/test_logical$ sh
bug_decoding.sh
*** -----------------------------
*** Initializing testdb database
*** -----------------------------
NOTICE:  table "pgbench_history" does not exist, skipping
NOTICE:  table "pgbench_tellers" does not exist, skipping
NOTICE:  table "pgbench_accounts" does not exist, skipping
NOTICE:  table "pgbench_branches" does not exist, skipping
creating tables...
100000 of 100000 tuples (100%) done (elapsed 0.03 s, remaining 0.00 s)
vacuum...
set primary keys...
set foreign keys...
done.
 wal_level
-----------
 logical
(1 row)

 max_wal_senders
-----------------
 2
(1 row)

 max_replication_slots
-----------------------
 2
(1 row)

ALTER TABLE
ALTER TABLE
ALTER TABLE
ALTER TABLE
     relname      | relreplident
------------------+--------------
 pgbench_accounts | f
 pgbench_branches | f
 pgbench_history  | f
 pgbench_tellers  | f
(4 rows)

                        Table "public.pgbench_tellers"
  Column  |     Type      | Modifiers | Storage  | Stats target |
Description
----------+---------------+-----------+----------+--------------+-------------
 tid      | integer       | not null  | plain    |              |
 bid      | integer       |           | plain    |              |
 tbalance | integer       |           | plain    |              |
 filler   | character(84) |           | extended |              |
Indexes:
    "pgbench_tellers_pkey" PRIMARY KEY, btree (tid)
Foreign-key constraints:
    "pgbench_tellers_bid_fkey" FOREIGN KEY (bid) REFERENCES
pgbench_branches(bid)
Referenced by:
    TABLE "pgbench_history" CONSTRAINT "pgbench_history_tid_fkey" FOREIGN
KEY (tid) REFERENCES pgbench_tellers(tid)
Replica Identity: FULL
Options: fillfactor=100

                       Table "public.pgbench_accounts"
  Column  |     Type      | Modifiers | Storage  | Stats target |
Description
----------+---------------+-----------+----------+--------------+-------------
 aid      | integer       | not null  | plain    |              |
 bid      | integer       |           | plain    |              |
 abalance | integer       |           | plain    |              |
 filler   | character(84) |           | extended |              |
Indexes:
    "pgbench_accounts_pkey" PRIMARY KEY, btree (aid)
Foreign-key constraints:
    "pgbench_accounts_bid_fkey" FOREIGN KEY (bid) REFERENCES
pgbench_branches(bid)
Referenced by:
    TABLE "pgbench_history" CONSTRAINT "pgbench_history_aid_fkey" FOREIGN
KEY (aid) REFERENCES pgbench_accounts(aid)
Replica Identity: FULL
Options: fillfactor=100

                       Table "public.pgbench_branches"
  Column  |     Type      | Modifiers | Storage  | Stats target |
Description
----------+---------------+-----------+----------+--------------+-------------
 bid      | integer       | not null  | plain    |              |
 bbalance | integer       |           | plain    |              |
 filler   | character(88) |           | extended |              |
Indexes:
    "pgbench_branches_pkey" PRIMARY KEY, btree (bid)
Referenced by:
    TABLE "pgbench_accounts" CONSTRAINT "pgbench_accounts_bid_fkey" FOREIGN
KEY (bid) REFERENCES pgbench_branches(bid)
    TABLE "pgbench_history" CONSTRAINT "pgbench_history_bid_fkey" FOREIGN
KEY (bid) REFERENCES pgbench_branches(bid)
    TABLE "pgbench_tellers" CONSTRAINT "pgbench_tellers_bid_fkey" FOREIGN
KEY (bid) REFERENCES pgbench_branches(bid)
Replica Identity: FULL
Options: fillfactor=100

                              Table "public.pgbench_history"
 Column |            Type             | Modifiers | Storage  | Stats target
| Description
--------+-----------------------------+-----------+----------+--------------+-------------
 tid    | integer                     |           | plain    |
|
 bid    | integer                     |           | plain    |
|
 aid    | integer                     |           | plain    |
|
 delta  | integer                     |           | plain    |
|
 mtime  | timestamp without time zone |           | plain    |
|
 filler | character(22)               |           | extended |
|
Foreign-key constraints:
    "pgbench_history_aid_fkey" FOREIGN KEY (aid) REFERENCES
pgbench_accounts(aid)
    "pgbench_history_bid_fkey" FOREIGN KEY (bid) REFERENCES
pgbench_branches(bid)
    "pgbench_history_tid_fkey" FOREIGN KEY (tid) REFERENCES
pgbench_tellers(tid)
Replica Identity: FULL

*** -----------------------------
*** Start pg_recvlogical using the test_decoding output plugin
*** -----------------------------
*** -----------------------------
*** Generate load
*** -----------------------------
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
number of transactions per client: 2
number of transactions actually processed: 2/2
latency average = 15.345 ms
tps = 65.167807 (including connections establishing)
tps = 78.259509 (excluding connections establishing)
*** -----------------------------
*** Stop pg_recvlogical
*** -----------------------------
*** -----------------------------
*** Looking at the end of report
*** !!! UPDATEs on pgbench_tellers and pgbench_branches show truncated old
rows (only pk columns are displayed),
*** while pgbench_account is processed correctly and REPLICA IDENTITY is
correctly set to FULL for all tables.
*** also true with the SQL interface.
*** -----------------------------
BEGIN 5454770
table public.pgbench_accounts: UPDATE: old-key: aid[integer]:24469
bid[integer]:1 abalance[integer]:0 filler[character]:'
                                                             ' new-tuple:
aid[integer]:24469 bid[integer]:1 abalance[integer]:-3373
filler[character]:'
                          '
table public.pgbench_tellers: UPDATE: old-key: tid[integer]:2 bid[integer]:1
tbalance[integer]:0 new-tuple: tid[integer]:2 bid[integer]:1
tbalance[integer]:-3373 filler[character]:null
table public.pgbench_branches: UPDATE: old-key: bid[integer]:1
bbalance[integer]:0 new-tuple: bid[integer]:1 bbalance[integer]:-3373
filler[character]:null
table public.pgbench_history: INSERT: tid[integer]:2 bid[integer]:1
aid[integer]:24469 delta[integer]:-3373 mtime[timestamp without time
zone]:'2017-01-21 09:51:29.728733' filler[character]:null
COMMIT 5454770
BEGIN 5454771
table public.pgbench_accounts: UPDATE: old-key: aid[integer]:4016
bid[integer]:1 abalance[integer]:0 filler[character]:'
                                                             ' new-tuple:
aid[integer]:4016 bid[integer]:1 abalance[integer]:3308 filler[character]:'

     '
table public.pgbench_tellers: UPDATE: old-key: tid[integer]:2 bid[integer]:1
tbalance[integer]:-3373 new-tuple: tid[integer]:2 bid[integer]:1
tbalance[integer]:-65 filler[character]:null
table public.pgbench_branches: UPDATE: old-key: bid[integer]:1
bbalance[integer]:-3373 new-tuple: bid[integer]:1 bbalance[integer]:-65
filler[character]:null
table public.pgbench_history: INSERT: tid[integer]:2 bid[integer]:1
aid[integer]:4016 delta[integer]:3308 mtime[timestamp without time
zone]:'2017-01-21 09:51:29.74555' filler[character]:null
COMMIT 5454771
#-------------------------------------------------------------------------------

The incomplete UPDATEs concern pgbench_tellers and pgbench_branches
tables.



--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs