Skip to content

Commit

Permalink
Merge pull request encoredev#15 from encoredev/trace-logs
Browse files Browse the repository at this point in the history 
all: add request logs to traces
  • Loading branch information
@eandre
eandre authored Apr 17, 2021
2 parents 06ad3d4 + 0c0947a commit 417831b
Show file tree
Hide file tree
Showing 14 changed files with 1,202 additions and 365 deletions.
6 changes: 6 additions & 0 deletions cli/daemon/dash/dashapp/src/components/icons.tsx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -256,6 +256,12 @@ export const database: Icon = (cls, title) =>
<path d="M17 5c0 1.657-3.134 3-7 3S3 6.657 3 5s3.134-3 7-3 7 1.343 7 3z" />
</svg>

export const menuAlt2: Icon = (cls, title) =>
<svg className={cls} fill="none" stroke="currentColor" viewBox="0 0 24 24">
{renderTitle(title)}
<path strokeLinecap="round" strokeLinejoin="round" strokeWidth="2" d="M4 6h16M4 12h16M4 18h7" />
</svg>

export const errCircle: Icon = (cls, title) =>
<svg className={cls} viewBox="0 0 20 20" fill="currentColor">
{renderTitle(title)}
Expand Down
56 changes: 49 additions & 7 deletions cli/daemon/dash/dashapp/src/components/trace/SpanDetail.tsx
View file
Original file line number Diff line number Diff line change
@@ -1,9 +1,10 @@
import { FunctionComponent, useState, useRef, useEffect } from "react"
import { Request, Trace, Event, DBTransaction, DBQuery, TraceExpr, RPCCall, AuthCall, HTTPCall } from "./model"
import { latencyStr, svcColor } from "./util"
import { Duration } from "luxon"
import React, { FunctionComponent, useRef, useState } from "react"
import * as icons from "~c/icons"
import { decodeBase64, Base64EncodedBytes } from "~lib/base64"
import React from "react"
import { Base64EncodedBytes, decodeBase64 } from "~lib/base64"
import { timeToDate } from "~lib/time"
import { DBQuery, Event, HTTPCall, LogMessage, Request, RPCCall, Trace } from "./model"
import { latencyStr, svcColor } from "./util"

interface Props {
trace: Trace;
Expand All @@ -12,14 +13,17 @@ interface Props {

const SpanDetail: FunctionComponent<Props> = (props) => {
const req = props.req
const tr = props.trace
const defLoc = props.trace.locations[req.def_loc]
const callLoc = req.call_loc !== null ? props.trace.locations[req.call_loc] : null

const numCalls = req.children.length
let numQueries = 0
let logs: LogMessage[] = []
for (const e of req.events) {
if (e.type === "DBQuery" ) { numQueries++ }
else if (e.type === "DBTransaction" ) { numQueries += e.queries.length }
else if (e.type === "LogMessage") { logs.push(e) }
}

let svcName = "unknown", rpcName = "Unknown"
Expand All @@ -45,7 +49,7 @@ const SpanDetail: FunctionComponent<Props> = (props) => {
}
</div>

<div className="py-3 grid grid-cols-3 gap-4 border-b border-gray-100">
<div className="py-3 grid grid-cols-4 gap-4 border-b border-gray-100">
<div className="flex items-center text-sm font-light text-gray-400">
{icons.clock("h-5 w-auto")}
<span className="font-bold mx-1 text-gray-800">{req.end_time ? latencyStr(req.end_time - req.start_time) : "Unknown"}</span>
Expand All @@ -63,6 +67,12 @@ const SpanDetail: FunctionComponent<Props> = (props) => {
<span className="font-bold mx-1 text-gray-800">{numQueries}</span>
DB Quer{numQueries !== 1 ? "ies" : "y"}
</div>

<div className="flex items-center text-sm font-light text-gray-400">
{icons.menuAlt2("h-5 w-auto")}
<span className="font-bold mx-1 text-gray-800">{logs.length}</span>
Log Line{numQueries !== 1 ? "s" : ""}
</div>
</div>

<div>
Expand Down Expand Up @@ -107,6 +117,15 @@ const SpanDetail: FunctionComponent<Props> = (props) => {
</div>
)}
</>}

{logs.length > 0 &&
<div className="mt-6">
<h4 className="text-xs font-semibold font-sans text-gray-300 leading-3 tracking-wider uppercase mb-2">Logs</h4>
<pre className="rounded overflow-auto border border-gray-200 p-2 bg-gray-100 text-gray-800 text-sm">
{logs.map((log, i) => renderLog(tr, log, i))}
</pre>
</div>
}
</div>

</div>
Expand Down Expand Up @@ -193,6 +212,8 @@ const GoroutineDetail: FunctionComponent<{g: gdata, req: Request, trace: Trace}>
el.style.marginLeft = `calc(${spanEl.offsetLeft}px)`;
}

const barEvents: (DBQuery | RPCCall | HTTPCall)[] = g.events.filter(e => e.type === "DBQuery" || e.type === "RPCCall" || e.type === "HTTPCall") as any

return <>
<div className="relative" style={{height: lineHeight+"px"}}>
<div ref={goroutineEl} className={`absolute bg-gray-600`}
Expand All @@ -203,7 +224,7 @@ const GoroutineDetail: FunctionComponent<{g: gdata, req: Request, trace: Trace}>
minWidth: "1px", // so it at least renders
}}>

{g.events.map((ev, i) => {
{barEvents.map((ev, i) => {
const start = Math.round((ev.start_time - g.start) / gdur * 100)
const end = Math.round((ev.end_time! - g.start) / gdur * 100)
const clsid = `ev-${req.id}-${g.goid}-${i}`
Expand Down Expand Up @@ -427,4 +448,25 @@ const HTTPCallTooltip: FunctionComponent<{call: HTTPCall, req: Request, trace: T
const renderData = (data: Base64EncodedBytes[]) => {
const json = JSON.parse(decodeBase64(data[0]))
return <pre className="rounded overflow-auto border border-gray-200 p-2 bg-gray-100 text-gray-800 text-sm">{JSON.stringify(json, undefined, " ")}</pre>
}

const renderLog = (tr: Trace, log: LogMessage, key: any) => {
let dt = timeToDate(tr.date)!
const ms = (log.time - tr.start_time)/1000
dt = dt.plus(Duration.fromMillis(ms))
return <div key={key}>
<span className="text-gray-400">{dt.toFormat("HH:mm:ss.SSS")}{" "}</span>
{
log.level === "DEBUG" ? <span className="text-yellow-500">DBG</span> :
log.level === "INFO" ? <span className="text-green-500">INF</span> :
<span className="text-red-500">ERR</span>
}
{" "}{log.msg}
{log.fields.map((f, i) =>
<>
{" "}<span className="text-blue-600">{f.key}</span><span className="text-gray-400">=</span>
{f.value}
</>
)}
</div>
}
16 changes: 15 additions & 1 deletion cli/daemon/dash/dashapp/src/components/trace/model.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -109,7 +109,21 @@ export interface HTTPCallMetrics {
body_closed?: number;
}

export type Event = DBTransaction | DBQuery | RPCCall | HTTPCall | Goroutine;
export interface LogMessage {
type: "LogMessage";
goid: number;
time: number;
level: "DEBUG" | "INFO" | "ERROR";
msg: string;
fields: LogField[];
}

export interface LogField {
key: string;
value: any;
}

export type Event = DBTransaction | DBQuery | RPCCall | HTTPCall | Goroutine | LogMessage;

export type TraceExpr = RpcDefExpr | RpcCallExpr | StaticCallExpr | AuthHandlerDefExpr

Expand Down
58 changes: 58 additions & 0 deletions cli/daemon/dash/trace.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -118,6 +118,20 @@ type HTTPCallMetrics struct {
BodyClosed *int64 `json:"body_closed,omitempty"`
}

type LogMessage struct {
Type string `json:"type"` // "LogMessage"
Goid uint32 `json:"goid"`
Time int64 `json:"time"`
Level string `json:"level"` // "DEBUG", "INFO", or "ERROR"
Message string `json:"msg"`
Fields []LogField `json:"fields"`
}

type LogField struct {
Key string `json:"key"`
Value interface{} `json:"value"`
}

type Event interface {
traceEvent()
}
Expand All @@ -127,6 +141,7 @@ func (DBTransaction) traceEvent() {}
func (DBQuery) traceEvent() {}
func (RPCCall) traceEvent() {}
func (HTTPCall) traceEvent() {}
func (LogMessage) traceEvent() {}

func TransformTrace(ct *trace.TraceMeta) (*Trace, error) {
traceID := traceUUID(ct.ID)
Expand Down Expand Up @@ -246,6 +261,9 @@ func (tp *traceParser) parseReq(req *tracepb.Request) (*Request, error) {

case *tracepb.Event_Goroutine:
r.Events = append(r.Events, tp.parseGoroutine(e.Goroutine))

case *tracepb.Event_Log:
r.Events = append(r.Events, tp.parseLog(e.Log))
}
}

Expand All @@ -262,6 +280,46 @@ func (tp *traceParser) parseGoroutine(g *tracepb.Goroutine) *Goroutine {
}
}

func (tp *traceParser) parseLog(l *tracepb.LogMessage) *LogMessage {
msg := &LogMessage{
Type: "LogMessage",
Goid: l.Goid,
Time: tp.time(l.Time),
Level: l.Level.String(),
Message: l.Msg,
Fields: []LogField{},
}
for _, f := range l.Fields {
field := LogField{Key: f.Key}
switch v := f.Value.(type) {
case *tracepb.LogField_Error:
field.Value = v.Error
case *tracepb.LogField_Str:
field.Value = v.Str
case *tracepb.LogField_Bool:
field.Value = v.Bool
case *tracepb.LogField_Time:
field.Value = v.Time.AsTime()
case *tracepb.LogField_Dur:
field.Value = time.Duration(v.Dur).String()
case *tracepb.LogField_Uuid:
field.Value = uuid.FromBytesOrNil(v.Uuid).String()
case *tracepb.LogField_Json:
field.Value = json.RawMessage(v.Json)
case *tracepb.LogField_Int:
field.Value = v.Int
case *tracepb.LogField_Uint:
field.Value = v.Uint
case *tracepb.LogField_Float32:
field.Value = v.Float32
case *tracepb.LogField_Float64:
field.Value = v.Float64
}
msg.Fields = append(msg.Fields, field)
}
return msg
}

func (tp *traceParser) parseTx(tx *tracepb.DBTransaction) (*DBTransaction, error) {
tp.txCounter++
txid := tp.txCounter
Expand Down
Loading

0 comments on commit 417831b

Please sign in to comment.