BUG #14710: Function now() and logical replication

The following bug has been logged on the website:

Bug reference: 14710
Logged by: Konstantin Evteev
Email address: konst583(at)gmail(dot)com
PostgreSQL version: 10beta1
Operating system: Debian GNU/Linux 8 (jessie)
Description:

Hello!
I have found a bug in logical replication and function now() on
subscriber.
now() always returns the same result (backend_start - logical replication
worker for subscription).
I'm using postgres 10 compiled from master branch
commit af51fea039bb8e00066d68d919312df1701dc03e

-- create database test_src;
-- create database test_dst;

\c test_src

create table tbl(id int primary key, v text);

create publication pub
for table tbl;

select * from pg_create_logical_replication_slot('sub', 'pgoutput');

\c test_dst

create table tbl(id int primary key, v text);

create function show_row() returns trigger language plpgsql as
$$
begin
raise notice 'role: %, level: %, name: %, new: %, now: %',
current_setting('session_replication_role'), tg_level, tg_name, new,
now();
return null;
end
$$;

create trigger show_row
after insert on tbl
for each row
execute procedure show_row();

alter table tbl
enable always trigger show_row;

----

create subscription sub
connection 'dbname=test_src host=postgres-test01 port=5420'
publication pub
with (create_slot = false);

----
\c test_src

test_src=# insert into tbl values (1, 'one'), (2, 'two');
INSERT 0 2
test_src=# insert into tbl values (3, 'three');
INSERT 0 1
test_src=# insert into tbl values (4, 'four');
INSERT 0 1

--------------
in log on dst db we can see only 1 value now()
--------------

2017-06-16 22:40:18.398 MSK [14849] LOG: logical replication table
synchronization worker for subscription "sub", table "tbl" has started
2017-06-16 22:40:19.398 MSK [14849] LOG: logical replication table
synchronization worker for subscription "sub", table "tbl" has finished
2017-06-16 22:40:49.346 MSK [14848] NOTICE: role: replica, level: ROW,
name: show_row, new: (1,one), now: 2017-06-16 22:40:18.391917+03
2017-06-16 22:40:49.346 MSK [14848] CONTEXT: PL/pgSQL function show_row()
line 3 at RAISE
2017-06-16 22:40:49.346 MSK [14848] NOTICE: role: replica, level: ROW,
name: show_row, new: (2,two), now: 2017-06-16 22:40:18.391917+03
2017-06-16 22:40:49.346 MSK [14848] CONTEXT: PL/pgSQL function show_row()
line 3 at RAISE
2017-06-16 22:40:57.425 MSK [14848] NOTICE: role: replica, level: ROW,
name: show_row, new: (3,three), now: 2017-06-16 22:40:18.391917+03
2017-06-16 22:40:57.425 MSK [14848] CONTEXT: PL/pgSQL function show_row()
line 3 at RAISE
2017-06-16 22:41:01.191 MSK [14848] NOTICE: role: replica, level: ROW,
name: show_row, new: (4,four), now: 2017-06-16 22:40:18.391917+03
2017-06-16 22:41:01.191 MSK [14848] CONTEXT: PL/pgSQL function show_row()
line 3 at RAISE
----

\c test_dst
test_dst=# select * from pg_stat_activity where application_name ilike
'logical replication worker for subscription%';

-[ RECORD 1 ]----+--------------------------------------------------
datid | 16529
datname | test_dst
pid | 14848
usesysid | 10
usename | kevteev
application_name | logical replication worker for subscription 16545
client_addr |
client_hostname |
client_port |
backend_start | 2017-06-16 22:40:18.392998+03
xact_start |
query_start |
state_change | 2017-06-16 22:41:01.192147+03
wait_event_type | Activity
wait_event | LogicalApplyMain
state | idle
backend_xid |
backend_xmin |
query |
backend_type | background worker

so the value now() = backend_start (logical replication worker for
subscription 16545)

--
Konstantin Evteev.