Skip to content

Commit 29306ca

Browse files
authored
fix(mysql): handle transaction payload event (#4433)
- DBI-809 - handle transaction payload event (MySQL can send it if binlog_transaction_compression=ON) - handle missing GTID events (MariadbGTIDEvent, GtidTaggedLogEvent)
1 parent f43a670 commit 29306ca

5 files changed

Lines changed: 202 additions & 64 deletions

File tree

flow/connectors/mysql/cdc.go

Lines changed: 84 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -482,72 +482,25 @@ func (c *MySqlConnector) PullRecords(
482482
return nil
483483
}
484484

485-
lastEventAt := time.Now()
486-
var mysqlParser *parser.Parser
487-
for inTx || (!overtime && recordCount < req.MaxBatchSize) {
488-
var event *replication.BinlogEvent
489-
// don't gamble on closed timeoutCtx.Done() being prioritized over event backlog channel
490-
err := timeoutCtx.Err()
491-
if err == nil {
492-
event, err = mystream.GetEvent(timeoutCtx)
493-
}
494-
if err != nil {
495-
if ctxErr := ctx.Err(); ctxErr != nil {
496-
c.logger.Info("[mysql] PullRecords context canceled, stopping streaming", slog.Any("error", err))
497-
return ctxErr
498-
}
499-
500-
if errors.Is(err, context.DeadlineExceeded) {
501-
if recordCount == 0 || inTx {
502-
if since := time.Since(lastEventAt); since > c.binlogStalenessThreshold() {
503-
return exceptions.NewMySQLStaleConnectionError(since, c.binlogHeartbeatPeriod)
504-
}
505-
506-
if recordCount == 0 {
507-
// progress offset while no records read to avoid falling behind when all tables inactive
508-
if updatedOffset != "" {
509-
c.logger.Info("[mysql] updating inactive offset", slog.Any("offset", updatedOffset))
510-
if err := c.SetLastOffset(ctx, req.FlowJobName, model.CdcCheckpoint{Text: updatedOffset}); err != nil {
511-
c.logger.Error("[mysql] failed to update offset, ignoring", slog.Any("error", err))
512-
} else {
513-
updatedOffset = ""
514-
}
515-
}
516-
resetTimeout(c.binlogStalenessThreshold())
517-
} else {
518-
c.logger.Info("[mysql] timeout reached, but still in transaction, waiting for inTx false",
519-
slog.Uint64("records", uint64(recordCount)),
520-
slog.Int64("bytes", totalFetchedBytes.Load()),
521-
slog.Int("channelLen", req.RecordStream.ChannelLen()),
522-
slog.Float64("elapsedMinutes", time.Since(pullStart).Minutes()))
523-
resetTimeout(time.Minute)
524-
overtime = true
525-
}
526-
527-
continue
528-
}
529-
530-
return nil
531-
}
532-
533-
c.logger.Error("[mysql] PullRecords failed to get event", slog.Any("error", err))
534-
return exceptions.NewMySQLExecuteError(err)
485+
recordCommitLagMetric := func(ctx context.Context, commitTs uint64) {
486+
if commitTs > 0 {
487+
otelManager.Metrics.CommitLagGauge.Record(ctx,
488+
time.Now().UTC().Sub(time.UnixMicro(int64(commitTs))).Microseconds())
535489
}
490+
}
536491

537-
lastEventAt = time.Now()
538-
539-
allFetchedBytes.Add(int64(len(event.RawData)))
540-
492+
lastEventAt := time.Now()
493+
var mysqlParser *parser.Parser
494+
processEvent := func(event *replication.BinlogEvent) error {
541495
switch ev := event.Event.(type) {
542496
case *replication.GTIDEvent:
543-
if ev.ImmediateCommitTimestamp > 0 {
544-
otelManager.Metrics.CommitLagGauge.Record(ctx,
545-
time.Now().UTC().Sub(time.UnixMicro(int64(ev.ImmediateCommitTimestamp))).Microseconds())
546-
}
497+
recordCommitLagMetric(ctx, ev.ImmediateCommitTimestamp)
498+
case *replication.GtidTaggedLogEvent: // MySQL 8.4+ tagged GTIDs
499+
recordCommitLagMetric(ctx, ev.ImmediateCommitTimestamp)
547500
case *replication.XIDEvent:
548501
if gset != nil {
549502
gset = ev.GSet
550-
updatedOffset = gset.String()
503+
updatedOffset = gset.String() // accumulated from GTID events above
551504
req.RecordStream.UpdateLatestCheckpointText(updatedOffset)
552505
} else if event.Header.LogPos > pos.Pos {
553506
pos.Pos = event.Header.LogPos
@@ -825,6 +778,78 @@ func (c *MySqlConnector) PullRecords(
825778
)
826779
}
827780
}
781+
782+
return nil
783+
}
784+
785+
for inTx || (!overtime && recordCount < req.MaxBatchSize) {
786+
var event *replication.BinlogEvent
787+
// don't gamble on closed timeoutCtx.Done() being prioritized over event backlog channel
788+
err := timeoutCtx.Err()
789+
if err == nil {
790+
event, err = mystream.GetEvent(timeoutCtx)
791+
}
792+
if err != nil {
793+
if ctxErr := ctx.Err(); ctxErr != nil {
794+
c.logger.Info("[mysql] PullRecords context canceled, stopping streaming", slog.Any("error", err))
795+
return ctxErr
796+
}
797+
798+
if errors.Is(err, context.DeadlineExceeded) {
799+
if recordCount == 0 || inTx {
800+
if since := time.Since(lastEventAt); since > c.binlogStalenessThreshold() {
801+
return exceptions.NewMySQLStaleConnectionError(since, c.binlogHeartbeatPeriod)
802+
}
803+
804+
if recordCount == 0 {
805+
// progress offset while no records read to avoid falling behind when all tables inactive
806+
if updatedOffset != "" {
807+
c.logger.Info("[mysql] updating inactive offset", slog.Any("offset", updatedOffset))
808+
if err := c.SetLastOffset(ctx, req.FlowJobName, model.CdcCheckpoint{Text: updatedOffset}); err != nil {
809+
c.logger.Error("[mysql] failed to update offset, ignoring", slog.Any("error", err))
810+
} else {
811+
updatedOffset = ""
812+
}
813+
}
814+
resetTimeout(c.binlogStalenessThreshold())
815+
} else {
816+
c.logger.Info("[mysql] timeout reached, but still in transaction, waiting for inTx false",
817+
slog.Uint64("records", uint64(recordCount)),
818+
slog.Int64("bytes", totalFetchedBytes.Load()),
819+
slog.Int("channelLen", req.RecordStream.ChannelLen()),
820+
slog.Float64("elapsedMinutes", time.Since(pullStart).Minutes()))
821+
resetTimeout(time.Minute)
822+
overtime = true
823+
}
824+
825+
continue
826+
}
827+
828+
return nil
829+
}
830+
831+
c.logger.Error("[mysql] PullRecords failed to get event", slog.Any("error", err))
832+
return exceptions.NewMySQLExecuteError(err)
833+
}
834+
835+
lastEventAt = time.Now()
836+
837+
allFetchedBytes.Add(int64(len(event.RawData)))
838+
839+
switch ev := event.Event.(type) {
840+
case *replication.TransactionPayloadEvent:
841+
for _, inner := range ev.Events {
842+
err = processEvent(inner)
843+
if err != nil {
844+
return err
845+
}
846+
}
847+
default:
848+
err = processEvent(event)
849+
if err != nil {
850+
return err
851+
}
852+
}
828853
}
829854
return nil
830855
}

flow/e2e/clickhouse_mysql_test.go

Lines changed: 112 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ import (
1010
"testing"
1111
"time"
1212

13+
"github.com/go-mysql-org/go-mysql/mysql"
1314
"github.com/google/uuid"
1415
"github.com/stretchr/testify/require"
1516
"github.com/testcontainers/testcontainers-go"
@@ -235,6 +236,117 @@ func (s ClickHouseSuite) Test_MySQL_Blobs() {
235236
RequireEnvCanceled(s.t, env)
236237
}
237238

239+
func (s ClickHouseSuite) Test_MySQL_TransactionPayloadCompression() {
240+
mySource, ok := s.source.(*MySqlSource)
241+
if !ok {
242+
s.t.Skip("only applies to mysql")
243+
}
244+
if mySource.Config.Flavor == protos.MySqlFlavor_MYSQL_MARIA {
245+
s.t.Skip("binlog_transaction_compression is not supported by MariaDB")
246+
}
247+
cmp, err := mySource.CompareServerVersion(s.t.Context(), mysql_validation.MySQLMinVersionForBinlogTransactionCompression)
248+
require.NoError(s.t, err)
249+
if cmp < 0 {
250+
s.t.Skip("only applies to mysql versions with binlog_transaction_compression")
251+
}
252+
253+
srcTableName := "test_txn_payload"
254+
srcFullName := s.attachSchemaSuffix(srcTableName)
255+
dstTableName := "test_txn_payload_dst"
256+
257+
require.NoError(s.t, s.source.Exec(s.t.Context(), fmt.Sprintf(`
258+
CREATE TABLE IF NOT EXISTS %s (
259+
id BIGINT PRIMARY KEY,
260+
val TEXT NOT NULL
261+
)
262+
`, srcFullName)))
263+
264+
connectionGen := FlowConnectionGenerationConfig{
265+
FlowJobName: s.attachSuffix(srcTableName),
266+
TableNameMapping: map[string]string{srcFullName: dstTableName},
267+
Destination: s.Peer().Name,
268+
}
269+
flowConnConfig := connectionGen.GenerateFlowConnectionConfigs(s)
270+
271+
tc := NewTemporalClient(s.t)
272+
env := ExecutePeerflow(s.t, tc, flowConnConfig)
273+
SetupCDCFlowStatusQuery(s.t, env, flowConnConfig)
274+
275+
// Compress this session's transactions so the upcoming DML lands in the binlog as a single
276+
// TRANSACTION_PAYLOAD_EVENT, exercising the compressed-payload decode path in CDC.
277+
require.NoError(s.t, s.source.Exec(s.t.Context(), "SET SESSION binlog_transaction_compression = ON"))
278+
279+
// Capture the binlog position, then write a large, highly compressible transaction as a single
280+
// multi-row INSERT so MySQL compresses it (compressed < uncompressed) into one payload event.
281+
posBefore, err := mySource.GetMasterPos(s.t.Context())
282+
require.NoError(s.t, err)
283+
284+
const rowCount = 200
285+
rowVal := strings.Repeat("peerdb-compressible-", 100) // ~2KB highly repetitive per row
286+
var insert strings.Builder
287+
fmt.Fprintf(&insert, "INSERT INTO %s (id, val) VALUES ", srcFullName)
288+
for i := 1; i <= rowCount; i++ {
289+
if i > 1 {
290+
insert.WriteByte(',')
291+
}
292+
fmt.Fprintf(&insert, "(%d, '%s')", i, rowVal)
293+
}
294+
require.NoError(s.t, s.source.Exec(s.t.Context(), insert.String()))
295+
296+
findPayloadEndPos := func(ctx context.Context, from mysql.Position) (bool, uint32, error) {
297+
rs, err := mySource.Execute(ctx, fmt.Sprintf("SHOW BINLOG EVENTS IN '%s' FROM %d", from.Name, from.Pos))
298+
if err != nil {
299+
return false, 0, err
300+
}
301+
for i := range rs.Values {
302+
// SHOW BINLOG EVENTS columns: Log_name, Pos, Event_type, Server_id, End_log_pos, Info
303+
eventType, _ := rs.GetString(i, 2)
304+
if strings.Contains(strings.ToLower(eventType), "payload") {
305+
pos, _ := rs.GetInt(i, 4)
306+
return true, uint32(pos), nil
307+
}
308+
}
309+
return false, 0, nil
310+
}
311+
hasPayload, payloadEndPos, err := findPayloadEndPos(s.t.Context(), posBefore)
312+
require.NoError(s.t, err)
313+
require.True(s.t, hasPayload, "expected a TRANSACTION_PAYLOAD_EVENT in the binlog")
314+
315+
// for GTID "SHOW BINLOG EVENTS" returns really complex format and it's different
316+
// across versions/flavors.
317+
// Therefore, we just get the latest GTID from a server instead of reading it from a binglog.
318+
gtidAfter, err := mySource.GetMasterGTIDSet(s.t.Context())
319+
require.NoError(s.t, err)
320+
321+
EnvWaitForEqualTablesWithNames(env, s, "waiting on cdc", srcTableName, dstTableName, "id,val")
322+
323+
// Assert the payload transaction was checkpointed
324+
pool, err := catalogTestAccessPool()
325+
require.NoError(s.t, err)
326+
var lastText string
327+
require.NoError(s.t, pool.QueryRow(s.t.Context(),
328+
"SELECT last_text FROM metadata_last_sync_state WHERE job_name = $1",
329+
flowConnConfig.FlowJobName,
330+
).Scan(&lastText))
331+
332+
if rest, isFilePos := strings.CutPrefix(lastText, "!f:"); isFilePos {
333+
comma := strings.LastIndexByte(rest, ',')
334+
require.NotEqual(s.t, -1, comma, "malformed file/pos offset %q", lastText)
335+
storedPos, parseErr := strconv.ParseUint(rest[comma+1:], 16, 32)
336+
require.NoError(s.t, parseErr)
337+
require.GreaterOrEqual(s.t, uint32(storedPos), payloadEndPos,
338+
"checkpoint did not advance past the TRANSACTION_PAYLOAD_EVENT")
339+
} else {
340+
storedSet, parseErr := mysql.ParseGTIDSet(mySource.Flavor(), lastText)
341+
require.NoError(s.t, parseErr)
342+
require.True(s.t, storedSet.Contain(gtidAfter),
343+
"checkpoint GTID set %s does not cover the committed payload transaction %s", storedSet, gtidAfter)
344+
}
345+
346+
env.Cancel(s.t.Context())
347+
RequireEnvCanceled(s.t, env)
348+
}
349+
238350
// Test_MySQL_Binary_Trailing_Zeros reproduces trailing-0x00 truncation of fixed-length
239351
// BINARY(N) columns over CDC.
240352
//

flow/go.mod

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ require (
3535
github.com/cockroachdb/pebble/v2 v2.1.5
3636
github.com/elastic/go-elasticsearch/v8 v8.19.6
3737
github.com/go-logr/logr v1.4.3
38-
github.com/go-mysql-org/go-mysql v1.15.1-0.20260615132323-06b4fb6b476d
38+
github.com/go-mysql-org/go-mysql v1.15.1-0.20260622021642-60bfbfea8dd0
3939
github.com/gogo/googleapis v1.4.1
4040
github.com/google/uuid v1.6.0
4141
github.com/grpc-ecosystem/go-grpc-middleware/v2 v2.3.3

flow/go.sum

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -315,8 +315,8 @@ github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI=
315315
github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY=
316316
github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
317317
github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
318-
github.com/go-mysql-org/go-mysql v1.15.1-0.20260615132323-06b4fb6b476d h1:Kl+pOPwscRCgRjhN76nQkJEiXk49q10BxwHCdSrzyOE=
319-
github.com/go-mysql-org/go-mysql v1.15.1-0.20260615132323-06b4fb6b476d/go.mod h1:VjBTZTTDKL8OMXUAhNbg3VHaVVq9HOXJEBLpAKBFIfE=
318+
github.com/go-mysql-org/go-mysql v1.15.1-0.20260622021642-60bfbfea8dd0 h1:WaAkvbSCNg814bfKOUPvWP70ZXzeDLolfoMjf9BB0lE=
319+
github.com/go-mysql-org/go-mysql v1.15.1-0.20260622021642-60bfbfea8dd0/go.mod h1:VjBTZTTDKL8OMXUAhNbg3VHaVVq9HOXJEBLpAKBFIfE=
320320
github.com/go-ole/go-ole v1.2.6/go.mod h1:pprOEPIfldk/42T2oK7lQ4v4JSDwmV0As9GaiUsvbm0=
321321
github.com/go-ole/go-ole v1.3.0 h1:Dt6ye7+vXGIKZ7Xtk4s6/xVdGDQynvom7xCFEdWr6uE=
322322
github.com/go-ole/go-ole v1.3.0/go.mod h1:5LS6F96DhAwUc7C+1HLexzMXY1xGRSryjyPPKW6zv78=

flow/pkg/mysql/validation.go

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,9 @@ import (
1313
)
1414

1515
const (
16-
MySQLMinVersionForBinlogRowMetadata = "8.0.1"
17-
MariaDBMinVersionForBinlogRowMetadata = "10.5.0"
16+
MySQLMinVersionForBinlogRowMetadata = "8.0.1"
17+
MariaDBMinVersionForBinlogRowMetadata = "10.5.0"
18+
MySQLMinVersionForBinlogTransactionCompression = "8.0.20"
1819
)
1920

2021
func CompareServerVersion(conn *client.Conn, version string) (int, error) {

0 commit comments

Comments
 (0)