diff --git a/go.mod b/go.mod index c6040c31..b28d5927 100644 --- a/go.mod +++ b/go.mod @@ -4,11 +4,14 @@ go 1.21 require ( github.com/AlekSi/pointer v1.2.0 + github.com/Ladicle/tabwriter v1.0.0 github.com/Masterminds/semver v1.5.0 github.com/alecthomas/kingpin v2.2.6+incompatible github.com/alecthomas/kong v0.8.0 + github.com/davecgh/go-spew v1.1.1 github.com/go-ini/ini v1.67.0 github.com/golang/mock v1.6.0 + github.com/google/go-cmp v0.5.9 github.com/google/uuid v1.3.1 github.com/hashicorp/go-version v1.6.0 github.com/howeyc/gopass v0.0.0-20210920133722-c8aef6fb66ef @@ -18,6 +21,7 @@ require ( github.com/pborman/getopt v1.1.0 github.com/percona/go-mysql v0.0.0-20210427141028-73d29c6da78c github.com/pkg/errors v0.9.1 + github.com/rs/zerolog v1.30.0 github.com/shirou/gopsutil v3.21.11+incompatible github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.8.4 @@ -25,6 +29,7 @@ require ( golang.org/x/crypto v0.13.0 golang.org/x/exp v0.0.0-20230321023759-10a507213a29 gopkg.in/mgo.v2 v2.0.0-20190816093944-a6b53ec6cb22 + gopkg.in/yaml.v2 v2.4.0 k8s.io/api v0.28.2 ) @@ -39,6 +44,8 @@ require ( github.com/google/gofuzz v1.2.0 // indirect github.com/json-iterator/go v1.1.12 // indirect github.com/klauspost/compress v1.16.3 // indirect + github.com/mattn/go-colorable v0.1.12 // indirect + github.com/mattn/go-isatty v0.0.14 // indirect github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect github.com/modern-go/reflect2 v1.0.2 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect @@ -55,7 +62,6 @@ require ( golang.org/x/term v0.12.0 // indirect golang.org/x/text v0.13.0 // indirect gopkg.in/inf.v0 v0.9.1 // indirect - gopkg.in/yaml.v2 v2.4.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect k8s.io/apimachinery v0.28.2 // indirect k8s.io/klog/v2 v2.100.1 // indirect diff --git a/go.sum b/go.sum index 12e99dfa..03030eee 100644 --- a/go.sum +++ b/go.sum @@ -1,5 +1,7 @@ github.com/AlekSi/pointer v1.2.0 h1:glcy/gc4h8HnG2Z3ZECSzZ1IX1x2JxRVuDzaJwQE0+w= github.com/AlekSi/pointer v1.2.0/go.mod h1:gZGfd3dpW4vEc/UlyfKKi1roIqcCgwOIvb0tSNSBle0= +github.com/Ladicle/tabwriter v1.0.0 h1:DZQqPvMumBDwVNElso13afjYLNp0Z7pHqHnu0r4t9Dg= +github.com/Ladicle/tabwriter v1.0.0/go.mod h1:c4MdCjxQyTbGuQO/gvqJ+IA/89UEwrsD6hUCW98dyp4= github.com/Masterminds/semver v1.5.0 h1:H65muMkzWKEuNDnfl9d70GUjFniHKHRbFPGBuZ3QEww= github.com/Masterminds/semver v1.5.0/go.mod h1:MB6lktGJrhw8PrUyiEoblNEGEQ+RzHPF078ddwwvV3Y= github.com/alecthomas/assert/v2 v2.1.0 h1:tbredtNcQnoSd3QBhQWI7QZ3XHOVkw1Moklp2ojoH/0= @@ -14,6 +16,7 @@ github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751 h1:JYp7IbQjafo github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= github.com/alecthomas/units v0.0.0-20211218093645-b94a6e3cc137 h1:s6gZFSlWYmbqAuRjVTiNNhvNRfY2Wxp9nhfyel4rklc= github.com/alecthomas/units v0.0.0-20211218093645-b94a6e3cc137/go.mod h1:OMCwj8VM1Kc9e19TLln2VL61YJF0x1XFtfdL4JdbSyE= +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -24,6 +27,7 @@ github.com/go-logr/logr v1.2.4 h1:g01GSCwiDw2xSZfjJ2/T9M+S6pFdcNtFYsp+Y43HYDQ= github.com/go-logr/logr v1.2.4/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= github.com/go-ole/go-ole v1.2.6 h1:/Fpf6oFPoeFik9ty7siob0G6Ke8QvQEuVcuChpwXzpY= github.com/go-ole/go-ole v1.2.6/go.mod h1:pprOEPIfldk/42T2oK7lQ4v4JSDwmV0As9GaiUsvbm0= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q= github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q= github.com/golang/mock v1.6.0 h1:ErTB+efbowRARo13NNdxyJji2egdxLGQhRaY+DUumQc= @@ -58,6 +62,10 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/lib/pq v1.10.9 h1:YXG7RB+JIjhP29X+OtkiDnYaXQwpS4JEWq7dtCCRUEw= github.com/lib/pq v1.10.9/go.mod h1:AlVN5x4E4T544tWzH6hKfbfQvm3HdbOxrmggDNAPY9o= +github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40= +github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= +github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y= +github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= github.com/mattn/go-shellwords v1.0.12 h1:M2zGm7EW6UQJvDeQxo4T51eKPurbeFbe8WtebGE2xrk= github.com/mattn/go-shellwords v1.0.12/go.mod h1:EZzvwXDESEeg03EKmM+RmDnNOPKG4lLtQsUlTZDWQ8Y= github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q= @@ -78,6 +86,9 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= +github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.30.0 h1:SymVODrcRsaRaSInD9yQtKbtWqwsfoPcRff/oRXLj4c= +github.com/rs/zerolog v1.30.0/go.mod h1:/tk+P47gFdPXq4QYjvCmT5/Gsug2nagsFWBWhAiSi1w= github.com/shirou/gopsutil v3.21.11+incompatible h1:+1+c1VGhc88SSonWP6foOcLhvnKlUeu/erjjvaPEYiI= github.com/shirou/gopsutil v3.21.11+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA= github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= @@ -151,6 +162,8 @@ golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= diff --git a/src/go/pt-galera-log-explainer/README.md b/src/go/pt-galera-log-explainer/README.md new file mode 100644 index 00000000..a17b5821 --- /dev/null +++ b/src/go/pt-galera-log-explainer/README.md @@ -0,0 +1,120 @@ +[![Go Report Card](https://goreportcard.com/badge/github.com/ylacancellera/galera-log-explainer)](https://goreportcard.com/report/github.com/ylacancellera/galera-log-explainer) + +# pt-galera-log-explainer + +Filter, aggregate and summarize multiple galera logs together. + + +## Features + +* List events in chronological order from any number of nodes +* List key points of information from logs (sst, view changes, general errors, maintenance operations) +* Translate advanced Galera information to a easily readable counterpart +* Filter on dates with --since, --until +* Filter on type of events +* Aggregates rotated logs together, even when there are logs from multiple nodes + +

+Get the latest cluster changes on a local server +```sh +pt-galera-log-explainer list --all --since 2023-01-05T03:24:26.000000Z /var/log/mysql/*.log +``` + +Or gather every log files and compile them +```sh +pt-galera-log-explainer list --all *.log +``` +![example](example.png) + +

+Find out information about nodes, using any type of info +```sh +pt-galera-log-explainer whois '218469b2' mysql.log +{ + "input": "218469b2", + "IPs": [ + "172.17.0.3" + ], + "nodeNames": [ + "galera-node2" + ], + "hostname": "", + "nodeUUIDs:": [ + "218469b2", + "259b78a0", + "fa81213d", + ] +} +``` + +You can find information from UUIDs, IPs, node names +``` +pt-galera-log-explainer whois '172.17.0.3' mysql.log + +pt-galera-log-explainer whois 'galera-node2' mysql.log +``` +

+List every replication failures (Galera 4) +```sh +pt-galera-log-explainer conflicts [--json|--yaml] *.log +``` +![conflicts example](example_conflicts.png) + +

+ +Automatically translate every information (IP, UUID) from a log +``` +pt-galera-log-explainer sed some/log.log another/one.log to_translate.log < to_translate.log | less + +cat to_translate.log | pt-galera-log-explainer sed some/log.log another/one.log to_translate.log | less +``` +Or get the raw `sed` command to do it yourself +``` +pt-galera-log-explainer sed some/log.log another/one.log to_translate.log +``` +

+Usage: +``` +Usage: pt-galera-log-explainer + +An utility to merge and help analyzing Galera logs + +Flags: + -h, --help Show context-sensitive help. + --no-color + --since=SINCE Only list events after this date, format: 2023-01-23T03:53:40Z (RFC3339) + --until=UNTIL Only list events before this date + -v, --verbosity=1 -v: Detailed (default), -vv: DebugMySQL (add every mysql info the tool used), + -vvv: Debug (internal tool debug) + --pxc-operator Analyze logs from Percona PXC operator. Off by default because it negatively + impacts performance for non-k8s setups + --exclude-regexes=EXCLUDE-REGEXES,... + Remove regexes from analysis. List regexes using 'pt-galera-log-explainer + regex-list' + --grep-cmd="grep" 'grep' command path. Could need to be set to 'ggrep' for darwin systems + --grep-args="-P" 'grep' arguments. perl regexp (-P) is necessary. -o will break the tool + +Commands: + list ... + + whois ... + + sed ... + + ctx ... + + regex-list + + version + + conflicts ... + +Run "pt-galera-log-explainer --help" for more information on a command. +``` + + +## Compatibility + +* Percona XtraDB Cluster: 5.5 to 8.0 +* MariaDB Galera Cluster: 10.0 to 10.6 +* Galera logs from K8s pods diff --git a/src/go/pt-galera-log-explainer/conflicts.go b/src/go/pt-galera-log-explainer/conflicts.go new file mode 100644 index 00000000..310d10c8 --- /dev/null +++ b/src/go/pt-galera-log-explainer/conflicts.go @@ -0,0 +1,72 @@ +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "gopkg.in/yaml.v2" +) + +type conflicts struct { + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` + Yaml bool `xor:"format"` + Json bool `xor:"format"` +} + +func (c *conflicts) Help() string { + return "Summarize every replication conflicts, from every node's point of view" +} + +func (c *conflicts) Run() error { + + regexes := regex.IdentsMap.Merge(regex.ApplicativeMap) + timeline, err := timelineFromPaths(c.Paths, regexes, CLI.Since, CLI.Until) + if err != nil { + return err + } + + ctxs := timeline.GetLatestUpdatedContextsByNodes() + for _, ctx := range ctxs { + if len(ctx.Conflicts) == 0 { + continue + } + var out string + + if c.Yaml { + tmp, err := yaml.Marshal(ctx.Conflicts) + if err != nil { + return err + } + out = string(tmp) + } else if c.Json { + tmp, err := json.Marshal(ctx.Conflicts) + if err != nil { + return err + } + out = string(tmp) + } else { + + for _, conflict := range ctx.Conflicts { + out += "\n" + out += "\n" + utils.Paint(utils.BlueText, "seqno: ") + conflict.Seqno + out += "\n\t" + utils.Paint(utils.BlueText, "winner: ") + conflict.Winner + out += "\n\t" + utils.Paint(utils.BlueText, "votes per nodes:") + for node, vote := range conflict.VotePerNode { + displayVote := utils.Paint(utils.RedText, vote.MD5) + if vote.MD5 == conflict.Winner { + displayVote = utils.Paint(utils.GreenText, vote.MD5) + } + out += "\n\t\t" + utils.Paint(utils.BlueText, node) + ": (" + displayVote + ") " + vote.Error + } + out += "\n\t" + utils.Paint(utils.BlueText, "initiated by: ") + fmt.Sprintf("%v", conflict.InitiatedBy) + } + + } + fmt.Println(out) + return nil + } + + return nil +} diff --git a/src/go/pt-galera-log-explainer/ctx.go b/src/go/pt-galera-log-explainer/ctx.go new file mode 100644 index 00000000..3cf4ab1a --- /dev/null +++ b/src/go/pt-galera-log-explainer/ctx.go @@ -0,0 +1,39 @@ +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/pkg/errors" +) + +type ctx struct { + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` +} + +func (c *ctx) Help() string { + return "Dump the context derived from the log" +} + +func (c *ctx) Run() error { + + if len(c.Paths) != 1 { + return errors.New("Can only use 1 path at a time for ctx subcommand") + } + + timeline, err := timelineFromPaths(c.Paths, regex.AllRegexes(), CLI.Since, CLI.Until) + if err != nil { + return err + } + + for _, t := range timeline { + out, err := json.MarshalIndent(t[len(t)-1].Ctx, "", "\t") + if err != nil { + return err + } + fmt.Println(string(out)) + } + + return nil +} diff --git a/src/go/pt-galera-log-explainer/display/timelinecli.go b/src/go/pt-galera-log-explainer/display/timelinecli.go new file mode 100644 index 00000000..6d6f92c1 --- /dev/null +++ b/src/go/pt-galera-log-explainer/display/timelinecli.go @@ -0,0 +1,352 @@ +package display + +import ( + "fmt" + "log" + "os" + "sort" + "strings" + + // regular tabwriter do not work with color, this is a forked versions that ignores color special characters + "github.com/Ladicle/tabwriter" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +// TimelineCLI print a timeline to the terminal using tabulated format +// It will print header and footers, and dequeue the timeline chronologically +func TimelineCLI(timeline types.Timeline, verbosity types.Verbosity) { + + timeline = removeEmptyColumns(timeline, verbosity) + + // to hold the current context for each node + // "keys" is needed, because iterating over a map must give a different order each time + // a slice keeps its order + keys, currentContext := initKeysContext(timeline) // currentcontext to follow when important thing changed + latestContext := timeline.GetLatestUpdatedContextsByNodes() // so that we have fully updated context when we print + lastContext := map[string]types.LogCtx{} // just to follow when important thing changed + + w := tabwriter.NewWriter(os.Stdout, 8, 8, 3, ' ', tabwriter.DiscardEmptyColumns) + defer w.Flush() + + // header + fmt.Fprintln(w, headerNodes(keys)) + fmt.Fprintln(w, headerFilePath(keys, currentContext)) + fmt.Fprintln(w, headerIP(keys, latestContext)) + fmt.Fprintln(w, headerName(keys, latestContext)) + fmt.Fprintln(w, headerVersion(keys, latestContext)) + fmt.Fprintln(w, separator(keys)) + + var ( + args []string // stuff to print + linecount int + ) + + // as long as there is a next event to print + for nextNodes := timeline.IterateNode(); len(nextNodes) != 0; nextNodes = timeline.IterateNode() { + + // Date column + date := timeline[nextNodes[0]][0].Date + args = []string{""} + if date != nil { + args = []string{date.DisplayTime} + } + + displayedValue := 0 + + // node values + for _, node := range keys { + + if !utils.SliceContains(nextNodes, node) { + // if there are no events, having a | is needed for tabwriter + // A few color can also help highlighting how the node is doing + ctx := currentContext[node] + args = append(args, utils.PaintForState("| ", ctx.State())) + continue + } + loginfo := timeline[node][0] + lastContext[node] = currentContext[node] + currentContext[node] = loginfo.Ctx + + timeline.Dequeue(node) + + msg := loginfo.Msg(latestContext[node]) + if verbosity > loginfo.Verbosity && msg != "" { + args = append(args, msg) + displayedValue++ + } else { + args = append(args, utils.PaintForState("| ", loginfo.Ctx.State())) + } + } + + if sep := transitionSeparator(keys, lastContext, currentContext); sep != "" { + // reset current context, so that we avoid duplicating transitions + // lastContext/currentContext is only useful for that anyway + lastContext = map[string]types.LogCtx{} + for k, v := range currentContext { + lastContext[k] = v + } + // print transition + fmt.Fprintln(w, sep) + } + + // If line is not filled with default placeholder values + if displayedValue == 0 { + continue + + } + + // Print tabwriter line + _, err := fmt.Fprintln(w, strings.Join(args, "\t")+"\t") + if err != nil { + log.Println("Failed to write a line", err) + } + linecount++ + } + + // footer + // only having a header is not fast enough to read when there are too many lines + if linecount >= 50 { + fmt.Fprintln(w, separator(keys)) + fmt.Fprintln(w, headerNodes(keys)) + fmt.Fprintln(w, headerFilePath(keys, currentContext)) + fmt.Fprintln(w, headerIP(keys, currentContext)) + fmt.Fprintln(w, headerName(keys, currentContext)) + fmt.Fprintln(w, headerVersion(keys, currentContext)) + } + + // TODO: where to print conflicts details ? +} + +func initKeysContext(timeline types.Timeline) ([]string, map[string]types.LogCtx) { + currentContext := map[string]types.LogCtx{} + + // keys will be used to access the timeline map with an ordered manner + // without this, we would not print on the correct column as the order of a map is guaranteed to be random each time + keys := make([]string, 0, len(timeline)) + for node := range timeline { + keys = append(keys, node) + if len(timeline[node]) > 0 { + currentContext[node] = timeline[node][0].Ctx + } else { + // Avoid crashing, but not ideal: we could have a better default Ctx with filepath at least + currentContext[node] = types.NewLogCtx() + } + } + sort.Strings(keys) + return keys, currentContext +} + +func separator(keys []string) string { + return " \t" + strings.Repeat(" \t", len(keys)) +} + +func headerNodes(keys []string) string { + return "identifier\t" + strings.Join(keys, "\t") + "\t" +} + +func headerFilePath(keys []string, ctxs map[string]types.LogCtx) string { + header := "current path\t" + for _, node := range keys { + if ctx, ok := ctxs[node]; ok { + if len(ctx.FilePath) < 50 { + header += ctx.FilePath + "\t" + } else { + header += "..." + ctx.FilePath[len(ctx.FilePath)-50:] + "\t" + } + } else { + header += " \t" + } + } + return header +} + +func headerIP(keys []string, ctxs map[string]types.LogCtx) string { + header := "last known ip\t" + for _, node := range keys { + if ctx, ok := ctxs[node]; ok && len(ctx.OwnIPs) > 0 { + header += ctx.OwnIPs[len(ctx.OwnIPs)-1] + "\t" + } else { + header += " \t" + } + } + return header +} + +func headerVersion(keys []string, ctxs map[string]types.LogCtx) string { + header := "mysql version\t" + for _, node := range keys { + if ctx, ok := ctxs[node]; ok { + header += ctx.Version + "\t" + } + } + return header +} + +func headerName(keys []string, ctxs map[string]types.LogCtx) string { + header := "last known name\t" + for _, node := range keys { + if ctx, ok := ctxs[node]; ok && len(ctx.OwnNames) > 0 { + header += ctx.OwnNames[len(ctx.OwnNames)-1] + "\t" + } else { + header += " \t" + } + } + return header +} + +func removeEmptyColumns(timeline types.Timeline, verbosity types.Verbosity) types.Timeline { + + for key := range timeline { + if !timeline[key][len(timeline[key])-1].Ctx.HasVisibleEvents(verbosity) { + delete(timeline, key) + } + } + return timeline +} + +// transition is to builds the check+display of an important context transition +// like files, IP, name, anything +// summary will hold the whole multi-line report +type transition struct { + s1, s2, changeType string + ok bool + summary transitionSummary +} + +// transitions will hold any number of transition to test +// transitionToPrint will hold whatever transition happened, but will also store empty transitions +// to ensure that every columns will have the same amount of rows to write: this is needed to maintain +// the columnar output +type transitions struct { + tests []*transition + transitionToPrint []*transition + numberFound int +} + +// 4 here means there are 4 rows to store +// 0: base info, 1: type of info that changed, 2: just an arrow placeholder, 3: new info +const RowPerTransitions = 4 + +type transitionSummary [RowPerTransitions]string + +// because only those transitions are implemented: file path, ip, node name, version +const NumberOfPossibleTransition = 4 + +// transactionSeparator is useful to highligh a change of context +// example, changing file +// mysqld.log.2 +// (file path) +// V +// mysqld.log.1 +// or a change of ip, node name, ... +// This feels complicated: it is +// It was made difficult because of how "tabwriter" works +// it needs an element on each columns so that we don't break columns +// The rows can't have a variable count of elements: it has to be strictly identical each time +// so the whole next functions are here to ensure it takes minimal spaces, while giving context and preserving columns +func transitionSeparator(keys []string, oldctxs, ctxs map[string]types.LogCtx) string { + + ts := map[string]*transitions{} + + // For each columns to print, we build tests + for _, node := range keys { + ctx, ok1 := ctxs[node] + oldctx, ok2 := oldctxs[node] + + ts[node] = &transitions{tests: []*transition{}} + if ok1 && ok2 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldctx.FilePath, s2: ctx.FilePath, changeType: "file path"}) + + if len(oldctx.OwnNames) > 0 && len(ctx.OwnNames) > 0 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldctx.OwnNames[len(oldctx.OwnNames)-1], s2: ctx.OwnNames[len(ctx.OwnNames)-1], changeType: "node name"}) + } + if len(oldctx.OwnIPs) > 0 && len(ctx.OwnIPs) > 0 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldctx.OwnIPs[len(oldctx.OwnIPs)-1], s2: ctx.OwnIPs[len(ctx.OwnIPs)-1], changeType: "node ip"}) + } + if oldctx.Version != "" && ctx.Version != "" { + ts[node].tests = append(ts[node].tests, &transition{s1: oldctx.Version, s2: ctx.Version, changeType: "version"}) + } + + } + + // we resolve tests + ts[node].fillEmptyTransition() + ts[node].iterate() + } + + highestStackOfTransitions := 0 + + // we need to know the maximum height to print + for _, node := range keys { + if ts[node].numberFound > highestStackOfTransitions { + highestStackOfTransitions = ts[node].numberFound + } + } + // now we have the height, we compile the stack to print (possibly empty placeholders for some columns) + for _, node := range keys { + ts[node].stackPrioritizeFound(highestStackOfTransitions) + } + + out := "\t" + for i := 0; i < highestStackOfTransitions; i++ { + for row := 0; row < RowPerTransitions; row++ { + for _, node := range keys { + out += ts[node].transitionToPrint[i].summary[row] + } + if !(i == highestStackOfTransitions-1 && row == RowPerTransitions-1) { // unless last row + out += "\n\t" + } + } + } + + if out == "\t" { + return "" + } + return out +} + +func (ts *transitions) iterate() { + + for _, test := range ts.tests { + + test.summarizeIfDifferent() + if test.ok { + ts.numberFound++ + } + } + +} + +func (ts *transitions) stackPrioritizeFound(height int) { + for i, test := range ts.tests { + // if at the right height + if len(ts.tests)-i+len(ts.transitionToPrint) == height { + ts.transitionToPrint = append(ts.transitionToPrint, ts.tests[i:]...) + } + if test.ok { + ts.transitionToPrint = append(ts.transitionToPrint, test) + } + } +} + +func (ts *transitions) fillEmptyTransition() { + if len(ts.tests) == NumberOfPossibleTransition { + return + } + for i := len(ts.tests); i < NumberOfPossibleTransition; i++ { + ts.tests = append(ts.tests, &transition{s1: "", s2: "", changeType: ""}) + } + +} + +func (t *transition) summarizeIfDifferent() { + if t.s1 != t.s2 { + t.summary = [RowPerTransitions]string{utils.Paint(utils.BrightBlueText, t.s1), utils.Paint(utils.BlueText, "("+t.changeType+")"), utils.Paint(utils.BrightBlueText, " V "), utils.Paint(utils.BrightBlueText, t.s2)} + t.ok = true + } + for i := range t.summary { + t.summary[i] = t.summary[i] + "\t" + } + return +} diff --git a/src/go/pt-galera-log-explainer/display/timelinecli_test.go b/src/go/pt-galera-log-explainer/display/timelinecli_test.go new file mode 100644 index 00000000..4c37dcde --- /dev/null +++ b/src/go/pt-galera-log-explainer/display/timelinecli_test.go @@ -0,0 +1,186 @@ +package display + +import ( + "testing" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func TestTransitionSeparator(t *testing.T) { + tests := []struct { + keys []string + oldctxs, ctxs map[string]types.LogCtx + expectedOut string + name string + }{ + { + name: "no changes", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {}, + }, + ctxs: map[string]types.LogCtx{ + + "node0": {}, + "node1": {}, + }, + expectedOut: "", + }, + { + name: "filepath changed on node0", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {FilePath: "path1"}, + "node1": {}, + }, + ctxs: map[string]types.LogCtx{ + + "node0": {FilePath: "path2"}, + "node1": {}, + }, + /* + path1 + (file path) + V + path2 + */ + expectedOut: "\tpath1\t\t\n\t(file path)\t\t\n\t V \t\t\n\tpath2\t\t", + }, + { + name: "filepath changed on node1", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {FilePath: "path1"}, + }, + ctxs: map[string]types.LogCtx{ + + "node0": {}, + "node1": {FilePath: "path2"}, + }, + expectedOut: "\t\tpath1\t\n\t\t(file path)\t\n\t\t V \t\n\t\tpath2\t", + }, + { + name: "filepath changed on both", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {FilePath: "path1_0"}, + "node1": {FilePath: "path1_1"}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {FilePath: "path2_0"}, + "node1": {FilePath: "path2_1"}, + }, + expectedOut: "\tpath1_0\tpath1_1\t\n\t(file path)\t(file path)\t\n\t V \t V \t\n\tpath2_0\tpath2_1\t", + }, + { + name: "node name changed on node1", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnNames: []string{"name1"}}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnNames: []string{"name1", "name2"}}, + }, + expectedOut: "\t\tname1\t\n\t\t(node name)\t\n\t\t V \t\n\t\tname2\t", + }, + { + name: "node ip changed on node1", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnIPs: []string{"ip1"}}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnIPs: []string{"ip1", "ip2"}}, + }, + expectedOut: "\t\tip1\t\n\t\t(node ip)\t\n\t\t V \t\n\t\tip2\t", + }, + { + name: "version changed on node1", + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {Version: "8.0.28"}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {Version: "8.0.30"}, + }, + expectedOut: "\t\t8.0.28\t\n\t\t(version)\t\n\t\t V \t\n\t\t8.0.30\t", + }, + { + name: "node ip, node name and filepath changed on node1", // very possible with operators + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnIPs: []string{"ip1"}, OwnNames: []string{"name1"}, FilePath: "path1"}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {}, + "node1": {OwnIPs: []string{"ip1", "ip2"}, OwnNames: []string{"name1", "name2"}, FilePath: "path2"}, + }, + /* + (timestamp) (node0) (node1) + \t \t path1 \t\n + \t \t (file path) \t\n + \t \t V \t\n + \t \t path2 \t\n + \t \t name1 \t\n + \t \t (node name) \t\n + \t \t V \t\n + \t \t name2 \t\n + \t \t ip2 \t\n + \t \t (node ip) \t\n + \t \t V \t\n + \t \t ip2 \t --only one without \n + + */ + expectedOut: "\t\tpath1\t\n\t\t(file path)\t\n\t\t V \t\n\t\tpath2\t\n\t\tname1\t\n\t\t(node name)\t\n\t\t V \t\n\t\tname2\t\n\t\tip1\t\n\t\t(node ip)\t\n\t\t V \t\n\t\tip2\t", + }, + + { + name: "node ip, node name and filepath changed on node1, nodename changed on node2", // very possible with operators + keys: []string{"node0", "node1"}, + oldctxs: map[string]types.LogCtx{ + "node0": {OwnNames: []string{"name1_0"}}, + "node1": {OwnIPs: []string{"ip1"}, OwnNames: []string{"name1_1"}, FilePath: "path1"}, + }, + ctxs: map[string]types.LogCtx{ + "node0": {OwnNames: []string{"name1_0", "name2_0"}}, + "node1": {OwnIPs: []string{"ip1", "ip2"}, OwnNames: []string{"name1_1", "name2_1"}, FilePath: "path2"}, + }, + /* + (timestamp) (node0) (node1) + \t name1_0\t path1 \t\n + \t (node name)\t (file path) \t\n + \t V \t V \t\n + \t name2_0\t path2 \t\n + \t \t name1_1 \t\n + \t \t (node name) \t\n + \t \t V \t\n + \t \t name2_1 \t\n + \t \t ip2 \t\n + \t \t (node ip) \t\n + \t \t V \t\n + \t \t ip2 \t --only one without \n + + */ + expectedOut: "\tname1_0\tpath1\t\n\t(node name)\t(file path)\t\n\t V \t V \t\n\tname2_0\tpath2\t\n\t\tname1_1\t\n\t\t(node name)\t\n\t\t V \t\n\t\tname2_1\t\n\t\tip1\t\n\t\t(node ip)\t\n\t\t V \t\n\t\tip2\t", + }, + } + + utils.SkipColor = true + for _, test := range tests { + out := transitionSeparator(test.keys, test.oldctxs, test.ctxs) + if out != test.expectedOut { + t.Errorf("testname: %s, expected: \n%#v\n got: \n%#v", test.name, test.expectedOut, out) + } + + } +} diff --git a/src/go/pt-galera-log-explainer/example.png b/src/go/pt-galera-log-explainer/example.png new file mode 100644 index 00000000..50672e52 Binary files /dev/null and b/src/go/pt-galera-log-explainer/example.png differ diff --git a/src/go/pt-galera-log-explainer/example_conflicts.png b/src/go/pt-galera-log-explainer/example_conflicts.png new file mode 100644 index 00000000..0b437a75 Binary files /dev/null and b/src/go/pt-galera-log-explainer/example_conflicts.png differ diff --git a/src/go/pt-galera-log-explainer/list.go b/src/go/pt-galera-log-explainer/list.go new file mode 100644 index 00000000..3e29015f --- /dev/null +++ b/src/go/pt-galera-log-explainer/list.go @@ -0,0 +1,80 @@ +package main + +import ( + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/display" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/pkg/errors" +) + +type list struct { + // Paths is duplicated because it could not work as variadic with kong cli if I set it as CLI object + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` + SkipStateColoredColumn bool `help:"avoid having the placeholder colored with mysql state, which is guessed using several regexes that will not be displayed"` + All bool `help:"List everything" xor:"states,views,events,sst,applicative"` + States bool `help:"List WSREP state changes(SYNCED, DONOR, ...)" xor:"states"` + Views bool `help:"List how Galera views evolved (who joined, who left)" xor:"views"` + Events bool `help:"List generic mysql events (start, shutdown, assertion failures)" xor:"events"` + SST bool `help:"List Galera synchronization event" xor:"sst"` + Applicative bool `help:"List applicative events (resyncs, desyncs, conflicts). Events tied to one's usage of Galera" xor:"applicative"` +} + +func (l *list) Help() string { + return `List events for each nodes in a columnar output + It will merge logs between themselves + + "identifier" is an internal metadata, this is used to merge logs. + +Usage: + galera-log-explainer list --all + galera-log-explainer list --all *.log + galera-log-explainer list --sst --views --states + galera-log-explainer list --events --views *.log + ` +} + +func (l *list) Run() error { + + if !(l.All || l.Events || l.States || l.SST || l.Views || l.Applicative) { + return errors.New("Please select a type of logs to search: --all, or any parameters from: --sst --views --events --states") + } + + toCheck := l.regexesToUse() + + timeline, err := timelineFromPaths(CLI.List.Paths, toCheck, CLI.Since, CLI.Until) + if err != nil { + return errors.Wrap(err, "Could not list events") + } + + display.TimelineCLI(timeline, CLI.Verbosity) + + return nil +} + +func (l *list) regexesToUse() types.RegexMap { + + // IdentRegexes is always needed: we would not be able to identify the node where the file come from + toCheck := regex.IdentsMap + if l.States || l.All { + toCheck.Merge(regex.StatesMap) + } else if !l.SkipStateColoredColumn { + regex.SetVerbosity(types.DebugMySQL, regex.StatesMap) + toCheck.Merge(regex.StatesMap) + } + if l.Views || l.All { + toCheck.Merge(regex.ViewsMap) + } + if l.SST || l.All { + toCheck.Merge(regex.SSTMap) + } + if l.Applicative || l.All { + toCheck.Merge(regex.ApplicativeMap) + } + if l.Events || l.All { + toCheck.Merge(regex.EventsMap) + } else if !l.SkipStateColoredColumn { + regex.SetVerbosity(types.DebugMySQL, regex.EventsMap) + toCheck.Merge(regex.EventsMap) + } + return toCheck +} diff --git a/src/go/pt-galera-log-explainer/main.go b/src/go/pt-galera-log-explainer/main.go new file mode 100644 index 00000000..de5834c0 --- /dev/null +++ b/src/go/pt-galera-log-explainer/main.go @@ -0,0 +1,283 @@ +package main + +import ( + "bufio" + "fmt" + "os" + "os/exec" + "runtime" + "strings" + "time" + + "github.com/alecthomas/kong" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "github.com/pkg/errors" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +// ldflags +var ( + version string + commit string + date string +) + +var CLI struct { + NoColor bool + Since *time.Time `help:"Only list events after this date, format: 2023-01-23T03:53:40Z (RFC3339)"` + Until *time.Time `help:"Only list events before this date"` + Verbosity types.Verbosity `type:"counter" short:"v" default:"1" help:"-v: Detailed (default), -vv: DebugMySQL (add every mysql info the tool used), -vvv: Debug (internal tool debug)"` + PxcOperator bool `default:"false" help:"Analyze logs from Percona PXC operator. Off by default because it negatively impacts performance for non-k8s setups"` + ExcludeRegexes []string `help:"Remove regexes from analysis. List regexes using 'pt-galera-log-explainer regex-list'"` + + List list `cmd:""` + Whois whois `cmd:""` + Sed sed `cmd:""` + Ctx ctx `cmd:""` + RegexList regexList `cmd:""` + Version versioncmd `cmd:""` + Conflicts conflicts `cmd:""` + + GrepCmd string `help:"'grep' command path. Could need to be set to 'ggrep' for darwin systems" default:"grep"` + GrepArgs string `help:"'grep' arguments. perl regexp (-P) is necessary. -o will break the tool" default:"-P"` +} + +func main() { + ctx := kong.Parse(&CLI, + kong.Name("pt-galera-log-explainer"), + kong.Description("An utility to merge and help analyzing Galera logs"), + kong.UsageOnError(), + ) + + zerolog.TimeFieldFormat = zerolog.TimeFormatUnix + zerolog.SetGlobalLevel(zerolog.WarnLevel) + log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}) + if CLI.Verbosity == types.Debug { + zerolog.SetGlobalLevel(zerolog.DebugLevel) + } + + utils.SkipColor = CLI.NoColor + err := ctx.Run() + ctx.FatalIfErrorf(err) +} + +type versioncmd struct{} + +func (v *versioncmd) Help() string { + return "" +} +func (v *versioncmd) Run() error { + fmt.Printf("version: %s, commit:%s, built at %s\n", version, commit, date) + return nil +} + +// timelineFromPaths takes every path, search them using a list of regexes +// and organize them in a timeline that will be ready to aggregate or read +func timelineFromPaths(paths []string, toCheck types.RegexMap, since, until *time.Time) (types.Timeline, error) { + timeline := make(types.Timeline) + found := false + + for _, path := range paths { + + extr := newExtractor(path, toCheck, since, until) + + localTimeline, err := extr.search() + if err != nil { + extr.logger.Warn().Err(err).Msg("Search failed") + continue + } + found = true + extr.logger.Debug().Str("path", path).Msg("Finished searching") + + // identify the node with the easiest to read information + // this is critical part to aggregate logs: this is what enable to merge logs + // ultimately the "identifier" will be used for columns header + var node string + if CLI.PxcOperator { + node = path + + } else { + + // Why it should not just identify using the file path: + // so that we are able to merge files that belong to the same nodes + // we wouldn't want them to be shown as from different nodes + node = types.Identifier(localTimeline[len(localTimeline)-1].Ctx) + if t, ok := timeline[node]; ok { + + extr.logger.Debug().Str("path", path).Str("node", node).Msg("Merging with existing timeline") + localTimeline = types.MergeTimeline(t, localTimeline) + } + } + extr.logger.Debug().Str("path", path).Str("node", node).Msg("Storing timeline") + timeline[node] = localTimeline + + } + if !found { + return nil, errors.New("Could not find data") + } + return timeline, nil +} + +// extractor is an utility struct to store what needs to be done +type extractor struct { + regexes types.RegexMap + path string + since, until *time.Time + logger zerolog.Logger +} + +func newExtractor(path string, toCheck types.RegexMap, since, until *time.Time) extractor { + e := extractor{regexes: toCheck, path: path, since: since, until: until} + e.logger = log.With().Str("component", "extractor").Str("path", e.path).Logger() + if since != nil { + e.logger = e.logger.With().Time("since", *e.since).Logger() + } + if until != nil { + e.logger = e.logger.With().Time("until", *e.until).Logger() + } + e.logger.Debug().Msg("new extractor") + + return e +} + +func (e *extractor) grepArgument() string { + + regexToSendSlice := e.regexes.Compile() + + grepRegex := "^" + if CLI.PxcOperator { + // special case + // I'm not adding pxcoperator map the same way others are used, because they do not have the same formats and same place + // it needs to be put on the front so that it's not 'merged' with the '{"log":"' json prefix + // this is to keep things as close as '^' as possible to keep doing prefix searches + grepRegex += "((" + strings.Join(regex.PXCOperatorMap.Compile(), "|") + ")|^{\"log\":\"" + e.regexes.Merge(regex.PXCOperatorMap) + } + if e.since != nil { + grepRegex += "(" + regex.BetweenDateRegex(e.since, CLI.PxcOperator) + "|" + regex.NoDatesRegex(CLI.PxcOperator) + ")" + } + grepRegex += ".*" + grepRegex += "(" + strings.Join(regexToSendSlice, "|") + ")" + if CLI.PxcOperator { + grepRegex += ")" + } + e.logger.Debug().Str("grepArg", grepRegex).Msg("Compiled grep arguments") + return grepRegex +} + +// search is the main function to search what we want in a file +func (e *extractor) search() (types.LocalTimeline, error) { + + // A first pass is done, with every regexes we want compiled in a single one. + grepRegex := e.grepArgument() + + /* + Regular grep is actually used + + There are no great alternatives, even less as golang libraries. + grep itself do not have great alternatives: they are less performant for common use-cases, or are not easily portable, or are costlier to execute. + grep is everywhere, grep is good enough, it even enable to use the stdout pipe. + + The usual bottleneck with grep is that it is single-threaded, but we actually benefit + from a sequential scan here as we will rely on the log order. + + Also, being sequential also ensure this program is light enough to run without too much impacts + It also helps to be transparent and not provide an obscure tool that work as a blackbox + */ + if runtime.GOOS == "darwin" && CLI.GrepCmd == "grep" { + e.logger.Warn().Msg("On Darwin systems, use 'pt-galera-log-explainer --grep-cmd=ggrep' as it requires grep v3") + } + + cmd := exec.Command(CLI.GrepCmd, CLI.GrepArgs, grepRegex, e.path) + + out, _ := cmd.StdoutPipe() + defer out.Close() + + err := cmd.Start() + if err != nil { + return nil, errors.Wrapf(err, "failed to search in %s", e.path) + } + + // grep treatment + s := bufio.NewScanner(out) + + // it will iterate on stdout pipe results + lt, err := e.iterateOnResults(s) + if err != nil { + e.logger.Warn().Err(err).Msg("Failed to iterate on results") + } + + // double-check it stopped correctly + if err = cmd.Wait(); err != nil { + return nil, errors.Wrap(err, "grep subprocess error") + } + + if len(lt) == 0 { + return nil, errors.New("Found nothing") + } + + return lt, nil +} + +func (e *extractor) sanitizeLine(s string) string { + if len(s) > 0 && s[0] == '\t' { + return s[1:] + } + return s +} + +// iterateOnResults will take line by line each logs that matched regex +// it will iterate on every regexes in slice, and apply the handler for each +// it also filters out --since and --until rows +func (e *extractor) iterateOnResults(s *bufio.Scanner) ([]types.LogInfo, error) { + + var ( + line string + lt types.LocalTimeline + recentEnough bool + displayer types.LogDisplayer + ) + ctx := types.NewLogCtx() + ctx.FilePath = e.path + + for s.Scan() { + line = e.sanitizeLine(s.Text()) + + var date *types.Date + t, layout, ok := regex.SearchDateFromLog(line) + if ok { + d := types.NewDate(t, layout) + date = &d + } + + // If it's recentEnough, it means we already validated a log: every next logs necessarily happened later + // this is useful because not every logs have a date attached, and some without date are very useful + if !recentEnough && e.since != nil && (date == nil || (date != nil && e.since.After(date.Time))) { + continue + } + if e.until != nil && date != nil && e.until.Before(date.Time) { + return lt, nil + } + recentEnough = true + + filetype := regex.FileType(line, CLI.PxcOperator) + ctx.FileType = filetype + + // We have to find again what regex worked to get this log line + // it can match multiple regexes + for key, regex := range e.regexes { + if !regex.Regex.MatchString(line) || utils.SliceContains(CLI.ExcludeRegexes, key) { + continue + } + ctx, displayer = regex.Handle(ctx, line) + li := types.NewLogInfo(date, displayer, line, regex, key, ctx, filetype) + + lt = lt.Add(li) + } + + } + return lt, nil +} diff --git a/src/go/pt-galera-log-explainer/regex/applicative.go b/src/go/pt-galera-log-explainer/regex/applicative.go new file mode 100644 index 00000000..8f476c6f --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/applicative.go @@ -0,0 +1,192 @@ +package regex + +import ( + "regexp" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + setType(types.ApplicativeRegexType, ApplicativeMap) +} + +var ApplicativeMap = types.RegexMap{ + + "RegexDesync": &types.LogRegex{ + Regex: regexp.MustCompile("desyncs itself from group"), + InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\) desyncs"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.Desynced = true + + node := submatches[groupNodeName] + return ctx, func(ctx types.LogCtx) string { + if utils.SliceContains(ctx.OwnNames, node) { + return utils.Paint(utils.YellowText, "desyncs itself from group") + } + return node + utils.Paint(utils.YellowText, " desyncs itself from group") + } + }, + }, + + "RegexResync": &types.LogRegex{ + Regex: regexp.MustCompile("resyncs itself to group"), + InternalRegex: regexp.MustCompile("\\(" + regexNodeName + "\\) resyncs"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.Desynced = false + node := submatches[groupNodeName] + return ctx, func(ctx types.LogCtx) string { + if utils.SliceContains(ctx.OwnNames, node) { + return utils.Paint(utils.YellowText, "resyncs itself to group") + } + return node + utils.Paint(utils.YellowText, " resyncs itself to group") + } + }, + }, + + "RegexInconsistencyVoteInit": &types.LogRegex{ + Regex: regexp.MustCompile("initiates vote on"), + InternalRegex: regexp.MustCompile("Member " + regexIdx + "\\(" + regexNodeName + "\\) initiates vote on " + regexUUID + ":" + regexSeqno + "," + regexErrorMD5 + ": (?P.*), Error_code:"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + node := submatches[groupNodeName] + seqno := submatches[groupSeqno] + errormd5 := submatches[groupErrorMD5] + errorstring := submatches["error"] + + c := types.Conflict{ + InitiatedBy: []string{node}, + Seqno: seqno, + VotePerNode: map[string]types.ConflictVote{node: types.ConflictVote{MD5: errormd5, Error: errorstring}}, + } + + ctx.Conflicts = ctx.Conflicts.Merge(c) + + return ctx, func(ctx types.LogCtx) string { + + if utils.SliceContains(ctx.OwnNames, node) { + return utils.Paint(utils.YellowText, "inconsistency vote started") + "(seqno:" + seqno + ")" + } + + return utils.Paint(utils.YellowText, "inconsistency vote started by "+node) + "(seqno:" + seqno + ")" + } + }, + }, + + "RegexInconsistencyVoteRespond": &types.LogRegex{ + Regex: regexp.MustCompile("responds to vote on "), + InternalRegex: regexp.MustCompile("Member " + regexIdx + "\\(" + regexNodeName + "\\) responds to vote on " + regexUUID + ":" + regexSeqno + "," + regexErrorMD5 + ": (?P.*)"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + node := submatches[groupNodeName] + seqno := submatches[groupSeqno] + errormd5 := submatches[groupErrorMD5] + errorstring := submatches["error"] + + latestConflict := ctx.Conflicts.ConflictWithSeqno(seqno) + if latestConflict == nil { + return ctx, nil + } + latestConflict.VotePerNode[node] = types.ConflictVote{MD5: errormd5, Error: errorstring} + + return ctx, func(ctx types.LogCtx) string { + + for _, name := range ctx.OwnNames { + vote, ok := latestConflict.VotePerNode[name] + if !ok { + continue + } + + return voteResponse(vote, *latestConflict) + } + + return "" + } + }, + }, + + "RegexInconsistencyVoted": &types.LogRegex{ + Regex: regexp.MustCompile("Inconsistency detected: Inconsistent by consensus"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "found inconsistent by vote")) + }, + }, + + "RegexInconsistencyWinner": &types.LogRegex{ + Regex: regexp.MustCompile("Winner: "), + InternalRegex: regexp.MustCompile("Winner: " + regexErrorMD5), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + errormd5 := submatches[groupErrorMD5] + + if len(ctx.Conflicts) == 0 { + return ctx, nil // nothing to guess + } + + c := ctx.Conflicts.ConflictFromMD5(errormd5) + if c == nil { + // some votes have been observed to be logged again + // sometimes days after the initial one + // the winner outcomes is not even always the initial one + + // as they don't add any helpful context, we should ignore + // plus, it would need multiline regexes, which is not supported here + return ctx, nil + } + c.Winner = errormd5 + + return ctx, func(ctx types.LogCtx) string { + out := "consistency vote(seqno:" + c.Seqno + "): " + for _, name := range ctx.OwnNames { + + vote, ok := c.VotePerNode[name] + if !ok { + continue + } + + if vote.MD5 == c.Winner { + return out + utils.Paint(utils.GreenText, "won") + } + return out + utils.Paint(utils.RedText, "lost") + } + return "" + } + }, + }, + + "RegexInconsistencyRecovery": &types.LogRegex{ + Regex: regexp.MustCompile("Recovering vote result from history"), + InternalRegex: regexp.MustCompile("Recovering vote result from history: " + regexUUID + ":" + regexSeqno + "," + regexErrorMD5), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + if len(ctx.OwnNames) == 0 { + return ctx, nil + } + + errormd5 := submatches[groupErrorMD5] + seqno := submatches[groupSeqno] + c := ctx.Conflicts.ConflictWithSeqno(seqno) + vote := types.ConflictVote{MD5: errormd5} + c.VotePerNode[ctx.OwnNames[len(ctx.OwnNames)-1]] = vote + + return ctx, types.SimpleDisplayer(voteResponse(vote, *c)) + }, + Verbosity: types.DebugMySQL, + }, +} + +func voteResponse(vote types.ConflictVote, conflict types.Conflict) string { + out := "consistency vote(seqno:" + conflict.Seqno + "): voted " + + initError := conflict.VotePerNode[conflict.InitiatedBy[0]] + switch vote.MD5 { + case "0000000000000000": + out += "Success" + case initError.MD5: + out += "same error" + default: + out += "different error" + } + + return out + +} diff --git a/src/go/pt-galera-log-explainer/regex/date.go b/src/go/pt-galera-log-explainer/regex/date.go new file mode 100644 index 00000000..973d37a5 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/date.go @@ -0,0 +1,117 @@ +package regex + +import ( + "fmt" + "strconv" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "github.com/rs/zerolog/log" +) + +// 5.5 date : 151027 6:02:49 +// 5.6 date : 2019-07-17 07:16:37 +//5.7 date : 2019-07-17T15:16:37.123456Z +//5.7 date : 2019-07-17T15:16:37.123456+01:00 +// 10.3 date: 2019-07-15 7:32:25 +var DateLayouts = []string{ + "2006-01-02T15:04:05.000000Z", // 5.7 + "2006-01-02T15:04:05.000000-07:00", // 5.7 + "060102 15:04:05", // 5.5 + "2006-01-02 15:04:05", // 5.6 + "2006-01-02 15:04:05", // 10.3, yes the extra space is needed + "2006/01/02 15:04:05", // sometimes found in socat errors +} + +// BetweenDateRegex generate a regex to filter mysql error log dates to just get +// events between 2 dates +// Currently limited to filter by day to produce "short" regexes. Finer events will be filtered later in code +// Trying to filter hours, minutes using regexes would produce regexes even harder to read +// while not really adding huge benefit as we do not expect so many events of interets +func BetweenDateRegex(since *time.Time, skipLeadingCircumflex bool) string { + /* + "2006-01-02 + "2006-01-0[3-9] + "2006-01-[1-9][0-9] + "2006-0[2-9]-[0-9]{2} + "2006-[1-9][0-9]-[0-9]{2} + "200[7-9]-[0-9]{2}-[0-9]{2} + "20[1-9][0-9]-[0-9]{2}-[0-9]{2} + */ + + separator := "|^" + if skipLeadingCircumflex { + separator = "|" + } + + regexConstructor := []struct { + unit int + unitToStr string + }{ + { + unit: since.Day(), + unitToStr: fmt.Sprintf("%02d", since.Day()), + }, + { + unit: int(since.Month()), + unitToStr: fmt.Sprintf("%02d", since.Month()), + }, + { + unit: since.Year(), + unitToStr: fmt.Sprintf("%d", since.Year())[2:], + }, + } + s := "" + for _, layout := range []string{"2006-01-02", "060102"} { + // base complete date + lastTransformed := since.Format(layout) + s += separator + lastTransformed + + for _, construct := range regexConstructor { + if construct.unit != 9 { + s += separator + utils.StringsReplaceReversed(lastTransformed, construct.unitToStr, string(construct.unitToStr[0])+"["+strconv.Itoa(construct.unit%10+1)+"-9]", 1) + } + // %1000 here is to cover the transformation of 2022 => 22 + s += separator + utils.StringsReplaceReversed(lastTransformed, construct.unitToStr, "["+strconv.Itoa((construct.unit%1000/10)+1)+"-9][0-9]", 1) + + lastTransformed = utils.StringsReplaceReversed(lastTransformed, construct.unitToStr, "[0-9][0-9]", 1) + + } + } + s += ")" + return "(" + s[1:] +} + +// basically capturing anything that does not have a date +// needed, else we would miss some logs, like wsrep recovery +func NoDatesRegex(skipLeadingCircumflex bool) string { + //return "((?![0-9]{4}-[0-9]{2}-[0-9]{2})|(?![0-9]{6}))" + if skipLeadingCircumflex { + return "(?![0-9]{4})" + } + return "^(?![0-9]{4})" +} + +/* +SYSLOG_DATE="\(Jan\|Feb\|Mar\|Apr\|May\|Jun\|Jul\|Aug\|Sep\|Oct\|Nov\|Dec\) \( \|[0-9]\)[0-9] [0-9]\{2\}:[0-9]\{2\}:[0-9]\{2\}" +REGEX_LOG_PREFIX="$REGEX_DATE \?[0-9]* " +*/ + +const k8sprefix = `{"log":"` + +func SearchDateFromLog(logline string) (time.Time, string, bool) { + if logline[:len(k8sprefix)] == k8sprefix { + logline = logline[len(k8sprefix):] + } + for _, layout := range DateLayouts { + if len(logline) < len(layout) { + continue + } + t, err := time.Parse(layout, logline[:len(layout)]) + if err == nil { + return t, layout, true + } + } + log.Debug().Str("log", logline).Msg("could not find date from log") + return time.Time{}, "", false +} diff --git a/src/go/pt-galera-log-explainer/regex/date_test.go b/src/go/pt-galera-log-explainer/regex/date_test.go new file mode 100644 index 00000000..0778e315 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/date_test.go @@ -0,0 +1,44 @@ +package regex + +import ( + "testing" + "time" +) + +func TestDateAfter(t *testing.T) { + tests := []struct { + input string + format string + expected string + }{ + { + input: "2006-01-02T15:04:05Z", + format: time.RFC3339, + expected: "(^2006-01-02|^2006-01-0[3-9]|^2006-01-[1-9][0-9]|^2006-0[2-9]-[0-9][0-9]|^2006-[1-9][0-9]-[0-9][0-9]|^200[7-9]-[0-9][0-9]-[0-9][0-9]|^20[1-9][0-9]-[0-9][0-9]-[0-9][0-9]|^060102|^06010[3-9]|^0601[1-9][0-9]|^060[2-9][0-9][0-9]|^06[1-9][0-9][0-9][0-9]|^0[7-9][0-9][0-9][0-9][0-9]|^[1-9][0-9][0-9][0-9][0-9][0-9])", + }, + { + input: "2006-01-02", + format: "2006-01-02", + expected: "(^2006-01-02|^2006-01-0[3-9]|^2006-01-[1-9][0-9]|^2006-0[2-9]-[0-9][0-9]|^2006-[1-9][0-9]-[0-9][0-9]|^200[7-9]-[0-9][0-9]-[0-9][0-9]|^20[1-9][0-9]-[0-9][0-9]-[0-9][0-9]|^060102|^06010[3-9]|^0601[1-9][0-9]|^060[2-9][0-9][0-9]|^06[1-9][0-9][0-9][0-9]|^0[7-9][0-9][0-9][0-9][0-9]|^[1-9][0-9][0-9][0-9][0-9][0-9])", + }, + { + input: "060102", + format: "060102", + expected: "(^2006-01-02|^2006-01-0[3-9]|^2006-01-[1-9][0-9]|^2006-0[2-9]-[0-9][0-9]|^2006-[1-9][0-9]-[0-9][0-9]|^200[7-9]-[0-9][0-9]-[0-9][0-9]|^20[1-9][0-9]-[0-9][0-9]-[0-9][0-9]|^060102|^06010[3-9]|^0601[1-9][0-9]|^060[2-9][0-9][0-9]|^06[1-9][0-9][0-9][0-9]|^0[7-9][0-9][0-9][0-9][0-9]|^[1-9][0-9][0-9][0-9][0-9][0-9])", + }, + { + input: "2022-01-22", + format: "2006-01-02", + expected: "(^2022-01-22|^2022-01-2[3-9]|^2022-01-[3-9][0-9]|^2022-0[2-9]-[0-9][0-9]|^2022-[1-9][0-9]-[0-9][0-9]|^202[3-9]-[0-9][0-9]-[0-9][0-9]|^20[3-9][0-9]-[0-9][0-9]-[0-9][0-9]|^220122|^22012[3-9]|^2201[3-9][0-9]|^220[2-9][0-9][0-9]|^22[1-9][0-9][0-9][0-9]|^2[3-9][0-9][0-9][0-9][0-9]|^[3-9][0-9][0-9][0-9][0-9][0-9])", + }, + } + + for _, test := range tests { + d, _ := time.Parse(test.format, test.input) + s := BetweenDateRegex(&d, false) + if s != test.expected { + t.Log("wrong date regex:", s) + t.Fail() + } + } +} diff --git a/src/go/pt-galera-log-explainer/regex/events.go b/src/go/pt-galera-log-explainer/regex/events.go new file mode 100644 index 00000000..a0c80ba7 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/events.go @@ -0,0 +1,179 @@ +package regex + +import ( + "regexp" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + setType(types.EventsRegexType, EventsMap) +} + +var EventsMap = types.RegexMap{ + "RegexStarting": &types.LogRegex{ + Regex: regexp.MustCompile("starting as process"), + InternalRegex: regexp.MustCompile("\\(mysqld " + regexVersion + ".*\\)"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.Version = submatches[groupVersion] + + msg := "starting(" + ctx.Version + if isShutdownReasonMissing(ctx) { + msg += ", " + utils.Paint(utils.YellowText, "could not catch how/when it stopped") + } + msg += ")" + ctx.SetState("OPEN") + + return ctx, types.SimpleDisplayer(msg) + }, + }, + "RegexShutdownComplete": &types.LogRegex{ + Regex: regexp.MustCompile("mysqld: Shutdown complete"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "shutdown complete")) + }, + }, + "RegexTerminated": &types.LogRegex{ + Regex: regexp.MustCompile("mysqld: Terminated"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "terminated")) + }, + }, + "RegexGotSignal6": &types.LogRegex{ + Regex: regexp.MustCompile("mysqld got signal 6"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "crash: got signal 6")) + }, + }, + "RegexGotSignal11": &types.LogRegex{ + Regex: regexp.MustCompile("mysqld got signal 11"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "crash: got signal 11")) + }, + }, + "RegexShutdownSignal": &types.LogRegex{ + Regex: regexp.MustCompile("Normal|Received shutdown"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "received shutdown")) + }, + }, + + // 2023-06-12T07:51:38.135646Z 0 [Warning] [MY-000000] [Galera] Exception while mapping writeset addr: 0x7fb668d4e568, seqno: 2770385572449823232, size: 73316, ctx: 0x56128412e0c0, flags: 1. store: 1, type: 32 into [555, 998): 'deque::_M_new_elements_at_back'. Aborting GCache recovery. + + "RegexAborting": &types.LogRegex{ + Regex: regexp.MustCompile("Aborting"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "ABORTING")) + }, + }, + + "RegexWsrepLoad": &types.LogRegex{ + Regex: regexp.MustCompile("wsrep_load\\(\\): loading provider library"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("OPEN") + if regexWsrepLoadNone.MatchString(log) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.GreenText, "started(standalone)")) + } + return ctx, types.SimpleDisplayer(utils.Paint(utils.GreenText, "started(cluster)")) + }, + }, + "RegexWsrepRecovery": &types.LogRegex{ + // INFO: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1 + Regex: regexp.MustCompile("Recovered position"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + msg := "wsrep recovery" + // if state is joiner, it can be due to sst + // if state is open, it is just a start sequence depending on platform + if isShutdownReasonMissing(ctx) && ctx.State() != "JOINER" && ctx.State() != "OPEN" { + msg += "(" + utils.Paint(utils.YellowText, "could not catch how/when it stopped") + ")" + } + ctx.SetState("RECOVERY") + + return ctx, types.SimpleDisplayer(msg) + }, + }, + + "RegexUnknownConf": &types.LogRegex{ + Regex: regexp.MustCompile("unknown variable"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + split := strings.Split(log, "'") + v := "?" + if len(split) > 0 { + v = split[1] + } + if len(v) > 20 { + v = v[:20] + "..." + } + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "unknown variable") + ": " + v) + }, + }, + + "RegexAssertionFailure": &types.LogRegex{ + Regex: regexp.MustCompile("Assertion failure"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "ASSERTION FAILURE")) + }, + }, + "RegexBindAddressAlreadyUsed": &types.LogRegex{ + Regex: regexp.MustCompile("asio error .bind: Address already in use"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "bind address already used")) + }, + }, + "RegexTooManyConnections": &types.LogRegex{ + Regex: regexp.MustCompile("Too many connections"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "too many connections")) + }, + }, + + "RegexReversingHistory": &types.LogRegex{ + Regex: regexp.MustCompile("Reversing history"), + InternalRegex: regexp.MustCompile("Reversing history: " + regexSeqno + " -> [0-9]*, this member has applied (?P[0-9]*) more events than the primary component"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + return ctx, types.SimpleDisplayer(utils.Paint(utils.BrightRedText, "having "+submatches["diff"]+" more events than the other nodes, data loss possible")) + }, + }, +} +var regexWsrepLoadNone = regexp.MustCompile("none") + +// isShutdownReasonMissing is returning true if the latest wsrep state indicated a "working" node +func isShutdownReasonMissing(ctx types.LogCtx) bool { + return ctx.State() != "DESTROYED" && ctx.State() != "CLOSED" && ctx.State() != "RECOVERY" && ctx.State() != "" +} + +/* + + +2023-05-09T17:39:19.955040Z 51 [Warning] [MY-000000] [Galera] failed to replay trx: source: fb9d6310-ee8b-11ed-8aee-f7542ad73e53 version: 5 local: 1 flags: 1 conn_id: 48 trx_id: 2696 tstamp: 1683653959142522853; state: EXECUTING:0->REPLICATING:782->CERTIFYING:3509->APPLYING:3748->COMMITTING:1343->COMMITTED:-1 +2023-05-09T17:39:19.955085Z 51 [Warning] [MY-000000] [Galera] Invalid state in replay for trx source: fb9d6310-ee8b-11ed-8aee-f7542ad73e53 version: 5 local: 1 flags: 1 conn_id: 48 trx_id: 2696 tstamp: 1683653959142522853; state: EXECUTING:0->REPLICATING:782->CERTIFYING:3509->APPLYING:3748->COMMITTING:1343->COMMITTED:-1 (FATAL) + at galera/src/replicator_smm.cpp:replay_trx():1247 + + +2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [Galera] gcs/src/gcs_group.cpp:group_post_state_exchange():431: Reversing history: 312312 -> 20121, this member has applied 12345 more events than the primary component.Data loss is possible. Must abort. + +2023-06-07T02:50:17.288285-06:00 0 [ERROR] WSREP: Requested size 114209078 for '/var/lib/mysql//galera.cache' exceeds available storage space 1: 28 (No space left on device) + +2023-01-01 11:33:15 2101097 [ERROR] mariadbd: Disk full (/tmp/#sql-temptable-.....MAI); waiting for someone to free some space... (errno: 28 "No space left on device") + +2023-06-13 1:15:27 35 [Note] WSREP: MDL BF-BF conflict + +*/ diff --git a/src/go/pt-galera-log-explainer/regex/file.go b/src/go/pt-galera-log-explainer/regex/file.go new file mode 100644 index 00000000..d2a01e3e --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/file.go @@ -0,0 +1,33 @@ +package regex + +import "regexp" + +var RegexOperatorFileType = regexp.MustCompile(`\"file\":\"/([a-z]+/)+(?P[a-z._-]+.log)\"}$`) +var RegexOperatorShellDebugFileType = regexp.MustCompile(`^\+`) + +func FileType(line string, operator bool) string { + if !operator { + // if not operator, we can't really guess + return "error.log" + } + r, err := internalRegexSubmatch(RegexOperatorFileType, line) + if err != nil { + if RegexOperatorShellDebugFileType.MatchString(line) { + return "operator shell" + } + return "" + } + t := r[RegexOperatorFileType.SubexpIndex("filetype")] + switch t { + case "mysqld.post.processing.log": + return "post.processing.log" + case "wsrep_recovery_verbose.log": + return "recovery.log" + case "mysqld-error.log": + return "error.log" + case "innobackup.backup.log": + return "backup.log" + default: + return t + } +} diff --git a/src/go/pt-galera-log-explainer/regex/file_test.go b/src/go/pt-galera-log-explainer/regex/file_test.go new file mode 100644 index 00000000..ce72fecf --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/file_test.go @@ -0,0 +1,47 @@ +package regex + +import ( + "testing" +) + +func TestFileType(t *testing.T) { + tests := []struct { + inputline string + inputoperator bool + expected string + }{ + { + inputline: `{"log":"2023-07-11T06:03:51.109165Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.\n","file":"/var/lib/mysql/wsrep_recovery_verbose.log"}`, + inputoperator: true, + expected: "recovery.log", + }, + { + inputline: `{"log":"2023-07-11T06:03:51.109165Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.\n","file":"/var/lib/mysql/mysqld-error.log"}`, + inputoperator: true, + expected: "error.log", + }, + { + inputline: `{"log":"2023-07-11T06:03:51.109165Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.\n","file":"/var/lib/mysql/mysqld.post.processing.log"}`, + inputoperator: true, + expected: "post.processing.log", + }, + { + inputline: `+ NODE_PORT=3306`, + inputoperator: true, + expected: "operator shell", + }, + { + inputline: `++ hostname -f`, + inputoperator: true, + expected: "operator shell", + }, + } + + for _, test := range tests { + + out := FileType(test.inputline, test.inputoperator) + if out != test.expected { + t.Errorf("expected: %s, got: %s", test.expected, out) + } + } +} diff --git a/src/go/pt-galera-log-explainer/regex/idents.go b/src/go/pt-galera-log-explainer/regex/idents.go new file mode 100644 index 00000000..ae77fb58 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/idents.go @@ -0,0 +1,212 @@ +package regex + +import ( + "regexp" + "strconv" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + init_add_regexes() + setType(types.IdentRegexType, IdentsMap) +} + +var IdentsMap = types.RegexMap{ + // sourceNode is to identify from which node this log was taken + "RegexSourceNode": &types.LogRegex{ + Regex: regexp.MustCompile("(local endpoint for a connection, blacklisting address)|(points to own listening address, blacklisting)"), + InternalRegex: regexp.MustCompile("\\(" + regexNodeHash + ", '.+'\\).+" + regexNodeIPMethod), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + ctx.AddOwnIP(ip) + return ctx, types.SimpleDisplayer(ip + " is local") + }, + Verbosity: types.DebugMySQL, + }, + + // 2022-12-18T01:03:17.950545Z 0 [Note] [MY-000000] [Galera] Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 127.0.0.1; + "RegexBaseHost": &types.LogRegex{ + Regex: regexp.MustCompile("base_host"), + InternalRegex: regexp.MustCompile("base_host = " + regexNodeIP), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + ctx.AddOwnIP(ip) + return ctx, types.SimpleDisplayer(ctx.OwnIPs[len(ctx.OwnIPs)-1] + " is local") + }, + Verbosity: types.DebugMySQL, + }, + + // 0: 015702fc-32f5-11ed-a4ca-267f97316394, node-1 + // 1: 08dd5580-32f7-11ed-a9eb-af5e3d01519e, garb + // TO *never* DO: store indexes to later search for them using SST infos and STATES EXCHANGES logs. EDIT: is definitely NOT reliable + "RegexMemberAssociations": &types.LogRegex{ + Regex: regexp.MustCompile("[0-9]: [a-z0-9]+-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]+, [a-zA-Z0-9-_]+"), + InternalRegex: regexp.MustCompile(regexIdx + ": " + regexUUID + ", " + regexNodeName), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + idx := submatches[groupIdx] + hash := submatches[groupUUID] + nodename := utils.ShortNodeName(submatches[groupNodeName]) + + // nodenames are truncated after 32 characters ... + if len(nodename) == 31 { + return ctx, nil + } + shorthash := utils.UUIDToShortUUID(hash) + ctx.HashToNodeName[shorthash] = nodename + + if ctx.MyIdx == idx && (ctx.IsPrimary() || ctx.MemberCount == 1) { + ctx.AddOwnHash(shorthash) + ctx.AddOwnName(nodename) + } + + return ctx, types.SimpleDisplayer(shorthash + " is " + nodename) + }, + Verbosity: types.DebugMySQL, + }, + + "RegexMemberCount": &types.LogRegex{ + Regex: regexp.MustCompile("members.[0-9]+.:"), + InternalRegex: regexp.MustCompile(regexMembers), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + members := submatches[groupMembers] + + membercount, err := strconv.Atoi(members) + if err != nil { + return ctx, nil + } + ctx.MemberCount = membercount + + return ctx, types.SimpleDisplayer("view member count: " + members) + }, + Verbosity: types.DebugMySQL, + }, + + // My UUID: 6938f4ae-32f4-11ed-be8d-8a0f53f88872 + "RegexOwnUUID": &types.LogRegex{ + Regex: regexp.MustCompile("My UUID"), + InternalRegex: regexp.MustCompile("My UUID: " + regexUUID), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + shorthash := utils.UUIDToShortUUID(submatches[groupUUID]) + + ctx.AddOwnHash(shorthash) + + return ctx, types.SimpleDisplayer(shorthash + " is local") + }, + Verbosity: types.DebugMySQL, + }, + + // 2023-01-06T06:59:26.527748Z 0 [Note] WSREP: (9509c194, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: + "RegexOwnUUIDFromMessageRelay": &types.LogRegex{ + Regex: regexp.MustCompile("turning message relay requesting"), + InternalRegex: regexp.MustCompile("\\(" + regexNodeHash + ", '" + regexNodeIPMethod + "'\\)"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + hash := submatches[groupNodeHash] + ctx.AddOwnHash(hash) + + return ctx, types.SimpleDisplayer(hash + " is local") + }, + Verbosity: types.DebugMySQL, + }, + + // 2023-01-06T07:05:35.693861Z 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2 + "RegexMyIDXFromComponent": &types.LogRegex{ + Regex: regexp.MustCompile("New COMPONENT:"), + InternalRegex: regexp.MustCompile("New COMPONENT:.*my_idx = " + regexIdx), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + idx := submatches[groupIdx] + ctx.MyIdx = idx + return ctx, types.SimpleDisplayer("my_idx=" + idx) + }, + Verbosity: types.DebugMySQL, + }, + + /* + + can't be trusted, from actual log: + View: + id: : + status: primary + protocol_version: 4 + capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO + final: no + own_index: 1 + members(3): + 0: , node0 + 1: , node1 + 2: , node2 + ================================================= + 2023-05-28T21:18:23.184707-05:00 2 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification. + 2023-05-28T21:18:23.193459-05:00 0 [Note] [MY-000000] [Galera] STATE EXCHANGE: sent state msg: + 2023-05-28T21:18:23.195777-05:00 0 [Note] [MY-000000] [Galera] STATE EXCHANGE: got state msg: from 0 (node1) + 2023-05-28T21:18:23.195805-05:00 0 [Note] [MY-000000] [Galera] STATE EXCHANGE: got state msg: from 1 (node2) + + + "RegexOwnNameFromStateExchange": &types.LogRegex{ + Regex: regexp.MustCompile("STATE EXCHANGE: got state msg"), + InternalRegex: regexp.MustCompile("STATE EXCHANGE:.* from " + regexIdx + " \\(" + regexNodeName + "\\)"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + r, err := internalRegexSubmatch(internalRegex, log) + if err != nil { + return ctx, nil + } + + idx := submatches[groupIdx] + name := submatches[groupNodeName] + if idx != ctx.MyIdx { + return ctx, types.SimpleDisplayer("name(" + name + ") from unknown idx") + } + + if ctx.State == "NON-PRIMARY" { + return ctx, types.SimpleDisplayer("name(" + name + ") can't be trusted as it's non-primary") + } + + ctx.AddOwnName(name) + return ctx, types.SimpleDisplayer("local name:" + name) + }, + Verbosity: types.DebugMySQL, + }, + */ +} + +func init_add_regexes() { + // 2023-01-06T07:05:34.035959Z 0 [Note] WSREP: (9509c194, 'tcp://0.0.0.0:4567') connection established to 838ebd6d tcp://ip:4567 + IdentsMap["RegexOwnUUIDFromEstablished"] = &types.LogRegex{ + Regex: regexp.MustCompile("connection established to"), + InternalRegex: IdentsMap["RegexOwnUUIDFromMessageRelay"].InternalRegex, + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return IdentsMap["RegexOwnUUIDFromMessageRelay"].Handler(submatches, ctx, log) + }, + Verbosity: types.DebugMySQL, + } + + IdentsMap["RegexOwnIndexFromView"] = &types.LogRegex{ + Regex: regexp.MustCompile("own_index:"), + InternalRegex: regexp.MustCompile("own_index: " + regexIdx), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return IdentsMap["RegexMyIDXFromComponent"].Handler(submatches, ctx, log) + }, + Verbosity: types.DebugMySQL, + } + + // 2023-01-06T07:05:35.698869Z 7 [Note] WSREP: New cluster view: global state: 00000000-0000-0000-0000-000000000000:0, view# 10: Primary, number of nodes: 2, my index: 0, protocol version 3 + // WARN: my index seems to always be 0 on this log on certain version. It had broken some nodenames + /* + IdentsMap["RegexMyIDXFromClusterView"] = &types.LogRegex{ + Regex: regexp.MustCompile("New cluster view:"), + InternalRegex: regexp.MustCompile("New cluster view:.*my index: " + regexIdx + ","), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return IdentsMap["RegexMyIDXFromComponent"].Handler(internalRegex, ctx, log) + }, + Verbosity: types.DebugMySQL, + } + */ +} diff --git a/src/go/pt-galera-log-explainer/regex/operator.go b/src/go/pt-galera-log-explainer/regex/operator.go new file mode 100644 index 00000000..480b0337 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/operator.go @@ -0,0 +1,55 @@ +package regex + +import ( + "regexp" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" +) + +func init() { + setType(types.PXCOperatorRegexType, PXCOperatorMap) +} + +// Regexes from this type should only be about operator extra logs +// it should not contain Galera logs +// Specifically operators are dumping configuration files, recoveries, script outputs, ... +// only those should be handled here, they are specific to pxc operator but still very insightful +var PXCOperatorMap = types.RegexMap{ + "RegexNodeNameFromEnv": &types.LogRegex{ + Regex: regexp.MustCompile(". NODE_NAME="), + InternalRegex: regexp.MustCompile("NODE_NAME=" + regexNodeName), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + nodename := submatches[groupNodeName] + nodename, _, _ = strings.Cut(nodename, ".") + ctx.AddOwnName(nodename) + return ctx, types.SimpleDisplayer("local name:" + nodename) + }, + Verbosity: types.DebugMySQL, + }, + + "RegexNodeIPFromEnv": &types.LogRegex{ + Regex: regexp.MustCompile(". NODE_IP="), + InternalRegex: regexp.MustCompile("NODE_IP=" + regexNodeIP), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + ctx.AddOwnIP(ip) + return ctx, types.SimpleDisplayer("local ip:" + ip) + }, + Verbosity: types.DebugMySQL, + }, + + // Why is it not in regular "views" regexes: + // it could have been useful as an "verbosity=types.Detailed" regexes, very rarely + // but in context of operators, it is actually a very important information + "RegexGcacheScan": &types.LogRegex{ + // those "operators" regexes do not have the log prefix added implicitely. It's not strictly needed, but + // it will help to avoid catching random piece of log out of order + Regex: regexp.MustCompile("^{\"log\":\".*GCache::RingBuffer initial scan"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer("recovering gcache") + }, + }, +} diff --git a/src/go/pt-galera-log-explainer/regex/regex.go b/src/go/pt-galera-log-explainer/regex/regex.go new file mode 100644 index 00000000..2a1c6a03 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/regex.go @@ -0,0 +1,72 @@ +package regex + +import ( + "errors" + "fmt" + "regexp" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" +) + +func internalRegexSubmatch(regex *regexp.Regexp, log string) ([]string, error) { + slice := regex.FindStringSubmatch(log) + if len(slice) == 0 { + return nil, errors.New(fmt.Sprintf("Could not find submatch from log \"%s\" using pattern \"%s\"", log, regex.String())) + } + return slice, nil +} + +func setType(t types.RegexType, regexes types.RegexMap) { + for _, regex := range regexes { + regex.Type = t + } + return +} + +// SetVerbosity accepts any LogRegex +// Some can be useful to construct context, but we can choose not to display them +func SetVerbosity(verbosity types.Verbosity, regexes types.RegexMap) { + for _, regex := range regexes { + regex.Verbosity = verbosity + } + return +} + +func AllRegexes() types.RegexMap { + IdentsMap.Merge(ViewsMap).Merge(SSTMap).Merge(EventsMap).Merge(StatesMap).Merge(ApplicativeMap) + return IdentsMap +} + +// general building block wsrep regexes +// It's later used to identify subgroups easier +var ( + groupMethod = "ssltcp" + groupNodeIP = "nodeip" + groupNodeHash = "uuid" + groupUUID = "uuid" // same value as groupnodehash, because both are used in same context + groupNodeName = "nodename" + groupNodeName2 = "nodename2" + groupIdx = "idx" + groupSeqno = "seqno" + groupMembers = "members" + groupVersion = "version" + groupErrorMD5 = "errormd5" + regexMembers = "(?P<" + groupMembers + ">[0-9]{1,2})" + regexNodeHash = "(?P<" + groupNodeHash + ">[a-zA-Z0-9-_]+)" + regexNodeName = "(?P<" + groupNodeName + `>[a-zA-Z0-9-_\.]+)` + regexNodeName2 = strings.Replace(regexNodeName, groupNodeName, groupNodeName2, 1) + regexUUID = "(?P<" + groupUUID + ">[a-z0-9]+-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]+)" // eg ed97c863-d5c9-11ec-8ab7-671bbd2d70ef + regexNodeHash1Dash = "(?P<" + groupNodeHash + ">[a-z0-9]+-[a-z0-9]{4})" // eg ed97c863-8ab7 + 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})" + regexVersion = "(?P<" + groupVersion + ">(5|8|10|11)\\.[0-9]\\.[0-9]{1,2})" + regexErrorMD5 = "(?P<" + groupErrorMD5 + ">[a-z0-9]*)" +) + +func IsNodeUUID(s string) bool { + b, _ := regexp.MatchString(regexUUID, s) + return b +} diff --git a/src/go/pt-galera-log-explainer/regex/regex_test.go b/src/go/pt-galera-log-explainer/regex/regex_test.go new file mode 100644 index 00000000..c9a675fa --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/regex_test.go @@ -0,0 +1,1286 @@ +package regex + +import ( + "io/ioutil" + "os/exec" + "testing" + + "github.com/davecgh/go-spew/spew" + "github.com/google/go-cmp/cmp" + "github.com/google/go-cmp/cmp/cmpopts" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "github.com/pkg/errors" +) + +func TestRegexes(t *testing.T) { + utils.SkipColor = true + tests := []struct { + name string + log, expectedOut string + inputCtx types.LogCtx + inputState string + expectedState string + expectedCtx types.LogCtx + displayerExpectedNil bool + expectedErr bool + mapToTest types.RegexMap + key string + }{ + { + name: "8.0.30-22", + log: "2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-22) starting as process 1", + expectedCtx: types.LogCtx{Version: "8.0.30"}, + expectedState: "OPEN", + expectedOut: "starting(8.0.30)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "8.0.2-22", + log: "2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.2-22) starting as process 1", + expectedCtx: types.LogCtx{Version: "8.0.2"}, + expectedState: "OPEN", + expectedOut: "starting(8.0.2)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "5.7.31-34-log", + log: "2001-01-01T01:01:01.000000Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.31-34-log) starting as process 2 ...", + expectedCtx: types.LogCtx{Version: "5.7.31"}, + expectedState: "OPEN", + expectedOut: "starting(5.7.31)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "10.4.25-MariaDB-log", + log: "2001-01-01 01:01:01 0 [Note] /usr/sbin/mysqld (mysqld 10.4.25-MariaDB-log) starting as process 2 ...", + expectedCtx: types.LogCtx{Version: "10.4.25"}, + expectedState: "OPEN", + expectedOut: "starting(10.4.25)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "10.2.31-MariaDB-1:10.2.31+maria~bionic-log", + log: "2001-01-01 01:01:01 0 [Note] /usr/sbin/mysqld (mysqld 10.2.31-MariaDB-1:10.2.31+maria~bionic-log) starting as process 2 ...", + expectedCtx: types.LogCtx{Version: "10.2.31"}, + expectedState: "OPEN", + expectedOut: "starting(10.2.31)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "5.7.28-enterprise-commercial-advanced-log", + log: "2001-01-01T01:01:01.000000Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.28-enterprise-commercial-advanced-log) starting as process 2 ...", + expectedCtx: types.LogCtx{Version: "5.7.28"}, + expectedState: "OPEN", + expectedOut: "starting(5.7.28)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "8.0.30 operator", + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-22.1) starting as process 1\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + expectedCtx: types.LogCtx{Version: "8.0.30"}, + expectedState: "OPEN", + expectedOut: "starting(8.0.30)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "wrong version 7.0.0", + log: "2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 7.0.0-22) starting as process 1", + displayerExpectedNil: true, + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "wrong version 8.12.0", + log: "2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.12.0-22) starting as process 1", + displayerExpectedNil: true, + mapToTest: EventsMap, + key: "RegexStarting", + }, + { + name: "could not catch how it stopped", + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-22.1) starting as process 1\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + expectedCtx: types.LogCtx{Version: "8.0.30"}, + expectedState: "OPEN", + inputState: "OPEN", + expectedOut: "starting(8.0.30, could not catch how/when it stopped)", + mapToTest: EventsMap, + key: "RegexStarting", + }, + + { + + log: "2001-01-01T01:01:01.000000Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.23-14.1) Percona XtraDB Cluster (GPL), Release rel14, Revision d3b9a1d, WSREP version 26.4.3.", + expectedState: "CLOSED", + expectedOut: "shutdown complete", + mapToTest: EventsMap, + key: "RegexShutdownComplete", + }, + + { + log: "2001-01-01 01:01:01 140430087788288 [Note] WSREP: /opt/rh-mariadb102/root/usr/libexec/mysqld: Terminated.", + expectedState: "CLOSED", + expectedOut: "terminated", + mapToTest: EventsMap, + key: "RegexTerminated", + }, + { + log: "2001-01-01T01:01:01.000000Z 8 [Note] WSREP: /usr/sbin/mysqld: Terminated.", + expectedState: "CLOSED", + expectedOut: "terminated", + mapToTest: EventsMap, + key: "RegexTerminated", + }, + + { + log: "01:01:01 UTC - mysqld got signal 6 ;", + expectedState: "CLOSED", + expectedOut: "crash: got signal 6", + mapToTest: EventsMap, + key: "RegexGotSignal6", + }, + { + log: "01:01:01 UTC - mysqld got signal 11 ;", + expectedState: "CLOSED", + expectedOut: "crash: got signal 11", + mapToTest: EventsMap, + key: "RegexGotSignal11", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [WSREP] Received shutdown signal. Will sleep for 10 secs before initiating shutdown. pxc_maint_mode switched to SHUTDOWN", + expectedState: "CLOSED", + expectedOut: "received shutdown", + mapToTest: EventsMap, + key: "RegexShutdownSignal", + }, + { + log: "2001-01-01 01:01:01 139688443508480 [Note] /opt/rh-mariadb102/root/usr/libexec/mysqld (unknown): Normal shutdown", + expectedState: "CLOSED", + expectedOut: "received shutdown", + mapToTest: EventsMap, + key: "RegexShutdownSignal", + }, + { + log: "2001-01-01 1:01:01 0 [Note] /usr/sbin/mariadbd (initiated by: unknown): Normal shutdown", + expectedState: "CLOSED", + expectedOut: "received shutdown", + mapToTest: EventsMap, + key: "RegexShutdownSignal", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-010119] [Server] Aborting", + expectedState: "CLOSED", + expectedOut: "ABORTING", + mapToTest: EventsMap, + key: "RegexAborting", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] wsrep_load(): loading provider library '/usr/lib64/galera4/libgalera_smm.so'", + expectedState: "OPEN", + expectedOut: "started(cluster)", + mapToTest: EventsMap, + key: "RegexWsrepLoad", + }, + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] wsrep_load(): loading provider library 'none'", + expectedState: "OPEN", + expectedOut: "started(standalone)", + mapToTest: EventsMap, + key: "RegexWsrepLoad", + }, + + { + log: "2001-01-01 01:01:01 140557650536640 [Note] WSREP: wsrep_load(): loading provider library '/opt/rh-mariadb102/root/usr/lib64/galera/libgalera_smm.so'", + expectedState: "OPEN", + expectedOut: "started(cluster)", + mapToTest: EventsMap, + key: "RegexWsrepLoad", + }, + + { + log: "2001-01-01T01:01:01.000000Z 3 [Note] [MY-000000] [Galera] Recovered position from storage: 7780bb61-87cf-11eb-b53b-6a7c64b0fee3:23506640", + expectedState: "RECOVERY", + expectedOut: "wsrep recovery", + mapToTest: EventsMap, + key: "RegexWsrepRecovery", + }, + { + log: " INFO: WSREP: Recovered position 9a4db4a5-5cf1-11ec-940d-6ba8c5905c02:30", + expectedState: "RECOVERY", + expectedOut: "wsrep recovery", + mapToTest: EventsMap, + key: "RegexWsrepRecovery", + }, + { + log: " INFO: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1", + expectedState: "RECOVERY", + expectedOut: "wsrep recovery", + mapToTest: EventsMap, + key: "RegexWsrepRecovery", + }, + { + name: "not unknown", + log: " INFO: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1", + expectedState: "RECOVERY", + inputState: "OPEN", + expectedOut: "wsrep recovery", + mapToTest: EventsMap, + key: "RegexWsrepRecovery", + }, + { + name: "could not catch how it stopped", + log: " INFO: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1", + expectedState: "RECOVERY", + inputState: "SYNCED", + expectedOut: "wsrep recovery(could not catch how/when it stopped)", + mapToTest: EventsMap, + key: "RegexWsrepRecovery", + }, + + { + log: "2001-01-01T01:01:01.045425-05:00 0 [ERROR] unknown variable 'validate_password_length=8'", + expectedOut: "unknown variable: validate_password_le...", + mapToTest: EventsMap, + key: "RegexUnknownConf", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: btr0cur.cc:296:btr_page_get_prev(get_block->frame, mtr) == page_get_page_no(page) thread 139538894652992", + expectedState: "CLOSED", + expectedOut: "ASSERTION FAILURE", + mapToTest: EventsMap, + key: "RegexAssertionFailure", + }, + + { + log: "2001-01-01 5:06:12 47285568576576 [ERROR] WSREP: failed to open gcomm backend connection: 98: error while trying to listen 'tcp://0.0.0.0:4567?socket.non_blocking=1', asio error 'bind: Address already in use': 98 (Address already in use)", + expectedState: "CLOSED", + expectedOut: "bind address already used", + mapToTest: EventsMap, + key: "RegexBindAddressAlreadyUsed", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [Galera] gcs/src/gcs_group.cpp:group_post_state_exchange():431: Reversing history: 150 -> 10, this member has applied 140 more events than the primary component.Data loss is possible. Must abort.", + expectedOut: "having 140 more events than the other nodes, data loss possible", + mapToTest: EventsMap, + key: "RegexReversingHistory", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] (90002222-1111, 'ssl://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address ssl://127.0.0.1:4567", + expectedCtx: types.LogCtx{OwnIPs: []string{"127.0.0.1"}}, + expectedOut: "127.0.0.1 is local", + mapToTest: IdentsMap, + key: "RegexSourceNode", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 127.0.0.1; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 10; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 4; evs.view_forget_timeout = PT24H; gcache.dir = /data/mysql/; gcache.freeze_purge_at_seqno = -1; gcache.keep_pages_count = 0; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 100; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.recovery = true; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = PT30S; pc.weight = 1; protonet.backend = asio; protonet.version = 0; repl.causal_read_timeout = PT30S; repl.commit_order = 3; repl.key_format = FLAT8; repl.max_ws_size = 2147483647; repl.proto_max = 10; socket.checksum = 2; socket.recv_buf_size = auto; socket.send_buf_size = auto; socket.ssl_ca = ca.pem; socket.ssl_cert = server-cert.pem; socket.ssl_cipher = ; socket.ssl_compression = YES; socket.ssl_key = server-key.pem;", + expectedCtx: types.LogCtx{OwnIPs: []string{"127.0.0.1"}}, + expectedOut: "127.0.0.1 is local", + mapToTest: IdentsMap, + key: "RegexBaseHost", + }, + + { + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, node1", + inputCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 1, + OwnHashes: []string{}, + OwnNames: []string{}, + HashToNodeName: map[string]string{}, + }, + inputState: "PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 1, + OwnHashes: []string{"015702fc-a4ca"}, + OwnNames: []string{"node1"}, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, node1", + inputCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 1, + OwnHashes: []string{}, + OwnNames: []string{}, + HashToNodeName: map[string]string{}, + }, + inputState: "NON-PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 1, + OwnHashes: []string{"015702fc-a4ca"}, + OwnNames: []string{"node1"}, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "NON-PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, node1", + inputCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 2, + HashToNodeName: map[string]string{}, + }, + inputState: "NON-PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "0", + MemberCount: 2, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "NON-PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + log: " 1: 015702fc-32f5-11ed-a4ca-267f97316394, node1", + inputCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + OwnHashes: []string{}, + OwnNames: []string{}, + HashToNodeName: map[string]string{}, + }, + inputState: "PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + OwnHashes: []string{"015702fc-a4ca"}, + OwnNames: []string{"node1"}, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, node1", + inputCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + HashToNodeName: map[string]string{}, + }, + inputState: "PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, node1.with.complete.fqdn", + inputCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + HashToNodeName: map[string]string{}, + }, + inputState: "PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + HashToNodeName: map[string]string{"015702fc-a4ca": "node1"}, + }, + expectedState: "PRIMARY", + expectedOut: "015702fc-a4ca is node1", + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + { + name: "name too long and truncated", + log: " 0: 015702fc-32f5-11ed-a4ca-267f97316394, name_so_long_it_will_get_trunca", + inputCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + }, + inputState: "PRIMARY", + expectedCtx: types.LogCtx{ + MyIdx: "1", + MemberCount: 1, + }, + expectedState: "PRIMARY", + expectedOut: "", + displayerExpectedNil: true, + mapToTest: IdentsMap, + key: "RegexMemberAssociations", + }, + + { + log: " members(1):", + expectedOut: "view member count: 1", + expectedCtx: types.LogCtx{MemberCount: 1}, + mapToTest: IdentsMap, + key: "RegexMemberCount", + }, + + { + log: "2001-01-01T01:01:01.000000Z 1 [Note] [MY-000000] [Galera] ####### My UUID: 60205de0-5cf6-11ec-8884-3a01908be11a", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{ + OwnHashes: []string{"60205de0-8884"}, + }, + expectedOut: "60205de0-8884 is local", + mapToTest: IdentsMap, + key: "RegexOwnUUID", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: (9509c194, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{ + OwnHashes: []string{"9509c194"}, + }, + expectedOut: "9509c194 is local", + mapToTest: IdentsMap, + key: "RegexOwnUUIDFromMessageRelay", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{ + MyIdx: "0", + }, + expectedOut: "my_idx=0", + mapToTest: IdentsMap, + key: "RegexMyIDXFromComponent", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: (9509c194, 'tcp://0.0.0.0:4567') connection established to 838ebd6d tcp://172.17.0.2:4567", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{ + OwnHashes: []string{"9509c194"}, + }, + expectedOut: "9509c194 is local", + mapToTest: IdentsMap, + key: "RegexOwnUUIDFromEstablished", + }, + + { + log: " own_index: 1", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{ + MyIdx: "1", + }, + expectedOut: "my_idx=1", + mapToTest: IdentsMap, + key: "RegexOwnIndexFromView", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] (60205de0-8884, 'ssl://0.0.0.0:4567') connection established to 5873acd0-baa8 ssl://172.17.0.2:4567", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"5873acd0-baa8": "172.17.0.2"}, + }, + expectedOut: "172.17.0.2 established", + mapToTest: ViewsMap, + key: "RegexNodeEstablished", + }, + { + name: "established to node's own ip", + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] (60205de0-8884, 'ssl://0.0.0.0:4567') connection established to 5873acd0-baa8 ssl://172.17.0.2:4567", + inputCtx: types.LogCtx{ + OwnIPs: []string{"172.17.0.2"}, + HashToIP: map[string]string{}, + }, + expectedCtx: types.LogCtx{ + OwnIPs: []string{"172.17.0.2"}, + HashToIP: map[string]string{"5873acd0-baa8": "172.17.0.2"}, + }, + expectedOut: "", + displayerExpectedNil: true, + mapToTest: ViewsMap, + key: "RegexNodeEstablished", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] declaring 5873acd0-baa8 at ssl://172.17.0.2:4567 stable", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{}, + IPToMethod: map[string]string{}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"5873acd0-baa8": "172.17.0.2"}, + IPToMethod: map[string]string{"172.17.0.2": "ssl"}, + }, + expectedOut: "172.17.0.2 joined", + mapToTest: ViewsMap, + key: "RegexNodeJoined", + }, + { + name: "mariadb variation", + log: "2001-01-01 1:01:30 0 [Note] WSREP: declaring 5873acd0-baa8 at tcp://172.17.0.2:4567 stable", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{}, + IPToMethod: map[string]string{}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"5873acd0-baa8": "172.17.0.2"}, + IPToMethod: map[string]string{"172.17.0.2": "tcp"}, + }, + expectedOut: "172.17.0.2 joined", + mapToTest: ViewsMap, + key: "RegexNodeJoined", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] forgetting 871c35de-99ae (ssl://172.17.0.2:4567)", + expectedOut: "172.17.0.2 left", + mapToTest: ViewsMap, + key: "RegexNodeLeft", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2", + expectedCtx: types.LogCtx{MemberCount: 2}, + expectedState: "PRIMARY", + expectedOut: "PRIMARY(n=2)", + mapToTest: ViewsMap, + key: "RegexNewComponent", + }, + { + name: "bootstrap", + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = yes, my_idx = 0, memb_num = 2", + expectedCtx: types.LogCtx{MemberCount: 2}, + expectedState: "PRIMARY", + expectedOut: "PRIMARY(n=2),bootstrap", + mapToTest: ViewsMap, + key: "RegexNewComponent", + }, + { + name: "don't set primary", + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2", + inputState: "JOINER", + expectedCtx: types.LogCtx{MemberCount: 2}, + expectedState: "JOINER", + expectedOut: "PRIMARY(n=2)", + mapToTest: ViewsMap, + key: "RegexNewComponent", + }, + { + name: "non-primary", + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 2", + expectedCtx: types.LogCtx{MemberCount: 2}, + expectedState: "NON-PRIMARY", + expectedOut: "NON-PRIMARY(n=2)", + mapToTest: ViewsMap, + key: "RegexNewComponent", + }, + + { + log: "2001-01-01T01:01:01.000000Z 84580 [Note] [MY-000000] [Galera] evs::proto(9a826787-9e98, LEAVING, view_id(REG,4971d113-87b0,22)) suspecting node: 4971d113-87b0", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{}, + }, + expectedOut: "4971d113-87b0 suspected to be down", + mapToTest: ViewsMap, + key: "RegexNodeSuspect", + }, + { + name: "with known ip", + log: "2001-01-01T01:01:01.000000Z 84580 [Note] [MY-000000] [Galera] evs::proto(9a826787-9e98, LEAVING, view_id(REG,4971d113-87b0,22)) suspecting node: 4971d113-87b0", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{"4971d113-87b0": "172.17.0.2"}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"4971d113-87b0": "172.17.0.2"}, + }, + expectedOut: "172.17.0.2 suspected to be down", + mapToTest: ViewsMap, + key: "RegexNodeSuspect", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: remote endpoint tcp://172.17.0.2:4567 changed identity 84953af9 -> 5a478da2", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{"84953af9": "172.17.0.2"}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"84953af9": "172.17.0.2", "5a478da2": "172.17.0.2"}, + }, + expectedOut: "172.17.0.2 changed identity", + mapToTest: ViewsMap, + key: "RegexNodeChangedIdentity", + }, + { + name: "with complete uuid", + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] remote endpoint ssl://172.17.0.2:4567 changed identity 595812bc-9c79-11ec-ad3f-3a7953bcc2fc -> 595812bc-9c79-11ec-ad40-3a7953bcc2fc", + inputCtx: types.LogCtx{ + HashToIP: map[string]string{"595812bc-ad3f": "172.17.0.2"}, + }, + expectedCtx: types.LogCtx{ + HashToIP: map[string]string{"595812bc-ad3f": "172.17.0.2", "595812bc-ad40": "172.17.0.2"}, + }, + expectedOut: "172.17.0.2 changed identity", + mapToTest: ViewsMap, + key: "RegexNodeChangedIdentity", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [Galera] It may not be safe to bootstrap the cluster from this node. It was not the last one to leave the cluster and may not contain all the updates. To force cluster bootstrap with this node, edit the grastate.dat file manually and set safe_to_bootstrap to 1 .", + expectedState: "CLOSED", + expectedOut: "not safe to bootstrap", + mapToTest: ViewsMap, + key: "RegexWsrepUnsafeBootstrap", + }, + + { + log: "2001-01-01T01:01:01.481967+09:00 4 [ERROR] WSREP: Node consistency compromised, aborting...", + expectedState: "CLOSED", + expectedOut: "consistency compromised", + mapToTest: ViewsMap, + key: "RegexWsrepConsistenctyCompromised", + }, + { + log: "2001-01-01T01:01:01.000000Z 86 [ERROR] WSREP: Node consistency compromized, aborting...", + expectedState: "CLOSED", + expectedOut: "consistency compromised", + mapToTest: ViewsMap, + key: "RegexWsrepConsistenctyCompromised", + }, + + { + log: "2001-01-01 5:06:12 47285568576576 [Note] WSREP: gcomm: bootstrapping new group 'cluster'", + expectedOut: "bootstrapping", + mapToTest: ViewsMap, + key: "RegexBootstrap", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Found saved state: 8e862473-455e-11e8-a0ca-3fcd8faf3209:-1, safe_to_bootstrap: 1", + expectedOut: "safe_to_bootstrap: 1", + mapToTest: ViewsMap, + key: "RegexSafeToBoostrapSet", + }, + { + name: "should not match", + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Found saved state: 8e862473-455e-11e8-a0ca-3fcd8faf3209:-1, safe_to_bootstrap: 0", + expectedErr: true, + mapToTest: ViewsMap, + key: "RegexSafeToBoostrapSet", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Warning] [MY-000000] [Galera] Could not open state file for reading: '/var/lib/mysql//grastate.dat'", + expectedOut: "no grastate.dat file", + mapToTest: ViewsMap, + key: "RegexNoGrastate", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Warning] [MY-000000] [Galera] No persistent state found. Bootstraping with default state", + expectedOut: "bootstrapping(empty grastate)", + mapToTest: ViewsMap, + key: "RegexBootstrapingDefaultState", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 1922878)", + expectedState: "CLOSED", + expectedOut: "OPEN -> CLOSED", + mapToTest: StatesMap, + key: "RegexShift", + }, + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 21582507)", + expectedState: "DONOR", + expectedOut: "SYNCED -> DONOR", + mapToTest: StatesMap, + key: "RegexShift", + }, + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 21582507)", + expectedState: "JOINED", + expectedOut: "DESYNCED -> JOINED", + mapToTest: StatesMap, + key: "RegexShift", + }, + + { + log: "2001-01-01 01:01:01 140446385440512 [Note] WSREP: Restored state OPEN -> SYNCED (72438094)", + expectedState: "SYNCED", + expectedOut: "(restored)OPEN -> SYNCED", + mapToTest: StatesMap, + key: "RegexRestoredState", + }, + + { + 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{}, + expectedOut: "node1 will resync node2", + mapToTest: SSTMap, + key: "RegexSSTRequestSuccess", + }, + { + 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{}, + expectedOut: "node1 will resync node2", + mapToTest: SSTMap, + key: "RegexSSTRequestSuccess", + }, + { + name: "joining", + 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"}, + }, + expectedCtx: types.LogCtx{ + OwnNames: []string{"node2"}, + SST: types.SST{ResyncedFromNode: "node1"}, + }, + expectedOut: "node1 will resync local node", + mapToTest: SSTMap, + key: "RegexSSTRequestSuccess", + }, + { + name: "donor", + 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"}, + }, + expectedCtx: types.LogCtx{ + OwnNames: []string{"node1"}, + SST: types.SST{ResyncingNode: "node2"}, + }, + expectedOut: "local node will resync node2", + mapToTest: SSTMap, + key: "RegexSSTRequestSuccess", + }, + + { + log: "2001-01-01 01:01:01.164 WARN: Member 1.0 (node2) requested state transfer from 'node1', but it is impossible to select State Transfer donor: Resource temporarily unavailable", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{}, + expectedOut: "node2 cannot find donor", + mapToTest: SSTMap, + key: "RegexSSTResourceUnavailable", + }, + { + name: "local", + log: "2001-01-01 01:01:01.164 WARN: Member 1.0 (node2) requested state transfer from 'node1', but it is impossible to select State Transfer donor: Resource temporarily unavailable", + inputCtx: types.LogCtx{ + OwnNames: []string{"node2"}, + }, + expectedCtx: types.LogCtx{ + OwnNames: []string{"node2"}, + }, + expectedOut: "cannot find donor", + mapToTest: SSTMap, + key: "RegexSSTResourceUnavailable", + }, + + { + 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{}, + expectedOut: "node1 synced node2", + mapToTest: SSTMap, + key: "RegexSSTComplete", + }, + { + name: "joiner", + 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"}, + }, + expectedCtx: types.LogCtx{ + SST: types.SST{ResyncedFromNode: ""}, + OwnNames: []string{"node2"}, + }, + expectedOut: "got SST from node1", + mapToTest: SSTMap, + key: "RegexSSTComplete", + }, + { + name: "joiner ist", + 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"}, + }, + expectedCtx: types.LogCtx{ + SST: types.SST{ResyncedFromNode: "", Type: ""}, + OwnNames: []string{"node2"}, + }, + expectedOut: "got IST from node1", + mapToTest: SSTMap, + key: "RegexSSTComplete", + }, + { + name: "donor", + 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"}, + }, + expectedCtx: types.LogCtx{ + SST: types.SST{ResyncingNode: ""}, + OwnNames: []string{"node1"}, + }, + expectedOut: "finished sending SST to node2", + mapToTest: SSTMap, + key: "RegexSSTComplete", + }, + { + name: "donor ist", + 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"}, + }, + expectedCtx: types.LogCtx{ + SST: types.SST{ResyncingNode: "", Type: ""}, + 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.", + inputCtx: types.LogCtx{}, + expectedCtx: types.LogCtx{}, + expectedOut: "node1 synced ??(node left)", + mapToTest: SSTMap, + key: "RegexSSTCompleteUnknown", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [WSREP] Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '172.17.0.2:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --basedir '/usr/' --plugindir '/usr/lib64/mysql/plugin/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --mysqld-version '8.0.28-19.1' '' --gtid '9db0bcdf-b31a-11ed-a398-2a4cfdd82049:1' : 22 (Invalid argument)", + expectedOut: "SST error", + mapToTest: SSTMap, + key: "RegexSSTError", + }, + + { + log: "2001-01-01T01:01:01.000000Z 1328586 [Note] [MY-000000] [WSREP] Initiating SST cancellation", + expectedOut: "former SST cancelled", + mapToTest: SSTMap, + key: "RegexSSTCancellation", + }, + + { + log: "2001-01-01T01:01:01.000000Z WSREP_SST: [INFO] Proceeding with SST.........", + expectedCtx: types.LogCtx{SST: types.SST{Type: "SST"}}, + expectedState: "JOINER", + expectedOut: "receiving SST", + mapToTest: SSTMap, + key: "RegexSSTProceeding", + }, + + { + 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, + key: "RegexSSTStreamingTo", + }, + + { + log: "2001-01-01 01:01:01 140446376740608 [Note] WSREP: IST received: e00c4fff-c4b0-11e9-96a8-0f9789de42ad:69472531", + expectedCtx: types.LogCtx{}, + expectedOut: "IST received(seqno:69472531)", + mapToTest: SSTMap, + key: "RegexISTReceived", + }, + + { + 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"}}, + expectedState: "DONOR", + expectedOut: "IST to 172.17.0.2(seqno:116)", + mapToTest: SSTMap, + key: "RegexISTSender", + }, + + { + 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"}}, + expectedState: "JOINER", + expectedOut: "will receive IST(seqno:116)", + mapToTest: SSTMap, + key: "RegexISTReceiver", + }, + { + 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"}}, + expectedState: "JOINER", + expectedOut: "will receive SST", + mapToTest: SSTMap, + key: "RegexISTReceiver", + }, + { + 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"}}, + expectedState: "JOINER", + expectedOut: "will receive IST", + mapToTest: SSTMap, + key: "RegexISTReceiver", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Warning] [MY-000000] [Galera] 0.1 (node): State transfer to -1.-1 (left the group) failed: -111 (Connection refused)", + expectedOut: "node failed to sync ??(node left)", + mapToTest: SSTMap, + key: "RegexSSTFailedUnknown", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Warning] [MY-000000] [Galera] 0.1 (node): State transfer to 0.2 (node2) failed: -111 (Connection refused)", + expectedOut: "node failed to sync node2", + mapToTest: SSTMap, + key: "RegexSSTStateTransferFailed", + }, + { + log: "2001-01-01T01:01:01.000000Z 0 [Warning] [MY-000000] [Galera] 0.1 (node): State transfer to -1.-1 (left the group) failed: -111 (Connection refused)", + displayerExpectedNil: true, + mapToTest: SSTMap, + key: "RegexSSTStateTransferFailed", + }, + + { + 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"}}, + 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"}}, + expectedOut: "IST is not applicable", + mapToTest: SSTMap, + key: "RegexFailedToPrepareIST", + }, + + { + 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"}}, + expectedOut: "IST will be used", + mapToTest: SSTMap, + key: "RegexBypassSST", + }, + + { + 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", + mapToTest: SSTMap, + key: "RegexSocatConnRefused", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [WSREP-SST] Preparing the backup at /var/lib/mysql/sst-xb-tmpdir", + expectedOut: "preparing SST backup", + mapToTest: SSTMap, + key: "RegexPreparingBackup", + }, + + { + log: "2001-01-01T01:01:01.000000Z WSREP_SST: [ERROR] Possible timeout in receving first data from donor in gtid/keyring stage", + expectedOut: "timeout from donor in gtid/keyring stage", + mapToTest: SSTMap, + key: "RegexTimeoutReceivingFirstData", + }, + + { + log: "2001-01-01 01:01:01 140666176771840 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():736: Will never receive state. Need to abort.", + expectedOut: "will never receive SST, aborting", + mapToTest: SSTMap, + key: "RegexWillNeverReceive", + }, + + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] WSREP: async IST sender failed to serve tcp://172.17.0.2:4568: ist send failed: asio.system:32', asio error 'write: Broken pipe': 32 (Broken pipe)", + expectedOut: "IST to 172.17.0.2 failed: Broken pipe", + mapToTest: SSTMap, + key: "RegexISTFailed", + }, + { + log: "2001-01-01 01:10:01 28949 [ERROR] WSREP: async IST sender failed to serve tcp://172.17.0.2:4568: ist send failed: asio.system:104', asio error 'write: Connection reset by peer': 104 (Connection reset by peer)", + expectedOut: "IST to 172.17.0.2 failed: Connection reset by peer", + mapToTest: SSTMap, + key: "RegexISTFailed", + }, + { + log: "2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [Galera] async IST sender failed to serve ssl://172.17.0.2:4568: ist send failed: ', asio error 'Got unexpected return from write: eof: 71 (Protocol error)", + expectedOut: "IST to 172.17.0.2 failed: Protocol error", + mapToTest: SSTMap, + key: "RegexISTFailed", + }, + { + log: `{\"log\":\"2001-01-01T01:01:01.000000Z 0 [ERROR] [MY-000000] [Galera] async IST sender failed to serve ssl://172.17.0.2:4568: ist send failed: ', asio error 'Got unexpected return from write: eof: 71 (Protocol error)\n\t at galerautils/src/gu_asio_stream_react.cpp:write():195': 71 (Protocol error)\n\t at galera/src/ist.cpp:send():856\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}`, + expectedOut: "IST to 172.17.0.2 failed: Protocol error", + mapToTest: SSTMap, + key: "RegexISTFailed", + }, + + { + log: "+ NODE_NAME=cluster1-pxc-0.cluster1-pxc.test-percona.svc.cluster.local", + expectedCtx: types.LogCtx{OwnNames: []string{"cluster1-pxc-0"}}, + expectedOut: "local name:cluster1-pxc-0", + mapToTest: PXCOperatorMap, + key: "RegexNodeNameFromEnv", + }, + + { + log: "+ NODE_IP=172.17.0.2", + expectedCtx: types.LogCtx{OwnIPs: []string{"172.17.0.2"}}, + expectedOut: "local ip:172.17.0.2", + mapToTest: PXCOperatorMap, + key: "RegexNodeIPFromEnv", + }, + + { + log: "{\"log\":\"2023-07-05T08:17:23.447015Z 0 [Note] [MY-000000] [Galera] GCache::RingBuffer initial scan... 0.0% ( 0/1073741848 bytes) complete.\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + expectedOut: "recovering gcache", + mapToTest: PXCOperatorMap, + key: "RegexGcacheScan", + }, + + { + log: "2001-01-01 1:01:01 0 [Note] WSREP: Member 0.0 (node) desyncs itself from group", + expectedCtx: types.LogCtx{Desynced: true}, + expectedOut: "node desyncs itself from group", + mapToTest: ApplicativeMap, + key: "RegexDesync", + }, + + { + log: "2001-01-01 1:01:01 0 [Note] WSREP: Member 0.0 (node) resyncs itself to group", + expectedCtx: types.LogCtx{Desynced: false}, + inputCtx: types.LogCtx{Desynced: true}, + expectedOut: "node resyncs itself to group", + mapToTest: ApplicativeMap, + key: "RegexResync", + }, + + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 1(node1) initiates vote on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,bdb2b9234ae75cb3: some error, Error_code: 123;\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + expectedOut: "inconsistency vote started by node1(seqno:20)", + expectedCtx: types.LogCtx{Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoteInit", + }, + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 1(node1) initiates vote on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,bdb2b9234ae75cb3: some error, Error_code: 123;\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node1"}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedOut: "inconsistency vote started(seqno:20)", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoteInit", + }, + + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 2(node2) responds to vote on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,0000000000000000: Success\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "0000000000000000", Error: "Success"}}}}}, + expectedOut: "consistency vote(seqno:20): voted Success", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoteRespond", + }, + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 2(node2) responds to vote on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,bdb2b9234ae75cb3: some error\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedOut: "consistency vote(seqno:20): voted same error", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoteRespond", + }, + { + // could not actually find a "responds to" with any error for now + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 0 [Note] [MY-000000] [Galera] Member 2(node2) responds to vote on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,ed9774a3cad44656: some different error\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "ed9774a3cad44656", Error: "some different error"}}}}}, + expectedOut: "consistency vote(seqno:20): voted different error", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoteRespond", + }, + + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 1 [ERROR] [MY-000000] [Galera] Inconsistency detected: Inconsistent by consensus on 8c9b5610-e020-11ed-a5ea-e253cc5f629d:127\n\t at galera/src/replicator_smm.cpp:process_apply_error():1469\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + expectedOut: "found inconsistent by vote", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyVoted", + }, + + { + log: "Winner: bdb2b9234ae75cb3", + inputCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedOut: "consistency vote(seqno:20): won", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyWinner", + }, + { + log: "Winner: 0000000000000000", + inputCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "0000000000000000", Error: "Success"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "0000000000000000", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "0000000000000000", Error: "Success"}}}}}, + expectedOut: "consistency vote(seqno:20): lost", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyWinner", + }, + { + name: "already voted conflict, should not print anything", + log: "Winner: 0000000000000000", + inputCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node1"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + displayerExpectedNil: true, + mapToTest: ApplicativeMap, + key: "RegexInconsistencyWinner", + }, + + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 1 [ERROR] [MY-000000] [Galera] Recovering vote result from history: 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,bdb2b9234ae75cb3\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "bdb2b9234ae75cb3"}}}}}, + expectedOut: "consistency vote(seqno:20): voted same error", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyRecovery", + }, + { + log: "{\"log\":\"2001-01-01T01:01:01.000000Z 1 [ERROR] [MY-000000] [Galera] Recovering vote result from history: 8c9b5610-e020-11ed-a5ea-e253cc5f629d:20,0000000000000000\n\",\"file\":\"/var/lib/mysql/mysqld-error.log\"}", + inputCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}}}}}, + expectedCtx: types.LogCtx{OwnNames: []string{"node2"}, Conflicts: types.Conflicts{&types.Conflict{InitiatedBy: []string{"node1"}, Winner: "bdb2b9234ae75cb3", Seqno: "20", VotePerNode: map[string]types.ConflictVote{"node1": types.ConflictVote{MD5: "bdb2b9234ae75cb3", Error: "some error"}, "node2": types.ConflictVote{MD5: "0000000000000000"}}}}}, + expectedOut: "consistency vote(seqno:20): voted Success", + mapToTest: ApplicativeMap, + key: "RegexInconsistencyRecovery", + }, + } + + for _, test := range tests { + if test.name == "" { + test.name = "default" + } + if _, ok := test.mapToTest[test.key]; !ok { + t.Fatalf("key %s does not exist in maps", test.key) + } + err := testRegexFromMap(t, test.log, test.mapToTest[test.key]) + if err != nil { + if test.expectedErr { + continue + } + t.Fatalf("key: %s\ntestname: %s\nregex string: \"%s\"\nlog: %s\n", test.key, test.name, test.mapToTest[test.key].Regex.String(), err) + } + + if test.inputState != "" { + test.inputCtx.SetState(test.inputState) + } + + ctx, displayer := test.mapToTest[test.key].Handle(test.inputCtx, test.log) + msg := "" + if displayer != nil { + msg = displayer(ctx) + } else if !test.displayerExpectedNil { + t.Errorf("key: %s\ntestname: %s\ndisplayer is nil\nexpected: not nil", test.key, test.name) + } + + // alternative to reflect.deepequal, it enables to avoid comparing "states" map + res := cmp.Equal(ctx, test.expectedCtx, cmpopts.IgnoreUnexported(types.LogCtx{})) + if !res || msg != test.expectedOut || ctx.State() != test.expectedState { + t.Errorf("\nkey: %s\ntestname: %s\nctx: %+v\nexpected ctx: %+v\nout: %s\nexpected out: %s\nstate: %s\nexpected state: %s", test.key, test.name, spew.Sdump(ctx), spew.Sdump(test.expectedCtx), msg, test.expectedOut, ctx.State(), test.expectedState) + t.Fail() + } + } +} + +func testRegexFromMap(t *testing.T, log string, regex *types.LogRegex) error { + m := types.RegexMap{"test": regex} + + return testActualGrepOnLog(t, log, m.Compile()[0]) +} + +func testActualGrepOnLog(t *testing.T, log, regex string) error { + + f, err := ioutil.TempFile(t.TempDir(), "test_log") + if err != nil { + return errors.Wrap(err, "failed to create tmp file") + } + defer f.Sync() + + _, err = f.WriteString(log) + if err != nil { + return errors.Wrap(err, "failed to write in tmp file") + } + + out, err := exec.Command("grep", "-P", regex, f.Name()).Output() + if err != nil { + return errors.Wrap(err, "failed to grep in tmp file") + } + if string(out) == "" { + return errors.Wrap(err, "empty results when grepping in tmp file") + } + return nil +} diff --git a/src/go/pt-galera-log-explainer/regex/sst.go b/src/go/pt-galera-log-explainer/regex/sst.go new file mode 100644 index 00000000..6e57e0bb --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/sst.go @@ -0,0 +1,310 @@ +package regex + +import ( + "regexp" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + setType(types.SSTRegexType, SSTMap) +} + +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 + "\\)\\("), + 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 + } + if utils.SliceContains(ctx.OwnNames, donor) { + ctx.SST.ResyncingNode = joiner + } + + return ctx, func(ctx types.LogCtx) string { + if utils.SliceContains(ctx.OwnNames, joiner) { + return donor + utils.Paint(utils.GreenText, " will resync local node") + } + if utils.SliceContains(ctx.OwnNames, donor) { + return utils.Paint(utils.GreenText, "local node will resync ") + joiner + } + + return donor + utils.Paint(utils.GreenText, " will resync ") + joiner + } + }, + Verbosity: types.Detailed, + }, + + "RegexSSTResourceUnavailable": &types.LogRegex{ + Regex: regexp.MustCompile("requested state transfer.*Resource temporarily unavailable"), + InternalRegex: regexp.MustCompile("Member .* \\(" + regexNodeName + "\\) requested state transfer"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + joiner := submatches[groupNodeName] + if utils.SliceContains(ctx.OwnNames, joiner) { + + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "cannot find donor")) + } + + return ctx, types.SimpleDisplayer(joiner + utils.Paint(utils.YellowText, " cannot find donor")) + }, + }, + + // 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"), + 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 + } + ctx.SST.Reset() + + ctx = addOwnNameWithSSTMetadata(ctx, joiner, donor) + + return ctx, func(ctx types.LogCtx) string { + if utils.SliceContains(ctx.OwnNames, joiner) { + return utils.Paint(utils.GreenText, "got "+displayType+" from ") + donor + } + if utils.SliceContains(ctx.OwnNames, donor) { + return utils.Paint(utils.GreenText, "finished sending "+displayType+" to ") + joiner + } + + return donor + utils.Paint(utils.GreenText, " synced ") + joiner + } + }, + }, + + // some weird ones: + // 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"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + donor := utils.ShortNodeName(submatches[groupNodeName]) + ctx = addOwnNameWithSSTMetadata(ctx, "", 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"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + donor := utils.ShortNodeName(submatches[groupNodeName]) + ctx = addOwnNameWithSSTMetadata(ctx, "", 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"), + 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) + return ctx, types.SimpleDisplayer(donor + utils.Paint(utils.RedText, " failed to sync ") + joiner) + }, + }, + + "RegexSSTError": &types.LogRegex{ + Regex: regexp.MustCompile("Process completed with error: wsrep_sst"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "SST error")) + }, + }, + + "RegexSSTCancellation": &types.LogRegex{ + Regex: regexp.MustCompile("Initiating SST cancellation"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "former SST cancelled")) + }, + }, + + "RegexSSTProceeding": &types.LogRegex{ + 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" + + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "receiving SST")) + }, + }, + + "RegexSSTStreamingTo": &types.LogRegex{ + Regex: regexp.MustCompile("Streaming the backup to"), + InternalRegex: regexp.MustCompile("Streaming the backup to joiner at " + regexNodeIP), + 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 + } + + return ctx, func(ctx types.LogCtx) string { + return utils.Paint(utils.YellowText, "SST to ") + types.DisplayNodeSimplestForm(ctx, node) + } + }, + }, + + "RegexISTReceived": &types.LogRegex{ + Regex: regexp.MustCompile("IST received"), + + // the UUID here is not from a node, it's a cluster state UUID, this is only used to ensure it's correctly parsed + InternalRegex: regexp.MustCompile("IST received: " + regexUUID + ":" + regexSeqno), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + seqno := submatches[groupSeqno] + return ctx, types.SimpleDisplayer(utils.Paint(utils.GreenText, "IST received") + "(seqno:" + seqno + ")") + }, + }, + + "RegexISTSender": &types.LogRegex{ + Regex: regexp.MustCompile("IST sender starting"), + + // 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") + + seqno := submatches[groupSeqno] + node := submatches[groupNodeIP] + + return ctx, func(ctx types.LogCtx) string { + return utils.Paint(utils.YellowText, "IST to ") + types.DisplayNodeSimplestForm(ctx, node) + "(seqno:" + seqno + ")" + } + }, + }, + + "RegexISTReceiver": &types.LogRegex{ + Regex: regexp.MustCompile("Prepared IST receiver"), + + InternalRegex: regexp.MustCompile("Prepared IST receiver( for (?P[0-9]+)-" + regexSeqno + ")?"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("JOINER") + + seqno := submatches[groupSeqno] + msg := utils.Paint(utils.YellowText, "will receive ") + + startingseqno := submatches["startingseqno"] + // if it's 0, it will go to SST without a doubt + if startingseqno == "0" { + ctx.SST.Type = "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" + msg += "IST" + if seqno != "" { + msg += "(seqno:" + seqno + ")" + } + } + return ctx, types.SimpleDisplayer(msg) + }, + }, + + "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" + return ctx, types.SimpleDisplayer("IST is not applicable") + }, + }, + + // 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" + return ctx, types.SimpleDisplayer("IST will be used") + }, + }, + + "RegexSocatConnRefused": &types.LogRegex{ + Regex: regexp.MustCompile("E connect.*Connection refused"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "socat: connection refused")) + }, + }, + + // 2023-05-12T02:52:33.767132Z 0 [Note] [MY-000000] [WSREP-SST] Preparing the backup at /var/lib/mysql/sst-xb-tmpdir + "RegexPreparingBackup": &types.LogRegex{ + Regex: regexp.MustCompile("Preparing the backup at"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer("preparing SST backup") + }, + Verbosity: types.Detailed, + }, + + "RegexTimeoutReceivingFirstData": &types.LogRegex{ + Regex: regexp.MustCompile("Possible timeout in receving first data from donor in gtid/keyring stage"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "timeout from donor in gtid/keyring stage")) + }, + }, + + "RegexWillNeverReceive": &types.LogRegex{ + Regex: regexp.MustCompile("Will never receive state. Need to abort"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "will never receive SST, aborting")) + }, + }, + + "RegexISTFailed": &types.LogRegex{ + Regex: regexp.MustCompile("async IST sender failed to serve"), + InternalRegex: regexp.MustCompile("IST sender failed to serve " + regexNodeIPMethod + ":.*asio error '.*: [0-9]+ \\((?P[\\w\\s]+)\\)"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + node := submatches[groupNodeIP] + istError := submatches["error"] + + return ctx, func(ctx types.LogCtx) string { + return "IST to " + types.DisplayNodeSimplestForm(ctx, node) + utils.Paint(utils.RedText, " failed: ") + istError + } + }, + }, +} + +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. + +) +*/ diff --git a/src/go/pt-galera-log-explainer/regex/states.go b/src/go/pt-galera-log-explainer/regex/states.go new file mode 100644 index 00000000..1f1075a9 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/states.go @@ -0,0 +1,44 @@ +package regex + +import ( + "regexp" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + setType(types.StatesRegexType, StatesMap) +} + +var ( + shiftFunc = func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ctx.SetState(submatches["state2"]) + log = utils.PaintForState(submatches["state1"], submatches["state1"]) + " -> " + utils.PaintForState(submatches["state2"], submatches["state2"]) + + return ctx, types.SimpleDisplayer(log) + } + shiftRegex = regexp.MustCompile("(?P[A-Z]+) -> (?P[A-Z]+)") +) + +var StatesMap = types.RegexMap{ + "RegexShift": &types.LogRegex{ + Regex: regexp.MustCompile("Shifting"), + InternalRegex: shiftRegex, + Handler: shiftFunc, + }, + + "RegexRestoredState": &types.LogRegex{ + Regex: regexp.MustCompile("Restored state"), + InternalRegex: shiftRegex, + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + var displayer types.LogDisplayer + ctx, displayer = shiftFunc(submatches, ctx, log) + + return ctx, types.SimpleDisplayer("(restored)" + displayer(ctx)) + }, + }, +} + +// [Note] [MY-000000] [WSREP] Server status change connected -> joiner diff --git a/src/go/pt-galera-log-explainer/regex/views.go b/src/go/pt-galera-log-explainer/regex/views.go new file mode 100644 index 00000000..692db875 --- /dev/null +++ b/src/go/pt-galera-log-explainer/regex/views.go @@ -0,0 +1,257 @@ +package regex + +import ( + "regexp" + "strconv" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +func init() { + setType(types.ViewsRegexType, ViewsMap) +} + +// "galera views" regexes +var ViewsMap = types.RegexMap{ + "RegexNodeEstablished": &types.LogRegex{ + Regex: regexp.MustCompile("connection established"), + InternalRegex: regexp.MustCompile("established to " + regexNodeHash + " " + regexNodeIPMethod), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + ctx.HashToIP[submatches[groupNodeHash]] = ip + if utils.SliceContains(ctx.OwnIPs, ip) { + return ctx, nil + } + return ctx, func(ctx types.LogCtx) string { return types.DisplayNodeSimplestForm(ctx, ip) + " established" } + }, + Verbosity: types.DebugMySQL, + }, + + "RegexNodeJoined": &types.LogRegex{ + Regex: regexp.MustCompile("declaring .* stable"), + InternalRegex: regexp.MustCompile("declaring " + regexNodeHash + " at " + regexNodeIPMethod), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + ctx.HashToIP[submatches[groupNodeHash]] = ip + ctx.IPToMethod[ip] = submatches[groupMethod] + return ctx, func(ctx types.LogCtx) string { + return types.DisplayNodeSimplestForm(ctx, ip) + utils.Paint(utils.GreenText, " joined") + } + }, + }, + + "RegexNodeLeft": &types.LogRegex{ + Regex: regexp.MustCompile("forgetting"), + InternalRegex: regexp.MustCompile("forgetting " + regexNodeHash + " \\(" + regexNodeIPMethod), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + ip := submatches[groupNodeIP] + return ctx, func(ctx types.LogCtx) string { + return types.DisplayNodeSimplestForm(ctx, ip) + utils.Paint(utils.RedText, " left") + } + }, + }, + + // New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 5 + "RegexNewComponent": &types.LogRegex{ + Regex: regexp.MustCompile("New COMPONENT:"), + InternalRegex: regexp.MustCompile("New COMPONENT: primary = (?P.+), bootstrap = (?P.*), my_idx = .*, memb_num = (?P[0-9]{1,2})"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + primary := submatches["primary"] == "yes" + membNum := submatches["memb_num"] + bootstrap := submatches["bootstrap"] == "yes" + memberCount, err := strconv.Atoi(membNum) + if err != nil { + return ctx, nil + } + + ctx.MemberCount = memberCount + if primary { + // we don't always store PRIMARY because we could have found DONOR/JOINER/SYNCED/DESYNCED just earlier + // and we do not want to override these as they have more value + if !ctx.IsPrimary() { + ctx.SetState("PRIMARY") + } + msg := utils.Paint(utils.GreenText, "PRIMARY") + "(n=" + membNum + ")" + if bootstrap { + msg += ",bootstrap" + } + return ctx, types.SimpleDisplayer(msg) + } + + ctx.SetState("NON-PRIMARY") + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "NON-PRIMARY") + "(n=" + membNum + ")") + }, + }, + + "RegexNodeSuspect": &types.LogRegex{ + Regex: regexp.MustCompile("suspecting node"), + InternalRegex: regexp.MustCompile("suspecting node: " + regexNodeHash), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + hash := submatches[groupNodeHash] + ip, ok := ctx.HashToIP[hash] + if ok { + return ctx, func(ctx types.LogCtx) string { + return types.DisplayNodeSimplestForm(ctx, ip) + utils.Paint(utils.YellowText, " suspected to be down") + } + } + return ctx, types.SimpleDisplayer(hash + utils.Paint(utils.YellowText, " suspected to be down")) + }, + Verbosity: types.Detailed, + }, + + "RegexNodeChangedIdentity": &types.LogRegex{ + Regex: regexp.MustCompile("remote endpoint.*changed identity"), + InternalRegex: regexp.MustCompile("remote endpoint " + regexNodeIPMethod + " changed identity " + regexNodeHash + " -> " + strings.Replace(regexNodeHash, groupNodeHash, groupNodeHash+"2", -1)), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + + hash := submatches[groupNodeHash] + hash2 := submatches[groupNodeHash+"2"] + ip, ok := ctx.HashToIP[hash] + if !ok && IsNodeUUID(hash) { + ip, ok = ctx.HashToIP[utils.UUIDToShortUUID(hash)] + + // there could have additional corner case to discover yet + if !ok { + return ctx, types.SimpleDisplayer(hash + utils.Paint(utils.YellowText, " changed identity")) + } + hash2 = utils.UUIDToShortUUID(hash2) + } + ctx.HashToIP[hash2] = ip + return ctx, func(ctx types.LogCtx) string { + return types.DisplayNodeSimplestForm(ctx, ip) + utils.Paint(utils.YellowText, " changed identity") + } + }, + Verbosity: types.Detailed, + }, + + "RegexWsrepUnsafeBootstrap": &types.LogRegex{ + Regex: regexp.MustCompile("ERROR.*not be safe to bootstrap"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "not safe to bootstrap")) + }, + }, + "RegexWsrepConsistenctyCompromised": &types.LogRegex{ + Regex: regexp.MustCompile(".ode consistency compromi.ed"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + ctx.SetState("CLOSED") + + return ctx, types.SimpleDisplayer(utils.Paint(utils.RedText, "consistency compromised")) + }, + }, + "RegexWsrepNonPrimary": &types.LogRegex{ + Regex: regexp.MustCompile("failed to reach primary view"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer("received " + utils.Paint(utils.RedText, "non primary")) + }, + }, + + "RegexBootstrap": &types.LogRegex{ + Regex: regexp.MustCompile("gcomm: bootstrapping new group"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "bootstrapping")) + }, + }, + + "RegexSafeToBoostrapSet": &types.LogRegex{ + Regex: regexp.MustCompile("safe_to_bootstrap: 1"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "safe_to_bootstrap: 1")) + }, + }, + "RegexNoGrastate": &types.LogRegex{ + Regex: regexp.MustCompile("Could not open state file for reading.*grastate.dat"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "no grastate.dat file")) + }, + Verbosity: types.Detailed, + }, + "RegexBootstrapingDefaultState": &types.LogRegex{ + Regex: regexp.MustCompile("Bootstraping with default state"), + Handler: func(submatches map[string]string, ctx types.LogCtx, log string) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "bootstrapping(empty grastate)")) + }, + }, +} + +/* + +2022-11-29T23:34:51.820009-05:00 0 [Warning] [MY-000000] [Galera] Could not find peer: c0ff4085-5ad7-11ed-8b74-cfeec74147fe + +2022-12-07 1:00:06 0 [Note] WSREP: Member 0.0 (node) synced with group. + + +2021-03-25T21:58:13.570928Z 0 [Warning] WSREP: no nodes coming from prim view, prim not possible +2021-03-25T21:58:13.855983Z 0 [Warning] WSREP: Quorum: No node with complete state: + + + +2021-04-22T08:01:05.000581Z 0 [Warning] WSREP: Failed to report last committed 66328091, -110 (Connection timed out) + + +input_map=evs::input_map: {aru_seq=8,safe_seq=8,node_index=node: {idx=0,range=[9,8],safe_seq=8} node: {idx=1,range=[9,8],safe_seq=8} }, +fifo_seq=4829086170, +last_sent=8, +known: +17a2e064 at tcp://ip:4567 +{o=0,s=1,i=0,fs=-1,} +470a6438 at tcp://ip:4567 +{o=1,s=0,i=0,fs=4829091361,jm= +{v=0,t=4,ut=255,o=1,s=8,sr=-1,as=8,f=4,src=470a6438,srcvid=view_id(REG,470a6438,24),insvid=view_id(UNKNOWN,00000000,0),ru=00000000,r=[-1,-1],fs=4829091361,nl=( + 17a2e064, {o=0,s=1,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} + 470a6438, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,470a6438,24),ss=8,ir=[9,8],} + 6548cf50, {o=1,s=1,e=0,ls=-1,vid=view_id(REG,17a2e064,24),ss=12,ir=[13,12],} + 8b0c0f77, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,470a6438,24),ss=8,ir=[9,8],} + d4397932, {o=0,s=1,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} +) +}, +} +6548cf50 at tcp://ip:4567 +{o=1,s=1,i=0,fs=-1,jm= +{v=0,t=4,ut=255,o=1,s=12,sr=-1,as=12,f=4,src=6548cf50,srcvid=view_id(REG,17a2e064,24),insvid=view_id(UNKNOWN,00000000,0),ru=00000000,r=[-1,-1],fs=4829165031,nl=( + 17a2e064, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,17a2e064,24),ss=12,ir=[13,12],} + 470a6438, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} + 6548cf50, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,17a2e064,24),ss=12,ir=[13,12],} + 8b0c0f77, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} + d4397932, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,17a2e064,24),ss=12,ir=[13,12],} +) +}, +} +8b0c0f77 at +{o=1,s=0,i=0,fs=-1,jm= +{v=0,t=4,ut=255,o=1,s=8,sr=-1,as=8,f=0,src=8b0c0f77,srcvid=view_id(REG,470a6438,24),insvid=view_id(UNKNOWN,00000000,0),ru=00000000,r=[-1,-1],fs=4829086170,nl=( + 17a2e064, {o=0,s=1,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} + 470a6438, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,470a6438,24),ss=8,ir=[9,8],} + 6548cf50, {o=1,s=1,e=0,ls=-1,vid=view_id(REG,17a2e064,24),ss=12,ir=[13,12],} + 8b0c0f77, {o=1,s=0,e=0,ls=-1,vid=view_id(REG,470a6438,24),ss=8,ir=[9,8],} + d4397932, {o=0,s=1,e=0,ls=-1,vid=view_id(REG,00000000,0),ss=-1,ir=[-1,-1],} +) +}, +} +d4397932 at tcp://ip:4567 +{o=0,s=1,i=0,fs=4685894552,} + } + + Transport endpoint is not connected + + + 2023-03-31T08:05:57.964535Z 0 [Note] WSREP: handshake failed, my group: '', peer group: '' + + 2023-04-04T22:35:23.487304Z 0 [Warning] [MY-000000] [Galera] Handshake failed: tlsv1 alert decrypt error + + 2023-04-16T19:35:06.875877Z 0 [Warning] [MY-000000] [Galera] Action message in non-primary configuration from member 0 + +{"log":"2023-06-10T04:50:46.835491Z 0 [Note] [MY-000000] [Galera] going to give up, state dump for diagnosis:\nevs::proto(evs::proto(6d0345f5-bcc0, GATHER, view_id(REG,02e369be-8363,1046)), GATHER) {\ncurrent_view=Current view of cluster as seen by this node\nview (view_id(REG,02e369be-8363,1046)\nmemb {\n\t02e369be-8363,0\n\t49761f3d-bd34,0\n\t6d0345f5-bcc0,0\n\tb05443d1-96bf,0\n\tb05443d1-96c0,0\n\t}\njoined {\n\t}\nleft {\n\t}\npartitioned {\n\t}\n),\ninput_map=evs::input_map: {aru_seq=461,safe_seq=461,node_index=node: {idx=0,range=[462,461],safe_seq=461} node: {idx=1,range=[462,461],safe_seq=461} node: {idx=2,range=[462,461],safe_seq=461} node: {idx=3,range=[462,461],safe_seq=461} node: {idx=4,range=[462,461],safe_seq=461} },\nfifo_seq=221418422,\nlast_sent=461,\nknown:\n","file":"/var/lib/mysql/mysqld-error.log"} + + +[Warning] WSREP: FLOW message from member -12921743687968 in non-primary configuration. Ignored. + +*/ diff --git a/src/go/pt-galera-log-explainer/regexList.go b/src/go/pt-galera-log-explainer/regexList.go new file mode 100644 index 00000000..2b7bbd1c --- /dev/null +++ b/src/go/pt-galera-log-explainer/regexList.go @@ -0,0 +1,39 @@ +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/pkg/errors" +) + +type regexList struct { + Json bool +} + +func (l *regexList) Help() string { + return "List available regexes. Can be used to exclude them later" +} + +func (l *regexList) Run() error { + + allregexes := regex.AllRegexes() + allregexes.Merge(regex.PXCOperatorMap) + + if l.Json { + out, err := json.Marshal(&allregexes) + if err != nil { + return errors.Wrap(err, "could not marshal regexes") + } + fmt.Println(string(out)) + return nil + } + keys := []string{} + for k := range allregexes { + keys = append(keys, k) + + } + fmt.Println(keys) + return nil +} diff --git a/src/go/pt-galera-log-explainer/sed.go b/src/go/pt-galera-log-explainer/sed.go new file mode 100644 index 00000000..13453bcf --- /dev/null +++ b/src/go/pt-galera-log-explainer/sed.go @@ -0,0 +1,110 @@ +package main + +import ( + "fmt" + "os" + "os/exec" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/pkg/errors" +) + +type sed struct { + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` + ByIP bool `help:"Replace by IP instead of name"` +} + +func (s *sed) Help() string { + return `sed translates a log, replacing node UUID, IPS, names with either name or IP everywhere. By default it replaces by name. + +Use like so: + cat node1.log | galera-log-explainer sed *.log | less + galera-log-explainer sed *.log < node1.log | less + +You can also simply call the command to get a generated sed command to review and apply yourself + galera-log-explainer sed *.log` +} + +func (s *sed) Run() error { + toCheck := regex.AllRegexes() + timeline, err := timelineFromPaths(s.Paths, toCheck, CLI.Since, CLI.Until) + if err != nil { + return errors.Wrap(err, "Found nothing worth replacing") + } + ctxs := timeline.GetLatestUpdatedContextsByNodes() + + args := []string{} + for key, ctx := range ctxs { + + tosearchs := []string{key} + tosearchs = append(tosearchs, ctx.OwnHashes...) + tosearchs = append(tosearchs, ctx.OwnIPs...) + tosearchs = append(tosearchs, ctx.OwnNames...) + for _, tosearch := range tosearchs { + ni := whoIs(ctxs, tosearch) + + fmt.Println(ni) + switch { + case CLI.Sed.ByIP: + args = append(args, sedByIP(ni)...) + default: + args = append(args, sedByName(ni)...) + } + } + + } + if len(args) == 0 { + return errors.New("Could not find informations to replace") + } + + fstat, err := os.Stdin.Stat() + if err != nil { + return err + } + if fstat.Size() == 0 { + fmt.Println("No files found in stdin, returning the sed command instead:") + fmt.Println("sed", strings.Join(args, " ")) + return nil + } + + cmd := exec.Command("sed", args...) + cmd.Stdin = os.Stdin + cmd.Stdout = os.Stdout + cmd.Stderr = os.Stderr + err = cmd.Start() + if err != nil { + return err + } + return cmd.Wait() +} + +func sedByName(ni types.NodeInfo) []string { + if len(ni.NodeNames) == 0 { + return nil + } + elem := ni.NodeNames[0] + args := sedSliceWith(ni.NodeUUIDs, elem) + args = append(args, sedSliceWith(ni.IPs, elem)...) + return args +} + +func sedByIP(ni types.NodeInfo) []string { + if len(ni.IPs) == 0 { + return nil + } + elem := ni.IPs[0] + args := sedSliceWith(ni.NodeUUIDs, elem) + args = append(args, sedSliceWith(ni.NodeNames, elem)...) + return args +} + +func sedSliceWith(elems []string, replace string) []string { + args := []string{} + for _, elem := range elems { + args = append(args, "-e") + args = append(args, "s/"+elem+"/"+replace+"/g") + } + return args +} diff --git a/src/go/pt-galera-log-explainer/types/conflicts.go b/src/go/pt-galera-log-explainer/types/conflicts.go new file mode 100644 index 00000000..4f3bf455 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/conflicts.go @@ -0,0 +1,57 @@ +package types + +type Conflicts []*Conflict + +type Conflict struct { + Seqno string + InitiatedBy []string + Winner string // winner will help the winning md5sum + VotePerNode map[string]ConflictVote +} + +type ConflictVote struct { + MD5 string + Error string +} + +func (cs Conflicts) Merge(c Conflict) Conflicts { + for i := range cs { + if c.Seqno == cs[i].Seqno { + for node, vote := range c.VotePerNode { + cs[i].VotePerNode[node] = vote + } + return cs + } + } + + return append(cs, &c) +} + +func (cs Conflicts) ConflictWithSeqno(seqno string) *Conflict { + // technically could make it a binary search, seqno should be ever increasing + for _, c := range cs { + if seqno == c.Seqno { + return c + } + } + return nil +} + +func (cs Conflicts) OldestUnresolved() *Conflict { + for _, c := range cs { + if c.Winner == "" { + return c + } + } + return nil +} +func (cs Conflicts) ConflictFromMD5(md5 string) *Conflict { + for _, c := range cs { + for _, vote := range c.VotePerNode { + if vote.MD5 == md5 { + return c + } + } + } + return nil +} diff --git a/src/go/pt-galera-log-explainer/types/ctx.go b/src/go/pt-galera-log-explainer/types/ctx.go new file mode 100644 index 00000000..5042161e --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/ctx.go @@ -0,0 +1,281 @@ +package types + +import ( + "encoding/json" + + "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 +type LogCtx struct { + FilePath string + FileType string + OwnIPs []string + OwnHashes []string + OwnNames []string + stateErrorLog string + stateRecoveryLog string + statePostProcessingLog string + stateBackupLog string + Version string + SST SST + MyIdx string + MemberCount int + Desynced bool + 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{}} +} + +// State will return the wsrep state of the current file type +// That is because for operator related logs, we have every type of files +// Not tracking and differenciating by file types led to confusions in most subcommands +// as it would seem that sometimes mysql is restarting after a crash, while actually +// the operator was simply launching a "wsrep-recover" instance while mysql was still running +func (ctx LogCtx) State() string { + switch ctx.FileType { + case "post.processing.log": + return ctx.statePostProcessingLog + case "recovery.log": + return ctx.stateRecoveryLog + case "backup.log": + return ctx.stateBackupLog + case "error.log": + fallthrough + default: + return ctx.stateErrorLog + } +} + +// SetState will double-check if the STATE exists, and also store it on the correct status +func (ctx *LogCtx) SetState(s string) { + + // NON-PRIMARY and RECOVERY are not a real wsrep state, but it's helpful here + // DONOR and DESYNCED are merged in wsrep, but we are able to distinguish here + // list at gcs/src/gcs.cpp, gcs_conn_state_str + if !utils.SliceContains([]string{"SYNCED", "JOINED", "DONOR", "DESYNCED", "JOINER", "PRIMARY", "NON-PRIMARY", "OPEN", "CLOSED", "DESTROYED", "ERROR", "RECOVERY"}, s) { + return + } + //ctx.state[ctx.FileType] = append(ctx.state[ctx.FileType], s) + switch ctx.FileType { + case "post.processing.log": + ctx.statePostProcessingLog = s + case "recovery.log": + ctx.stateRecoveryLog = s + case "backup.log": + ctx.stateBackupLog = s + case "error.log": + fallthrough + default: + ctx.stateErrorLog = s + } +} + +func (ctx *LogCtx) HasVisibleEvents(level Verbosity) bool { + return level >= ctx.minVerbosity +} + +func (ctx *LogCtx) IsPrimary() bool { + return utils.SliceContains([]string{"SYNCED", "DONOR", "DESYNCED", "JOINER", "PRIMARY"}, ctx.State()) +} + +func (ctx *LogCtx) OwnHostname() string { + for _, ip := range ctx.OwnIPs { + if hn, ok := ctx.IPToHostname[ip]; ok { + return hn + } + } + for _, hash := range ctx.OwnHashes { + if hn, ok := ctx.IPToHostname[ctx.HashToIP[hash]]; ok { + return hn + } + } + return "" +} + +func (ctx *LogCtx) HashesFromIP(ip string) []string { + hashes := []string{} + for hash, ip2 := range ctx.HashToIP { + if ip == ip2 { + hashes = append(hashes, hash) + } + } + return hashes +} + +func (ctx *LogCtx) HashesFromNodeName(nodename string) []string { + hashes := []string{} + for hash, nodename2 := range ctx.HashToNodeName { + if nodename == nodename2 { + hashes = append(hashes, hash) + } + } + return hashes +} + +func (ctx *LogCtx) IPsFromNodeName(nodename string) []string { + ips := []string{} + for ip, nodename2 := range ctx.IPToNodeName { + if nodename == nodename2 { + ips = append(ips, ip) + } + } + return ips +} + +func (ctx *LogCtx) AllNodeNames() []string { + nodenames := ctx.OwnNames + for _, nn := range ctx.HashToNodeName { + if !utils.SliceContains(nodenames, nn) { + nodenames = append(nodenames, nn) + } + } + for _, nn := range ctx.IPToNodeName { + if !utils.SliceContains(nodenames, nn) { + nodenames = append(nodenames, nn) + } + } + return nodenames +} + +// AddOwnName propagates a name into the translation maps using the trusted node's known own hashes and ips +func (ctx *LogCtx) AddOwnName(name string) { + // used to be a simple "if utils.SliceContains", changed to "is it the last known name?" + // because somes names/ips come back and forth, we should keep track of that + name = utils.ShortNodeName(name) + if len(ctx.OwnNames) > 0 && ctx.OwnNames[len(ctx.OwnNames)-1] == name { + return + } + ctx.OwnNames = append(ctx.OwnNames, name) + for _, hash := range ctx.OwnHashes { + + ctx.HashToNodeName[hash] = name + } + for _, ip := range ctx.OwnIPs { + ctx.IPToNodeName[ip] = name + } +} + +// AddOwnHash propagates a hash into the translation maps +func (ctx *LogCtx) AddOwnHash(hash string) { + if utils.SliceContains(ctx.OwnHashes, hash) { + return + } + ctx.OwnHashes = append(ctx.OwnHashes, hash) + + for _, ip := range ctx.OwnIPs { + ctx.HashToIP[hash] = ip + } + for _, name := range ctx.OwnNames { + ctx.HashToNodeName[hash] = name + } +} + +// AddOwnIP propagates a ip into the translation maps +func (ctx *LogCtx) AddOwnIP(ip string) { + // see AddOwnName comment + if len(ctx.OwnIPs) > 0 && ctx.OwnIPs[len(ctx.OwnIPs)-1] == ip { + return + } + ctx.OwnIPs = append(ctx.OwnIPs, ip) + for _, hash := range ctx.OwnHashes { + ctx.HashToIP[hash] = ip + } + for _, name := range ctx.OwnNames { + ctx.IPToNodeName[ip] = name + } +} + +// MergeMapsWith will take a slice of contexts and merge every translation maps +// into the base context. It won't touch "local" infos such as "ownNames" +func (base *LogCtx) MergeMapsWith(ctxs []LogCtx) { + for _, ctx := range ctxs { + for hash, ip := range ctx.HashToIP { + base.HashToIP[hash] = ip + } + for hash, nodename := range ctx.HashToNodeName { + + base.HashToNodeName[hash] = nodename + } + for ip, hostname := range ctx.IPToHostname { + base.IPToHostname[ip] = hostname + } + for ip, nodename := range ctx.IPToNodeName { + base.IPToNodeName[ip] = nodename + } + for ip, method := range ctx.IPToMethod { + base.IPToMethod[ip] = method + } + } +} + +// Inherit will fill the local information from given context +// into the base +// It is used when merging, so that we do not start from nothing +// It helps when dealing with many small files +func (base *LogCtx) Inherit(ctx LogCtx) { + base.OwnHashes = append(ctx.OwnHashes, base.OwnHashes...) + base.OwnNames = append(ctx.OwnNames, base.OwnNames...) + base.OwnIPs = append(ctx.OwnIPs, base.OwnIPs...) + if base.Version == "" { + base.Version = ctx.Version + } + base.MergeMapsWith([]LogCtx{ctx}) +} + +func (l LogCtx) MarshalJSON() ([]byte, error) { + return json.Marshal(struct { + FilePath string + FileType string + OwnIPs []string + OwnHashes []string + OwnNames []string + StateErrorLog string + StateRecoveryLog string + StatePostProcessingLog string + StateBackupLog string + Version string + SST SST + MyIdx string + MemberCount int + Desynced bool + HashToIP map[string]string + HashToNodeName map[string]string + IPToHostname map[string]string + IPToMethod map[string]string + IPToNodeName map[string]string + MinVerbosity Verbosity + Conflicts Conflicts + }{ + FilePath: l.FilePath, + FileType: l.FileType, + OwnIPs: l.OwnIPs, + OwnHashes: l.OwnHashes, + StateErrorLog: l.stateErrorLog, + StateRecoveryLog: l.stateRecoveryLog, + StatePostProcessingLog: l.statePostProcessingLog, + StateBackupLog: l.stateBackupLog, + Version: l.Version, + SST: l.SST, + MyIdx: l.MyIdx, + MemberCount: l.MemberCount, + Desynced: l.Desynced, + HashToIP: l.HashToIP, + HashToNodeName: l.HashToNodeName, + IPToHostname: l.IPToHostname, + IPToMethod: l.IPToMethod, + IPToNodeName: l.IPToNodeName, + MinVerbosity: l.minVerbosity, + Conflicts: l.Conflicts, + }) +} diff --git a/src/go/pt-galera-log-explainer/types/loginfo.go b/src/go/pt-galera-log-explainer/types/loginfo.go new file mode 100644 index 00000000..9cd923f5 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/loginfo.go @@ -0,0 +1,97 @@ +package types + +import ( + "fmt" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" +) + +type Verbosity int + +const ( + Info Verbosity = iota + // Detailed is having every suspect/warn + Detailed + // DebugMySQL only includes finding that are usually not relevant to show but useful to create the log context (eg: how we found the local address) + DebugMySQL + Debug +) + +// LogInfo is to store a single event in log. This is something that should be displayed ultimately, this is what we want when we launch this tool +type LogInfo struct { + Date *Date + displayer LogDisplayer // what to show + Log string // the raw log + RegexType RegexType + RegexUsed string + Ctx LogCtx // the context is copied for each logInfo, so that it is easier to handle some info (current state), and this is also interesting to check how it evolved + Verbosity Verbosity + RepetitionCount int + extraNotes map[string]string +} + +func NewLogInfo(date *Date, displayer LogDisplayer, log string, regex *LogRegex, regexkey string, ctx LogCtx, filetype string) LogInfo { + li := LogInfo{ + Date: date, + Log: log, + displayer: displayer, + Ctx: ctx, + RegexType: regex.Type, + RegexUsed: regexkey, + Verbosity: regex.Verbosity, + extraNotes: map[string]string{}, + } + if filetype != "error.log" && filetype != "" { + li.extraNotes["filetype"] = filetype + } + return li +} + +func (li *LogInfo) Msg(ctx LogCtx) string { + if li.displayer == nil { + return "" + } + msg := "" + if li.RepetitionCount > 0 { + msg += utils.Paint(utils.BlueText, fmt.Sprintf("(repeated x%d)", li.RepetitionCount)) + } + msg += li.displayer(ctx) + for _, note := range li.extraNotes { + msg += utils.Paint(utils.BlueText, fmt.Sprintf("(%s)", note)) + } + return msg +} + +// IsDuplicatedEvent will aim to keep 2 occurences of the same event +// To be considered duplicated, they must be from the same regexes and have the same message +func (current *LogInfo) IsDuplicatedEvent(base, previous LogInfo) bool { + return base.RegexUsed == previous.RegexUsed && + base.displayer != nil && previous.displayer != nil && current.displayer != nil && + base.displayer(base.Ctx) == previous.displayer(previous.Ctx) && + previous.RegexUsed == current.RegexUsed && + previous.displayer(previous.Ctx) == current.displayer(current.Ctx) +} + +type Date struct { + Time time.Time + DisplayTime string + Layout string +} + +func NewDate(t time.Time, layout string) Date { + return Date{ + Time: t, + Layout: layout, + DisplayTime: t.Format(layout), + } +} + +// LogDisplayer is the handler to generate messages thanks to a context +// The context in parameters should be as updated as possible +type LogDisplayer func(LogCtx) string + +// SimpleDisplayer satisfies LogDisplayer and ignores any context received +func SimpleDisplayer(s string) LogDisplayer { + return func(_ LogCtx) string { return s } +} diff --git a/src/go/pt-galera-log-explainer/types/loginfo_test.go b/src/go/pt-galera-log-explainer/types/loginfo_test.go new file mode 100644 index 00000000..407cfc12 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/loginfo_test.go @@ -0,0 +1,53 @@ +package types + +import ( + "testing" +) + +func TestIsDuplicatedEvent(t *testing.T) { + + tests := []struct { + name string + inputbase LogInfo + inputprevious LogInfo + inputcurrent LogInfo + expected bool + }{ + { + name: "different regex, same output", + inputbase: LogInfo{RegexUsed: "some regex", displayer: SimpleDisplayer("")}, + inputprevious: LogInfo{RegexUsed: "some other regex", displayer: SimpleDisplayer("")}, + inputcurrent: LogInfo{RegexUsed: "yet another regex", displayer: SimpleDisplayer("")}, + expected: false, + }, + { + name: "same regex, different output", + inputbase: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("out1")}, + inputprevious: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("out2")}, + inputcurrent: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("out3")}, + expected: false, + }, + { + name: "not enough duplication yet", + inputbase: LogInfo{RegexUsed: "another regex", displayer: SimpleDisplayer("")}, + inputprevious: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("same")}, + inputcurrent: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("same")}, + expected: false, + }, + { + name: "duplicated", + inputbase: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("same")}, + inputprevious: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("same")}, + inputcurrent: LogInfo{RegexUsed: "same regex", displayer: SimpleDisplayer("same")}, + expected: true, + }, + } + + for _, test := range tests { + out := test.inputcurrent.IsDuplicatedEvent(test.inputbase, test.inputprevious) + if out != test.expected { + t.Fatalf("%s failed: expected %v, got %v", test.name, test.expected, out) + } + } + +} diff --git a/src/go/pt-galera-log-explainer/types/nodeinfo.go b/src/go/pt-galera-log-explainer/types/nodeinfo.go new file mode 100644 index 00000000..d1229050 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/nodeinfo.go @@ -0,0 +1,12 @@ +package types + +// NodeInfo is mainly used by "whois" subcommand +// This is to display its result +// As it's the base work for "sed" subcommand, it's in types package +type NodeInfo struct { + Input string `json:"input"` + IPs []string `json:"IPs"` + NodeNames []string `json:"nodeNames"` + Hostname string `json:"hostname"` + NodeUUIDs []string `json:"nodeUUIDs:"` +} diff --git a/src/go/pt-galera-log-explainer/types/regex.go b/src/go/pt-galera-log-explainer/types/regex.go new file mode 100644 index 00000000..1a3092a0 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/regex.go @@ -0,0 +1,91 @@ +package types + +import ( + "encoding/json" + "regexp" +) + +// LogRegex is the work struct to work on lines that were sent by "grep" + +type LogRegex struct { + Regex *regexp.Regexp // to send to grep, should be as simple as possible but without collisions + InternalRegex *regexp.Regexp // for internal usage in handler func + Type RegexType + + // Taking into arguments the current context and log line, returning an updated context and a closure to get the msg to display + // Why a closure: to later inject an updated context instead of the current partial context + // This ensure every hash/ip/nodenames are already known when crafting the message + Handler func(map[string]string, LogCtx, string) (LogCtx, LogDisplayer) + Verbosity Verbosity // To be able to hide details from summaries +} + +func (l *LogRegex) Handle(ctx LogCtx, line string) (LogCtx, LogDisplayer) { + if ctx.minVerbosity > l.Verbosity { + ctx.minVerbosity = l.Verbosity + } + mergedResults := map[string]string{} + if l.InternalRegex == nil { + return l.Handler(mergedResults, ctx, line) + } + slice := l.InternalRegex.FindStringSubmatch(line) + if len(slice) == 0 { + return ctx, nil + } + for _, subexpname := range l.InternalRegex.SubexpNames() { + if subexpname == "" { // 1st element is always empty for the complete regex + continue + } + mergedResults[subexpname] = slice[l.InternalRegex.SubexpIndex(subexpname)] + } + return l.Handler(mergedResults, ctx, line) +} + +func (l *LogRegex) MarshalJSON() ([]byte, error) { + out := &struct { + Regex string `json:"regex"` + InternalRegex string `json:"internalRegex"` + Type RegexType `json:"type"` + Verbosity Verbosity `json:"verbosity"` + }{ + Type: l.Type, + Verbosity: l.Verbosity, + } + if l.Regex != nil { + out.Regex = l.Regex.String() + } + if l.InternalRegex != nil { + out.InternalRegex = l.InternalRegex.String() + } + + return json.Marshal(out) +} + +type RegexType string + +var ( + EventsRegexType RegexType = "events" + SSTRegexType RegexType = "sst" + ViewsRegexType RegexType = "views" + IdentRegexType RegexType = "identity" + StatesRegexType RegexType = "states" + PXCOperatorRegexType RegexType = "pxc-operator" + ApplicativeRegexType RegexType = "applicative" +) + +type RegexMap map[string]*LogRegex + +func (r RegexMap) Merge(r2 RegexMap) RegexMap { + for key, value := range r2 { + r[key] = value + } + return r +} + +func (r RegexMap) Compile() []string { + + arr := []string{} + for _, regex := range r { + arr = append(arr, regex.Regex.String()) + } + return arr +} diff --git a/src/go/pt-galera-log-explainer/types/sst.go b/src/go/pt-galera-log-explainer/types/sst.go new file mode 100644 index 00000000..97986812 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/sst.go @@ -0,0 +1,15 @@ +package types + +type SST struct { + Method string + Type string + ResyncingNode string + ResyncedFromNode string +} + +func (s *SST) Reset() { + s.Method = "" + s.Type = "" + s.ResyncedFromNode = "" + s.ResyncingNode = "" +} diff --git a/src/go/pt-galera-log-explainer/types/timeline.go b/src/go/pt-galera-log-explainer/types/timeline.go new file mode 100644 index 00000000..5dbd07e7 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/timeline.go @@ -0,0 +1,178 @@ +package types + +import ( + "math" + "time" +) + +// It should be kept already sorted by timestamp +type LocalTimeline []LogInfo + +func (lt LocalTimeline) Add(li LogInfo) LocalTimeline { + + // to deduplicate, it will keep 2 loginfo occurences + // 1st one for the 1st timestamp found, it will also show the number of repetition + // 2nd loginfo the keep the last timestamp found, so that we don't loose track + // so there will be a corner case if the first ever event is repeated, but that is acceptable + if len(lt) > 1 && li.IsDuplicatedEvent(lt[len(lt)-2], lt[len(lt)-1]) { + lt[len(lt)-2].RepetitionCount++ + lt[len(lt)-1] = li + } else { + lt = append(lt, li) + } + return lt +} + +// "string" key is a node IP +type Timeline map[string]LocalTimeline + +// MergeTimeline is helpful when log files are split by date, it can be useful to be able to merge content +// a "timeline" come from a log file. Log files that came from some node should not never have overlapping dates +func MergeTimeline(t1, t2 LocalTimeline) LocalTimeline { + if len(t1) == 0 { + return t2 + } + if len(t2) == 0 { + return t1 + } + + startt1 := getfirsttime(t1) + startt2 := getfirsttime(t2) + + // just flip them, easier than adding too many nested conditions + // t1: ---O----?-- + // t2: --O-----?-- + if startt1.After(startt2) { + return MergeTimeline(t2, t1) + } + + endt1 := getlasttime(t1) + endt2 := getlasttime(t2) + + // if t2 is an updated version of t1, or t1 an updated of t2, or t1=t2 + // t1: --O-----?-- + // t2: --O-----?-- + if startt1.Equal(startt2) { + // t2 > t1 + // t1: ---O---O---- + // t2: ---O-----O-- + if endt1.Before(endt2) { + return t2 + } + // t1: ---O-----O-- + // t2: ---O-----O-- + // or + // t1: ---O-----O-- + // t2: ---O---O---- + return t1 + } + + // if t1 superseds t2 + // t1: --O-----O-- + // t2: ---O---O--- + // or + // t1: --O-----O-- + // t2: ---O----O-- + if endt1.After(endt2) || endt1.Equal(endt2) { + return t1 + } + //return append(t1, t2...) + + // t1: --O----O---- + // t2: ----O----O-- + if endt1.After(startt2) { + // t1: --O----O---- + // t2: ----OO--OO-- + //>t : --O----OOO-- won't try to get things between t1.end and t2.start + // we assume they're identical, they're supposed to be from the same server + t2 = CutTimelineAt(t2, endt1) + // no return here, to avoid repeating the ctx.inherit + } + + // t1: --O--O------ + // t2: ------O--O-- + t2[len(t2)-1].Ctx.Inherit(t1[len(t1)-1].Ctx) + return append(t1, t2...) +} + +func getfirsttime(l LocalTimeline) time.Time { + for _, event := range l { + if event.Date != nil && (event.Ctx.FileType == "error.log" || event.Ctx.FileType == "") { + return event.Date.Time + } + } + return time.Time{} +} +func getlasttime(l LocalTimeline) time.Time { + for i := len(l) - 1; i >= 0; i-- { + if l[i].Date != nil && (l[i].Ctx.FileType == "error.log" || l[i].Ctx.FileType == "") { + return l[i].Date.Time + } + } + return time.Time{} +} + +// CutTimelineAt returns a localtimeline with the 1st event starting +// right after the time sent as parameter +func CutTimelineAt(t LocalTimeline, at time.Time) LocalTimeline { + var i int + for i = 0; i < len(t); i++ { + if t[i].Date.Time.After(at) { + break + } + } + + return t[i:] +} + +func (t *Timeline) GetLatestUpdatedContextsByNodes() map[string]LogCtx { + updatedCtxs := map[string]LogCtx{} + latestctxs := []LogCtx{} + + for key, localtimeline := range *t { + if len(localtimeline) == 0 { + updatedCtxs[key] = NewLogCtx() + continue + } + latestctx := localtimeline[len(localtimeline)-1].Ctx + latestctxs = append(latestctxs, latestctx) + updatedCtxs[key] = latestctx + } + + for _, ctx := range updatedCtxs { + ctx.MergeMapsWith(latestctxs) + } + return updatedCtxs +} + +// iterateNode is used to search the source node(s) that contains the next chronological events +// it returns a slice in case 2 nodes have their next event precisely at the same time, which +// happens a lot on some versions +func (t Timeline) IterateNode() []string { + var ( + nextDate time.Time + nextNodes []string + ) + nextDate = time.Unix(math.MaxInt32, 0) + for node := range t { + if len(t[node]) == 0 { + continue + } + curDate := getfirsttime(t[node]) + if curDate.Before(nextDate) { + nextDate = curDate + nextNodes = []string{node} + } else if curDate.Equal(nextDate) { + nextNodes = append(nextNodes, node) + } + } + return nextNodes +} + +func (t Timeline) Dequeue(node string) { + + // dequeue the events + if len(t[node]) > 0 { + t[node] = t[node][1:] + } +} diff --git a/src/go/pt-galera-log-explainer/types/timeline_test.go b/src/go/pt-galera-log-explainer/types/timeline_test.go new file mode 100644 index 00000000..7b6dd659 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/timeline_test.go @@ -0,0 +1,261 @@ +package types + +import ( + "reflect" + "testing" + "time" +) + +func TestMergeTimeline(t *testing.T) { + + tests := []struct { + name string + input1 LocalTimeline + input2 LocalTimeline + expected LocalTimeline + }{ + { + name: "t1 is completely before the t2", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + { + name: "t1 is completely after the t2", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + }, + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + { + name: "t1 is a superset of t2, with same start time", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + }, + // actually what is expected, as we don't expect logs to be different as we already merge them when they are with an identical identifier + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + { + name: "t1 overlap with t2, sharing events", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 4, 1, 1, 1, 1, time.UTC)}, + }, + }, + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 4, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + + { + name: "t1 is completely before the t2, but t2 has null trailing dates", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{}, + }, + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{}, + }, + }, + + { + name: "t1 is completely before the t2, but t1 has null leading dates", + input1: LocalTimeline{ + LogInfo{}, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + expected: LocalTimeline{ + LogInfo{}, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 2, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + } + + for _, test := range tests { + out := MergeTimeline(test.input1, test.input2) + if !reflect.DeepEqual(out, test.expected) { + t.Fatalf("%s failed: expected %v, got %v", test.name, test.expected, out) + } + } + +} + +func TestCutTimelineAt(t *testing.T) { + + tests := []struct { + name string + input1 LocalTimeline + input2 time.Time + expected LocalTimeline + }{ + { + name: "simple cut", + input1: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 1, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC)}, + }, + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + input2: time.Date(2023, time.January, 2, 1, 1, 1, 1, time.UTC), + expected: LocalTimeline{ + LogInfo{ + Date: &Date{Time: time.Date(2023, time.January, 3, 1, 1, 1, 1, time.UTC)}, + }, + }, + }, + } + + for _, test := range tests { + out := CutTimelineAt(test.input1, test.input2) + if !reflect.DeepEqual(out, test.expected) { + t.Fatalf("%s failed: expected %v, got %v", test.name, test.expected, out) + } + } + +} diff --git a/src/go/pt-galera-log-explainer/types/utils.go b/src/go/pt-galera-log-explainer/types/utils.go new file mode 100644 index 00000000..201b2d21 --- /dev/null +++ b/src/go/pt-galera-log-explainer/types/utils.go @@ -0,0 +1,56 @@ +package types + +import ( + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "github.com/rs/zerolog/log" +) + +// Identifier is used to identify a node timeline. +// It will the column headers +// It will also impacts how logs are merged if we have multiple logs per nodes +// +// In order of preference: wsrep_node_name (or galera "node" name), hostname, ip, filepath +func Identifier(ctx LogCtx) string { + if len(ctx.OwnNames) > 0 { + return ctx.OwnNames[len(ctx.OwnNames)-1] + } + if len(ctx.OwnIPs) > 0 { + return DisplayNodeSimplestForm(ctx, ctx.OwnIPs[len(ctx.OwnIPs)-1]) + } + if len(ctx.OwnHashes) > 0 { + if name, ok := ctx.HashToNodeName[ctx.OwnHashes[0]]; ok { + return name + } + if ip, ok := ctx.HashToIP[ctx.OwnHashes[0]]; ok { + return DisplayNodeSimplestForm(ctx, ip) + } + } + return ctx.FilePath +} + +// DisplayNodeSimplestForm is useful to get the most easily to read string for a given IP +// This only has impacts on display +// In order of preference: wsrep_node_name (or galera "node" name), hostname, ip +func DisplayNodeSimplestForm(ctx LogCtx, ip string) string { + if nodename, ok := ctx.IPToNodeName[ip]; ok { + s := utils.ShortNodeName(nodename) + log.Debug().Str("ip", ip).Str("simplestform", s).Str("from", "IPToNodeName").Msg("nodeSimplestForm") + return s + } + + for hash, storedip := range ctx.HashToIP { + if ip == storedip { + if nodename, ok := ctx.HashToNodeName[hash]; ok { + s := utils.ShortNodeName(nodename) + log.Debug().Str("ip", ip).Str("simplestform", s).Str("from", "HashToNodeName").Msg("nodeSimplestForm") + return s + } + } + } + if hostname, ok := ctx.IPToHostname[ip]; ok { + log.Debug().Str("ip", ip).Str("simplestform", hostname).Str("from", "IPToHostname").Msg("nodeSimplestForm") + return hostname + } + log.Debug().Str("ip", ip).Str("simplestform", ip).Str("from", "default").Msg("nodeSimplestForm") + return ip +} diff --git a/src/go/pt-galera-log-explainer/utils/utils.go b/src/go/pt-galera-log-explainer/utils/utils.go new file mode 100644 index 00000000..900acf7d --- /dev/null +++ b/src/go/pt-galera-log-explainer/utils/utils.go @@ -0,0 +1,123 @@ +package utils + +import ( + "fmt" + "strings" +) + +// Color is given its own type for safe function signatures +type Color string + +// Color codes interpretted by the terminal +// NOTE: all codes must be of the same length or they will throw off the field alignment of tabwriter +const ( + ResetText Color = "\x1b[0000m" + BrightText = "\x1b[0001m" + RedText = "\x1b[0031m" + GreenText = "\x1b[0032m" + YellowText = "\x1b[0033m" + BlueText = "\x1b[0034m" + MagentaText = "\x1b[0035m" + CyanText = "\x1b[0036m" + WhiteText = "\x1b[0037m" + DefaultText = "\x1b[0039m" + BrightRedText = "\x1b[1;31m" + BrightGreenText = "\x1b[1;32m" + BrightYellowText = "\x1b[1;33m" + BrightBlueText = "\x1b[1;34m" + BrightMagentaText = "\x1b[1;35m" + BrightCyanText = "\x1b[1;36m" + BrightWhiteText = "\x1b[1;37m" +) + +var colorsToTextColor = map[string]Color{ + "yellow": YellowText, + "green": GreenText, + "red": RedText, +} + +var SkipColor bool + +// Color implements the Stringer interface for interoperability with string +func (c *Color) String() string { + return string(*c) +} + +func Paint(color Color, value string) string { + if SkipColor { + return value + } + return fmt.Sprintf("%v%v%v", color, value, ResetText) +} + +func PaintForState(text, state string) string { + + c := ColorForState(state) + if c != "" { + return Paint(colorsToTextColor[c], text) + } + + return text +} + +func ColorForState(state string) string { + switch state { + case "DONOR", "JOINER", "DESYNCED": + return "yellow" + case "SYNCED": + return "green" + case "CLOSED", "NON-PRIMARY": + return "red" + default: + return "" + } +} + +func SliceContains(s []string, str string) bool { + for _, v := range s { + if v == str { + return true + } + } + return false +} + +func SliceMergeDeduplicate(s, s2 []string) []string { + for _, str := range s2 { + if !SliceContains(s, str) { + s = append(s, str) + } + } + return s +} + +// StringsReplaceReversed is similar to strings.Replace, but replacing the +// right-most elements instead of left-most +func StringsReplaceReversed(s, old, new string, n int) string { + + s2 := s + stop := len(s) + + for i := 0; i < n; i++ { + stop = strings.LastIndex(s[:stop], old) + + s2 = (s[:stop]) + new + s2[stop+len(old):] + } + return s2 +} + +func UUIDToShortUUID(uuid string) string { + splitted := strings.Split(uuid, "-") + return splitted[0] + "-" + splitted[3] +} + +// ShortNodeName helps reducing the node name when it is the default value (node hostname) +// It only keeps the top-level domain +func ShortNodeName(s string) string { + // short enough + if len(s) < 10 { + return s + } + before, _, _ := strings.Cut(s, ".") + return before +} diff --git a/src/go/pt-galera-log-explainer/utils/utils_test.go b/src/go/pt-galera-log-explainer/utils/utils_test.go new file mode 100644 index 00000000..dbc3fe60 --- /dev/null +++ b/src/go/pt-galera-log-explainer/utils/utils_test.go @@ -0,0 +1,42 @@ +package utils + +import "testing" + +func TestStringsReplaceReverse(t *testing.T) { + + tests := []struct { + inputS string + inputOld string + inputNew string + inputCount int + expected string + }{ + { + inputS: "2022-22-22", + inputOld: "22", + inputNew: "XX", + inputCount: 1, + expected: "2022-22-XX", + }, + { + inputS: "2022-22-22", + inputOld: "22", + inputNew: "XX", + inputCount: 2, + expected: "2022-XX-XX", + }, + { + inputS: "2022-22-22", + inputOld: "22", + inputNew: "XX", + inputCount: 3, + expected: "20XX-XX-XX", + }, + } + for _, test := range tests { + if s := StringsReplaceReversed(test.inputS, test.inputOld, test.inputNew, test.inputCount); s != test.expected { + t.Log("Expected", test.expected, "got", s) + t.Fail() + } + } +} diff --git a/src/go/pt-galera-log-explainer/whois.go b/src/go/pt-galera-log-explainer/whois.go new file mode 100644 index 00000000..f8a7b500 --- /dev/null +++ b/src/go/pt-galera-log-explainer/whois.go @@ -0,0 +1,102 @@ +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-galera-log-explainer/utils" + "github.com/pkg/errors" +) + +type whois struct { + Search string `arg:"" name:"search" help:"the identifier (node name, ip, uuid, hash) to search"` + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` +} + +func (w *whois) Help() string { + return `Take any type of info pasted from error logs and find out about it. +It will list known node name(s), IP(s), hostname(s), and other known node's UUIDs. +` +} + +func (w *whois) Run() error { + + toCheck := regex.AllRegexes() + timeline, err := timelineFromPaths(CLI.Whois.Paths, toCheck, CLI.Since, CLI.Until) + if err != nil { + return errors.Wrap(err, "Found nothing to translate") + } + ctxs := timeline.GetLatestUpdatedContextsByNodes() + + ni := whoIs(ctxs, CLI.Whois.Search) + + json, err := json.MarshalIndent(ni, "", "\t") + if err != nil { + return err + } + fmt.Println(string(json)) + return nil +} + +func whoIs(ctxs map[string]types.LogCtx, search string) types.NodeInfo { + ni := types.NodeInfo{Input: search} + if regex.IsNodeUUID(search) { + search = utils.UUIDToShortUUID(search) + } + var ( + ips []string + hashes []string + nodenames []string + ) + + for _, ctx := range ctxs { + if utils.SliceContains(ctx.OwnNames, search) || utils.SliceContains(ctx.OwnHashes, search) || utils.SliceContains(ctx.OwnIPs, search) { + ni.NodeNames = ctx.OwnNames + ni.NodeUUIDs = ctx.OwnHashes + ni.IPs = ctx.OwnIPs + ni.Hostname = ctx.OwnHostname() + } + + if nodename, ok := ctx.HashToNodeName[search]; ok { + nodenames = utils.SliceMergeDeduplicate(nodenames, []string{nodename}) + hashes = utils.SliceMergeDeduplicate(hashes, []string{search}) + } + + if ip, ok := ctx.HashToIP[search]; ok { + ips = utils.SliceMergeDeduplicate(ips, []string{ip}) + hashes = utils.SliceMergeDeduplicate(hashes, []string{search}) + + } else if nodename, ok := ctx.IPToNodeName[search]; ok { + nodenames = utils.SliceMergeDeduplicate(nodenames, []string{nodename}) + ips = utils.SliceMergeDeduplicate(ips, []string{search}) + + } else if utils.SliceContains(ctx.AllNodeNames(), search) { + nodenames = utils.SliceMergeDeduplicate(nodenames, []string{search}) + } + + for _, nodename := range nodenames { + hashes = utils.SliceMergeDeduplicate(hashes, ctx.HashesFromNodeName(nodename)) + ips = utils.SliceMergeDeduplicate(ips, ctx.IPsFromNodeName(nodename)) + } + + for _, ip := range ips { + hashes = utils.SliceMergeDeduplicate(hashes, ctx.HashesFromIP(ip)) + nodename, ok := ctx.IPToNodeName[ip] + if ok { + nodenames = utils.SliceMergeDeduplicate(nodenames, []string{nodename}) + } + } + for _, hash := range hashes { + nodename, ok := ctx.HashToNodeName[hash] + if ok { + nodenames = utils.SliceMergeDeduplicate(nodenames, []string{nodename}) + } + } + } + ni.NodeNames = nodenames + ni.NodeUUIDs = hashes + ni.IPs = ips + return ni +}