diff --git a/README.md b/README.md index 3227234..b61659c 100644 --- a/README.md +++ b/README.md @@ -2,9 +2,7 @@ To visualize what BOSH is busy doing during a task. -It's taking an after-the-fact approach at profiling by reading the debug logs and pretending it knows what BOSH was thinking while it happened. You probably shouldn't fully trust the accuracy of the results. - -alpha/experiment/buggy/use-at-your-own-risk +It's taking an after-the-fact approach at profiling by reading logs and pretending it knows what BOSH was thinking while it happened. You probably shouldn't fully trust the accuracy of the results. ## Quick Start @@ -29,6 +27,19 @@ Provide the debug log of a deploy task via `STDIN`... Open the URL it prints (something like http://localhost:16686/trace/1cfa67194cc4d8ef). +## Caveats + +alpha/experiment/buggy/use-at-your-own-risk; also: + + * alpha (pre-alpha?) + * experiment / proof of concept; worth pursuing more? get in touch + * currently only works with deploy tasks + * not tested with failed tasks + * not tested across diverse environments + * don't expect the code to easily make sense right now + * relevant log lines are included in traces and may include sensitive data + + ## Screenshot ![Screenshot](docs/example.png) diff --git a/cmd/taskdebugdebug/main.go b/cmd/taskdebugdebug/main.go index 8b4b1e5..9460e9f 100644 --- a/cmd/taskdebugdebug/main.go +++ b/cmd/taskdebugdebug/main.go @@ -5,15 +5,11 @@ import ( "os" "github.com/dpb587/bosh-log-tracer/log" - "github.com/dpb587/bosh-log-tracer/log/taskdebug" + "github.com/dpb587/bosh-log-tracer/log/taskdebug/parser" "github.com/dpb587/bosh-log-tracer/observer/debug" ) func main() { - var err error - - parsers := taskdebug.Parser - observer := debug.NewObserver() observer.Begin() defer observer.Commit() @@ -31,14 +27,12 @@ func main() { RawLineData: scanner.Text(), } - for _, p := range parsers { - l, err = p.Parse(l) - if err != nil { - panic(err) - } + l, err := parser.Parser.Parse(l) + if err != nil { + panic(err) } - err := observer.Handle(l) + err = observer.Handle(l) if err != nil { panic(err) } diff --git a/cmd/taskdebugjaeger/main.go b/cmd/taskdebugjaeger/main.go index e5da8bc..49c1a77 100644 --- a/cmd/taskdebugjaeger/main.go +++ b/cmd/taskdebugjaeger/main.go @@ -5,16 +5,13 @@ import ( "os" "github.com/dpb587/bosh-log-tracer/log" - "github.com/dpb587/bosh-log-tracer/log/taskdebug" "github.com/dpb587/bosh-log-tracer/log/taskdebug/jaeger" + "github.com/dpb587/bosh-log-tracer/log/taskdebug/parser" "github.com/dpb587/bosh-log-tracer/observer/context" ) func main() { - var err error - ctx := &context.Context{} - parsers := taskdebug.Parser observer := jaeger.NewObserver(ctx, jaeger.ObserverOptions{ IncludeLogReferences: true, @@ -35,14 +32,12 @@ func main() { RawLineData: scanner.Text(), } - for _, p := range parsers { - l, err = p.Parse(l) - if err != nil { - panic(err) - } + l, err := parser.Parser.Parse(l) + if err != nil { + panic(err) } - err := observer.Handle(l) + err = observer.Handle(l) if err != nil { panic(err) } diff --git a/log/multi.go b/log/multi.go new file mode 100644 index 0000000..03dca16 --- /dev/null +++ b/log/multi.go @@ -0,0 +1,28 @@ +package log + +type multiParser struct { + parsers []LineParser +} + +var _ LineParser = &multiParser{} + +func NewMultiParser(parsers ...LineParser) LineParser { + return &multiParser{ + parsers: parsers, + } +} + +func (lp multiParser) Parse(in Line) (Line, error) { + var err error + + out := in + + for _, p := range lp.parsers { + out, err = p.Parse(out) + if err != nil { + return nil, err + } + } + + return out, nil +} diff --git a/log/taskdebug/cpi_aws_rpc.go b/log/taskdebug/cpi_aws_rpc.go index f3c3160..1205b3b 100644 --- a/log/taskdebug/cpi_aws_rpc.go +++ b/log/taskdebug/cpi_aws_rpc.go @@ -1,18 +1,11 @@ package taskdebug import ( - "regexp" - "strconv" - "strings" "time" "github.com/dpb587/bosh-log-tracer/log" ) -var CPIAWSRPCParser = cpiAWSRPCParser{} - -type cpiAWSRPCParser struct{} - type CPIAWSRPCMessage struct { RawMessage @@ -24,42 +17,4 @@ type CPIAWSRPCMessage struct { PayloadMethod string } -// [Aws::EC2::Client 200 1.069542 0 retries] run_instances(... -var cpiAWSRPCOneRE = regexp.MustCompile(`^\[Aws::EC2::Client (\d+) ([\d\.]+) (\d) retries\] (.+)$`) - -func (p cpiAWSRPCParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "ExternalCpiLog" { - return inU, nil - } - - if m := cpiAWSRPCOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - out := CPIAWSRPCMessage{ - RawMessage: in, - Correlation: in.Tags["req_id"], - Payload: m[4], - } - - out.PayloadMethod = strings.SplitN(out.Payload, "(", 2)[0] - - if res, err := strconv.ParseFloat(m[2], 64); err == nil { - out.Duration = time.Duration(int64(res * 1000000)) - } - - if res, err := strconv.Atoi(m[1]); err == nil { - out.StatusCode = res - } - - if res, err := strconv.Atoi(m[3]); err == nil { - out.Retries = res - } - - return out, nil - } - - return inU, nil -} +var _ log.Line = &CPIAWSRPCMessage{} diff --git a/log/taskdebug/external_cpi.go b/log/taskdebug/external_cpi.go index aac044a..0c18180 100644 --- a/log/taskdebug/external_cpi.go +++ b/log/taskdebug/external_cpi.go @@ -1,14 +1,6 @@ package taskdebug -import ( - "regexp" - - "github.com/dpb587/bosh-log-tracer/log" -) - -var ExternalCPIParser = externalCPIParser{} - -type externalCPIParser struct{} +import "github.com/dpb587/bosh-log-tracer/log" type ExternalCPIMessage struct { RawMessage @@ -18,29 +10,4 @@ type ExternalCPIMessage struct { Remaining string } -// [external-cpi] [cpi-308955] request: {"method":"create_vm","arguments":[... -var externalCPIOneRE = regexp.MustCompile(`^\[external-cpi\] \[(cpi-\d+)\] (request|response): (.+)$`) - -func (p externalCPIParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := externalCPIOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - out := ExternalCPIMessage{ - RawMessage: in, - Correlation: m[1], - Event: m[2], - Remaining: m[3], - } - - return out, nil - } - - return inU, nil -} +var _ log.Line = &ExternalCPIMessage{} diff --git a/log/taskdebug/external_cpi_request.go b/log/taskdebug/external_cpi_request.go index 372884c..fe2c6f1 100644 --- a/log/taskdebug/external_cpi_request.go +++ b/log/taskdebug/external_cpi_request.go @@ -1,15 +1,6 @@ package taskdebug -import ( - "encoding/json" - "regexp" - - "github.com/dpb587/bosh-log-tracer/log" -) - -var ExternalCPIRequestParser = externalCPIRequestParser{} - -type externalCPIRequestParser struct{} +import "github.com/dpb587/bosh-log-tracer/log" type ExternalCPIRequestMessage struct { ExternalCPIMessage @@ -19,51 +10,4 @@ type ExternalCPIRequestMessage struct { Command string } -// [external-cpi] [cpi-308955] request: {"method":"create_vm","arguments":[... -var externalCPIRequestOneRE = regexp.MustCompile(`(\{.+\}) with command: (.+)$`) - -func (p externalCPIRequestParser) Parse(inU log.Line) (log.Line, error) { - inU, err := ExternalCPIParser.Parse(inU) - if inU == nil || err != nil { - return inU, err - } - - in, ok := inU.(ExternalCPIMessage) - if !ok { - return inU, nil - } - - upstreamU, err := ExternalCPIParser.Parse(in) - if upstreamU == nil || err != nil { - return upstreamU, err - } - - upstream := upstreamU.(ExternalCPIMessage) - - if upstream.Event != "request" { - return upstream, nil - } - - if m := externalCPIRequestOneRE.FindStringSubmatch(upstream.Remaining); len(m) > 0 { - out := ExternalCPIRequestMessage{ - ExternalCPIMessage: upstream, - Payload: m[1], - Command: m[2], - } - - var payload struct { - Method string `json:"method"` - } - - err = json.Unmarshal([]byte(out.Payload), &payload) - if err != nil { - panic(err) - } - - out.PayloadMethod = payload.Method - - return out, nil - } - - return upstreamU, nil -} +var _ log.Line = &ExternalCPIRequestMessage{} diff --git a/log/taskdebug/instance_aspect_changed.go b/log/taskdebug/instance_aspect_changed.go index 041bf13..bb2b37e 100644 --- a/log/taskdebug/instance_aspect_changed.go +++ b/log/taskdebug/instance_aspect_changed.go @@ -3,16 +3,11 @@ package taskdebug import ( "encoding/json" "fmt" - "regexp" "strings" "github.com/dpb587/bosh-log-tracer/log" ) -var InstanceAspectChangedParser = instanceAspectChangedParser{} - -type instanceAspectChangedParser struct{} - type InstanceAspectChangedMessage struct { RawMessage @@ -24,6 +19,8 @@ type InstanceAspectChangedMessage struct { ChangedTo string } +var _ log.Line = &InstanceAspectChangedMessage{} + type packageChangeSet map[string]struct { Name string `json:"name"` Version string `json:"version"` @@ -73,35 +70,3 @@ func (m InstanceAspectChangedMessage) GetChangedPackages() []string { return res } - -var _ log.Line = &InstanceAspectChangedMessage{} - -// stemcell_changed? changed FROM: version: 315.36 TO: version: 315.41 on instance concourse/6318b9e7-8c72-4c4e-8769-e59abaa32297 (0) -var instanceAspectChangedOneRE = regexp.MustCompile(`^(.+)_changed\? changed FROM: (.+) TO: (.+) on instance ([^/]+)/([^ ]+) \((\d+)\)$`) - -func (p instanceAspectChangedParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := instanceAspectChangedOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - msg := InstanceAspectChangedMessage{ - RawMessage: in, - InstanceGroup: m[4], - InstanceID: m[5], - InstanceIndex: m[6], - Aspect: m[1], - ChangedFrom: m[2], - ChangedTo: m[3], - } - - return msg, nil - } - - return inU, nil -} diff --git a/log/taskdebug/lock.go b/log/taskdebug/lock.go index 2664ece..eba47f8 100644 --- a/log/taskdebug/lock.go +++ b/log/taskdebug/lock.go @@ -1,15 +1,9 @@ package taskdebug import ( - "regexp" - "github.com/dpb587/bosh-log-tracer/log" ) -var LockParser = lockParser{} - -type lockParser struct{} - type LockMessage struct { RawMessage @@ -19,33 +13,3 @@ type LockMessage struct { } var _ log.Line = &LockMessage{} - -// Acquiring lock: lock:deployment:concourse -// Acquired lock: lock:deployment:concourse -// Renewing lock: lock:deployment:concourse -// Deleted lock: lock:deployment:concourse uid: 3366af32-333e-453c-a73d-e2d7730071ba -var lockMessageOneRE = regexp.MustCompile(`^(Acquiring|Acquired|Renewing|Deleted) lock: ([^\s]+)( uid: (.+))?$`) - -func (p lockParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := lockMessageOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - msg := LockMessage{ - RawMessage: in, - Event: m[1], - Name: m[2], - UID: m[4], - } - - return msg, nil - } - - return inU, nil -} diff --git a/log/taskdebug/nats.go b/log/taskdebug/nats.go index 5f0dc27..bf7ab97 100644 --- a/log/taskdebug/nats.go +++ b/log/taskdebug/nats.go @@ -3,15 +3,10 @@ package taskdebug import ( "encoding/json" "fmt" - "regexp" "github.com/dpb587/bosh-log-tracer/log" ) -var NATSMessageParser = natsMessageParser{} - -type natsMessageParser struct{} - type NATSMessageMessage struct { RawMessage @@ -76,30 +71,3 @@ func (m NATSMessageMessage) GetReceivedDrainValue() int64 { return payload.Value } - -// SENT: agent.0e2a1093-0ace-4685-a361-a6f40a11f7ed {"protocol":3,"method":"get_state",... -var natsMessageOneRE = regexp.MustCompile(`^(SENT|RECEIVED): ([^ ]+) (.+)$`) - -func (p natsMessageParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := natsMessageOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - out := NATSMessageMessage{ - RawMessage: in, - Event: m[1], - Channel: m[2], - Payload: m[3], - } - - return out, nil - } - - return inU, nil -} diff --git a/log/taskdebug/nats_sent_agent.go b/log/taskdebug/nats_sent_agent.go index 44ecddf..ebf1a33 100644 --- a/log/taskdebug/nats_sent_agent.go +++ b/log/taskdebug/nats_sent_agent.go @@ -3,15 +3,10 @@ package taskdebug import ( "encoding/json" "fmt" - "strings" "github.com/dpb587/bosh-log-tracer/log" ) -var NATSMessageSentAgentParser = natsMessageSentAgentParser{} - -type natsMessageSentAgentParser struct{} - type NATSMessageSentAgentMessage struct { NATSMessageMessage @@ -40,41 +35,3 @@ func (m NATSMessageSentAgentMessage) GetArgument0String() string { return payload.Arguments[0].(string) } - -func (p natsMessageSentAgentParser) Parse(inU log.Line) (log.Line, error) { - inU, err := NATSMessageParser.Parse(inU) - if inU == nil || err != nil { - return inU, err - } - - in, ok := inU.(NATSMessageMessage) - if !ok { - return inU, nil - } - - if !strings.HasPrefix(in.Channel, "agent.") { - return inU, nil - } - - out := NATSMessageSentAgentMessage{ - NATSMessageMessage: in, - AgentID: strings.TrimPrefix(in.Channel, "agent."), - } - - var payload struct { - Protocol int `json:"protocol"` - Method string `json:"method"` - ReplyTo string `json:"reply_to"` - } - - err = json.Unmarshal([]byte(out.Payload), &payload) - if err != nil { - panic(err) - } - - out.PayloadProtocol = payload.Protocol - out.PayloadMethod = payload.Method - out.PayloadReplyTo = payload.ReplyTo - - return out, nil -} diff --git a/log/taskdebug/parser/cpi_aws_rpc.go b/log/taskdebug/parser/cpi_aws_rpc.go new file mode 100644 index 0000000..cd0b1ae --- /dev/null +++ b/log/taskdebug/parser/cpi_aws_rpc.go @@ -0,0 +1,55 @@ +package parser + +import ( + "regexp" + "strconv" + "strings" + "time" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var CPIAWSRPCParser = cpiAWSRPCParser{} + +type cpiAWSRPCParser struct{} + +// [Aws::EC2::Client 200 1.069542 0 retries] run_instances(... +var cpiAWSRPCOneRE = regexp.MustCompile(`^\[Aws::EC2::Client (\d+) ([\d\.]+) (\d) retries\] (.+)$`) + +func (p cpiAWSRPCParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "ExternalCpiLog" { + return inU, nil + } + + if m := cpiAWSRPCOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + out := taskdebug.CPIAWSRPCMessage{ + RawMessage: in, + Correlation: in.Tags["req_id"], + Payload: m[4], + } + + out.PayloadMethod = strings.SplitN(out.Payload, "(", 2)[0] + + if res, err := strconv.ParseFloat(m[2], 64); err == nil { + out.Duration = time.Duration(int64(res * 1000000)) + } + + if res, err := strconv.Atoi(m[1]); err == nil { + out.StatusCode = res + } + + if res, err := strconv.Atoi(m[3]); err == nil { + out.Retries = res + } + + return out, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/external_cpi.go b/log/taskdebug/parser/external_cpi.go new file mode 100644 index 0000000..60e9134 --- /dev/null +++ b/log/taskdebug/parser/external_cpi.go @@ -0,0 +1,39 @@ +package parser + +import ( + "regexp" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var ExternalCPIParser = externalCPIParser{} + +type externalCPIParser struct{} + +// [external-cpi] [cpi-308955] request: {"method":"create_vm","arguments":[... +var externalCPIOneRE = regexp.MustCompile(`^\[external-cpi\] \[(cpi-\d+)\] (request|response): (.+)$`) + +func (p externalCPIParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := externalCPIOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + out := taskdebug.ExternalCPIMessage{ + RawMessage: in, + Correlation: m[1], + Event: m[2], + Remaining: m[3], + } + + return out, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/external_cpi_request.go b/log/taskdebug/parser/external_cpi_request.go new file mode 100644 index 0000000..38009d9 --- /dev/null +++ b/log/taskdebug/parser/external_cpi_request.go @@ -0,0 +1,62 @@ +package parser + +import ( + "encoding/json" + "regexp" + + "github.com/dpb587/bosh-log-tracer/log/taskdebug" + "github.com/dpb587/bosh-log-tracer/log" +) + +var ExternalCPIRequestParser = externalCPIRequestParser{} + +type externalCPIRequestParser struct{} + +// [external-cpi] [cpi-308955] request: {"method":"create_vm","arguments":[... +var externalCPIRequestOneRE = regexp.MustCompile(`(\{.+\}) with command: (.+)$`) + +func (p externalCPIRequestParser) Parse(inU log.Line) (log.Line, error) { + inU, err := ExternalCPIParser.Parse(inU) + if inU == nil || err != nil { + return inU, err + } + + in, ok := inU.(taskdebug.ExternalCPIMessage) + if !ok { + return inU, nil + } + + upstreamU, err := ExternalCPIParser.Parse(in) + if upstreamU == nil || err != nil { + return upstreamU, err + } + + upstream := upstreamU.(taskdebug.ExternalCPIMessage) + + if upstream.Event != "request" { + return upstream, nil + } + + if m := externalCPIRequestOneRE.FindStringSubmatch(upstream.Remaining); len(m) > 0 { + out := taskdebug.ExternalCPIRequestMessage{ + ExternalCPIMessage: upstream, + Payload: m[1], + Command: m[2], + } + + var payload struct { + Method string `json:"method"` + } + + err = json.Unmarshal([]byte(out.Payload), &payload) + if err != nil { + panic(err) + } + + out.PayloadMethod = payload.Method + + return out, nil + } + + return upstreamU, nil +} diff --git a/log/taskdebug/parser/instance_aspect_changed.go b/log/taskdebug/parser/instance_aspect_changed.go new file mode 100644 index 0000000..e5e40f3 --- /dev/null +++ b/log/taskdebug/parser/instance_aspect_changed.go @@ -0,0 +1,42 @@ +package parser + +import ( + "regexp" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var InstanceAspectChangedParser = instanceAspectChangedParser{} + +type instanceAspectChangedParser struct{} + +// stemcell_changed? changed FROM: version: 315.36 TO: version: 315.41 on instance concourse/6318b9e7-8c72-4c4e-8769-e59abaa32297 (0) +var instanceAspectChangedOneRE = regexp.MustCompile(`^(.+)_changed\? changed FROM: (.+) TO: (.+) on instance ([^/]+)/([^ ]+) \((\d+)\)$`) + +func (p instanceAspectChangedParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := instanceAspectChangedOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + msg := taskdebug.InstanceAspectChangedMessage{ + RawMessage: in, + InstanceGroup: m[4], + InstanceID: m[5], + InstanceIndex: m[6], + Aspect: m[1], + ChangedFrom: m[2], + ChangedTo: m[3], + } + + return msg, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/lock.go b/log/taskdebug/parser/lock.go new file mode 100644 index 0000000..e98b827 --- /dev/null +++ b/log/taskdebug/parser/lock.go @@ -0,0 +1,42 @@ +package parser + +import ( + "regexp" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var LockParser = lockParser{} + +type lockParser struct{} + +// Acquiring lock: lock:deployment:concourse +// Acquired lock: lock:deployment:concourse +// Renewing lock: lock:deployment:concourse +// Deleted lock: lock:deployment:concourse uid: 3366af32-333e-453c-a73d-e2d7730071ba +var lockMessageOneRE = regexp.MustCompile(`^(Acquiring|Acquired|Renewing|Deleted) lock: ([^\s]+)( uid: (.+))?$`) + +func (p lockParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := lockMessageOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + msg := taskdebug.LockMessage{ + RawMessage: in, + Event: m[1], + Name: m[2], + UID: m[4], + } + + return msg, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/nats.go b/log/taskdebug/parser/nats.go new file mode 100644 index 0000000..596c622 --- /dev/null +++ b/log/taskdebug/parser/nats.go @@ -0,0 +1,39 @@ +package parser + +import ( + "regexp" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var NATSMessageParser = natsMessageParser{} + +type natsMessageParser struct{} + +// SENT: agent.0e2a1093-0ace-4685-a361-a6f40a11f7ed {"protocol":3,"method":"get_state",... +var natsMessageOneRE = regexp.MustCompile(`^(SENT|RECEIVED): ([^ ]+) (.+)$`) + +func (p natsMessageParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := natsMessageOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + out := taskdebug.NATSMessageMessage{ + RawMessage: in, + Event: m[1], + Channel: m[2], + Payload: m[3], + } + + return out, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/nats_sent_agent.go b/log/taskdebug/parser/nats_sent_agent.go new file mode 100644 index 0000000..955e366 --- /dev/null +++ b/log/taskdebug/parser/nats_sent_agent.go @@ -0,0 +1,51 @@ +package parser + +import ( + "encoding/json" + "strings" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var NATSMessageSentAgentParser = natsMessageSentAgentParser{} + +type natsMessageSentAgentParser struct{} + +func (p natsMessageSentAgentParser) Parse(inU log.Line) (log.Line, error) { + inU, err := NATSMessageParser.Parse(inU) + if inU == nil || err != nil { + return inU, err + } + + in, ok := inU.(taskdebug.NATSMessageMessage) + if !ok { + return inU, nil + } + + if !strings.HasPrefix(in.Channel, "agent.") { + return inU, nil + } + + out := taskdebug.NATSMessageSentAgentMessage{ + NATSMessageMessage: in, + AgentID: strings.TrimPrefix(in.Channel, "agent."), + } + + var payload struct { + Protocol int `json:"protocol"` + Method string `json:"method"` + ReplyTo string `json:"reply_to"` + } + + err = json.Unmarshal([]byte(out.Payload), &payload) + if err != nil { + panic(err) + } + + out.PayloadProtocol = payload.Protocol + out.PayloadMethod = payload.Method + out.PayloadReplyTo = payload.ReplyTo + + return out, nil +} diff --git a/log/taskdebug/parser.go b/log/taskdebug/parser/parser.go similarity index 83% rename from log/taskdebug/parser.go rename to log/taskdebug/parser/parser.go index a65b6a5..2f99877 100644 --- a/log/taskdebug/parser.go +++ b/log/taskdebug/parser/parser.go @@ -1,8 +1,8 @@ -package taskdebug +package parser import "github.com/dpb587/bosh-log-tracer/log" -var Parser = []log.LineParser{ +var Parser = log.NewMultiParser( RawParser, ProcessParser, @@ -17,4 +17,4 @@ var Parser = []log.LineParser{ ExternalCPIParser, CPIAWSRPCParser, -} +) diff --git a/log/taskdebug/parser/process.go b/log/taskdebug/parser/process.go new file mode 100644 index 0000000..71d01f6 --- /dev/null +++ b/log/taskdebug/parser/process.go @@ -0,0 +1,40 @@ +package parser + +import ( + "regexp" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var ProcessParser = processParser{} + +type processParser struct{} + +// Running from worker 'worker_4' on director/e522142e-d0e2-4605-7c57-2cab3e749003 (127.0.0.1) +var processOneRE = regexp.MustCompile(`^Running from worker '([^']+)' on ([^/]+)/([^ ]+) \(([^\)]+)\)$`) + +func (p processParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := processOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + out := taskdebug.ProcessMessage{ + RawMessage: in, + WorkerName: m[1], + InstanceName: m[2], + InstanceID: m[3], + IP: m[4], + } + + return out, nil + } + + return inU, nil +} diff --git a/log/taskdebug/parser/raw.go b/log/taskdebug/parser/raw.go new file mode 100644 index 0000000..be41ec7 --- /dev/null +++ b/log/taskdebug/parser/raw.go @@ -0,0 +1,97 @@ +package parser + +import ( + "fmt" + "regexp" + "time" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var RawParser = rawParser{} + +type rawParser struct{} + +// I, [2019-06-19T01:44:52.546138 #26587] [] INFO -- DirectorJobRunner: ... +var rawOneRE = regexp.MustCompile(`^(\w), \[([^ ]+) #(\d+)\] \[([^\]]*)\]\s+(\w+) -- ([^:]+): (.+)$`) + +// I, [2019-06-19T01:47:50.061354 #26935] INFO -- [req_id cpi-354031]: ... +var rawTwoRE = regexp.MustCompile(`^(\w), \[([^ ]+) #(\d+)\]\s+(\w+) -- \[req_id cpi-(\d+)\]: (.+)$`) + +func (p rawParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(log.RawLine) + if !ok { + return inU, nil + } + + out := taskdebug.RawMessage{ + RawLine: in, + Message: in.RawLineData, + } + + if m := rawOneRE.FindStringSubmatch(out.Message); len(m) > 0 { + out.Process = m[3] + out.Tags = p.parseTags(m[4]) + out.LogLevel = m[5] + out.Component = m[6] + out.Message = m[7] + + if t, err := time.Parse("2006-01-02T15:04:05", m[2]); err == nil { + out.LogTime = t + } + } else if m := rawTwoRE.FindStringSubmatch(out.Message); len(m) > 0 { + out.Process = m[3] + out.Tags = map[string]string{"req_id": "cpi-" + m[5]} + out.LogLevel = m[4] + out.Component = "ExternalCpiLog" + out.Message = m[6] + + if t, err := time.Parse("2006-01-02T15:04:05", m[2]); err == nil { + out.LogTime = t + } + } + + return out, nil +} + +// task:80528 +var rawTagsOneRE = regexp.MustCompile(`^task:(\d+)$`) + +// compile_package(legacy/e8d0a259ffde97201489d0b5f47822026cdfebf1, bosh-aws-xen-hvm-ubuntu-trusty-go_agent/3586.40) +var rawTagsTwoRE = regexp.MustCompile(`^compile_package\(([^/]+)/([^,]+), ([^/]+)/([^\)]+)\)$`) + +// create_missing_vm(compilation-1b6dfd75-028e-469c-9512-bcce3b0a5504/6056c8c0-2bad-40cf-bcec-4c56f66f12de (0)/1) +var rawTagsThreeRE = regexp.MustCompile(`^create_missing_vm\(([^/]+)/([^ ]+) \((\d+)\)/(\d+)\)$`) + +// canary_update(appsrv/a3cc41b0-e2f2-4722-89a8-b4d31a1e60d7 (0)) +// instance_update(appsrv/ccd2905c-0e7e-45bd-9f9a-9455fad0fafc (0)) +var rawTagsFourRE = regexp.MustCompile(`^(canary_update|instance_update)\(([^/]+)/([^ ]+) \((\d+)\)\)$`) + +func (p rawParser) parseTags(raw string) map[string]string { + tags := map[string]string{} + + if m := rawTagsOneRE.FindStringSubmatch(raw); len(m) > 0 { + tags["task"] = m[1] + } else if m := rawTagsTwoRE.FindStringSubmatch(raw); len(m) > 0 { + tags["action"] = "compile_package" + tags["package"] = fmt.Sprintf("%s/%s", m[1], m[2]) + tags["package_name"] = m[1] + tags["package_fingerprint"] = m[2] + tags["stemcell"] = fmt.Sprintf("%s/%s", m[3], m[4]) + tags["stemcell_os"] = m[3] + tags["stemcell_version"] = m[4] + } else if m := rawTagsThreeRE.FindStringSubmatch(raw); len(m) > 0 { + tags["action"] = "create_missing_vm" + tags["instance_group"] = m[1] + tags["instance_id"] = m[2] + tags["instance_index"] = m[3] + } else if m := rawTagsFourRE.FindStringSubmatch(raw); len(m) > 0 { + tags["action"] = m[1] + tags["instance_group"] = m[2] + tags["instance_id"] = m[3] + tags["instance_index"] = m[4] + } + + return tags +} diff --git a/log/taskdebug/parser/sequel.go b/log/taskdebug/parser/sequel.go new file mode 100644 index 0000000..d7b93db --- /dev/null +++ b/log/taskdebug/parser/sequel.go @@ -0,0 +1,44 @@ +package parser + +import ( + "regexp" + "strconv" + "time" + + "github.com/dpb587/bosh-log-tracer/log" + "github.com/dpb587/bosh-log-tracer/log/taskdebug" +) + +var SequelParser = sequelParser{} + +type sequelParser struct{} + +// (0.000175s) (conn: 47432699065800) SELECT * FROM "tasks" WHERE "id" = 50995 +var sequelOneRE = regexp.MustCompile(`^\(([\d\.]+)s\)\s\(conn:\s(\d+)\)\s(.+)$`) + +func (p sequelParser) Parse(inU log.Line) (log.Line, error) { + in, ok := inU.(taskdebug.RawMessage) + if !ok { + return inU, nil + } + + if in.Component != "DirectorJobRunner" { + return inU, nil + } + + if m := sequelOneRE.FindStringSubmatch(in.Message); len(m) > 0 { + msg := taskdebug.SequelMessage{ + RawMessage: in, + Connection: m[2], + Query: m[3], + } + + if res, err := strconv.ParseFloat(m[1], 64); err == nil { + msg.Duration = time.Duration(int64(res * 1000000)) + } + + return msg, nil + } + + return inU, nil +} diff --git a/log/taskdebug/process.go b/log/taskdebug/process.go index b1138ac..4440ec4 100644 --- a/log/taskdebug/process.go +++ b/log/taskdebug/process.go @@ -1,15 +1,9 @@ package taskdebug import ( - "regexp" - "github.com/dpb587/bosh-log-tracer/log" ) -var ProcessParser = processParser{} - -type processParser struct{} - type ProcessMessage struct { RawMessage @@ -20,31 +14,3 @@ type ProcessMessage struct { } var _ log.Line = &ProcessMessage{} - -// Running from worker 'worker_4' on director/e522142e-d0e2-4605-7c57-2cab3e749003 (127.0.0.1) -var processOneRE = regexp.MustCompile(`^Running from worker '([^']+)' on ([^/]+)/([^ ]+) \(([^\)]+)\)$`) - -func (p processParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := processOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - out := ProcessMessage{ - RawMessage: in, - WorkerName: m[1], - InstanceName: m[2], - InstanceID: m[3], - IP: m[4], - } - - return out, nil - } - - return inU, nil -} diff --git a/log/taskdebug/raw.go b/log/taskdebug/raw.go index 41d0848..9f87f51 100644 --- a/log/taskdebug/raw.go +++ b/log/taskdebug/raw.go @@ -1,17 +1,11 @@ package taskdebug import ( - "fmt" - "regexp" "time" "github.com/dpb587/bosh-log-tracer/log" ) -var RawParser = rawParser{} - -type rawParser struct{} - type RawMessage struct { log.RawLine @@ -24,86 +18,3 @@ type RawMessage struct { } var _ log.Line = &RawMessage{} - -// I, [2019-06-19T01:44:52.546138 #26587] [] INFO -- DirectorJobRunner: ... -var rawOneRE = regexp.MustCompile(`^(\w), \[([^ ]+) #(\d+)\] \[([^\]]*)\]\s+(\w+) -- ([^:]+): (.+)$`) - -// I, [2019-06-19T01:47:50.061354 #26935] INFO -- [req_id cpi-354031]: ... -var rawTwoRE = regexp.MustCompile(`^(\w), \[([^ ]+) #(\d+)\]\s+(\w+) -- \[req_id cpi-(\d+)\]: (.+)$`) - -func (p rawParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(log.RawLine) - if !ok { - return inU, nil - } - - out := RawMessage{ - RawLine: in, - Message: in.RawLineData, - } - - if m := rawOneRE.FindStringSubmatch(out.Message); len(m) > 0 { - out.Process = m[3] - out.Tags = p.parseTags(m[4]) - out.LogLevel = m[5] - out.Component = m[6] - out.Message = m[7] - - if t, err := time.Parse("2006-01-02T15:04:05", m[2]); err == nil { - out.LogTime = t - } - } else if m := rawTwoRE.FindStringSubmatch(out.Message); len(m) > 0 { - out.Process = m[3] - out.Tags = map[string]string{"req_id": "cpi-" + m[5]} - out.LogLevel = m[4] - out.Component = "ExternalCpiLog" - out.Message = m[6] - - if t, err := time.Parse("2006-01-02T15:04:05", m[2]); err == nil { - out.LogTime = t - } - } - - return out, nil -} - -// task:80528 -var rawTagsOneRE = regexp.MustCompile(`^task:(\d+)$`) - -// compile_package(legacy/e8d0a259ffde97201489d0b5f47822026cdfebf1, bosh-aws-xen-hvm-ubuntu-trusty-go_agent/3586.40) -var rawTagsTwoRE = regexp.MustCompile(`^compile_package\(([^/]+)/([^,]+), ([^/]+)/([^\)]+)\)$`) - -// create_missing_vm(compilation-1b6dfd75-028e-469c-9512-bcce3b0a5504/6056c8c0-2bad-40cf-bcec-4c56f66f12de (0)/1) -var rawTagsThreeRE = regexp.MustCompile(`^create_missing_vm\(([^/]+)/([^ ]+) \((\d+)\)/(\d+)\)$`) - -// canary_update(appsrv/a3cc41b0-e2f2-4722-89a8-b4d31a1e60d7 (0)) -// instance_update(appsrv/ccd2905c-0e7e-45bd-9f9a-9455fad0fafc (0)) -var rawTagsFourRE = regexp.MustCompile(`^(canary_update|instance_update)\(([^/]+)/([^ ]+) \((\d+)\)\)$`) - -func (p rawParser) parseTags(raw string) map[string]string { - tags := map[string]string{} - - if m := rawTagsOneRE.FindStringSubmatch(raw); len(m) > 0 { - tags["task"] = m[1] - } else if m := rawTagsTwoRE.FindStringSubmatch(raw); len(m) > 0 { - tags["action"] = "compile_package" - tags["package"] = fmt.Sprintf("%s/%s", m[1], m[2]) - tags["package_name"] = m[1] - tags["package_fingerprint"] = m[2] - tags["stemcell"] = fmt.Sprintf("%s/%s", m[3], m[4]) - tags["stemcell_os"] = m[3] - tags["stemcell_version"] = m[4] - } else if m := rawTagsThreeRE.FindStringSubmatch(raw); len(m) > 0 { - tags["action"] = "create_missing_vm" - tags["instance_group"] = m[1] - tags["instance_id"] = m[2] - tags["instance_index"] = m[3] - } else if m := rawTagsFourRE.FindStringSubmatch(raw); len(m) > 0 { - tags["action"] = m[1] - tags["instance_group"] = m[2] - tags["instance_id"] = m[3] - tags["instance_index"] = m[4] - } - - return tags -} diff --git a/log/taskdebug/sequel.go b/log/taskdebug/sequel.go index dc9c932..3b5bccd 100644 --- a/log/taskdebug/sequel.go +++ b/log/taskdebug/sequel.go @@ -1,17 +1,11 @@ package taskdebug import ( - "regexp" - "strconv" "time" "github.com/dpb587/bosh-log-tracer/log" ) -var SequelParser = sequelParser{} - -type sequelParser struct{} - type SequelMessage struct { RawMessage @@ -21,33 +15,3 @@ type SequelMessage struct { } var _ log.Line = &SequelMessage{} - -// (0.000175s) (conn: 47432699065800) SELECT * FROM "tasks" WHERE "id" = 50995 -var sequelOneRE = regexp.MustCompile(`^\(([\d\.]+)s\)\s\(conn:\s(\d+)\)\s(.+)$`) - -func (p sequelParser) Parse(inU log.Line) (log.Line, error) { - in, ok := inU.(RawMessage) - if !ok { - return inU, nil - } - - if in.Component != "DirectorJobRunner" { - return inU, nil - } - - if m := sequelOneRE.FindStringSubmatch(in.Message); len(m) > 0 { - msg := SequelMessage{ - RawMessage: in, - Connection: m[2], - Query: m[3], - } - - if res, err := strconv.ParseFloat(m[1], 64); err == nil { - msg.Duration = time.Duration(int64(res * 1000000)) - } - - return msg, nil - } - - return inU, nil -}