Bug #89148 The timestamp of the GITD events in the GR relay log look wrong.

Description:
Hi,

It looks to me that there is something wrong with the timestamps of the GTID event of Group Replication.  I would expect the timestamps to be corresponding to when the event was committed (or certified) but I am getting timestamps which looks like when Group Replication was started.

Here is an extract of the relay logs of Group Replication:

# mysqlbinlog my_relaylog-group_replication_applier.N | grep -e last_  |
    sed -e 's/server id.*last/[...] last/' -e 's/.rbr_only.*/ [...]/'
#180106 19:31:36 [...] last_committed=0 sequence_number=0 [...]
#180106 19:31:36 [...] last_committed=1 sequence_number=2 [...] -- CREATE DB
#180106 19:31:36 [...] last_committed=2 sequence_number=3 [...] -- CREATE TB
#180106 19:31:36 [...] last_committed=3 sequence_number=4 [...] -- INSERT a
#180106 19:31:36 [...] last_committed=3 sequence_number=5 [...] -- INSERT b
#180106 19:31:36 [...] last_committed=3 sequence_number=6 [...] -- INSERT c

And the corresponding binary logs:

# mysqlbinlog my_binlog.M | grep -e last_ |
    sed -e 's/server id.*last/[...] last/' -e 's/.rbr_only.*/ [...]/'
#180106 19:31:59 [...] last_committed=0 sequence_number=1 [...] -- CREATE DB
#180106 19:32:02 [...] last_committed=1 sequence_number=2 [...] -- CREATE TB
#180106 19:32:05 [...] last_committed=2 sequence_number=3 [...] -- INSERT a
#180106 19:32:08 [...] last_committed=3 sequence_number=4 [...] -- INSERT b
#180106 19:32:11 [...] last_committed=4 sequence_number=5 [...] -- INSERT c

Note: those extracts are from the following blog post:
https://jfg-mysql.blogspot.com/2018/01/write-set-in-mysql-5-7-group-replication.html

All the timestamps of the relay log events are 19:31:36 (I guess this match when Group Replication was started) and the binary log timestamps look like a match for the moment the transactions were run.

We can see the same in the relay log extract of Bug#89147 (notice both GTID events having 19:40:07 and the next event having 19:42:13 and 19:42:20 respectively):

# at 13288
#180106 19:40:07 [...] end_log_pos 61 GTID last_committed=55 sequence_number=57 [...]
SET @@SESSION.GTID_NEXT= 'UUID:171'/*!*/;
# at 13349
#180106 19:42:13 server id 198208002  end_log_pos 69  Query thread_id=2488 exec_time=0  error_code=0
[...]
# at 14722
#180106 19:40:07 [...] end_log_pos 61 GTID last_committed=61 sequence_number=63 [...]
SET @@SESSION.GTID_NEXT= 'UUID:177'/*!*/;
# at 14783
#180106 19:42:20 [...] end_log_pos 69 Query thread_id=2517 exec_time=0 error_code=0
[...]

Many thanks for looking into that,

JFG

How to repeat:
See description.

Hello Jean,

Thank you for the report and feature request!

Thanks,
Umesh

certification_handler.cc handle_transaction_id
 
    /*
      Remote transaction.
    */
    if (seq_number > 0)
    {
      if (!tcle->is_gtid_specified())
      {
        // Create new GTID event.
        Gtid gtid= { group_sidno, seq_number };
        Gtid_specification gtid_specification= { GTID_GROUP, gtid };
        Gtid_log_event *gle_generated= new Gtid_log_event(gle->server_id,
                                                gle->is_using_trans_cache(),
                                                gle->last_committed,
                                                gle->sequence_number,
                                                gle->may_have_sbr_stmts,
                                                gtid_specification);

        /*slave create a new gle, and this event will use slave's applier thread 
          time, but this time will never changed after mgr started. So change it to 
          use  master's gle time*/
        gle_generated->header()->when= gle->header()->when;

        pevent->reset_pipeline_event();
        pevent->set_LogEvent(gle_generated);

see fix above. I think this way can fix this bug.