Skip to content

Commit

Permalink
Refactor span log helpers
Browse files Browse the repository at this point in the history
  • Loading branch information
aledbf committed Jun 3, 2021
1 parent 015b38f commit 660c7ec
Show file tree
Hide file tree
Showing 6 changed files with 32 additions and 42 deletions.
12 changes: 1 addition & 11 deletions components/common-go/tracing/tracing.go
Original file line number Diff line number Diff line change
Expand Up @@ -135,16 +135,6 @@ func FromTraceID(traceID string) opentracing.SpanContext {
return spanCtx
}

// LogEvent logs an event in the trace.
func LogEvent(span opentracing.Span, name string) {
span.LogFields(tracelog.String("event", name))
}

// LogKV is a convenience method which logs a single key-value pair to a span
func LogKV(span opentracing.Span, key, value string) {
span.LogFields(tracelog.String(key, value))
}

// LogError logs an error and marks the span as errornous
func LogError(span opentracing.Span, err error) {
span.LogFields(tracelog.Error(err))
Expand All @@ -168,5 +158,5 @@ func LogMessageSafe(span opentracing.Span, name string, req proto.Message) {
msg = string(safeReqs)
}

LogKV(span, name, msg)
span.LogKV(name, msg)
}
10 changes: 5 additions & 5 deletions components/image-builder/pkg/resolve/resolve.go
Original file line number Diff line number Diff line change
Expand Up @@ -60,7 +60,7 @@ func (dr *DockerRegistryResolver) Resolve(ctx context.Context, ref string, opts

options := getOptions(opts)

tracing.LogKV(span, "original-ref", ref)
span.LogKV("original-ref", ref)

// The ref may be what Docker calls a "familiar" name, e.g. ubuntu:latest instead of docker.io/library/ubuntu:latest.
// To make this a valid digested form we first need to normalize that familiar name.
Expand All @@ -71,27 +71,27 @@ func (dr *DockerRegistryResolver) Resolve(ctx context.Context, ref string, opts

// The reference is already in digest form we don't have to do anything
if _, ok := pref.(reference.Canonical); ok {
tracing.LogKV(span, "result", ref)
span.LogKV("result", ref)
return ref, nil
}

nref := pref.String()
tracing.LogKV(span, "normalized-ref", nref)
span.LogKV("normalized-ref", nref)

manifest, err := dr.Client.DistributionInspect(ctx, nref, options.Auth)
// do not wrap this error so that others can check if this IsErrNotFound (Docker SDK doesn't use Go2 error values)
if err != nil {
return "", err
}
tracing.LogEvent(span, "got manifest")
span.LogKV("event", "got manifest")

cres, err := reference.WithDigest(pref, manifest.Descriptor.Digest)
if err != nil {
return "", err
}
res = cres.String()

tracing.LogKV(span, "result", res)
span.LogKV("result", res)

return res, nil
}
Expand Down
30 changes: 15 additions & 15 deletions components/ws-manager/pkg/manager/manager.go
Original file line number Diff line number Diff line change
Expand Up @@ -152,26 +152,26 @@ func (m *Manager) StartWorkspace(ctx context.Context, req *api.StartWorkspaceReq
if exists {
return nil, xerrors.Errorf("workspace %s exists already", req.Id)
}
tracing.LogEvent(span, "workspace does not exist")
span.LogKV("event", "workspace does not exist")
err = validateStartWorkspaceRequest(req)
if err != nil {
return nil, xerrors.Errorf("cannot start workspace: %w", err)
}
tracing.LogEvent(span, "validated workspace start request")
span.LogKV("event", "validated workspace start request")
// create the objects required to start the workspace pod/service
startContext, err := m.newStartWorkspaceContext(ctx, req)
if err != nil {
return nil, xerrors.Errorf("cannot create context: %w", err)
}
tracing.LogEvent(span, "created start workspace context")
span.LogKV("event", "created start workspace context")
clog.Info("starting new workspace")
// we must create the workspace pod first to make sure we don't clean up the services or configmap we're about to create
// because they're "dangling".
pod, err := m.createWorkspacePod(startContext)
if err != nil {
return nil, xerrors.Errorf("cannot create workspace pod: %w", err)
}
tracing.LogEvent(span, "pod description created")
span.LogKV("event", "pod description created")
err = m.Clientset.Create(ctx, pod)
if err != nil {
m, _ := json.Marshal(pod)
Expand All @@ -180,7 +180,7 @@ func (m *Manager) StartWorkspace(ctx context.Context, req *api.StartWorkspaceReq
clog.WithError(err).WithField("req", req).WithField("pod", safePod).Error("was unable to start workspace")
return nil, err
}
tracing.LogEvent(span, "pod created")
span.LogKV("event", "pod created")

// only regular workspaces get a service, the others are fine with just pod
okResponse := &api.StartWorkspaceResponse{Url: startContext.WorkspaceURL}
Expand Down Expand Up @@ -224,7 +224,7 @@ func (m *Manager) StartWorkspace(ctx context.Context, req *api.StartWorkspaceReq
// could not create Theia service
return nil, xerrors.Errorf("cannot create workspace's Theia service: %w", err)
}
tracing.LogEvent(span, "theia service created")
span.LogKV("event", "theia service created")

// if we have ports configured already, create the ports service
if len(req.Spec.Ports) > 0 {
Expand All @@ -239,7 +239,7 @@ func (m *Manager) StartWorkspace(ctx context.Context, req *api.StartWorkspaceReq
// could not create ports service
return nil, xerrors.Errorf("cannot create workspace's public service: %w", err)
}
tracing.LogEvent(span, "ports service created")
span.LogKV("event", "ports service created")
}

m.metrics.OnWorkspaceStarted(req.Type)
Expand Down Expand Up @@ -397,7 +397,7 @@ func (m *Manager) stopWorkspace(ctx context.Context, workspaceID string, gracePe
PropagationPolicy: &propagationPolicy,
},
)
tracing.LogEvent(span, "theia service deleted")
span.LogKV("event", "theia service deleted")

portsServiceErr := m.Clientset.Delete(ctx, &corev1.Service{
ObjectMeta: metav1.ObjectMeta{
Expand All @@ -410,7 +410,7 @@ func (m *Manager) stopWorkspace(ctx context.Context, workspaceID string, gracePe
PropagationPolicy: &propagationPolicy,
},
)
tracing.LogEvent(span, "ports service deleted")
span.LogKV("event", "ports service deleted")

podErr := m.Clientset.Delete(ctx,
&corev1.Pod{
Expand All @@ -424,7 +424,7 @@ func (m *Manager) stopWorkspace(ctx context.Context, workspaceID string, gracePe
PropagationPolicy: &propagationPolicy,
},
)
tracing.LogEvent(span, "pod deleted")
span.LogKV("event", "pod deleted")

if podErr != nil {
return xerrors.Errorf("stopWorkspace: %w", podErr)
Expand Down Expand Up @@ -621,7 +621,7 @@ func (m *Manager) ControlPort(ctx context.Context, req *api.ControlPortRequest)
if err != nil {
return nil, xerrors.Errorf("cannot create service: %w", err)
}
tracing.LogEvent(span, "port service created")
span.LogKV("event", "port service created")

service = *newService

Expand All @@ -647,7 +647,7 @@ func (m *Manager) ControlPort(ctx context.Context, req *api.ControlPortRequest)
return nil, err
}
}
tracing.LogEvent(span, "host available")
span.LogKV("event", "host available")

// we've successfully exposed the port by creating the service
err = notifyStatusChange()
Expand Down Expand Up @@ -699,7 +699,7 @@ func (m *Manager) ControlPort(ctx context.Context, req *api.ControlPortRequest)
PropagationPolicy: &propagationPolicy,
})

tracing.LogEvent(span, "port service deleted")
span.LogKV("event", "port service deleted")
} else {
// we've made it here which means we need to actually patch the service
service.Spec = *spec
Expand All @@ -725,7 +725,7 @@ func (m *Manager) ControlPort(ctx context.Context, req *api.ControlPortRequest)
if err != nil {
return nil, xerrors.Errorf("cannot update service: %w", err)
}
tracing.LogEvent(span, "port service updated")
span.LogKV("event", "port service updated")
}
if err != nil {
return nil, xerrors.Errorf("cannot control port: %w", err)
Expand Down Expand Up @@ -781,7 +781,7 @@ func (m *Manager) DescribeWorkspace(ctx context.Context, req *api.DescribeWorksp
return nil, status.Errorf(codes.Internal, "cannot get workspace status: %q", err)
}
tracing.ApplyOWI(span, wsk8s.GetOWIFromObject(&pod.ObjectMeta))
tracing.LogEvent(span, "get pod")
span.LogKV("event", "get pod")

wso, err := m.getWorkspaceObjects(ctx, pod)
if err != nil {
Expand Down
4 changes: 2 additions & 2 deletions components/ws-manager/pkg/manager/manager_ee.go
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ func (m *Manager) TakeSnapshot(ctx context.Context, req *api.TakeSnapshotRequest
return nil, status.Errorf(codes.Internal, "cannot get workspace status: %q", err)
}
tracing.ApplyOWI(span, wsk8s.GetOWIFromObject(&pod.ObjectMeta))
tracing.LogEvent(span, "get pod")
span.LogKV("event", "get pod")

wso, err := m.getWorkspaceObjects(ctx, pod)
if err != nil {
Expand Down Expand Up @@ -82,7 +82,7 @@ func (m *Manager) ControlAdmission(ctx context.Context, req *api.ControlAdmissio
return nil, status.Errorf(codes.Internal, "cannot get workspace status: %q", err)
}
tracing.ApplyOWI(span, wsk8s.GetOWIFromObject(&pod.ObjectMeta))
tracing.LogEvent(span, "get pod")
span.LogKV("event", "get pod")

wso, err := m.getWorkspaceObjects(ctx, pod)
if err != nil {
Expand Down
10 changes: 5 additions & 5 deletions components/ws-manager/pkg/manager/monitor.go
Original file line number Diff line number Diff line change
Expand Up @@ -327,7 +327,7 @@ func (m *Monitor) actOnPodEvent(ctx context.Context, status *api.WorkspaceStatus
}

if !wso.IsWorkspaceHeadless() {
tracing.LogEvent(span, "removeTraceAnnotation")
span.LogKV("event", "removeTraceAnnotation")
// once a regular workspace is up and running, we'll remove the traceID information so that the parent span
// ends once the workspace has started
err := m.manager.markWorkspace(ctx, workspaceID, deleteMark(wsk8s.TraceIDAnnotation))
Expand Down Expand Up @@ -556,7 +556,7 @@ func (m *Monitor) traceWorkspace(occasion string, wso *workspaceObjects) opentra
if wso.Pod != nil {
tracing.ApplyOWI(span, wsk8s.GetOWIFromObject(&wso.Pod.ObjectMeta))
}
tracing.LogKV(span, "occasion", occasion)
span.LogKV("occasion", occasion)

// OpenTracing does not support creating a span from a SpanContext https://github.com/opentracing/specification/issues/81.
// Until that changes we just finish the span immediately after calling on-change.
Expand Down Expand Up @@ -584,7 +584,7 @@ func (m *Monitor) waitForWorkspaceReady(ctx context.Context, pod *corev1.Pod) (e
return
}

tracing.LogEvent(span, "probeDone")
span.LogKV("event", "probeDone")
probeResult := *r
if probeResult == WorkspaceProbeStopped {
// Workspace probe was stopped most likely because the workspace itself was stopped.
Expand Down Expand Up @@ -629,7 +629,7 @@ func (m *Monitor) waitForWorkspaceReady(ctx context.Context, pod *corev1.Pod) (e
m.initializerMapLock.Lock()
delete(m.initializerMap, pod.Name)
m.initializerMapLock.Unlock()
tracing.LogEvent(span, "contentInitDone")
span.LogKV("event", "contentInitDone")

// workspace is ready - mark it as such
err = m.manager.markWorkspace(ctx, workspaceID, deleteMark(workspaceNeverReadyAnnotation))
Expand Down Expand Up @@ -918,7 +918,7 @@ func (m *Monitor) finalizeWorkspaceContent(ctx context.Context, wso *workspaceOb
gitStatus *csapi.GitStatus
)
for i := 0; i < wsdaemonMaxAttempts; i++ {
tracing.LogKV(span, "attempt", strconv.Itoa(i))
span.LogKV("attempt", strconv.Itoa(i))
didSometing, gs, err := doFinalize()
if !didSometing {
// someone else is managing finalization process ... we don't have to bother
Expand Down
8 changes: 4 additions & 4 deletions components/ws-manager/pkg/manager/probe.go
Original file line number Diff line number Diff line change
Expand Up @@ -79,25 +79,25 @@ func (p *WorkspaceReadyProbe) Run(ctx context.Context) WorkspaceProbeResult {
return WorkspaceProbeStopped
}

tracing.LogEvent(span, "probe start")
span.LogKV("event", "probe start")
resp, err := client.Get(p.readyURL)

if err != nil {
urlerr, ok := err.(*url.Error)
if !ok || !urlerr.Timeout() {
tracing.LogKV(span, "response", "error")
span.LogKV("response", "error")
log.WithError(err).Debug("got a non-timeout error during workspace probe")
time.Sleep(p.RetryDelay)
continue
}

// we've timed out - do not log this as it would spam the logs for no good reason
tracing.LogKV(span, "response", "timeout")
span.LogKV("response", "timeout")
continue
}

if resp.StatusCode != http.StatusOK {
tracing.LogKV(span, "response", fmt.Sprintf("%v", resp.StatusCode))
span.LogKV("response", fmt.Sprintf("%v", resp.StatusCode))
log.WithField("url", p.readyURL).WithField("status", resp.StatusCode).Debug("workspace did not respond to ready probe with OK status")
time.Sleep(p.RetryDelay)
continue
Expand Down

0 comments on commit 660c7ec

Please sign in to comment.