Use prefix in all vtorc check and recover logs

[ejortegau]

Description

This is meant to make recovery actions more easily identified from the logs. See #17465

Some examples of recoveries, when running the local example cluster:

Initial recovery for cluster with no primary

I0117 11:19:11.970564  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Starting checkAndRecover
I0117 11:19:11.970622  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with ClusterHasNoPrimary detection on zone1-0000000100; isActionable?: true
I0117 11:19:11.984405  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: Proceeding with ClusterHasNoPrimary recovery on zone1-0000000100 validation after acquiring shard lock.
I0117 11:19:11.985613  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Force refreshing all shard tablets
I0117 11:19:12.002617  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with recovery on zone1-0000000100; isRecoverable?: true
I0117 11:19:12.002932  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: Analysis: ClusterHasNoPrimary, will elect a new primary for commerce:0
W0117 11:19:12.014369  231305 log.go:153] Recovery for ClusterHasNoPrimary on commerce/0: PRS - no replication statue from zone1-0000000101, using empty gtid set
W0117 11:19:12.014626  231305 log.go:153] Recovery for ClusterHasNoPrimary on commerce/0: PRS - no replication statue from zone1-0000000100, using empty gtid set
I0117 11:19:12.970190  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Starting checkAndRecover
I0117 11:19:12.970230  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with ClusterHasNoPrimary detection on zone1-0000000100; isActionable?: true
E0117 11:19:12.971729  231305 log.go:168] Recovery for ClusterHasNoPrimary on commerce/0: Failed to lock shard, aborting recovery: node already exists: lock already exists at path keyspaces/commerce/shards/0
I0117 11:19:13.004532  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Recovery succeeded
I0117 11:19:13.005549  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: Topology recovery: {"ID":1,"AnalysisEntry":{"AnalyzedInstanceAlias":"zone1-0000000100","AnalyzedInstancePrimaryAlias":"\u003cnil\u003e","TabletType":2,"PrimaryTimeStamp":"0001-01-01T00:00:00Z","ClusterDetails":{"Keyspace":"commerce","Shard":"0"},"AnalyzedKeyspace":"commerce","AnalyzedShard":"0","ShardPrimaryTermTimestamp":"","AnalyzedInstanceBinlogCoordinates":{"LogFile":"vt-0000000100-bin.000001","LogPos":157,"Type":0},"IsPrimary":true,"IsClusterPrimary":false,"LastCheckValid":true,"LastCheckPartialSuccess":true,"CountReplicas":0,"CountValidReplicas":0,"CountValidReplicatingReplicas":0,"ReplicationStopped":true,"ErrantGTID":"","ReplicaNetTimeout":0,"HeartbeatInterval":0,"Analysis":"ClusterHasNoPrimary","Description":"Cluster has no primary","StructureAnalysis":["NoWriteablePrimaryStructureWarning"],"OracleGTIDImmediateTopology":false,"BinlogServerImmediateTopology":false,"SemiSyncPrimaryEnabled":false,"SemiSyncPrimaryStatus":false,"SemiSyncPrimaryWaitForReplicaCount":1,"SemiSyncPrimaryClients":0,"SemiSyncReplicaEnabled":false,"CountSemiSyncReplicasEnabled":0,"CountLoggingReplicas":0,"CountStatementBasedLoggingReplicas":0,"CountMixedBasedLoggingReplicas":0,"CountRowBasedLoggingReplicas":0,"CountDistinctMajorVersionsLoggingReplicas":0,"CountDelayedReplicas":0,"CountLaggingReplicas":0,"IsActionableRecovery":true,"RecoveryId":1,"GTIDMode":"ON","MinReplicaGTIDMode":"","MaxReplicaGTIDMode":"","MaxReplicaGTIDErrant":"","IsReadOnly":true},"SuccessorAlias":"zone1-0000000100","IsSuccessful":true,"AllErrors":[],"RecoveryStartTimestamp":"","RecoveryEndTimestamp":"","DetectionID":0}
I0117 11:19:13.005686  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Forcing refresh of all tablets post recovery

Recovering from a stopped MySQL in primary tablet

I0117 11:20:44.971064  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Starting checkAndRecover
I0117 11:20:44.971142  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with DeadPrimary detection on zone1-0000000100; isActionable?: true
I0117 11:20:44.983679  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: Proceeding with DeadPrimary recovery on zone1-0000000100 validation after acquiring shard lock.
I0117 11:20:44.984512  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Force refreshing all shard tablets
I0117 11:20:44.996572  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with recovery on zone1-0000000100; isRecoverable?: true
I0117 11:20:44.996823  231305 log.go:138] Recovery for DeadPrimary on commerce/0: Analysis: DeadPrimary, RecoverDeadPrimary zone1-0000000100
I0117 11:20:44.997167  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - will initiate emergency reparent shard in keyspace - commerce, shard - 0
I0117 11:20:44.997934  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - Getting a new durability policy for semi_sync
I0117 11:20:45.000444  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000101
I0117 11:20:45.000465  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000102
I0117 11:20:45.000463  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000100
W0117 11:20:45.002324  231305 log.go:153] Recovery for DeadPrimary on commerce/0: ERS - failed to get replication status from zone1-0000000100: rpc error: code = Unknown desc = TabletManager.StopReplicationAndGetStatus on zone1-0000000100: before status failed: net.Dial(/home/eduardo.ortega/vitess_sandbox/v22-dev/examples/local/vtdataroot/vt_0000000100/mysql.sock) to local server failed: dial unix /home/eduardo.ortega/vitess_sandbox/v22-dev/examples/local/vtdataroot/vt_0000000100/mysql.sock: connect: no such file or directory (errno 2002) (sqlstate HY000)
I0117 11:20:45.006592  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - started finding the intermediate source
I0117 11:20:45.006785  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - finding intermediate source - sorted replica: cell:"zone1"  uid:102
I0117 11:20:45.006887  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - finding intermediate source - sorted replica: cell:"zone1"  uid:101
I0117 11:20:45.006991  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - intermediate source selected - cell:"zone1"  uid:102
I0117 11:20:45.007065  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - found better candidate - cell:"zone1"  uid:102
I0117 11:20:45.007129  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - intermediate source is ideal candidate- true
I0117 11:20:45.007516  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - starting promotion for the new primary - zone1-0000000102
I0117 11:20:45.007552  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - setting new primary on replica zone1-0000000100
I0117 11:20:45.007560  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - setting new primary on replica zone1-0000000101
I0117 11:20:45.074764  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - populating reparent journal on new primary zone1-0000000102
I0117 11:20:45.080035  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Recovery succeeded
I0117 11:20:45.080105  231305 log.go:138] Recovery for DeadPrimary on commerce/0: Topology recovery: {"ID":6,"AnalysisEntry":{"AnalyzedInstanceAlias":"zone1-0000000100","AnalyzedInstancePrimaryAlias":"\u003cnil\u003e","TabletType":1,"PrimaryTimeStamp":"0001-01-01T00:00:00Z","ClusterDetails":{"Keyspace":"commerce","Shard":"0"},"AnalyzedKeyspace":"commerce","AnalyzedShard":"0","ShardPrimaryTermTimestamp":"2025-01-17 10:19:12.022420359 +0000 UTC","AnalyzedInstanceBinlogCoordinates":{"LogFile":"vt-0000000100-bin.000001","LogPos":18489,"Type":0},"IsPrimary":true,"IsClusterPrimary":true,"LastCheckValid":false,"LastCheckPartialSuccess":false,"CountReplicas":2,"CountValidReplicas":2,"CountValidReplicatingReplicas":0,"ReplicationStopped":true,"ErrantGTID":"","ReplicaNetTimeout":0,"HeartbeatInterval":0,"Analysis":"DeadPrimary","Description":"Primary cannot be reached by vtorc and none of its replicas is replicating","StructureAnalysis":null,"OracleGTIDImmediateTopology":true,"BinlogServerImmediateTopology":false,"SemiSyncPrimaryEnabled":true,"SemiSyncPrimaryStatus":true,"SemiSyncPrimaryWaitForReplicaCount":1,"SemiSyncPrimaryClients":2,"SemiSyncReplicaEnabled":true,"CountSemiSyncReplicasEnabled":2,"CountLoggingReplicas":2,"CountStatementBasedLoggingReplicas":0,"CountMixedBasedLoggingReplicas":0,"CountRowBasedLoggingReplicas":2,"CountDistinctMajorVersionsLoggingReplicas":1,"CountDelayedReplicas":0,"CountLaggingReplicas":0,"IsActionableRecovery":true,"RecoveryId":19,"GTIDMode":"ON","MinReplicaGTIDMode":"ON","MaxReplicaGTIDMode":"ON","MaxReplicaGTIDErrant":"","IsReadOnly":false},"SuccessorAlias":"zone1-0000000102","IsSuccessful":true,"AllErrors":[],"RecoveryStartTimestamp":"","RecoveryEndTimestamp":"","DetectionID":0}
I0117 11:20:45.080127  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Forcing refresh of all tablets post recovery

Related Issue(s)

#17465

Checklist

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

Deployment Notes

n/a

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[codecov]

Codecov Report

Attention: Patch coverage is 0% with 140 lines in your changes missing coverage. Please review.

Project coverage is 67.67%. Comparing base (5468f5d) to head (ee34454).
Report is 3 commits behind head on main.

Files with missing lines	Patch %	Lines
go/vt/vtorc/logic/topology_recovery.go	0.00%	89 Missing ⚠️
go/vt/log/log.go	0.00%	51 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #17526      +/-   ##
==========================================
- Coverage   67.70%   67.67%   -0.04%     
==========================================
  Files        1584     1585       +1     
  Lines      254718   254905     +187     
==========================================
+ Hits       172463   172508      +45     
- Misses      82255    82397     +142     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[timvaillancourt]

@ejortegau is it possible to get a sanitized example of what this looks like?

[ejortegau]

is it possible to get a sanitized example of what this looks like?

@timvaillancourt , Added them in the PR's description.