diff --git a/docs/pt-mongo-log-explainer.rst b/docs/pt-mongo-log-explainer.rst new file mode 100644 index 000000000..13e31601f --- /dev/null +++ b/docs/pt-mongo-log-explainer.rst @@ -0,0 +1 @@ +../src/go/pt-mongo-log-explainer/README.rst diff --git a/src/go/pt-mongo-log-explainer/README.rst b/src/go/pt-mongo-log-explainer/README.rst new file mode 100644 index 000000000..25a8388df --- /dev/null +++ b/src/go/pt-mongo-log-explainer/README.rst @@ -0,0 +1,379 @@ +.. _pt-mongo-log-explainer-readme: + +================================ +:program:`pt-mongo-log-explainer` +================================ + +Filter, aggregate, and summarize **MongoDB** (``mongod`` / ``mongos``) logs—especially **replica set** and **sharded cluster** deployments. + +The tool accepts multiple log files in **text** (legacy) or **JSON** (structured logging, MongoDB 4.4+), classifies lines into events, optionally **correlates** related sequences across nodes, **tags anomalies**, and prints a **chronological timeline** (``timeline``) or a **columnar multi-node view** (``list``). + +Usage +===== + +.. code-block:: bash + + pt-mongo-log-explainer [--config=...] [--since=TIME] [--until=TIME] [-v|-vv] [--no-color] + [--merge-by-directory] [--skip-merge] [--exclude-regexes=...] [--grep-cmd=PATH] + [--custom-regexes=...] [--version] [--version-check] + + + +Commands available +==================== + +timeline (recommended) +~~~~~~~~~~~~~~~~~~~~~~~~ + +Merged chronological timeline (one event per line, or JSON). + +.. code-block:: bash + + pt-mongo-log-explainer timeline [flags] [log2] ... + +**Default output format**:: + + [timestamp] [node] [host:port] [event_type] [status] [details] + +**Examples** + +.. code-block:: bash + + pt-mongo-log-explainer timeline /path/node1.log /path/node2.log + pt-mongo-log-explainer timeline --full-scan --elections --replication *.log + pt-mongo-log-explainer timeline --errors --highlight-anomalies=true *.log + pt-mongo-log-explainer timeline --json *.log + pt-mongo-log-explainer timeline --timezone=America/New_York *.log + pt-mongo-log-explainer timeline --limit=500 *.log + pt-mongo-log-explainer timeline --skip-correlate --skip-anomalies *.log + +**Category filters** (OR logic; omit all to include every classified event): + +``--elections`` + Election, primary/secondary transitions, heartbeats, topology, quorum. + +``--replication`` + Initial sync, rollback, oplog, sync source changes, replication lag. + +``--errors`` + Auth, network, socket, DNS, connection pool, write concern, fatals. + +``--sharding`` + Chunk migration, balancer, generic sharding lines. + +``--performance`` + Slow queries, long-running commands, index builds, timeouts. + +**Other timeline flags** + +``--full-scan`` + Read entire files (no ``grep -P`` pre-filter). + +``--json`` + JSON array output. + +``--highlight-anomalies`` / ``--highlight-anomalies=true`` + Highlight ``[ANOMALY:...]`` tags (respects global ``--no-color``). + +``--timezone=ZONE`` + IANA timezone for timestamps (default ``UTC``). + +``--limit=N`` + Max events after filters (``0`` = unlimited). + +``--skip-correlate`` / ``--skip-anomalies`` + Disable correlation or anomaly passes. + + +list +~~~~ + +Columnar output: one column per log / node slice. Pick **one** of ``--all`` **or** any of the grouped flags below. + +.. code-block:: bash + + pt-mongo-log-explainer list { --all | [--states] [--topology] [--events] [--replication] [--cluster] } + +**Examples** + +.. code-block:: bash + + pt-mongo-log-explainer list --all node1.log node2.log + pt-mongo-log-explainer list --replication --topology --states *.log + pt-mongo-log-explainer list --events --topology *.log + +``--skip-state-colored-column`` + Do not color idle columns by inferred member state. + + +whois +~~~~~ + +Resolve a hostname, IPv4, host:port, or member ``_id`` using the translation database built from logs. + +.. code-block:: bash + + pt-mongo-log-explainer whois [--json] [--type { nodename | ip | hostport | _id | auto }] + +**Examples** + +.. code-block:: bash + + pt-mongo-log-explainer whois 507f1f77bcf86cd799439011 mongo.log + pt-mongo-log-explainer whois 10.0.0.3 *.log + pt-mongo-log-explainer whois shard1-primary *.log + + +ctx +~~~ + +Dump inferred context (translation DB + per-file contexts) as JSON. + +.. code-block:: bash + + pt-mongo-log-explainer ctx + + +regex-list +~~~~~~~~~~ + +Print all built-in regex definitions as JSON (for use with ``--exclude-regexes``). + +.. code-block:: bash + + pt-mongo-log-explainer regex-list + + +Global flags (before ````) +=================================== + +``--config`` + Toolkit configuration file(s); must be first if specified. + +``--since`` / ``--until`` + RFC3339 timestamps; only events inside the window are kept. + +``--no-color`` + Strip ANSI color sequences from stderr/stdout helpers. + +``-v`` / ``-vv`` + Verbose / debug logging. + +``--merge-by-directory`` / ``--skip-merge`` + Control how multi-file logs are merged for identity / columns. + +``--exclude-regexes`` + Repeatable; each value removes a regex key (see ``regex-list``). + Scope: the regex pipeline used by ``list``, ``whois`` and ``ctx``. It does + not affect ``timeline`` / ``summary``, which use the structured parser. + +``--grep-cmd`` + Path to GNU-compatible ``grep`` (default ``grep``). Use ``ggrep`` on macOS when needed. + +``--custom-regexes`` + ``PATTERN=message`` pairs separated by ``;`` (optional static message). + Scope: the regex pipeline used by ``list``, ``whois`` and ``ctx``. Custom + regexes are not applied to ``timeline`` / ``summary``. + +``--version`` / ``--version-check`` + Print version; optionally contact Percona update API. + + +Example outputs +=============== + +.. code-block:: text + + [2026-04-22 10:15:32] [node1] [10.0.0.1:27017] [ELECTION_SUCCESS] [SUCCESS] [term=5] + [ANOMALY:ELECTION_STORM] [2026-04-22 10:16:01] [node1] [10.0.0.1:27017] [ELECTION] [INFO] [rs=rs0] + + +Event Type Reference +==================== + +Node / Instance +~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``PROCESS_START`` node MongoDB process startup (mongod or mongos) +``PROCESS_SHUTDOWN`` failure Graceful or forced shutdown +``NODE_LISTEN`` node Listening for connections on port +============================== ====================== ====================================================== + +Replica Set Role & Status +~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``PRIMARY_TRANSITION`` role Node became primary +``SECONDARY_TRANSITION`` role Node became secondary +``STEPDOWN`` role Primary stepping down +``ELECTION`` role Election event (generic) +``ELECTION_SUCCESS`` role Election succeeded +``ELECTION_FAIL`` role Election failed or aborted +``MEMBER_STATE`` role Member state change (PRIMARY, SECONDARY, etc.) +``REPL_STATE`` role Replication state info +============================== ====================== ====================================================== + +Cluster Topology +~~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``HEARTBEAT`` topology Heartbeat success +``HEARTBEAT_FAIL`` topology Heartbeat failure / timeout +``MEMBER_JOIN`` topology New member added to replica set +``MEMBER_LEAVE`` topology Member removed from replica set +``MEMBER_UNREACHABLE`` topology Member marked not reachable / DOWN +``RECONFIG`` topology Replica set reconfiguration +``RS_CONFIG`` topology Replica set config dump +``RS_INITIATE`` topology Replica set initiation +``QUORUM_LOSS`` topology Not enough members for majority +``QUORUM_OK`` topology Quorum check succeeded +============================== ====================== ====================================================== + +Replication Events +~~~~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``INITIAL_SYNC`` replication Initial sync start / complete / failure +``ROLLBACK`` replication Rollback in progress +``REPL_OPLOG`` replication Oplog apply / repl writer activity +``REPL_LAG`` replication Replication lag measurement +``SYNC_SOURCE_CHANGE`` replication Oplog sync source changed +``OPLOG_WINDOW`` replication Oplog window shrinking warning +``OPLOG_TAIL_SLOW`` replication Slow oplog tailing +``REPL`` replication Generic replication event (REPL component fallback) +============================== ====================== ====================================================== + +Failures & Errors +~~~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``NETWORK_ERROR`` failure Generic network error / connection closed +``AUTH_FAILURE`` failure Authentication failure +``FATAL_ERROR`` failure Fatal assertion or crash +``CONN_POOL_ERROR`` failure Connection pool exhaustion +``SOCKET_ERROR`` failure Socket exception +``DNS_ERROR`` failure DNS resolution failure +``WRITE_CONCERN_ERROR`` failure Write concern timeout or error +============================== ====================== ====================================================== + +Sharding Events +~~~~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``CHUNK_MIGRATION`` sharding Chunk migration (phase=start/complete/abort) +``BALANCER`` sharding Balancer activity (enabled/disabled/round) +``SHARDING`` sharding Generic sharding event (component fallback) +============================== ====================== ====================================================== + +Performance +~~~~~~~~~~~~~ + +============================== ====================== ====================================================== +Event Type Category Description +============================== ====================== ====================================================== +``SLOW_QUERY`` performance Slow query detected +``SLOW_WRITE`` performance Slow write operation +``LONG_RUNNING_CMD`` performance Command exceeding time threshold +``INDEX_BUILD`` performance Index build start / complete +``OP_TIMEOUT`` performance Operation exceeded MaxTimeMS +``CURSOR_TIMEOUT`` performance Cursor timed out +============================== ====================== ====================================================== + + +Anomaly Detection +================= + +The tool automatically flags anomalous patterns with ``[ANOMALY:TAG]`` markers. + +============================== ====================================================== +Anomaly Tag Trigger +============================== ====================================================== +``ROLLBACK`` Any rollback event +``LAG`` Replication lag detected +``LAG_SPIKE`` Numeric lag > 10 seconds +``ELECTION_STORM`` 3+ elections within 5 minutes +``FREQUENT_ELECTIONS`` 4+ elections within 15 minutes +``TOPOLOGY_FLAP`` 5+ member join/leave events in 30 minutes +``NODE_FLAPPING`` 3+ restart cycles (shutdown+start) in 30 minutes +``SYNC_FAILURE`` Initial sync or other sync failure +``SYNC_TIMEOUT`` Initial sync start without completion in 2 hours +``AUTH_BURST`` 5+ auth failures from same node in 1 minute +``SUSTAINED_HB_FAIL`` 3+ heartbeat failures within 30 seconds +============================== ====================================================== + + +Event Correlation +================= + +The correlator detects cross-node causal sequences and annotates event details +with ``sequence=`` tags: + +- **heartbeat_loss -> election**: Heartbeat failure followed by election within 3 minutes +- **stepdown -> election -> primary**: Stepdown chain with new primary within 30 seconds +- **initial_sync_lifecycle**: Initial sync start matched with its completion/failure +- **restart**: Process shutdown followed by start on the same node within 10 minutes +- **rollback -> recovery**: Rollback followed by oplog catch-up on the same node +- **migration lifecycle**: Chunk migration start matched with complete/abort + +Related events share a ``sequence_id`` field in JSON output for programmatic grouping. + + +JSON Output Schema +================== + +When using ``timeline --json``, each event is a JSON object:: + + { + "time": "2026-04-20T10:00:06Z", + "node": "mongo-primary", + "host_port": "10.0.0.1:27017", + "event_type": "ELECTION_SUCCESS", + "status": "SUCCESS", + "details": "term=1 newState=PRIMARY", + "category": "role", + "source_file": "/path/to/node1.log", + "raw": "", + "anomaly": "ELECTION_STORM", + "sequence_id": "stepdown-3" + } + +Fields ``raw``, ``anomaly``, and ``sequence_id`` are omitted when empty. + + +Sphinx / HTML documentation +=========================== + +A Percona-style page suitable for the Toolkit docs tree lives at: + +``docs/pt-mongo-log-explainer.rst`` (repository root). + + +Requirements +============ + +* ``grep`` with **PCRE** support (``grep -P``), version 3.x typical on Linux. +* On macOS, set ``--grep-cmd=ggrep`` if BSD grep is the default. + +Building +======== + +From the Go module (see the main Percona Toolkit Makefile under ``src/go``): + +.. code-block:: bash + + VERSION=0.0.1 make build + +This produces ``bin/pt-mongo-log-explainer`` when run from repository conventions. diff --git a/src/go/pt-mongo-log-explainer/collect/pattern.go b/src/go/pt-mongo-log-explainer/collect/pattern.go new file mode 100644 index 000000000..44785cb1c --- /dev/null +++ b/src/go/pt-mongo-log-explainer/collect/pattern.go @@ -0,0 +1,68 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package collect + +import "strings" + +// GrepAlternation returns a PCRE alternation of literals for fast pre-filtering (grep -P). +func GrepAlternation() string { + parts := []string{ + `election`, `primary`, `secondary`, `arbiter`, `rollback`, `heartbeat`, + `initial sync`, `replSet`, `replica set`, `reconfig`, `stepped down`, `stepping down`, + `mongos`, `chunk`, `balancer`, `migration`, `sharding`, + `authentication failed`, `auth failed`, `network error`, `connection reset`, + `MongoDB starting`, `waiting for connections`, `shutting down`, `now exiting`, + `fatal`, `assertion`, `slow query`, `oplog`, `transition to`, `member is now in state`, + `pid=`, `64-bit host=`, `db version`, `Replica Set Member State`, + `"msg"`, `"c":"REPL"`, `"c":"SHARDING"`, `"c":"NETWORK"`, `"c":"CONN"`, + `Changed sync source`, `sync source`, `oplog window`, + `quorum`, `not enough`, `majority`, + `not reachable`, `connection pool`, `socket exception`, `SocketException`, + `DNS resolution`, `write concern`, `WriteConcernError`, + `index build`, `exceeded time limit`, `MaxTimeMSExpired`, + `cursor.*timed out`, `long-running`, + `migration started`, `migration committed`, `migration aborted`, + `balancer round`, `balancer enabled`, `balancer disabled`, + `"c":"ELECTION"`, `"c":"REPL_HB"`, `"c":"INDEX"`, + } + var b strings.Builder + for i, p := range parts { + if i > 0 { + b.WriteString(`|`) + } + b.WriteString(regexpQuoteMetaPCRE(p)) + } + return b.String() +} + +func regexpQuoteMetaPCRE(s string) string { + // minimal escaping for alternation literals in PCRE + r := strings.NewReplacer( + `\`, `\\`, + `.`, `\.`, + `*`, `\*`, + `+`, `\+`, + `?`, `\?`, + `|`, `\|`, + `(`, `\(`, + `)`, `\)`, + `[`, `\[`, + `]`, `\]`, + `{`, `\{`, + `}`, `\}`, + `^`, `\^`, + `$`, `\$`, + ) + return r.Replace(s) +} diff --git a/src/go/pt-mongo-log-explainer/collect/stream.go b/src/go/pt-mongo-log-explainer/collect/stream.go new file mode 100644 index 000000000..ef5041ab0 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/collect/stream.go @@ -0,0 +1,76 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package collect + +import ( + "bufio" + "os" + "os/exec" + "strings" + + "github.com/pkg/errors" +) + +// ForEachLine invokes fn for each line in path. If useGrep is true, only lines matching +// GrepAlternation() are passed (via grep -P); otherwise the whole file is scanned. +func ForEachLine(path, grepCmd string, useGrep bool, fn func(string) error) error { + if useGrep { + return forEachLineGrep(path, grepCmd, fn) + } + f, err := os.Open(path) + if err != nil { + return err + } + defer f.Close() + s := bufio.NewScanner(f) + s.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for s.Scan() { + if err := fn(s.Text()); err != nil { + return err + } + } + return s.Err() +} + +func forEachLineGrep(path, grepCmd string, fn func(string) error) error { + pat := GrepAlternation() + cmd := exec.Command(grepCmd, "-a", "-P", pat, path) + out, err := cmd.StdoutPipe() + if err != nil { + return err + } + if err := cmd.Start(); err != nil { + return errors.Wrapf(err, "grep start on %s", path) + } + s := bufio.NewScanner(out) + s.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for s.Scan() { + line := s.Text() + if strings.HasPrefix(line, "\t") { + line = line[1:] + } + if err := fn(line); err != nil { + _ = cmd.Process.Kill() + return err + } + } + _ = out.Close() + if err := cmd.Wait(); err != nil { + if exit, ok := err.(*exec.ExitError); ok && exit.ExitCode() == 1 { + return nil + } + return errors.Wrap(err, "grep") + } + return s.Err() +} diff --git a/src/go/pt-mongo-log-explainer/correlator/correlator.go b/src/go/pt-mongo-log-explainer/correlator/correlator.go new file mode 100644 index 000000000..54b2167c9 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/correlator/correlator.go @@ -0,0 +1,393 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package correlator + +import ( + "fmt" + "regexp" + "sort" + "strconv" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" +) + +var seqCounter int + +func nextSeqID(prefix string) string { + seqCounter++ + return fmt.Sprintf("%s-%d", prefix, seqCounter) +} + +// ResetSequenceCounter resets the internal counter (useful for tests). +func ResetSequenceCounter() { seqCounter = 0 } + +// addSeqTag prepends a "sequence=..." hint to an event's details, but only once. +// Without this guard an event matched by two upstream events (e.g. an election +// preceded by two stepdown lines) would receive the same tag repeatedly. +func addSeqTag(details, tag string) string { + if strings.Contains(details, tag) { + return details + } + return strings.TrimSpace(tag + " " + details) +} + +// SortByTime sorts events chronologically (stable for equal timestamps). +func SortByTime(evts []*types.StructuredEvent) { + sort.SliceStable(evts, func(i, j int) bool { + if evts[i].Time.Equal(evts[j].Time) { + return evts[i].SourceFile < evts[j].SourceFile + } + return evts[i].Time.Before(evts[j].Time) + }) +} + +// Correlate adds cross-node sequence hints to event details and assigns SequenceIDs. +func Correlate(evts []*types.StructuredEvent) { + correlateHeartbeatElection(evts) + correlateStepdownChain(evts) + correlateSyncLifecycle(evts) + correlateMigrationLifecycle(evts) + correlateRestartSequence(evts) + correlateRollbackCascade(evts) +} + +func correlateHeartbeatElection(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "HEARTBEAT_FAIL" { + continue + } + t0 := evts[i].Time + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 3*time.Minute { + break + } + if strings.HasPrefix(evts[j].EventType, "ELECTION") { + sid := nextSeqID("hb-elect") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=heartbeat_loss→election") + break + } + if evts[j].EventType == "PRIMARY_TRANSITION" { + sid := nextSeqID("hb-primary") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=heartbeat_loss→primary_change") + break + } + } + } +} + +// correlateStepdownChain: STEPDOWN -> ELECTION -> PRIMARY_TRANSITION within 30s +func correlateStepdownChain(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "STEPDOWN" { + continue + } + t0 := evts[i].Time + sid := "" + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 30*time.Second { + break + } + if strings.HasPrefix(evts[j].EventType, "ELECTION") && sid == "" { + sid = nextSeqID("stepdown") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=stepdown→election") + } + if evts[j].EventType == "PRIMARY_TRANSITION" && sid != "" { + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=stepdown→election→primary") + break + } + } + } +} + +// correlateSyncLifecycle: INITIAL_SYNC start -> complete/fail on same node +func correlateSyncLifecycle(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "INITIAL_SYNC" || evts[i].Status != types.StatusInfo { + continue + } + t0 := evts[i].Time + node := evts[i].Node + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 2*time.Hour { + break + } + if evts[j].EventType == "INITIAL_SYNC" && evts[j].Node == node && + (evts[j].Status == types.StatusSuccess || evts[j].Status == types.StatusFailure) { + sid := nextSeqID("isync") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + tag := "sequence=initial_sync_lifecycle" + evts[i].Details = addSeqTag(evts[i].Details, tag) + evts[j].Details = addSeqTag(evts[j].Details, tag) + break + } + } + } +} + +// correlateMigrationLifecycle: CHUNK_MIGRATION start -> complete/fail +func correlateMigrationLifecycle(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "CHUNK_MIGRATION" || !strings.Contains(evts[i].Details, "phase=start") { + continue + } + t0 := evts[i].Time + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 30*time.Minute { + break + } + if evts[j].EventType == "CHUNK_MIGRATION" && + (strings.Contains(evts[j].Details, "phase=complete") || strings.Contains(evts[j].Details, "phase=abort")) { + sid := nextSeqID("migrate") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + break + } + } + } +} + +// correlateRestartSequence: PROCESS_SHUTDOWN -> PROCESS_START on same node +func correlateRestartSequence(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "PROCESS_SHUTDOWN" { + continue + } + t0 := evts[i].Time + node := evts[i].Node + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 10*time.Minute { + break + } + if evts[j].EventType == "PROCESS_START" && evts[j].Node == node { + sid := nextSeqID("restart") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=restart") + break + } + } + } +} + +// correlateRollbackCascade: ROLLBACK -> INITIAL_SYNC or catch-up replication on same node +func correlateRollbackCascade(evts []*types.StructuredEvent) { + for i := range evts { + if evts[i].EventType != "ROLLBACK" { + continue + } + t0 := evts[i].Time + node := evts[i].Node + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 10*time.Minute { + break + } + if evts[j].Node == node && + (evts[j].EventType == "INITIAL_SYNC" || evts[j].EventType == "REPL_OPLOG") { + sid := nextSeqID("rollback") + evts[i].SequenceID = sid + evts[j].SequenceID = sid + evts[j].Details = addSeqTag(evts[j].Details, "sequence=rollback→recovery") + break + } + } + } +} + +// MarkAnomalies sets the Anomaly field using heuristic rules. +func MarkAnomalies(evts []*types.StructuredEvent) { + for i := range evts { + markRollback(evts, i) + markLag(evts, i) + markElectionStorm(evts, i) + markFrequentElections(evts, i) + markTopologyFlap(evts, i) + markNodeFlapping(evts, i) + markSyncFailure(evts, i) + markAuthBurst(evts, i) + markSustainedHeartbeatFail(evts, i) + markSyncTimeout(evts, i) + } +} + +func markRollback(evts []*types.StructuredEvent, i int) { + if evts[i].EventType == "ROLLBACK" { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "ROLLBACK") + } +} + +var reLagNum = regexp.MustCompile(`lag=([0-9]+(?:\.[0-9]+)?)`) + +func markLag(evts []*types.StructuredEvent, i int) { + det := strings.ToLower(evts[i].Details) + if evts[i].EventType == "REPL_LAG" || strings.Contains(det, "lag") { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "LAG") + if m := reLagNum.FindStringSubmatch(evts[i].Details); len(m) > 1 { + if v, err := strconv.ParseFloat(m[1], 64); err == nil && v > 10 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "LAG_SPIKE") + } + } + } +} + +// 3+ elections in 5 minutes +func markElectionStorm(evts []*types.StructuredEvent, i int) { + if !strings.HasPrefix(evts[i].EventType, "ELECTION") { + return + } + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return strings.HasPrefix(e.EventType, "ELECTION") + }, 5*time.Minute) + if n >= 3 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "ELECTION_STORM") + } +} + +// 4+ elections in 15 minutes (original rule preserved) +func markFrequentElections(evts []*types.StructuredEvent, i int) { + if !strings.HasPrefix(evts[i].EventType, "ELECTION") { + return + } + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return strings.HasPrefix(e.EventType, "ELECTION") + }, 15*time.Minute) + if n >= 4 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "FREQUENT_ELECTIONS") + } +} + +func markTopologyFlap(evts []*types.StructuredEvent, i int) { + if evts[i].EventType != "MEMBER_LEAVE" && evts[i].EventType != "MEMBER_JOIN" { + return + } + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return e.EventType == "MEMBER_LEAVE" || e.EventType == "MEMBER_JOIN" + }, 30*time.Minute) + if n >= 5 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "TOPOLOGY_FLAP") + } +} + +// Per-node PROCESS_SHUTDOWN -> PROCESS_START cycles: 3+ restarts in 30 min +func markNodeFlapping(evts []*types.StructuredEvent, i int) { + if evts[i].EventType != "PROCESS_START" { + return + } + node := evts[i].Node + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return e.Node == node && (e.EventType == "PROCESS_START" || e.EventType == "PROCESS_SHUTDOWN") + }, 30*time.Minute) + if n >= 6 { // 3 restart cycles = 3 shutdowns + 3 starts + evts[i].Anomaly = appendTag(evts[i].Anomaly, "NODE_FLAPPING") + } +} + +func markSyncFailure(evts []*types.StructuredEvent, i int) { + if evts[i].Status == types.StatusFailure && strings.Contains(evts[i].EventType, "SYNC") { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "SYNC_FAILURE") + } +} + +// 5+ AUTH_FAILURE from same node within 1 minute +func markAuthBurst(evts []*types.StructuredEvent, i int) { + if evts[i].EventType != "AUTH_FAILURE" { + return + } + node := evts[i].Node + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return e.EventType == "AUTH_FAILURE" && e.Node == node + }, 1*time.Minute) + if n >= 5 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "AUTH_BURST") + } +} + +// 3+ HEARTBEAT_FAIL within 30 seconds +func markSustainedHeartbeatFail(evts []*types.StructuredEvent, i int) { + if evts[i].EventType != "HEARTBEAT_FAIL" { + return + } + n := countInWindow(evts, i, func(e *types.StructuredEvent) bool { + return e.EventType == "HEARTBEAT_FAIL" + }, 30*time.Second) + if n >= 3 { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "SUSTAINED_HB_FAIL") + } +} + +// INITIAL_SYNC start without complete within 2 hours on same node +func markSyncTimeout(evts []*types.StructuredEvent, i int) { + if evts[i].EventType != "INITIAL_SYNC" || evts[i].Status != types.StatusInfo { + return + } + node := evts[i].Node + t0 := evts[i].Time + for j := i + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > 2*time.Hour { + evts[i].Anomaly = appendTag(evts[i].Anomaly, "SYNC_TIMEOUT") + return + } + if evts[j].EventType == "INITIAL_SYNC" && evts[j].Node == node && + (evts[j].Status == types.StatusSuccess || evts[j].Status == types.StatusFailure) { + return + } + } + // Reached end of events without finding completion + evts[i].Anomaly = appendTag(evts[i].Anomaly, "SYNC_TIMEOUT") +} + +// countInWindow counts matching events within a time window around the given index. +// Exploits the sorted order of evts to break early. +func countInWindow(evts []*types.StructuredEvent, idx int, pred func(*types.StructuredEvent) bool, win time.Duration) int { + t0 := evts[idx].Time + c := 0 + // scan backwards + for j := idx; j >= 0; j-- { + if t0.Sub(evts[j].Time) > win { + break + } + if pred(evts[j]) { + c++ + } + } + // scan forwards (skip idx to avoid double-count) + for j := idx + 1; j < len(evts); j++ { + if evts[j].Time.Sub(t0) > win { + break + } + if pred(evts[j]) { + c++ + } + } + return c +} + +func appendTag(cur, tag string) string { + if strings.Contains(cur, tag) { + return cur + } + if cur == "" { + return tag + } + return cur + "," + tag +} diff --git a/src/go/pt-mongo-log-explainer/ctx.go b/src/go/pt-mongo-log-explainer/ctx.go new file mode 100644 index 000000000..693dac744 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/ctx.go @@ -0,0 +1,55 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" +) + +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 { + + timeline, err := timelineFromPaths(c.Paths, regex.AllRegexes()) + if err != nil { + return err + } + + out := struct { + DB any + Contexts []any + }{} + out.DB = translate.GetDB() + + for _, t := range timeline { + out.Contexts = append(out.Contexts, t[len(t)-1].LogCtx) + } + + outjson, err := json.MarshalIndent(out, "", "\t") + if err != nil { + return err + } + fmt.Println(string(outjson)) + return nil +} diff --git a/src/go/pt-mongo-log-explainer/display/timelinecli.go b/src/go/pt-mongo-log-explainer/display/timelinecli.go new file mode 100644 index 000000000..f4305dc62 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/display/timelinecli.go @@ -0,0 +1,375 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +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-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-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.GetLatestContextsByNodes() // so that we have fully updated context when we print + lastContext := make(map[string]types.LogCtx, len(timeline)) // 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 + logCtx := currentContext[node] + args = append(args, utils.PaintForState("| ", logCtx.State())) + continue + } + loginfo := timeline[node][0] + lastContext[node] = currentContext[node] + currentContext[node] = loginfo.LogCtx + + 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.LogCtx.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)) + } + +} + +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].LogCtx + } 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 { + var b strings.Builder + b.WriteString("identifier\t") + for i, k := range keys { + if i > 0 { + b.WriteByte('\t') + } + b.WriteString(utils.Paint(utils.NodeHue(k), k)) + } + b.WriteString("\t") + return b.String() +} + +func headerFilePath(keys []string, logCtxs map[string]types.LogCtx) string { + header := "current path\t" + for _, node := range keys { + if logCtx, ok := logCtxs[node]; ok { + if len(logCtx.FilePath) < 50 { + header += logCtx.FilePath + "\t" + } else { + header += "..." + logCtx.FilePath[len(logCtx.FilePath)-50:] + "\t" + } + } else { + header += " \t" + } + } + return header +} + +func headerIP(keys []string, logCtxs map[string]types.LogCtx) string { + header := "last known ip\t" + for _, node := range keys { + if logCtx, ok := logCtxs[node]; ok && len(logCtx.OwnIPs) > 0 { + header += logCtx.OwnIPs[len(logCtx.OwnIPs)-1] + "\t" + } else { + header += " \t" + } + } + return header +} + +func headerVersion(keys []string, logCtxs map[string]types.LogCtx) string { + header := "mongodb version\t" + for _, node := range keys { + if logCtx, ok := logCtxs[node]; ok { + header += logCtx.Version + "\t" + } + } + return header +} + +func headerName(keys []string, logCtxs map[string]types.LogCtx) string { + header := "last known name\t" + for _, node := range keys { + if logCtx, ok := logCtxs[node]; ok && len(logCtx.OwnNames) > 0 { + header += logCtx.OwnNames[len(logCtx.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].LogCtx.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 highlight a change of context +// example, changing file +// +// mongod.log.2 +// (file path) +// V +// mongod.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, oldlogCtxs, logCtxs map[string]types.LogCtx) string { + + ts := map[string]*transitions{} + + // For each columns to print, we build tests + for _, node := range keys { + logCtx, ok1 := logCtxs[node] + oldlogCtx, ok2 := oldlogCtxs[node] + + ts[node] = &transitions{tests: []*transition{}} + if ok1 && ok2 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldlogCtx.FilePath, s2: logCtx.FilePath, changeType: "file path"}) + + if len(oldlogCtx.OwnNames) > 0 && len(logCtx.OwnNames) > 0 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldlogCtx.OwnNames[len(oldlogCtx.OwnNames)-1], s2: logCtx.OwnNames[len(logCtx.OwnNames)-1], changeType: "node name"}) + } + if len(oldlogCtx.OwnIPs) > 0 && len(logCtx.OwnIPs) > 0 { + ts[node].tests = append(ts[node].tests, &transition{s1: oldlogCtx.OwnIPs[len(oldlogCtx.OwnIPs)-1], s2: logCtx.OwnIPs[len(logCtx.OwnIPs)-1], changeType: "node ip"}) + } + if oldlogCtx.Version != "" && logCtx.Version != "" { + ts[node].tests = append(ts[node].tests, &transition{s1: oldlogCtx.Version, s2: logCtx.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-mongo-log-explainer/internal.go b/src/go/pt-mongo-log-explainer/internal.go new file mode 100644 index 000000000..6273e723f --- /dev/null +++ b/src/go/pt-mongo-log-explainer/internal.go @@ -0,0 +1,223 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "bufio" + "os" + "os/exec" + "runtime" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/pkg/errors" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +var logger zerolog.Logger + +func initComponentLogger() { + logger = log.With().Str("component", "extractor").Logger() + if CLI.Since != nil { + logger = logger.With().Time("since", *CLI.Since).Logger() + } + if CLI.Until != nil { + logger = logger.With().Time("until", *CLI.Until).Logger() + } +} + +var ( + errDirectoriesUnsupported = errors.New("directories are not supported") +) + +// 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, regexes types.RegexMap) (types.Timeline, error) { + timeline := make(types.Timeline) + found := false + + compiledRegex := prepareGrepArgument(regexes) + + for _, path := range paths { + osinfo, err := os.Stat(path) + if err != nil { + return nil, err + } + if osinfo.IsDir() { + return nil, errDirectoriesUnsupported + } + + stdout := make(chan string) + + go func() { + err := execGrepAndIterate(path, compiledRegex, stdout) + if err != nil { + logger.Error().Str("path", path).Err(err).Msg("execGrepAndIterate returned error") + } + close(stdout) + }() + + // it will iterate on stdout pipe results + localTimeline := iterateOnGrepResults(path, regexes, stdout) + if len(localTimeline) == 0 { + continue + } + found = true + logger.Debug().Str("path", path).Msg("finished searching") + + // 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 + if CLI.SkipMerge { + timeline[path] = localTimeline + } else if CLI.MergeByDirectory { + timeline.MergeByDirectory(path, localTimeline) + } else { + timeline.MergeByIdentifier(localTimeline) + } + } + if !found { + return nil, errors.New("could not find data") + } + return timeline, nil +} + +func prepareGrepArgument(regexes types.RegexMap) string { + + regexToSendSlice := regexes.Compile() + + grepRegex := "^" + if CLI.Since != nil { + grepRegex += "(" + regex.BetweenDateRegex(CLI.Since, false) + "|" + regex.NoDatesRegex(false) + ")" + } + grepRegex += ".*" + grepRegex += "(" + strings.Join(regexToSendSlice, "|") + ")" + logger.Debug().Str("grepArg", grepRegex).Msg("compiled grep arguments") + return grepRegex +} + +func execGrepAndIterate(path, compiledRegex string, stdout chan<- string) error { + + // A first pass is done, with every regexes we want compiled in a single one. + + /* + 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" { + return errors.New("GNU grep with PCRE support is required on macOS. Install it with 'brew install grep' (provides ggrep)") + } + + cmd := exec.Command(CLI.GrepCmd, "-a", "-P", compiledRegex, path) + + out, err := cmd.StdoutPipe() + if err != nil { + return errors.Wrap(err, "could not open stdout pipe") + } + defer out.Close() + + err = cmd.Start() + if err != nil { + return errors.Wrapf(err, "failed to search in %s", path) + } + + // grep treatment + s := bufio.NewScanner(out) + for s.Scan() { + stdout <- s.Text() + } + + // double-check it stopped correctly + if err = cmd.Wait(); err != nil { + if exiterr, ok := err.(*exec.ExitError); ok && exiterr.ExitCode() == 1 { + return nil + } + return errors.Wrap(err, "grep subprocess error") + } + + return nil +} + +func sanitizeLine(s string) string { + if len(s) > 0 && s[0] == '\t' { + return s[1:] + } + return s +} + +// iterateOnGrepResults 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 iterateOnGrepResults(path string, regexes types.RegexMap, grepStdout <-chan string) types.LocalTimeline { + + var ( + lt types.LocalTimeline + displayer types.LogDisplayer + timestamp time.Time + ) + logCtx := types.NewLogCtx() + logCtx.FilePath = path + + for line := range grepStdout { + line = sanitizeLine(line) + + var date *types.Date + t, layout, ok := regex.SearchDateFromLog(line) + if ok { + // diff between date and timestamp: + // timestamp is an internal usage to handle translations, it must be non-empty + // date is something that will be displayed ultimately, it can empty + date = types.NewDate(t, layout) + timestamp = t + } // else, keep the previous timestamp + + // 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 CLI.Since != nil && CLI.Since.After(timestamp) { + continue + } + if CLI.Until != nil && CLI.Until.Before(timestamp) { + return lt + } + + filetype := regex.FileType(line, false) + logCtx.FileType = filetype + + // We have to find again what regex worked to get this log line + // it can match multiple regexes + for key, regex := range regexes { + if !regex.Regex.MatchString(line) || utils.SliceContains(CLI.ExcludeRegexes, key) { + continue + } + logCtx, displayer = regex.Handle(logCtx, line, timestamp) + li := types.NewLogInfo(date, displayer, line, regex, key, logCtx, filetype) + lt = lt.Add(li) + } + + } + return lt +} diff --git a/src/go/pt-mongo-log-explainer/list.go b/src/go/pt-mongo-log-explainer/list.go new file mode 100644 index 000000000..593a8af12 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/list.go @@ -0,0 +1,104 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/display" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" + "github.com/percona/percona-toolkit/src/go/pt-mongo-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:"Do not color idle columns by inferred replica-set member state"` + All bool `help:"List everything" xor:"states,topology,events,replication,cluster"` + States bool `help:"List replica-set member state changes (PRIMARY, SECONDARY, ...)" xor:"states"` + Topology bool `help:"List topology / config events (initiate, reconfig, member add/remove)" xor:"topology"` + Events bool `help:"List process events (startup, shutdown, fatal errors)" xor:"events"` + Replication bool `help:"List replication sync events (initial sync, oplog apply, resync)" xor:"replication"` + Cluster bool `help:"List cluster-level events (elections, not-primary, write concern, stepdown, rollback)" xor:"cluster"` +} + +func (l *list) Help() string { + return fmt.Sprintf(`List events for each node in a columnar output + It will merge logs between themselves + + "identifier" is an internal metadata, this is used to merge logs. + +Usage: + %[1]s list --all + %[1]s list --all *.log + %[1]s list --replication --topology --states + %[1]s list --events --topology *.log + `, toolname) +} + +func (l *list) Run() error { + + if !(l.All || l.Events || l.States || l.Replication || l.Topology || l.Cluster) { + return errors.New("flag required: --all, or any parameters from: --replication --topology --events --states --cluster") + } + + toCheck := l.regexesToUse() + + timeline, err := timelineFromPaths(CLI.List.Paths, toCheck) + if err != nil { + return errors.Wrap(err, "could not list events") + } + + if CLI.Verbosity == types.Debug { + out, err := translate.DBToJson() + if err != nil { + return errors.Wrap(err, "could not dump translation structs to json") + } + fmt.Println(out) + } + + display.TimelineCLI(timeline, CLI.Verbosity) + + return nil +} + +func (l *list) regexesToUse() types.RegexMap { + + toCheck := regex.IdentsMap + if l.States || l.All { + toCheck.Merge(regex.StatesMap) + } else if !l.SkipStateColoredColumn { + regex.SetVerbosity(types.DebugContext, regex.StatesMap) + toCheck.Merge(regex.StatesMap) + } + if l.Topology || l.All { + toCheck.Merge(regex.TopologyMap) + } + if l.Replication || l.All { + toCheck.Merge(regex.ReplicationMap) + } + if l.Cluster || l.All { + toCheck.Merge(regex.ClusterMap) + } + if l.Events || l.All { + toCheck.Merge(regex.EventsMap) + } else if !l.SkipStateColoredColumn { + regex.SetVerbosity(types.DebugContext, regex.EventsMap) + toCheck.Merge(regex.EventsMap) + } + toCheck.Merge(regex.CustomMap) + return toCheck +} diff --git a/src/go/pt-mongo-log-explainer/main.go b/src/go/pt-mongo-log-explainer/main.go new file mode 100644 index 000000000..67558e86a --- /dev/null +++ b/src/go/pt-mongo-log-explainer/main.go @@ -0,0 +1,126 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "fmt" + "os" + "os/exec" + "runtime" + "time" + + "github.com/alecthomas/kong" + "github.com/percona/percona-toolkit/src/go/lib/config" + "github.com/percona/percona-toolkit/src/go/lib/versioncheck" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +const ( + toolname = "pt-mongo-log-explainer" +) + +// We do not set anything here, these variables are defined by the Makefile +var ( + Build string //nolint + GoVersion string //nolint + Version string //nolint + Commit string //nolint +) + +type CliOptions struct { + config.ConfigFlag + 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:"0" help:"-v: debug context (how the tool inferred hosts/ports), -vv: internal debug"` + ExcludeRegexes []string `help:"Remove regexes from analysis. List regexes using 'pt-mongo-log-explainer regex-list'"` + MergeByDirectory bool `help:"Merge timelines by parent directory name instead of inferred node identity"` + SkipMerge bool `help:"Do not merge log files; one column per file path"` + + Timeline timeline `cmd:"" help:"Structured chronological timeline (recommended for cluster analysis)"` + List list `cmd:""` + Whois whois `cmd:""` + Summary summary `cmd:"" help:"Show cluster topology summary: nodes, IPs, versions, states"` + Ctx ctx `cmd:""` + RegexList regexList `cmd:""` + + GrepCmd string `help:"'grep' command path. Auto-detects 'ggrep' on macOS if available" default:"grep"` + + CustomRegexes map[string]string `help:"Add custom regexes, printed in magenta. Format: (golang regex string)=[optional static message to display]. If the static message is left empty, the captured string will be printed instead. Custom regexes are separated using semi-colon."` + Version kong.VersionFlag `name:"version" help:"Show version and exit"` + VersionCheck bool `name:"version-check" negatable:"" default:"false" help:"Contact Percona version-check API on startup (off by default for local builds; use --version-check to enable)"` +} + +func (c *CliOptions) AfterApply() error { + if c.VersionCheck { + advice, err := versioncheck.CheckUpdates(toolname, Version) + if err != nil { + log.Error().Msgf("cannot check version updates: %s", err.Error()) + } else if advice != "" { + log.Info().Msgf("%s", advice) + } + } + + return nil +} + +var CLI = &CliOptions{} + +func main() { + kCtx, _, err := config.Setup( + toolname, + CLI, + kong.Description("MongoDB cluster log analysis: structured timeline (timeline) or columnar list (list)"), + kong.Vars{ + "version": fmt.Sprintf( + "%s\nVersion %s\nBuild: %s using %s\nCommit: %s", + toolname, Version, Build, GoVersion, Commit, + ), + }, + ) + if err != nil { + log.Error().Msgf("cannot get parameters: %s", err.Error()) + os.Exit(1) + } + + if CLI.Version { + return + } + + if runtime.GOOS == "darwin" && CLI.GrepCmd == "grep" { + if path, err := exec.LookPath("ggrep"); err == nil { + CLI.GrepCmd = path + } + } + + zerolog.TimeFieldFormat = zerolog.TimeFormatUnix + zerolog.SetGlobalLevel(zerolog.InfoLevel) + log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr, NoColor: CLI.NoColor, FormatTimestamp: func(_ interface{}) string { return "" }}) + initComponentLogger() + if CLI.Verbosity == types.Debug { + zerolog.SetGlobalLevel(zerolog.DebugLevel) + } + + utils.SkipColor = CLI.NoColor + + err = regex.AddCustomRegexes(CLI.CustomRegexes) + kCtx.FatalIfErrorf(err) + + err = kCtx.Run() + kCtx.FatalIfErrorf(err) +} diff --git a/src/go/pt-mongo-log-explainer/main_test.go b/src/go/pt-mongo-log-explainer/main_test.go new file mode 100644 index 000000000..9517e81f4 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/main_test.go @@ -0,0 +1,208 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "bytes" + "os" + "os/exec" + "path/filepath" + "regexp" + "strings" + "testing" +) + +// toolExecutable is built once in TestMain so the suite is self-contained and +// does not depend on `make build` having run first. +var toolExecutable string + +// expectedDir holds the golden output files, one per test case name. +const expectedDir = "tests/expected" + +func TestMain(m *testing.M) { + tmp, err := os.MkdirTemp("", "pt-mongo-log-explainer-test") + if err != nil { + panic("cannot create temp dir: " + err.Error()) + } + defer os.RemoveAll(tmp) + + bin := filepath.Join(tmp, toolname) + build := exec.Command("go", "build", "-o", bin, ".") + build.Stderr = os.Stderr + if err := build.Run(); err != nil { + panic("cannot build " + toolname + " for tests: " + err.Error()) + } + toolExecutable = bin + + os.Exit(m.Run()) +} + +// runTool executes the built binary with the given arguments, expanding the +// optional path glob, and returns stdout only (stderr carries log lines that +// must not pollute the golden output). +func runTool(t *testing.T, args []string, pathGlob string) []byte { + t.Helper() + + full := append([]string{}, args...) + if pathGlob != "" { + matches, err := filepath.Glob(pathGlob) + if err != nil { + t.Fatalf("bad glob %q: %v", pathGlob, err) + } + if len(matches) == 0 { + t.Fatalf("glob %q matched no files", pathGlob) + } + full = append(full, matches...) + } + + cmd := exec.Command(toolExecutable, full...) + var stdout, stderr bytes.Buffer + cmd.Stdout = &stdout + cmd.Stderr = &stderr + if err := cmd.Run(); err != nil { + t.Fatalf("running %s %s failed: %v\nstderr: %s", + toolExecutable, strings.Join(full, " "), err, stderr.String()) + } + return stdout.Bytes() +} + +// TestCommands runs each command against the fixture logs and compares stdout to +// a golden file. Set UPDATE_GOLDEN=1 to (re)generate the golden files. +// +// Each case is executed several times because map iteration and file read order +// are randomized in Go; this guards against accidental non-determinism. +func TestCommands(t *testing.T) { + cases := []struct { + name string + args []string + path string + }{ + {"summary_replicaset", []string{"summary", "--no-color"}, "tests/logs/replicaset/*.log"}, + {"summary_sharded", []string{"summary", "--no-color"}, "tests/logs/sharded/*.log"}, + {"whois_ip", []string{"whois", "--no-color", "192.168.1.10"}, "tests/logs/replicaset/*.log"}, + {"whois_nodename", []string{"whois", "--no-color", "mongo-rs0-0"}, "tests/logs/replicaset/*.log"}, + {"whois_id", []string{"whois", "--no-color", "0"}, "tests/logs/replicaset/*.log"}, + {"timeline_all", []string{"timeline", "--no-color"}, "tests/logs/replicaset/*.log"}, + {"timeline_replication", []string{"timeline", "--replication", "--no-color"}, "tests/logs/replicaset/*.log"}, + {"timeline_elections", []string{"timeline", "--elections", "--no-color"}, "tests/logs/replicaset/*.log"}, + {"timeline_json", []string{"timeline", "--json"}, "tests/logs/replicaset/*.log"}, + {"timeline_sharding", []string{"timeline", "--sharding", "--no-color"}, "tests/logs/sharded/*.log"}, + {"list_all", []string{"list", "--all", "--no-color"}, "tests/logs/replicaset/*.log"}, + {"regex_list", []string{"regex-list"}, ""}, + + // Real-world MongoDB 7.0 structured (JSON) log shape. Guards the version + // parser against false positives (OS release, driver version, loopback IP). + {"summary_standalone_70", []string{"summary", "--no-color"}, "tests/logs/standalone/*.log"}, + {"list_standalone_70", []string{"list", "--all", "--no-color"}, "tests/logs/standalone/*.log"}, + } + + update := os.Getenv("UPDATE_GOLDEN") != "" + + for _, tc := range cases { + tc := tc + t.Run(tc.name, func(t *testing.T) { + goldenPath := filepath.Join(expectedDir, tc.name) + + var first []byte + const runs = 5 + for i := 0; i < runs; i++ { + out := runTool(t, tc.args, tc.path) + if i == 0 { + first = out + continue + } + if !bytes.Equal(first, out) { + t.Fatalf("non-deterministic output across runs for %q:\n--- run 0 ---\n%s\n--- run %d ---\n%s", + tc.name, first, i, out) + } + } + + if update { + if err := os.MkdirAll(expectedDir, 0o755); err != nil { + t.Fatalf("cannot create %s: %v", expectedDir, err) + } + if err := os.WriteFile(goldenPath, first, 0o644); err != nil { + t.Fatalf("cannot write golden %s: %v", goldenPath, err) + } + return + } + + want, err := os.ReadFile(goldenPath) + if err != nil { + t.Fatalf("cannot read golden %s (run with UPDATE_GOLDEN=1 to create): %v", goldenPath, err) + } + if !bytes.Equal(want, first) { + t.Errorf("output mismatch for %q\n%s", tc.name, firstDiff(want, first)) + } + }) + } +} + +// firstDiff returns a short human-readable description of the first line that +// differs between want and got. +func firstDiff(want, got []byte) string { + wl := strings.Split(string(want), "\n") + gl := strings.Split(string(got), "\n") + n := len(wl) + if len(gl) < n { + n = len(gl) + } + for i := 0; i < n; i++ { + if wl[i] != gl[i] { + return "first difference at line " + itoa(i+1) + + "\n want: " + wl[i] + + "\n got: " + gl[i] + } + } + if len(wl) != len(gl) { + return "outputs have different line counts: want " + itoa(len(wl)) + ", got " + itoa(len(gl)) + } + return "(no line-level difference found)" +} + +func itoa(i int) string { + if i == 0 { + return "0" + } + neg := i < 0 + if neg { + i = -i + } + var b [20]byte + p := len(b) + for i > 0 { + p-- + b[p] = byte('0' + i%10) + i /= 10 + } + if neg { + p-- + b[p] = '-' + } + return string(b[p:]) +} + +// TestVersionOption verifies that --version prints the tool name and a version +// line. The version value comes from the build (ldflags); when built without +// ldflags it falls back to an empty string, so we only require the labels. +func TestVersionOption(t *testing.T) { + out, err := exec.Command(toolExecutable, "--version").Output() + if err != nil { + t.Fatalf("error executing %s --version: %v", toolname, err) + } + re := regexp.MustCompile(`(?s)` + regexp.QuoteMeta(toolname) + `.*Version.*Build:.*Commit:`) + if !re.Match(out) { + t.Errorf("%s --version produced unexpected output:\n%s", toolname, out) + } +} diff --git a/src/go/pt-mongo-log-explainer/parser/context.go b/src/go/pt-mongo-log-explainer/parser/context.go new file mode 100644 index 000000000..90e77850d --- /dev/null +++ b/src/go/pt-mongo-log-explainer/parser/context.go @@ -0,0 +1,281 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package parser + +import ( + "fmt" + "path/filepath" + "regexp" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" +) + +// ScanContext holds identity inferred from a single log file. +// ServerHost/ServerPort describe this mongod/mongos instance (for timeline columns). +// ClientIP is the last remote peer from "connection accepted" and is not used for HostPort(). +// SourcePath is the log file path (used as a stable node label when hostname is not parsed yet). +type ScanContext struct { + SourcePath string + ServerHost string + ServerPort string + ServerIP string // from bindIp or net.bindIp option + ClientIP string + RSName string + Version string + Process string // mongod | mongos | "" + MeHostPort string // from JSON attr "host": "h:port" +} + +var ( + reHostEq = regexp.MustCompile(`(?i)\bhost=([a-zA-Z0-9._-]+)`) + rePortEq = regexp.MustCompile(`(?i)\bport=([0-9]{2,6})\b`) + reMongoStart = regexp.MustCompile(`(?i)MongoDB starting.*host=([a-zA-Z0-9._-]+)`) + reReplSet = regexp.MustCompile(`(?i)replica\s+set\s+([a-zA-Z0-9_-]{2,64})|replSet[^a-zA-Z0-9_]+([a-zA-Z0-9_-]{2,64})`) + reVersion = regexp.MustCompile(`(?i)db version v([0-9]+\.[0-9]+\.[0-9]+)`) + reMongos = regexp.MustCompile(`(?i)\bmongos\b`) + reConnFrom = regexp.MustCompile(`(?i)connection accepted from ([0-9.]+):([0-9]+)`) + rePIDPortHost = regexp.MustCompile(`(?i)pid=\d+\s+port=([0-9]{2,6})\s+64-bit\s+host=([a-zA-Z0-9._-]+)`) + reReplSetName = regexp.MustCompile(`(?i)replSetName:\s*"([^"]+)"`) + reRSConfigID = regexp.MustCompile(`(?i)Replica Set Config:\s*\{\s*_id:\s*"([^"]+)"`) + reBindIP = regexp.MustCompile(`(?i)bindIp[^0-9]*([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3})`) +) + +// HostPort returns this server's host:port for display (not client addresses). +func (s *ScanContext) HostPort() string { + if s.MeHostPort != "" { + return s.MeHostPort + } + if s.ServerHost != "" && s.ServerPort != "" { + return s.ServerHost + ":" + s.ServerPort + } + if s.ServerHost != "" { + return s.ServerHost + } + return "" +} + +// NodeLabel prefers short server hostname, else log file basename (so merged timelines stay distinguishable). +func (s *ScanContext) NodeLabel() string { + if s.ServerHost != "" { + h := s.ServerHost + if i := strings.IndexByte(h, '.'); i > 0 { + return h[:i] + } + return h + } + if s.SourcePath != "" { + base := filepath.Base(s.SourcePath) + base = strings.TrimSuffix(base, ".log") + return base + } + return "unknown" +} + +// UpdateFromText extracts identity hints from a plain-text mongod line. +func (s *ScanContext) UpdateFromText(line string) { + if reMongos.MatchString(line) { + s.Process = "mongos" + } + if m := reMongoStart.FindStringSubmatch(line); len(m) > 1 { + s.ServerHost = m[1] + if s.Process == "" { + s.Process = "mongod" + } + } + if m := rePIDPortHost.FindStringSubmatch(line); len(m) > 2 { + s.ServerPort = m[1] + s.ServerHost = m[2] + if s.Process == "" { + s.Process = "mongod" + } + } + if m := reHostEq.FindStringSubmatch(line); len(m) > 1 { + // startup / control lines: host= is this node + if strings.Contains(strings.ToLower(line), "mongodb starting") || + strings.Contains(strings.ToLower(line), "control") || + strings.Contains(strings.ToLower(line), "initandlisten") { + s.ServerHost = m[1] + } + } + if m := rePortEq.FindStringSubmatch(line); len(m) > 1 { + if strings.Contains(strings.ToLower(line), "mongodb starting") || + strings.Contains(strings.ToLower(line), "control") || + strings.Contains(strings.ToLower(line), "initandlisten") || + strings.Contains(strings.ToLower(line), "waiting for connections") { + s.ServerPort = m[1] + } + } + if m := reReplSet.FindStringSubmatch(line); len(m) > 1 { + rs := m[1] + if rs == "" { + rs = m[2] + } + rsLower := strings.ToLower(rs) + if rs != "" && rsLower != "initiate" && rsLower != "config" && + rsLower != "member" && rsLower != "starting" && rsLower != "state" { + s.RSName = rs + } + } + if m := reReplSetName.FindStringSubmatch(line); len(m) > 1 { + s.RSName = m[1] + } + low := strings.ToLower(line) + if strings.Contains(low, "db version v") { + if m := reVersion.FindStringSubmatch(line); len(m) > 1 { + s.Version = m[1] + } + } + if m := reConnFrom.FindStringSubmatch(line); len(m) > 1 { + s.ClientIP = m[1] + } + if strings.Contains(strings.ToLower(line), "replica set config:") { + if m := reRSConfigID.FindStringSubmatch(line); len(m) > 1 && s.RSName == "" { + s.RSName = m[1] + } + } + if m := reBindIP.FindStringSubmatch(line); len(m) > 1 { + ip := m[1] + if ip != "0.0.0.0" && ip != "127.0.0.1" { + s.ServerIP = ip + } + } +} + +// UpdateFromJSONAttr merges common JSON log attr fields into context. +func (s *ScanContext) UpdateFromJSONAttr(attr map[string]interface{}, msg, c string) { + if attr == nil { + return + } + lc := strings.ToLower(c) + lm := strings.ToLower(msg) + + // Only trust attr["host"] for this node's identity from startup/control lines, + // not from replication config lines that list all members. + isStartupLine := lc == "control" || strings.Contains(lm, "mongod startup") || + strings.Contains(lm, "mongos startup") || strings.Contains(lm, "mongodb starting") || + strings.Contains(lm, "options") + if h, ok := attr["host"].(string); ok && isStartupLine && h != "" { + if strings.Contains(h, ":") { + s.MeHostPort = h + parts := strings.SplitN(h, ":", 2) + s.ServerHost = parts[0] + s.ServerPort = parts[1] + } else { + s.ServerHost = h + } + } + if p, ok := attr["port"]; ok && isStartupLine { + port := jsonPortString(p) + if port != "" { + s.ServerPort = port + if s.ServerHost != "" { + s.MeHostPort = s.ServerHost + ":" + port + } + } + } + if setName, ok := attr["setName"].(string); ok { + s.RSName = setName + } + if v, ok := attr["version"].(string); ok { + s.Version = v + } + // "Build Info" line: attr.buildInfo.version + if bi, ok := attr["buildInfo"].(map[string]interface{}); ok { + if v, ok := bi["version"].(string); ok && v != "" { + s.Version = v + } + } + // "Options set by command line" line: attr.options.replication.replSet, attr.options.net.* + if opts, ok := attr["options"].(map[string]interface{}); ok { + if repl, ok := opts["replication"].(map[string]interface{}); ok { + if rs, ok := repl["replSet"].(string); ok && rs != "" { + s.RSName = rs + } + } + if netObj, ok := opts["net"].(map[string]interface{}); ok { + if bindIP, ok := netObj["bindIp"].(string); ok && bindIP != "0.0.0.0" && bindIP != "127.0.0.1" { + s.ServerIP = bindIP + } + if p, ok := netObj["port"]; ok { + port := jsonPortString(p) + if port != "" { + s.ServerPort = port + if s.ServerHost != "" { + s.MeHostPort = s.ServerHost + ":" + port + } + } + } + } + } + if _, ok := attr["mongos"].(map[string]interface{}); ok { + s.Process = "mongos" + } + if netObj, ok := attr["net"].(map[string]interface{}); ok { + if bindIP, ok := netObj["bindIp"].(string); ok && bindIP != "0.0.0.0" && bindIP != "127.0.0.1" { + s.ServerIP = bindIP + } + } + // "New replica set config in use" line: attr.config._id + if cfg, ok := attr["config"].(map[string]interface{}); ok { + if rsID, ok := cfg["_id"].(string); ok && rsID != "" && s.RSName == "" { + s.RSName = rsID + } + } + if lc == "shard" || lc == "sharding" || strings.Contains(lm, "chunk") || strings.Contains(lm, "balancer") { + if s.Process == "" { + s.Process = "mongos" + } + } + if lc == "control" && strings.Contains(lm, "mongos") { + s.Process = "mongos" + } + if lc == "control" && strings.Contains(lm, "mongod") { + s.Process = "mongod" + } +} + +// FlushToTranslateDB pushes identity accumulated during parsing into the translate +// maps so that whois can resolve hostnames, host:port, and replica set names. +func (s *ScanContext) FlushToTranslateDB(ts time.Time) { + name := s.NodeLabel() + hp := s.HostPort() + if name != "" && name != "unknown" { + if hp != "" { + translate.AddHostPortToNodeName(hp, name, ts) + } + if s.RSName != "" { + translate.AddNodeNameToRSName(name, s.RSName, ts) + } + if s.ServerIP != "" { + translate.AddIPToNodeName(s.ServerIP, name, ts) + } + } +} + +func jsonPortString(v interface{}) string { + switch x := v.(type) { + case float64: + return fmt.Sprintf("%.0f", x) + case int: + return fmt.Sprintf("%d", x) + case int64: + return fmt.Sprintf("%d", x) + case string: + return x + default: + return "" + } +} diff --git a/src/go/pt-mongo-log-explainer/parser/parse.go b/src/go/pt-mongo-log-explainer/parser/parse.go new file mode 100644 index 000000000..f67cd6e3f --- /dev/null +++ b/src/go/pt-mongo-log-explainer/parser/parse.go @@ -0,0 +1,447 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package parser + +import ( + "encoding/json" + "fmt" + "regexp" + "strconv" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" +) + +var reSlowMS = regexp.MustCompile(`(?i)([0-9]{3,})ms\s*$`) +var reElectionWord = regexp.MustCompile(`(?i)\belection\b`) +var reMemberStateLine = regexp.MustCompile(`(?i)Replica Set Member State:\s*([A-Z0-9_]+)`) + +func textHasElectionNoise(low string) bool { + return strings.Contains(low, "electiontimeout") || strings.Contains(low, "electiontimeoutmillis") +} + +func textMentionsRealElection(low string) bool { + if textHasElectionNoise(low) { + return false + } + return reElectionWord.MatchString(low) +} + +func jsonMentionsRealElection(lm string) bool { + if strings.Contains(lm, "electiontimeout") || strings.Contains(lm, "electiontimeoutmillis") { + return false + } + if strings.Contains(lm, "election") && strings.Contains(lm, "succeed") { + return true + } + if strings.Contains(lm, "election") && (strings.Contains(lm, "fail") || strings.Contains(lm, "abort")) { + return true + } + return reElectionWord.MatchString(lm) +} + +func isOplogReplicationLine(low string) bool { + return strings.Contains(low, "oplog.rs") || strings.Contains(low, "local.oplog") +} + +// IsJSONLine returns true if the line looks like a MongoDB structured JSON log record. +func IsJSONLine(line string) bool { + s := strings.TrimSpace(line) + return len(s) > 1 && s[0] == '{' && s[len(s)-1] == '}' +} + +// ParseLine turns one log line into a structured event when it matches known patterns. +func ParseLine(path, line string, ctx *ScanContext) *types.StructuredEvent { + line = strings.TrimSpace(line) + if line == "" { + return nil + } + if ctx.SourcePath == "" { + ctx.SourcePath = path + } + if IsJSONLine(line) { + return parseJSONLine(path, line, ctx) + } + ctx.UpdateFromText(line) + return parseTextLine(path, line, ctx) +} + +func parseJSONLine(path, line string, ctx *ScanContext) *types.StructuredEvent { + var root map[string]interface{} + if err := json.Unmarshal([]byte(line), &root); err != nil { + return nil + } + ts := extractJSONTime(root) + if ts.IsZero() { + if t, _, ok := regex.SearchDateFromLog(line); ok { + ts = t + } + } + if ts.IsZero() { + return nil + } + msg, _ := root["msg"].(string) + c, _ := root["c"].(string) + attr, _ := root["attr"].(map[string]interface{}) + ctx.UpdateFromJSONAttr(attr, msg, c) + + et, cat, st, details := classifyJSON(msg, c, attr, line) + if et == "" { + return nil + } + return finalizeEvent(path, line, ctx, ts, et, cat, st, details) +} + +func extractJSONTime(root map[string]interface{}) time.Time { + tv, ok := root["t"] + if !ok { + return time.Time{} + } + switch t := tv.(type) { + case map[string]interface{}: + if d, ok := t["$date"].(string); ok { + for _, layout := range regex.DateLayouts { + if tt, err := time.Parse(layout, d); err == nil { + return tt + } + } + if tt, err := time.Parse(time.RFC3339Nano, d); err == nil { + return tt + } + if tt, err := time.Parse(time.RFC3339, d); err == nil { + return tt + } + } + if nested, ok := t["$date"].(map[string]interface{}); ok { + if nl, ok := nested["$numberLong"].(string); ok { + if ms, err := strconv.ParseInt(nl, 10, 64); err == nil { + return time.UnixMilli(ms).UTC() + } + } + } + case string: + if tt, err := time.Parse(time.RFC3339Nano, t); err == nil { + return tt + } + } + return time.Time{} +} + +func classifyJSON(msg, c string, attr map[string]interface{}, raw string) (eventType string, category types.EventCategory, status types.EventStatus, details string) { + lm := strings.ToLower(msg) + lc := strings.ToLower(c) + + switch { + case strings.Contains(lm, "waiting for connections"): + return "NODE_LISTEN", types.CatNode, types.StatusInfo, msg + case strings.Contains(lm, "mongod startup") || strings.Contains(lm, "mongos startup"): + return "PROCESS_START", types.CatNode, types.StatusSuccess, msg + case strings.Contains(lm, "shutting down") || strings.Contains(lm, "now exiting"): + return "PROCESS_SHUTDOWN", types.CatFailure, types.StatusWarn, msg + case strings.Contains(lm, "transition to primary"): + return "PRIMARY_TRANSITION", types.CatRole, types.StatusSuccess, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "stepped down") || strings.Contains(lm, "stepping down"): + return "STEPDOWN", types.CatRole, types.StatusWarn, jsonAttrSummary(attr, msg) + case jsonMentionsRealElection(lm) && strings.Contains(lm, "succeed"): + return "ELECTION_SUCCESS", types.CatRole, types.StatusSuccess, jsonAttrSummary(attr, msg) + case jsonMentionsRealElection(lm) && (strings.Contains(lm, "fail") || strings.Contains(lm, "abort")): + return "ELECTION_FAIL", types.CatRole, types.StatusFailure, jsonAttrSummary(attr, msg) + case jsonMentionsRealElection(lm): + return "ELECTION", types.CatRole, types.StatusInfo, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "rollback") || strings.Contains(lm, "rolling back"): + return "ROLLBACK", types.CatReplication, types.StatusFailure, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "initial sync"): + st := types.StatusInfo + if strings.Contains(lm, "fail") || strings.Contains(lm, "error") { + st = types.StatusFailure + } + if strings.Contains(lm, "complete") || strings.Contains(lm, "finished") { + st = types.StatusSuccess + } + return "INITIAL_SYNC", types.CatReplication, st, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "heartbeat") && (strings.Contains(lm, "fail") || strings.Contains(lm, "timeout") || strings.Contains(lm, "error")): + return "HEARTBEAT_FAIL", types.CatTopology, types.StatusFailure, msg + case strings.Contains(lm, "heartbeat"): + return "HEARTBEAT", types.CatTopology, types.StatusInfo, msg + case strings.Contains(lm, "member is now in state"): + return "MEMBER_STATE", types.CatRole, types.StatusInfo, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "member") && (strings.Contains(lm, "added") || strings.Contains(lm, "join")): + return "MEMBER_JOIN", types.CatTopology, types.StatusSuccess, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "member") && (strings.Contains(lm, "removed") || strings.Contains(lm, "left")): + return "MEMBER_LEAVE", types.CatTopology, types.StatusWarn, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "replset") && strings.Contains(lm, "reconfig"): + return "RECONFIG", types.CatTopology, types.StatusInfo, msg + + // --- Replication: sync source changes and oplog --- + case strings.Contains(lm, "changed sync source") || strings.Contains(lm, "sync source"): + return "SYNC_SOURCE_CHANGE", types.CatReplication, types.StatusInfo, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "oplog window"): + return "OPLOG_WINDOW", types.CatReplication, types.StatusWarn, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "repl writer") || (isOplogReplicationLine(lm) && strings.Contains(lm, "applied")): + return "REPL_OPLOG", types.CatReplication, types.StatusInfo, shorten(msg, 160) + case attr != nil && (attr["lag"] != nil || attr["replicationLag"] != nil): + return "REPL_LAG", types.CatReplication, types.StatusWarn, jsonLagSummary(attr, msg) + + // --- Topology: quorum --- + case strings.Contains(lm, "not enough") && strings.Contains(lm, "majority"): + return "QUORUM_LOSS", types.CatTopology, types.StatusFailure, msg + case strings.Contains(lm, "quorum check") && strings.Contains(lm, "succeeded"): + return "QUORUM_OK", types.CatTopology, types.StatusSuccess, msg + + // --- Topology: member unreachable --- + case strings.Contains(lm, "not reachable") || (strings.Contains(lm, "member") && strings.Contains(lm, "down")): + return "MEMBER_UNREACHABLE", types.CatTopology, types.StatusFailure, jsonAttrSummary(attr, msg) + + // --- Sharding: specific migration lifecycle (must precede generic chunk/balancer cases) --- + case strings.Contains(lm, "migration started"): + return "CHUNK_MIGRATION", types.CatSharding, types.StatusInfo, "phase=start " + jsonAttrSummary(attr, msg) + case strings.Contains(lm, "migration committed"): + return "CHUNK_MIGRATION", types.CatSharding, types.StatusSuccess, "phase=complete " + jsonAttrSummary(attr, msg) + case strings.Contains(lm, "migration aborted"): + return "CHUNK_MIGRATION", types.CatSharding, types.StatusFailure, "phase=abort " + jsonAttrSummary(attr, msg) + case strings.Contains(lm, "balancer enabled"): + return "BALANCER", types.CatSharding, types.StatusSuccess, "action=enabled" + case strings.Contains(lm, "balancer disabled"): + return "BALANCER", types.CatSharding, types.StatusWarn, "action=disabled" + case strings.Contains(lm, "balancer round"): + return "BALANCER", types.CatSharding, types.StatusInfo, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "chunk") && (strings.Contains(lm, "move") || strings.Contains(lm, "migration")): + return "CHUNK_MIGRATION", types.CatSharding, types.StatusInfo, jsonAttrSummary(attr, msg) + case strings.Contains(lm, "balancer"): + return "BALANCER", types.CatSharding, types.StatusInfo, msg + + // --- Failures: specific checks before generic NETWORK_ERROR --- + case strings.Contains(lm, "dns resolution") || strings.Contains(lm, "dns lookup"): + return "DNS_ERROR", types.CatFailure, types.StatusFailure, shorten(msg, 200) + case strings.Contains(lm, "connection pool"): + return "CONN_POOL_ERROR", types.CatFailure, types.StatusFailure, shorten(msg, 200) + case strings.Contains(lm, "socket exception") || strings.Contains(lm, "socketexception"): + return "SOCKET_ERROR", types.CatFailure, types.StatusFailure, shorten(msg, 200) + case strings.Contains(lm, "write concern") || strings.Contains(lm, "writeconcernerror"): + return "WRITE_CONCERN_ERROR", types.CatFailure, types.StatusFailure, jsonAttrSummary(attr, msg) + case lc == "network" && (strings.Contains(lm, "error") || strings.Contains(lm, "fail") || strings.Contains(lm, "closed")): + return "NETWORK_ERROR", types.CatFailure, types.StatusFailure, msg + case strings.Contains(lm, "authentication failed") || strings.Contains(lm, "auth failed"): + return "AUTH_FAILURE", types.CatFailure, types.StatusFailure, msg + case strings.Contains(lm, "assert") || strings.Contains(lm, "fatal"): + return "FATAL_ERROR", types.CatFailure, types.StatusFailure, msg + + // --- Performance --- + case strings.Contains(lm, "slow query") || strings.Contains(lm, "command slow"): + return "SLOW_QUERY", types.CatPerformance, types.StatusWarn, shorten(raw, 200) + case strings.Contains(lm, "index build") && strings.Contains(lm, "start"): + return "INDEX_BUILD", types.CatPerformance, types.StatusInfo, "phase=start " + jsonAttrSummary(attr, msg) + case strings.Contains(lm, "index build") && (strings.Contains(lm, "complete") || strings.Contains(lm, "done")): + return "INDEX_BUILD", types.CatPerformance, types.StatusSuccess, "phase=complete " + jsonAttrSummary(attr, msg) + case strings.Contains(lm, "exceeded time limit") || strings.Contains(lm, "maxtimemsexpired"): + return "OP_TIMEOUT", types.CatPerformance, types.StatusFailure, shorten(msg, 200) + case strings.Contains(lm, "cursor") && strings.Contains(lm, "timed out"): + return "CURSOR_TIMEOUT", types.CatPerformance, types.StatusWarn, shorten(msg, 200) + } + + // Component-based fallback + switch lc { + case "repl": + if strings.Contains(lm, "primary") { + return "REPL_STATE", types.CatRole, types.StatusInfo, msg + } + if isOplogReplicationLine(lm) { + return "REPL_OPLOG", types.CatReplication, types.StatusInfo, shorten(msg, 160) + } + return "REPL", types.CatReplication, types.StatusInfo, shorten(msg, 160) + case "sharding", "shard": + return "SHARDING", types.CatSharding, types.StatusInfo, shorten(msg, 160) + case "write": + if strings.Contains(lm, "slow") { + return "SLOW_WRITE", types.CatPerformance, types.StatusWarn, msg + } + } + return "", "", types.StatusUnknown, "" +} + +func parseTextLine(path, line string, ctx *ScanContext) *types.StructuredEvent { + ts, _, ok := regex.SearchDateFromLog(line) + if !ok { + return nil + } + low := strings.ToLower(line) + var et string + var cat types.EventCategory + var st types.EventStatus + var details string + + switch { + case strings.Contains(low, "mongodb starting"): + et, cat, st, details = "PROCESS_START", types.CatNode, types.StatusSuccess, shorten(line, 200) + case strings.Contains(low, "waiting for connections"): + et, cat, st, details = "NODE_LISTEN", types.CatNode, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "replica set config:"): + et, cat, st, details = "RS_CONFIG", types.CatTopology, types.StatusInfo, shorten(line, 220) + case reMemberStateLine.MatchString(line): + m := reMemberStateLine.FindStringSubmatch(line) + if len(m) > 1 { + et, cat, st, details = "MEMBER_STATE", types.CatRole, types.StatusInfo, "state="+m[1] + } else { + et, cat, st, details = "MEMBER_STATE", types.CatRole, types.StatusInfo, shorten(line, 200) + } + case strings.Contains(low, "transition to primary"): + et, cat, st, details = "PRIMARY_TRANSITION", types.CatRole, types.StatusSuccess, shorten(line, 200) + case strings.Contains(low, "stepped down") || strings.Contains(low, "stepping down"): + et, cat, st, details = "STEPDOWN", types.CatRole, types.StatusWarn, shorten(line, 200) + case !textHasElectionNoise(low) && strings.Contains(low, "election") && strings.Contains(low, "succeed"): + et, cat, st, details = "ELECTION_SUCCESS", types.CatRole, types.StatusSuccess, shorten(line, 200) + case !textHasElectionNoise(low) && strings.Contains(low, "election") && (strings.Contains(low, "fail") || strings.Contains(low, "abort")): + et, cat, st, details = "ELECTION_FAIL", types.CatRole, types.StatusFailure, shorten(line, 200) + case textMentionsRealElection(low): + et, cat, st, details = "ELECTION", types.CatRole, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "rollback"): + et, cat, st, details = "ROLLBACK", types.CatReplication, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "initial sync"): + et, cat, st, details = "INITIAL_SYNC", types.CatReplication, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "heartbeat") && (strings.Contains(low, "fail") || strings.Contains(low, "timeout")): + et, cat, st, details = "HEARTBEAT_FAIL", types.CatTopology, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "heartbeat"): + et, cat, st, details = "HEARTBEAT", types.CatTopology, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "replsetinitiate") || strings.Contains(low, "initiating a replica set"): + et, cat, st, details = "RS_INITIATE", types.CatTopology, types.StatusSuccess, shorten(line, 200) + case strings.Contains(low, "reconfig"): + et, cat, st, details = "RECONFIG", types.CatTopology, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "chunk") && strings.Contains(low, "move"): + et, cat, st, details = "CHUNK_MIGRATION", types.CatSharding, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "balancer"): + et, cat, st, details = "BALANCER", types.CatSharding, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "authentication failed"): + et, cat, st, details = "AUTH_FAILURE", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "connection reset") || strings.Contains(low, "network error"): + et, cat, st, details = "NETWORK_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "shutting down") || strings.Contains(low, "now exiting"): + et, cat, st, details = "PROCESS_SHUTDOWN", types.CatFailure, types.StatusWarn, shorten(line, 200) + case strings.Contains(low, "fatal") || strings.Contains(low, "assertion"): + et, cat, st, details = "FATAL_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "slow query"): + et, cat, st, details = "SLOW_QUERY", types.CatPerformance, types.StatusWarn, shorten(line, 200) + case strings.Contains(low, "changed sync source") || (strings.Contains(low, "sync source") && !strings.Contains(low, "initial sync")): + et, cat, st, details = "SYNC_SOURCE_CHANGE", types.CatReplication, types.StatusInfo, shorten(line, 200) + case strings.Contains(low, "oplog window"): + et, cat, st, details = "OPLOG_WINDOW", types.CatReplication, types.StatusWarn, shorten(line, 200) + case strings.Contains(low, "not enough") && strings.Contains(low, "majority"): + et, cat, st, details = "QUORUM_LOSS", types.CatTopology, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "quorum check") && strings.Contains(low, "succeeded"): + et, cat, st, details = "QUORUM_OK", types.CatTopology, types.StatusSuccess, shorten(line, 200) + case strings.Contains(low, "not reachable"): + et, cat, st, details = "MEMBER_UNREACHABLE", types.CatTopology, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "connection pool"): + et, cat, st, details = "CONN_POOL_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "socket exception") || strings.Contains(low, "socketexception"): + et, cat, st, details = "SOCKET_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "dns resolution") || strings.Contains(low, "dns lookup"): + et, cat, st, details = "DNS_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "write concern") || strings.Contains(low, "writeconcernerror"): + et, cat, st, details = "WRITE_CONCERN_ERROR", types.CatFailure, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "migration started"): + et, cat, st, details = "CHUNK_MIGRATION", types.CatSharding, types.StatusInfo, "phase=start "+shorten(line, 180) + case strings.Contains(low, "migration committed"): + et, cat, st, details = "CHUNK_MIGRATION", types.CatSharding, types.StatusSuccess, "phase=complete "+shorten(line, 180) + case strings.Contains(low, "migration aborted"): + et, cat, st, details = "CHUNK_MIGRATION", types.CatSharding, types.StatusFailure, "phase=abort "+shorten(line, 180) + case strings.Contains(low, "index build") && strings.Contains(low, "start"): + et, cat, st, details = "INDEX_BUILD", types.CatPerformance, types.StatusInfo, "phase=start "+shorten(line, 180) + case strings.Contains(low, "index build") && (strings.Contains(low, "complete") || strings.Contains(low, "done")): + et, cat, st, details = "INDEX_BUILD", types.CatPerformance, types.StatusSuccess, "phase=complete "+shorten(line, 180) + case strings.Contains(low, "exceeded time limit") || strings.Contains(low, "maxtimemsexpired"): + et, cat, st, details = "OP_TIMEOUT", types.CatPerformance, types.StatusFailure, shorten(line, 200) + case strings.Contains(low, "cursor") && strings.Contains(low, "timed out"): + et, cat, st, details = "CURSOR_TIMEOUT", types.CatPerformance, types.StatusWarn, shorten(line, 200) + case isOplogReplicationLine(low) && reSlowMS.MatchString(line): + et, cat, st, details = "OPLOG_TAIL_SLOW", types.CatReplication, types.StatusWarn, shorten(line, 200) + case reSlowMS.MatchString(line): + et, cat, st, details = "LONG_RUNNING_CMD", types.CatPerformance, types.StatusWarn, shorten(line, 200) + case strings.Contains(low, "secondary") && strings.Contains(low, "transition"): + et, cat, st, details = "SECONDARY_TRANSITION", types.CatRole, types.StatusInfo, shorten(line, 200) + default: + return nil + } + return finalizeEvent(path, line, ctx, ts, et, cat, st, details) +} + +func finalizeEvent(path, raw string, ctx *ScanContext, ts time.Time, et string, cat types.EventCategory, st types.EventStatus, details string) *types.StructuredEvent { + if ctx.RSName != "" && !strings.Contains(details, "rs=") { + details = fmt.Sprintf("rs=%s %s", ctx.RSName, details) + } + if ctx.Version != "" && strings.HasPrefix(et, "PROCESS_START") { + details = fmt.Sprintf("version=%s %s", ctx.Version, details) + } + if ctx.Process != "" && !strings.Contains(details, "process=") && + (cat == types.CatNode || strings.HasPrefix(et, "PROCESS_") || et == "NODE_LISTEN") { + details = fmt.Sprintf("process=%s %s", ctx.Process, strings.TrimSpace(details)) + } + return &types.StructuredEvent{ + Time: ts, + Node: ctx.NodeLabel(), + HostPort: ctx.HostPort(), + EventType: et, + Status: st, + Details: strings.TrimSpace(details), + Category: cat, + SourceFile: path, + Raw: raw, + } +} + +func jsonAttrSummary(attr map[string]interface{}, msg string) string { + if attr == nil { + return msg + } + parts := []string{} + for _, k := range []string{ + "term", "newState", "oldState", "from", "to", "syncSource", + "member", "name", "error", "code", "replicaSetId", + "namespace", "shard", "donorShard", "recipientShard", + "indexName", "buildUUID", + } { + if v, ok := attr[k]; ok { + parts = append(parts, fmt.Sprintf("%s=%v", k, v)) + } + } + if len(parts) == 0 { + return msg + } + return strings.Join(parts, " ") +} + +func jsonLagSummary(attr map[string]interface{}, msg string) string { + if attr == nil { + return msg + } + parts := []string{} + for _, k := range []string{"lag", "replicationLag", "member", "syncSource"} { + if v, ok := attr[k]; ok { + parts = append(parts, fmt.Sprintf("%s=%v", k, v)) + } + } + if len(parts) == 0 { + return msg + } + return strings.Join(parts, " ") +} + +func shorten(s string, n int) string { + s = strings.ReplaceAll(strings.TrimSpace(s), "\t", " ") + if len(s) <= n { + return s + } + return s[:n] + "…" +} diff --git a/src/go/pt-mongo-log-explainer/regex/cluster.go b/src/go/pt-mongo-log-explainer/regex/cluster.go new file mode 100644 index 000000000..06cf25742 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/cluster.go @@ -0,0 +1,75 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +func init() { + setType(types.ClusterRegexType, ClusterMap) +} + +// ClusterMap holds cluster-level operational events: elections, stepdowns, rollbacks, write concern. +var ClusterMap = types.RegexMap{ + "RegexNotPrimary": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)NotPrimary|not master|not writable primary`), + InternalRegex: regexp.MustCompile(`(?i)(NotPrimary|not master|not writable primary)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "not primary")) + }, + Verbosity: types.Info, + }, + + "RegexWriteConcernTimeout": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)wtimeout|write concern`), + InternalRegex: regexp.MustCompile(`(?i)(wtimeout|WriteConcernFailed|write concern)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "write concern")) + }, + Verbosity: types.Info, + }, + + "RegexStepDown": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)stepped down|Stepping down|transition to secondary`), + InternalRegex: regexp.MustCompile(`(?i)(stepped down|Stepping down)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "step down")) + }, + Verbosity: types.Info, + }, + + "RegexElection": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)election|voteRequest|election succeeded|election failed`), + InternalRegex: regexp.MustCompile(`(?i)(election|voteRequest)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("election activity") + }, + Verbosity: types.Info, + }, + + "RegexRollbackEvent": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)rollback|Rolling back`), + InternalRegex: regexp.MustCompile(`(?i)(rollback|Rolling back)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + logCtx.SetState("ROLLBACK") + return logCtx, types.SimpleDisplayer(utils.Paint(utils.RedText, "rollback")) + }, + Verbosity: types.Info, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regex/custom.go b/src/go/pt-mongo-log-explainer/regex/custom.go new file mode 100644 index 000000000..68f4f11b9 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/custom.go @@ -0,0 +1,56 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/pkg/errors" +) + +var CustomMap = types.RegexMap{} + +func AddCustomRegexes(regexes map[string]string) error { + for regexstring, output := range regexes { + r, err := regexp.Compile(regexstring) + if err != nil { + return errors.Wrap(err, "failed to add custom regex") + } + + lr := &types.LogRegex{Regex: r, Type: types.CustomRegexType} + + if output == "" { + // capture and print everything that matched, instead of a static message + lr.InternalRegex, err = regexp.Compile("(?P" + regexstring + ")") + if err != nil { + return errors.Wrap(err, "failed to add custom regex: failed to generate dynamic output") + } + + lr.Handler = func(submatch map[string]string, ctx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.MagentaText, submatch["all"])) + } + + } else { + lr.Handler = func(_ map[string]string, ctx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return ctx, types.SimpleDisplayer(utils.Paint(utils.MagentaText, output)) + } + } + + CustomMap[regexstring] = lr + } + return nil +} diff --git a/src/go/pt-mongo-log-explainer/regex/date.go b/src/go/pt-mongo-log-explainer/regex/date.go new file mode 100644 index 000000000..2b0b4a092 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/date.go @@ -0,0 +1,121 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "fmt" + "regexp" + "strconv" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/rs/zerolog/log" +) + +var jsonDateRE = regexp.MustCompile(`"\$date"\s*:\s*\{\s*"\$numberLong"\s*:\s*"([0-9]+)"\s*\}`) +var jsonDateREISO = regexp.MustCompile(`"\$date"\s*:\s*"([^"]+)"`) + +// DateLayouts cover common mongod log timestamp prefixes (legacy text format). +var DateLayouts = []string{ + "2006-01-02T15:04:05.000000Z07:00", + "2006-01-02T15:04:05.000000Z", + "2006-01-02T15:04:05.000Z07:00", + "2006-01-02T15:04:05.000Z", + "2006-01-02T15:04:05Z07:00", + "2006-01-02T15:04:05Z", + "2006-01-02T15:04:05.000000+0000", + "2006-01-02T15:04:05.000+0000", + "2006-01-02T15:04:05.000000-0700", + "2006-01-02T15:04:05.000-0700", +} + +func BetweenDateRegex(since *time.Time, skipLeadingCircumflex bool) string { + 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"} { + 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) + } + 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:] +} + +func NoDatesRegex(skipLeadingCircumflex bool) string { + if skipLeadingCircumflex { + return "(?![0-9]{4})" + } + return "^(?![0-9]{4})" +} + +func SearchDateFromLog(logline string) (time.Time, string, bool) { + if m := jsonDateREISO.FindStringSubmatch(logline); len(m) > 1 { + raw := m[1] + for _, layout := range DateLayouts { + if len(raw) < 10 { + break + } + if t, err := time.Parse(layout, raw); err == nil { + return t, layout, true + } + } + if t, err := time.Parse(time.RFC3339Nano, raw); err == nil { + return t, time.RFC3339Nano, true + } + if t, err := time.Parse(time.RFC3339, raw); err == nil { + return t, time.RFC3339, true + } + } + if m := jsonDateRE.FindStringSubmatch(logline); len(m) > 1 { + ms, err := strconv.ParseInt(m[1], 10, 64) + if err == nil { + sec := ms / 1000 + nsec := (ms % 1000) * 1e6 + t := time.Unix(sec, nsec).UTC() + return t, "epoch_ms", true + } + } + for _, layout := range DateLayouts { + if len(logline) < len(layout) { + continue + } + prefix := logline + if len(prefix) > len(layout) { + prefix = logline[:len(layout)] + } + t, err := time.Parse(layout, prefix) + 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-mongo-log-explainer/regex/events.go b/src/go/pt-mongo-log-explainer/regex/events.go new file mode 100644 index 000000000..82213bdd3 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/events.go @@ -0,0 +1,64 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +func init() { + setType(types.EventsRegexType, EventsMap) +} + +var EventsMap = types.RegexMap{ + "RegexMongoDBStarting": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)MongoDB starting|mongod.*starting`), + InternalRegex: regexp.MustCompile(`(?i)MongoDB starting|starting.*mongod`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.GreenText, "mongod starting")) + }, + Verbosity: types.Info, + }, + + "RegexShutdown": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)Shutting down|now exiting|shutdown: `), + InternalRegex: regexp.MustCompile(`(?i)(Shutting down|now exiting|shutdown:)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.YellowText, "shutdown")) + }, + Verbosity: types.Info, + }, + + "RegexFatalAssertion": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)Fatal|assertion.*failed|segmentation fault`), + InternalRegex: regexp.MustCompile(`(?i)(Fatal assertion|assertion.*failed|segmentation fault)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.RedText, "fatal/assert")) + }, + Verbosity: types.Info, + }, + + "RegexDBException": &types.LogRegex{ + Regex: regexp.MustCompile(`DBException|Location[0-9]+`), + InternalRegex: regexp.MustCompile(`(?P(DBException|Location[0-9]+))`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer(utils.Paint(utils.RedText, submatches["err"])) + }, + Verbosity: types.Info, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regex/file.go b/src/go/pt-mongo-log-explainer/regex/file.go new file mode 100644 index 000000000..513df6d44 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/file.go @@ -0,0 +1,20 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + +func FileType(_ string, _ bool) string { + return types.MongoLogFileType +} diff --git a/src/go/pt-mongo-log-explainer/regex/idents.go b/src/go/pt-mongo-log-explainer/regex/idents.go new file mode 100644 index 000000000..dab733d1a --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/idents.go @@ -0,0 +1,154 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +func init() { + setType(types.IdentRegexType, IdentsMap) +} + +var IdentsMap = types.RegexMap{ + // RegexMongoVersion captures the SERVER version only from authoritative + // contexts: the legacy "db version vX.Y.Z" startup line and the structured + // (JSON) Build Info field "buildInfo":{"version":"X.Y.Z"}. It deliberately + // anchors to those prefixes so it cannot incorrectly capture unrelated number triples + // such as the 127.0.0.1 loopback IP, an OS release (e.g. 2023.9.20250929), + // or a client driver version ("driver":{"version":"1.17.4"}). + "RegexMongoVersion": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)db version v[0-9]|"buildInfo"\s*:\s*\{\s*"version"`), + InternalRegex: regexp.MustCompile(`(?i)(?:db version v|"buildInfo"\s*:\s*\{\s*"version"\s*:\s*"v?)(?P[0-9]+\.[0-9]+\.[0-9]+[-.0-9A-Za-z]*)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + v := submatches["ver"] + if v != "" { + logCtx.Version = v + } + return logCtx, types.SimpleDisplayer("version " + v) + }, + Verbosity: types.DebugContext, + }, + + "RegexWaitingForConnections": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)waiting for connections`), + InternalRegex: regexp.MustCompile(`(?i)(port|\"port\")\D*(?P[0-9]{2,6})`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + p := submatches["port"] + if p == "" { + return logCtx, nil + } + name := "listen:" + p + logCtx.AddOwnName(name, date) + return logCtx, types.SimpleDisplayer("listening port " + p) + }, + Verbosity: types.DebugContext, + }, + + "RegexBindIP": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)bindIp.*[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+`), + InternalRegex: regexp.MustCompile(`bindIp[^0-9]*(?P<` + groupHost + `>[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3})`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + ip := submatches[groupHost] + if ip == "" || ip == "0.0.0.0" || ip == "127.0.0.1" { + return logCtx, nil + } + logCtx.AddOwnIP(ip, date) + return logCtx, types.SimpleDisplayer("bind " + ip) + }, + Verbosity: types.DebugContext, + }, + + // RegexConnectionAccepted captures peer IPs from both the legacy text form + // ("connection accepted from IP:PORT") and the structured (JSON) form + // ("msg":"Connection accepted","attr":{"remote":"IP:PORT"}). Loopback peers + // carry no cluster-identity value and are skipped. + "RegexConnectionAccepted": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)connection accepted`), + InternalRegex: regexp.MustCompile(`(?i)(?:from |"remote"\s*:\s*")(?P<` + groupHost + `>[0-9.]+):(?P<` + groupPort + `>[0-9]+)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + ip := submatches[groupHost] + if ip == "" || ip == "127.0.0.1" { + return logCtx, nil + } + translate.AddPeerIP(ip, date) + return logCtx, types.SimpleDisplayer("peer " + ip) + }, + Verbosity: types.DebugContext, + }, + + "RegexConfigHost": &types.LogRegex{ + Regex: regexp.MustCompile(`\"host\"\s*:\s*\"`), + InternalRegex: regexp.MustCompile(`\"host\"\s*:\s*\"(?P[a-zA-Z0-9._-]+):(?P

[0-9]{2,6})\"`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + h := utils.ShortNodeName(submatches["h"]) + hostport := h + ":" + submatches["p"] + translate.AddHashToNodeName(hostport, h, date) + if ipv4RE.MatchString(h) { + logCtx.AddOwnIP(h, date) + } else { + logCtx.AddOwnName(h, date) + } + return logCtx, types.SimpleDisplayer("cfg member " + hostport) + }, + Verbosity: types.DebugContext, + }, + + "RegexReplSetName": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)replSet|replica set`), + InternalRegex: regexp.MustCompile(`(?i)(replSet|replica set|replicaSet)[^a-zA-Z0-9_]+(?P[a-zA-Z0-9_-]{2,64})`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + rs := submatches["rs"] + rsLower := strings.ToLower(rs) + if rs == "" || rsLower == "initiate" || rsLower == "config" || + rsLower == "member" || rsLower == "starting" || rsLower == "state" { + return logCtx, nil + } + logCtx.AddOwnName("rs:"+rs, date) + return logCtx, types.SimpleDisplayer("replSet " + rs) + }, + Verbosity: types.DebugContext, + }, + + "RegexMemberIDHost": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)member.*_id.*host`), + InternalRegex: regexp.MustCompile(`(?i)_id:\s*(?P[0-9]+).*host:\s*\"(?P[a-zA-Z0-9._-]+):(?P

[0-9]{2,6})\"`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + h := utils.ShortNodeName(submatches["h"]) + mid := submatches["mid"] + if mid != "" { + translate.AddHashToNodeName(mid, h, date) + } + return logCtx, types.SimpleDisplayer("member " + mid + " " + h) + }, + Verbosity: types.DebugContext, + }, + + "RegexElectionObjectId": &types.LogRegex{ + Regex: regexp.MustCompile(`ObjectId\('\s*[a-fA-F0-9]{24}\s*'\)`), + InternalRegex: regexp.MustCompile(`ObjectId\('\s*(?P[a-fA-F0-9]{24})\s*'\)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, date time.Time) (types.LogCtx, types.LogDisplayer) { + oid := strings.ToLower(submatches["oid"]) + logCtx.AddOwnHash(oid, date) + return logCtx, types.SimpleDisplayer("id " + oid[:8]) + }, + Verbosity: types.DebugContext, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regex/regex.go b/src/go/pt-mongo-log-explainer/regex/regex.go new file mode 100644 index 000000000..0cfe4d6ba --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/regex.go @@ -0,0 +1,85 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "errors" + "fmt" + "regexp" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/rs/zerolog/log" +) + +var uuidFullRE = regexp.MustCompile(`(?i)^[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}$`) +var uuidShortRE = regexp.MustCompile(`(?i)^[a-f0-9]{8}-[a-f0-9]{4}$`) +var ipv4RE = regexp.MustCompile(`^[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}$`) + +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 + } +} + +func SetVerbosity(verbosity types.Verbosity, regexes types.RegexMap) { + for _, regex := range regexes { + regex.Verbosity = verbosity + } +} + +func AllRegexes() types.RegexMap { + IdentsMap.Merge(TopologyMap).Merge(ReplicationMap).Merge(EventsMap).Merge(StatesMap).Merge(ClusterMap).Merge(CustomMap) + return IdentsMap +} + +var ( + groupHost = "host" + groupPort = "port" + groupNodeName = "nodename" + groupUUID = "_id" + groupMembers = "members" + groupVersion = "version" + regexHostPort = "(?P<" + groupHost + `>[a-zA-Z0-9._-]+):(?P<` + groupPort + `>[0-9]{2,6})` + regexNodeIP = "(?P<" + groupHost + ">[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3})" + regexNodeName = "(?P<" + groupNodeName + `>[a-zA-Z0-9._-]+)` + regexUUID = "(?P<" + groupUUID + ">[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12})" + regexShortUUID = "(?P<" + groupUUID + ">[a-f0-9]{8}-[a-f0-9]{4})" + regexMembers = "(?P<" + groupMembers + ">[0-9]{1,3})" + regexVersion = "(?P<" + groupVersion + `>([0-9]+)\.([0-9]+)\.([0-9]+))` +) + +func IsNodeUUID(s string) bool { + return uuidFullRE.MatchString(s) || uuidShortRE.MatchString(s) +} + +func IsMongoObjectID(s string) bool { + b, err := regexp.MatchString(`^[a-fA-F0-9]{24}$`, s) + if err != nil { + log.Warn().Err(err).Str("input", s).Msg("failed to check ObjectId") + return false + } + return b +} + +func IsNodeIP(s string) bool { + return ipv4RE.MatchString(s) +} diff --git a/src/go/pt-mongo-log-explainer/regex/replication.go b/src/go/pt-mongo-log-explainer/regex/replication.go new file mode 100644 index 000000000..52e5de2fe --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/replication.go @@ -0,0 +1,64 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" +) + +func init() { + setType(types.ReplicationRegexType, ReplicationMap) +} + +// ReplicationMap holds replication / initial-sync / oplog events. +var ReplicationMap = types.RegexMap{ + "RegexInitialSync": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)initial sync`), + InternalRegex: regexp.MustCompile(`(?i)initial sync`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("initial sync") + }, + Verbosity: types.Info, + }, + + "RegexInitialSyncComplete": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)initial sync complete|finished initial sync`), + InternalRegex: regexp.MustCompile(`(?i)initial sync complete|finished initial sync`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("initial sync done") + }, + Verbosity: types.Info, + }, + + "RegexOplogApplication": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)oplog|replication batch|Applying batch`), + InternalRegex: regexp.MustCompile(`(?i)(oplog|replication batch|Applying batch)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("oplog apply") + }, + Verbosity: types.DebugContext, + }, + + "RegexResync": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)resync|resync requested|full sync`), + InternalRegex: regexp.MustCompile(`(?i)(resync|full sync)`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("resync") + }, + Verbosity: types.Info, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regex/states.go b/src/go/pt-mongo-log-explainer/regex/states.go new file mode 100644 index 000000000..ef49e27a1 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/states.go @@ -0,0 +1,64 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +func init() { + setType(types.StatesRegexType, StatesMap) +} + +var StatesMap = types.RegexMap{ + "RegexTransitionPrimary": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)transition to primary`), + InternalRegex: regexp.MustCompile(`(?i)transition to primary`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + logCtx.SetState("PRIMARY") + return logCtx, types.SimpleDisplayer(utils.PaintForState("PRIMARY", "PRIMARY")) + }, + Verbosity: types.Info, + }, + + "RegexMemberState": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)(member is now in state|transition to member state|entering .* state)`), + InternalRegex: regexp.MustCompile(`(?i)(?PPRIMARY|SECONDARY|ARBITER|STARTUP2?|RECOVERING|ROLLBACK|REMOVED|DOWN)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + st := strings.ToUpper(submatches["st"]) + if st == "" { + return logCtx, nil + } + logCtx.SetState(st) + return logCtx, types.SimpleDisplayer(utils.PaintForState(st, st)) + }, + Verbosity: types.Info, + }, + + "RegexJSONNewState": &types.LogRegex{ + Regex: regexp.MustCompile(`"newState"`), + InternalRegex: regexp.MustCompile(`"newState"\s*:\s*"(?PPRIMARY|SECONDARY|ARBITER|STARTUP2?|RECOVERING|ROLLBACK|REMOVED|DOWN)"`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + st := strings.ToUpper(submatches["st"]) + logCtx.SetState(st) + return logCtx, types.SimpleDisplayer(utils.PaintForState(st, st)) + }, + Verbosity: types.Info, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regex/topology.go b/src/go/pt-mongo-log-explainer/regex/topology.go new file mode 100644 index 000000000..46837a17f --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regex/topology.go @@ -0,0 +1,72 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package regex + +import ( + "regexp" + "strconv" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" +) + +func init() { + setType(types.TopologyRegexType, TopologyMap) +} + +// TopologyMap holds replica-set topology / configuration events. +var TopologyMap = types.RegexMap{ + "RegexReplSetInitiate": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)replSetInitiate|initiating a replica set`), + InternalRegex: regexp.MustCompile(`(?i)replSetInitiate|initiating a replica set`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + logCtx.MemberCount = 1 + return logCtx, types.SimpleDisplayer("replSet initiate") + }, + Verbosity: types.Info, + }, + + "RegexReplicaSetReconfig": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)new replica set config|replSetReconfig|reconfiguring replica set`), + InternalRegex: regexp.MustCompile(`(?i)new replica set config|replSetReconfig|reconfiguring replica set`), + Handler: func(_ map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("replica set reconfig") + }, + Verbosity: types.Info, + }, + + "RegexMemberCountInConfig": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)members\.[0-9]|"members"\s*:\s*\[`), + InternalRegex: regexp.MustCompile(`(?i)version:\s*(?P[0-9]+).*members:\s*(?P[0-9]+)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + if n := submatches["n"]; n != "" { + if c, err := strconv.Atoi(n); err == nil { + logCtx.MemberCount = c + return logCtx, types.SimpleDisplayer("member count " + n) + } + } + return logCtx, types.SimpleDisplayer("topology change") + }, + Verbosity: types.DebugContext, + }, + + "RegexAddedRemovedMember": &types.LogRegex{ + Regex: regexp.MustCompile(`(?i)added .*member|removed .*member|Adding .* to replica set`), + InternalRegex: regexp.MustCompile(`(?i)(?Padded|removed|Adding)`), + Handler: func(submatches map[string]string, logCtx types.LogCtx, _ string, _ time.Time) (types.LogCtx, types.LogDisplayer) { + return logCtx, types.SimpleDisplayer("member " + submatches["ev"]) + }, + Verbosity: types.Info, + }, +} diff --git a/src/go/pt-mongo-log-explainer/regexList.go b/src/go/pt-mongo-log-explainer/regexList.go new file mode 100644 index 000000000..24930f7e4 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/regexList.go @@ -0,0 +1,41 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "encoding/json" + "fmt" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/pkg/errors" +) + +type regexList struct { +} + +func (l *regexList) Help() string { + return "List available regexes. Can be used to exclude them later" +} + +func (l *regexList) Run() error { + + allregexes := regex.AllRegexes() + + out, err := json.Marshal(&allregexes) + if err != nil { + return errors.Wrap(err, "could not marshal regexes") + } + fmt.Println(string(out)) + return nil +} diff --git a/src/go/pt-mongo-log-explainer/renderer/color_human.go b/src/go/pt-mongo-log-explainer/renderer/color_human.go new file mode 100644 index 000000000..293c7095d --- /dev/null +++ b/src/go/pt-mongo-log-explainer/renderer/color_human.go @@ -0,0 +1,100 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. + +package renderer + +import ( + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +// eventTypeColor picks a semantic color for the event type column. +func eventTypeColor(et string) utils.Color { + switch et { + case "PROCESS_SHUTDOWN", "STEPDOWN", "ELECTION_FAIL", "FATAL_ERROR", "ROLLBACK", + "AUTH_FAILURE", "NETWORK_ERROR", "HEARTBEAT_FAIL", "QUORUM_LOSS", "MEMBER_UNREACHABLE", + "CONN_POOL_ERROR", "CONN_POOL_EXHAUSTED", "DNS_ERROR", "SOCKET_ERROR", "WRITE_CONCERN_ERROR", + "WT_PANIC", "WT_DATA_CORRUPTION": + return utils.BrightRedText + case "PROCESS_START", "NODE_LISTEN", "ELECTION_SUCCESS", "PRIMARY_TRANSITION", "QUORUM_OK": + return utils.BrightGreenText + case "SECONDARY_TRANSITION", "MEMBER_STATE", "RS_INITIATE", "INITIAL_SYNC": + return utils.GreenText + case "ELECTION", "RECONFIG", "RS_CONFIG", "HEARTBEAT", "SYNC_SOURCE_CHANGE", "MEMBER_JOIN", "MEMBER_LEAVE": + return utils.CyanText + case "SLOW_QUERY", "SLOW_WRITE", "LONG_RUNNING_CMD", "INDEX_BUILD", "OP_TIMEOUT", "CURSOR_TIMEOUT", + "OPLOG_TAIL_SLOW", "WT_CACHE_PRESSURE", "WT_CHECKPOINT_SLOW", "FLOW_CONTROL": + return utils.YellowText + case "CHUNK_MIGRATION", "BALANCER", "SHARDING": + return utils.BrightMagentaText + default: + if strings.Contains(strings.ToLower(et), "fail") || strings.Contains(strings.ToLower(et), "error") { + return utils.BrightRedText + } + return utils.WhiteText + } +} + +func statusColor(st types.EventStatus) utils.Color { + switch st { + case types.StatusFailure: + return utils.BrightRedText + case types.StatusSuccess: + return utils.BrightGreenText + case types.StatusWarn: + return utils.YellowText + case types.StatusInfo: + return utils.CyanText + default: + return utils.WhiteText + } +} + +func formatHumanLine(e *types.StructuredEvent, ts, hp, node string, highlight bool) string { + if utils.SkipColor { + return formatHumanPlain(e, ts, hp, node, highlight) + } + + prefix := "" + if e.Anomaly != "" && highlight { + prefix = utils.Paint(utils.BrightYellowText, "[ANOMALY:"+e.Anomaly+"] ") + } + + et := e.EventType + st := string(e.Status) + + nc := utils.NodeHue(node) + ec := eventTypeColor(et) + sc := statusColor(e.Status) + + // Prefer strong red/green from status when it disagrees with a neutral event color + if e.Status == types.StatusFailure { + ec = utils.BrightRedText + } + if e.Status == types.StatusSuccess && (et == "MEMBER_STATE" || et == "HEARTBEAT" || et == "REPL") { + ec = utils.GreenText + } + + line := prefix + + utils.Paint(utils.WhiteText, "["+ts+"]") + " " + + utils.Paint(nc, "["+node+"]") + " " + + utils.Paint(utils.BrightBlueText, "["+hp+"]") + " " + + utils.Paint(ec, "["+et+"]") + " " + + utils.Paint(sc, "["+st+"]") + " " + + utils.Paint(utils.WhiteText, "["+e.Details+"]") + + return line +} + +func formatHumanPlain(e *types.StructuredEvent, ts, hp, node string, highlight bool) string { + prefix := "" + if e.Anomaly != "" && highlight { + prefix = "[ANOMALY:" + e.Anomaly + "] " + } + return prefix + "[" + ts + "] [" + node + "] [" + hp + "] [" + e.EventType + "] [" + string(e.Status) + "] [" + e.Details + "]" +} diff --git a/src/go/pt-mongo-log-explainer/renderer/renderer.go b/src/go/pt-mongo-log-explainer/renderer/renderer.go new file mode 100644 index 000000000..66967cd5b --- /dev/null +++ b/src/go/pt-mongo-log-explainer/renderer/renderer.go @@ -0,0 +1,161 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package renderer + +import ( + "encoding/json" + "fmt" + "io" + "strings" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" +) + +const humanTimeLayout = "2006-01-02 15:04:05" + +// WriteHuman prints one line per event: +// [timestamp] [node] [host:port] [event_type] [status] [details] +// When utils.SkipColor is false, node names use a stable per-node color, event types use +// semantic colors (e.g. shutdown/stepdown/failures in red, healthy transitions in green). +func WriteHuman(w io.Writer, evts []*types.StructuredEvent, highlight bool) error { + for _, e := range evts { + ts := e.Time.Format(humanTimeLayout) + if e.Time.IsZero() { + ts = "unknown-time" + } + hp := e.HostPort + if hp == "" { + hp = "-" + } + node := e.Node + if node == "" { + node = "-" + } + line := formatHumanLine(e, ts, hp, node, highlight) + if _, err := fmt.Fprintln(w, line); err != nil { + return err + } + } + return nil +} + +// WriteJSON emits a JSON array of events. +func WriteJSON(w io.Writer, evts []*types.StructuredEvent) error { + enc := json.NewEncoder(w) + enc.SetIndent("", " ") + return enc.Encode(evts) +} + +// FilterCategories keeps events matching enabled filters (OR). If none enabled, returns all. +func FilterCategories(evts []*types.StructuredEvent, elections, replication, errors_, sharding, performance bool) []*types.StructuredEvent { + if !elections && !replication && !errors_ && !sharding && !performance { + return evts + } + out := make([]*types.StructuredEvent, 0, len(evts)) + for _, e := range evts { + if matchAnyFilter(e, elections, replication, errors_, sharding, performance) { + out = append(out, e) + } + } + return out +} + +func matchAnyFilter(e *types.StructuredEvent, elections, replication, errors_, sharding, performance bool) bool { + et := e.EventType + cat := e.Category + + if elections && electionRelated(et, cat) { + return true + } + if replication && replicationRelated(et, cat) { + return true + } + if errors_ && failureRelated(e, et, cat) { + return true + } + if sharding && shardingRelated(et, cat) { + return true + } + if performance && performanceRelated(et, cat) { + return true + } + return false +} + +func electionRelated(et string, cat types.EventCategory) bool { + if cat == types.CatRole || cat == types.CatTopology { + return true + } + switch et { + case "PRIMARY_TRANSITION", "STEPDOWN", "SECONDARY_TRANSITION", "MEMBER_STATE", + "ELECTION", "ELECTION_SUCCESS", "ELECTION_FAIL", + "RS_CONFIG", "HEARTBEAT", "HEARTBEAT_FAIL", "RS_INITIATE", "RECONFIG", + "MEMBER_JOIN", "MEMBER_LEAVE", "MEMBER_UNREACHABLE", + "QUORUM_LOSS", "QUORUM_OK": + return true + } + if strings.HasPrefix(et, "ELECTION") { + return true + } + return false +} + +func replicationRelated(et string, cat types.EventCategory) bool { + if cat == types.CatReplication { + return true + } + switch et { + case "INITIAL_SYNC", "ROLLBACK", "REPL_OPLOG", "REPL", "REPL_STATE", "REPL_LAG", + "RS_INITIATE", "OPLOG_TAIL_SLOW", "SYNC_SOURCE_CHANGE", "OPLOG_WINDOW": + return true + } + return false +} + +func failureRelated(e *types.StructuredEvent, et string, cat types.EventCategory) bool { + if cat == types.CatFailure { + return true + } + if e.Status == types.StatusFailure { + return true + } + switch et { + case "NETWORK_ERROR", "AUTH_FAILURE", "FATAL_ERROR", "PROCESS_SHUTDOWN", "HEARTBEAT_FAIL", + "CONN_POOL_ERROR", "SOCKET_ERROR", "DNS_ERROR", "WRITE_CONCERN_ERROR": + return true + } + return false +} + +func shardingRelated(et string, cat types.EventCategory) bool { + if cat == types.CatSharding { + return true + } + switch et { + case "CHUNK_MIGRATION", "BALANCER", "SHARDING": + return true + } + return false +} + +func performanceRelated(et string, cat types.EventCategory) bool { + if cat == types.CatPerformance { + return true + } + switch et { + case "LONG_RUNNING_CMD", "INDEX_BUILD", "OP_TIMEOUT", "CURSOR_TIMEOUT": + return true + } + return strings.Contains(et, "SLOW") +} diff --git a/src/go/pt-mongo-log-explainer/summary.go b/src/go/pt-mongo-log-explainer/summary.go new file mode 100644 index 000000000..5b5ca6632 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/summary.go @@ -0,0 +1,246 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. + +package main + +import ( + "fmt" + "sort" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/collect" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/parser" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/pkg/errors" +) + +type summary struct { + Paths []string `arg:"" name:"paths" help:"MongoDB log files to analyze"` +} + +func (s *summary) Help() string { + return fmt.Sprintf(`Show cluster topology summary: each node's hostname, IP, host:port, +replica set, MongoDB version, and last known member state. + +Usage: + %[1]s summary *.log + %[1]s summary tests/logs/replicaset/*.log +`, toolname) +} + +type nodeSummary struct { + Hostname string + IP string + HostPort string + RSName string + Version string + State string + LogFile string +} + +func (s *summary) Run() error { + if len(s.Paths) == 0 { + return errors.New("at least one log path is required") + } + + nodes := s.collectNodes() + if len(nodes) == 0 { + return errors.New("no node identity found in the provided logs") + } + + sort.Slice(nodes, func(i, j int) bool { + if nodes[i].RSName != nodes[j].RSName { + return nodes[i].RSName < nodes[j].RSName + } + return nodes[i].Hostname < nodes[j].Hostname + }) + + s.printSummary(nodes) + return nil +} + +func (s *summary) collectNodes() []nodeSummary { + seen := map[string]*nodeSummary{} // keyed by hostname+hostport + var order []string // preserves first-seen order + + for _, path := range s.Paths { + ctx := &parser.ScanContext{} + lastState := "" + var lastTS time.Time + + _ = collect.ForEachLine(path, CLI.GrepCmd, false, func(line string) error { + ev := parser.ParseLine(path, line, ctx) + if ev == nil { + return nil + } + if !ev.Time.IsZero() { + lastTS = ev.Time + } + st := extractState(ev) + if st != "" { + lastState = st + } + return nil + }) + + hostname := ctx.NodeLabel() + if hostname == "" || hostname == "unknown" { + continue + } + + if lastTS.IsZero() { + lastTS = time.Now() + } + ctx.FlushToTranslateDB(lastTS) + + // Fall back: if structured parser didn't catch state, try regex pipeline. + if lastState == "" { + lastState = s.stateFromRegex(path) + } + + hp := ctx.HostPort() + key := hostname + if hp != "" { + key = hp + } + if existing, ok := seen[key]; ok { + if lastState != "" { + existing.State = lastState + } + if ctx.ServerIP != "" { + existing.IP = ctx.ServerIP + } + if hp != "" && existing.HostPort == "" { + existing.HostPort = hp + } + if ctx.Version != "" { + existing.Version = ctx.Version + } + if ctx.RSName != "" { + existing.RSName = ctx.RSName + } + continue + } + + ns := &nodeSummary{ + Hostname: hostname, + IP: ctx.ServerIP, + HostPort: hp, + RSName: ctx.RSName, + Version: ctx.Version, + State: lastState, + LogFile: path, + } + seen[key] = ns + order = append(order, key) + } + + nodes := make([]nodeSummary, 0, len(order)) + for _, key := range order { + nodes = append(nodes, *seen[key]) + } + return nodes +} + +func extractState(ev *types.StructuredEvent) string { + switch ev.EventType { + case "PRIMARY_TRANSITION": + return "PRIMARY" + case "STEPDOWN": + return "SECONDARY" + case "SECONDARY_TRANSITION": + return "SECONDARY" + case "MEMBER_STATE": + if strings.HasPrefix(ev.Details, "state=") { + return strings.TrimPrefix(ev.Details, "state=") + } + for _, kw := range []string{"PRIMARY", "SECONDARY", "ARBITER", "RECOVERING", "STARTUP", "STARTUP2", "ROLLBACK", "DOWN", "REMOVED"} { + if strings.Contains(strings.ToUpper(ev.Details), kw) { + return kw + } + } + } + return "" +} + +func (s *summary) stateFromRegex(path string) string { + regexes := make(types.RegexMap, len(regex.IdentsMap)+len(regex.StatesMap)) + regexes.Merge(regex.IdentsMap) + regexes.Merge(regex.StatesMap) + timeline, err := timelineFromPaths([]string{path}, regexes) + if err != nil { + return "" + } + ctxs := timeline.GetLatestContextsByNodes() + for _, logCtx := range ctxs { + if st := logCtx.State(); st != "" { + return st + } + } + return "" +} + +func (s *summary) printSummary(nodes []nodeSummary) { + currentRS := "" + + for i, n := range nodes { + if n.RSName != currentRS { + if i > 0 { + fmt.Println() + } + rs := n.RSName + if rs == "" { + rs = "(no replica set)" + } + fmt.Println(utils.Paint(utils.BrightWhiteText, "Replica Set: "+rs)) + fmt.Println(utils.Paint(utils.BrightWhiteText, strings.Repeat("─", 50))) + currentRS = n.RSName + } + + color := nodeColor(i) + + hostname := utils.Paint(color, n.Hostname) + ip := n.IP + if ip == "" { + ip = "-" + } + hp := n.HostPort + if hp == "" { + hp = "-" + } + version := n.Version + if version == "" { + version = "-" + } + state := n.State + if state == "" { + state = "UNKNOWN" + } + stateDisplay := utils.PaintForState(state, state) + + fmt.Printf(" %s\n", hostname) + fmt.Printf(" %-12s %s\n", utils.Paint(utils.BlueText, "IP:"), ip) + fmt.Printf(" %-12s %s\n", utils.Paint(utils.BlueText, "Host:Port:"), hp) + fmt.Printf(" %-12s %s\n", utils.Paint(utils.BlueText, "Version:"), version) + fmt.Printf(" %-12s %s\n", utils.Paint(utils.BlueText, "State:"), stateDisplay) + } +} + +var memberColors = []utils.Color{ + utils.BrightCyanText, + utils.BrightMagentaText, + utils.BrightGreenText, + utils.BrightYellowText, + utils.BrightBlueText, + utils.BrightWhiteText, +} + +func nodeColor(idx int) utils.Color { + return memberColors[idx%len(memberColors)] +} diff --git a/src/go/pt-mongo-log-explainer/tests/expected/list_all b/src/go/pt-mongo-log-explainer/tests/expected/list_all new file mode 100644 index 000000000..9a0e6c4be --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/list_all @@ -0,0 +1,27 @@ +identifier rs:rs0 +current path tests/logs/replicaset/mongo-0.log +last known ip 192.168.1.12 +last known name rs:rs0 +mongodb version 6.0.12 + +2024-06-01T12:00:00.100+0000 mongod starting +2024-06-01T12:00:02.300+0000 replSet initiate + listen:27017 + (node name) + V + rs:rs0 +2024-06-01T12:00:02.400+0000 replica set reconfig +2024-06-01T12:00:03.500+0000 PRIMARY +2024-06-01T12:00:04.000+0000 election activity +2024-06-01T12:00:15.000+0000 step down +2024-06-01T12:00:15.100+0000 step down +2024-06-01T12:00:20.000+0000 replica set reconfig +2024-06-01T12:00:20.100+0000 replica set reconfig + tests/logs/replicaset/mongo-0.log + (file path) + V + tests/logs/replicaset/mongo-2.log + 192.168.1.10 + (node ip) + V + 192.168.1.12 diff --git a/src/go/pt-mongo-log-explainer/tests/expected/list_standalone_70 b/src/go/pt-mongo-log-explainer/tests/expected/list_standalone_70 new file mode 100644 index 000000000..bce9c193e --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/list_standalone_70 @@ -0,0 +1,9 @@ +identifier listen:27027 +current path tests/logs/standalone/mongod-7.0.log +last known ip 10.0.0.5 +last known name listen:27027 +mongodb version 7.0.28-15 + +2026-05-11T14:52:46.010+08:00 mongod starting +2026-05-11T14:52:48.000+08:00 PRIMARY +2026-05-11T14:52:48.000+08:00 PRIMARY diff --git a/src/go/pt-mongo-log-explainer/tests/expected/regex_list b/src/go/pt-mongo-log-explainer/tests/expected/regex_list new file mode 100644 index 000000000..baa55ddcf --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/regex_list @@ -0,0 +1 @@ +{"RegexAddedRemovedMember":{"regex":"(?i)added .*member|removed .*member|Adding .* to replica set","internalRegex":"(?i)(?P\u003cev\u003eadded|removed|Adding)","type":"topology","verbosity":0},"RegexBindIP":{"regex":"(?i)bindIp.*[0-9]+\\.[0-9]+\\.[0-9]+\\.[0-9]+","internalRegex":"bindIp[^0-9]*(?P\u003chost\u003e[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3}\\.[0-9]{1,3})","type":"identity","verbosity":1},"RegexConfigHost":{"regex":"\\\"host\\\"\\s*:\\s*\\\"","internalRegex":"\\\"host\\\"\\s*:\\s*\\\"(?P\u003ch\u003e[a-zA-Z0-9._-]+):(?P\u003cp\u003e[0-9]{2,6})\\\"","type":"identity","verbosity":1},"RegexConnectionAccepted":{"regex":"(?i)connection accepted","internalRegex":"(?i)(?:from |\"remote\"\\s*:\\s*\")(?P\u003chost\u003e[0-9.]+):(?P\u003cport\u003e[0-9]+)","type":"identity","verbosity":1},"RegexDBException":{"regex":"DBException|Location[0-9]+","internalRegex":"(?P\u003cerr\u003e(DBException|Location[0-9]+))","type":"events","verbosity":0},"RegexElection":{"regex":"(?i)election|voteRequest|election succeeded|election failed","internalRegex":"(?i)(election|voteRequest)","type":"cluster","verbosity":0},"RegexElectionObjectId":{"regex":"ObjectId\\('\\s*[a-fA-F0-9]{24}\\s*'\\)","internalRegex":"ObjectId\\('\\s*(?P\u003coid\u003e[a-fA-F0-9]{24})\\s*'\\)","type":"identity","verbosity":1},"RegexFatalAssertion":{"regex":"(?i)Fatal|assertion.*failed|segmentation fault","internalRegex":"(?i)(Fatal assertion|assertion.*failed|segmentation fault)","type":"events","verbosity":0},"RegexInitialSync":{"regex":"(?i)initial sync","internalRegex":"(?i)initial sync","type":"replication","verbosity":0},"RegexInitialSyncComplete":{"regex":"(?i)initial sync complete|finished initial sync","internalRegex":"(?i)initial sync complete|finished initial sync","type":"replication","verbosity":0},"RegexJSONNewState":{"regex":"\"newState\"","internalRegex":"\"newState\"\\s*:\\s*\"(?P\u003cst\u003ePRIMARY|SECONDARY|ARBITER|STARTUP2?|RECOVERING|ROLLBACK|REMOVED|DOWN)\"","type":"states","verbosity":0},"RegexMemberCountInConfig":{"regex":"(?i)members\\.[0-9]|\"members\"\\s*:\\s*\\[","internalRegex":"(?i)version:\\s*(?P\u003cv\u003e[0-9]+).*members:\\s*(?P\u003cn\u003e[0-9]+)","type":"topology","verbosity":1},"RegexMemberIDHost":{"regex":"(?i)member.*_id.*host","internalRegex":"(?i)_id:\\s*(?P\u003cmid\u003e[0-9]+).*host:\\s*\\\"(?P\u003ch\u003e[a-zA-Z0-9._-]+):(?P\u003cp\u003e[0-9]{2,6})\\\"","type":"identity","verbosity":1},"RegexMemberState":{"regex":"(?i)(member is now in state|transition to member state|entering .* state)","internalRegex":"(?i)(?P\u003cst\u003ePRIMARY|SECONDARY|ARBITER|STARTUP2?|RECOVERING|ROLLBACK|REMOVED|DOWN)","type":"states","verbosity":0},"RegexMongoDBStarting":{"regex":"(?i)MongoDB starting|mongod.*starting","internalRegex":"(?i)MongoDB starting|starting.*mongod","type":"events","verbosity":0},"RegexMongoVersion":{"regex":"(?i)db version v[0-9]|\"buildInfo\"\\s*:\\s*\\{\\s*\"version\"","internalRegex":"(?i)(?:db version v|\"buildInfo\"\\s*:\\s*\\{\\s*\"version\"\\s*:\\s*\"v?)(?P\u003cver\u003e[0-9]+\\.[0-9]+\\.[0-9]+[-.0-9A-Za-z]*)","type":"identity","verbosity":1},"RegexNotPrimary":{"regex":"(?i)NotPrimary|not master|not writable primary","internalRegex":"(?i)(NotPrimary|not master|not writable primary)","type":"cluster","verbosity":0},"RegexOplogApplication":{"regex":"(?i)oplog|replication batch|Applying batch","internalRegex":"(?i)(oplog|replication batch|Applying batch)","type":"replication","verbosity":1},"RegexReplSetInitiate":{"regex":"(?i)replSetInitiate|initiating a replica set","internalRegex":"(?i)replSetInitiate|initiating a replica set","type":"topology","verbosity":0},"RegexReplSetName":{"regex":"(?i)replSet|replica set","internalRegex":"(?i)(replSet|replica set|replicaSet)[^a-zA-Z0-9_]+(?P\u003crs\u003e[a-zA-Z0-9_-]{2,64})","type":"identity","verbosity":1},"RegexReplicaSetReconfig":{"regex":"(?i)new replica set config|replSetReconfig|reconfiguring replica set","internalRegex":"(?i)new replica set config|replSetReconfig|reconfiguring replica set","type":"topology","verbosity":0},"RegexResync":{"regex":"(?i)resync|resync requested|full sync","internalRegex":"(?i)(resync|full sync)","type":"replication","verbosity":0},"RegexRollbackEvent":{"regex":"(?i)rollback|Rolling back","internalRegex":"(?i)(rollback|Rolling back)","type":"cluster","verbosity":0},"RegexShutdown":{"regex":"(?i)Shutting down|now exiting|shutdown: ","internalRegex":"(?i)(Shutting down|now exiting|shutdown:)","type":"events","verbosity":0},"RegexStepDown":{"regex":"(?i)stepped down|Stepping down|transition to secondary","internalRegex":"(?i)(stepped down|Stepping down)","type":"cluster","verbosity":0},"RegexTransitionPrimary":{"regex":"(?i)transition to primary","internalRegex":"(?i)transition to primary","type":"states","verbosity":0},"RegexWaitingForConnections":{"regex":"(?i)waiting for connections","internalRegex":"(?i)(port|\\\"port\\\")\\D*(?P\u003cport\u003e[0-9]{2,6})","type":"identity","verbosity":1},"RegexWriteConcernTimeout":{"regex":"(?i)wtimeout|write concern","internalRegex":"(?i)(wtimeout|WriteConcernFailed|write concern)","type":"cluster","verbosity":0}} diff --git a/src/go/pt-mongo-log-explainer/tests/expected/summary_replicaset b/src/go/pt-mongo-log-explainer/tests/expected/summary_replicaset new file mode 100644 index 000000000..f31c97eba --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/summary_replicaset @@ -0,0 +1,17 @@ +Replica Set: rs0 +────────────────────────────────────────────────── + mongo-rs0-0 + IP: 192.168.1.10 + Host:Port: mongo-rs0-0:27017 + Version: 6.0.12 + State: SECONDARY + mongo-rs0-1 + IP: 192.168.1.11 + Host:Port: mongo-rs0-1:27017 + Version: 6.0.12 + State: PRIMARY + mongo-rs0-2 + IP: 192.168.1.12 + Host:Port: mongo-rs0-2:27017 + Version: 6.0.12 + State: SECONDARY diff --git a/src/go/pt-mongo-log-explainer/tests/expected/summary_sharded b/src/go/pt-mongo-log-explainer/tests/expected/summary_sharded new file mode 100644 index 000000000..25db9cff2 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/summary_sharded @@ -0,0 +1,18 @@ + configsvr-0 + IP: - + Host:Port: configsvr-0:27019 + Version: - + State: UNKNOWN + mongos-router-1 + IP: - + Host:Port: mongos-router-1:27017 + Version: - + State: UNKNOWN + +Replica Set: shard0-rs +────────────────────────────────────────────────── + shard0-rs0-0 + IP: - + Host:Port: shard0-rs0-0:27018 + Version: - + State: PRIMARY diff --git a/src/go/pt-mongo-log-explainer/tests/expected/summary_standalone_70 b/src/go/pt-mongo-log-explainer/tests/expected/summary_standalone_70 new file mode 100644 index 000000000..112521d10 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/summary_standalone_70 @@ -0,0 +1,5 @@ + mongo-node-a + IP: 10.0.0.5,127.0.0.1 + Host:Port: mongo-node-a:27027 + Version: 7.0.28-15 + State: PRIMARY diff --git a/src/go/pt-mongo-log-explainer/tests/expected/timeline_all b/src/go/pt-mongo-log-explainer/tests/expected/timeline_all new file mode 100644 index 000000000..6e5cc5c8a --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/timeline_all @@ -0,0 +1,31 @@ +[2024-06-01 12:00:00] [mongo-rs0-0] [mongo-rs0-0:27017] [PROCESS_START] [SUCCESS] [process=mongod 2024-06-01T12:00:00.100+0000 I CONTROL [initandlisten] MongoDB starting : pid=1001 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-0] +[2024-06-01 12:00:00] [mongo-rs0-1] [mongo-rs0-1:27017] [PROCESS_START] [SUCCESS] [process=mongod 2024-06-01T12:00:00.120+0000 I CONTROL [initandlisten] MongoDB starting : pid=1002 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-1] +[2024-06-01 12:00:00] [mongo-rs0-2] [mongo-rs0-2:27017] [PROCESS_START] [SUCCESS] [process=mongod 2024-06-01T12:00:00.130+0000 I CONTROL [initandlisten] MongoDB starting : pid=1003 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-2] +[2024-06-01 12:00:01] [mongo-rs0-0] [mongo-rs0-0:27017] [NODE_LISTEN] [INFO] [process=mongod 2024-06-01T12:00:01.200+0000 I NETWORK [listener] waiting for connections on port 27017] +[2024-06-01 12:00:01] [mongo-rs0-1] [mongo-rs0-1:27017] [NODE_LISTEN] [INFO] [process=mongod 2024-06-01T12:00:01.250+0000 I NETWORK [listener] waiting for connections on port 27017] +[2024-06-01 12:00:01] [mongo-rs0-2] [mongo-rs0-2:27017] [NODE_LISTEN] [INFO] [process=mongod 2024-06-01T12:00:01.260+0000 I NETWORK [listener] waiting for connections on port 27017] +[2024-06-01 12:00:02] [mongo-rs0-0] [mongo-rs0-0:27017] [RS_INITIATE] [SUCCESS] [2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received] +[2024-06-01 12:00:03] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:03.000+0000 I REPL [initialSync] initial sync source chosen: mongo-rs0-0:27017] +[2024-06-01 12:00:03] [mongo-rs0-0] [mongo-rs0-0:27017] [PRIMARY_TRANSITION] [SUCCESS] [rs=rs0 2024-06-01T12:00:03.500+0000 I REPL [conn1] transition to primary complete; database writes are now permitted] +[2024-06-01 12:00:03] [mongo-rs0-0] [mongo-rs0-0:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=PRIMARY] +[2024-06-01 12:00:04] [mongo-rs0-0] [mongo-rs0-0:27017] [ELECTION_SUCCESS] [SUCCESS] [rs=rs0 2024-06-01T12:00:04.000+0000 I ELECTION [conn1] election succeeded for term 1] +[2024-06-01 12:00:04] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:04.000+0000 I REPL [initialSync] initial sync in progress: cloning collection local.oplog.rs] +[2024-06-01 12:00:07] [mongo-rs0-2] [mongo-rs0-2:27017] [SECONDARY_TRANSITION] [INFO] [rs=rs0 2024-06-01T12:00:07.000+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING] +[2024-06-01 12:00:07] [mongo-rs0-2] [mongo-rs0-2:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=SECONDARY] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:08.000+0000 I REPL [initialSync] initial sync complete] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:08.100+0000 I REPL [initialSync] finished initial sync, transitioning to steady replication] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=SECONDARY] +[2024-06-01 12:00:12] [mongo-rs0-2] [mongo-rs0-2:27017] [ROLLBACK] [FAILURE] [rs=rs0 2024-06-01T12:00:12.000+0000 W REPL [rsBackgroundSync] rollback required after sync source change] +[2024-06-01 12:00:12] [mongo-rs0-2] [mongo-rs0-2:27017] [ROLLBACK] [FAILURE] [rs=rs0 2024-06-01T12:00:12.500+0000 E REPL [rsBackgroundSync] rollback failed: could not complete rollback] +[2024-06-01 12:00:15] [mongo-rs0-0] [mongo-rs0-0:27017] [STEPDOWN] [WARN] [rs=rs0 2024-06-01T12:00:15.000+0000 I REPL [conn5] stepping down self from primary; stepping down to secondary] +[2024-06-01 12:00:15] [mongo-rs0-0] [mongo-rs0-0:27017] [STEPDOWN] [WARN] [rs=rs0 2024-06-01T12:00:15.100+0000 I REPL [conn5] stepped down from primary] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [ELECTION_SUCCESS] [SUCCESS] [sequence=stepdown→election rs=rs0 2024-06-01T12:00:15.500+0000 I ELECTION [conn3] election succeeded for term 2] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [PRIMARY_TRANSITION] [SUCCESS] [sequence=stepdown→election→primary rs=rs0 2024-06-01T12:00:15.700+0000 I REPL [conn3] transition to primary complete; database writes are now permitted] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=PRIMARY] +[2024-06-01 12:00:16] [mongo-rs0-0] [mongo-rs0-0:27017] [SECONDARY_TRANSITION] [INFO] [rs=rs0 2024-06-01T12:00:16.200+0000 I REPL [conn5] transition to SECONDARY from PRIMARY] +[2024-06-01 12:00:18] [mongo-rs0-1] [mongo-rs0-1:27017] [HEARTBEAT_FAIL] [FAILURE] [rs=rs0 2024-06-01T12:00:18.000+0000 W REPL [rsBackgroundSync] heartbeat to mongo-rs0-2:27017 failed after 3 attempts: timeout] +[2024-06-01 12:00:20] [mongo-rs0-0] [mongo-rs0-0:27017] [RECONFIG] [INFO] [rs=rs0 2024-06-01T12:00:20.000+0000 I REPL [conn6] replSetReconfig command received] +[2024-06-01 12:00:20] [mongo-rs0-0] [mongo-rs0-0:27017] [RECONFIG] [INFO] [rs=rs0 2024-06-01T12:00:20.100+0000 I REPL [conn6] replSetReconfig finished; new config version 2] +[2024-06-01 12:00:25] [mongo-rs0-1] [mongo-rs0-1:27017] [SYNC_SOURCE_CHANGE] [INFO] [rs=rs0 2024-06-01T12:00:25.000+0000 I REPL [rsBackgroundSync] Changed sync source from mongo-rs0-0:27017 to mongo-rs0-2:27017] +[2024-06-01 12:00:30] [mongo-rs0-2] [mongo-rs0-2:27017] [QUORUM_OK] [SUCCESS] [rs=rs0 2024-06-01T12:00:30.000+0000 I REPL [rsBackgroundSync] quorum check succeeded for replica set rs0] +[2024-06-01 12:05:00] [mongo-rs0-0] [mongo-rs0-0:27017] [SLOW_QUERY] [WARN] [rs=rs0 2024-06-01T12:05:00.000+0000 I COMMAND [conn9] slow query: { find: "orders" } planSummary: IXSCAN keysExamined:1200000 docsExamined:1200000 durationMillis: 850] diff --git a/src/go/pt-mongo-log-explainer/tests/expected/timeline_elections b/src/go/pt-mongo-log-explainer/tests/expected/timeline_elections new file mode 100644 index 000000000..fd0db47c4 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/timeline_elections @@ -0,0 +1,17 @@ +[2024-06-01 12:00:02] [mongo-rs0-0] [mongo-rs0-0:27017] [RS_INITIATE] [SUCCESS] [2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received] +[2024-06-01 12:00:03] [mongo-rs0-0] [mongo-rs0-0:27017] [PRIMARY_TRANSITION] [SUCCESS] [rs=rs0 2024-06-01T12:00:03.500+0000 I REPL [conn1] transition to primary complete; database writes are now permitted] +[2024-06-01 12:00:03] [mongo-rs0-0] [mongo-rs0-0:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=PRIMARY] +[2024-06-01 12:00:04] [mongo-rs0-0] [mongo-rs0-0:27017] [ELECTION_SUCCESS] [SUCCESS] [rs=rs0 2024-06-01T12:00:04.000+0000 I ELECTION [conn1] election succeeded for term 1] +[2024-06-01 12:00:07] [mongo-rs0-2] [mongo-rs0-2:27017] [SECONDARY_TRANSITION] [INFO] [rs=rs0 2024-06-01T12:00:07.000+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING] +[2024-06-01 12:00:07] [mongo-rs0-2] [mongo-rs0-2:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=SECONDARY] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=SECONDARY] +[2024-06-01 12:00:15] [mongo-rs0-0] [mongo-rs0-0:27017] [STEPDOWN] [WARN] [rs=rs0 2024-06-01T12:00:15.000+0000 I REPL [conn5] stepping down self from primary; stepping down to secondary] +[2024-06-01 12:00:15] [mongo-rs0-0] [mongo-rs0-0:27017] [STEPDOWN] [WARN] [rs=rs0 2024-06-01T12:00:15.100+0000 I REPL [conn5] stepped down from primary] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [ELECTION_SUCCESS] [SUCCESS] [sequence=stepdown→election rs=rs0 2024-06-01T12:00:15.500+0000 I ELECTION [conn3] election succeeded for term 2] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [PRIMARY_TRANSITION] [SUCCESS] [sequence=stepdown→election→primary rs=rs0 2024-06-01T12:00:15.700+0000 I REPL [conn3] transition to primary complete; database writes are now permitted] +[2024-06-01 12:00:15] [mongo-rs0-1] [mongo-rs0-1:27017] [MEMBER_STATE] [INFO] [rs=rs0 state=PRIMARY] +[2024-06-01 12:00:16] [mongo-rs0-0] [mongo-rs0-0:27017] [SECONDARY_TRANSITION] [INFO] [rs=rs0 2024-06-01T12:00:16.200+0000 I REPL [conn5] transition to SECONDARY from PRIMARY] +[2024-06-01 12:00:18] [mongo-rs0-1] [mongo-rs0-1:27017] [HEARTBEAT_FAIL] [FAILURE] [rs=rs0 2024-06-01T12:00:18.000+0000 W REPL [rsBackgroundSync] heartbeat to mongo-rs0-2:27017 failed after 3 attempts: timeout] +[2024-06-01 12:00:20] [mongo-rs0-0] [mongo-rs0-0:27017] [RECONFIG] [INFO] [rs=rs0 2024-06-01T12:00:20.000+0000 I REPL [conn6] replSetReconfig command received] +[2024-06-01 12:00:20] [mongo-rs0-0] [mongo-rs0-0:27017] [RECONFIG] [INFO] [rs=rs0 2024-06-01T12:00:20.100+0000 I REPL [conn6] replSetReconfig finished; new config version 2] +[2024-06-01 12:00:30] [mongo-rs0-2] [mongo-rs0-2:27017] [QUORUM_OK] [SUCCESS] [rs=rs0 2024-06-01T12:00:30.000+0000 I REPL [rsBackgroundSync] quorum check succeeded for replica set rs0] diff --git a/src/go/pt-mongo-log-explainer/tests/expected/timeline_json b/src/go/pt-mongo-log-explainer/tests/expected/timeline_json new file mode 100644 index 000000000..b699b41a5 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/timeline_json @@ -0,0 +1,353 @@ +[ + { + "time": "2024-06-01T12:00:00.1Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "PROCESS_START", + "status": "SUCCESS", + "details": "process=mongod 2024-06-01T12:00:00.100+0000 I CONTROL [initandlisten] MongoDB starting : pid=1001 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-0", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:00.100+0000 I CONTROL [initandlisten] MongoDB starting : pid=1001 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-0" + }, + { + "time": "2024-06-01T12:00:00.12Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "PROCESS_START", + "status": "SUCCESS", + "details": "process=mongod 2024-06-01T12:00:00.120+0000 I CONTROL [initandlisten] MongoDB starting : pid=1002 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-1", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:00.120+0000 I CONTROL [initandlisten] MongoDB starting : pid=1002 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-1" + }, + { + "time": "2024-06-01T12:00:00.13Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "PROCESS_START", + "status": "SUCCESS", + "details": "process=mongod 2024-06-01T12:00:00.130+0000 I CONTROL [initandlisten] MongoDB starting : pid=1003 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-2", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:00.130+0000 I CONTROL [initandlisten] MongoDB starting : pid=1003 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-2" + }, + { + "time": "2024-06-01T12:00:01.2Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "NODE_LISTEN", + "status": "INFO", + "details": "process=mongod 2024-06-01T12:00:01.200+0000 I NETWORK [listener] waiting for connections on port 27017", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:01.200+0000 I NETWORK [listener] waiting for connections on port 27017" + }, + { + "time": "2024-06-01T12:00:01.25Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "NODE_LISTEN", + "status": "INFO", + "details": "process=mongod 2024-06-01T12:00:01.250+0000 I NETWORK [listener] waiting for connections on port 27017", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:01.250+0000 I NETWORK [listener] waiting for connections on port 27017" + }, + { + "time": "2024-06-01T12:00:01.26Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "NODE_LISTEN", + "status": "INFO", + "details": "process=mongod 2024-06-01T12:00:01.260+0000 I NETWORK [listener] waiting for connections on port 27017", + "category": "node", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:01.260+0000 I NETWORK [listener] waiting for connections on port 27017" + }, + { + "time": "2024-06-01T12:00:02.3Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "RS_INITIATE", + "status": "SUCCESS", + "details": "2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received", + "category": "topology", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received" + }, + { + "time": "2024-06-01T12:00:03Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "INITIAL_SYNC", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:03.000+0000 I REPL [initialSync] initial sync source chosen: mongo-rs0-0:27017", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:03.000+0000 I REPL [initialSync] initial sync source chosen: mongo-rs0-0:27017", + "anomaly": "SYNC_TIMEOUT" + }, + { + "time": "2024-06-01T12:00:03.5Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "PRIMARY_TRANSITION", + "status": "SUCCESS", + "details": "rs=rs0 2024-06-01T12:00:03.500+0000 I REPL [conn1] transition to primary complete; database writes are now permitted", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:03.500+0000 I REPL [conn1] transition to primary complete; database writes are now permitted" + }, + { + "time": "2024-06-01T12:00:03.6Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "MEMBER_STATE", + "status": "INFO", + "details": "rs=rs0 state=PRIMARY", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:03.600+0000 I REPL [conn1] Replica Set Member State: PRIMARY" + }, + { + "time": "2024-06-01T12:00:04Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "ELECTION_SUCCESS", + "status": "SUCCESS", + "details": "rs=rs0 2024-06-01T12:00:04.000+0000 I ELECTION [conn1] election succeeded for term 1", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:04.000+0000 I ELECTION [conn1] election succeeded for term 1" + }, + { + "time": "2024-06-01T12:00:04Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "INITIAL_SYNC", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:04.000+0000 I REPL [initialSync] initial sync in progress: cloning collection local.oplog.rs", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:04.000+0000 I REPL [initialSync] initial sync in progress: cloning collection local.oplog.rs", + "anomaly": "SYNC_TIMEOUT" + }, + { + "time": "2024-06-01T12:00:07Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "SECONDARY_TRANSITION", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:07.000+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:07.000+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING" + }, + { + "time": "2024-06-01T12:00:07.1Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "MEMBER_STATE", + "status": "INFO", + "details": "rs=rs0 state=SECONDARY", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:07.100+0000 I REPL [rsSync] Replica Set Member State: SECONDARY" + }, + { + "time": "2024-06-01T12:00:08Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "INITIAL_SYNC", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:08.000+0000 I REPL [initialSync] initial sync complete", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:08.000+0000 I REPL [initialSync] initial sync complete", + "anomaly": "SYNC_TIMEOUT" + }, + { + "time": "2024-06-01T12:00:08.1Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "INITIAL_SYNC", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:08.100+0000 I REPL [initialSync] finished initial sync, transitioning to steady replication", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:08.100+0000 I REPL [initialSync] finished initial sync, transitioning to steady replication", + "anomaly": "SYNC_TIMEOUT" + }, + { + "time": "2024-06-01T12:00:08.5Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "MEMBER_STATE", + "status": "INFO", + "details": "rs=rs0 state=SECONDARY", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:08.500+0000 I REPL [rsBackgroundSync] Replica Set Member State: SECONDARY" + }, + { + "time": "2024-06-01T12:00:12Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "ROLLBACK", + "status": "FAILURE", + "details": "rs=rs0 2024-06-01T12:00:12.000+0000 W REPL [rsBackgroundSync] rollback required after sync source change", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:12.000+0000 W REPL [rsBackgroundSync] rollback required after sync source change", + "anomaly": "ROLLBACK" + }, + { + "time": "2024-06-01T12:00:12.5Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "ROLLBACK", + "status": "FAILURE", + "details": "rs=rs0 2024-06-01T12:00:12.500+0000 E REPL [rsBackgroundSync] rollback failed: could not complete rollback", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:12.500+0000 E REPL [rsBackgroundSync] rollback failed: could not complete rollback", + "anomaly": "ROLLBACK" + }, + { + "time": "2024-06-01T12:00:15Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "STEPDOWN", + "status": "WARN", + "details": "rs=rs0 2024-06-01T12:00:15.000+0000 I REPL [conn5] stepping down self from primary; stepping down to secondary", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:15.000+0000 I REPL [conn5] stepping down self from primary; stepping down to secondary", + "sequence_id": "stepdown-1" + }, + { + "time": "2024-06-01T12:00:15.1Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "STEPDOWN", + "status": "WARN", + "details": "rs=rs0 2024-06-01T12:00:15.100+0000 I REPL [conn5] stepped down from primary", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:15.100+0000 I REPL [conn5] stepped down from primary", + "sequence_id": "stepdown-2" + }, + { + "time": "2024-06-01T12:00:15.5Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "ELECTION_SUCCESS", + "status": "SUCCESS", + "details": "sequence=stepdown→election rs=rs0 2024-06-01T12:00:15.500+0000 I ELECTION [conn3] election succeeded for term 2", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:15.500+0000 I ELECTION [conn3] election succeeded for term 2", + "sequence_id": "stepdown-2" + }, + { + "time": "2024-06-01T12:00:15.7Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "PRIMARY_TRANSITION", + "status": "SUCCESS", + "details": "sequence=stepdown→election→primary rs=rs0 2024-06-01T12:00:15.700+0000 I REPL [conn3] transition to primary complete; database writes are now permitted", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:15.700+0000 I REPL [conn3] transition to primary complete; database writes are now permitted", + "sequence_id": "stepdown-2" + }, + { + "time": "2024-06-01T12:00:15.8Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "MEMBER_STATE", + "status": "INFO", + "details": "rs=rs0 state=PRIMARY", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:15.800+0000 I REPL [conn3] Replica Set Member State: PRIMARY" + }, + { + "time": "2024-06-01T12:00:16.2Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "SECONDARY_TRANSITION", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:16.200+0000 I REPL [conn5] transition to SECONDARY from PRIMARY", + "category": "role", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:16.200+0000 I REPL [conn5] transition to SECONDARY from PRIMARY" + }, + { + "time": "2024-06-01T12:00:18Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "HEARTBEAT_FAIL", + "status": "FAILURE", + "details": "rs=rs0 2024-06-01T12:00:18.000+0000 W REPL [rsBackgroundSync] heartbeat to mongo-rs0-2:27017 failed after 3 attempts: timeout", + "category": "topology", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:18.000+0000 W REPL [rsBackgroundSync] heartbeat to mongo-rs0-2:27017 failed after 3 attempts: timeout" + }, + { + "time": "2024-06-01T12:00:20Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "RECONFIG", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:20.000+0000 I REPL [conn6] replSetReconfig command received", + "category": "topology", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:20.000+0000 I REPL [conn6] replSetReconfig command received" + }, + { + "time": "2024-06-01T12:00:20.1Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "RECONFIG", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:20.100+0000 I REPL [conn6] replSetReconfig finished; new config version 2", + "category": "topology", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:00:20.100+0000 I REPL [conn6] replSetReconfig finished; new config version 2" + }, + { + "time": "2024-06-01T12:00:25Z", + "node": "mongo-rs0-1", + "host_port": "mongo-rs0-1:27017", + "event_type": "SYNC_SOURCE_CHANGE", + "status": "INFO", + "details": "rs=rs0 2024-06-01T12:00:25.000+0000 I REPL [rsBackgroundSync] Changed sync source from mongo-rs0-0:27017 to mongo-rs0-2:27017", + "category": "replication", + "source_file": "tests/logs/replicaset/mongo-1.log", + "raw": "2024-06-01T12:00:25.000+0000 I REPL [rsBackgroundSync] Changed sync source from mongo-rs0-0:27017 to mongo-rs0-2:27017" + }, + { + "time": "2024-06-01T12:00:30Z", + "node": "mongo-rs0-2", + "host_port": "mongo-rs0-2:27017", + "event_type": "QUORUM_OK", + "status": "SUCCESS", + "details": "rs=rs0 2024-06-01T12:00:30.000+0000 I REPL [rsBackgroundSync] quorum check succeeded for replica set rs0", + "category": "topology", + "source_file": "tests/logs/replicaset/mongo-2.log", + "raw": "2024-06-01T12:00:30.000+0000 I REPL [rsBackgroundSync] quorum check succeeded for replica set rs0" + }, + { + "time": "2024-06-01T12:05:00Z", + "node": "mongo-rs0-0", + "host_port": "mongo-rs0-0:27017", + "event_type": "SLOW_QUERY", + "status": "WARN", + "details": "rs=rs0 2024-06-01T12:05:00.000+0000 I COMMAND [conn9] slow query: { find: \"orders\" } planSummary: IXSCAN keysExamined:1200000 docsExamined:1200000 durationMillis: 850", + "category": "performance", + "source_file": "tests/logs/replicaset/mongo-0.log", + "raw": "2024-06-01T12:05:00.000+0000 I COMMAND [conn9] slow query: { find: \"orders\" } planSummary: IXSCAN keysExamined:1200000 docsExamined:1200000 durationMillis: 850" + } +] diff --git a/src/go/pt-mongo-log-explainer/tests/expected/timeline_replication b/src/go/pt-mongo-log-explainer/tests/expected/timeline_replication new file mode 100644 index 000000000..b35327ee0 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/timeline_replication @@ -0,0 +1,8 @@ +[2024-06-01 12:00:02] [mongo-rs0-0] [mongo-rs0-0:27017] [RS_INITIATE] [SUCCESS] [2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received] +[2024-06-01 12:00:03] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:03.000+0000 I REPL [initialSync] initial sync source chosen: mongo-rs0-0:27017] +[2024-06-01 12:00:04] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:04.000+0000 I REPL [initialSync] initial sync in progress: cloning collection local.oplog.rs] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:08.000+0000 I REPL [initialSync] initial sync complete] +[2024-06-01 12:00:08] [mongo-rs0-1] [mongo-rs0-1:27017] [INITIAL_SYNC] [INFO] [rs=rs0 2024-06-01T12:00:08.100+0000 I REPL [initialSync] finished initial sync, transitioning to steady replication] +[2024-06-01 12:00:12] [mongo-rs0-2] [mongo-rs0-2:27017] [ROLLBACK] [FAILURE] [rs=rs0 2024-06-01T12:00:12.000+0000 W REPL [rsBackgroundSync] rollback required after sync source change] +[2024-06-01 12:00:12] [mongo-rs0-2] [mongo-rs0-2:27017] [ROLLBACK] [FAILURE] [rs=rs0 2024-06-01T12:00:12.500+0000 E REPL [rsBackgroundSync] rollback failed: could not complete rollback] +[2024-06-01 12:00:25] [mongo-rs0-1] [mongo-rs0-1:27017] [SYNC_SOURCE_CHANGE] [INFO] [rs=rs0 2024-06-01T12:00:25.000+0000 I REPL [rsBackgroundSync] Changed sync source from mongo-rs0-0:27017 to mongo-rs0-2:27017] diff --git a/src/go/pt-mongo-log-explainer/tests/expected/timeline_sharding b/src/go/pt-mongo-log-explainer/tests/expected/timeline_sharding new file mode 100644 index 000000000..1b0caac92 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/timeline_sharding @@ -0,0 +1,7 @@ +[2024-06-01 14:00:05] [mongos-router-1] [mongos-router-1:27017] [BALANCER] [INFO] [2024-06-01T14:00:05.000+0000 I SHARDING [Balancer] balancer enabled for cluster] +[2024-06-01 14:00:10] [mongos-router-1] [mongos-router-1:27017] [CHUNK_MIGRATION] [INFO] [2024-06-01T14:00:10.000+0000 I SHARDING [Balancer] balancer round complete: moved 2 chunks] +[2024-06-01 14:00:15] [mongos-router-1] [mongos-router-1:27017] [CHUNK_MIGRATION] [INFO] [2024-06-01T14:00:15.000+0000 I SHARDING [conn2] chunk move scheduled from shard shard0 to shard shard1 ns=test.orders] +[2024-06-01 14:00:16] [mongos-router-1] [mongos-router-1:27017] [CHUNK_MIGRATION] [INFO] [phase=start 2024-06-01T14:00:16.000+0000 I SHARDING [conn2] migration started for namespace test.orders] +[2024-06-01 14:00:18] [mongos-router-1] [mongos-router-1:27017] [CHUNK_MIGRATION] [SUCCESS] [phase=complete 2024-06-01T14:00:18.500+0000 I SHARDING [conn2] migration committed for namespace test.orders] +[2024-06-01 14:00:25] [mongos-router-1] [mongos-router-1:27017] [CHUNK_MIGRATION] [FAILURE] [phase=abort 2024-06-01T14:00:25.000+0000 W SHARDING [conn3] migration aborted for namespace test.inventory due to lock timeout] +[2024-06-01 14:00:30] [mongos-router-1] [mongos-router-1:27017] [BALANCER] [INFO] [2024-06-01T14:00:30.000+0000 I SHARDING [Balancer] balancer disabled by user command] diff --git a/src/go/pt-mongo-log-explainer/tests/expected/whois_id b/src/go/pt-mongo-log-explainer/tests/expected/whois_id new file mode 100644 index 000000000..b4213da8d --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/whois_id @@ -0,0 +1,3 @@ +nodename: +└── 0 + diff --git a/src/go/pt-mongo-log-explainer/tests/expected/whois_ip b/src/go/pt-mongo-log-explainer/tests/expected/whois_ip new file mode 100644 index 000000000..cd1a43ef7 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/whois_ip @@ -0,0 +1,9 @@ +ip: +└── 192.168.1.10 + └── nodename: + └── mongo-rs0-0 + └── _id: + └── 0 + + + diff --git a/src/go/pt-mongo-log-explainer/tests/expected/whois_nodename b/src/go/pt-mongo-log-explainer/tests/expected/whois_nodename new file mode 100644 index 000000000..c91d2a893 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/expected/whois_nodename @@ -0,0 +1,9 @@ +nodename: +└── mongo-rs0-0 + ├── ip: + │ └── 192.168.1.10 + │ + └── _id: + └── 0 + + diff --git a/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-0.log b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-0.log new file mode 100644 index 000000000..d1ed9927e --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-0.log @@ -0,0 +1,22 @@ +2024-06-01T12:00:00.100+0000 I CONTROL [initandlisten] MongoDB starting : pid=1001 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-0 +2024-06-01T12:00:00.110+0000 I CONTROL [initandlisten] options: { net: { bindIp: "192.168.1.10", port: 27017 } } +2024-06-01T12:00:00.150+0000 I CONTROL [initandlisten] db version v6.0.12 +2024-06-01T12:00:01.200+0000 I NETWORK [listener] waiting for connections on port 27017 +2024-06-01T12:00:01.500+0000 I NETWORK [listener] connection accepted from 192.168.1.11:45231 +2024-06-01T12:00:01.600+0000 I NETWORK [listener] connection accepted from 192.168.1.12:45232 +2024-06-01T12:00:02.300+0000 I REPL [conn1] replSetInitiate admin command received +2024-06-01T12:00:02.350+0000 I REPL [conn1] initiating a new replica set +2024-06-01T12:00:02.355+0000 I REPL [conn1] configuration for replica set rs0 with 3 members +2024-06-01T12:00:02.400+0000 I REPL [conn1] new replica set config version: 1 members: 3 +2024-06-01T12:00:02.450+0000 I REPL [conn1] member _id: 0 host: "mongo-rs0-0:27017" +2024-06-01T12:00:02.460+0000 I REPL [conn1] member _id: 1 host: "mongo-rs0-1:27017" +2024-06-01T12:00:02.470+0000 I REPL [conn1] member _id: 2 host: "mongo-rs0-2:27017" +2024-06-01T12:00:03.500+0000 I REPL [conn1] transition to primary complete; database writes are now permitted +2024-06-01T12:00:03.600+0000 I REPL [conn1] Replica Set Member State: PRIMARY +2024-06-01T12:00:04.000+0000 I ELECTION [conn1] election succeeded for term 1 +2024-06-01T12:00:15.000+0000 I REPL [conn5] stepping down self from primary; stepping down to secondary +2024-06-01T12:00:15.100+0000 I REPL [conn5] stepped down from primary +2024-06-01T12:00:16.200+0000 I REPL [conn5] transition to SECONDARY from PRIMARY +2024-06-01T12:00:20.000+0000 I REPL [conn6] replSetReconfig command received +2024-06-01T12:00:20.100+0000 I REPL [conn6] replSetReconfig finished; new config version 2 +2024-06-01T12:05:00.000+0000 I COMMAND [conn9] slow query: { find: "orders" } planSummary: IXSCAN keysExamined:1200000 docsExamined:1200000 durationMillis: 850 diff --git a/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-1.log b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-1.log new file mode 100644 index 000000000..639186c72 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-1.log @@ -0,0 +1,17 @@ +2024-06-01T12:00:00.120+0000 I CONTROL [initandlisten] MongoDB starting : pid=1002 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-1 +2024-06-01T12:00:00.125+0000 I CONTROL [initandlisten] db version v6.0.12 +2024-06-01T12:00:00.130+0000 I CONTROL [initandlisten] options: { net: { bindIp: "192.168.1.11", port: 27017 } } +2024-06-01T12:00:01.250+0000 I NETWORK [listener] waiting for connections on port 27017 +2024-06-01T12:00:01.400+0000 I NETWORK [listener] connection accepted from 192.168.1.10:46100 +2024-06-01T12:00:02.500+0000 I REPL [initandlisten] replica set rs0 starting up +2024-06-01T12:00:03.000+0000 I REPL [initialSync] initial sync source chosen: mongo-rs0-0:27017 +2024-06-01T12:00:04.000+0000 I REPL [initialSync] initial sync in progress: cloning collection local.oplog.rs +2024-06-01T12:00:08.000+0000 I REPL [initialSync] initial sync complete +2024-06-01T12:00:08.100+0000 I REPL [initialSync] finished initial sync, transitioning to steady replication +2024-06-01T12:00:08.500+0000 I REPL [rsBackgroundSync] Replica Set Member State: SECONDARY +2024-06-01T12:00:09.000+0000 I REPL [rsBackgroundSync] Applying batch of operations from oplog +2024-06-01T12:00:15.500+0000 I ELECTION [conn3] election succeeded for term 2 +2024-06-01T12:00:15.700+0000 I REPL [conn3] transition to primary complete; database writes are now permitted +2024-06-01T12:00:15.800+0000 I REPL [conn3] Replica Set Member State: PRIMARY +2024-06-01T12:00:18.000+0000 W REPL [rsBackgroundSync] heartbeat to mongo-rs0-2:27017 failed after 3 attempts: timeout +2024-06-01T12:00:25.000+0000 I REPL [rsBackgroundSync] Changed sync source from mongo-rs0-0:27017 to mongo-rs0-2:27017 diff --git a/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-2.log b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-2.log new file mode 100644 index 000000000..8f674a900 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/replicaset/mongo-2.log @@ -0,0 +1,14 @@ +2024-06-01T12:00:00.130+0000 I CONTROL [initandlisten] MongoDB starting : pid=1003 port=27017 dbpath=/data/db 64-bit host=mongo-rs0-2 +2024-06-01T12:00:00.135+0000 I CONTROL [initandlisten] db version v6.0.12 +2024-06-01T12:00:00.140+0000 I CONTROL [initandlisten] options: { net: { bindIp: "192.168.1.12", port: 27017 } } +2024-06-01T12:00:01.260+0000 I NETWORK [listener] waiting for connections on port 27017 +2024-06-01T12:00:01.400+0000 I NETWORK [listener] connection accepted from 192.168.1.10:47200 +2024-06-01T12:00:01.500+0000 I NETWORK [listener] connection accepted from 192.168.1.11:47201 +2024-06-01T12:00:02.600+0000 I REPL [initandlisten] replica set rs0 starting up +2024-06-01T12:00:03.200+0000 I REPL [rsSync] transition to RECOVERING from STARTUP2 +2024-06-01T12:00:07.000+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING +2024-06-01T12:00:07.100+0000 I REPL [rsSync] Replica Set Member State: SECONDARY +2024-06-01T12:00:12.000+0000 W REPL [rsBackgroundSync] rollback required after sync source change +2024-06-01T12:00:12.500+0000 E REPL [rsBackgroundSync] rollback failed: could not complete rollback +2024-06-01T12:00:30.000+0000 I REPL [rsBackgroundSync] quorum check succeeded for replica set rs0 +2024-06-01T12:00:45.000+0000 I COMMAND [conn2] command test.$cmd command: find { find: "events", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:5000000 durationMillis: 2100 diff --git a/src/go/pt-mongo-log-explainer/tests/logs/sharded/configsvr.log b/src/go/pt-mongo-log-explainer/tests/logs/sharded/configsvr.log new file mode 100644 index 000000000..987973240 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/sharded/configsvr.log @@ -0,0 +1,5 @@ +2024-06-01T14:00:00.020+0000 I CONTROL [initandlisten] MongoDB starting : pid=7001 port=27019 dbpath=/data/config 64-bit host=configsvr-0 +2024-06-01T14:00:01.000+0000 I NETWORK [listener] waiting for connections on port 27019 +2024-06-01T14:00:05.000+0000 I SHARDING [conn1] replica set config for shard shard0 updated +2024-06-01T14:00:08.000+0000 I SHARDING [conn2] chunk migration between shards for ns=test.orders +2024-06-01T14:00:20.000+0000 W NETWORK [conn3] network error while communicating with host shard0-rs0-1:27018: connection reset by peer diff --git a/src/go/pt-mongo-log-explainer/tests/logs/sharded/mongos.log b/src/go/pt-mongo-log-explainer/tests/logs/sharded/mongos.log new file mode 100644 index 000000000..c2b656b36 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/sharded/mongos.log @@ -0,0 +1,10 @@ +2024-06-01T14:00:00.000+0000 I CONTROL [main] MongoDB starting : pid=5001 port=27017 dbpath=/data/configdb 64-bit host=mongos-router-1 +2024-06-01T14:00:01.000+0000 I NETWORK [listener] waiting for connections on port 27017 +2024-06-01T14:00:05.000+0000 I SHARDING [Balancer] balancer enabled for cluster +2024-06-01T14:00:10.000+0000 I SHARDING [Balancer] balancer round complete: moved 2 chunks +2024-06-01T14:00:15.000+0000 I SHARDING [conn2] chunk move scheduled from shard shard0 to shard shard1 ns=test.orders +2024-06-01T14:00:16.000+0000 I SHARDING [conn2] migration started for namespace test.orders +2024-06-01T14:00:18.500+0000 I SHARDING [conn2] migration committed for namespace test.orders +2024-06-01T14:00:25.000+0000 W SHARDING [conn3] migration aborted for namespace test.inventory due to lock timeout +2024-06-01T14:00:30.000+0000 I SHARDING [Balancer] balancer disabled by user command +2024-06-01T14:00:40.000+0000 I COMMAND [conn5] slow query: { count: "orders" } keysExamined:800000 docsExamined:800000 durationMillis: 1200 diff --git a/src/go/pt-mongo-log-explainer/tests/logs/sharded/shard0-primary.log b/src/go/pt-mongo-log-explainer/tests/logs/sharded/shard0-primary.log new file mode 100644 index 000000000..23a596ddf --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/sharded/shard0-primary.log @@ -0,0 +1,7 @@ +2024-06-01T14:00:00.050+0000 I CONTROL [initandlisten] MongoDB starting : pid=6001 port=27018 dbpath=/data/db 64-bit host=shard0-rs0-0 +2024-06-01T14:00:01.000+0000 I NETWORK [listener] waiting for connections on port 27018 +2024-06-01T14:00:02.000+0000 I REPL [initandlisten] replica set shard0-rs starting up +2024-06-01T14:00:03.000+0000 I REPL [conn1] Replica Set Member State: PRIMARY +2024-06-01T14:00:04.000+0000 I SHARDING [conn2] sharding metadata refresh for database test +2024-06-01T14:00:10.000+0000 I REPL [conn4] Applying batch of operations from oplog for namespace test.orders +2024-06-01T14:00:12.000+0000 W WRITE [conn6] command test.orders command: insert { insert: "orders" } write concern error: wtimeout diff --git a/src/go/pt-mongo-log-explainer/tests/logs/standalone/mongod-7.0.log b/src/go/pt-mongo-log-explainer/tests/logs/standalone/mongod-7.0.log new file mode 100644 index 000000000..b81581a2a --- /dev/null +++ b/src/go/pt-mongo-log-explainer/tests/logs/standalone/mongod-7.0.log @@ -0,0 +1,14 @@ +{"t":{"$date":"2026-05-11T14:52:46.003+08:00"},"s":"I","c":"CONTROL","id":23285,"ctx":"main","msg":"Automatically disabling TLS 1.0"} +{"t":{"$date":"2026-05-11T14:52:46.007+08:00"},"s":"I","c":"NETWORK","id":4648601,"ctx":"main","msg":"Implicit TCP FastOpen unavailable."} +{"t":{"$date":"2026-05-11T14:52:46.010+08:00"},"s":"I","c":"CONTROL","id":4615611,"ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":688508,"port":27027,"dbPath":"/data/db","architecture":"64-bit","host":"mongo-node-a"}} +{"t":{"$date":"2026-05-11T14:52:46.010+08:00"},"s":"I","c":"CONTROL","id":23403,"ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"7.0.28-15","gitVersion":"574f4d867493f37","modules":["enterprise"],"allocator":"tcmalloc"}}} +{"t":{"$date":"2026-05-11T14:52:46.010+08:00"},"s":"I","c":"CONTROL","id":51765,"ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Amazon Linux release 2023.9.20250929","version":"Kernel 6.1.153-175.280.amzn2023.x86_64"}}} +{"t":{"$date":"2026-05-11T14:52:46.110+08:00"},"s":"I","c":"NETWORK","id":4915702,"ctx":"initandlisten","msg":"Configuration","attr":{"net":{"bindIp":"10.0.0.5,127.0.0.1","port":27027}}} +{"t":{"$date":"2026-05-11T14:52:47.137+08:00"},"s":"I","c":"STORAGE","id":22315,"ctx":"initandlisten","msg":"Opening WiredTiger"} +{"t":{"$date":"2026-05-11T14:52:47.190+08:00"},"s":"I","c":"REPL","id":40440,"ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"} +{"t":{"$date":"2026-05-11T14:52:47.265+08:00"},"s":"I","c":"REPL","id":6015317,"ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled"}} +{"t":{"$date":"2026-05-11T14:52:47.300+08:00"},"s":"I","c":"NETWORK","id":23016,"ctx":"listener","msg":"Waiting for connections","attr":{"port":27027}} +{"t":{"$date":"2026-05-11T14:52:48.000+08:00"},"s":"I","c":"REPL","id":21392,"ctx":"conn1","msg":"transition to PRIMARY complete; database writes are now permitted","attr":{"newState":"PRIMARY"}} +{"t":{"$date":"2026-05-11T15:00:26.389+08:00"},"s":"I","c":"NETWORK","id":22943,"ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:39552","connectionId":1}} +{"t":{"$date":"2026-05-11T15:00:26.399+08:00"},"s":"I","c":"NETWORK","id":51800,"ctx":"conn2","msg":"client metadata","attr":{"remote":"10.0.0.9:53994","client":"conn2","doc":{"driver":{"name":"mongo-go-driver","version":"1.17.4"},"os":{"type":"linux"},"platform":"go1.22"}}} +{"t":{"$date":"2026-05-11T15:05:00.000+08:00"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn2","msg":"Slow query","attr":{"ns":"app.orders","durationMillis":850,"planSummary":"COLLSCAN"}} diff --git a/src/go/pt-mongo-log-explainer/timeline.go b/src/go/pt-mongo-log-explainer/timeline.go new file mode 100644 index 000000000..a09f4546a --- /dev/null +++ b/src/go/pt-mongo-log-explainer/timeline.go @@ -0,0 +1,131 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "fmt" + "os" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/collect" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/correlator" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/parser" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/renderer" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/pkg/errors" +) + +type timeline struct { + Paths []string `arg:"" name:"paths" help:"MongoDB log files (text or JSON per line)"` + + FullScan bool `help:"Scan every line (slower; grep pre-filter misses rare lines without keywords)"` + + Elections bool `help:"Only election, primary/secondary transitions, heartbeats, topology"` + Replication bool `help:"Only replication / initial sync / rollback / oplog"` + Errors bool `help:"Only failures, auth, network, fatals"` + Sharding bool `help:"Only chunk migration, balancer, sharding"` + Performance bool `help:"Only slow queries / long ops"` + JSON bool `help:"Emit JSON instead of human-readable lines"` + Highlight bool `name:"highlight-anomalies" help:"Highlight anomaly tags in color (human output)"` + SkipCorrelate bool `help:"Skip sequence correlation hints"` + SkipAnomalies bool `help:"Skip anomaly tagging"` + Timezone string `help:"Normalize all timestamps to this timezone (e.g. UTC, America/New_York). Default: UTC" default:"UTC"` + Limit int `help:"Maximum number of events to output (0 = unlimited)" default:"0"` +} + +func (t *timeline) Help() string { + return fmt.Sprintf(`Build a merged chronological timeline of MongoDB cluster events. + +Output format (default): + [timestamp] [node] [host:port] [event_type] [status] [details] + +Examples: + %[1]s timeline -- /data/mongo/*.log + %[1]s timeline --full-scan --elections --replication /node1.log /node2.log + %[1]s timeline --errors --highlight-anomalies=true *.log + %[1]s timeline --json *.log +`, toolname) +} + +func (t *timeline) Run() error { + if len(t.Paths) == 0 { + return errors.New("at least one log path is required") + } + + loc, err := time.LoadLocation(t.Timezone) + if err != nil { + return errors.Wrapf(err, "invalid timezone %q", t.Timezone) + } + + // Pre-allocate based on estimated event density (~1 event per 500 bytes). + var totalSize int64 + for _, path := range t.Paths { + if info, err := os.Stat(path); err == nil { + totalSize += info.Size() + } + } + estEvents := int(totalSize / 500) + if estEvents < 256 { + estEvents = 256 + } + all := make([]*types.StructuredEvent, 0, estEvents) + + for _, path := range t.Paths { + ctx := &parser.ScanContext{} + err := collect.ForEachLine(path, CLI.GrepCmd, !t.FullScan, func(line string) error { + ev := parser.ParseLine(path, line, ctx) + if ev == nil { + return nil + } + if CLI.Since != nil && ev.Time.Before(*CLI.Since) { + return nil + } + if CLI.Until != nil && ev.Time.After(*CLI.Until) { + return nil + } + ev.Time = ev.Time.In(loc) + all = append(all, ev) + return nil + }) + if err != nil { + return err + } + } + + if len(all) == 0 { + return errors.New("no structured events found (try --full-scan or different log paths)") + } + + correlator.SortByTime(all) + if !t.SkipCorrelate { + correlator.Correlate(all) + } + if !t.SkipAnomalies { + correlator.MarkAnomalies(all) + } + + out := renderer.FilterCategories(all, t.Elections, t.Replication, t.Errors, t.Sharding, t.Performance) + if len(out) == 0 { + return errors.New("no events after category filters (adjust flags or omit filters for full output)") + } + + if t.Limit > 0 && len(out) > t.Limit { + out = out[:t.Limit] + } + + if t.JSON { + return renderer.WriteJSON(os.Stdout, out) + } + return renderer.WriteHuman(os.Stdout, out, t.Highlight && !CLI.NoColor) +} diff --git a/src/go/pt-mongo-log-explainer/translate/translate.go b/src/go/pt-mongo-log-explainer/translate/translate.go new file mode 100644 index 000000000..a07a91873 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/translate/translate.go @@ -0,0 +1,370 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package translate + +import ( + "encoding/json" + "sort" + "sync" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +type translationUnit struct { + Value string + Timestamp time.Time +} + +type translationsDB struct { + // 1 hash: only 1 IP. If there's a restart, the hash will change as well. + HashToIP map[string]*translationUnit + + HashToNodeNames map[string][]translationUnit + IPToNodeNames map[string][]translationUnit + + // in case methods changed in the middle, tcp=>ssl + IPToMethods map[string][]translationUnit + + // MongoDB identity: host:port -> nodename, and nodename -> host:port + HostPortToNodeNames map[string][]translationUnit + NodeNameToHostPorts map[string][]translationUnit + NodeNameToRSNames map[string][]translationUnit + + rwlock sync.RWMutex +} + +var AssumeIPStable bool = true + +var db = translationsDB{} + +func init() { + initTranslationsDB() +} + +func initTranslationsDB() { + db = translationsDB{ + HashToIP: map[string]*translationUnit{}, + HashToNodeNames: map[string][]translationUnit{}, + IPToMethods: map[string][]translationUnit{}, + IPToNodeNames: map[string][]translationUnit{}, + HostPortToNodeNames: map[string][]translationUnit{}, + NodeNameToHostPorts: map[string][]translationUnit{}, + NodeNameToRSNames: map[string][]translationUnit{}, + } +} + +// only useful for tests +func ResetDB() { + initTranslationsDB() +} + +func DBToJson() (string, error) { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + snap := struct { + HashToIP map[string]*translationUnit + HashToNodeNames map[string][]translationUnit + IPToNodeNames map[string][]translationUnit + IPToMethods map[string][]translationUnit + HostPortToNodeNames map[string][]translationUnit + NodeNameToHostPorts map[string][]translationUnit + NodeNameToRSNames map[string][]translationUnit + }{ + HashToIP: db.HashToIP, + HashToNodeNames: db.HashToNodeNames, + IPToNodeNames: db.IPToNodeNames, + IPToMethods: db.IPToMethods, + HostPortToNodeNames: db.HostPortToNodeNames, + NodeNameToHostPorts: db.NodeNameToHostPorts, + NodeNameToRSNames: db.NodeNameToRSNames, + } + out, err := json.MarshalIndent(snap, "", "\t") + return string(out), err +} + +func GetDB() *translationsDB { + return &db +} + +func (tu *translationUnit) UpdateTimestamp(ts time.Time) { + // we want to avoid gap of information, so the earliest proof should be kept + if tu.Timestamp.After(ts) { + tu.Timestamp = ts + } +} + +func AddHashToIP(hash, ip string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + latestValue, ok := db.HashToIP[hash] + if ok && latestValue != nil { + latestValue.UpdateTimestamp(ts) + } else { + db.HashToIP[hash] = &translationUnit{Value: ip, Timestamp: ts} + } +} + +func getLatestValue(m map[string][]translationUnit, key string) *translationUnit { + if len(m[key]) == 0 { + return nil + } + return &m[key][len(m[key])-1] +} + +func upsertToMap(m map[string][]translationUnit, key string, tu translationUnit) { + + latestValue := getLatestValue(m, key) + if latestValue == nil || latestValue.Value != tu.Value { + m[key] = append(m[key], tu) + return + } + // we want to avoid gap of information, so the earliest proof should be kept + if latestValue.Timestamp.After(tu.Timestamp) { + latestValue.Timestamp = tu.Timestamp + } +} + +func AddHashToNodeName(hash, name string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + name = utils.ShortNodeName(name) + upsertToMap(db.HashToNodeNames, hash, translationUnit{Value: name, Timestamp: ts}) +} + +func AddIPToNodeName(ip, name string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + name = utils.ShortNodeName(name) + upsertToMap(db.IPToNodeNames, ip, translationUnit{Value: name, Timestamp: ts}) +} + +func AddIPToMethod(ip, method string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + upsertToMap(db.IPToMethods, ip, translationUnit{Value: method, Timestamp: ts}) +} + +func GetIPFromHash(hash string) string { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + ip, ok := db.HashToIP[hash] + if ok { + return ip.Value + } + return "" +} + +func mostAppropriateValueFromTS(units []translationUnit, ts time.Time) translationUnit { + + if len(units) == 0 { + return translationUnit{} + } + + // We start from the first unit, this ensures we can retroactively use information that were + // seen in the future. + // the first ever information will be the base, then we will override if there is a more recent version + cur := units[0] + for _, unit := range units[1:] { + if unit.Timestamp.After(cur.Timestamp) && (unit.Timestamp.Before(ts) || unit.Timestamp.Equal(ts)) { + cur = unit + } + } + return cur +} + +func GetNodeNameFromHash(hash string, ts time.Time) string { + db.rwlock.RLock() + names := db.HashToNodeNames[hash] + db.rwlock.RUnlock() + return mostAppropriateValueFromTS(names, ts).Value +} + +func GetNodeNameFromIP(ip string, ts time.Time) string { + db.rwlock.RLock() + names := db.IPToNodeNames[ip] + db.rwlock.RUnlock() + return mostAppropriateValueFromTS(names, ts).Value +} + +func GetMethodFromIP(ip string, ts time.Time) string { + db.rwlock.RLock() + methods := db.IPToMethods[ip] + db.rwlock.RUnlock() + return mostAppropriateValueFromTS(methods, ts).Value +} + +func (db *translationsDB) getHashSliceFromIP(ip string) []translationUnit { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + + units := []translationUnit{} + for hash, unit := range db.HashToIP { + if unit.Value == ip { + units = append(units, translationUnit{Value: hash, Timestamp: unit.Timestamp}) + } + } + + sort.Slice(units, func(i, j int) bool { + return units[i].Timestamp.Before(units[j].Timestamp) + }) + return units +} + +func (db *translationsDB) getHashFromIP(ip string, ts time.Time) string { + units := db.getHashSliceFromIP(ip) + return mostAppropriateValueFromTS(units, ts).Value +} + +// SimplestInfoFromIP returns the most human-readable label for a given IP. +// In order of preference: node name, hostname, ip +func SimplestInfoFromIP(ip string, date time.Time) string { + if nodename := GetNodeNameFromIP(ip, date); nodename != "" { + return nodename + } + + // This means we trust the fact that some nodes hashes/names sharing the same IP + // will ultimately be from the same node. On on-premise setups this is safe to assume + if AssumeIPStable { + for _, units := range db.getHashSliceFromIP(ip) { + if nodename := GetNodeNameFromHash(units.Value, date); nodename != "" { + return nodename + } + } + // on k8s setups, we cannot assume this, IPs are reused between nodes. + // we have to strictly use ip=>hash pairs we saw in logs at specific timeframe + } else { + if hash := db.getHashFromIP(ip, date); hash != "" { + if nodename := GetNodeNameFromHash(hash, date); nodename != "" { + return nodename + } + } + } + return ip +} + +func SimplestInfoFromHash(hash string, date time.Time) string { + if nodename := GetNodeNameFromHash(hash, date); nodename != "" { + return nodename + } + + if ip := GetIPFromHash(hash); ip != "" { + return SimplestInfoFromIP(ip, date) + } + return hash +} + +// AddPeerIP records that an IP was seen connecting to a cluster node. +// Unlike AddOwnIP (called on LogCtx), this does not associate the IP with the +// parsing node — it just ensures the IP exists in the DB so whois can find it. +func AddPeerIP(ip string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + if _, ok := db.IPToNodeNames[ip]; !ok { + db.IPToNodeNames[ip] = nil + } +} + +func AddHostPortToNodeName(hostport, name string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + name = utils.ShortNodeName(name) + upsertToMap(db.HostPortToNodeNames, hostport, translationUnit{Value: name, Timestamp: ts}) + upsertToMap(db.NodeNameToHostPorts, name, translationUnit{Value: hostport, Timestamp: ts}) +} + +func AddNodeNameToRSName(nodename, rsname string, ts time.Time) { + db.rwlock.Lock() + defer db.rwlock.Unlock() + nodename = utils.ShortNodeName(nodename) + upsertToMap(db.NodeNameToRSNames, nodename, translationUnit{Value: rsname, Timestamp: ts}) +} + +func GetNodeNameFromHostPort(hostport string, ts time.Time) string { + db.rwlock.RLock() + names := db.HostPortToNodeNames[hostport] + db.rwlock.RUnlock() + return mostAppropriateValueFromTS(names, ts).Value +} + +func GetHostPortsFromNodeName(name string, ts time.Time) []string { + db.rwlock.RLock() + units := db.NodeNameToHostPorts[name] + db.rwlock.RUnlock() + var out []string + for _, u := range units { + out = append(out, u.Value) + } + return out +} + +func GetRSNameFromNodeName(name string, ts time.Time) string { + db.rwlock.RLock() + units := db.NodeNameToRSNames[name] + db.rwlock.RUnlock() + return mostAppropriateValueFromTS(units, ts).Value +} + +func IsHostPortKnown(hp string) bool { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + _, ok := db.HostPortToNodeNames[hp] + return ok +} + +func IsNodeUUIDKnown(uuid string) bool { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + + _, ok := db.HashToIP[uuid] + if ok { + return true + } + _, ok = db.HashToNodeNames[uuid] + return ok +} + +func IsNodeNameKnown(name string) bool { + db.rwlock.RLock() + defer db.rwlock.RUnlock() + + if _, ok := db.NodeNameToHostPorts[name]; ok { + return true + } + if _, ok := db.NodeNameToRSNames[name]; ok { + return true + } + for _, nodenames := range db.HashToNodeNames { + for _, nodename := range nodenames { + if name == nodename.Value { + return true + } + } + } + for _, nodenames := range db.IPToNodeNames { + for _, nodename := range nodenames { + if name == nodename.Value { + return true + } + } + } + for _, nodenames := range db.HostPortToNodeNames { + for _, nodename := range nodenames { + if name == nodename.Value { + return true + } + } + } + return false +} diff --git a/src/go/pt-mongo-log-explainer/translate/whois.go b/src/go/pt-mongo-log-explainer/translate/whois.go new file mode 100644 index 000000000..0422f31f8 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/translate/whois.go @@ -0,0 +1,255 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package translate + +import ( + "encoding/json" + "strings" + "time" + + "cmp" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/xlab/treeprint" + "golang.org/x/exp/slices" +) + +// isSharedName returns true for names that are shared across multiple nodes +// and would bridge unrelated identities in the whois tree (e.g. "listen:27017" +// is common to every mongod on that port, "rs:rs0" is common to every member +// of the replica set). +func isSharedName(name string) bool { + return strings.HasPrefix(name, "listen:") || strings.HasPrefix(name, "rs:") +} + +type WhoisNode struct { + parentNode *WhoisNode `json:"-"` + rootNode *WhoisNode `json:"-"` + nodetype string `json:"-"` + Values map[string]WhoisValue // the key here are the actual values stored for this node +} + +type WhoisValue struct { + Timestamp *time.Time `json:"-"` // used internally for sort order; hidden from output + SubNodes map[string]*WhoisNode `json:",omitempty"` // associating the next node to a type of value (uuid, ip, node name) +} + +// When initiating recursion, instead of iterating over maps we should iterate over a fixed order of types +// maps orders are not guaranteed, and there are multiple paths of identifying information +// Forcing the order ultimately helps to provide repeatable output, so it helps with regression tests +// It also helps reducing graph depth, as "nodename" will have most of its information linked to it directly +var forcedIterationOrder = []string{"nodename", "ip", "_id"} + +func Whois(search, searchtype string) *WhoisNode { + w := &WhoisNode{ + nodetype: searchtype, + Values: map[string]WhoisValue{}, + } + w.rootNode = w + w.Values[search] = WhoisValue{SubNodes: map[string]*WhoisNode{}} + w.filter() + return w +} + +func (v WhoisValue) AddChildKey(parentNode *WhoisNode, nodetype, value string, timestamp time.Time) { + child := v.SubNodes[nodetype] + nodeNew := false + if child == nil { + child = &WhoisNode{ + nodetype: nodetype, + rootNode: parentNode.rootNode, + parentNode: parentNode, + Values: map[string]WhoisValue{}, + } + // delaying storage, we have to make sure + // not to store duplicate nodes first to avoid infinite recursion + nodeNew = true + } + ok := child.addKey(value, timestamp) + if nodeNew && ok { + v.SubNodes[nodetype] = child + } +} + +func (n *WhoisNode) MarshalJSON() ([]byte, error) { + return json.Marshal(n.Values) +} + +func (n *WhoisNode) String() string { + return n.tree().String() +} + +func (n *WhoisNode) tree() treeprint.Tree { + root := treeprint.NewWithRoot(utils.Paint(utils.GreenText, n.nodetype) + ":") + for _, value := range n.valuesSortedByTimestamps() { + valueData := n.Values[value] + str := value + if len(valueData.SubNodes) == 0 { + root.AddNode(str) + continue + } + subtree := root.AddBranch(str) + + // forcing map iteration for repeatable outputs + for _, subNodeType := range forcedIterationOrder { + subnode, ok := valueData.SubNodes[subNodeType] + if ok { + subtree.AddNode(subnode.tree()) + } + } + } + return root +} + +func (n *WhoisNode) valuesSortedByTimestamps() []string { + values := []string{} + for value := range n.Values { + values = append(values, value) + } + + // keep nil timestamps at the top + slices.SortFunc(values, func(a, b string) int { + va, vb := n.Values[a].Timestamp, n.Values[b].Timestamp + switch { + case va == nil && vb == nil: + return cmp.Compare(a, b) + case va == nil: + return -1 // nil < non-nil + case vb == nil: + return 1 // non-nil > nil + default: + if va.Before(*vb) { + return -1 + } + if va.After(*vb) { + return 1 + } + return cmp.Compare(a, b) + } + }) + return values +} + +func (n *WhoisNode) addKey(value string, timestamp time.Time) bool { + storedValue := n.rootNode.GetValueData(value, n.nodetype) + if storedValue != nil { + if storedValue.Timestamp != nil && storedValue.Timestamp.Before(timestamp) { + storedValue.Timestamp = ×tamp + } + return false + } + n.Values[value] = WhoisValue{Timestamp: ×tamp, SubNodes: map[string]*WhoisNode{}} + return true +} + +func (n *WhoisNode) GetValueData(search, searchType string) *WhoisValue { + for value, valueData := range n.Values { + if n.nodetype == searchType && search == value { + return &valueData + } + // iterating over subnodes here is fine, as the value we search for should be unique + // so the way to access don't have to be forced + for _, nextNode := range valueData.SubNodes { + if nextNode != nil { + if valueData := nextNode.GetValueData(search, searchType); valueData != nil { + return valueData + } + } + } + } + return nil +} + +func (n *WhoisNode) filter() { + switch n.nodetype { + case "ip": + n.filterDBUsingIP() + case "_id": + n.FilterDBUsingUUID() + case "nodename": + n.FilterDBUsingNodeName() + } + + for _, valueData := range n.Values { + // see comment on "forcedIterationOrder" + for _, nextNodeType := range forcedIterationOrder { + nextNode := valueData.SubNodes[nextNodeType] + if nextNode != nil { + nextNode.filter() + } + } + } +} + +func (n *WhoisNode) filterDBUsingIP() { + for ip, valueData := range n.Values { + for hash, ip2 := range db.HashToIP { + if ip == ip2.Value { + valueData.AddChildKey(n, "_id", hash, ip2.Timestamp) + } + } + nodenames, ok := db.IPToNodeNames[ip] + if ok { + for _, nodename := range nodenames { + if isSharedName(nodename.Value) { + continue + } + valueData.AddChildKey(n, "nodename", nodename.Value, nodename.Timestamp) + } + } + } + + return +} + +func (n *WhoisNode) FilterDBUsingUUID() { + for uuid, valueData := range n.Values { + nodenames, ok := db.HashToNodeNames[uuid] + if ok { + for _, nodename := range nodenames { + valueData.AddChildKey(n, "nodename", nodename.Value, nodename.Timestamp) + } + } + ip, ok := db.HashToIP[uuid] + if ok { + valueData.AddChildKey(n, "ip", ip.Value, ip.Timestamp) + } + } + + return +} + +func (n *WhoisNode) FilterDBUsingNodeName() { + for nodename, valueData := range n.Values { + if nodename == "unspecified" || isSharedName(nodename) { + continue + } + for uuid, nodenames2 := range db.HashToNodeNames { + for _, nodename2 := range nodenames2 { + if nodename == nodename2.Value { + valueData.AddChildKey(n, "_id", uuid, nodename2.Timestamp) + } + } + } + for ip, nodenames2 := range db.IPToNodeNames { + for _, nodename2 := range nodenames2 { + if nodename == nodename2.Value { + valueData.AddChildKey(n, "ip", ip, nodename2.Timestamp) + } + } + } + } + + return +} diff --git a/src/go/pt-mongo-log-explainer/types/logctx.go b/src/go/pt-mongo-log-explainer/types/logctx.go new file mode 100644 index 000000000..47620f6a1 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/logctx.go @@ -0,0 +1,146 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import ( + "encoding/json" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +// LogCtx is the main context storage for a node. +// It is the principal storage of this tool, this is the source of truth to merge logs and take decisions +// It is stored along with each single log line we matched, and copied for each new log line. +// It is NOT meant to be used as a singleton by pointer, it must keep its original state for each log lines +// If not, every information would be overwritten (states, version, membercount, ...) and we would not be able to give the history of changes +type LogCtx struct { + FilePath string + FileType string + OwnIPs []string + OwnHashes []string + OwnNames []string + state string + Version string + OperatorMetadata *OperatorMetadata + + MyIdx string + MemberCount int + minVerbosity Verbosity +} + +func NewLogCtx() LogCtx { + return LogCtx{minVerbosity: Debug} +} + +// State returns the last known replica-set member state parsed from mongod logs. +func (logCtx LogCtx) State() string { + return logCtx.state +} + +func (logCtx *LogCtx) SetState(s string) { + valid := []string{ + "PRIMARY", "SECONDARY", "ARBITER", "STARTUP", "STARTUP2", + "RECOVERING", "ROLLBACK", "REMOVED", "DOWN", + } + if !utils.SliceContains(valid, s) { + return + } + logCtx.state = s +} + +func (logCtx *LogCtx) HasVisibleEvents(level Verbosity) bool { + return level >= logCtx.minVerbosity +} + +func (logCtx *LogCtx) IsPrimary() bool { + return logCtx.State() == "PRIMARY" +} + +// AddOwnName propagates a name into the translation maps using the trusted node's known own hashes and ips +func (logCtx *LogCtx) AddOwnName(name string, date time.Time) { + name = utils.ShortNodeName(name) + if len(logCtx.OwnNames) > 0 && logCtx.OwnNames[len(logCtx.OwnNames)-1] == name { + return + } + logCtx.OwnNames = append(logCtx.OwnNames, name) + + if lenIPs := len(logCtx.OwnIPs); lenIPs > 0 { + translate.AddIPToNodeName(logCtx.OwnIPs[lenIPs-1], name, date) + } +} + +// AddOwnHash propagates a hash into the translation maps +func (logCtx *LogCtx) AddOwnHash(hash string, date time.Time) { + if utils.SliceContains(logCtx.OwnHashes, hash) { + return + } + logCtx.OwnHashes = append(logCtx.OwnHashes, hash) + + if lenIPs := len(logCtx.OwnIPs); lenIPs > 0 { + translate.AddHashToIP(hash, logCtx.OwnIPs[lenIPs-1], date) + } + if lenNodeNames := len(logCtx.OwnNames); lenNodeNames > 0 { + translate.AddHashToNodeName(hash, logCtx.OwnNames[lenNodeNames-1], date) + } +} + +// AddOwnIP propagates an ip into the translation maps +func (logCtx *LogCtx) AddOwnIP(ip string, date time.Time) { + if len(logCtx.OwnIPs) > 0 && logCtx.OwnIPs[len(logCtx.OwnIPs)-1] == ip { + return + } + logCtx.OwnIPs = append(logCtx.OwnIPs, ip) + + if lenNodeNames := len(logCtx.OwnNames); lenNodeNames > 0 { + translate.AddIPToNodeName(ip, logCtx.OwnNames[lenNodeNames-1], date) + } +} + +// 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. +func (base *LogCtx) Inherit(logCtx LogCtx) { + base.OwnHashes = append(logCtx.OwnHashes, base.OwnHashes...) + base.OwnNames = append(logCtx.OwnNames, base.OwnNames...) + base.OwnIPs = append(logCtx.OwnIPs, base.OwnIPs...) + if base.Version == "" { + base.Version = logCtx.Version + } +} + +func (logCtx *LogCtx) MarshalJSON() ([]byte, error) { + return json.Marshal(struct { + FilePath string + FileType string + OwnIPs []string + OwnHashes []string + OwnNames []string + State string + Version string + MyIdx string + MemberCount int + MinVerbosity Verbosity + }{ + FilePath: logCtx.FilePath, + FileType: logCtx.FileType, + OwnIPs: logCtx.OwnIPs, + OwnHashes: logCtx.OwnHashes, + State: logCtx.state, + Version: logCtx.Version, + MyIdx: logCtx.MyIdx, + MemberCount: logCtx.MemberCount, + MinVerbosity: logCtx.minVerbosity, + }) +} diff --git a/src/go/pt-mongo-log-explainer/types/loginfo.go b/src/go/pt-mongo-log-explainer/types/loginfo.go new file mode 100644 index 000000000..72ee4af28 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/loginfo.go @@ -0,0 +1,121 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import ( + "fmt" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" +) + +type Verbosity int + +const ( + Info Verbosity = iota + // DebugContext includes findings that are usually not relevant to show but useful to create the log context (eg: how we found the local address) + DebugContext + 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 + LogCtx 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, logCtx LogCtx, filetype string) LogInfo { + li := LogInfo{ + Date: date, + Log: log, + displayer: displayer, + LogCtx: logCtx, + RegexType: regex.Type, + RegexUsed: regexkey, + Verbosity: regex.Verbosity, + extraNotes: map[string]string{}, + } + if filetype != MongoLogFileType && filetype != "" { + li.extraNotes["filetype"] = filetype + } + return li +} + +func (li *LogInfo) Msg(logCtx 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(logCtx) + for _, note := range li.extraNotes { + msg += utils.Paint(utils.BlueText, fmt.Sprintf("(%s)", note)) + } + return msg +} + +// IsDuplicatedEvent will aim to keep 2 occurrences 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.LogCtx) == previous.displayer(previous.LogCtx) && + previous.RegexUsed == current.RegexUsed && + previous.displayer(previous.LogCtx) == current.displayer(current.LogCtx) +} + +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 } +} + +func FormatByIPDisplayer(layout, ip string, date time.Time) LogDisplayer { + return func(_ LogCtx) string { + return fmt.Sprintf(layout, translate.SimplestInfoFromIP(ip, date)) + } +} + +func FormatByHashDisplayer(layout, hash string, date time.Time) LogDisplayer { + return func(_ LogCtx) string { + return fmt.Sprintf(layout, translate.SimplestInfoFromHash(hash, date)) + } +} diff --git a/src/go/pt-mongo-log-explainer/types/nodeinfo.go b/src/go/pt-mongo-log-explainer/types/nodeinfo.go new file mode 100644 index 000000000..4bd5df462 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/nodeinfo.go @@ -0,0 +1,21 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +type WhoisOutput struct { + Input string `json:"input"` + IPs []string `json:"IPs"` + NodeNames []string `json:"nodeNames"` + MemberIDs []string `json:"memberIDs"` +} diff --git a/src/go/pt-mongo-log-explainer/types/operator.go b/src/go/pt-mongo-log-explainer/types/operator.go new file mode 100644 index 000000000..094e1272e --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/operator.go @@ -0,0 +1,25 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +const ( + OperatorLogPrefix = `{"log":"` + MongoLogFileType = "mongod.log" +) + +type OperatorMetadata struct { + PodName string + Deployment string + Namespace string +} diff --git a/src/go/pt-mongo-log-explainer/types/regex.go b/src/go/pt-mongo-log-explainer/types/regex.go new file mode 100644 index 000000000..d48086e36 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/regex.go @@ -0,0 +1,105 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import ( + "encoding/json" + "regexp" + "time" +) + +// 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, time.Time) (LogCtx, LogDisplayer) + Verbosity Verbosity // To be able to hide details from summaries +} + +func (l *LogRegex) Handle(logCtx LogCtx, line string, date time.Time) (LogCtx, LogDisplayer) { + if logCtx.minVerbosity > l.Verbosity { + logCtx.minVerbosity = l.Verbosity + } + mergedResults := map[string]string{} + if l.InternalRegex == nil { + return l.Handler(mergedResults, logCtx, line, date) + } + slice := l.InternalRegex.FindStringSubmatch(line) + if len(slice) == 0 { + return logCtx, 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, logCtx, line, date) +} + +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" + ReplicationRegexType RegexType = "replication" + TopologyRegexType RegexType = "topology" + IdentRegexType RegexType = "identity" + StatesRegexType RegexType = "states" + ClusterRegexType RegexType = "cluster" + CustomRegexType RegexType = "custom" +) + +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-mongo-log-explainer/types/structured_event.go b/src/go/pt-mongo-log-explainer/types/structured_event.go new file mode 100644 index 000000000..8977f72ba --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/structured_event.go @@ -0,0 +1,57 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import "time" + +// EventCategory groups events for CLI filters (--elections, --replication, ...). +type EventCategory string + +const ( + CatNode EventCategory = "node" + CatRole EventCategory = "role" + CatTopology EventCategory = "topology" + CatReplication EventCategory = "replication" + CatFailure EventCategory = "failure" + CatSharding EventCategory = "sharding" + CatPerformance EventCategory = "performance" + CatCorrelation EventCategory = "correlation" + CatAnomaly EventCategory = "anomaly" +) + +// EventStatus is a coarse outcome for automation / sorting. +type EventStatus string + +const ( + StatusInfo EventStatus = "INFO" + StatusSuccess EventStatus = "SUCCESS" + StatusWarn EventStatus = "WARN" + StatusFailure EventStatus = "FAILURE" + StatusUnknown EventStatus = "UNKNOWN" +) + +// StructuredEvent is a normalized cluster event for timeline output. +type StructuredEvent struct { + Time time.Time `json:"time"` + Node string `json:"node"` + HostPort string `json:"host_port"` + EventType string `json:"event_type"` + Status EventStatus `json:"status"` + Details string `json:"details"` + Category EventCategory `json:"category"` + SourceFile string `json:"source_file"` + Raw string `json:"raw,omitempty"` + Anomaly string `json:"anomaly,omitempty"` + SequenceID string `json:"sequence_id,omitempty"` +} diff --git a/src/go/pt-mongo-log-explainer/types/timeline.go b/src/go/pt-mongo-log-explainer/types/timeline.go new file mode 100644 index 000000000..dd6b4b8b2 --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/timeline.go @@ -0,0 +1,229 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import ( + "math" + "path/filepath" + "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 occurrences + // 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 + +func (timeline Timeline) MergeByIdentifier(lt LocalTimeline) { + // 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 + node := Identifier(lt[len(lt)-1].LogCtx, getlasttime(lt)) + if lt2, ok := timeline[node]; ok { + lt = MergeTimeline(lt2, lt) + } + timeline[node] = lt +} + +func (timeline Timeline) MergeByDirectory(path string, lt LocalTimeline) { + node := filepath.Base(filepath.Dir(path)) + for _, lt2 := range timeline { + if len(lt2) > 0 && node == filepath.Base(filepath.Dir(lt2[0].LogCtx.FilePath)) { + lt = MergeTimeline(lt2, lt) + break + } + } + timeline[node] = lt +} + +// MergeByPodnameElsePath will try to keep podnames as identifier as it make more sense +// if it does not have any metadata to use, it will resort to file paths +// Merging operator logs is rare, but it happens when following multiple pt-k8s-debug-collector dumps +func (timeline Timeline) MergeByPodnameElsePath(path string, lt LocalTimeline) { + metadata := lt[len(lt)-1].LogCtx.OperatorMetadata + if metadata == nil { + timeline[path] = lt + return + } + for _, lt2 := range timeline { + if len(lt2) == 0 { + continue + } + if metadata2 := lt2[len(lt2)-1].LogCtx.OperatorMetadata; metadata2 != nil && + metadata.PodName == metadata2.PodName && + metadata.Deployment == metadata2.Deployment && + metadata.Namespace == metadata2.Namespace { + + lt = MergeTimeline(lt2, lt) + break + } + } + timeline[metadata.PodName] = lt +} + +// 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 logCtx.inherit + } + + // t1: --O--O------ + // t2: ------O--O-- + t2[len(t2)-1].LogCtx.Inherit(t1[len(t1)-1].LogCtx) + return append(t1, t2...) +} + +func getfirsttime(l LocalTimeline) time.Time { + for _, event := range l { + if event.Date != nil && (event.LogCtx.FileType == MongoLogFileType || event.LogCtx.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].LogCtx.FileType == MongoLogFileType || l[i].LogCtx.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 != nil && t[i].Date.Time.After(at) { + break + } + } + + return t[i:] +} + +func (t *Timeline) GetLatestContextsByNodes() map[string]LogCtx { + latestlogCtxs := make(map[string]LogCtx, len(*t)) + + for key, localtimeline := range *t { + latestlogCtxs[key] = localtimeline[len(localtimeline)-1].LogCtx + } + + return latestlogCtxs +} + +// 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-mongo-log-explainer/types/utils.go b/src/go/pt-mongo-log-explainer/types/utils.go new file mode 100644 index 000000000..23f577a4f --- /dev/null +++ b/src/go/pt-mongo-log-explainer/types/utils.go @@ -0,0 +1,36 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package types + +import ( + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" +) + +// Identifier picks a column header key for a node's timeline (hostname, listen port, IP, etc.). +func Identifier(logCtx LogCtx, date time.Time) string { + if len(logCtx.OwnNames) > 0 { + return logCtx.OwnNames[len(logCtx.OwnNames)-1] + } + if len(logCtx.OwnIPs) > 0 { + return translate.SimplestInfoFromIP(logCtx.OwnIPs[len(logCtx.OwnIPs)-1], date) + } + for _, hash := range logCtx.OwnHashes { + if out := translate.SimplestInfoFromHash(hash, date); out != hash { + return out + } + } + return logCtx.FilePath +} diff --git a/src/go/pt-mongo-log-explainer/utils/utils.go b/src/go/pt-mongo-log-explainer/utils/utils.go new file mode 100644 index 000000000..b662e6d8b --- /dev/null +++ b/src/go/pt-mongo-log-explainer/utils/utils.go @@ -0,0 +1,164 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package utils + +import ( + "fmt" + "hash/fnv" + "strings" + + "k8s.io/utils/net" +) + +// Color is given its own type for safe function signatures +type Color string + +// Color codes interpreted 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 + } + if color == "" { + return value + } + return fmt.Sprintf("%v%v%v", color, value, ResetText) +} + +// distinctNodeColors assigns a stable, distinct color per node label for multi-column views. +var distinctNodeColors = []Color{ + BrightCyanText, BrightMagentaText, BrightBlueText, BrightGreenText, BrightYellowText, BrightWhiteText, +} + +// NodeHue returns a terminal color for a node identifier (hostname / short name). +func NodeHue(label string) Color { + if label == "" || label == "-" { + return WhiteText + } + h := fnv.New32a() + _, _ = h.Write([]byte(label)) + return distinctNodeColors[h.Sum32()%uint32(len(distinctNodeColors))] +} + +func PaintForState(text, state string) string { + + c := ColorForState(state) + if c != "" { + return Paint(colorsToTextColor[c], text) + } + + return text +} + +func ColorForState(state string) string { + switch strings.ToUpper(state) { + case "ROLLBACK", "STARTUP", "STARTUP2", "RECOVERING", "ARBITER": + return "yellow" + case "PRIMARY", "SECONDARY": + return "green" + case "DOWN", "REMOVED", "UNKNOWN": + 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 { + split := strings.Split(uuid, "-") + if len(split) != 5 { + return uuid + } + return split[0] + "-" + split[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 + } + // for the rare case of having IPs set as node names + if net.IsIPv4String(s) { + return s + } + before, _, _ := strings.Cut(s, ".") + return before +} diff --git a/src/go/pt-mongo-log-explainer/whois.go b/src/go/pt-mongo-log-explainer/whois.go new file mode 100644 index 000000000..2d4ccb9fe --- /dev/null +++ b/src/go/pt-mongo-log-explainer/whois.go @@ -0,0 +1,148 @@ +// This program is copyright 2023-2026 Percona LLC and/or its affiliates. +// +// THIS PROGRAM IS PROVIDED "AS IS" AND WITHOUT ANY EXPRESS OR IMPLIED +// WARRANTIES, INCLUDING, WITHOUT LIMITATION, THE IMPLIED WARRANTIES OF +// MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. +// +// This program is free software; you can redistribute it and/or modify it under +// the terms of the GNU General Public License as published by the Free Software +// Foundation, version 2. +// +// You should have received a copy of the GNU General Public License, version 2 +// along with this program; if not, see . + +package main + +import ( + "encoding/json" + "fmt" + "strings" + "time" + + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/collect" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/parser" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/regex" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/translate" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/types" + "github.com/percona/percona-toolkit/src/go/pt-mongo-log-explainer/utils" + "github.com/pkg/errors" + "github.com/rs/zerolog/log" +) + +type whois struct { + Search string `arg:"" name:"search" help:"the identifier (node name, ip, host:port, _id) to search"` + SearchType string `name:"type" help:"Kind of input: nodename, ip, hostport, _id. Auto-detected when possible." enum:"nodename,ip,hostport,_id,auto" default:"auto"` + Paths []string `arg:"" name:"paths" help:"paths of the log to use"` + Json bool +} + +func (w *whois) Help() string { + return fmt.Sprintf(`Resolve a hostname, host:port, IPv4, or member _id seen in mongod/mongos logs +into related names, addresses, replica sets, and ports discovered while scanning. + +Usage: + %[1]s whois 'mongo-rs0-0' *.log + %[1]s whois '192.168.1.10' *.log + %[1]s whois 'mongo-rs0-0:27017' --type hostport *.log + %[1]s whois '0' --type _id *.log +`, toolname) +} + +func (w *whois) Run() error { + if w.SearchType == "auto" { + detectAndNormalizeSearch(w) + } + + // Phase 1: run the grep/regex pipeline to populate the translate DB. + _, regexErr := timelineFromPaths(CLI.Whois.Paths, regex.AllRegexes()) + + // Phase 2: run the structured parser pipeline to extract richer MongoDB identity. + w.scanWithParser() + + if regexErr != nil && !translate.IsNodeNameKnown(w.Search) && !translate.IsNodeUUIDKnown(w.Search) && !translate.IsHostPortKnown(w.Search) { + return errors.Wrap(regexErr, "found nothing to translate") + } + + // Post-scan auto-detection for ambiguous 8-char inputs. + if w.SearchType == "auto" { + w.SearchType = resolveAmbiguous(w.Search) + if w.SearchType == "" { + return errors.New("could not detect the type of input. Try to provide --type. It may mean the info is unknown") + } + } + + if CLI.Verbosity == types.Debug { + out, err := translate.DBToJson() + if err != nil { + return errors.Wrap(err, "could not dump translation structs to json") + } + fmt.Println(out) + } + + log.Debug().Str("searchType", w.SearchType).Msg("whois searchType") + + out := translate.Whois(w.Search, w.SearchType) + + if w.Json { + j, err := json.MarshalIndent(out, "", "\t") + if err != nil { + return err + } + fmt.Println(string(j)) + } else { + fmt.Println(out) + } + return nil +} + +func detectAndNormalizeSearch(w *whois) { + switch { + case regex.IsMongoObjectID(w.Search): + w.Search = strings.ToLower(w.Search) + w.SearchType = "_id" + case regex.IsNodeUUID(w.Search): + w.Search = utils.UUIDToShortUUID(w.Search) + w.SearchType = "_id" + case regex.IsNodeIP(w.Search): + w.SearchType = "ip" + case strings.Contains(w.Search, ":"): + w.SearchType = "hostport" + case len(w.Search) != 8: + w.SearchType = "nodename" + default: + log.Info().Msg("input type is ambiguous; scanning files. Use --type to force nodename|ip|hostport|_id") + } +} + +func resolveAmbiguous(search string) string { + if translate.IsNodeUUIDKnown(search) { + return "_id" + } + if translate.IsNodeNameKnown(search) { + return "nodename" + } + if translate.IsHostPortKnown(search) { + return "hostport" + } + return "" +} + +// scanWithParser runs the structured parser over every log file to populate the +// translate DB with MongoDB-specific identity (hostname, host:port, replica set). +func (w *whois) scanWithParser() { + for _, path := range w.Paths { + ctx := &parser.ScanContext{} + var lastTS time.Time + _ = collect.ForEachLine(path, CLI.GrepCmd, false, func(line string) error { + ev := parser.ParseLine(path, line, ctx) + if ev != nil && !ev.Time.IsZero() { + lastTS = ev.Time + } + return nil + }) + if lastTS.IsZero() { + lastTS = time.Now() + } + ctx.FlushToTranslateDB(lastTS) + } +}