diff --git a/cdc/api/middleware/middleware.go b/cdc/api/middleware/middleware.go index ce3ee800af..b50b37d4c2 100644 --- a/cdc/api/middleware/middleware.go +++ b/cdc/api/middleware/middleware.go @@ -24,6 +24,7 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/pkg/config" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/upstream" "go.uber.org/zap" ) @@ -52,7 +53,7 @@ func LogMiddleware() gin.HandlerFunc { zap.Int("status", c.Writer.Status()), zap.String("method", c.Request.Method), zap.String("path", path), - zap.String("query", query), + logutil.ZapRedactString("query", query), zap.String("ip", c.ClientIP()), zap.String("user-agent", c.Request.UserAgent()), zap.String("client-version", version), zap.String("username", user), diff --git a/cdc/entry/mounter.go b/cdc/entry/mounter.go index 07fd0baacb..7c4342f0b0 100644 --- a/cdc/entry/mounter.go +++ b/cdc/entry/mounter.go @@ -38,6 +38,7 @@ import ( cerror "github.com/pingcap/tiflow/pkg/errors" pfilter "github.com/pingcap/tiflow/pkg/filter" "github.com/pingcap/tiflow/pkg/integrity" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/prometheus/client_golang/prometheus" "go.uber.org/zap" ) @@ -134,7 +135,9 @@ func (m *mounter) DecodeEvent(ctx context.Context, event *model.PolymorphicEvent func (m *mounter) unmarshalAndMountRowChanged(ctx context.Context, raw *model.RawKVEntry) (*model.RowChangedEvent, error) { if !bytes.HasPrefix(raw.Key, tablePrefix) { - log.Error("unexpected key prefix found in row kv entry", zap.String("key", hex.EncodeToString(raw.Key)), zap.Any("eventCommitTs", raw.CRTs), zap.Any("eventStartTs", raw.StartTs)) + log.Error("unexpected key prefix found in row kv entry", + logutil.ZapRedactString("key", hex.EncodeToString(raw.Key)), + zap.Any("eventCommitTs", raw.CRTs), zap.Any("eventStartTs", raw.StartTs)) return nil, nil } // checksumKey is only used to calculate raw checksum if necessary. @@ -147,7 +150,7 @@ func (m *mounter) unmarshalAndMountRowChanged(ctx context.Context, raw *model.Ra log.Warn("empty value and old value", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Any("row", raw)) + logutil.ZapRedactAny("row", raw)) } baseInfo := baseKVEntry{ StartTs: raw.StartTs, @@ -178,7 +181,7 @@ func (m *mounter) unmarshalAndMountRowChanged(ctx context.Context, raw *model.Ra } log.Error("can not found table schema", zap.Uint64("ts", raw.CRTs), - zap.String("key", hex.EncodeToString(raw.Key)), + logutil.ZapRedactString("key", hex.EncodeToString(raw.Key)), zap.Int64("tableID", physicalTableID)) return nil, cerror.ErrSnapshotTableNotFound.GenWithStackByArgs(physicalTableID) } @@ -428,7 +431,7 @@ func (m *mounter) verifyColumnChecksum( if err != nil { log.Error("failed to calculate the checksum", zap.Uint32("first", first), zap.Any("columnInfos", columnInfos), - zap.Any("rawColumns", rawColumns), zap.Error(err)) + logutil.ZapRedactAny("rawColumns", rawColumns), zap.Error(err)) return 0, false, err } @@ -445,7 +448,7 @@ func (m *mounter) verifyColumnChecksum( if !skipFail { log.Error("cannot found the extra checksum, the first checksum mismatched", zap.Uint32("checksum", checksum), zap.Uint32("first", first), zap.Uint32("extra", extra), - zap.Any("columnInfos", columnInfos), zap.Any("rawColumns", rawColumns), zap.Any("tz", m.tz)) + zap.Any("columnInfos", columnInfos), logutil.ZapRedactAny("rawColumns", rawColumns), zap.Any("tz", m.tz)) return checksum, false, nil } @@ -453,7 +456,7 @@ func (m *mounter) verifyColumnChecksum( log.Warn("checksum mismatch on the old value, "+ "this may caused by Add Column / Drop Column executed, skip verification", zap.Uint32("checksum", checksum), zap.Uint32("first", first), zap.Uint32("extra", extra), - zap.Any("columnInfos", columnInfos), zap.Any("rawColumns", rawColumns), zap.Any("tz", m.tz)) + zap.Any("columnInfos", columnInfos), logutil.ZapRedactAny("rawColumns", rawColumns), zap.Any("tz", m.tz)) m.lastSkipOldValueTime = time.Now() } return checksum, true, nil @@ -524,7 +527,7 @@ func newDatum(value interface{}, ft types.FieldType) (types.Datum, error) { return types.NewBytesDatum([]byte(v)), nil } log.Panic("unknown data type when build datum", - zap.Any("type", ft.GetType()), zap.Any("value", value), zap.Reflect("type", reflect.TypeOf(value))) + zap.Any("type", ft.GetType()), logutil.ZapRedactAny("value", value), zap.Reflect("type", reflect.TypeOf(value))) case mysql.TypeFloat: return types.NewFloat32Datum(value.(float32)), nil case mysql.TypeDouble: @@ -559,7 +562,7 @@ func verifyRawBytesChecksum( datum, err := newDatum(col.Value, columnInfo.FieldType) if err != nil { log.Error("build datum for raw checksum calculation failed", - zap.Any("col", col), zap.Any("columnInfo", columnInfo), zap.Error(err)) + logutil.ZapRedactAny("col", col), zap.Any("columnInfo", columnInfo), zap.Error(err)) return 0, false, errors.Trace(err) } datums = append(datums, &datum) @@ -576,8 +579,8 @@ func verifyRawBytesChecksum( log.Error("raw bytes checksum mismatch", zap.Int("version", decoder.ChecksumVersion()), zap.Uint32("expected", expected), zap.Uint32("obtained", obtained), - zap.Any("tableInfo", tableInfo), zap.Any("columns", columns), - zap.Any("handle", handle.String()), zap.Any("tz", tz)) + zap.Any("tableInfo", tableInfo), logutil.ZapRedactAny("columns", columns), + logutil.ZapRedactString("handle", handle.String()), zap.Any("tz", tz)) return expected, false, nil } @@ -611,8 +614,8 @@ func (m *mounter) verifyChecksum( expected, matched, err := verifyRawBytesChecksum(tableInfo, columns, decoder, handle, key, m.tz) if err != nil { log.Error("calculate raw checksum failed", - zap.Int("version", version), zap.Any("tz", m.tz), zap.Any("handle", handle.String()), - zap.Any("key", key), zap.Any("columns", columns), zap.Error(err)) + zap.Int("version", version), zap.Any("tz", m.tz), logutil.ZapRedactString("handle", handle.String()), + logutil.ZapRedactStringer("key", key), logutil.ZapRedactAny("columns", columns), zap.Error(err)) return 0, false, errors.Trace(err) } if !matched { @@ -621,7 +624,7 @@ func (m *mounter) verifyChecksum( columnChecksum, err := calculateColumnChecksum(columnInfos, rawColumns, m.tz) if err != nil { log.Error("failed to calculate column-level checksum, after raw checksum verification passed", - zap.Any("columnsInfo", columnInfos), zap.Any("rawColumns", rawColumns), + zap.Any("columnsInfo", columnInfos), logutil.ZapRedactAny("rawColumns", rawColumns), zap.Any("tz", m.tz), zap.Error(err)) return 0, false, errors.Trace(err) } @@ -674,7 +677,7 @@ func (m *mounter) mountRowKVEntry( if !matched { log.Error("previous columns checksum mismatch", zap.Uint32("checksum", preChecksum), zap.Any("tableInfo", tableInfo), - zap.Any("preCols", preCols), zap.Any("rawCols", preRawCols)) + logutil.ZapRedactAny("preCols", preCols), logutil.ZapRedactAny("rawCols", preRawCols)) if m.integrity.ErrorHandle() { return nil, rawRow, cerror.ErrCorruptedDataMutation. GenWithStackByArgs(m.changefeedID.Namespace, m.changefeedID.ID) @@ -701,7 +704,7 @@ func (m *mounter) mountRowKVEntry( if !matched { log.Error("current columns checksum mismatch", zap.Uint32("checksum", currentChecksum), zap.Any("tableInfo", tableInfo), - zap.Any("cols", cols), zap.Any("rawCols", rawCols)) + logutil.ZapRedactAny("cols", cols), logutil.ZapRedactAny("rawCols", rawCols)) if m.integrity.ErrorHandle() { return nil, rawRow, cerror.ErrCorruptedDataMutation. GenWithStackByArgs(m.changefeedID.Namespace, m.changefeedID.ID) diff --git a/cdc/kv/matcher.go b/cdc/kv/matcher.go index bf61039269..7d8189811b 100644 --- a/cdc/kv/matcher.go +++ b/cdc/kv/matcher.go @@ -16,6 +16,7 @@ package kv import ( "github.com/pingcap/kvproto/pkg/cdcpb" "github.com/pingcap/log" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" ) @@ -106,7 +107,7 @@ func (m *matcher) matchCachedRow(initialized bool) []*cdcpb.Event_Row { // prewrite log before initialized, a committed log with // the same key and start-ts must have been received. log.Info("ignore commit event without prewrite", - zap.Binary("key", cacheEntry.GetKey()), + logutil.ZapRedactAny("key", cacheEntry.GetKey()), zap.Uint64("startTs", cacheEntry.GetStartTs())) continue } diff --git a/cdc/kv/matcher_redaction_test.go b/cdc/kv/matcher_redaction_test.go new file mode 100644 index 0000000000..609d355c03 --- /dev/null +++ b/cdc/kv/matcher_redaction_test.go @@ -0,0 +1,66 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package kv + +import ( + "bytes" + "encoding/base64" + "encoding/json" + "fmt" + "testing" + + "github.com/pingcap/errors" + "github.com/pingcap/kvproto/pkg/cdcpb" + "github.com/pingcap/log" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func TestMatchCachedRowLogRedaction(t *testing.T) { + key := []byte("unmatched-primary-key-secret") + encodedKey := base64.StdEncoding.EncodeToString(key) + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + var output bytes.Buffer + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + + matcher := newMatcher() + matcher.cacheCommitRow(&cdcpb.Event_Row{StartTs: 1, CommitTs: 2, Key: key}) + require.Empty(t, matcher.matchCachedRow(true)) + require.Empty(t, matcher.cachedCommit) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "ignore commit event without prewrite", entry["msg"]) + require.Equal(t, float64(1), entry["startTs"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, encodedKey, entry["key"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["key"]) + require.NotContains(t, output.String(), string(key)) + require.NotContains(t, output.String(), encodedKey) + require.NotContains(t, output.String(), fmt.Sprint(key)) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(key)), entry["key"]) + } + }) + } +} diff --git a/cdc/kv/regionlock/region_range_lock.go b/cdc/kv/regionlock/region_range_lock.go index 51ed495d2c..714e2a48fe 100644 --- a/cdc/kv/regionlock/region_range_lock.go +++ b/cdc/kv/regionlock/region_range_lock.go @@ -26,6 +26,8 @@ import ( "github.com/google/btree" "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/spanz" "go.uber.org/zap" ) @@ -94,8 +96,8 @@ func rangeLockEntryLess(a, b *rangeLockEntry) bool { func (e *rangeLockEntry) String() string { return fmt.Sprintf("region %v [%v, %v), version %v, %d waiters", e.regionID, - hex.EncodeToString(e.startKey), - hex.EncodeToString(e.endKey), + redact.String(hex.EncodeToString(e.startKey)), + redact.String(hex.EncodeToString(e.endKey)), e.regionVersion, len(e.waiterSignalChs)) } @@ -183,8 +185,8 @@ func (l *RangeLock) UnlockRange( log.Panic("unlocking a not locked range", zap.String("changefeed", l.changefeed), zap.Uint64("regionID", regionID), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey)), + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey)), zap.Uint64("version", version)) } if entry.regionID != regionID { @@ -192,8 +194,8 @@ func (l *RangeLock) UnlockRange( zap.String("changefeed", l.changefeed), zap.Uint64("expectedRegionID", regionID), zap.Uint64("foundRegionID", entry.regionID), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey))) + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey))) } if entry != l.regionIDToLockedRanges[regionID] { log.Panic("range lock and region id lock mismatch when trying to unlock", @@ -209,8 +211,8 @@ func (l *RangeLock) UnlockRange( log.Panic("unlocking region doesn't match the locked region", zap.String("changefeed", l.changefeed), zap.Uint64("regionID", regionID), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey)), + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey)), zap.Uint64("version", version), zap.String("foundLockEntry", entry.String())) } @@ -235,8 +237,8 @@ func (l *RangeLock) UnlockRange( zap.String("changefeed", l.changefeed), zap.Uint64("lockID", l.id), zap.Uint64("regionID", entry.regionID), zap.Uint64("resolvedTs", newResolvedTs), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey))) + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey))) return } @@ -437,8 +439,8 @@ func (l *RangeLock) tryLockRange(startKey, endKey []byte, regionID, regionVersio zap.Uint64("regionID", regionID), zap.Uint64("version", regionVersion), zap.Uint64("resolvedTs", resolvedTs), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey))) + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey))) return LockRangeResult{ Status: LockRangeStatusSuccess, @@ -450,7 +452,8 @@ func (l *RangeLock) tryLockRange(startKey, endKey []byte, regionID, regionVersio var overlapStr []string for _, r := range overlappedRangeLocks { overlapStr = append(overlapStr, fmt.Sprintf("regionID: %v, ver: %v, start: %v, end: %v", - r.regionID, r.regionVersion, hex.EncodeToString(r.startKey), hex.EncodeToString(r.endKey))) // DEBUG + r.regionID, r.regionVersion, + redact.String(hex.EncodeToString(r.startKey)), redact.String(hex.EncodeToString(r.endKey)))) // DEBUG } // Check if the current acuqiring range is stale, @@ -471,8 +474,8 @@ func (l *RangeLock) tryLockRange(startKey, endKey []byte, regionID, regionVersio log.Info("try lock range staled", zap.String("changefeed", l.changefeed), zap.Uint64("lockID", l.id), zap.Uint64("regionID", regionID), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey)), + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey)), zap.Strings("allOverlapping", overlapStr)) // DEBUG for _, r := range overlappedRangeLocks { @@ -512,8 +515,8 @@ func (l *RangeLock) tryLockRange(startKey, endKey []byte, regionID, regionVersio log.Info("lock range blocked", zap.String("changefeed", l.changefeed), zap.Uint64("lockID", l.id), zap.Uint64("regionID", regionID), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey)), + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey)), zap.Strings("blockedBy", overlapStr)) // DEBUG return LockRangeResult{ diff --git a/cdc/kv/shared_client.go b/cdc/kv/shared_client.go index 8c775b6383..2ec3182428 100644 --- a/cdc/kv/shared_client.go +++ b/cdc/kv/shared_client.go @@ -33,6 +33,7 @@ import ( "github.com/pingcap/tiflow/pkg/chann" "github.com/pingcap/tiflow/pkg/config" cerror "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/pingcap/tiflow/pkg/txnutil" @@ -305,7 +306,7 @@ func (s *SharedClient) Subscribe(subID SubscriptionID, span tablepb.Span, startT zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", rt.subscriptionID), - zap.String("span", rt.span.String())) + logutil.ZapRedactString("span", rt.span.String())) } // Unsubscribe the given table span. All covered regions will be deregistered asynchronously. @@ -321,7 +322,7 @@ func (s *SharedClient) Unsubscribe(subID SubscriptionID) { zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", rt.subscriptionID), - zap.String("span", rt.span.String())) + logutil.ZapRedactString("span", rt.span.String())) return } log.Warn("event feed unsubscribes table, but not found", @@ -458,7 +459,7 @@ func (s *SharedClient) handleRegions(ctx context.Context, eg *errgroup.Group) er zap.Uint64("streamID", stream.streamID), zap.Any("subscriptionID", region.subscribedTable.subscriptionID), zap.Uint64("regionID", region.verID.GetID()), - zap.String("span", region.span.String()), + logutil.ZapRedactString("span", region.span.String()), zap.String("addr", store.storeAddr)) } } @@ -561,7 +562,7 @@ func (s *SharedClient) divideSpanAndScheduleRegionRequests( zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", subscribedTable.subscriptionID), - zap.Any("span", nextSpan)) + logutil.ZapRedactAny("span", nextSpan)) backoff := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) regions, err := s.regionCache.BatchLoadRegionsWithKeyRange(backoff, nextSpan.StartKey, nextSpan.EndKey, limit) @@ -570,7 +571,7 @@ func (s *SharedClient) divideSpanAndScheduleRegionRequests( zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", subscribedTable.subscriptionID), - zap.String("span", nextSpan.String()), + logutil.ZapRedactString("span", nextSpan.String()), zap.Error(err)) backoffBeforeLoad = true continue @@ -588,7 +589,7 @@ func (s *SharedClient) divideSpanAndScheduleRegionRequests( zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", subscribedTable.subscriptionID), - zap.String("span", nextSpan.String())) + logutil.ZapRedactString("span", nextSpan.String())) backoffBeforeLoad = true continue } @@ -607,7 +608,7 @@ func (s *SharedClient) divideSpanAndScheduleRegionRequests( zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", subscribedTable.subscriptionID), - zap.String("span", nextSpan.String())) + logutil.ZapRedactString("span", nextSpan.String())) } verID := tikv.NewRegionVerID(regionMeta.Id, regionMeta.RegionEpoch.ConfVer, regionMeta.RegionEpoch.Version) @@ -877,7 +878,7 @@ func (s *SharedClient) logSlowRegions(ctx context.Context) error { zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", subscriptionID), zap.Int64("tableID", rt.span.TableID), - zap.Any("holes", attr.UnLockedRanges)) + logutil.ZapRedactAny("holes", attr.UnLockedRanges)) } } s.totalSpans.RUnlock() @@ -921,7 +922,7 @@ func (r *subscribedTable) resolveStaleLocks(s *SharedClient, targetTs uint64) { zap.String("namespace", s.changefeed.Namespace), zap.String("changefeed", s.changefeed.ID), zap.Any("subscriptionID", r.subscriptionID), - zap.Any("ranges", res)) + logutil.ZapRedactAny("ranges", res)) } type sharedClientMetrics struct { diff --git a/cdc/kv/shared_region_worker.go b/cdc/kv/shared_region_worker.go index f00b131d3d..76fc475f35 100644 --- a/cdc/kv/shared_region_worker.go +++ b/cdc/kv/shared_region_worker.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" cerror "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/prometheus/client_golang/prometheus" "go.uber.org/zap" @@ -263,7 +264,7 @@ func handleEventEntry( zap.Uint64("regionID", regionID), zap.Int64("tableID", state.region.span.TableID), zap.Uint64("requestID", state.requestID), - zap.Stringer("span", &state.region.span)) + logutil.ZapRedactStringer("span", &state.region.span)) for _, cachedEvent := range state.matcher.matchCachedRow(true) { revent, err := assembleRowEvent(regionID, cachedEvent) diff --git a/cdc/model/sink.go b/cdc/model/sink.go index 491093bd23..8e8f1a6325 100644 --- a/cdc/model/sink.go +++ b/cdc/model/sink.go @@ -29,6 +29,7 @@ import ( "github.com/pingcap/tidb/pkg/util/rowcodec" "github.com/pingcap/tiflow/pkg/errors" "github.com/pingcap/tiflow/pkg/integrity" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/quotes" "github.com/pingcap/tiflow/pkg/sink" "github.com/pingcap/tiflow/pkg/util" @@ -901,7 +902,7 @@ func BuildTiDBTableInfoImpl( if !flag.IsHandleKey() { log.Panic("Primary key must be handle key", zap.String("table", tableName), - zap.Any("columns", columns), + logutil.ZapRedactAny("columns", columns), zap.Any("indexColumns", indexColumns)) } // just set it for test compatibility, @@ -915,7 +916,7 @@ func BuildTiDBTableInfoImpl( if !flag.IsPrimaryKey() && !flag.IsUniqueKey() { log.Panic("Handle key must either be primary key or unique key", zap.String("table", tableName), - zap.Any("columns", columns), + logutil.ZapRedactAny("columns", columns), zap.Any("indexColumns", indexColumns)) } } @@ -987,7 +988,7 @@ func BuildTiDBTableInfoImpl( zap.String("table", tableName), zap.Any("colOffsets", colOffsets), zap.String("indexName", indexInfo.Name.O), - zap.Any("columns", columns), + logutil.ZapRedactAny("columns", columns), zap.Any("indexColumns", indexColumns)) } hasHandleIndex = true @@ -1009,7 +1010,7 @@ func BuildTiDBTableInfoImpl( if hasPrimaryKeyColumn != hasPrimaryKeyIndex { log.Panic("Primary key column and primary key index is not consistent", zap.String("table", tableName), - zap.Any("columns", columns), + logutil.ZapRedactAny("columns", columns), zap.Any("indexColumns", indexColumns), zap.Bool("hasPrimaryKeyColumn", hasPrimaryKeyColumn), zap.Bool("hasPrimaryKeyIndex", hasPrimaryKeyIndex)) @@ -1224,7 +1225,7 @@ func trySplitAndSortUpdateEvent( // begin; insert into t (id) values (1); delete from t where id=1; commit; // Just ignore these row changed events. if colLen == 0 && preColLen == 0 { - log.Warn("skip emit empty row event", zap.Any("event", e)) + log.Warn("skip emit empty row event", logutil.ZapRedactAny("event", e)) continue } @@ -1311,8 +1312,8 @@ func SplitUpdateEvent( zap.Uint64("commitTs", updateEvent.CommitTs), zap.String("schema", updateEvent.TableInfo.TableName.Schema), zap.String("table", updateEvent.TableInfo.GetTableName()), - zap.Any("preCols", updateEvent.PreColumns), - zap.Any("cols", updateEvent.Columns)) + logutil.ZapRedactAny("preCols", updateEvent.PreColumns), + logutil.ZapRedactAny("cols", updateEvent.Columns)) return &deleteEvent, &insertEvent, nil } @@ -1324,7 +1325,7 @@ func (t *SingleTableTxn) Append(row *RowChangedEvent) { zap.Uint64("startTs", t.StartTs), zap.Uint64("commitTs", t.CommitTs), zap.Any("table", t.GetPhysicalTableID()), - zap.Any("row", row)) + logutil.ZapRedactAny("row", row)) } t.Rows = append(t.Rows, row) } diff --git a/cdc/model/sink_redaction_test.go b/cdc/model/sink_redaction_test.go new file mode 100644 index 0000000000..b28afa33f0 --- /dev/null +++ b/cdc/model/sink_redaction_test.go @@ -0,0 +1,139 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package model + +import ( + "bytes" + "encoding/json" + "fmt" + "testing" + + "github.com/pingcap/errors" + "github.com/pingcap/log" + "github.com/pingcap/tidb/pkg/parser/mysql" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func captureModelRedactionLogs(t *testing.T, mode redact.RedactionMode) *bytes.Buffer { + t.Helper() + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + output := &bytes.Buffer{} + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + return output +} + +func TestSplitUpdateEventLogRedaction(t *testing.T) { + const oldSecret, newSecret = "old-row-secret", "new-row-secret" + columns := []*Column{{Name: "value", Type: mysql.TypeVarchar, Value: newSecret}} + tableInfo := BuildTableInfo("db", "tbl", columns, nil) + row := &RowChangedEvent{ + StartTs: 1, CommitTs: 2, TableInfo: tableInfo, + Columns: Columns2ColumnDatas(columns, tableInfo), + PreColumns: Columns2ColumnDatas([]*Column{{Name: "value", Type: mysql.TypeVarchar, Value: oldSecret}}, tableInfo), + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureModelRedactionLogs(t, mode) + + deleted, inserted, err := SplitUpdateEvent(row) + require.NoError(t, err) + require.True(t, deleted.IsDelete()) + require.True(t, inserted.IsInsert()) + require.Equal(t, oldSecret, deleted.PreColumns[0].Value) + require.Equal(t, newSecret, inserted.Columns[0].Value) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "split update event", entry["msg"]) + require.Equal(t, "db", entry["schema"]) + require.Equal(t, "tbl", entry["table"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, oldSecret, entry["preCols"].([]interface{})[0].(map[string]interface{})["value"]) + require.Equal(t, newSecret, entry["cols"].([]interface{})[0].(map[string]interface{})["value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["preCols"]) + require.Equal(t, "?", entry["cols"]) + require.NotContains(t, output.String(), oldSecret) + require.NotContains(t, output.String(), newSecret) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(row.PreColumns)), entry["preCols"]) + require.Equal(t, redact.String(fmt.Sprint(row.Columns)), entry["cols"]) + } + }) + } +} + +func TestSingleTableTxnAppendLogRedaction(t *testing.T) { + const secret = "unexpected-row-secret" + columns := []*Column{{Name: "value", Type: mysql.TypeVarchar, Value: secret}} + tableInfo := BuildTableInfo("db", "tbl", columns, nil) + row := &RowChangedEvent{StartTs: 2, CommitTs: 3, TableInfo: tableInfo, Columns: Columns2ColumnDatas(columns, tableInfo)} + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureModelRedactionLogs(t, mode) + txn := &SingleTableTxn{StartTs: 1, CommitTs: 3, TableInfo: tableInfo} + require.PanicsWithValue(t, "unexpected row change event", func() { txn.Append(row) }) + require.Empty(t, txn.Rows) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + switch mode { + case redact.RedactionModeOff: + loggedRow := entry["row"].(map[string]interface{}) + require.Equal(t, secret, loggedRow["Columns"].([]interface{})[0].(map[string]interface{})["value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["row"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(row)), entry["row"]) + } + }) + } +} + +func TestRedoRowSchemaInvariantLogRedaction(t *testing.T) { + const secret = "redo-primary-key-secret" + // Redo restoration must reject a primary-key column without a handle-key flag. + row := &RowChangedEventInRedoLog{ + Table: &TableName{Schema: "db", Table: "tbl"}, + Columns: []*Column{{ + Name: "value", Type: mysql.TypeVarchar, Flag: PrimaryKeyFlag, Value: secret, + }}, + IndexColumns: [][]int{{0}}, + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureModelRedactionLogs(t, mode) + require.PanicsWithValue(t, "Primary key must be handle key", func() { row.ToRowChangedEvent() }) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "tbl", entry["table"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, secret, entry["columns"].([]interface{})[0].(map[string]interface{})["Value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["columns"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(row.Columns)), entry["columns"]) + } + }) + } +} diff --git a/cdc/processor/memquota/mem_quota.go b/cdc/processor/memquota/mem_quota.go index c30640037a..bf8ec57127 100644 --- a/cdc/processor/memquota/mem_quota.go +++ b/cdc/processor/memquota/mem_quota.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/prometheus/client_golang/prometheus" "go.uber.org/zap" @@ -254,7 +255,7 @@ func (m *MemQuota) clear(span tablepb.Span) uint64 { log.Warn("Table consumed memory records not found", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return 0 } diff --git a/cdc/processor/processor.go b/cdc/processor/processor.go index fbf015e6b4..8e8ab73992 100644 --- a/cdc/processor/processor.go +++ b/cdc/processor/processor.go @@ -40,6 +40,7 @@ import ( cerror "github.com/pingcap/tiflow/pkg/errors" "github.com/pingcap/tiflow/pkg/etcd" "github.com/pingcap/tiflow/pkg/filter" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/pingcap/tiflow/pkg/retry" "github.com/pingcap/tiflow/pkg/sink" @@ -154,7 +155,7 @@ func (p *processor) AddTableSpan( zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", startTs), zap.Bool("isPrepare", isPrepare)) return false, cerror.ErrUnexpected.FastGenByArgs("table start ts must not be 0") @@ -171,7 +172,7 @@ func (p *processor) AddTableSpan( zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", startTs), zap.Bool("isPrepare", isPrepare)) return true, nil @@ -194,7 +195,7 @@ func (p *processor) AddTableSpan( zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", startTs), zap.Bool("isPrepare", isPrepare)) return true, nil @@ -203,7 +204,7 @@ func (p *processor) AddTableSpan( zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", startTs), zap.Bool("isPrepare", isPrepare)) p.removeTable(span) @@ -219,7 +220,7 @@ func (p *processor) AddTableSpan( zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", startTs), zap.Bool("isPrepare", isPrepare)) } @@ -246,7 +247,7 @@ func (p *processor) RemoveTableSpan(span tablepb.Span) bool { zap.String("capture", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return true } return p.sinkManager.r.AsyncStopTable(span) @@ -274,7 +275,7 @@ func (p *processor) IsAddTableSpanFinished(span tablepb.Span, isPrepare bool) bo zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Bool("isPrepare", isPrepare)) } @@ -290,7 +291,7 @@ func (p *processor) IsAddTableSpanFinished(span tablepb.Span, isPrepare bool) bo zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("tableResolvedTs", tableResolvedTs), zap.Uint64("tableCheckpointTs", tableCheckpointTs), zap.Uint64("globalCheckpointTs", globalCheckpointTs), @@ -303,7 +304,7 @@ func (p *processor) IsAddTableSpanFinished(span tablepb.Span, isPrepare bool) bo zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("tableResolvedTs", tableResolvedTs), zap.Uint64("tableCheckpointTs", tableCheckpointTs), zap.Uint64("globalCheckpointTs", globalCheckpointTs), @@ -324,7 +325,7 @@ func (p *processor) IsRemoveTableSpanFinished(span tablepb.Span) (model.Ts, bool zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return 0, true } @@ -335,7 +336,7 @@ func (p *processor) IsRemoveTableSpanFinished(span tablepb.Span) (model.Ts, bool zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), zap.Uint64("checkpointTs", stats.CheckpointTs), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Any("tableStatus", state)) return 0, false } @@ -349,7 +350,7 @@ func (p *processor) IsRemoveTableSpanFinished(span tablepb.Span) (model.Ts, bool zap.String("captureID", p.captureInfo.ID), zap.String("namespace", p.changefeedID.Namespace), zap.String("changefeed", p.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", stats.CheckpointTs)) return stats.CheckpointTs, true diff --git a/cdc/processor/sinkmanager/manager.go b/cdc/processor/sinkmanager/manager.go index 171443fa1b..1d949d7b39 100644 --- a/cdc/processor/sinkmanager/manager.go +++ b/cdc/processor/sinkmanager/manager.go @@ -35,6 +35,7 @@ import ( "github.com/pingcap/tiflow/cdc/sink/tablesink" pconfig "github.com/pingcap/tiflow/pkg/config" cerror "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/retry" "github.com/pingcap/tiflow/pkg/spanz" "github.com/pingcap/tiflow/pkg/upstream" @@ -455,7 +456,7 @@ func (m *SinkManager) backgroundGC(errors chan<- error) { log.Error("Failed to clean table in sort engine", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Error(err)) select { case errors <- err: @@ -465,7 +466,7 @@ func (m *SinkManager) backgroundGC(errors chan<- error) { log.Debug("table stale data has been cleaned", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Any("upperBound", cleanPos)) } sink.lastCleanTime = time.Now() @@ -501,7 +502,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Info("Table sink not found, probably already removed", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) // Maybe the table sink is removed by the processor.(Scheduled the table to other nodes.) // So we do **not** need add it back to the heap. continue @@ -520,7 +521,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Info("Table sink is not replicating, skip it", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.String("tableState", tableState.String())) continue } @@ -559,7 +560,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Info("table sink has been restarted", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Any("lastWrittenPos", lastWrittenPos), zap.String("sinkError", sinkErr.Error())) } else { @@ -567,7 +568,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Warn("table sink restart fail", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.String("sinkError", sinkErr.Error()), zap.Error(restartErr)) } @@ -591,7 +592,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Debug("MemoryQuotaTracing: try acquire memory for table sink task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Uint64("memory", requestMemSize)) t := &sinkTask{ @@ -622,7 +623,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Debug("Generate sink task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Any("lowerBound", lowerBound), zap.Any("currentUpperBound", upperBound)) default: @@ -630,7 +631,7 @@ func (m *SinkManager) generateSinkTasks(ctx context.Context) error { log.Debug("MemoryQuotaTracing: refund memory for table sink task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Uint64("memory", requestMemSize)) break LOOP } @@ -674,7 +675,7 @@ func (m *SinkManager) generateRedoTasks(ctx context.Context) error { log.Info("Table sink not found, probably already removed", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) // Maybe the table sink is removed by the processor.(Scheduled the table to other nodes.) // So we do **not** need add it back to the heap. continue @@ -693,7 +694,7 @@ func (m *SinkManager) generateRedoTasks(ctx context.Context) error { log.Info("Table sink is not replicating, skip it", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.String("tableState", tableState.String())) continue } @@ -723,7 +724,7 @@ func (m *SinkManager) generateRedoTasks(ctx context.Context) error { log.Debug("MemoryQuotaTracing: try acquire memory for redo log task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Uint64("memory", requestMemSize)) t := &redoTask{ @@ -754,7 +755,7 @@ func (m *SinkManager) generateRedoTasks(ctx context.Context) error { log.Debug("Generate redo task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Any("lowerBound", lowerBound), zap.Any("currentUpperBound", upperBound), zap.Float64("lag", time.Since(oracle.GetTimeFromTS(upperBound.CommitTs)).Seconds())) @@ -763,7 +764,7 @@ func (m *SinkManager) generateRedoTasks(ctx context.Context) error { log.Debug("MemoryQuotaTracing: refund memory for redo log task", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &tableSink.span), + logutil.ZapRedactStringer("span", &tableSink.span), zap.Uint64("memory", requestMemSize)) break LOOP } @@ -802,7 +803,7 @@ func (m *SinkManager) UpdateReceivedSorterResolvedTs(span tablepb.Span, ts model log.Debug("Table sink not found when updating resolved ts", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return } tableSink.(*tableSinkWrapper).updateReceivedSorterResolvedTs(ts) @@ -848,14 +849,14 @@ func (m *SinkManager) AddTable(span tablepb.Span, startTs model.Ts, targetTs mod log.Panic("Add an exists table sink", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } m.sinkMemQuota.AddTable(span) m.redoMemQuota.AddTable(span) log.Info("Add table sink", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("startTs", startTs), zap.Uint64("version", sinkWrapper.version)) return sinkWrapper @@ -866,7 +867,7 @@ func (m *SinkManager) StartTable(span tablepb.Span, startTs model.Ts) error { log.Info("Start table sink", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("startTs", startTs), ) tableSink, ok := m.tableSinks.Load(span) @@ -874,7 +875,7 @@ func (m *SinkManager) StartTable(span tablepb.Span, startTs model.Ts) error { log.Panic("Table sink not found when starting table stats", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } if err := tableSink.(*tableSinkWrapper).start(m.managerCtx, startTs); err != nil { @@ -905,7 +906,7 @@ func (m *SinkManager) AsyncStopTable(span tablepb.Span) bool { log.Warn("Table sink not found when removing table", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } if tableSink.(*tableSinkWrapper).asyncStop() { cleanedBytes := m.sinkMemQuota.RemoveTable(span) @@ -913,7 +914,7 @@ func (m *SinkManager) AsyncStopTable(span tablepb.Span) bool { log.Debug("MemoryQuotaTracing: Clean up memory quota for table sink task when removing table", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("memory", cleanedBytes)) return true } @@ -930,13 +931,13 @@ func (m *SinkManager) RemoveTable(span tablepb.Span) { log.Panic("Remove an unexist table sink", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } checkpointTs := value.(*tableSinkWrapper).getCheckpointTs() log.Info("Remove table sink successfully", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("checkpointTs", checkpointTs.Ts)) } @@ -967,7 +968,7 @@ func (m *SinkManager) GetTableState(span tablepb.Span) (tablepb.TableState, bool log.Debug("Table sink not found when getting table state", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return tablepb.TableStateAbsent, false } @@ -981,7 +982,7 @@ func (m *SinkManager) GetTableState(span tablepb.Span) (tablepb.TableState, bool log.Debug("MemoryQuotaTracing: Clean up memory quota for table sink task when removing table", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("memory", cleanedBytes)) } return tableSink.getState(), true @@ -994,7 +995,7 @@ func (m *SinkManager) GetTableStats(span tablepb.Span) TableStats { log.Panic("Table sink not found when getting table stats", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } tableSink := value.(*tableSinkWrapper) @@ -1016,7 +1017,7 @@ func (m *SinkManager) GetTableStats(span tablepb.Span) TableStats { log.Panic("sinkManager: sink upperbound should not less than checkpoint ts", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("upperbound", sinkUpperBound), zap.Any("checkpointTs", checkpointTs)) } diff --git a/cdc/processor/sinkmanager/redo_log_advancer.go b/cdc/processor/sinkmanager/redo_log_advancer.go index b34d2177e5..ee13774965 100644 --- a/cdc/processor/sinkmanager/redo_log_advancer.go +++ b/cdc/processor/sinkmanager/redo_log_advancer.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/memquota" "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter" "github.com/pingcap/tiflow/cdc/redo" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" ) @@ -86,7 +87,7 @@ func (a *redoLogAdvancer) advance(ctx context.Context) error { log.Debug("MemoryQuotaTracing: refund memory for redo log task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", refundMem)) } } @@ -108,7 +109,7 @@ func (a *redoLogAdvancer) advance(ctx context.Context) error { log.Debug("update resolved ts to redo", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("resolvedTs", a.lastTxnCommitTs)) a.emittedCommitTs = a.lastTxnCommitTs } @@ -139,7 +140,7 @@ func (a *redoLogAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: force acquire memory for redo log task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", a.usedMem-a.availableMem)) a.availableMem = a.usedMem } @@ -167,7 +168,7 @@ func (a *redoLogAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: try acquire memory for redo log task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", requestMemSize)) } } else { @@ -180,7 +181,7 @@ func (a *redoLogAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: block acquire memory for redo log task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", requestMemSize)) } } @@ -253,7 +254,7 @@ func (a *redoLogAdvancer) cleanup() { log.Debug("MemoryQuotaTracing: refund memory for redo log task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", a.availableMem-a.usedMem)) } } diff --git a/cdc/processor/sinkmanager/redo_log_worker.go b/cdc/processor/sinkmanager/redo_log_worker.go index cb970afd02..8708ef6ffe 100644 --- a/cdc/processor/sinkmanager/redo_log_worker.go +++ b/cdc/processor/sinkmanager/redo_log_worker.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/memquota" "github.com/pingcap/tiflow/cdc/processor/sourcemanager" "github.com/pingcap/tiflow/cdc/redo" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/tikv/client-go/v2/oracle" "go.uber.org/zap" ) @@ -82,7 +83,7 @@ func (w *redoWorker) handleTask(ctx context.Context, task *redoTask) (finalErr e log.Error("redo worker fails to close iterator", zap.String("namespace", w.changefeedID.Namespace), zap.String("changefeed", w.changefeedID.ID), - zap.Stringer("span", &task.span), + logutil.ZapRedactStringer("span", &task.span), zap.Error(err)) } }() @@ -91,7 +92,7 @@ func (w *redoWorker) handleTask(ctx context.Context, task *redoTask) (finalErr e log.Debug("redo task finished", zap.String("namespace", w.changefeedID.Namespace), zap.String("changefeed", w.changefeedID.ID), - zap.Stringer("span", &task.span), + logutil.ZapRedactStringer("span", &task.span), zap.Any("lowerBound", lowerBound), zap.Any("upperBound", upperBound), zap.Any("lastPos", advancer.lastPos), diff --git a/cdc/processor/sinkmanager/table_sink_advancer.go b/cdc/processor/sinkmanager/table_sink_advancer.go index be70fb9ad6..65165f2234 100644 --- a/cdc/processor/sinkmanager/table_sink_advancer.go +++ b/cdc/processor/sinkmanager/table_sink_advancer.go @@ -19,6 +19,7 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/memquota" "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" ) @@ -87,7 +88,7 @@ func (a *tableSinkAdvancer) advance(isLastTime bool) (err error) { log.Debug("check should advance or not", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Bool("splitTxn", a.splitTxn), zap.Uint64("currTxnCommitTs", a.currTxnCommitTs), zap.Uint64("lastTxnCommitTs", a.lastTxnCommitTs), @@ -168,7 +169,7 @@ func (a *tableSinkAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: force acquire memory for table sink task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", a.usedMem-a.availableMem)) a.availableMem = a.usedMem } @@ -200,7 +201,7 @@ func (a *tableSinkAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: try acquire memory for table sink task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", requestMemSize)) } } else { @@ -213,7 +214,7 @@ func (a *tableSinkAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: force acquire memory for table sink task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", requestMemSize)) } else { // NOTE: if splitTxn is true it's not required to force acquire memory. @@ -226,7 +227,7 @@ func (a *tableSinkAdvancer) tryAdvanceAndAcquireMem( log.Debug("MemoryQuotaTracing: block acquire memory for table sink task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", requestMemSize)) } } @@ -283,7 +284,7 @@ func (a *tableSinkAdvancer) cleanup() { log.Debug("MemoryQuotaTracing: refund memory for table sink task", zap.String("namespace", a.task.tableSink.changefeed.Namespace), zap.String("changefeed", a.task.tableSink.changefeed.ID), - zap.Stringer("span", &a.task.span), + logutil.ZapRedactStringer("span", &a.task.span), zap.Uint64("memory", a.availableMem-a.usedMem)) } } @@ -301,7 +302,7 @@ func advanceTableSinkWithBatchID( log.Debug("Advance table sink with batch ID", zap.String("namespace", t.tableSink.changefeed.Namespace), zap.String("changefeed", t.tableSink.changefeed.ID), - zap.Stringer("span", &t.span), + logutil.ZapRedactStringer("span", &t.span), zap.Any("resolvedTs", resolvedTs), zap.Uint64("size", size)) if size > 0 { @@ -320,7 +321,7 @@ func advanceTableSink( log.Debug("Advance table sink without batch ID", zap.String("namespace", t.tableSink.changefeed.Namespace), zap.String("changefeed", t.tableSink.changefeed.ID), - zap.Stringer("span", &t.span), + logutil.ZapRedactStringer("span", &t.span), zap.Any("resolvedTs", resolvedTs), zap.Uint64("size", size)) if size > 0 { diff --git a/cdc/processor/sinkmanager/table_sink_worker.go b/cdc/processor/sinkmanager/table_sink_worker.go index d1bd8b60df..db21ba4790 100644 --- a/cdc/processor/sinkmanager/table_sink_worker.go +++ b/cdc/processor/sinkmanager/table_sink_worker.go @@ -26,6 +26,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/sourcemanager" "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter" "github.com/pingcap/tiflow/cdc/sink/tablesink" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/prometheus/client_golang/prometheus" "github.com/tikv/client-go/v2/oracle" "go.uber.org/zap" @@ -137,7 +138,7 @@ func (w *sinkWorker) handleTask(ctx context.Context, task *sinkTask) (finalErr e log.Debug("Sink task finished", zap.String("namespace", w.changefeedID.Namespace), zap.String("changefeed", w.changefeedID.ID), - zap.Stringer("span", &task.span), + logutil.ZapRedactStringer("span", &task.span), zap.Any("lowerBound", lowerBound), zap.Any("upperBound", upperBound), zap.Bool("splitTxn", w.splitTxn), @@ -172,7 +173,7 @@ func (w *sinkWorker) handleTask(ctx context.Context, task *sinkTask) (finalErr e log.Error("sink worker fails to close iterator", zap.String("namespace", w.changefeedID.Namespace), zap.String("changefeed", w.changefeedID.ID), - zap.Stringer("span", &task.span), + logutil.ZapRedactStringer("span", &task.span), zap.Error(err)) } }() diff --git a/cdc/processor/sinkmanager/table_sink_wrapper.go b/cdc/processor/sinkmanager/table_sink_wrapper.go index 3dfa10c7f9..91be547002 100644 --- a/cdc/processor/sinkmanager/table_sink_wrapper.go +++ b/cdc/processor/sinkmanager/table_sink_wrapper.go @@ -28,6 +28,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/sink/tablesink" cerrors "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/retry" "github.com/pingcap/tiflow/pkg/util" "github.com/tikv/client-go/v2/oracle" @@ -147,7 +148,7 @@ func (t *tableSinkWrapper) start(ctx context.Context, startTs model.Ts) (err err log.Panic("The table sink has already started", zap.String("namespace", t.changefeed.Namespace), zap.String("changefeed", t.changefeed.ID), - zap.Stringer("span", &t.span), + logutil.ZapRedactStringer("span", &t.span), zap.Uint64("startTs", startTs), zap.Uint64("oldReplicateTs", t.replicateTs.Load()), ) @@ -163,7 +164,7 @@ func (t *tableSinkWrapper) start(ctx context.Context, startTs model.Ts) (err err log.Info("Sink is started", zap.String("namespace", t.changefeed.Namespace), zap.String("changefeed", t.changefeed.ID), - zap.Stringer("span", &t.span), + logutil.ZapRedactStringer("span", &t.span), zap.Uint64("startTs", startTs), zap.Uint64("replicateTs", ts), ) @@ -279,7 +280,7 @@ func (t *tableSinkWrapper) markAsClosing() { log.Info("Sink is closing", zap.String("namespace", t.changefeed.Namespace), zap.String("changefeed", t.changefeed.ID), - zap.Stringer("span", &t.span)) + logutil.ZapRedactStringer("span", &t.span)) break } } @@ -295,7 +296,7 @@ func (t *tableSinkWrapper) markAsClosed() { log.Info("Sink is closed", zap.String("namespace", t.changefeed.Namespace), zap.String("changefeed", t.changefeed.ID), - zap.Stringer("span", &t.span)) + logutil.ZapRedactStringer("span", &t.span)) return } } @@ -396,7 +397,7 @@ func (t *tableSinkWrapper) restart(ctx context.Context) (err error) { log.Info("Sink is restarted", zap.String("namespace", t.changefeed.Namespace), zap.String("changefeed", t.changefeed.ID), - zap.Stringer("span", &t.span), + logutil.ZapRedactStringer("span", &t.span), zap.Uint64("replicateTs", ts)) return nil } @@ -464,8 +465,8 @@ func handleRowChangedEvents( log.Warn("skip emit nil event", zap.String("namespace", changefeed.Namespace), zap.String("changefeed", changefeed.ID), - zap.Stringer("span", &span), - zap.Any("event", e)) + logutil.ZapRedactStringer("span", &span), + logutil.ZapRedactAny("event", e)) continue } @@ -475,10 +476,10 @@ func handleRowChangedEvents( // Just ignore these row changed events. if len(rowEvent.Columns) == 0 && len(rowEvent.PreColumns) == 0 { log.Warn("skip emit empty row event", - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.String("namespace", changefeed.Namespace), zap.String("changefeed", changefeed.ID), - zap.Any("event", e)) + logutil.ZapRedactAny("event", e)) continue } diff --git a/cdc/processor/sinkmanager/tasks.go b/cdc/processor/sinkmanager/tasks.go index 312412b446..649635d9e0 100644 --- a/cdc/processor/sinkmanager/tasks.go +++ b/cdc/processor/sinkmanager/tasks.go @@ -20,6 +20,7 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/tikv/client-go/v2/oracle" "go.uber.org/zap" ) @@ -96,7 +97,7 @@ func validateAndAdjustBound( log.Panic("Task upperbound must be a ResolvedTs", zap.String("namespace", changefeedID.Namespace), zap.String("changefeed", changefeedID.ID), - zap.Stringer("span", span), + logutil.ZapRedactStringer("span", span), zap.Any("upperBound", upperBound)) } return lowerBound, upperBound diff --git a/cdc/processor/sourcemanager/sorter/memory/event_sorter.go b/cdc/processor/sourcemanager/sorter/memory/event_sorter.go index 73ffe00cd1..9af6ea8ea2 100644 --- a/cdc/processor/sourcemanager/sorter/memory/event_sorter.go +++ b/cdc/processor/sourcemanager/sorter/memory/event_sorter.go @@ -23,8 +23,8 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" - "go.uber.org/zap" ) var ( @@ -61,14 +61,14 @@ func (s *EventSorter) IsTableBased() bool { func (s *EventSorter) AddTable(span tablepb.Span, startTs model.Ts) { resolvedTs := startTs if _, exists := s.tables.LoadOrStore(span, &tableSorter{resolvedTs: &resolvedTs}); exists { - log.Panic("add an exist table", zap.Stringer("span", &span)) + log.Panic("add an exist table", logutil.ZapRedactStringer("span", &span)) } } // RemoveTable implements sorter.SortEngine. func (s *EventSorter) RemoveTable(span tablepb.Span) { if _, exists := s.tables.LoadAndDelete(span); !exists { - log.Panic("remove an unexist table", zap.Stringer("span", &span)) + log.Panic("remove an unexist table", logutil.ZapRedactStringer("span", &span)) } } @@ -76,7 +76,7 @@ func (s *EventSorter) RemoveTable(span tablepb.Span) { func (s *EventSorter) Add(span tablepb.Span, events ...*model.PolymorphicEvent) { value, exists := s.tables.Load(span) if !exists { - log.Panic("add events into an unexist table", zap.Stringer("span", &span)) + log.Panic("add events into an unexist table", logutil.ZapRedactStringer("span", &span)) } resolvedTs, hasNewResolved := value.(*tableSorter).add(events...) @@ -100,7 +100,7 @@ func (s *EventSorter) OnResolve(action func(tablepb.Span, model.Ts)) { func (s *EventSorter) FetchByTable(span tablepb.Span, lowerBound, upperBound sorter.Position) sorter.EventIterator { value, exists := s.tables.Load(span) if !exists { - log.Panic("fetch events from an unexist table", zap.Stringer("span", &span)) + log.Panic("fetch events from an unexist table", logutil.ZapRedactStringer("span", &span)) } return value.(*tableSorter).fetch(span, lowerBound, upperBound) @@ -116,7 +116,7 @@ func (s *EventSorter) FetchAllTables(lowerBound sorter.Position) sorter.EventIte func (s *EventSorter) CleanByTable(span tablepb.Span, upperBound sorter.Position) error { value, exists := s.tables.Load(span) if !exists { - log.Panic("clean an unexist table", zap.Stringer("span", &span)) + log.Panic("clean an unexist table", logutil.ZapRedactStringer("span", &span)) } value.(*tableSorter).clean(span, upperBound) @@ -221,7 +221,7 @@ func (s *tableSorter) fetch( iter := &EventIter{} if s.resolvedTs == nil || upperBound.CommitTs > *s.resolvedTs { - log.Panic("fetch unresolved events", zap.Stringer("span", &span)) + log.Panic("fetch unresolved events", logutil.ZapRedactStringer("span", &span)) } startIdx := sort.Search(len(s.resolved), func(idx int) bool { @@ -242,7 +242,7 @@ func (s *tableSorter) clean(span tablepb.Span, upperBound sorter.Position) { s.mu.Lock() defer s.mu.Unlock() if s.resolvedTs == nil || upperBound.CommitTs > *s.resolvedTs { - log.Panic("clean unresolved events", zap.Stringer("span", &span)) + log.Panic("clean unresolved events", logutil.ZapRedactStringer("span", &span)) } startIdx := sort.Search(len(s.resolved), func(idx int) bool { diff --git a/cdc/processor/sourcemanager/sorter/pebble/event_sorter.go b/cdc/processor/sourcemanager/sorter/pebble/event_sorter.go index 12917dc102..ec28820687 100644 --- a/cdc/processor/sourcemanager/sorter/pebble/event_sorter.go +++ b/cdc/processor/sourcemanager/sorter/pebble/event_sorter.go @@ -27,6 +27,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/sourcemanager/sorter/pebble/encoding" "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/pkg/chann" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/prometheus/client_golang/prometheus" "go.uber.org/zap" @@ -107,7 +108,7 @@ func (s *EventSorter) AddTable(span tablepb.Span, startTs model.Ts) { log.Warn("add an exist table", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return } state := &tableState{ @@ -127,7 +128,7 @@ func (s *EventSorter) RemoveTable(span tablepb.Span) { log.Warn("remove an unexist table", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return } s.tables.Delete(span) @@ -146,7 +147,7 @@ func (s *EventSorter) Add(span tablepb.Span, events ...*model.PolymorphicEvent) log.Panic("add events into an non-existent table", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } maxCommitTs := state.maxReceivedCommitTs.Load() @@ -195,7 +196,7 @@ func (s *EventSorter) FetchByTable(span tablepb.Span, lowerBound, upperBound sor log.Panic("fetch unresolved events", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("upperBound", upperBound.CommitTs), zap.Uint64("lowerBound", lowerBound.CommitTs), zap.Uint64("resolved", sortedResolved)) @@ -253,7 +254,7 @@ func (s *EventSorter) GetStatsByTable(span tablepb.Span) sorter.TableStats { log.Panic("Get stats from an non-existent table", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) } maxCommitTs := state.maxReceivedCommitTs.Load() @@ -413,7 +414,7 @@ func (s *EventSorter) batchCommitAndUpdateResolvedTs( log.Debug("Table is removed, skip updating resolved", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("resolved", resolved)) return true } @@ -531,7 +532,7 @@ func (s *EventSorter) cleanTable( log.Info("clean stale table range fails", zap.String("namespace", s.changefeedID.Namespace), zap.String("changefeed", s.changefeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Error(err)) return err } diff --git a/cdc/puller/multiplexing_puller.go b/cdc/puller/multiplexing_puller.go index 278a7e447c..c66b8e203f 100644 --- a/cdc/puller/multiplexing_puller.go +++ b/cdc/puller/multiplexing_puller.go @@ -25,6 +25,7 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/puller/frontier" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/prometheus/client_golang/prometheus" @@ -82,7 +83,7 @@ func (p *tableProgress) handleResolvedSpans(ctx context.Context, e *model.Resolv zap.String("namespace", p.changefeed.Namespace), zap.String("changefeed", p.changefeed.ID), zap.String("tableName", p.tableName), - zap.Any("spans", p.spans)) + logutil.ZapRedactAny("spans", p.spans)) } p.tsTracker.Forward(resolvedSpan.Region, resolvedSpan.Span, e.ResolvedTs) if e.ResolvedTs > p.maxIngressResolvedTs.Load() { @@ -96,7 +97,7 @@ func (p *tableProgress) handleResolvedSpans(ctx context.Context, e *model.Resolv zap.String("namespace", p.changefeed.Namespace), zap.String("changefeed", p.changefeed.ID), zap.String("tableName", p.tableName), - zap.Any("tableID", p.spans), + logutil.ZapRedactAny("tableID", p.spans), zap.Uint64("resolvedTs", resolvedTs), zap.Duration("duration", time.Since(p.start)), ) @@ -233,7 +234,7 @@ func (p *MultiplexingPuller) subscribe( log.Panic("redundant subscription", zap.String("namespace", p.changefeed.Namespace), zap.String("changefeed", p.changefeed.ID), - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) } } @@ -300,7 +301,7 @@ func (p *MultiplexingPuller) unsubscribe(spans []tablepb.Span) { log.Panic("unexist unsubscription", zap.String("namespace", p.changefeed.Namespace), zap.String("changefeed", p.changefeed.ID), - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) } } if len(progress.spans) != len(spans) { diff --git a/cdc/redo/manager.go b/cdc/redo/manager.go index c490751b69..5df3553a09 100644 --- a/cdc/redo/manager.go +++ b/cdc/redo/manager.go @@ -29,6 +29,7 @@ import ( "github.com/pingcap/tiflow/pkg/chann" "github.com/pingcap/tiflow/pkg/config" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/redo" "github.com/pingcap/tiflow/pkg/spanz" "github.com/pingcap/tiflow/pkg/util" @@ -367,7 +368,7 @@ func (m *logManager) AddTable(span tablepb.Span, startTs uint64) { log.Warn("add duplicated table in redo log manager", zap.String("namespace", m.cfg.ChangeFeedID.Namespace), zap.String("changefeed", m.cfg.ChangeFeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return } } @@ -378,7 +379,7 @@ func (m *logManager) RemoveTable(span tablepb.Span) { log.Warn("remove a table not maintained in redo log manager", zap.String("namespace", m.cfg.ChangeFeedID.Namespace), zap.String("changefeed", m.cfg.ChangeFeedID.ID), - zap.Stringer("span", &span)) + logutil.ZapRedactStringer("span", &span)) return } } @@ -406,7 +407,7 @@ func (m *logManager) postFlush(tableRtsMap *spanz.HashMap[model.Ts]) { log.Debug("flush redo with regressed resolved ts", zap.String("namespace", m.cfg.ChangeFeedID.Namespace), zap.String("changefeed", m.cfg.ChangeFeedID.ID), - zap.Stringer("span", &span), + logutil.ZapRedactStringer("span", &span), zap.Uint64("flushed", flushed), zap.Uint64("current", value.(*statefulRts).getFlushed())) } diff --git a/cdc/scheduler/internal/v3/agent/agent.go b/cdc/scheduler/internal/v3/agent/agent.go index d2dd1bbfa7..171493add8 100644 --- a/cdc/scheduler/internal/v3/agent/agent.go +++ b/cdc/scheduler/internal/v3/agent/agent.go @@ -28,6 +28,7 @@ import ( "github.com/pingcap/tiflow/pkg/config" "github.com/pingcap/tiflow/pkg/errors" "github.com/pingcap/tiflow/pkg/etcd" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/p2p" "github.com/pingcap/tiflow/pkg/version" "go.etcd.io/etcd/client/v3/concurrency" @@ -259,7 +260,7 @@ func (a *agent) handleMessage(msg []*schedulepb.Message) (result []*schedulepb.M zap.String("capture", a.CaptureID), zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.Any("message", message)) + logutil.ZapRedactAny("message", message)) } } return @@ -275,7 +276,7 @@ func (a *agent) handleMessageHeartbeat(request *schedulepb.Heartbeat) (*schedule log.Warn("schedulerv3: CheckpointTs is greater than ResolvedTs", zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) } if table.task != nil && table.task.IsRemove { status.State = tablepb.TableStateStopping @@ -307,7 +308,7 @@ func (a *agent) handleMessageHeartbeat(request *schedulepb.Heartbeat) (*schedule zap.String("capture", a.CaptureID), zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.Any("message", message)) + logutil.ZapRedactAny("message", message)) return message, request.GetBarrier() } @@ -370,8 +371,8 @@ func (a *agent) handleMessageDispatchTableRequest( zap.String("capture", a.CaptureID), zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.String("span", span.String()), - zap.Any("request", request)) + logutil.ZapRedactString("span", span.String()), + logutil.ZapRedactAny("request", request)) return } task = &dispatchTableTask{ @@ -385,7 +386,7 @@ func (a *agent) handleMessageDispatchTableRequest( zap.String("capture", a.CaptureID), zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.Any("request", request)) + logutil.ZapRedactAny("request", request)) return } table.injectDispatchTableTask(task) @@ -490,7 +491,7 @@ func (a *agent) sendMsgs(ctx context.Context, msgs []*schedulepb.Message) error zap.String("capture", a.CaptureID), zap.String("namespace", a.ChangeFeedID.Namespace), zap.String("changefeed", a.ChangeFeedID.ID), - zap.Any("message", m)) + logutil.ZapRedactAny("message", m)) } m.Header = &schedulepb.Message_Header{ Version: a.Version, diff --git a/cdc/scheduler/internal/v3/agent/agent_test.go b/cdc/scheduler/internal/v3/agent/agent_test.go index 1b9617b3d4..e94afb440c 100644 --- a/cdc/scheduler/internal/v3/agent/agent_test.go +++ b/cdc/scheduler/internal/v3/agent/agent_test.go @@ -29,6 +29,7 @@ import ( "github.com/pingcap/tiflow/pkg/config" cerror "github.com/pingcap/tiflow/pkg/errors" mock_etcd "github.com/pingcap/tiflow/pkg/etcd/mock" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -1073,7 +1074,7 @@ func (e *MockTableExecutor) AddTableSpan( ) (bool, error) { startTs := checkpoint.CheckpointTs log.Info("AddTableSpan", - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Any("startTs", startTs), zap.Bool("isPrepare", isPrepare)) @@ -1105,7 +1106,7 @@ func (e *MockTableExecutor) IsAddTableSpanFinished(span tablepb.Span, isPrepare _, ok := e.tables.Get(span) if !ok { log.Panic("table which was added is not found", - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Bool("isPrepare", isPrepare)) } @@ -1130,7 +1131,7 @@ func (e *MockTableExecutor) IsAddTableSpanFinished(span tablepb.Span, isPrepare func (e *MockTableExecutor) RemoveTableSpan(span tablepb.Span) bool { state, ok := e.tables.Get(span) if !ok { - log.Warn("table to be remove is not found", zap.String("span", span.String())) + log.Warn("table to be remove is not found", logutil.ZapRedactString("span", span.String())) return true } switch state { @@ -1140,7 +1141,7 @@ func (e *MockTableExecutor) RemoveTableSpan(span tablepb.Span) bool { default: } // the current `processor implementation, does not consider table's state - log.Info("RemoveTableSpan", zap.String("span", span.String()), zap.Any("state", state)) + log.Info("RemoveTableSpan", logutil.ZapRedactString("span", span.String()), zap.Any("state", state)) args := e.Called(span) if args.Bool(0) { @@ -1155,13 +1156,13 @@ func (e *MockTableExecutor) IsRemoveTableSpanFinished(span tablepb.Span) (model. if !ok { // the real `table executor` processor, would panic in such case. log.Warn("table to be removed is not found", - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) return 0, true } args := e.Called(span) if args.Bool(1) { log.Info("remove table finished, remove it from the executor", - zap.String("span", span.String()), zap.Any("state", state)) + logutil.ZapRedactString("span", span.String()), zap.Any("state", state)) e.tables.Delete(span) } else { // revert the state back to old state, assume it's `replicating`, diff --git a/cdc/scheduler/internal/v3/agent/table.go b/cdc/scheduler/internal/v3/agent/table.go index 63fecbafc8..b6da67ce97 100644 --- a/cdc/scheduler/internal/v3/agent/table.go +++ b/cdc/scheduler/internal/v3/agent/table.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/scheduler/internal" "github.com/pingcap/tiflow/cdc/scheduler/schedulepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "go.uber.org/zap" ) @@ -61,7 +62,7 @@ func (t *tableSpan) getAndUpdateTableSpanState() (tablepb.TableState, bool) { log.Debug("schedulerv3: table state changed", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("oldState", oldState), zap.Stringer("state", t.state)) return t.state, true @@ -130,7 +131,7 @@ func (t *tableSpan) handleRemoveTableTask() *schedulepb.Message { log.Warn("schedulerv3: remove table, but table is absent", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span)) + logutil.ZapRedactAny("tableSpan", t.span)) t.task = nil return newRemoveTableResponseMessage(t.getTableSpanStatus(false)) case tablepb.TableStateStopping, // stopping now is useless @@ -163,7 +164,7 @@ func (t *tableSpan) handleRemoveTableTask() *schedulepb.Message { log.Panic("schedulerv3: unknown table state", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Stringer("state", state)) + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("state", state)) } } return nil @@ -180,7 +181,7 @@ func (t *tableSpan) handleAddTableTask(ctx context.Context) (result *schedulepb. log.Warn("schedulerv3: agent add table failed", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Any("task", t.task), + logutil.ZapRedactAny("tableSpan", t.span), logutil.ZapRedactAny("task", t.task), zap.Error(err)) status := t.getTableSpanStatus(false) return newAddTableResponseMessage(status), errors.Trace(err) @@ -190,7 +191,7 @@ func (t *tableSpan) handleAddTableTask(ctx context.Context) (result *schedulepb. log.Info("schedulerv3: table is replicating", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Stringer("state", state)) + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("state", state)) t.task = nil status := t.getTableSpanStatus(false) return newAddTableResponseMessage(status), nil @@ -200,7 +201,7 @@ func (t *tableSpan) handleAddTableTask(ctx context.Context) (result *schedulepb. log.Info("schedulerv3: table is prepared", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Stringer("state", state)) + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("state", state)) t.task = nil return newAddTableResponseMessage(t.getTableSpanStatus(false)), nil } @@ -211,7 +212,7 @@ func (t *tableSpan) handleAddTableTask(ctx context.Context) (result *schedulepb. log.Warn("schedulerv3: agent add table failed", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Stringer("state", state), + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("state", state), zap.Error(err)) status := t.getTableSpanStatus(false) return newAddTableResponseMessage(status), errors.Trace(err) @@ -235,20 +236,20 @@ func (t *tableSpan) handleAddTableTask(ctx context.Context) (result *schedulepb. log.Info("schedulerv3: add table finished", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), zap.Stringer("state", state)) + logutil.ZapRedactAny("tableSpan", t.span), zap.Stringer("state", state)) case tablepb.TableStateStopping, tablepb.TableStateStopped: log.Warn("schedulerv3: ignore add table", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span)) + logutil.ZapRedactAny("tableSpan", t.span)) t.task = nil return newAddTableResponseMessage(t.getTableSpanStatus(false)), nil default: log.Panic("schedulerv3: unknown table state", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span)) + logutil.ZapRedactAny("tableSpan", t.span)) } } @@ -260,15 +261,15 @@ func (t *tableSpan) injectDispatchTableTask(task *dispatchTableTask) { log.Panic("schedulerv3: tableID not match", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), - zap.Stringer("task.TableID", &task.Span)) + logutil.ZapRedactAny("tableSpan", t.span), + logutil.ZapRedactStringer("task.TableID", &task.Span)) } if t.task == nil { log.Info("schedulerv3: table found new task", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), - zap.Any("task", task)) + logutil.ZapRedactAny("tableSpan", t.span), + logutil.ZapRedactAny("task", task)) t.task = task return } @@ -276,9 +277,9 @@ func (t *tableSpan) injectDispatchTableTask(task *dispatchTableTask) { "since there is one not finished yet", zap.String("namespace", t.changefeedID.Namespace), zap.String("changefeed", t.changefeedID.ID), - zap.Any("tableSpan", t.span), - zap.Any("nowTask", t.task), - zap.Any("ignoredTask", task)) + logutil.ZapRedactAny("tableSpan", t.span), + logutil.ZapRedactAny("nowTask", t.task), + logutil.ZapRedactAny("ignoredTask", task)) } func (t *tableSpan) poll(ctx context.Context) (*schedulepb.Message, error) { @@ -364,7 +365,7 @@ func (tm *tableSpanManager) dropTableSpan(span tablepb.Span) { log.Warn("schedulerv3: tableManager drop table not found", zap.String("namespace", tm.changefeedID.Namespace), zap.String("changefeed", tm.changefeedID.ID), - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) return } state, _ := table.getAndUpdateTableSpanState() @@ -372,14 +373,14 @@ func (tm *tableSpanManager) dropTableSpan(span tablepb.Span) { log.Panic("schedulerv3: tableManager drop table undesired", zap.String("namespace", tm.changefeedID.Namespace), zap.String("changefeed", tm.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Stringer("state", table.state)) } log.Debug("schedulerv3: tableManager drop table", zap.String("namespace", tm.changefeedID.Namespace), zap.String("changefeed", tm.changefeedID.ID), - zap.String("span", span.String())) + logutil.ZapRedactString("span", span.String())) tm.tables.Delete(span) } diff --git a/cdc/scheduler/internal/v3/agent/table_test.go b/cdc/scheduler/internal/v3/agent/table_test.go index 7835322211..4d47a8f2a8 100644 --- a/cdc/scheduler/internal/v3/agent/table_test.go +++ b/cdc/scheduler/internal/v3/agent/table_test.go @@ -14,12 +14,21 @@ package agent import ( + "bytes" + "encoding/hex" + "encoding/json" + "strings" "testing" + "github.com/pingcap/errors" + "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/spanz" "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) func TestTableManager(t *testing.T) { @@ -37,3 +46,62 @@ func TestTableManager(t *testing.T) { tableM.dropTableSpan(span1) require.False(t, tableM.tables.Has(span1)) } + +func TestInjectDispatchTableTaskLogRedaction(t *testing.T) { + span := tablepb.Span{ + TableID: 42, StartKey: []byte("table-start-secret"), EndKey: []byte("table-end-secret"), + } + taskSpan := tablepb.Span{ + TableID: 42, StartKey: []byte("task-start-secret"), EndKey: []byte("task-end-secret"), + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + var output bytes.Buffer + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + + table := newTableSpan(model.DefaultChangeFeedID("redact-task"), span, newMockTableExecutor()) + task := &dispatchTableTask{Span: taskSpan} + require.PanicsWithValue(t, "schedulerv3: tableID not match", func() { table.injectDispatchTableTask(task) }) + require.Nil(t, table.task) + require.Equal(t, span, table.span) + require.Equal(t, taskSpan, task.Span) + + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "schedulerv3: tableID not match", entry["msg"]) + require.Equal(t, "redact-task", entry["changefeed"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, taskSpan.String(), entry["task.TableID"]) + for _, key := range []tablepb.Key{span.StartKey, span.EndKey, taskSpan.StartKey, taskSpan.EndKey} { + require.Contains(t, output.String(), hex.EncodeToString(key)) + } + case redact.RedactionModeOn: + require.Equal(t, "?", entry["tableSpan"]) + require.Equal(t, "?", entry["task.TableID"]) + case redact.RedactionModeMarker: + require.Equal(t, "‹"+taskSpan.String()+"›", entry["task.TableID"]) + for _, field := range []string{"tableSpan", "task.TableID"} { + value := entry[field].(string) + require.True(t, strings.HasPrefix(value, "‹") && strings.HasSuffix(value, "›")) + } + } + + // A matching dispatch still becomes the active task without altering its keys. + matchingTask := &dispatchTableTask{Span: span} + table.injectDispatchTableTask(matchingTask) + require.Same(t, matchingTask, table.task) + require.Equal(t, span, matchingTask.Span) + if mode == redact.RedactionModeOn { + for _, key := range []tablepb.Key{span.StartKey, span.EndKey, taskSpan.StartKey, taskSpan.EndKey} { + require.NotContains(t, output.String(), string(key)) + require.NotContains(t, output.String(), hex.EncodeToString(key)) + } + } + }) + } +} diff --git a/cdc/scheduler/internal/v3/coordinator.go b/cdc/scheduler/internal/v3/coordinator.go index 2ff15e5162..4eff38bc9e 100644 --- a/cdc/scheduler/internal/v3/coordinator.go +++ b/cdc/scheduler/internal/v3/coordinator.go @@ -32,6 +32,7 @@ import ( "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/transport" "github.com/pingcap/tiflow/cdc/scheduler/schedulepb" "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/p2p" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/pingcap/tiflow/pkg/spanz" @@ -421,7 +422,7 @@ func (c *coordinator) sendMsgs(ctx context.Context, msgs []*schedulepb.Message) log.Panic("invalid message no destination or unknown message type", zap.String("namespace", c.changefeedID.Namespace), zap.String("changefeed", c.changefeedID.ID), - zap.Any("message", m)) + logutil.ZapRedactAny("message", m)) } epoch := schedulepb.ProcessorEpoch{} diff --git a/cdc/scheduler/internal/v3/keyspan/reconciler.go b/cdc/scheduler/internal/v3/keyspan/reconciler.go index 021cc28aa6..d448468b96 100644 --- a/cdc/scheduler/internal/v3/keyspan/reconciler.go +++ b/cdc/scheduler/internal/v3/keyspan/reconciler.go @@ -24,6 +24,7 @@ import ( "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/replication" "github.com/pingcap/tiflow/pkg/config" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/pingcap/tiflow/pkg/upstream" @@ -150,10 +151,10 @@ func (m *Reconciler) Reconcile( zap.String("namespace", m.changefeedID.Namespace), zap.Int64("tableID", tableID), zap.Int("holes", len(holes)), - zap.String("spanStart", tableStart.String()), - zap.String("spanEnd", tableEnd.String()), - zap.String("foundStart", coveredSpans[0].String()), - zap.String("foundEnd", coveredSpans[len(coveredSpans)-1].String())) + logutil.ZapRedactString("spanStart", tableStart.String()), + logutil.ZapRedactString("spanEnd", tableEnd.String()), + logutil.ZapRedactString("foundStart", coveredSpans[0].String()), + logutil.ZapRedactString("foundEnd", coveredSpans[len(coveredSpans)-1].String())) spans := make([]tablepb.Span, 0, len(coveredSpans)+len(holes)) spans = append(spans, coveredSpans...) for _, s := range holes { diff --git a/cdc/scheduler/internal/v3/keyspan/splitter_region_count.go b/cdc/scheduler/internal/v3/keyspan/splitter_region_count.go index 49205f928d..c3a14d4e6b 100644 --- a/cdc/scheduler/internal/v3/keyspan/splitter_region_count.go +++ b/cdc/scheduler/internal/v3/keyspan/splitter_region_count.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/tikv/client-go/v2/tikv" "go.uber.org/zap" ) @@ -53,7 +54,7 @@ func (m *regionCountSplitter) split( log.Warn("schedulerv3: list regions failed, skip split span", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Error(err)) return []tablepb.Span{span} } @@ -61,7 +62,7 @@ func (m *regionCountSplitter) split( log.Info("schedulerv3: skip split span by region count", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Int("totalCaptures", captureNum), zap.Int("regionCount", len(regions)), zap.Int("regionThreshold", m.regionThreshold)) @@ -82,10 +83,10 @@ func (m *regionCountSplitter) split( log.Warn("schedulerv3: list region out of order detected", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), - zap.Stringer("lastSpan", &spans[len(spans)-1]), - zap.String("startKey", hex.EncodeToString(startKey)), - zap.String("endKey", hex.EncodeToString(endKey))) + logutil.ZapRedactString("span", span.String()), + logutil.ZapRedactStringer("lastSpan", &spans[len(spans)-1]), + logutil.ZapRedactString("startKey", hex.EncodeToString(startKey)), + logutil.ZapRedactString("endKey", hex.EncodeToString(endKey))) return []tablepb.Span{span} } spans = append(spans, tablepb.Span{ @@ -111,7 +112,7 @@ func (m *regionCountSplitter) split( log.Info("schedulerv3: split span by region count", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Int("spans", len(spans)), zap.Int("totalCaptures", captureNum), zap.Int("regionCount", len(regions)), diff --git a/cdc/scheduler/internal/v3/keyspan/splitter_write.go b/cdc/scheduler/internal/v3/keyspan/splitter_write.go index 653328ba61..f021ee1453 100644 --- a/cdc/scheduler/internal/v3/keyspan/splitter_write.go +++ b/cdc/scheduler/internal/v3/keyspan/splitter_write.go @@ -20,6 +20,7 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "go.uber.org/zap" ) @@ -65,7 +66,7 @@ func (m *writeSplitter) split( log.Warn("schedulerv3: scan regions failed, skip split span", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Error(err)) return nil } @@ -76,7 +77,7 @@ func (m *writeSplitter) split( " the maxSpanRegionLimit, skip split span", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Error(err)) return []tablepb.Span{span} } @@ -85,7 +86,7 @@ func (m *writeSplitter) split( log.Info("schedulerv3: split span by written keys", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.Ints("perSpanRegionCounts", splitInfo.RegionCounts), zap.Uint64s("weights", splitInfo.Weights), zap.Int("spans", len(splitInfo.Spans)), @@ -260,8 +261,8 @@ func (m *writeSplitter) splitRegionsByWrittenKeysV1( zap.Int("regionsLength", len(regions)), zap.Int("restSpans", restSpans), zap.Int64("restWeight", restWeight), - zap.Any("prevSpan", spans[len(spans)-2]), - zap.Any("lastSpan", spans[len(spans)-1]), + logutil.ZapRedactAny("prevSpan", spans[len(spans)-2]), + logutil.ZapRedactAny("lastSpan", spans[len(spans)-1]), ) } return &splitRegionsInfo{ diff --git a/cdc/scheduler/internal/v3/replication/replication_manager.go b/cdc/scheduler/internal/v3/replication/replication_manager.go index 8f200f2d35..afa2b87df9 100644 --- a/cdc/scheduler/internal/v3/replication/replication_manager.go +++ b/cdc/scheduler/internal/v3/replication/replication_manager.go @@ -27,6 +27,7 @@ import ( "github.com/pingcap/tiflow/cdc/redo" "github.com/pingcap/tiflow/cdc/scheduler/internal" "github.com/pingcap/tiflow/cdc/scheduler/schedulepb" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "github.com/tikv/client-go/v2/oracle" "go.uber.org/zap" @@ -262,7 +263,7 @@ func (r *Manager) HandleMessage( log.Warn("schedulerv3: ignore message", zap.String("namespace", r.changefeedID.Namespace), zap.String("changefeed", r.changefeedID.ID), - zap.Stringer("type", msg.MsgType), zap.Any("message", msg)) + zap.Stringer("type", msg.MsgType), logutil.ZapRedactAny("message", msg)) } } return sentMsgs, nil @@ -279,7 +280,7 @@ func (r *Manager) handleMessageHeartbeatResponse( zap.String("namespace", r.changefeedID.Namespace), zap.String("changefeed", r.changefeedID.ID), zap.Any("from", from), - zap.Any("message", status)) + logutil.ZapRedactAny("message", status)) continue } msgs, err := table.handleTableStatus(from, &status) @@ -312,7 +313,7 @@ func (r *Manager) handleMessageDispatchTableResponse( log.Warn("schedulerv3: ignore unknown dispatch table response", zap.String("namespace", r.changefeedID.Namespace), zap.String("changefeed", r.changefeedID.ID), - zap.Any("message", msg)) + logutil.ZapRedactAny("message", msg)) return nil, nil } @@ -321,7 +322,7 @@ func (r *Manager) handleMessageDispatchTableResponse( log.Info("schedulerv3: ignore table status no table found", zap.String("namespace", r.changefeedID.Namespace), zap.String("changefeed", r.changefeedID.ID), - zap.Any("message", status)) + logutil.ZapRedactAny("message", status)) return nil, nil } msgs, err := table.handleTableStatus(from, status) @@ -613,8 +614,8 @@ func (r *Manager) AdvanceCheckpoint( log.Warn("schedulerv3: span hole detected, skip advance checkpoint", zap.String("namespace", r.changefeedID.Namespace), zap.String("changefeed", r.changefeedID.ID), - zap.String("lastSpan", lastSpan.String()), - zap.String("span", span.String())) + logutil.ZapRedactString("lastSpan", lastSpan.String()), + logutil.ZapRedactString("span", span.String())) tableHasHole = true return false } diff --git a/cdc/scheduler/internal/v3/replication/replication_set.go b/cdc/scheduler/internal/v3/replication/replication_set.go index f3662cf419..fe86b1f737 100644 --- a/cdc/scheduler/internal/v3/replication/replication_set.go +++ b/cdc/scheduler/internal/v3/replication/replication_set.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/scheduler/schedulepb" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" ) @@ -200,7 +201,7 @@ func NewReplicationSet( return nil, r.multiplePrimaryError( table, captureID, "schedulerv3: multiple primary", zap.Any("primary", r.Primary), - zap.Any("status", tableStatus)) + logutil.ZapRedactAny("status", tableStatus)) } // Recognize primary if it's table is in replicating state. err := r.setCapture(captureID, RoleSecondary) @@ -233,8 +234,8 @@ func NewReplicationSet( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", table.Span.TableID), - zap.Any("replicationSet", r), - zap.Any("status", tableStatus)) + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactAny("status", tableStatus)) err := r.setCapture(captureID, RoleUndetermined) if err != nil { return nil, errors.Trace(err) @@ -248,8 +249,8 @@ func NewReplicationSet( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", table.Span.TableID), - zap.Any("replicationSet", r), - zap.Any("status", tableStatus)) + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactAny("status", tableStatus)) } } @@ -274,7 +275,7 @@ func NewReplicationSet( log.Info("schedulerv3: initialize replication set", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return r, nil } @@ -329,7 +330,7 @@ func (r *ReplicationSet) promoteSecondary(captureID model.CaptureID) error { zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil } role, ok := r.Captures[captureID] @@ -359,8 +360,8 @@ func (r *ReplicationSet) inconsistentError( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.String("captureID", captureID), - zap.Stringer("tableState", input), - zap.Any("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), }...) log.L().WithOptions(zap.AddCallerSkip(1)).Error(msg, fields...) return errors.ErrReplicationSetInconsistent.GenWithStackByArgs( @@ -374,8 +375,8 @@ func (r *ReplicationSet) multiplePrimaryError( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.String("captureID", captureID), - zap.Stringer("tableState", input), - zap.Any("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), }...) log.L().WithOptions(zap.AddCallerSkip(1)).Error(msg, fields...) return errors.ErrReplicationSetMultiplePrimaryError.GenWithStackByArgs( @@ -458,7 +459,7 @@ func (r *ReplicationSet) poll( log.Info("schedulerv3: replication state transition, poll", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), zap.Stringer("old", oldState), zap.Stringer("new", r.State)) @@ -489,9 +490,9 @@ func (r *ReplicationSet) pollOnAbsent( log.Warn("schedulerv3: ignore input, unexpected replication set state", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return false, nil } @@ -538,9 +539,9 @@ func (r *ReplicationSet) pollOnPrepare( log.Info("schedulerv3: primary is stopped during Prepare", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) r.clearPrimary() return nil, false, nil } @@ -548,9 +549,9 @@ func (r *ReplicationSet) pollOnPrepare( log.Info("schedulerv3: capture is stopped during Prepare", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) err := r.clearCapture(captureID, RoleSecondary) if err != nil { return nil, false, errors.Trace(err) @@ -570,9 +571,9 @@ func (r *ReplicationSet) pollOnPrepare( log.Warn("schedulerv3: ignore input, unexpected replication set state", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, false, nil } @@ -605,8 +606,8 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: there are unknown captures during commit", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r), - zap.Stringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID)) return nil, false, nil } @@ -619,8 +620,8 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: promote secondary, no primary", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r), - zap.Stringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID)) } // Secondary has been promoted, retry AddTableRequest. @@ -650,9 +651,9 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: primary is stopped during Commit", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) r.State = ReplicationSetStateAbsent return nil, true, nil } @@ -665,8 +666,8 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: replication state promote secondary", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r), - zap.Stringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), zap.String("original", original), zap.String("captureID", secondary)) return &schedulepb.Message{ @@ -689,9 +690,9 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: secondary is stopped during Commit", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) err := r.clearCapture(captureID, RoleSecondary) if err != nil { return nil, false, errors.Trace(err) @@ -705,9 +706,9 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: capture is stopped during Commit", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) err := r.clearCapture(captureID, RoleUndetermined) return nil, false, errors.Trace(err) } @@ -755,9 +756,9 @@ func (r *ReplicationSet) pollOnCommit( log.Info("schedulerv3: capture is stopping during Commit", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, false, nil } @@ -766,9 +767,9 @@ func (r *ReplicationSet) pollOnCommit( log.Warn("schedulerv3: ignore input, unexpected replication set state", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, false, nil } @@ -797,9 +798,9 @@ func (r *ReplicationSet) pollOnReplicating( log.Info("schedulerv3: primary is stopped during Replicating", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) r.clearPrimary() r.State = ReplicationSetStateAbsent return nil, true, nil @@ -808,9 +809,9 @@ func (r *ReplicationSet) pollOnReplicating( log.Warn("schedulerv3: ignore input, unexpected replication set state", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, false, nil } @@ -846,8 +847,8 @@ func (r *ReplicationSet) pollOnRemoving( log.Warn("schedulerv3: replication state remove capture with error", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r), - zap.Stringer("tableState", input), + logutil.ZapRedactAny("replicationSet", r), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), zap.Error(err)) } @@ -858,9 +859,9 @@ func (r *ReplicationSet) pollOnRemoving( log.Warn("schedulerv3: ignore input, unexpected replication set state", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Stringer("tableState", input), + logutil.ZapRedactStringer("tableState", input), zap.String("captureID", captureID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, false, nil } @@ -879,7 +880,7 @@ func (r *ReplicationSet) handleAddTable( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, nil } err := r.setCapture(captureID, RoleSecondary) @@ -900,7 +901,7 @@ func (r *ReplicationSet) handleAddTable( log.Info("schedulerv3: replication state transition, add table", zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Stringer("old", oldState), zap.Stringer("new", r.State)) return msgs, nil } @@ -914,7 +915,7 @@ func (r *ReplicationSet) handleMoveTable( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, nil } // Ignore move table if @@ -925,7 +926,7 @@ func (r *ReplicationSet) handleMoveTable( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, nil } oldState := r.State @@ -938,7 +939,7 @@ func (r *ReplicationSet) handleMoveTable( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Stringer("new", r.State), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Stringer("old", oldState)) status := tablepb.TableStatus{ Span: r.Span, @@ -955,7 +956,7 @@ func (r *ReplicationSet) handleRemoveTable() ([]*schedulepb.Message, error) { zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, nil } // Ignore remove table if it's not in Replicating state. @@ -964,7 +965,7 @@ func (r *ReplicationSet) handleRemoveTable() ([]*schedulepb.Message, error) { zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r)) + logutil.ZapRedactAny("replicationSet", r)) return nil, nil } oldState := r.State @@ -973,7 +974,7 @@ func (r *ReplicationSet) handleRemoveTable() ([]*schedulepb.Message, error) { zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Stringer("old", oldState)) status := tablepb.TableStatus{ Span: r.Span, @@ -1014,7 +1015,7 @@ func (r *ReplicationSet) handleCaptureShutdown( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Stringer("old", oldState), zap.Stringer("new", r.State)) return msgs, true, errors.Trace(err) } @@ -1027,7 +1028,7 @@ func (r *ReplicationSet) updateCheckpointAndStats( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Any("checkpoint", checkpoint)) // TODO: resolvedTs should not be zero, but we have to handle it for now. @@ -1046,7 +1047,7 @@ func (r *ReplicationSet) updateCheckpointAndStats( zap.String("namespace", r.Changefeed.Namespace), zap.String("changefeed", r.Changefeed.ID), zap.Int64("tableID", r.Span.TableID), - zap.Any("replicationSet", r), + logutil.ZapRedactAny("replicationSet", r), zap.Any("checkpointTs", r.Checkpoint.CheckpointTs), zap.Any("resolvedTs", r.Checkpoint.ResolvedTs)) } diff --git a/cdc/scheduler/internal/v3/replication/replication_set_test.go b/cdc/scheduler/internal/v3/replication/replication_set_test.go index d7ab23f739..1f59d4426d 100644 --- a/cdc/scheduler/internal/v3/replication/replication_set_test.go +++ b/cdc/scheduler/internal/v3/replication/replication_set_test.go @@ -14,19 +14,121 @@ package replication import ( + "bytes" "container/heap" + "encoding/hex" "encoding/json" "math/rand" + "strings" "testing" "time" + perrors "github.com/pingcap/errors" + "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/scheduler/schedulepb" + "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/spanz" "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) +func TestNewReplicationSetLogRedaction(t *testing.T) { + span := tablepb.Span{ + TableID: 42, StartKey: []byte("replication-start-secret"), EndKey: []byte("replication-end-secret"), + } + testcases := []struct { + name string + state tablepb.TableState + message string + expectedState ReplicationSetState + multiple bool + }{ + {"stopping", tablepb.TableStateStopping, "schedulerv3: found a stopping capture during initializing", ReplicationSetStateRemoving, false}, + {"unknown", tablepb.TableState(99), "schedulerv3: unknown table state", ReplicationSetStateAbsent, false}, + {"multiple primary", tablepb.TableStateReplicating, "schedulerv3: multiple primary", ReplicationSetStateUnknown, true}, + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + for _, tc := range testcases { + t.Run(mode.String()+"/"+tc.name, func(t *testing.T) { + originalMode := perrors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { perrors.RedactLogEnabled.Store(originalMode) }) + var output bytes.Buffer + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + + statuses := map[model.CaptureID]*tablepb.TableStatus{ + "capture-1": {Span: span, State: tc.state, Checkpoint: tablepb.Checkpoint{CheckpointTs: 10, ResolvedTs: 10}}, + } + if tc.multiple { + statuses["capture-2"] = &tablepb.TableStatus{ + Span: span, State: tc.state, Checkpoint: tablepb.Checkpoint{CheckpointTs: 10, ResolvedTs: 10}, + } + } + set, err := NewReplicationSet(span, 10, statuses, model.DefaultChangeFeedID("redact-set")) + if tc.multiple { + require.Nil(t, set) + require.True(t, errors.ErrReplicationSetMultiplePrimaryError.Equal(err)) + require.Contains(t, err.Error(), "tableID 42, schedulerv3: multiple primary") + // Propagated errors retain table IDs, without embedding either span key. + for _, key := range []tablepb.Key{span.StartKey, span.EndKey} { + require.NotContains(t, err.Error(), string(key)) + require.NotContains(t, err.Error(), hex.EncodeToString(key)) + } + } else { + require.NoError(t, err) + require.Equal(t, tc.expectedState, set.State) + require.Equal(t, span, set.Span) + if tc.state == tablepb.TableStateStopping { + require.Equal(t, Role(RoleUndetermined), set.Captures["capture-1"]) + } else { + require.Empty(t, set.Captures) + } + } + for _, status := range statuses { + require.Equal(t, span, status.Span) + require.Equal(t, tc.state, status.State) + } + + var entry map[string]interface{} + for _, line := range bytes.Split(bytes.TrimSpace(output.Bytes()), []byte("\n")) { + var candidate map[string]interface{} + require.NoError(t, json.Unmarshal(line, &candidate)) + if candidate["msg"] == tc.message { + entry = candidate + } + } + require.NotNil(t, entry, "expected the real initialization diagnostic") + require.Equal(t, "redact-set", entry["changefeed"]) + switch mode { + case redact.RedactionModeOff: + loggedStatuses := entry["status"].(map[string]interface{}) + require.Len(t, loggedStatuses, len(statuses)) + loggedSpan := loggedStatuses["capture-1"].(map[string]interface{})["span"] + require.Equal(t, span.String(), loggedSpan) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["status"]) + require.Equal(t, "?", entry["replicationSet"]) + for _, key := range []tablepb.Key{span.StartKey, span.EndKey} { + require.NotContains(t, output.String(), string(key)) + require.NotContains(t, output.String(), hex.EncodeToString(key)) + } + case redact.RedactionModeMarker: + value := entry["status"].(string) + require.True(t, strings.HasPrefix(value, "‹") && strings.HasSuffix(value, "›")) + for _, key := range []tablepb.Key{span.StartKey, span.EndKey} { + require.Contains(t, value, hex.EncodeToString(key)) + } + } + }) + } + } +} + // See https://stackoverflow.com/a/30230552/3920448 for details. func nextPerm(p []int) { for i := len(p) - 1; i >= 0; i-- { diff --git a/cdc/scheduler/internal/v3/scheduler/scheduler_drain_capture.go b/cdc/scheduler/internal/v3/scheduler/scheduler_drain_capture.go index 66de141b7a..252a7cbae8 100644 --- a/cdc/scheduler/internal/v3/scheduler/scheduler_drain_capture.go +++ b/cdc/scheduler/internal/v3/scheduler/scheduler_drain_capture.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/member" "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/replication" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "go.uber.org/zap" ) @@ -136,7 +137,7 @@ func (d *drainCaptureScheduler) Schedule( zap.String("namespace", d.changefeedID.Namespace), zap.String("changefeed", d.changefeedID.ID), zap.String("target", d.target), - zap.Any("replication", rep)) + logutil.ZapRedactAny("replication", rep)) skipDrain = true return false } diff --git a/cdc/scheduler/internal/v3/scheduler/scheduler_manager.go b/cdc/scheduler/internal/v3/scheduler/scheduler_manager.go index f41921fc75..e3230c85d6 100644 --- a/cdc/scheduler/internal/v3/scheduler/scheduler_manager.go +++ b/cdc/scheduler/internal/v3/scheduler/scheduler_manager.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/member" "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/replication" "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "go.uber.org/zap" ) @@ -108,7 +109,7 @@ func (sm *Manager) MoveTable(span tablepb.Span, target model.CaptureID) { "since the last triggered task not finished", zap.String("namespace", sm.changefeedID.Namespace), zap.String("changefeed", sm.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("targetCapture", target)) } } diff --git a/cdc/scheduler/internal/v3/scheduler/scheduler_move_table.go b/cdc/scheduler/internal/v3/scheduler/scheduler_move_table.go index 10b44de77e..131641ea5e 100644 --- a/cdc/scheduler/internal/v3/scheduler/scheduler_move_table.go +++ b/cdc/scheduler/internal/v3/scheduler/scheduler_move_table.go @@ -21,6 +21,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/member" "github.com/pingcap/tiflow/cdc/scheduler/internal/v3/replication" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/spanz" "go.uber.org/zap" ) @@ -101,7 +102,7 @@ func (m *moveTableScheduler) Schedule( log.Warn("schedulerv3: move table ignored, since the table cannot found", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("captureID", task.MoveTable.DestCapture)) toBeDeleted = append(toBeDeleted, span) return true @@ -113,7 +114,7 @@ func (m *moveTableScheduler) Schedule( log.Info("schedulerv3: move table ignored, since the target capture cannot found", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("captureID", task.MoveTable.DestCapture)) toBeDeleted = append(toBeDeleted, span) return true @@ -122,7 +123,7 @@ func (m *moveTableScheduler) Schedule( log.Warn("schedulerv3: move table ignored, target capture is not initialized", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("captureID", task.MoveTable.DestCapture), zap.Any("state", status.State)) toBeDeleted = append(toBeDeleted, span) @@ -134,7 +135,7 @@ func (m *moveTableScheduler) Schedule( log.Warn("schedulerv3: move table ignored, table not found in the replication set", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("captureID", task.MoveTable.DestCapture)) toBeDeleted = append(toBeDeleted, span) return true @@ -144,7 +145,7 @@ func (m *moveTableScheduler) Schedule( log.Info("schedulerv3: move table ignored, since the table is not replicating now", zap.String("namespace", m.changefeedID.Namespace), zap.String("changefeed", m.changefeedID.ID), - zap.String("span", span.String()), + logutil.ZapRedactString("span", span.String()), zap.String("captureID", task.MoveTable.DestCapture), zap.Any("replicationState", rep.State)) toBeDeleted = append(toBeDeleted, span) diff --git a/cdc/sink/dmlsink/blackhole/black_hole_dml_sink.go b/cdc/sink/dmlsink/blackhole/black_hole_dml_sink.go index 83f321dcdf..58a57f911a 100644 --- a/cdc/sink/dmlsink/blackhole/black_hole_dml_sink.go +++ b/cdc/sink/dmlsink/blackhole/black_hole_dml_sink.go @@ -19,8 +19,8 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/sink/dmlsink" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/sink" - "go.uber.org/zap" ) // Assert EventSink[E event.TableEvent] implementation @@ -40,7 +40,7 @@ func (s *DMLSink) WriteEvents(rows ...*dmlsink.CallbackableEvent[*model.RowChang if err == nil { for _, row := range rows { // NOTE: don't change the log, some tests depend on it. - log.Debug("BlackHoleSink: WriteEvents", zap.Any("row", row.Event)) + log.Debug("BlackHoleSink: WriteEvents", logutil.ZapRedactAny("row", row.Event)) row.Callback() } } diff --git a/cdc/sink/dmlsink/blackhole/log_redaction_test.go b/cdc/sink/dmlsink/blackhole/log_redaction_test.go new file mode 100644 index 0000000000..3596b5d90e --- /dev/null +++ b/cdc/sink/dmlsink/blackhole/log_redaction_test.go @@ -0,0 +1,73 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package blackhole + +import ( + "bytes" + "encoding/json" + "fmt" + "testing" + + "github.com/pingcap/errors" + "github.com/pingcap/log" + "github.com/pingcap/tiflow/cdc/model" + "github.com/pingcap/tiflow/cdc/sink/dmlsink" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func TestWriteEventsLogRedaction(t *testing.T) { + const secret = "blackhole-secret-value" + cols := []*model.Column{{Name: "value", Type: 1, Value: secret}} + tableInfo := model.BuildTableInfo("db", "tbl", cols, nil) + row := &model.RowChangedEvent{ + StartTs: 1, CommitTs: 2, TableInfo: tableInfo, + Columns: model.Columns2ColumnDatas(cols, tableInfo), + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + var output bytes.Buffer + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + + callbacks := 0 + err := NewDMLSink().WriteEvents(&dmlsink.RowChangeCallbackableEvent{ + Event: row, Callback: func() { callbacks++ }, + }) + require.NoError(t, err) + require.Equal(t, 1, callbacks) + require.Equal(t, secret, row.Columns[0].Value) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "BlackHoleSink: WriteEvents", entry["msg"]) + switch mode { + case redact.RedactionModeOff: + loggedRow := entry["row"].(map[string]interface{}) + loggedCols := loggedRow["Columns"].([]interface{}) + require.Equal(t, secret, loggedCols[0].(map[string]interface{})["value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["row"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(row)), entry["row"]) + } + }) + } +} diff --git a/cdc/sink/dmlsink/mq/worker.go b/cdc/sink/dmlsink/mq/worker.go index d5e4433f25..cbb8764e15 100644 --- a/cdc/sink/dmlsink/mq/worker.go +++ b/cdc/sink/dmlsink/mq/worker.go @@ -27,6 +27,7 @@ import ( "github.com/pingcap/tiflow/cdc/sink/tablesink/state" "github.com/pingcap/tiflow/pkg/chann" "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/sink" "github.com/pingcap/tiflow/pkg/sink/codec" "go.uber.org/zap" @@ -138,7 +139,7 @@ func (w *worker) nonBatchEncodeRun(ctx context.Context) error { log.Debug("Skip event of stopped table", zap.String("namespace", w.changeFeedID.Namespace), zap.String("changefeed", w.changeFeedID.ID), - zap.Any("event", event)) + logutil.ZapRedactAny("event", event)) continue } if err := w.encoderGroup.AddEvents( @@ -252,7 +253,7 @@ func (w *worker) group( // Skip this event when the table is stopping. if msg.rowEvent.GetTableSinkState() != state.TableSinkSinking { msg.rowEvent.Callback() - log.Debug("Skip event of stopped table", zap.Any("event", msg.rowEvent)) + log.Debug("Skip event of stopped table", logutil.ZapRedactAny("event", msg.rowEvent)) continue } if _, ok := groupedMsgs[msg.key]; !ok { diff --git a/cdc/sink/dmlsink/txn/mysql/mysql.go b/cdc/sink/dmlsink/txn/mysql/mysql.go index 8331bb7aea..5818b16d1f 100644 --- a/cdc/sink/dmlsink/txn/mysql/mysql.go +++ b/cdc/sink/dmlsink/txn/mysql/mysql.go @@ -38,6 +38,7 @@ import ( "github.com/pingcap/tiflow/cdc/sink/metrics/txn" "github.com/pingcap/tiflow/pkg/config" cerror "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/retry" pmysql "github.com/pingcap/tiflow/pkg/sink/mysql" "github.com/pingcap/tiflow/pkg/sqlmodel" @@ -226,7 +227,7 @@ func (s *mysqlBackend) Flush(ctx context.Context) (err error) { dmls := s.prepareDMLs() log.Debug("prepare DMLs", zap.String("changefeed", s.changefeed), zap.Any("rows", s.rows), - zap.Strings("sqls", dmls.sqls), zap.Any("values", dmls.values)) + zap.Strings("sqls", dmls.sqls), logutil.ZapRedactAny("values", dmls.values)) start := time.Now() if err := s.execDMLWithMaxRetries(ctx, dmls); err != nil { @@ -273,7 +274,7 @@ func (s *mysqlBackend) MaxFlushInterval() time.Duration { type preparedDMLs struct { startTs []model.Ts - sqls []string + sqls []string // Generated SQL templates contain placeholders, never row values. values [][]interface{} callbacks []dmlsink.CallbackFunc rowCount int @@ -636,7 +637,7 @@ func (s *mysqlBackend) multiStmtExecute( multiStmtSQL := strings.Join(dmls.sqls, ";") log.Debug("exec row", zap.String("changefeed", s.changefeed), zap.Int("workerID", s.workerID), - zap.String("sql", multiStmtSQL), zap.Any("args", multiStmtArgs)) + zap.String("sql", multiStmtSQL), logutil.ZapRedactAny("args", multiStmtArgs)) ctx, cancel := context.WithTimeout(ctx, writeTimeout) defer cancel() start := time.Now() @@ -663,7 +664,7 @@ func (s *mysqlBackend) sequenceExecute( for i, query := range dmls.sqls { args := dmls.values[i] log.Debug("exec row", zap.String("changefeed", s.changefeed), zap.Int("workerID", s.workerID), - zap.String("sql", query), zap.Any("args", args)) + zap.String("sql", query), logutil.ZapRedactAny("args", args)) ctx, cancelFunc := context.WithTimeout(ctx, writeTimeout) var prepStmt *sql.Stmt @@ -710,7 +711,7 @@ func (s *mysqlBackend) execDMLWithMaxRetries(pctx context.Context, dmls *prepare log.Error("unexpected number of sqls and values", zap.String("changefeed", s.changefeed), zap.Strings("sqls", dmls.sqls), - zap.Any("values", dmls.values)) + logutil.ZapRedactAny("values", dmls.values)) return cerror.ErrUnexpected.FastGenByArgs("unexpected number of sqls and values") } @@ -814,6 +815,8 @@ func wrapMysqlTxnError(err error) error { return cerror.WrapError(cerror.ErrMySQLTxnError, err) } +// logDMLTxnErr keeps generated SQL templates and transaction metadata readable. +// Callers must keep row values in separate arguments, never interpolate them into query. func logDMLTxnErr( err error, start time.Time, changefeed string, query string, count int, startTs []model.Ts, diff --git a/cdc/sink/dmlsink/txn/mysql/mysql_test.go b/cdc/sink/dmlsink/txn/mysql/mysql_test.go index 61e120ac51..6801f6dd77 100644 --- a/cdc/sink/dmlsink/txn/mysql/mysql_test.go +++ b/cdc/sink/dmlsink/txn/mysql/mysql_test.go @@ -14,12 +14,14 @@ package mysql import ( + "bytes" "context" "database/sql" "database/sql/driver" "fmt" "net" "net/url" + "strings" "sync" "testing" "time" @@ -40,12 +42,14 @@ import ( "github.com/pingcap/tiflow/cdc/sink/dmlsink" "github.com/pingcap/tiflow/cdc/sink/metrics" "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/sink" pmysql "github.com/pingcap/tiflow/pkg/sink/mysql" "github.com/pingcap/tiflow/pkg/sqlmodel" "github.com/pingcap/tiflow/pkg/util" "github.com/stretchr/testify/require" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest/observer" ) @@ -99,6 +103,113 @@ func newTestMockDB(t *testing.T) (db *sql.DB, mock sqlmock.Sqlmock) { return } +func TestLogDMLTxnErrRedaction(t *testing.T) { + const secret = "secret-value" + const literal = "‹literal›" + tableInfo := model.BuildTableInfo("test", "accounts", []*model.Column{ + {Name: "value", Type: mysql.TypeVarchar}, + {Name: "marker", Type: mysql.TypeVarchar}, + }, nil) + cols := model.Columns2ColumnDatas([]*model.Column{ + {Name: "value", Value: secret}, + {Name: "marker", Value: literal}, + }, tableInfo) + query, args := prepareReplace(tableInfo.TableName.QuoteString(), cols, tableInfo, true, true) + require.Equal(t, "INSERT INTO `test`.`accounts` (`value`,`marker`) VALUES (?,?)", query) + require.Equal(t, []interface{}{secret, literal}, args) + modes := []struct { + mode redact.RedactionMode + expectedArgs string + }{ + {redact.RedactionModeOff, "[secret-value ‹literal›]"}, + {redact.RedactionModeOn, "?"}, + {redact.RedactionModeMarker, "‹[secret-value ‹‹literal››]›"}, + } + errCases := []struct { + name string + number uint16 + message string + retryable bool + }{ + {"retryable", mysql.ErrLockDeadlock, "deadlock", true}, + {"nonretryable", mysql.ErrDupEntry, "duplicate key", false}, + } + + for _, mode := range modes { + for _, errCase := range errCases { + for _, multiStmt := range []bool{false, true} { + t.Run(fmt.Sprintf("%s/%s/multiStmt=%t", mode.mode, errCase.name, multiStmt), func(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode.mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + core, logs := observer.New(zap.DebugLevel) + var output bytes.Buffer + jsonCore := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), + zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(zapcore.NewTee(core, jsonCore)), &log.ZapProperties{ + Level: zap.NewAtomicLevelAt(zap.DebugLevel), + })) + + cause := &dmysql.MySQLError{Number: errCase.number, Message: errCase.message} + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherEqual)) + require.NoError(t, err) + mock.ExpectBegin() + mock.ExpectExec(query).WithArgs(secret, literal).WillReturnError(cause) + mock.ExpectRollback() + mock.ExpectClose() + t.Cleanup(func() { + require.NoError(t, db.Close()) + require.NoError(t, mock.ExpectationsWereMet()) + }) + tx, err := db.Begin() + require.NoError(t, err) + backend := &mysqlBackend{db: db, changefeed: "test-changefeed"} + dmls := &preparedDMLs{ + sqls: []string{query}, values: [][]interface{}{args}, rowCount: 1, startTs: []model.Ts{42}, + } + var wrappedErr error + if multiStmt { + wrappedErr = backend.multiStmtExecute(context.Background(), dmls, tx, time.Second) + } else { + wrappedErr = backend.sequenceExecute(context.Background(), dmls, tx, time.Second) + } + + require.Same(t, cause, errors.Cause(wrappedErr)) + require.Contains(t, wrappedErr.Error(), "Failed query info: "+query+"; ") + require.Contains(t, wrappedErr.Error(), cause.Error()) + require.NotContains(t, wrappedErr.Error(), secret) + require.NotContains(t, wrappedErr.Error(), "literal") + entries := logs.All() + require.Len(t, entries, 2) + require.Equal(t, query, entries[0].ContextMap()["sql"]) + require.Equal(t, mode.expectedArgs, fmt.Sprint(entries[0].ContextMap()["args"])) + require.Equal(t, query, entries[1].ContextMap()["query"]) + if errCase.retryable { + require.Equal(t, zap.WarnLevel, entries[1].Level) + require.Equal(t, "execute DMLs with error, retry later", entries[1].Message) + } else { + require.Equal(t, zap.ErrorLevel, entries[1].Level) + require.Equal(t, "execute DMLs with error, can not retry", entries[1].Message) + } + switch mode.mode { + case redact.RedactionModeOff: + require.Contains(t, output.String(), secret) + require.Contains(t, output.String(), literal) + case redact.RedactionModeOn: + require.NotContains(t, output.String(), secret) + require.NotContains(t, output.String(), "literal") + case redact.RedactionModeMarker: + require.Contains(t, output.String(), mode.expectedArgs) + unmarked := strings.ReplaceAll(output.String(), mode.expectedArgs, "") + require.NotContains(t, unmarked, secret) + require.NotContains(t, unmarked, "literal") + } + }) + } + } + } +} + func TestPrepareDML(t *testing.T) { t.Parallel() tableInfo := model.BuildTableInfo("common_1", "uk_without_pk", []*model.Column{ diff --git a/cdc/sink/tablesink/progress_tracker.go b/cdc/sink/tablesink/progress_tracker.go index b9ee4a73f7..6cb2f9e6f0 100644 --- a/cdc/sink/tablesink/progress_tracker.go +++ b/cdc/sink/tablesink/progress_tracker.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/cdc/processor/tablepb" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" ) @@ -308,7 +309,7 @@ func (r *progressTracker) doCheckClosed() bool { for now > lastCheck+int64(warnDuration.Seconds()) { if r.lastCheckClosed.CompareAndSwap(lastCheck, now) { log.Warn("Close table doesn't return in time, may be stuck", - zap.Stringer("span", &r.span), + logutil.ZapRedactStringer("span", &r.span), zap.Int("trackingCount", trackingCount), zap.Any("lastMinResolvedTs", resolvedTs)) break diff --git a/cdc/sink/tablesink/table_sink_impl.go b/cdc/sink/tablesink/table_sink_impl.go index 7e6b7d7154..c1ca1e074a 100644 --- a/cdc/sink/tablesink/table_sink_impl.go +++ b/cdc/sink/tablesink/table_sink_impl.go @@ -22,6 +22,7 @@ import ( "github.com/pingcap/tiflow/cdc/processor/tablepb" "github.com/pingcap/tiflow/cdc/sink/dmlsink" "github.com/pingcap/tiflow/cdc/sink/tablesink/state" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/pdutil" "github.com/prometheus/client_golang/prometheus" "github.com/tikv/client-go/v2/oracle" @@ -239,7 +240,7 @@ func (e *EventTableSink[E, P]) freeze() { log.Info("Stopping table sink", zap.String("namespace", e.changefeedID.Namespace), zap.String("changefeed", e.changefeedID.ID), - zap.Stringer("span", &e.span), + logutil.ZapRedactStringer("span", &e.span), zap.Uint64("checkpointTs", stoppingCheckpointTs.Ts)) break } @@ -257,7 +258,7 @@ func (e *EventTableSink[E, P]) markAsClosed() (modified bool) { log.Info("Table sink stopped", zap.String("namespace", e.changefeedID.Namespace), zap.String("changefeed", e.changefeedID.ID), - zap.Stringer("span", &e.span), + logutil.ZapRedactStringer("span", &e.span), zap.Uint64("checkpointTs", stoppedCheckpointTs.Ts)) return true } diff --git a/docs/log-redaction.md b/docs/log-redaction.md new file mode 100644 index 0000000000..4697849274 --- /dev/null +++ b/docs/log-redaction.md @@ -0,0 +1,65 @@ +# TiCDC log redaction + +TiCDC can hide sensitive values in annotated log fields or mark them for later +redaction. Redaction is disabled by default. + +Set the mode in the TiCDC server configuration: + +```toml +[security] +redact-info-log = true +``` + +The supported configuration values are: + +| Value | Behavior | Example field value | +| --- | --- | --- | +| `false` | Keep the original value | `customer-data` | +| `true` | Replace the value | `?` | +| `"MARKER"` | Enclose the original value in markers | `‹customer-data›` | + +You can also set `cdc server --redact-info-log=true` or +`cdc server --redact-info-log=MARKER`. An explicitly supplied command-line flag +overrides the configuration file, including `--redact-info-log=false`. +Restart the server to change its configured mode. + +MARKER mode retains sensitive data in the original log. Remove the marked content +before sharing that log. Literal `‹` and `›` characters within a sensitive value +are doubled so they can be distinguished from the enclosing markers. + +## Coverage + +The annotated fields cover row values, keys and key spans, DML arguments, +scheduler messages carrying spans, HTTP request query strings, and +etcd values and watch events that can contain changefeed configuration. +Etcd keys, changefeed identities, timestamps, and other diagnostic fields remain +available. With redaction disabled, the original field values are preserved. + +Parameterized DML templates remain readable, including schema, table, and column +names. Their arguments are redacted separately. SQL containing literal row values +must be annotated as sensitive in its entirety. + +The configured mode also controls existing TiDB error and TiKV client redaction. +TiKV's key helpers hide keys in both ON and MARKER modes. + +DDL text and region error objects remain readable. DDL can contain sensitive +literals, such as a column's `DEFAULT` value. This feature redacts the +annotated fields; it does not guarantee that every log message, error string, or +third-party log is free of sensitive content. DM retains its existing redaction +setting. This facility is not enabled in sync-diff-inspector. + +## Annotating sensitive fields + +Use the helpers in `pkg/logutil` when adding a field containing sensitive data: + +```go +log.Debug("exec row", + zap.String("sql", queryTemplate), + logutil.ZapRedactAny("args", args)) +``` + +`ZapRedactString`, `ZapRedactAny`, `ZapRedactStringer`, and `ZapRedactStrings` +preserve the original zap field behavior in OFF mode and replace the content +with `?` in ON mode. MARKER formatting is deferred until zap encodes the field, +so a filtered debug entry does not format its arguments. Each field retains the +redaction decision made when it was constructed. diff --git a/engine/pkg/orm/log.go b/engine/pkg/orm/log.go index 97044f2dca..1ccfd5bbe6 100644 --- a/engine/pkg/orm/log.go +++ b/engine/pkg/orm/log.go @@ -19,6 +19,7 @@ import ( "time" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" "go.uber.org/zap" "gorm.io/gorm" "gorm.io/gorm/logger" @@ -90,7 +91,7 @@ func (l *ormLogger) Trace(ctx context.Context, begin time.Time, resFunc func() ( logFunc = l.lg.Debug } var fields []zap.Field - fields = append(fields, zap.Duration("elapsed", elapsed), zap.String("sql", sql), zap.Int64("affected-rows", rows)) + fields = append(fields, zap.Duration("elapsed", elapsed), logutil.ZapRedactString("sql", sql), zap.Int64("affected-rows", rows)) if err != nil { fields = append(fields, zap.Error(err)) } diff --git a/pkg/cmd/server/server.go b/pkg/cmd/server/server.go index b5799afecb..6783f44ff4 100644 --- a/pkg/cmd/server/server.go +++ b/pkg/cmd/server/server.go @@ -70,6 +70,8 @@ func (o *Options) addFlags(cmd *cobra.Command) { cmd.Flags().StringVar(&o.ServerConfig.LogFile, "log-file", o.ServerConfig.LogFile, "log file path") cmd.Flags().StringVar(&o.ServerConfig.LogLevel, "log-level", o.ServerConfig.LogLevel, "log level (etc: debug|info|warn|error)") + cmd.Flags().Var(&o.ServerConfig.Security.RedactInfoLog, "redact-info-log", + "whether to enable the log redaction (false|true|\"MARKER\")") cmd.Flags().StringVar(&o.ServerConfig.DataDir, "data-dir", o.ServerConfig.DataDir, "the path to the directory used to store TiCDC-generated data") @@ -105,7 +107,13 @@ func (o *Options) run(cmd *cobra.Command) error { }) defer cancel() - _, err := ticdcutil.GetTimezone(o.ServerConfig.TZ) + // Initialize log redaction settings + err := logutil.InitLogRedactionFromType(o.ServerConfig.Security.RedactInfoLog) + if err != nil { + return errors.Annotate(err, "failed to initialize log redaction") + } + + _, err = ticdcutil.GetTimezone(o.ServerConfig.TZ) if err != nil { return errors.Annotate(err, "can not load timezone, Please specify the time zone through environment variable `TZ` or command line parameters `--tz`") } @@ -196,6 +204,8 @@ func (o *Options) complete(cmd *cobra.Command) error { cfg.Security.KeyPath = o.ServerConfig.Security.KeyPath case "cert-allowed-cn": cfg.Security.CertAllowedCN = o.ServerConfig.Security.CertAllowedCN + case "redact-info-log": + cfg.Security.RedactInfoLog = o.ServerConfig.Security.RedactInfoLog case "sort-dir": // user specified sorter dir should not take effect, it's always `/tmp/sorter` // if user try to set sort-dir by flag, warn it. @@ -254,6 +264,8 @@ func (o *Options) getCredential() *security.Credential { CertPath: o.CertPath, KeyPath: o.KeyPath, CertAllowedCN: certAllowedCN, + // Keep the redaction flag when complete replaces the security config. + RedactInfoLog: o.ServerConfig.Security.RedactInfoLog, } } diff --git a/pkg/cmd/server/server_test.go b/pkg/cmd/server/server_test.go index 61856dae7a..63efb09eeb 100644 --- a/pkg/cmd/server/server_test.go +++ b/pkg/cmd/server/server_test.go @@ -23,6 +23,7 @@ import ( ticonfig "github.com/pingcap/tidb/pkg/config" "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/security" "github.com/spf13/cobra" "github.com/stretchr/testify/require" @@ -106,6 +107,82 @@ func TestDefaultCfg(t *testing.T) { require.Equal(t, "http://127.0.0.1:2379", o.ServerPdAddr) } +func TestRedactInfoLogConfiguration(t *testing.T) { + modes := []struct { + name string + flagValue string + configValue string + expected logutil.RedactInfoLogType + }{ + {"off", "false", "false", logutil.RedactInfoLogOFF}, + {"on", "true", "true", logutil.RedactInfoLogON}, + {"marker", "MARKER", `"MARKER"`, logutil.RedactInfoLogMarker}, + } + + check := func(t *testing.T, configValue, flagValue string, expected logutil.RedactInfoLogType) { + t.Helper() + cmd := new(cobra.Command) + o := newOptions() + o.addFlags(cmd) + + var args []string + if configValue != "" { + configPath := filepath.Join(t.TempDir(), "ticdc.toml") + content := "[security]\nredact-info-log = " + configValue + "\n" + require.NoError(t, os.WriteFile(configPath, []byte(content), 0o600)) + args = append(args, "--config", configPath) + } + if flagValue != "" { + args = append(args, "--redact-info-log", flagValue) + } + + require.NoError(t, cmd.ParseFlags(args)) + require.NoError(t, o.complete(cmd)) + require.Equal(t, expected, o.ServerConfig.Security.RedactInfoLog) + } + + for _, mode := range modes { + t.Run("flag/"+mode.name, func(t *testing.T) { + check(t, "", mode.flagValue, mode.expected) + }) + t.Run("config/"+mode.name, func(t *testing.T) { + check(t, mode.configValue, "", mode.expected) + }) + for _, configMode := range modes { + t.Run("override/"+configMode.name+"/"+mode.name, func(t *testing.T) { + check(t, configMode.configValue, mode.flagValue, mode.expected) + }) + } + } +} + +func TestRedactInfoLogInvalidConfiguration(t *testing.T) { + for _, value := range []string{"invalid", "2", ""} { + t.Run("flag/"+value, func(t *testing.T) { + cmd := new(cobra.Command) + o := newOptions() + o.addFlags(cmd) + + err := cmd.ParseFlags([]string{"--redact-info-log=" + value}) + require.ErrorContains(t, err, `the "redact-info-log" value is invalid`) + }) + } + + for _, value := range []string{`"invalid"`, `"true"`, "2"} { + t.Run("config/"+value, func(t *testing.T) { + configPath := filepath.Join(t.TempDir(), "ticdc.toml") + content := "[security]\nredact-info-log = " + value + "\n" + require.NoError(t, os.WriteFile(configPath, []byte(content), 0o600)) + cmd := new(cobra.Command) + o := newOptions() + o.addFlags(cmd) + + require.NoError(t, cmd.ParseFlags([]string{"--config", configPath})) + require.ErrorContains(t, o.complete(cmd), `the "redact-info-log" value is invalid`) + }) + } +} + func TestParseCfg(t *testing.T) { dataDir := t.TempDir() cmd := new(cobra.Command) diff --git a/pkg/cmd/util/ticdc.toml b/pkg/cmd/util/ticdc.toml index 9058ede002..e1eff667cd 100644 --- a/pkg/cmd/util/ticdc.toml +++ b/pkg/cmd/util/ticdc.toml @@ -34,6 +34,8 @@ max-days = 0 max-backups = 0 [security] +# Hide sensitive log fields with true, or mark them with "MARKER". +# redact-info-log = false # ca-path = "" # cert-path = "" # key-path = "" diff --git a/pkg/config/config_test_data.go b/pkg/config/config_test_data.go index 38b7290fe6..629e407021 100644 --- a/pkg/config/config_test_data.go +++ b/pkg/config/config_test_data.go @@ -143,7 +143,8 @@ const ( "cert-allowed-cn": null, "mtls": false, "client-user-required": false, - "client-allowed-user": null + "client-allowed-user": null, + "redact-info-log": false }, "kv-client": { "enable-multiplexing": true, diff --git a/pkg/logutil/integration_test.go b/pkg/logutil/integration_test.go new file mode 100644 index 0000000000..8b00bc04f9 --- /dev/null +++ b/pkg/logutil/integration_test.go @@ -0,0 +1,84 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +//go:build integration + +package logutil + +import ( + "testing" + + "github.com/pingcap/log" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest" +) + +func TestRedactionIntegration(t *testing.T) { + // Create a test logger that captures output + buf := &zaptest.Buffer{} + logger := zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(zap.NewDevelopmentEncoderConfig()), + buf, + zapcore.DebugLevel, + )) + + // Replace global logger for test + originalLogger := log.L() + log.ReplaceGlobals(logger, &log.ZapProperties{Level: zap.NewAtomicLevelAt(zapcore.DebugLevel)}) + defer func() { + log.ReplaceGlobals(originalLogger, nil) + }() + + sensitiveData := "SELECT * FROM users WHERE password = 'secret123'" + + // Test with redaction OFF + err := InitLogRedactionFromType(RedactInfoLogOFF) + require.NoError(t, err) + + buf.Reset() + log.Info("Testing redaction OFF", + ZapRedactString("query", sensitiveData)) + + output := buf.String() + require.Contains(t, output, sensitiveData) + + // Test with redaction ON + err = InitLogRedactionFromType(RedactInfoLogON) + require.NoError(t, err) + + buf.Reset() + log.Info("Testing redaction ON", + ZapRedactString("query", sensitiveData)) + + output = buf.String() + require.Contains(t, output, `"query":"?"`) + require.NotContains(t, output, sensitiveData) + + // Test with redaction MARKER + err = InitLogRedactionFromType(RedactInfoLogMarker) + require.NoError(t, err) + + buf.Reset() + log.Info("Testing redaction MARKER", + ZapRedactString("query", sensitiveData)) + + output = buf.String() + require.Contains(t, output, "‹"+sensitiveData+"›") + + // Reset to OFF for cleanup + err = InitLogRedactionFromType(RedactInfoLogOFF) + require.NoError(t, err) +} diff --git a/pkg/logutil/log.go b/pkg/logutil/log.go index 5ac1c6bf55..0adc6da49e 100644 --- a/pkg/logutil/log.go +++ b/pkg/logutil/log.go @@ -16,6 +16,7 @@ package logutil import ( "bytes" "context" + "fmt" "io" "os" "strconv" @@ -26,6 +27,7 @@ import ( "github.com/go-sql-driver/mysql" "github.com/pingcap/errors" "github.com/pingcap/log" + "github.com/pingcap/tiflow/pkg/logutil/redact" "go.uber.org/zap" "go.uber.org/zap/zapcore" "google.golang.org/grpc/grpclog" @@ -349,3 +351,23 @@ func InitGinLogWritter() io.Writer { gin.DefaultErrorWriter = &loggerWriter{logFunc: logFunc} return gin.DefaultErrorWriter } + +// ZapRedactString returns a zap field with redacted string content +func ZapRedactString(key, value string) zap.Field { + return redact.ZapString(key, value) +} + +// ZapRedactAny returns a zap field with redacted content +func ZapRedactAny(key string, value interface{}) zap.Field { + return redact.ZapAny(key, value) +} + +// ZapRedactStringer returns a zap field with redacted content +func ZapRedactStringer(key string, value fmt.Stringer) zap.Field { + return redact.ZapStringer(key, value) +} + +// ZapRedactStrings returns a zap field with redacted content +func ZapRedactStrings(key string, value []string) zap.Field { + return redact.ZapStrings(key, value) +} diff --git a/pkg/logutil/log_redact_dependencies_test.go b/pkg/logutil/log_redact_dependencies_test.go new file mode 100644 index 0000000000..33128243f5 --- /dev/null +++ b/pkg/logutil/log_redact_dependencies_test.go @@ -0,0 +1,61 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logutil + +import ( + "testing" + + "github.com/pingcap/errors" + "github.com/pingcap/tidb/pkg/types" + "github.com/stretchr/testify/require" + tikvredact "github.com/tikv/client-go/v2/util/redact" + "go.uber.org/zap/zapcore" +) + +func TestInitLogRedactionControlsDependencies(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + const sensitiveValue = "customer‹›" + for _, tc := range []struct { + mode RedactInfoLogType + sharedMode string + wantValue string + wantKey string + }{ + {RedactInfoLogOFF, errors.RedactLogDisable, sensitiveValue, "736563726574"}, + {RedactInfoLogON, errors.RedactLogEnable, "?", "?"}, + {RedactInfoLogMarker, errors.RedactLogMarker, "‹customer‹‹›››", "?"}, + } { + t.Run(tc.mode.String(), func(t *testing.T) { + require.NoError(t, InitLogRedactionFromType(tc.mode)) + require.Equal(t, tc.sharedMode, errors.RedactLogEnabled.Load()) + + enc := zapcore.NewMapObjectEncoder() + ZapRedactString("value", sensitiveValue).AddTo(enc) + require.Equal(t, tc.wantValue, enc.Fields["value"]) + + // TiKV's existing key helper suppresses values in both ON and MARKER. + require.Equal(t, tc.wantKey, tikvredact.Key([]byte("secret"))) + + // TiDB annotates the incorrect value while preserving its type and error code. + err := types.ErrWrongValue.GenWithStackByArgs("datetime", sensitiveValue) + require.Contains(t, err.Error(), "Incorrect datetime value: '"+tc.wantValue+"'") + if tc.mode == RedactInfoLogON { + require.NotContains(t, err.Error(), sensitiveValue) + } + }) + } +} diff --git a/pkg/logutil/log_redact_test.go b/pkg/logutil/log_redact_test.go new file mode 100644 index 0000000000..7b0379bad2 --- /dev/null +++ b/pkg/logutil/log_redact_test.go @@ -0,0 +1,261 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logutil + +import ( + "fmt" + "testing" + + "github.com/pingcap/log" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" + "go.uber.org/zap/zaptest" +) + +type testStringer struct { + str string +} + +func (s *testStringer) String() string { + return s.str +} + +func TestZapRedactionFields(t *testing.T) { + sensitiveValue := "secret_value" + + // Test ZapRedactString + err := InitLogRedactionFromType(RedactInfoLogON) + require.NoError(t, err) + + field := ZapRedactString("key", sensitiveValue) + require.Equal(t, "key", field.Key) + require.Equal(t, "?", field.String) + + // Test with redaction OFF + err = InitLogRedactionFromType(RedactInfoLogOFF) + require.NoError(t, err) + + field = ZapRedactString("key", sensitiveValue) + require.Equal(t, "key", field.Key) + require.Equal(t, sensitiveValue, field.String) + + // Reset to OFF + err = InitLogRedactionFromType(RedactInfoLogOFF) + require.NoError(t, err) +} + +func TestZapAny(t *testing.T) { + testCases := []struct { + name string + mode RedactInfoLogType + key string + value interface{} + expected string + }{ + // RedactInfoLogOFF tests + { + name: "off mode with string", + mode: RedactInfoLogOFF, + key: "test", + value: "sensitive data", + expected: "sensitive data", + }, + { + name: "off mode with int", + mode: RedactInfoLogOFF, + key: "count", + value: 42, + expected: "42", + }, + { + name: "off mode with struct", + mode: RedactInfoLogOFF, + key: "data", + value: struct{ Name string }{"Alice"}, + expected: "{\\\"Name\\\":\\\"Alice\\\"}", + }, + // RedactInfoLogON tests + { + name: "on mode with string", + mode: RedactInfoLogON, + key: "test", + value: "sensitive data", + expected: "?", + }, + { + name: "on mode with int", + mode: RedactInfoLogON, + key: "count", + value: 42, + expected: "?", + }, + { + name: "on mode with struct", + mode: RedactInfoLogON, + key: "data", + value: struct{ Name string }{"Alice"}, + expected: "?", + }, + // RedactInfoLogMarker tests + { + name: "marker mode with string", + mode: RedactInfoLogMarker, + key: "test", + value: "sensitive", + expected: "‹sensitive›", + }, + { + name: "marker mode with special chars", + mode: RedactInfoLogMarker, + key: "test", + value: "f‹xcv", + expected: "‹f‹‹xcv›", + }, + { + name: "marker mode with int", + mode: RedactInfoLogMarker, + key: "count", + value: 42, + expected: "‹42›", + }, + { + name: "marker mode with struct", + mode: RedactInfoLogMarker, + key: "data", + value: struct{ Name string }{"Alice"}, + expected: "‹{Alice}›", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + err := InitLogRedactionFromType(tc.mode) + require.NoError(t, err) + var buffer zaptest.Buffer + err = InitLogger(&Config{Level: "info"}, WithOutputWriteSyncer(&buffer)) + require.NoError(t, err) + log.Info("ZapRedactAnyTest", ZapRedactAny(tc.key, tc.value)) + require.Contains(t, buffer.String(), tc.expected) + require.Contains(t, buffer.String(), tc.key) + buffer.Reset() + }) + } +} + +func TestZapStringer(t *testing.T) { + testCases := []struct { + name string + mode RedactInfoLogType + key string + value fmt.Stringer + expected string + }{ + { + name: "off mode", + mode: RedactInfoLogOFF, + key: "keyOffMode", + value: &testStringer{"sensitive data"}, + expected: "sensitive data", + }, + { + name: "on mode", + mode: RedactInfoLogON, + key: "keyOnMode", + value: &testStringer{"sensitive data"}, + expected: "?", + }, + { + name: "marker mode", + mode: RedactInfoLogMarker, + key: "keyMarkerMode", + value: &testStringer{"sensitive data"}, + expected: "‹sensitive data›", + }, + { + name: "marker mode with special chars", + mode: RedactInfoLogMarker, + key: "keySpecial", + value: &testStringer{"f‹xcv"}, + expected: "‹f‹‹xcv›", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + err := InitLogRedactionFromType(tc.mode) + require.NoError(t, err) + var buffer zaptest.Buffer + err = InitLogger(&Config{Level: "info"}, WithOutputWriteSyncer(&buffer)) + require.NoError(t, err) + log.Info("TestZapStringer", redact.ZapStringer(tc.key, tc.value)) + require.Contains(t, buffer.String(), tc.expected) + require.Contains(t, buffer.String(), tc.key) + buffer.Reset() + }) + } +} + +func TestZapStrings(t *testing.T) { + testCases := []struct { + name string + mode RedactInfoLogType + key string + value []string + expected string + }{ + { + name: "off mode", + mode: RedactInfoLogOFF, + key: "keyOffMode", + value: []string{"sensitive", "data"}, + expected: "[sensitive,data]", + }, + { + name: "on mode", + mode: RedactInfoLogON, + key: "keyOnMode", + value: []string{"sensitive", "data"}, + expected: "?", + }, + { + name: "marker mode", + mode: RedactInfoLogMarker, + key: "keyMarkerMode", + value: []string{"sensitive", "data"}, + expected: "[‹sensitive›,‹data›]", + }, + { + name: "marker mode with special chars", + mode: RedactInfoLogMarker, + key: "keySpecial", + value: []string{"f‹xcv"}, + expected: "‹f‹‹xcv›", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + err := InitLogRedactionFromType(tc.mode) + require.NoError(t, err) + var buffer zaptest.Buffer + err = InitLogger(&Config{Level: "info"}, WithOutputWriteSyncer(&buffer)) + require.NoError(t, err) + log.Info("TestZapStringer", ZapRedactStrings(tc.key, tc.value)) + require.Contains(t, buffer.String(), tc.expected) + require.Contains(t, buffer.String(), tc.key) + buffer.Reset() + }) + } +} diff --git a/pkg/logutil/redact/redact.go b/pkg/logutil/redact/redact.go new file mode 100644 index 0000000000..af3bef9505 --- /dev/null +++ b/pkg/logutil/redact/redact.go @@ -0,0 +1,205 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package redact + +import ( + "fmt" + + "github.com/pingcap/errors" + tidbredact "github.com/pingcap/tidb/pkg/util/redact" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +var ( + // ensure the lazy types implement the zap interfaces at compile time + _ fmt.Stringer = lazyString("") + _ fmt.Stringer = lazyAny{} + _ zapcore.ArrayMarshaler = lazyStrings(nil) +) + +// lazyString defers marker redaction of a string until the log entry is +// actually encoded. Building the marked copy eagerly is wasted work when the +// entry is filtered out by the log level, which is the common case for +// debug logs on hot paths. +type lazyString string + +func (s lazyString) String() string { + return markString(string(s)) +} + +// lazyAny defers both formatting (fmt.Sprint) and marker redaction of an +// arbitrary value until the log entry is actually encoded. +type lazyAny struct { + value interface{} +} + +func (a lazyAny) String() string { + return markString(fmt.Sprint(a.value)) +} + +// lazyStrings defers marker redaction of a string slice until the log entry +// is actually encoded. +type lazyStrings []string + +// MarshalLogArray implements zapcore.ArrayMarshaler. +func (s lazyStrings) MarshalLogArray(enc zapcore.ArrayEncoder) error { + for _, v := range s { + enc.AppendString(markString(v)) + } + return nil +} + +// RedactionMode represents the type of log redaction +type RedactionMode int32 + +const ( + // RedactionModeOff disables redaction, shows all content + RedactionModeOff RedactionMode = iota + // RedactionModeOn enables redaction, replaces sensitive content with "?" + RedactionModeOn + // RedactionModeMarker enables redaction with markers, surrounds content with ‹› + RedactionModeMarker +) + +// String returns the string representation of RedactionMode +func (mode RedactionMode) String() string { + switch mode { + case RedactionModeOff: + return "OFF" + case RedactionModeOn: + return "ON" + case RedactionModeMarker: + return "MARKER" + default: + return "UNKNOWN" + } +} + +// SetRedactionMode sets the global redaction mode shared with TiDB errors and +// TiKV client logs. Invalid modes enable full redaction. +func SetRedactionMode(mode RedactionMode) { + switch mode { + case RedactionModeOff: + errors.RedactLogEnabled.Store(errors.RedactLogDisable) + case RedactionModeMarker: + errors.RedactLogEnabled.Store(errors.RedactLogMarker) + default: + errors.RedactLogEnabled.Store(errors.RedactLogEnable) + } +} + +// GetRedactionMode returns the current global redaction mode. The empty default +// disables redaction, while unknown modes enable full redaction. +func GetRedactionMode() RedactionMode { + switch errors.RedactLogEnabled.Load() { + case "", errors.RedactLogDisable: + return RedactionModeOff + case errors.RedactLogMarker: + return RedactionModeMarker + default: + return RedactionModeOn + } +} + +// String redacts a string according to the current global redaction mode +func String(input string) string { + mode := GetRedactionMode() + switch mode { + case RedactionModeMarker: + return markString(input) + case RedactionModeOff: + return input + case RedactionModeOn: + return "?" + default: + return "?" + } +} + +// markString escapes existing markers before surrounding the input. It does +// not consult the global mode, so lazy fields keep the mode selected when +// they were constructed even if the configuration changes before encoding. +func markString(input string) string { + return tidbredact.String(errors.RedactLogMarker, input) +} + +// ZapString returns a zap field with redacted string content. +// +// In marker mode the redacted copy is built lazily, when the entry is encoded, +// so callers can pass large strings to log.Debug without paying for them when +// debug logging is disabled. +func ZapString(key string, value string) zap.Field { + mode := GetRedactionMode() + switch mode { + case RedactionModeOff: + return zap.String(key, value) + case RedactionModeOn: + return zap.String(key, "?") + case RedactionModeMarker: + return zap.Stringer(key, lazyString(value)) + default: + return zap.String(key, "?") + } +} + +// ZapAny returns a zap field with redacted content. +// +// In marker mode the value is formatted with fmt.Sprint and redacted lazily, +// when the entry is encoded. Filtered log entries skip formatting and escaping. +func ZapAny(key string, value interface{}) zap.Field { + mode := GetRedactionMode() + switch mode { + case RedactionModeOff: + return zap.Any(key, value) + case RedactionModeOn: + return zap.String(key, "?") + case RedactionModeMarker: + // use fmt.Sprint instead of zap.Any("", value).String as it is not materialized string + return zap.Stringer(key, lazyAny{value: value}) + default: + return zap.String(key, "?") + } +} + +// ZapStringer returns a zap field with redacted stringer content. String is +// called lazily in marker mode and is never called when redaction is on. +func ZapStringer(key string, value fmt.Stringer) zap.Field { + switch GetRedactionMode() { + case RedactionModeOff: + return zap.Stringer(key, value) + case RedactionModeMarker: + return zap.Stringer(key, lazyAny{value: value}) + default: + return zap.String(key, "?") + } +} + +// ZapStrings returns a zap field with redacted string slice content. +// +// In marker mode the redacted copies are built lazily, when the entry is encoded. +func ZapStrings(key string, value []string) zap.Field { + mode := GetRedactionMode() + switch mode { + case RedactionModeOff: + return zap.Strings(key, value) + case RedactionModeOn: + return zap.String(key, "?") + case RedactionModeMarker: + return zap.Array(key, lazyStrings(value)) + default: + return zap.String(key, "?") + } +} diff --git a/pkg/logutil/redact/redact_test.go b/pkg/logutil/redact/redact_test.go new file mode 100644 index 0000000000..14ba5ce7ac --- /dev/null +++ b/pkg/logutil/redact/redact_test.go @@ -0,0 +1,303 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package redact + +import ( + "bytes" + "encoding/json" + "fmt" + "testing" + + "github.com/pingcap/errors" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func TestRedactString(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + testCases := []struct { + mode RedactionMode + input string + output string + }{ + {RedactionModeOff, "sensitive data", "sensitive data"}, + {RedactionModeOff, "f‹xcv", "f‹xcv"}, + {RedactionModeOn, "sensitive data", "?"}, + {RedactionModeOn, "f‹xcv", "?"}, + {RedactionModeMarker, "sensitive data", "‹sensitive data›"}, + {RedactionModeMarker, "f‹xcv", "‹f‹‹xcv›"}, + {RedactionModeMarker, "f›xcv", "‹f››xcv›"}, + } + + for _, tc := range testCases { + SetRedactionMode(tc.mode) + result := String(tc.input) + require.Equal(t, tc.output, result, "String failed for mode %v, input %s", tc.mode, tc.input) + } +} + +func TestRedactionModeSettings(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + // Test setting and getting modes + SetRedactionMode(RedactionModeOn) + require.Equal(t, RedactionModeOn, GetRedactionMode()) + + SetRedactionMode(RedactionModeOff) + require.Equal(t, RedactionModeOff, GetRedactionMode()) + + SetRedactionMode(RedactionModeMarker) + require.Equal(t, RedactionModeMarker, GetRedactionMode()) +} + +func TestRedactionModeUsesSharedState(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + for _, tc := range []struct { + mode RedactionMode + want string + }{ + {RedactionModeOff, errors.RedactLogDisable}, + {RedactionModeOn, errors.RedactLogEnable}, + {RedactionModeMarker, errors.RedactLogMarker}, + {RedactionMode(-1), errors.RedactLogEnable}, + } { + SetRedactionMode(tc.mode) + require.Equal(t, tc.want, errors.RedactLogEnabled.Load()) + } + + for _, tc := range []struct { + sharedMode string + wantMode RedactionMode + wantValue string + }{ + {"", RedactionModeOff, "secret‹›"}, + {errors.RedactLogDisable, RedactionModeOff, "secret‹›"}, + {errors.RedactLogEnable, RedactionModeOn, "?"}, + {errors.RedactLogMarker, RedactionModeMarker, "‹secret‹‹›››"}, + {"invalid", RedactionModeOn, "?"}, + } { + t.Run("shared mode "+tc.sharedMode, func(t *testing.T) { + errors.RedactLogEnabled.Store(tc.sharedMode) + require.Equal(t, tc.wantMode, GetRedactionMode()) + require.Equal(t, tc.wantValue, String("secret‹›")) + require.Equal(t, tc.wantValue, encodeField(ZapString("value", "secret‹›"))["value"]) + if tc.wantMode == RedactionModeOn { + calls := 0 + value := countingStringer{calls: &calls, value: "secret‹›"} + require.Equal(t, "?", encodeField(ZapAny("value", value))["value"]) + require.Equal(t, "?", encodeField(ZapStringer("value", value))["value"]) + require.Zero(t, calls) + } + }) + } +} + +// countingStringer records how many times String is called so tests can +// assert that redaction work is deferred until a field is encoded. +type countingStringer struct { + calls *int + value string +} + +func (c countingStringer) String() string { + *c.calls++ + return c.value +} + +func encodeField(f zap.Field) map[string]interface{} { + enc := zapcore.NewMapObjectEncoder() + f.AddTo(enc) + return enc.Fields +} + +func TestZapAnyIsLazyInMarkerMode(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + SetRedactionMode(RedactionModeMarker) + + calls := 0 + field := ZapAny("key", countingStringer{calls: &calls, value: "secret"}) + require.Equal(t, 0, calls, "value must not be formatted when the field is built") + + fields := encodeField(field) + require.Equal(t, 1, calls, "value must be formatted exactly once when encoded") + require.Equal(t, "‹secret›", fields["key"]) +} + +func TestZapStringIsLazyInMarkerMode(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + SetRedactionMode(RedactionModeMarker) + field := ZapString("key", "a‹b") + require.Equal(t, zapcore.StringerType, field.Type, "marker mode must defer building the redacted copy") + require.Equal(t, "‹a‹‹b›", encodeField(field)["key"]) + + SetRedactionMode(RedactionModeOff) + field = ZapString("key", "plain") + require.Equal(t, zapcore.StringType, field.Type) + require.Equal(t, "plain", field.String) + + SetRedactionMode(RedactionModeOn) + field = ZapString("key", "plain") + require.Equal(t, zapcore.StringType, field.Type) + require.Equal(t, "?", field.String) +} + +func TestZapStringsIsLazyInMarkerMode(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + SetRedactionMode(RedactionModeMarker) + + field := ZapStrings("key", []string{"a", "b›c"}) + require.Equal(t, zapcore.ArrayMarshalerType, field.Type, "marker mode must defer building the redacted copies") + require.Equal(t, []interface{}{"‹a›", "‹b››c›"}, encodeField(field)["key"]) +} + +func jsonLogger(buffer *bytes.Buffer) *zap.Logger { + encoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{MessageKey: "message"}) + return zap.New(zapcore.NewCore(encoder, zapcore.AddSync(buffer), zap.InfoLevel)) +} + +func loggedFields(t *testing.T, buffer *bytes.Buffer) map[string]interface{} { + t.Helper() + var fields map[string]interface{} + require.NoError(t, json.Unmarshal(buffer.Bytes(), &fields)) + return fields +} + +func TestFilteredDebugDoesNotFormatValues(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + SetRedactionMode(RedactionModeMarker) + + var buffer bytes.Buffer + logger := jsonLogger(&buffer) + calls := 0 + value := countingStringer{calls: &calls, value: "secret‹›"} + fields := []zap.Field{ + ZapString("string", value.value), + ZapAny("any", value), + ZapStringer("stringer", value), + ZapStrings("strings", []string{value.value}), + } + logger.Debug("filtered", fields...) + require.Zero(t, calls) + require.Empty(t, buffer.String()) + + logger.Info("encoded", fields...) + require.Equal(t, 2, calls) + encoded := loggedFields(t, &buffer) + for _, key := range []string{"string", "any", "stringer"} { + require.Equal(t, "‹secret‹‹›››", encoded[key]) + } + require.Equal(t, []interface{}{"‹secret‹‹›››"}, encoded["strings"]) +} + +func TestZapFieldsRetainModeUntilEncoding(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + testCases := []struct { + name string + initialMode RedactionMode + finalMode RedactionMode + want string + wantStrings interface{} + wantCalls int + }{ + {"marker to off", RedactionModeMarker, RedactionModeOff, "‹secret‹‹›››", []interface{}{"‹secret‹‹›››"}, 2}, + {"marker to on", RedactionModeMarker, RedactionModeOn, "‹secret‹‹›››", []interface{}{"‹secret‹‹›››"}, 2}, + {"on to off", RedactionModeOn, RedactionModeOff, "?", "?", 0}, + {"off to marker", RedactionModeOff, RedactionModeMarker, "secret‹›", []interface{}{"secret‹›"}, 2}, + } + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + SetRedactionMode(tc.initialMode) + calls := 0 + value := countingStringer{calls: &calls, value: "secret‹›"} + fields := []zap.Field{ + ZapString("string", value.value), + ZapAny("any", value), + ZapStringer("stringer", value), + ZapStrings("strings", []string{value.value}), + } + require.Zero(t, calls) + + SetRedactionMode(tc.finalMode) + var buffer bytes.Buffer + jsonLogger(&buffer).Info("test", fields...) + encoded := loggedFields(t, &buffer) + for _, key := range []string{"string", "any", "stringer"} { + require.Equal(t, tc.want, encoded[key]) + } + require.Equal(t, tc.wantStrings, encoded["strings"]) + require.Equal(t, tc.wantCalls, calls) + }) + } +} + +func TestZapFieldsMatchOriginalsWhenOff(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + SetRedactionMode(RedactionModeOff) + + calls := 0 + value := countingStringer{calls: &calls, value: "secret"} + require.Equal(t, zap.String("string", "secret"), ZapString("string", "secret")) + require.Equal(t, zap.Any("any", value), ZapAny("any", value)) + require.Equal(t, zap.Stringer("stringer", value), ZapStringer("stringer", value)) + require.Equal(t, zap.Strings("strings", []string{"secret"}), ZapStrings("strings", []string{"secret"})) + require.Zero(t, calls) +} + +func TestZapStringerNilValues(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + + values := []struct { + name string + value fmt.Stringer + }{ + {"nil interface", nil}, + {"nil pointer", (*countingStringer)(nil)}, + } + for _, mode := range []RedactionMode{RedactionModeOff, RedactionModeOn, RedactionModeMarker} { + for _, value := range values { + t.Run(mode.String()+"/"+value.name, func(t *testing.T) { + SetRedactionMode(mode) + var buffer bytes.Buffer + jsonLogger(&buffer).Info("test", ZapStringer("value", value.value)) + encoded := loggedFields(t, &buffer) + switch mode { + case RedactionModeOff: + var original bytes.Buffer + jsonLogger(&original).Info("test", zap.Stringer("value", value.value)) + require.Equal(t, loggedFields(t, &original), encoded) + case RedactionModeOn: + require.Equal(t, "?", encoded["value"]) + case RedactionModeMarker: + require.Equal(t, "‹›", encoded["value"]) + } + }) + } + } +} diff --git a/pkg/logutil/redact_type.go b/pkg/logutil/redact_type.go new file mode 100644 index 0000000000..770e199b20 --- /dev/null +++ b/pkg/logutil/redact_type.go @@ -0,0 +1,218 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logutil + +import ( + "encoding/json" + "strings" + + "github.com/pingcap/errors" + "github.com/pingcap/tiflow/pkg/logutil/redact" +) + +// RedactInfoLogType is the behavior of redacting sensitive information in logs. +type RedactInfoLogType int + +func (t RedactInfoLogType) Type() string { + return "redactLog" +} + +const ( + // RedactInfoLogOFF means log redaction is disabled. + RedactInfoLogOFF RedactInfoLogType = iota + // RedactInfoLogON means log redaction is enabled, and will replace the sensitive information with "?". + RedactInfoLogON + // RedactInfoLogMarker means log redaction is enabled, and will use single guillemets ‹› to enclose the sensitive information. + RedactInfoLogMarker +) + +const invalidRedactInfoLogTypeErrMsg = `the "redact-info-log" value is invalid; it should be either false, true, or "MARKER"` + +// String returns the string representation of RedactInfoLogType +func (t RedactInfoLogType) String() string { + switch t { + case RedactInfoLogOFF: + return "OFF" + case RedactInfoLogON: + return "ON" + case RedactInfoLogMarker: + return "MARKER" + default: + return "UNKNOWN" + } +} + +// UnmarshalJSON implements the json.Unmarshaler interface +func (t *RedactInfoLogType) UnmarshalJSON(data []byte) error { + if strings.TrimSpace(string(data)) == "null" { + return errors.New(invalidRedactInfoLogTypeErrMsg) + } + // First try to unmarshal as string to check for "MARKER" + var s string + err := json.Unmarshal(data, &s) + if err == nil && strings.ToUpper(s) == "MARKER" { + *t = RedactInfoLogMarker + return nil + } + + // Then try to unmarshal as boolean + var b bool + err = json.Unmarshal(data, &b) + if err != nil { + return errors.New(invalidRedactInfoLogTypeErrMsg) + } + + if b { + *t = RedactInfoLogON + } else { + *t = RedactInfoLogOFF + } + return nil +} + +// MarshalJSON implements the json.Marshaler interface +func (t RedactInfoLogType) MarshalJSON() ([]byte, error) { + switch t { + case RedactInfoLogOFF: + return json.Marshal(false) + case RedactInfoLogON: + return json.Marshal(true) + case RedactInfoLogMarker: + return json.Marshal("MARKER") + default: + return nil, errors.Errorf("invalid RedactInfoLogType: %d", int(t)) + } +} + +// UnmarshalTOML implements the TOML unmarshaler interface +func (t *RedactInfoLogType) UnmarshalTOML(data interface{}) error { + switch v := data.(type) { + case bool: + if v { + *t = RedactInfoLogON + } else { + *t = RedactInfoLogOFF + } + return nil + case string: + if strings.ToUpper(v) == "MARKER" { + *t = RedactInfoLogMarker + return nil + } + return errors.New(invalidRedactInfoLogTypeErrMsg) + default: + return errors.New(invalidRedactInfoLogTypeErrMsg) + } +} + +// MarshalTOML implements the TOML marshaler interface +func (t RedactInfoLogType) MarshalTOML() ([]byte, error) { + // These JSON literals are also valid TOML values. + return t.MarshalJSON() +} + +// UnmarshalText implements the encoding.TextUnmarshaler interface +func (t *RedactInfoLogType) UnmarshalText(text []byte) error { + s := strings.ToUpper(string(text)) + switch s { + case "FALSE", "OFF", "0": + *t = RedactInfoLogOFF + case "TRUE", "ON", "1": + *t = RedactInfoLogON + case "MARKER": + *t = RedactInfoLogMarker + default: + return errors.New(invalidRedactInfoLogTypeErrMsg) + } + return nil +} + +// MarshalText implements the encoding.TextMarshaler interface +func (t RedactInfoLogType) MarshalText() ([]byte, error) { + switch t { + case RedactInfoLogOFF: + return []byte("false"), nil + case RedactInfoLogON: + return []byte("true"), nil + case RedactInfoLogMarker: + return []byte("MARKER"), nil + default: + return nil, errors.Errorf("invalid RedactInfoLogType: %d", int(t)) + } +} + +// ToRedactionMode converts RedactInfoLogType to redact.RedactionMode +func (t RedactInfoLogType) ToRedactionMode() redact.RedactionMode { + switch t { + case RedactInfoLogOFF: + return redact.RedactionModeOff + case RedactInfoLogON: + return redact.RedactionModeOn + case RedactInfoLogMarker: + return redact.RedactionModeMarker + default: + return redact.RedactionModeOff + } +} + +// InitLogRedactionFromType initializes log redaction from RedactInfoLogType +func InitLogRedactionFromType(redactType RedactInfoLogType) error { + switch redactType { + case RedactInfoLogOFF, RedactInfoLogON, RedactInfoLogMarker: + default: + return errors.Errorf("invalid RedactInfoLogType: %d", int(redactType)) + } + redactionMode := redactType.ToRedactionMode() + redact.SetRedactionMode(redactionMode) + return nil +} + +// ParseRedactInfoLog parses a string value into RedactInfoLogType for backward compatibility +func ParseRedactInfoLog(value string) (RedactInfoLogType, error) { + var t RedactInfoLogType + err := t.UnmarshalText([]byte(value)) + if err != nil { + return RedactInfoLogOFF, err + } + return t, nil +} + +// ValidateRedactInfoLog validates that a string is a valid redact-info-log value +func ValidateRedactInfoLog(value string) error { + _, err := ParseRedactInfoLog(value) + return err +} + +// Set implements the pflag.Value interface +func (t *RedactInfoLogType) Set(s string) error { + return t.UnmarshalText([]byte(s)) +} + +// RedactInfoLogFromBoolAndMode creates RedactInfoLogType from legacy boolean and mode string +// This is for backward compatibility with the old separate config approach +func RedactInfoLogFromBoolAndMode(enabled bool, mode string) RedactInfoLogType { + if !enabled { + return RedactInfoLogOFF + } + + switch strings.ToUpper(mode) { + case "MARKER": + return RedactInfoLogMarker + case "ON", "TRUE", "1": + return RedactInfoLogON + default: + return RedactInfoLogON // Default to ON when enabled but mode unclear + } +} diff --git a/pkg/logutil/redact_type_test.go b/pkg/logutil/redact_type_test.go new file mode 100644 index 0000000000..0f65965353 --- /dev/null +++ b/pkg/logutil/redact_type_test.go @@ -0,0 +1,324 @@ +// Copyright 2024 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logutil + +import ( + "bytes" + "encoding/json" + "testing" + + "github.com/BurntSushi/toml" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" +) + +func TestRedactInfoLogType_String(t *testing.T) { + testCases := []struct { + input RedactInfoLogType + expected string + }{ + {RedactInfoLogOFF, "OFF"}, + {RedactInfoLogON, "ON"}, + {RedactInfoLogMarker, "MARKER"}, + } + + for _, tc := range testCases { + require.Equal(t, tc.expected, tc.input.String()) + } +} + +func TestRedactInfoLogType_UnmarshalJSON(t *testing.T) { + testCases := []struct { + input string + expected RedactInfoLogType + hasError bool + }{ + {`false`, RedactInfoLogOFF, false}, + {`true`, RedactInfoLogON, false}, + {`"MARKER"`, RedactInfoLogMarker, false}, + {`"marker"`, RedactInfoLogMarker, false}, + {`"Marker"`, RedactInfoLogMarker, false}, + {`"invalid"`, RedactInfoLogOFF, true}, + {`123`, RedactInfoLogOFF, true}, + {`null`, RedactInfoLogOFF, true}, + } + + for _, tc := range testCases { + var result RedactInfoLogType + err := json.Unmarshal([]byte(tc.input), &result) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, result) + } + } +} + +func TestRedactInfoLogType_MarshalJSON(t *testing.T) { + testCases := []struct { + input RedactInfoLogType + expected string + }{ + {RedactInfoLogOFF, `false`}, + {RedactInfoLogON, `true`}, + {RedactInfoLogMarker, `"MARKER"`}, + } + + for _, tc := range testCases { + result, err := json.Marshal(tc.input) + require.NoError(t, err) + require.Equal(t, tc.expected, string(result)) + } +} + +func TestRedactInfoLogType_UnmarshalTOML(t *testing.T) { + testCases := []struct { + input interface{} + expected RedactInfoLogType + hasError bool + }{ + {false, RedactInfoLogOFF, false}, + {true, RedactInfoLogON, false}, + {"MARKER", RedactInfoLogMarker, false}, + {"marker", RedactInfoLogMarker, false}, + {"invalid", RedactInfoLogOFF, true}, + {123, RedactInfoLogOFF, true}, + } + + for _, tc := range testCases { + var result RedactInfoLogType + err := result.UnmarshalTOML(tc.input) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, result) + } + } +} + +func TestRedactInfoLogType_UnmarshalText(t *testing.T) { + testCases := []struct { + input string + expected RedactInfoLogType + hasError bool + }{ + {"false", RedactInfoLogOFF, false}, + {"FALSE", RedactInfoLogOFF, false}, + {"off", RedactInfoLogOFF, false}, + {"OFF", RedactInfoLogOFF, false}, + {"0", RedactInfoLogOFF, false}, + {"true", RedactInfoLogON, false}, + {"TRUE", RedactInfoLogON, false}, + {"on", RedactInfoLogON, false}, + {"ON", RedactInfoLogON, false}, + {"1", RedactInfoLogON, false}, + {"MARKER", RedactInfoLogMarker, false}, + {"marker", RedactInfoLogMarker, false}, + {"Marker", RedactInfoLogMarker, false}, + {"invalid", RedactInfoLogOFF, true}, + } + + for _, tc := range testCases { + var result RedactInfoLogType + err := result.UnmarshalText([]byte(tc.input)) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, result) + } + } +} + +func TestRedactInfoLogType_ToRedactionMode(t *testing.T) { + testCases := []struct { + input RedactInfoLogType + expected redact.RedactionMode + }{ + {RedactInfoLogOFF, redact.RedactionModeOff}, + {RedactInfoLogON, redact.RedactionModeOn}, + {RedactInfoLogMarker, redact.RedactionModeMarker}, + } + + for _, tc := range testCases { + result := tc.input.ToRedactionMode() + require.Equal(t, tc.expected, result) + } +} + +func TestParseRedactInfoLog(t *testing.T) { + testCases := []struct { + input string + expected RedactInfoLogType + hasError bool + }{ + {"false", RedactInfoLogOFF, false}, + {"true", RedactInfoLogON, false}, + {"MARKER", RedactInfoLogMarker, false}, + {"invalid", RedactInfoLogOFF, true}, + } + + for _, tc := range testCases { + result, err := ParseRedactInfoLog(tc.input) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, result) + } + } +} + +func TestRedactInfoLogFromBoolAndMode(t *testing.T) { + testCases := []struct { + enabled bool + mode string + expected RedactInfoLogType + }{ + {false, "ON", RedactInfoLogOFF}, + {false, "MARKER", RedactInfoLogOFF}, + {true, "ON", RedactInfoLogON}, + {true, "MARKER", RedactInfoLogMarker}, + {true, "invalid", RedactInfoLogON}, + {true, "", RedactInfoLogON}, + } + + for _, tc := range testCases { + result := RedactInfoLogFromBoolAndMode(tc.enabled, tc.mode) + require.Equal(t, tc.expected, result) + } +} + +func TestTOMLIntegration(t *testing.T) { + type TestConfig struct { + RedactInfoLog RedactInfoLogType `toml:"redact-info-log"` + } + + testCases := []struct { + tomlContent string + expected RedactInfoLogType + hasError bool + }{ + {`redact-info-log = false`, RedactInfoLogOFF, false}, + {`redact-info-log = true`, RedactInfoLogON, false}, + {`redact-info-log = "MARKER"`, RedactInfoLogMarker, false}, + {`redact-info-log = "marker"`, RedactInfoLogMarker, false}, + } + + for _, tc := range testCases { + var config TestConfig + err := toml.Unmarshal([]byte(tc.tomlContent), &config) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, config.RedactInfoLog) + } + } +} + +func TestJSONIntegration(t *testing.T) { + type TestConfig struct { + RedactInfoLog RedactInfoLogType `json:"redact-info-log"` + } + + testCases := []struct { + jsonContent string + expected RedactInfoLogType + hasError bool + }{ + {`{"redact-info-log": false}`, RedactInfoLogOFF, false}, + {`{"redact-info-log": true}`, RedactInfoLogON, false}, + {`{"redact-info-log": "MARKER"}`, RedactInfoLogMarker, false}, + {`{"redact-info-log": "marker"}`, RedactInfoLogMarker, false}, + } + + for _, tc := range testCases { + var config TestConfig + err := json.Unmarshal([]byte(tc.jsonContent), &config) + if tc.hasError { + require.Error(t, err) + } else { + require.NoError(t, err) + require.Equal(t, tc.expected, config.RedactInfoLog) + } + } +} + +func TestRedactInfoLogTOMLRoundTrip(t *testing.T) { + type testConfig struct { + RedactInfoLog RedactInfoLogType `toml:"redact-info-log"` + } + for _, tc := range []struct { + mode RedactInfoLogType + literal string + }{ + {RedactInfoLogOFF, "false"}, + {RedactInfoLogON, "true"}, + {RedactInfoLogMarker, `"MARKER"`}, + } { + t.Run(tc.mode.String(), func(t *testing.T) { + var buf bytes.Buffer + err := toml.NewEncoder(&buf).Encode(testConfig{RedactInfoLog: tc.mode}) + require.NoError(t, err) + require.Equal(t, "redact-info-log = "+tc.literal+"\n", buf.String()) + var decoded testConfig + require.NoError(t, toml.Unmarshal(buf.Bytes(), &decoded)) + require.Equal(t, tc.mode, decoded.RedactInfoLog) + }) + } + var buf bytes.Buffer + require.Error(t, toml.NewEncoder(&buf).Encode(testConfig{RedactInfoLog: RedactInfoLogType(-1)})) +} + +func TestInitLogRedactionFromType(t *testing.T) { + originalMode := redact.GetRedactionMode() + t.Cleanup(func() { redact.SetRedactionMode(originalMode) }) + testCases := []RedactInfoLogType{ + RedactInfoLogOFF, + RedactInfoLogON, + RedactInfoLogMarker, + } + + for _, tc := range testCases { + err := InitLogRedactionFromType(tc) + require.NoError(t, err) + + // Verify the global redaction mode was set correctly + expectedMode := tc.ToRedactionMode() + actualMode := redact.GetRedactionMode() + require.Equal(t, expectedMode, actualMode) + } + // Reject invalid modes without silently disabling an enabled mode. + redact.SetRedactionMode(redact.RedactionModeOn) + require.Error(t, InitLogRedactionFromType(RedactInfoLogType(-1))) + require.Equal(t, redact.RedactionModeOn, redact.GetRedactionMode()) +} + +func TestValidateRedactInfoLog(t *testing.T) { + validValues := []string{"false", "true", "MARKER", "marker", "TRUE", "FALSE", "OFF", "ON", "0", "1"} + for _, val := range validValues { + err := ValidateRedactInfoLog(val) + require.NoError(t, err, "should be valid: %s", val) + } + + invalidValues := []string{"invalid", "2", "yes", "no", "maybe"} + for _, val := range invalidValues { + err := ValidateRedactInfoLog(val) + require.Error(t, err, "should be invalid: %s", val) + } +} diff --git a/pkg/orchestrator/etcd_worker.go b/pkg/orchestrator/etcd_worker.go index 5abd5db508..c9c911f7c0 100644 --- a/pkg/orchestrator/etcd_worker.go +++ b/pkg/orchestrator/etcd_worker.go @@ -25,6 +25,7 @@ import ( "github.com/pingcap/tiflow/pkg/chdelay" cerrors "github.com/pingcap/tiflow/pkg/errors" "github.com/pingcap/tiflow/pkg/etcd" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/migrate" "github.com/pingcap/tiflow/pkg/orchestrator/util" pkgutil "github.com/pingcap/tiflow/pkg/util" @@ -220,7 +221,7 @@ func (worker *EtcdWorker) Run(ctx context.Context, session *concurrency.Session, log.Info("Stale Etcd event dropped", zap.Int64("eventRevision", response.Header.GetRevision()), zap.Int64("previousRevision", worker.revision), - zap.Any("events", response.Events), + logutil.ZapRedactAny("events", response.Events), zap.String("role", role)) continue } @@ -362,7 +363,7 @@ func (worker *EtcdWorker) handleEvent(_ context.Context, event *clientv3.Event) "owner resign or externally delete operation"+ "exit etcd worker and campaign again", zap.String("ownerMetaKey", worker.ownerMetaKey), - zap.String("value", string(event.Kv.Value)), + logutil.ZapRedactString("value", string(event.Kv.Value)), zap.Error(err)) return err } diff --git a/pkg/orchestrator/reactor_state.go b/pkg/orchestrator/reactor_state.go index ccbde53e1c..332d47c066 100644 --- a/pkg/orchestrator/reactor_state.go +++ b/pkg/orchestrator/reactor_state.go @@ -23,6 +23,7 @@ import ( "github.com/pingcap/tiflow/cdc/model" cerrors "github.com/pingcap/tiflow/pkg/errors" "github.com/pingcap/tiflow/pkg/etcd" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/orchestrator/util" "go.uber.org/zap" ) @@ -156,7 +157,7 @@ func (s *GlobalReactorState) Update(key util.EtcdKey, value []byte, _ bool) erro case etcd.CDCKeyTypeMetaVersion: default: log.Warn("receive an unexpected etcd event", zap.String("key", key.String()), - zap.ByteString("value", value), zap.String("role", s.Role)) + logutil.ZapRedactString("value", string(value)), zap.String("role", s.Role)) } return nil } @@ -428,7 +429,7 @@ func (s *ChangefeedReactorState) Update(key util.EtcdKey, value []byte, _ bool) return errors.Trace(err) } if err := s.UpdateCDCKey(k, value); err != nil { - log.Error("failed to update status", zap.String("key", key.String()), zap.ByteString("value", value)) + log.Error("failed to update status", zap.String("key", key.String()), logutil.ZapRedactString("value", string(value))) return errors.Trace(err) } return nil diff --git a/pkg/orchestrator/reactor_state_test.go b/pkg/orchestrator/reactor_state_test.go index 1a8e232dde..08ec468909 100644 --- a/pkg/orchestrator/reactor_state_test.go +++ b/pkg/orchestrator/reactor_state_test.go @@ -21,12 +21,17 @@ import ( "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" + "github.com/pingcap/log" "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/pkg/config" "github.com/pingcap/tiflow/pkg/etcd" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/orchestrator/util" putil "github.com/pingcap/tiflow/pkg/util" "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" ) func TestCheckCaptureAlive(t *testing.T) { @@ -715,3 +720,43 @@ func TestCheckChangefeedNormal(t *testing.T) { stateTester.MustApplyPatches() require.Equal(t, state.Status.CheckpointTs, uint64(2)) } + +func TestUpdateFailureRedactsValue(t *testing.T) { + // An undecodable changefeed info, whose raw value may contain the sink URI. + const value = `{"sink-uri": "mysql://root:verysecure@127.0.0.1:3306/"` + testCases := []struct { + name string + mode redact.RedactionMode + expected string + }{ + {name: "off", mode: redact.RedactionModeOff, expected: value}, + {name: "on", mode: redact.RedactionModeOn, expected: "?"}, + {name: "marker", mode: redact.RedactionModeMarker, expected: "‹" + value + "›"}, + } + originalMode := redact.GetRedactionMode() + t.Cleanup(func() { redact.SetRedactionMode(originalMode) }) + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + redact.SetRedactionMode(tc.mode) + core, logs := observer.New(zapcore.DebugLevel) + restore := log.ReplaceGlobals(zap.New(core), nil) + defer restore() + + state := NewChangefeedReactorState(etcd.DefaultCDCClusterID, + model.DefaultChangeFeedID("test1")) + key := util.NewEtcdKey(etcd.DefaultClusterAndNamespacePrefix + "/changefeed/info/test1") + err := state.Update(key, []byte(value), false) + require.Error(t, err) + + entries := logs.FilterMessage("failed to update status").All() + require.Len(t, entries, 1) + fields := entries[0].ContextMap() + require.Equal(t, key.String(), fields["key"]) + require.Equal(t, tc.expected, fields["value"]) + if tc.mode == redact.RedactionModeOn { + require.NotContains(t, fmt.Sprint(fields), "verysecure") + } + }) + } +} diff --git a/pkg/security/credential.go b/pkg/security/credential.go index ef454bacb6..364b39dd8b 100644 --- a/pkg/security/credential.go +++ b/pkg/security/credential.go @@ -23,6 +23,7 @@ import ( "strings" "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" pd "github.com/tikv/pd/client" "google.golang.org/grpc" "google.golang.org/grpc/credentials" @@ -46,6 +47,8 @@ type Credential struct { ClientUserRequired bool `toml:"client-user-required" json:"client-user-required"` ClientAllowedUser []string `toml:"client-allowed-user" json:"client-allowed-user"` + + RedactInfoLog logutil.RedactInfoLogType `toml:"redact-info-log" json:"redact-info-log"` } // Value implements the driver.Valuer interface diff --git a/pkg/sink/codec/avro/avro.go b/pkg/sink/codec/avro/avro.go index 52cc83da4c..85e975aaed 100644 --- a/pkg/sink/codec/avro/avro.go +++ b/pkg/sink/codec/avro/avro.go @@ -33,6 +33,8 @@ import ( "github.com/pingcap/tiflow/cdc/model" "github.com/pingcap/tiflow/pkg/config" cerror "github.com/pingcap/tiflow/pkg/errors" + "github.com/pingcap/tiflow/pkg/logutil" + "github.com/pingcap/tiflow/pkg/logutil/redact" "github.com/pingcap/tiflow/pkg/sink/codec" "github.com/pingcap/tiflow/pkg/sink/codec/common" "github.com/tikv/client-go/v2/oracle" @@ -217,13 +219,13 @@ func (a *BatchEncoder) AppendRowChangedEvent( key, err := a.encodeKey(ctx, topic, e) if err != nil { - log.Error("avro encoding key failed", zap.Error(err), zap.Any("event", e)) + log.Error("avro encoding key failed", zap.Error(err), logutil.ZapRedactAny("event", e)) return errors.Trace(err) } value, err := a.encodeValue(ctx, topic, e) if err != nil { - log.Error("avro encoding value failed", zap.Error(err), zap.Any("event", e)) + log.Error("avro encoding value failed", zap.Error(err), logutil.ZapRedactAny("event", e)) return errors.Trace(err) } @@ -638,7 +640,7 @@ func (a *BatchEncoder) columns2AvroData(input avroEncodeInput) (map[string]inter } } - log.Debug("rowToAvroData", zap.Any("data", ret)) + log.Debug("rowToAvroData", logutil.ZapRedactAny("data", ret)) return ret, nil } @@ -923,7 +925,15 @@ func (a *BatchEncoder) columnToAvroData(col model.ColumnDataX) (interface{}, str if v, ok := col.Value.(string); ok { n, err := strconv.ParseInt(v, 10, 32) if err != nil { - log.Info("avro encoder parse year value failed", zap.String("value", v), zap.Error(err)) + // NumError includes the input in its message. Redact a copy so + // both this diagnostic and subsequent logs of the returned error + // protect the value while retaining the parsing error cause. + if numErr, ok := err.(*strconv.NumError); ok { + redactedErr := *numErr + redactedErr.Num = redact.String(numErr.Num) + err = &redactedErr + } + log.Info("avro encoder parse year value failed", logutil.ZapRedactString("value", v), zap.Error(err)) return nil, "", cerror.WrapError(cerror.ErrAvroEncodeFailed, err) } return int32(n), "int", nil @@ -935,7 +945,7 @@ func (a *BatchEncoder) columnToAvroData(col model.ColumnDataX) (interface{}, str } return nil, "", cerror.ErrAvroEncodeFailed default: - log.Error("unknown mysql type", zap.Any("value", col.Value), zap.Any("mysqlType", col.GetType())) + log.Error("unknown mysql type", logutil.ZapRedactAny("value", col.Value), zap.Any("mysqlType", col.GetType())) return nil, "", cerror.ErrAvroEncodeFailed.GenWithStack("unknown mysql type") } } diff --git a/pkg/sink/codec/avro/confluent_schema_registry_test.go b/pkg/sink/codec/avro/confluent_schema_registry_test.go index 596323f791..c47290092d 100644 --- a/pkg/sink/codec/avro/confluent_schema_registry_test.go +++ b/pkg/sink/codec/avro/confluent_schema_registry_test.go @@ -25,9 +25,10 @@ import ( "github.com/stretchr/testify/require" ) -func getTestingContext() context.Context { - // nolint:govet - ctx, _ := context.WithTimeout(context.Background(), time.Second*3) +func getTestingContext(t *testing.T) context.Context { + t.Helper() + ctx, cancel := context.WithTimeout(context.Background(), time.Second*3) + t.Cleanup(cancel) return ctx } @@ -35,7 +36,7 @@ func TestSchemaRegistry(t *testing.T) { startHTTPInterceptForTestingRegistry() defer stopHTTPInterceptForTestingRegistry() - ctx := getTestingContext() + ctx := getTestingContext(t) manager, err := NewConfluentSchemaManager(ctx, "http://127.0.0.1:8081", nil) require.NoError(t, err) @@ -107,7 +108,7 @@ func TestSchemaRegistryBad(t *testing.T) { startHTTPInterceptForTestingRegistry() defer stopHTTPInterceptForTestingRegistry() - ctx := getTestingContext() + ctx := getTestingContext(t) _, err := NewConfluentSchemaManager(ctx, "http://127.0.0.1:808", nil) require.Error(t, err) @@ -119,7 +120,7 @@ func TestSchemaRegistryIdempotent(t *testing.T) { startHTTPInterceptForTestingRegistry() defer stopHTTPInterceptForTestingRegistry() - ctx := getTestingContext() + ctx := getTestingContext(t) manager, err := NewConfluentSchemaManager(ctx, "http://127.0.0.1:8081", nil) require.NoError(t, err) @@ -164,7 +165,7 @@ func TestGetCachedOrRegister(t *testing.T) { startHTTPInterceptForTestingRegistry() defer stopHTTPInterceptForTestingRegistry() - ctx := getTestingContext() + ctx := getTestingContext(t) manager, err := NewConfluentSchemaManager(ctx, "http://127.0.0.1:8081", nil) require.NoError(t, err) diff --git a/pkg/sink/codec/avro/log_redaction_test.go b/pkg/sink/codec/avro/log_redaction_test.go new file mode 100644 index 0000000000..4c405ebcf1 --- /dev/null +++ b/pkg/sink/codec/avro/log_redaction_test.go @@ -0,0 +1,213 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package avro + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "strconv" + "strings" + "testing" + + "github.com/linkedin/goavro/v2" + "github.com/pingcap/errors" + "github.com/pingcap/log" + "github.com/pingcap/tidb/pkg/parser/mysql" + "github.com/pingcap/tiflow/cdc/model" + "github.com/pingcap/tiflow/pkg/config" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/pingcap/tiflow/pkg/sink/codec/common" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func captureAvroRedactionLogs(t *testing.T, mode redact.RedactionMode) *bytes.Buffer { + t.Helper() + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + output := &bytes.Buffer{} + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + return output +} + +func avroLogEntry(t *testing.T, output *bytes.Buffer, message string) map[string]interface{} { + t.Helper() + for _, line := range strings.Split(strings.TrimSpace(output.String()), "\n") { + var entry map[string]interface{} + require.NoError(t, json.Unmarshal([]byte(line), &entry)) + if entry["msg"] == message { + return entry + } + } + t.Fatalf("log entry %q missing from %s", message, output.String()) + return nil +} + +// Avoid an external schema registry while exercising the normal encoder paths. +type redactionSchemaManager struct { + SchemaManager + err error +} + +func (m redactionSchemaManager) GetCachedOrRegister(_ context.Context, _ string, _ uint64, schemaGen SchemaGenerator) (*goavro.Codec, []byte, error) { + if m.err != nil { + return nil, nil, m.err + } + schema, err := schemaGen() + if err != nil { + return nil, nil, err + } + codec, err := goavro.NewCodec(schema) + return codec, nil, err +} + +func TestAvroRowDataLogRedaction(t *testing.T) { + const secret = "avro-row-secret" + columns := []*model.Column{{Name: "value", Type: mysql.TypeVarchar, Value: secret}} + tableInfo := model.BuildTableInfo("db", "tbl", columns, nil) + input := avroEncodeInput{ + TableInfo: tableInfo, + columns: model.Columns2ColumnDatas(columns, tableInfo), + colInfos: tableInfo.GetColInfosForRowChangedEvent(), + } + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureAvroRedactionLogs(t, mode) + encoder := NewAvroEncoder(model.DefaultNamespace, nil, common.NewConfig(config.ProtocolAvro)).(*BatchEncoder) + data, err := encoder.columns2AvroData(input) + require.NoError(t, err) + require.Equal(t, map[string]interface{}{"value": secret}, data) + entry := avroLogEntry(t, output, "rowToAvroData") + switch mode { + case redact.RedactionModeOff: + require.Equal(t, data, entry["data"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["data"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, "‹map[value:"+secret+"]›", entry["data"]) + } + }) + } +} + +func TestAvroEncodeFailureLogRedaction(t *testing.T) { + const secret = "avro-encode-error-secret" + for _, keyFailure := range []bool{true, false} { + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(fmt.Sprintf("key=%t/%s", keyFailure, mode), func(t *testing.T) { + output := captureAvroRedactionLogs(t, mode) + column := &model.Column{Name: "value", Type: mysql.TypeVarchar, Value: secret} + var indices [][]int + if keyFailure { + column.Flag = model.HandleKeyFlag | model.PrimaryKeyFlag + indices = [][]int{{0}} + } + columns := []*model.Column{column} + tableInfo := model.BuildTableInfo("db", "tbl", columns, indices) + row := &model.RowChangedEvent{TableInfo: tableInfo, Columns: model.Columns2ColumnDatas(columns, tableInfo)} + registryErr := errors.New("schema registry unavailable") + encoder := NewAvroEncoder(model.DefaultNamespace, redactionSchemaManager{err: registryErr}, common.NewConfig(config.ProtocolAvro)) + callbacks := 0 + err := encoder.AppendRowChangedEvent(context.Background(), "topic", row, func() { callbacks++ }) + require.Same(t, registryErr, errors.Cause(err)) + require.Empty(t, encoder.Build()) + require.Zero(t, callbacks) + message := "avro encoding value failed" + if keyFailure { + message = "avro encoding key failed" + } + entry := avroLogEntry(t, output, message) + switch mode { + case redact.RedactionModeOff: + loggedEvent := entry["event"].(map[string]interface{}) + require.Equal(t, secret, loggedEvent["Columns"].([]interface{})[0].(map[string]interface{})["value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["event"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, redact.String(fmt.Sprint(row)), entry["event"]) + } + }) + } + } +} + +func TestAvroYearParseErrorRedaction(t *testing.T) { + const secret = "invalid-year-secret" + columns := []*model.Column{{Name: "value", Type: mysql.TypeYear, Value: secret}} + tableInfo := model.BuildTableInfo("db", "tbl", columns, nil) + row := &model.RowChangedEvent{TableInfo: tableInfo, Columns: model.Columns2ColumnDatas(columns, tableInfo)} + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureAvroRedactionLogs(t, mode) + encoder := NewAvroEncoder(model.DefaultNamespace, redactionSchemaManager{}, common.NewConfig(config.ProtocolAvro)) + err := encoder.AppendRowChangedEvent(context.Background(), "topic", row, func() {}) + require.Error(t, err) + var numErr *strconv.NumError + require.ErrorAs(t, err, &numErr) + require.Same(t, strconv.ErrSyntax, numErr.Err) + require.Equal(t, "ParseInt", numErr.Func) + require.Equal(t, secret, row.Columns[0].Value) + entry := avroLogEntry(t, output, "avro encoder parse year value failed") + switch mode { + case redact.RedactionModeOff: + require.Equal(t, secret, entry["value"]) + require.Equal(t, secret, numErr.Num) + require.Contains(t, entry["error"], secret) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["value"]) + require.Equal(t, "?", numErr.Num) + require.NotContains(t, output.String(), secret) + require.NotContains(t, err.Error(), secret) + case redact.RedactionModeMarker: + require.Equal(t, "‹"+secret+"›", entry["value"]) + require.Equal(t, "‹"+secret+"›", numErr.Num) + require.Contains(t, entry["error"], "‹"+secret+"›") + } + }) + } +} + +func TestAvroUnknownTypeLogRedaction(t *testing.T) { + const secret = "unknown-avro-type-secret" + columns := []*model.Column{{Name: "value", Type: mysql.TypeUnspecified, Value: secret}} + tableInfo := model.BuildTableInfo("db", "tbl", columns, nil) + input := avroEncodeInput{TableInfo: tableInfo, columns: model.Columns2ColumnDatas(columns, tableInfo)} + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + output := captureAvroRedactionLogs(t, mode) + encoder := NewAvroEncoder(model.DefaultNamespace, nil, common.NewConfig(config.ProtocolAvro)).(*BatchEncoder) + _, err := encoder.columns2AvroData(input) + require.Error(t, err) + entry := avroLogEntry(t, output, "unknown mysql type") + require.Equal(t, float64(mysql.TypeUnspecified), entry["mysqlType"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, secret, entry["value"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["value"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, "‹"+secret+"›", entry["value"]) + } + }) + } +} diff --git a/pkg/sqlmodel/multirow.go b/pkg/sqlmodel/multirow.go index 2a6de0f880..4b26dfefb9 100644 --- a/pkg/sqlmodel/multirow.go +++ b/pkg/sqlmodel/multirow.go @@ -17,6 +17,7 @@ import ( "strings" "github.com/pingcap/log" + "github.com/pingcap/tiflow/pkg/logutil" "github.com/pingcap/tiflow/pkg/quotes" "go.uber.org/zap" ) @@ -183,7 +184,7 @@ func GenUpdateSQL(changes ...*RowChange) (string, []any) { log.Panic("len(whereValues) != len(whereColumns)", zap.Int("len(whereValues)", len(whereValues)), zap.Int("len(whereColumns)", len(whereColumns)), - zap.Any("whereValues", whereValues), + logutil.ZapRedactAny("whereValues", whereValues), zap.Stringer("sourceTable", change.sourceTable)) } diff --git a/pkg/sqlmodel/multirow_redaction_test.go b/pkg/sqlmodel/multirow_redaction_test.go new file mode 100644 index 0000000000..6c94152ffa --- /dev/null +++ b/pkg/sqlmodel/multirow_redaction_test.go @@ -0,0 +1,64 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package sqlmodel + +import ( + "bytes" + "encoding/json" + "testing" + + "github.com/pingcap/errors" + "github.com/pingcap/log" + cdcmodel "github.com/pingcap/tiflow/cdc/model" + "github.com/pingcap/tiflow/pkg/logutil/redact" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func TestGenUpdateSQLInvariantLogRedaction(t *testing.T) { + const secret = "sql-primary-key-secret" + table := &cdcmodel.TableName{Schema: "db", Table: "tbl"} + firstInfo := mockTableInfo(t, "CREATE TABLE tbl (a VARCHAR(64) PRIMARY KEY, b VARCHAR(64))") + secondInfo := mockTableInfo(t, "CREATE TABLE tbl (a VARCHAR(64), b VARCHAR(64), PRIMARY KEY (a, b))") + first := NewRowChange(table, table, []interface{}{"first", "before"}, []interface{}{"first", "after"}, firstInfo, firstInfo, nil) + second := NewRowChange(table, table, []interface{}{secret, "before"}, []interface{}{secret, "after"}, secondInfo, secondInfo, nil) + for _, mode := range []redact.RedactionMode{redact.RedactionModeOff, redact.RedactionModeOn, redact.RedactionModeMarker} { + t.Run(mode.String(), func(t *testing.T) { + originalMode := errors.RedactLogEnabled.Load() + redact.SetRedactionMode(mode) + t.Cleanup(func() { errors.RedactLogEnabled.Store(originalMode) }) + var output bytes.Buffer + core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(&output), zap.DebugLevel) + t.Cleanup(log.ReplaceGlobals(zap.New(core), &log.ZapProperties{Level: zap.NewAtomicLevelAt(zap.DebugLevel)})) + + require.PanicsWithValue(t, "len(whereValues) != len(whereColumns)", func() { GenUpdateSQL(first, second) }) + var entry map[string]interface{} + require.NoError(t, json.Unmarshal(output.Bytes(), &entry)) + require.Equal(t, "len(whereValues) != len(whereColumns)", entry["msg"]) + require.Equal(t, float64(2), entry["len(whereValues)"]) + require.Equal(t, float64(1), entry["len(whereColumns)"]) + switch mode { + case redact.RedactionModeOff: + require.Equal(t, []interface{}{secret, "before"}, entry["whereValues"]) + case redact.RedactionModeOn: + require.Equal(t, "?", entry["whereValues"]) + require.NotContains(t, output.String(), secret) + case redact.RedactionModeMarker: + require.Equal(t, "‹["+secret+" before]›", entry["whereValues"]) + } + }) + } +} diff --git a/tests/integration_tests/log_redaction/conf/changefeed.toml b/tests/integration_tests/log_redaction/conf/changefeed.toml new file mode 100644 index 0000000000..b6ec313883 --- /dev/null +++ b/tests/integration_tests/log_redaction/conf/changefeed.toml @@ -0,0 +1,2 @@ +[filter] +rules = ["log_redaction.*"] diff --git a/tests/integration_tests/log_redaction/run.sh b/tests/integration_tests/log_redaction/run.sh new file mode 100755 index 0000000000..9d7970062f --- /dev/null +++ b/tests/integration_tests/log_redaction/run.sh @@ -0,0 +1,91 @@ +#!/bin/bash + +set -euo pipefail + +CUR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) +source "$CUR/../_utils/test_prepare" +WORK_DIR=$OUT_DIR/$TEST_NAME +CDC_BINARY=cdc.test +SINK_TYPE=$1 + +# This case checks the MySQL sink's parameterized statements and row arguments. +if [ "$SINK_TYPE" != "mysql" ]; then + exit 0 +fi + +function wait_for_row() { + local table=$1 + local i + for ((i = 0; i < 60; i++)); do + if run_sql "SELECT COUNT(*) AS matches FROM log_redaction.$table WHERE id = 1 AND val = 'redaction-secret' AND marked = 'redaction-marker-secret‹sensitive›';" \ + "$DOWN_TIDB_HOST" "$DOWN_TIDB_PORT" && + grep -Fq "matches: 1" "$OUT_DIR/sql_res.$TEST_NAME.txt"; then + return + fi + sleep 1 + done + echo "The original row values were not replicated for mode $table" + return 1 +} + +function check_mode() { + local mode=$1 + local config_value=$2 + local table=rows_$mode + local server_config=$WORK_DIR/server_$mode.toml + local log_file=$WORK_DIR/cdc_$mode.log + local exec_log=$WORK_DIR/exec_$mode.log + local start_ts + printf '[security]\nredact-info-log = %s\n' "$config_value" >"$server_config" + start_ts=$(run_cdc_cli_tso_query "$UP_PD_HOST_1" "$UP_PD_PORT_1") + run_cdc_server --workdir "$WORK_DIR" --binary "$CDC_BINARY" --config "$server_config" --logsuffix "_$mode" + run_cdc_cli changefeed create --changefeed-id="redact-$mode" --start-ts="$start_ts" \ + --sink-uri="mysql://normal:123456@$DOWN_TIDB_HOST:$DOWN_TIDB_PORT/" \ + --config="$CUR/conf/changefeed.toml" + + run_sql "CREATE DATABASE IF NOT EXISTS log_redaction;" "$UP_TIDB_HOST" "$UP_TIDB_PORT" + run_sql "CREATE TABLE log_redaction.$table (id INT PRIMARY KEY, val VARCHAR(64), marked VARCHAR(64)) CHARSET utf8mb4;" \ + "$UP_TIDB_HOST" "$UP_TIDB_PORT" + run_sql "INSERT INTO log_redaction.$table VALUES (1, 'redaction-secret', 'redaction-marker-secret‹sensitive›');" \ + "$UP_TIDB_HOST" "$UP_TIDB_PORT" + check_table_exists "log_redaction.$table" "$DOWN_TIDB_HOST" "$DOWN_TIDB_PORT" + wait_for_row "$table" + + run_cdc_cli changefeed remove --changefeed-id="redact-$mode" + cleanup_process "$CDC_BINARY" + + # Require a real DML entry before testing absence of values. The template + # remains useful for troubleshooting in every mode. + grep -F "exec row" "$log_file" | grep -F "log_redaction" >"$exec_log" + grep -Fq " VALUES " "$exec_log" + grep -Fq "?" "$exec_log" + case "$mode" in + off) + grep -Fq "redaction-secret" "$exec_log" + grep -Fq "redaction-marker-secret‹sensitive›" "$exec_log" + ;; + on) + grep -Fq "[args=?]" "$exec_log" + if grep -Eq "redaction-secret|redaction-marker-secret" "$log_file"; then + echo "Sensitive row values leaked in ON mode" + return 1 + fi + ;; + marker) + grep -Fq '[args="‹[' "$exec_log" + grep -Fq ']›"]' "$exec_log" + grep -Fq "redaction-secret" "$exec_log" + grep -Fq "redaction-marker-secret‹‹sensitive››" "$exec_log" + ;; + esac +} + +trap stop_tidb_cluster EXIT +rm -rf "$WORK_DIR" +mkdir -p "$WORK_DIR" +start_tidb_cluster --workdir "$WORK_DIR" +check_mode off false +check_mode on true +check_mode marker '"MARKER"' +check_logs "$WORK_DIR" +echo "[$(date)] <<<<<< run test case $TEST_NAME success! >>>>>>" diff --git a/tests/integration_tests/run_group.sh b/tests/integration_tests/run_group.sh index dbadaf5926..985db29c25 100755 --- a/tests/integration_tests/run_group.sh +++ b/tests/integration_tests/run_group.sh @@ -11,7 +11,7 @@ group_num=${group#G} # Other tests that only support mysql: batch_update_to_no_batch ddl_reentrant # changefeed_fast_fail changefeed_resume_with_checkpoint_ts sequence # multi_cdc_cluster capture_suicide_while_balance_table -mysql_only="down_db_require_secure_transport bdr_mode capture_suicide_while_balance_table syncpoint syncpoint_check_ts server_config_compatibility changefeed_dup_error_restart safe_mode" +mysql_only="down_db_require_secure_transport bdr_mode capture_suicide_while_balance_table syncpoint syncpoint_check_ts server_config_compatibility changefeed_dup_error_restart safe_mode log_redaction" mysql_only_http="http_api http_api_tls api_v2 http_api_tls_with_user_auth cli_tls_with_auth" mysql_only_consistent_replicate="consistent_replicate_ddl consistent_replicate_gbk consistent_replicate_nfs consistent_replicate_storage_file consistent_replicate_storage_file_large_value consistent_replicate_storage_s3 consistent_partition_table"