EXPAND ALL
  • Home

Dynamic Logging In Go

This is a simple demo showing the ability of Pixie to add dynamic structured logs into Go binaries deployed in production environments. This capability allows debugging Go binaries in production without the need to instrument the source code with additional log statements, recompile, and redeploy.

A simple overview of this functionality is show here:

Dynamic Structured Loggging in Go

In a legacy systems a modify, compile, deploy cycle is required to get visibility into the binary if the appropriate log lines are missing. Pixie allows you to dynamically capture function arguments, latency, etc., without this slow process. Since we use new kernel technologies like eBPF we can safely insert these logs without stopping execution of you program with minimal overhead.

Tutorial Overview

Prerequisites

Pixie (>= v0.4.0) needs to be installed on your K8s cluster. If it is not already installed then please consult our docs.

You also need to clone the pixie repo to get the relevant files.

git clone https://github.com/pixie-labs/pixie.git
cd pixie/demos/simple-gotracing

Running the demo

The demo is completely self-contained and will install a simple Go application under the namespace px-demo-gotracing. The source of this application is in app.go. To deploy this application run:

kubectl apply -f k8s_manifest.yaml

We are going to dynamic trace the computeE function in app.go to get started. This is a simple function that tried to approximate the value of eulers number by using a taylor series. The number of iterations of the expansion is specified by the iters query param to the HTTP handler. To see how this works we can connect to the service by forwarding the appropriate port:

kubectl port-forward service/gotracing-svc -n px-demo-gotracing 9090

We can use curl to quickly access the api. The number of iterations is the query parameter iters.

curl http://localhost:9090/e
# e = 2.7183
curl http://localhost:9090/e\?iters\=2
# e = 2.0000
curl http://localhost:9090/e\?iters\=200
# e = 2.7183

As expected the accuracy of e approaches the expected value of 2.7183 as we increase the number of iterations.

The full source code of this is located here. The function that computes this is shown below:

// computeE computes the approximation of e by running a fixed number of iterations.
func computeE(iterations int64) float64 {
res := 2.0
fact := 1.0
for i := int64(2); i < iterations; i++ {
fact *= float64(i)
res += 1 / fact
}
return res
}

The function computeE is called by an HTTP handler. Let's say we want to quickly access the arguments to the computeE function, and it's latency. We can use the provided capture_args.pxl script. The complete script has code to programmatically insert the log and capture data for a time period. However, the actual function that captures this data is straightforward:

@pxtrace.goprobe("main.computeE")
def probe_func():
return [{
'iterations': pxtrace.ArgExpr("iterations"),
'latency': pxtrace.FunctionLatency(),
}]

This PXL function simply attached to the main.computeE function and grabs the iterations argument along with the execution time in nanoseconds.

To attach this function to our running binary we need to first identify the UPID of the process we want to trace. The UPID refers to the unique process id, which is a process ID that is globally unique in the entire cluster. In future versions of Pixie we will make this process easier. For now, we can easily get the UPID by running the follow script:

px run px/upids -- --namespace px-demo-gotracing
# [0000] INFO Pixie CLI
# Table ID: UPIDs
# CLUSTERID POD CONTAINER UPID CMDLINE POD CREATE TIME
# f890689b-299c-43fd-8d2a-b0c528a58393 px-demo-gotracing/gotracing-7cdd66f89d-khnss app 00000003-0023-9267-0000-000008e60831 ./main 2020-08-09T20:39:34-07:00

The relevant UPID is in the fourth column. Edit the upid variable in the capture_args.pxl script with this value. Alternatively, you can run the following shell command that will do the substitution for you:

px run -f capture_args.pxl
# [0000] INFO Pixie CLI
# ✔ Preparing schema
# ✔ Deploying compute_e_data
# Table ID: output
# CLUSTERID UPID TIME GOID ITERATIONS

The result data will be empty since no requests have been made yet. Let's run the curl commands we have above and see what happens:

px run -f capture_args.pxl
# [0000] INFO Pixie CLI
# Table ID: output
# CLUSTERID UPID TIME GOID ITERATIONS
# f890689b-299c-43fd-8d2a-b0c528a58393 00000003-0024-844a-0000-000008caa618 2020-08-09T17:16:11-07:00 194529 100
# f890689b-299c-43fd-8d2a-b0c528a58393 00000003-0024-844a-0000-000008caa618 2020-08-09T17:16:14-07:00 194416 2
# f890689b-299c-43fd-8d2a-b0c528a58393 00000003-0024-844a-0000-000008caa618 2020-08-09T17:16:16-07:00 194531 200

There it is, we just capture all the arguments to the computeE function without changing the source code or redeploying it. We also found out that the default number of iterations is a 100 without having to look through the source code. While this example is straight forward and simple and hardly requires the use of dynamic logging to understand, we can easily see how this can be used to debug much more complicated scenarios.

Cleaning up

To delete the demo from the cluster just run:

kubectl delete namespace px-demo-gotracing

Modifying the demo

The demo can easily be modified by editing the app.go source file. After that you can simply create a new docker image by running:

docker build . -t <image name>

Edit the image name in k8s_manifest.yaml to correspond to you new image and redeploy.

Copyright © 2020 Pixie Labs Inc.