From 1a0426708143508845211c52c5cdce6beb547c2e Mon Sep 17 00:00:00 2001 From: Robert Cowham Date: Tue, 11 Jun 2024 18:51:14 +0100 Subject: [PATCH] Mark various lines as block ends and ignore them --- p4dlog.go | 35 +++++++++++++++++++++++++++++++---- p4dlog_test.go | 38 ++++++++++++++++++++++++++++++++++++-- 2 files changed, 67 insertions(+), 6 deletions(-) diff --git a/p4dlog.go b/p4dlog.go index 24db492..93b6415 100644 --- a/p4dlog.go +++ b/p4dlog.go @@ -1948,12 +1948,20 @@ func blankLine(line string) bool { return len(line) == 0 } +// Basic strings which start/end a block var blockEnds = []string{ "Perforce server info:", "Perforce server error:", - "locks acquired by blocking after", +} + +// Various line prefixes that both can end a block, and should be ignored - see ignoreLine +var BlockEndPrefixes = []string{ "Rpc himark:", - "server to client"} + "server to client", + "server to inter", + "Forwarder set trusted client address", + "NetSslTransport::SendOrReceive", // Optional configurable +} var msgActiveThreads = " active threads." var reServerThreads = regexp.MustCompile(`^\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d \d+ pid (\d+): Server is now using (\d+) active threads.`) @@ -1967,6 +1975,11 @@ func blockEnd(line string) bool { return true } } + for _, str := range BlockEndPrefixes { + if strings.HasPrefix(line, str) { + return true + } + } if strings.HasSuffix(line, msgActiveThreads) { // OK to do a regex as does occur frequently if m := reServerThreads.FindStringSubmatch(line); len(m) > 0 { return true @@ -1975,6 +1988,16 @@ func blockEnd(line string) bool { return false } +// Lines to be ignored and not added to blocks +func ignoreLine(line string) bool { + for _, str := range BlockEndPrefixes { + if strings.HasPrefix(line, str) { + return true + } + } + return false +} + // CmdsPendingCount - count of unmatched commands func (fp *P4dFileParser) CmdsPendingCount() int { fp.m.Lock() @@ -2050,9 +2073,13 @@ func (fp *P4dFileParser) LogParser(ctx context.Context, linesChan <-chan string, } } block = new(Block) - block.addLine(line, fp.lineNo) + if !ignoreLine(line) { + block.addLine(line, fp.lineNo) + } } else { - block.addLine(line, fp.lineNo) + if !ignoreLine(line) { + block.addLine(line, fp.lineNo) + } } fp.lineNo++ } else { diff --git a/p4dlog_test.go b/p4dlog_test.go index 27214af..f5e7094 100644 --- a/p4dlog_test.go +++ b/p4dlog_test.go @@ -891,8 +891,6 @@ locks acquired by blocking after 3 non-blocking attempts //assert.Equal(t, "", output[0]) assert.JSONEq(t, cleanJSON(`{"processKey":"f7d483631e94d16adde6c5306be15fbe","cmd":"user-revert","pid":22245,"lineNo":2,"user":"auto","workspace":"archive_auto","completedLapse":6.92,"ip":"127.0.0.1","app":"archive/v60","args":"/usr/local/arch/datastore/...","startTime":"2018/09/06 06:00:02","endTime":"2018/09/06 06:00:02","running":1,"uCpu":6901,"sCpu":4,"diskIn":32,"diskOut":8,"maxRss":19996,"cmdError":false,"tables":[{"tableName":"protect","totalReadWait":4,"totalReadHeld":6875,"totalWriteWait":5,"totalWriteHeld":6},{"tableName":"resolve","totalReadWait":23792,"totalReadHeld":3,"totalWriteWait":2,"totalWriteHeld":1,"maxReadWait":23792,"maxReadHeld":3,"maxWriteWait":2,"maxWriteHeld":1}]}`), cleanJSON(output[0])) - assert.JSONEq(t, cleanJSON(`{"processKey":"f7d483631e94d16adde6c5306be15fbe","cmd":"user-revert","pid":22245,"lineNo":2,"user":"auto","workspace":"archive_auto","completedLapse":6.92,"ip":"127.0.0.1","app":"archive/v60","args":"/usr/local/arch/datastore/...","startTime":"2018/09/06 06:00:02","endTime":"2018/09/06 06:00:02","running":1,"uCpu":6901,"sCpu":4,"diskIn":32,"diskOut":8,"maxRss":19996,"cmdError":false,"tables":[{"tableName":"protect","totalReadWait":4,"totalReadHeld":6875,"totalWriteWait":5,"totalWriteHeld":6},{"tableName":"resolve","totalReadWait":23792,"totalReadHeld":3,"totalWriteWait":2,"totalWriteHeld":1,"maxReadWait":23792,"maxReadHeld":3,"maxWriteWait":2,"maxWriteHeld":1}]}`), - cleanJSON(output[0])) } func TestTriggers(t *testing.T) { @@ -1272,3 +1270,39 @@ Perforce server info: assert.JSONEq(t, cleanJSON(`{"app":"Git Fusion/2017.1.SNAPSHOT/1778910 (2019/04/01)/v82 (brokered)", "args":"git-fusion-auth-keys-last-changenum-gfprod3", "cmd":"user-key", "cmdError":true, "completedLapse":0.002, "diskOut":8, "endTime":"2024/06/10 06:12:03", "ip":"127.0.0.1/10.5.40.30", "lineNo":2, "maxRss":13876, "memMB":30, "memPeakMB":30, "pid":1.837049e+06, "processKey":"e60035bfd064b9c153c732d3b6a9206a", "rpcHimarkFwd":97604, "rpcHimarkRev":318788, "rpcMsgsOut":1, "running":1, "sCpu":1, "startTime":"2024/06/10 06:12:03", "uCpu":1, "user":"git-fusion-user", "workspace":"git-fusion--gfprod3-076a3fa2-272b-11ef-8240-0050568421b4","tables":[]}`), cleanJSON(output[0])) } + +func TestTriggerLapse(t *testing.T) { + testInput := ` +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' + +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' trigger JIRAUpdater +lapse .149s + +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' trigger swarm +lapse .044s +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' +--- storageup/storageup(R) +--- total lock wait+held read/write 0ms+60ms/0ms+0ms + +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' +--- storageup/storagemasterup(R) +--- total lock wait+held read/write 0ms+60ms/0ms+0ms + +Perforce server info: + 2024/06/09 22:16:38 pid 485300 completed .216s 38+10us 288+704io 0+0net 18476k 0pf +Perforce server info: + 2024/06/09 22:16:38 pid 485300 p4dtguser@p4dtgprod20 127.0.0.1/10.5.53.61 [p4jobdt/v93 (brokered)] 'user-job -i' +--- lapse .216s +--- usage 38+10us 288+712io 0+0net 18476k 0pf +--- memory cmd/proc 31mb/32mb` + output := parseLogLines(testInput) + assert.Equal(t, 1, len(output)) + // assert.Equal(t, "", output[0]) + assert.JSONEq(t, cleanJSON(`{"app":"p4jobdt/v93 (brokered)", "args":"-i", "cmd":"user-job", "cmdError":false, "completedLapse":0.216, "diskIn":288, "diskOut":712, "endTime":"2024/06/09 22:16:38", "ip":"127.0.0.1/10.5.53.61", "lineNo":2, "maxRss":18476, "memMB":31, "memPeakMB":32, "pid":485300, "processKey":"f59cacda1499ad10dd54d6fae994530b", "running":1, "sCpu":10, "startTime":"2024/06/09 22:16:38", "tables":[{"tableName":"storagemasterup_R", "totalReadHeld":60}, {"tableName":"storageup_R", "totalReadHeld":60}, {"tableName":"trigger_JIRAUpdater", "triggerLapse":0.149}, {"tableName":"trigger_swarm", "triggerLapse":0.044}], "uCpu":38, "user":"p4dtguser", "workspace":"p4dtgprod20"}`), + cleanJSON(output[0])) +}