BUG #14529: Missing non pk data for "before image" in logical decoding

The following bug has been logged on the website:

Bug reference: 14529
Logged by: Philippe BEAUDOIN
Email address: philippe(dot)beaudoin(at)dalibo(dot)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(at)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.