percona/percona-toolkit
1
0
Fork 0
mirror of https://github.com/percona/percona-toolkit.git synced 2025-09-12 14:18:32 +00:00
Code Issues Packages Projects Releases Wiki Activity

Add: concurrent SSTs handling

Browse Source 
It is a thing: 2 nodes joining at the same time, with 2 JOINERs and 2
DONORs cluster-wide
It can happen on operators with 2 garbd joining at the same time

Before, pt-galera-log-explainer was using SST metadata naively.
Basically if a node was DONOR and we found a "transfer completed"
message, we assumed the donor name we found is the correct one.
So for concurrent SSTs, donors were swapping names.

Now, it is handled by a map, indexed by a donor name. To know if a node
is actual donor or not, it now compare timestamps of events. It assumes
both "selected donor" and "shifting DONOR" messages should have happen
in less than 0.01 secs to avoid any conflict.

Regression tests coming in next commit with an operator logs having
concurrent SSTs. Another conflicts was sometimes breaking the test
depending on the order on which we read files, hence why it's not added
here yet
This commit is contained in:
Yoann La Cancellera
2023-10-16 10:51:39 +02:00
parent 117d683872
commit 208708a58b
10 changed files with 312 additions and 185 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
src/go/pt-galera-log-explainer/regex/regex.go
View File

@@ -61,7 +61,7 @@ var (
regexSeqno = "(?P<" + groupSeqno + ">[0-9]+)"
regexNodeIP = "(?P<" + groupNodeIP + ">[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3})"
regexNodeIPMethod = "(?P<" + groupMethod + ">.+)://" + regexNodeIP + ":[0-9]{1,6}"
regexIdx = "(?P<" + groupIdx + ">-?[0-9]{1,2})"
regexIdx = "(?P<" + groupIdx + ">-?[0-9]{1,2})(\\.-?[0-9])?"
regexVersion = "(?P<" + groupVersion + ">(5|8|10|11)\\.[0-9]\\.[0-9]{1,2})"
regexErrorMD5 = "(?P<" + groupErrorMD5 + ">[a-z0-9]*)"
)

172
src/go/pt-galera-log-explainer/regex/regex_test.go
View File

@@ -4,6 +4,7 @@ import (
"io/ioutil"
"os/exec"
"testing"
"time"
"github.com/davecgh/go-spew/spew"
"github.com/google/go-cmp/cmp"
@@ -740,8 +741,8 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Member 2.0 (node2) requested state transfer from '*any*'. Selected 0.0 (node1)(SYNCED) as donor.",
inputCtx: types.LogCtx{},
expectedCtx: types.LogCtx{},
inputCtx: types.LogCtx{SSTs: map[string]types.SST{}},
expectedCtx: types.LogCtx{SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", SelectionTimestamp: timeMustParse("2001-01-01T01:01:01.000000Z")}}},
expectedOut: "node1 will resync node2",
mapToTest: SSTMap,
key: "RegexSSTRequestSuccess",
@@ -749,8 +750,8 @@ func TestRegexes(t *testing.T) {
{
name: "with fqdn",
log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 2.0 (node2.host.com) requested state transfer from '*any*'. Selected 0.0 (node1.host.com)(SYNCED) as donor.",
inputCtx: types.LogCtx{},
expectedCtx: types.LogCtx{},
inputCtx: types.LogCtx{SSTs: map[string]types.SST{}},
expectedCtx: types.LogCtx{SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", SelectionTimestamp: timeMustParse("2001-01-01T01:01:01.000000Z")}}},
expectedOut: "node1 will resync node2",
mapToTest: SSTMap,
key: "RegexSSTRequestSuccess",
@@ -760,10 +761,11 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Member 2.0 (node2) requested state transfer from '*any*'. Selected 0.0 (node1)(SYNCED) as donor.",
inputCtx: types.LogCtx{
OwnNames: []string{"node2"},
SSTs: map[string]types.SST{},
},
expectedCtx: types.LogCtx{
OwnNames: []string{"node2"},
SST: types.SST{ResyncedFromNode: "node1"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", SelectionTimestamp: timeMustParse("2001-01-01T01:01:01.000000Z")}},
},
expectedOut: "node1 will resync local node",
mapToTest: SSTMap,
@@ -774,10 +776,11 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Member 2.0 (node2) requested state transfer from '*any*'. Selected 0.0 (node1)(SYNCED) as donor.",
inputCtx: types.LogCtx{
OwnNames: []string{"node1"},
SSTs: map[string]types.SST{},
},
expectedCtx: types.LogCtx{
OwnNames: []string{"node1"},
SST: types.SST{ResyncingNode: "node2"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", SelectionTimestamp: timeMustParse("2001-01-01T01:01:01.000000Z")}},
},
expectedOut: "local node will resync node2",
mapToTest: SSTMap,
@@ -808,8 +811,12 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{},
expectedCtx: types.LogCtx{},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{},
},
expectedOut: "node1 synced node2",
mapToTest: SSTMap,
key: "RegexSSTComplete",
@@ -819,10 +826,10 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
OwnNames: []string{"node2"},
SST: types.SST{ResyncedFromNode: "node1"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncedFromNode: ""},
SSTs: map[string]types.SST{},
OwnNames: []string{"node2"},
},
expectedOut: "got SST from node1",
@@ -834,10 +841,10 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
OwnNames: []string{"node2"},
SST: types.SST{ResyncedFromNode: "node1", Type: "IST"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncedFromNode: "", Type: ""},
SSTs: map[string]types.SST{},
OwnNames: []string{"node2"},
},
expectedOut: "got IST from node1",
@@ -849,10 +856,10 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
OwnNames: []string{"node1"},
SST: types.SST{ResyncingNode: "node2"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncingNode: ""},
SSTs: map[string]types.SST{},
OwnNames: []string{"node1"},
},
expectedOut: "finished sending SST to node2",
@@ -864,48 +871,16 @@ func TestRegexes(t *testing.T) {
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
OwnNames: []string{"node1"},
SST: types.SST{ResyncingNode: "node2", Type: "IST"},
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncingNode: "", Type: ""},
SSTs: map[string]types.SST{},
OwnNames: []string{"node1"},
},
expectedOut: "finished sending IST to node2",
mapToTest: SSTMap,
key: "RegexSSTComplete",
},
{
name: "with donor name",
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
SST: types.SST{ResyncingNode: "node2", Type: "IST"},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncingNode: "", Type: ""},
OwnNames: []string{"node1"},
},
inputState: "DONOR",
expectedState: "DONOR",
expectedOut: "finished sending IST to node2",
mapToTest: SSTMap,
key: "RegexSSTComplete",
},
{
name: "with joiner name",
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to 2.0 (node2) complete.",
inputCtx: types.LogCtx{
SST: types.SST{ResyncingNode: "node2", Type: "IST"},
},
expectedCtx: types.LogCtx{
SST: types.SST{ResyncingNode: "", Type: ""},
OwnNames: []string{"node2"},
},
inputState: "JOINER",
expectedState: "JOINER",
expectedOut: "got IST from node1",
mapToTest: SSTMap,
key: "RegexSSTComplete",
},
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: 0.0 (node1): State transfer to -1.-1 (left the group) complete.",
@@ -932,7 +907,14 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z WSREP_SST: [INFO] Proceeding with SST.........",
expectedCtx: types.LogCtx{SST: types.SST{Type: "SST"}},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "SST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "receiving SST",
mapToTest: SSTMap,
@@ -941,7 +923,6 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z WSREP_SST: [INFO] Streaming the backup to joiner at 172.17.0.2 4444",
expectedCtx: types.LogCtx{SST: types.SST{ResyncingNode: "172.17.0.2"}},
expectedState: "DONOR",
expectedOut: "SST to 172.17.0.2",
mapToTest: SSTMap,
@@ -958,7 +939,14 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01 1:01:01 140433613571840 [Note] WSREP: async IST sender starting to serve tcp://172.17.0.2:4568 sending 2-116",
expectedCtx: types.LogCtx{SST: types.SST{Type: "IST"}},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node1"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
OwnNames: []string{"node1"},
},
expectedState: "DONOR",
expectedOut: "IST to 172.17.0.2(seqno:116)",
mapToTest: SSTMap,
@@ -967,7 +955,14 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Prepared IST receiver for 114-116, listening at: ssl://172.17.0.2:4568",
expectedCtx: types.LogCtx{SST: types.SST{Type: "IST"}},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "will receive IST(seqno:116)",
mapToTest: SSTMap,
@@ -975,7 +970,14 @@ func TestRegexes(t *testing.T) {
},
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Prepared IST receiver for 0-116, listening at: ssl://172.17.0.2:4568",
expectedCtx: types.LogCtx{SST: types.SST{Type: "SST"}},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "SST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "will receive SST",
mapToTest: SSTMap,
@@ -984,7 +986,14 @@ func TestRegexes(t *testing.T) {
{
name: "mdb variant",
log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Prepared IST receiver, listening at: ssl://172.17.0.2:4568",
expectedCtx: types.LogCtx{SST: types.SST{Type: "IST"}},
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "will receive IST",
mapToTest: SSTMap,
@@ -1013,14 +1022,32 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z 1 [Note] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (ed16c932-84b3-11ed-998c-8e3ae5bc328f): 1 (Operation not permitted)",
expectedCtx: types.LogCtx{SST: types.SST{Type: "SST"}},
inputState: "JOINER",
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "SST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "IST is not applicable",
mapToTest: SSTMap,
key: "RegexFailedToPrepareIST",
},
{
log: "2001-01-01T01:01:01.000000Z 1 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state seqno is undefined: 1 (Operation not permitted)",
expectedCtx: types.LogCtx{SST: types.SST{Type: "SST"}},
inputState: "JOINER",
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "SST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "IST is not applicable",
mapToTest: SSTMap,
key: "RegexFailedToPrepareIST",
@@ -1028,12 +1055,38 @@ func TestRegexes(t *testing.T) {
{
log: "2001-01-01T01:01:01.000000Z WSREP_SST: [INFO] Bypassing SST. Can work it through IST",
expectedCtx: types.LogCtx{SST: types.SST{Type: "IST"}},
inputState: "JOINER",
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "IST will be used",
mapToTest: SSTMap,
key: "RegexBypassSST",
},
{
log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [WSREP-SST] xtrabackup_ist received from donor: Running IST",
inputState: "JOINER",
inputCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2"}},
OwnNames: []string{"node2"},
},
expectedCtx: types.LogCtx{
SSTs: map[string]types.SST{"node1": types.SST{Donor: "node1", Joiner: "node2", Type: "IST"}},
OwnNames: []string{"node2"},
},
expectedState: "JOINER",
expectedOut: "IST running",
mapToTest: SSTMap,
key: "RegexXtrabackupISTReceived",
},
{
log: "2001/01/01 01:01:01 socat[23579] E connect(62, AF=2 172.17.0.20:4444, 16): Connection refused",
expectedOut: "socat: connection refused",
@@ -1256,6 +1309,11 @@ func TestRegexes(t *testing.T) {
}
}
func timeMustParse(s string) *time.Time {
t, _, _ := SearchDateFromLog(s)
return &t
}
func testRegexFromMap(t *testing.T, log string, regex *types.LogRegex) error {
m := types.RegexMap{"test": regex}

94
src/go/pt-galera-log-explainer/regex/sst.go
View File

@@ -15,18 +15,26 @@ var SSTMap = types.RegexMap{
// TODO: requested state from unknown node
"RegexSSTRequestSuccess": &types.LogRegex{
Regex: regexp.MustCompile("requested state transfer.*Selected"),
InternalRegex: regexp.MustCompile("Member .* \\(" + regexNodeName + "\\) requested state transfer.*Selected .* \\(" + regexNodeName2 + "\\)\\("),
InternalRegex: regexp.MustCompile("Member " + regexIdx + " \\(" + regexNodeName + "\\) requested state transfer.*Selected " + regexIdx + " \\(" + regexNodeName2 + "\\)\\("),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
joiner := utils.ShortNodeName(submatches[groupNodeName])
donor := utils.ShortNodeName(submatches[groupNodeName2])
if utils.SliceContains(ctx.OwnNames, joiner) {
ctx.SST.ResyncedFromNode = donor
sst := types.SST{
Donor: donor,
Joiner: joiner,
}
if utils.SliceContains(ctx.OwnNames, donor) {
ctx.SST.ResyncingNode = joiner
// here this is a limitation of the handler signature
// this is the only case when resorting to timestamps is necessary
selectionTimestamp, _, ok := SearchDateFromLog(log)
if ok {
sst.SelectionTimestamp = &selectionTimestamp
}
ctx.SSTs[donor] = sst
return ctx, func(ctx types.LogCtx) string {
if utils.SliceContains(ctx.OwnNames, joiner) {
return donor + utils.Paint(utils.GreenText, " will resync local node")
@@ -58,18 +66,16 @@ var SSTMap = types.RegexMap{
// 2022-12-24T03:28:22.444125Z 0 [Note] WSREP: 0.0 (name): State transfer to 2.0 (name2) complete.
"RegexSSTComplete": &types.LogRegex{
Regex: regexp.MustCompile("State transfer to.*complete"),
InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\): State transfer.*\\(" + regexNodeName2 + "\\) complete"),
InternalRegex: regexp.MustCompile(regexIdx + " \\(" + regexNodeName + "\\): State transfer to " + regexIdx + " \\(" + regexNodeName2 + "\\) complete"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
donor := utils.ShortNodeName(submatches[groupNodeName])
joiner := utils.ShortNodeName(submatches[groupNodeName2])
displayType := "SST"
if ctx.SST.Type != "" {
displayType = ctx.SST.Type
if ctx.SSTs[donor].Type != "" {
displayType = ctx.SSTs[donor].Type
}
ctx.SST.Reset()
ctx = addOwnNameWithSSTMetadata(ctx, joiner, donor)
delete(ctx.SSTs, donor)
return ctx, func(ctx types.LogCtx) string {
if utils.SliceContains(ctx.OwnNames, joiner) {
@@ -88,34 +94,34 @@ var SSTMap = types.RegexMap{
// 2022-12-24T03:27:41.966118Z 0 [Note] WSREP: 0.0 (name): State transfer to -1.-1 (left the group) complete.
"RegexSSTCompleteUnknown": &types.LogRegex{
Regex: regexp.MustCompile("State transfer to.*left the group.*complete"),
InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\): State transfer.*\\(left the group\\) complete"),
InternalRegex: regexp.MustCompile(regexIdx + " \\(" + regexNodeName + "\\): State transfer.*\\(left the group\\) complete"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
donor := utils.ShortNodeName(submatches[groupNodeName])
ctx = addOwnNameWithSSTMetadata(ctx, "", donor)
delete(ctx.SSTs, donor)
return ctx, types.SimpleDisplayer(donor + utils.Paint(utils.RedText, " synced ??(node left)"))
},
},
"RegexSSTFailedUnknown": &types.LogRegex{
Regex: regexp.MustCompile("State transfer to.*left the group.*failed"),
InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\): State transfer.*\\(left the group\\) failed"),
InternalRegex: regexp.MustCompile(regexIdx + " \\(" + regexNodeName + "\\): State transfer.*\\(left the group\\) failed"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
donor := utils.ShortNodeName(submatches[groupNodeName])
ctx = addOwnNameWithSSTMetadata(ctx, "", donor)
delete(ctx.SSTs, donor)
return ctx, types.SimpleDisplayer(donor + utils.Paint(utils.RedText, " failed to sync ??(node left)"))
},
},
"RegexSSTStateTransferFailed": &types.LogRegex{
Regex: regexp.MustCompile("State transfer to.*failed:"),
InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\): State transfer.*\\(" + regexNodeName2 + "\\) failed"),
InternalRegex: regexp.MustCompile(regexIdx + " \\(" + regexNodeName + "\\): State transfer to " + regexIdx + " \\(" + regexNodeName2 + "\\) failed"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
donor := utils.ShortNodeName(submatches[groupNodeName])
joiner := utils.ShortNodeName(submatches[groupNodeName2])
ctx = addOwnNameWithSSTMetadata(ctx, joiner, donor)
delete(ctx.SSTs, donor)
return ctx, types.SimpleDisplayer(donor + utils.Paint(utils.RedText, " failed to sync ") + joiner)
},
},
@@ -128,6 +134,15 @@ var SSTMap = types.RegexMap{
},
},
"RegexSSTInitiating": &types.LogRegex{
Regex: regexp.MustCompile("Initiating SST.IST transfer on DONOR side"),
InternalRegex: regexp.MustCompile("DONOR side \\((?P<scriptname>[a-zA-Z0-9-_]*) --role 'donor' --address '" + regexNodeIP + ":(?P<sstport>[0-9]*)\\)"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
return ctx, types.SimpleDisplayer("init sst using " + submatches["scriptname"])
},
},
"RegexSSTCancellation": &types.LogRegex{
Regex: regexp.MustCompile("Initiating SST cancellation"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
@@ -140,7 +155,7 @@ var SSTMap = types.RegexMap{
Regex: regexp.MustCompile("Proceeding with SST"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SetState("JOINER")
ctx.SST.Type = "SST"
ctx.SetSSTTypeMaybe("SST")
return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "receiving SST"))
},
@@ -152,13 +167,10 @@ var SSTMap = types.RegexMap{
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SetState("DONOR")
node := submatches[groupNodeIP]
if ctx.SST.ResyncingNode == "" { // we should already have something at this point
ctx.SST.ResyncingNode = node
}
joiner := submatches[groupNodeIP]
return ctx, func(ctx types.LogCtx) string {
return utils.Paint(utils.YellowText, "SST to ") + types.DisplayNodeSimplestForm(ctx, node)
return utils.Paint(utils.YellowText, "SST to ") + types.DisplayNodeSimplestForm(ctx, joiner)
}
},
},
@@ -181,8 +193,8 @@ var SSTMap = types.RegexMap{
// TODO: sometimes, it's a hostname here
InternalRegex: regexp.MustCompile("IST sender starting to serve " + regexNodeIPMethod + " sending [0-9]+-" + regexSeqno),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SST.Type = "IST"
ctx.SetState("DONOR")
ctx.SetSSTTypeMaybe("IST")
seqno := submatches[groupSeqno]
node := submatches[groupNodeIP]
@@ -206,13 +218,13 @@ var SSTMap = types.RegexMap{
startingseqno := submatches["startingseqno"]
// if it's 0, it will go to SST without a doubt
if startingseqno == "0" {
ctx.SST.Type = "SST"
ctx.SetSSTTypeMaybe("SST")
msg += "SST"
// not totally correct, but need more logs to get proper pattern
// in some cases it does IST before going with SST
} else {
ctx.SST.Type = "IST"
ctx.SetSSTTypeMaybe("IST")
msg += "IST"
if seqno != "" {
msg += "(seqno:" + seqno + ")"
@@ -225,16 +237,25 @@ var SSTMap = types.RegexMap{
"RegexFailedToPrepareIST": &types.LogRegex{
Regex: regexp.MustCompile("Failed to prepare for incremental state transfer"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SST.Type = "SST"
ctx.SetSSTTypeMaybe("SST")
return ctx, types.SimpleDisplayer("IST is not applicable")
},
},
"RegexXtrabackupISTReceived": &types.LogRegex{
Regex: regexp.MustCompile("xtrabackup_ist received from donor"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SetSSTTypeMaybe("IST")
return ctx, types.SimpleDisplayer("IST running")
},
Verbosity: types.DebugMySQL, // that one is not really helpful, except for tooling constraints
},
// could not find production examples yet, but it did exist in older version there also was "Bypassing state dump"
"RegexBypassSST": &types.LogRegex{
Regex: regexp.MustCompile("Bypassing SST"),
Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SST.Type = "IST"
ctx.SetSSTTypeMaybe("IST")
return ctx, types.SimpleDisplayer("IST will be used")
},
},
@@ -283,24 +304,7 @@ var SSTMap = types.RegexMap{
},
}
func addOwnNameWithSSTMetadata(ctx types.LogCtx, joiner, donor string) types.LogCtx {
var nameToAdd string
if ctx.State() == "JOINER" && joiner != "" {
nameToAdd = joiner
}
if ctx.State() == "DONOR" && donor != "" {
nameToAdd = donor
}
if nameToAdd != "" {
ctx.AddOwnName(nameToAdd)
}
return ctx
}
/*
2023-06-07T02:42:29.734960-06:00 0 [ERROR] WSREP: sst sent called when not SST donor, state SYNCED
2023-06-07T02:42:00.234711-06:00 0 [Warning] WSREP: Protocol violation. JOIN message sender 0.0 (node1) is not in state transfer (SYNCED). Message ignored.

11
src/go/pt-galera-log-explainer/regex/states.go
View File

@@ -14,7 +14,16 @@ func init() {
var (
shiftFunc = func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) {
ctx.SetState(submatches["state2"])
newState := submatches["state2"]
ctx.SetState(newState)
if newState == "DONOR" || newState == "JOINER" {
shiftTimestamp, _, ok := SearchDateFromLog(log)
if ok {
ctx.ConfirmSSTMetadata(shiftTimestamp)
}
}
log = utils.PaintForState(submatches["state1"], submatches["state1"]) + " -> " + utils.PaintForState(submatches["state2"], submatches["state2"])
return ctx, types.SimpleDisplayer(log)

18
src/go/pt-galera-log-explainer/tests/expected/upgrade_list_all
View File

@@ -1,7 +1,7 @@
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28
2023-03-12T07:24:13.733958Z | starting(5.7.40) |
@@ -225,7 +225,7 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:35:07.638676Z will receive IST(seqno:178226774) |  | 
2023-03-12T19:35:07.644560Z |  |  local node will resync node1
2023-03-12T19:35:07.644570Z |  |  SYNCED -> DONOR
2023-03-12T19:35:07.644668Z node3 will resync node1 |  | 
2023-03-12T19:35:07.644668Z node3 will resync local node |  | 
2023-03-12T19:35:07.644683Z PRIMARY -> JOINER |  | 
2023-03-12T19:35:07.644740Z |  node3 will resync node1 | 
2023-03-12T19:36:48.567087Z timeout from donor in gtid/keyring stage |  | 
@@ -259,16 +259,16 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:43:18.130916Z OPEN -> PRIMARY |  | 
2023-03-12T19:43:18.904410Z will receive IST(seqno:178226792) |  | 
2023-03-12T19:43:18.913328Z |  |  node1 cannot find donor
2023-03-12T19:43:18.913429Z node1 cannot find donor |  | 
2023-03-12T19:43:18.913429Z cannot find donor |  | 
2023-03-12T19:43:18.913565Z |  node1 cannot find donor | 
2023-03-12T19:43:19.914122Z |  |  node1 cannot find donor
2023-03-12T19:43:19.914259Z node1 cannot find donor |  | 
2023-03-12T19:43:19.914259Z cannot find donor |  | 
2023-03-12T19:43:19.914362Z |  node1 cannot find donor | 
2023-03-12T19:43:20.914957Z |  |  (repeated x97)node1 cannot find donor
2023-03-12T19:43:20.915143Z (repeated x97)node1 cannot find donor |  | 
2023-03-12T19:43:20.915143Z (repeated x97)cannot find donor |  | 
2023-03-12T19:43:20.915262Z |  (repeated x97)node1 cannot find donor | 
2023-03-12T19:44:58.999603Z |  |  node1 cannot find donor
2023-03-12T19:44:58.999791Z node1 cannot find donor |  | 
2023-03-12T19:44:58.999791Z cannot find donor |  | 
2023-03-12T19:44:58.999891Z |  node1 cannot find donor | 
2023-03-12T19:44:59.817822Z timeout from donor in gtid/keyring stage |  | 
2023-03-12T19:44:59.839692Z SST error |  | 
@@ -318,8 +318,8 @@ mysql version 8.0.28 8.0.28
2023-03-12T22:00:28.094664Z |  |  node2 left
2023-03-12T22:00:28.094708Z |  |  PRIMARY(n=1)
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28

18
src/go/pt-galera-log-explainer/tests/expected/upgrade_list_all_no_color
View File

@@ -1,7 +1,7 @@
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28
2023-03-12T07:24:13.733958Z | starting(5.7.40) |
@@ -225,7 +225,7 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:35:07.638676Z will receive IST(seqno:178226774) | |
2023-03-12T19:35:07.644560Z | | local node will resync node1
2023-03-12T19:35:07.644570Z | | SYNCED -> DONOR
2023-03-12T19:35:07.644668Z node3 will resync node1 | |
2023-03-12T19:35:07.644668Z node3 will resync local node | |
2023-03-12T19:35:07.644683Z PRIMARY -> JOINER | |
2023-03-12T19:35:07.644740Z | node3 will resync node1 |
2023-03-12T19:36:48.567087Z timeout from donor in gtid/keyring stage | |
@@ -259,16 +259,16 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:43:18.130916Z OPEN -> PRIMARY | |
2023-03-12T19:43:18.904410Z will receive IST(seqno:178226792) | |
2023-03-12T19:43:18.913328Z | | node1 cannot find donor
2023-03-12T19:43:18.913429Z node1 cannot find donor | |
2023-03-12T19:43:18.913429Z cannot find donor | |
2023-03-12T19:43:18.913565Z | node1 cannot find donor |
2023-03-12T19:43:19.914122Z | | node1 cannot find donor
2023-03-12T19:43:19.914259Z node1 cannot find donor | |
2023-03-12T19:43:19.914259Z cannot find donor | |
2023-03-12T19:43:19.914362Z | node1 cannot find donor |
2023-03-12T19:43:20.914957Z | | (repeated x97)node1 cannot find donor
2023-03-12T19:43:20.915143Z (repeated x97)node1 cannot find donor | |
2023-03-12T19:43:20.915143Z (repeated x97)cannot find donor | |
2023-03-12T19:43:20.915262Z | (repeated x97)node1 cannot find donor |
2023-03-12T19:44:58.999603Z | | node1 cannot find donor
2023-03-12T19:44:58.999791Z node1 cannot find donor | |
2023-03-12T19:44:58.999791Z cannot find donor | |
2023-03-12T19:44:58.999891Z | node1 cannot find donor |
2023-03-12T19:44:59.817822Z timeout from donor in gtid/keyring stage | |
2023-03-12T19:44:59.839692Z SST error | |
@@ -318,8 +318,8 @@ mysql version 8.0.28 8.0.28
2023-03-12T22:00:28.094664Z | | node2 left
2023-03-12T22:00:28.094708Z | | PRIMARY(n=1)
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28

18
src/go/pt-galera-log-explainer/tests/expected/upgrade_list_all_since
View File

@@ -1,7 +1,7 @@
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28
2023-03-12T13:13:14.886853Z | got SST from node3 |
@@ -28,7 +28,7 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:35:07.638676Z will receive IST(seqno:178226774) |  | 
2023-03-12T19:35:07.644560Z |  |  local node will resync node1
2023-03-12T19:35:07.644570Z |  |  SYNCED -> DONOR
2023-03-12T19:35:07.644668Z node3 will resync node1 |  | 
2023-03-12T19:35:07.644668Z node3 will resync local node |  | 
2023-03-12T19:35:07.644683Z PRIMARY -> JOINER |  | 
2023-03-12T19:35:07.644740Z |  node3 will resync node1 | 
2023-03-12T19:36:48.567087Z timeout from donor in gtid/keyring stage |  | 
@@ -62,16 +62,16 @@ mysql version 8.0.28 8.0.28
2023-03-12T19:43:18.130916Z OPEN -> PRIMARY |  | 
2023-03-12T19:43:18.904410Z will receive IST(seqno:178226792) |  | 
2023-03-12T19:43:18.913328Z |  |  node1 cannot find donor
2023-03-12T19:43:18.913429Z node1 cannot find donor |  | 
2023-03-12T19:43:18.913429Z cannot find donor |  | 
2023-03-12T19:43:18.913565Z |  node1 cannot find donor | 
2023-03-12T19:43:19.914122Z |  |  node1 cannot find donor
2023-03-12T19:43:19.914259Z node1 cannot find donor |  | 
2023-03-12T19:43:19.914259Z cannot find donor |  | 
2023-03-12T19:43:19.914362Z |  node1 cannot find donor | 
2023-03-12T19:43:20.914957Z |  |  (repeated x97)node1 cannot find donor
2023-03-12T19:43:20.915143Z (repeated x97)node1 cannot find donor |  | 
2023-03-12T19:43:20.915143Z (repeated x97)cannot find donor |  | 
2023-03-12T19:43:20.915262Z |  (repeated x97)node1 cannot find donor | 
2023-03-12T19:44:58.999603Z |  |  node1 cannot find donor
2023-03-12T19:44:58.999791Z node1 cannot find donor |  | 
2023-03-12T19:44:58.999791Z cannot find donor |  | 
2023-03-12T19:44:58.999891Z |  node1 cannot find donor | 
2023-03-12T19:44:59.817822Z timeout from donor in gtid/keyring stage |  | 
2023-03-12T19:44:59.839692Z SST error |  | 
@@ -121,8 +121,8 @@ mysql version 8.0.28 8.0.28
2023-03-12T22:00:28.094664Z |  |  node2 left
2023-03-12T22:00:28.094708Z |  |  PRIMARY(n=1)
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28

18
src/go/pt-galera-log-explainer/tests/expected/upgrade_list_sst
View File

@@ -1,7 +1,7 @@
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28
5.7.40
@@ -42,23 +42,23 @@ mysql version 8.0.28 8.0.28
2023-03-12T13:13:19.156722Z | IST received(seqno:170407338) | 
2023-03-12T19:35:07.638676Z will receive IST(seqno:178226774) |  | 
2023-03-12T19:35:07.644560Z |  |  local node will resync node1
2023-03-12T19:35:07.644668Z node3 will resync node1 |  | 
2023-03-12T19:35:07.644668Z node3 will resync local node |  | 
2023-03-12T19:35:07.644740Z |  node3 will resync node1 | 
2023-03-12T19:36:48.567087Z timeout from donor in gtid/keyring stage |  | 
2023-03-12T19:36:48.589084Z SST error |  | 
2023-03-12T19:36:48.590647Z former SST cancelled |  | 
2023-03-12T19:43:18.904410Z will receive IST(seqno:178226792) |  | 
2023-03-12T19:43:18.913328Z |  |  node1 cannot find donor
2023-03-12T19:43:18.913429Z node1 cannot find donor |  | 
2023-03-12T19:43:18.913429Z cannot find donor |  | 
2023-03-12T19:43:18.913565Z |  node1 cannot find donor | 
2023-03-12T19:43:19.914122Z |  |  node1 cannot find donor
2023-03-12T19:43:19.914259Z node1 cannot find donor |  | 
2023-03-12T19:43:19.914259Z cannot find donor |  | 
2023-03-12T19:43:19.914362Z |  node1 cannot find donor | 
2023-03-12T19:43:20.914957Z |  |  (repeated x97)node1 cannot find donor
2023-03-12T19:43:20.915143Z (repeated x97)node1 cannot find donor |  | 
2023-03-12T19:43:20.915143Z (repeated x97)cannot find donor |  | 
2023-03-12T19:43:20.915262Z |  (repeated x97)node1 cannot find donor | 
2023-03-12T19:44:58.999603Z |  |  node1 cannot find donor
2023-03-12T19:44:58.999791Z node1 cannot find donor |  | 
2023-03-12T19:44:58.999791Z cannot find donor |  | 
2023-03-12T19:44:58.999891Z |  node1 cannot find donor | 
2023-03-12T19:44:59.817822Z timeout from donor in gtid/keyring stage |  | 
2023-03-12T19:44:59.839692Z SST error |  | 
@@ -76,8 +76,8 @@ mysql version 8.0.28 8.0.28
2023-03-12T22:00:27.089809Z |  SST error | 
2023-03-12T22:00:27.237486Z |  former SST cancelled | 
identifier 172.17.0.2 node2 node3
identifier node1 node2 node3
current path tests/logs/upgrade/node1.log tests/logs/upgrade/node2.log tests/logs/upgrade/node3.log
last known ip 172.17.0.2 172.17.0.3 172.17.0.4
last known name node2 node3
last known name node1 node2 node3
mysql version 8.0.28 8.0.28 8.0.28

66
src/go/pt-galera-log-explainer/types/ctx.go
View File

@@ -2,13 +2,16 @@ package types
import (
"encoding/json"
"time"
"github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils"
)
// LogCtx is a context for a given file.
// It is the principal storage of this tool
// Everything relevant will be stored here
// LogCtx is the main context storage for a node.
// It is the principal storage of this tool, this is the source of truth to merge logs and take decisions
// It is stored along wih each single log line we matched, and copied for each new log line.
// It is NOT meant to be used as a singleton by pointer, it must keep its original state for each log lines
// If not, every informaiton would be overwritten (states, sst, version, membercount, ...) and we would not be able to give the history of changes
type LogCtx struct {
FilePath string
FileType string
@@ -20,21 +23,38 @@ type LogCtx struct {
statePostProcessingLog string
stateBackupLog string
Version string
SST SST
// SSTs where key is donor name, as it will always be known.
// is meant to be shared with a deep copy, there's no sense to share the pointer
// because it is meant to store a state at a specific time
SSTs map[string]SST
MyIdx string
MemberCount int
Desynced bool
minVerbosity Verbosity
Conflicts Conflicts
// translation maps, the only elements that can be shared and copied by pointer
HashToIP map[string]string
HashToNodeName map[string]string
IPToHostname map[string]string
IPToMethod map[string]string
IPToNodeName map[string]string
minVerbosity Verbosity
Conflicts Conflicts
}
func NewLogCtx() LogCtx {
return LogCtx{minVerbosity: Debug, HashToIP: map[string]string{}, IPToHostname: map[string]string{}, IPToMethod: map[string]string{}, IPToNodeName: map[string]string{}, HashToNodeName: map[string]string{}}
ctx := LogCtx{minVerbosity: Debug}
ctx.InitMaps()
return ctx
}
func (ctx *LogCtx) InitMaps() {
ctx.SSTs = map[string]SST{}
ctx.HashToIP = map[string]string{}
ctx.IPToHostname = map[string]string{}
ctx.IPToMethod = map[string]string{}
ctx.IPToNodeName = map[string]string{}
ctx.HashToNodeName = map[string]string{}
}
// State will return the wsrep state of the current file type
@@ -234,6 +254,34 @@ func (base *LogCtx) Inherit(ctx LogCtx) {
base.MergeMapsWith([]LogCtx{ctx})
}
func (ctx *LogCtx) SetSSTTypeMaybe(ssttype string) {
for key, sst := range ctx.SSTs {
if len(ctx.SSTs) == 1 || (ctx.State() == "DONOR" && utils.SliceContains(ctx.OwnNames, key)) || (ctx.State() == "JOINER" && utils.SliceContains(ctx.OwnNames, sst.Joiner)) {
sst.Type = ssttype
ctx.SSTs[key] = sst
return
}
}
}
func (ctx *LogCtx) ConfirmSSTMetadata(shiftTimestamp time.Time) {
if ctx.State() != "DONOR" && ctx.State() != "JOINER" {
return
}
for key, sst := range ctx.SSTs {
if sst.MustHaveHappenedLocally(shiftTimestamp) {
if ctx.State() == "DONOR" {
ctx.AddOwnName(key)
}
if ctx.State() == "JOINER" {
ctx.AddOwnName(sst.Joiner)
}
}
}
return
}
func (l LogCtx) MarshalJSON() ([]byte, error) {
return json.Marshal(struct {
FilePath string
@@ -246,7 +294,7 @@ func (l LogCtx) MarshalJSON() ([]byte, error) {
StatePostProcessingLog string
StateBackupLog string
Version string
SST SST
SSTs map[string]SST
MyIdx string
MemberCount int
Desynced bool
@@ -267,7 +315,7 @@ func (l LogCtx) MarshalJSON() ([]byte, error) {
StatePostProcessingLog: l.statePostProcessingLog,
StateBackupLog: l.stateBackupLog,
Version: l.Version,
SST: l.SST,
SSTs: l.SSTs,
MyIdx: l.MyIdx,
MemberCount: l.MemberCount,
Desynced: l.Desynced,

22
src/go/pt-galera-log-explainer/types/sst.go
View File

@@ -1,15 +1,23 @@
package types
import "time"
type SST struct {
Method string
Type string
ResyncingNode string
ResyncedFromNode string
Joiner string
Donor string
SelectionTimestamp *time.Time
}
func (s *SST) Reset() {
s.Method = ""
s.Type = ""
s.ResyncedFromNode = ""
s.ResyncingNode = ""
// MustHaveHappenedLocally use the "selected x as donor" timestamp
// and compare it to the timestamp of donor/joiner wsrep status shift
// Usually, when it is selected, joiner/donor take a few milliseconds to shift their status
// This is the most solid way so far to correctly map donor and joiners when concurrents SSTs
// are running
func (sst SST) MustHaveHappenedLocally(shiftTimestamp time.Time) bool {
if sst.SelectionTimestamp == nil {
return false
}
return shiftTimestamp.Sub(*sst.SelectionTimestamp).Seconds() <= 0.01
}