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

Setup

  1. Pixie needs to be installed on your Kubernetes cluster. If it is not already installed, please consult our install guides.

  2. 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.probe("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

Building and Deploying the App

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.

Formatting the pxtrace.probe path

The format of the probe path differs slightly depending on whether the function being traced is a standard function or a receiver method. To create the pxtrace.probe path follow these steps:

  1. Get the package path (typically the directory of the file that contains the function) + prefix under GoSrc.

  2. Get the full function name. For simple functions (like the computeE example above), this is simply the name of the function. For receiver methods, format as (*<struct-name>).<funcName>.

  3. Combine together as <gopath>.<fullFuncName>. Note that if the fullFuncName is unambiguous, you may leave out the gopath.

Example Probe for a Regular Function

To trace the encodeError Go function from https://github.com/microservices-demo/payment/blob/master/transport.go, with the following signature:

func encodeError(_ context.Context, err error, w http.ResponseWriter) {}
  1. Take the project path + package prefix from the top of the file: github.com/microservices-demo/payment + payment

  2. Take the function name: encodeError

  3. Combine these two parts together to get the full probe path. The resulting PxL script probe is:

@pxtrace.probe("github.com/microservices-demo/payment/payment.encodeError")

Example Probe for a Struct Function

To trace the Authorise receiver method from https://github.com/microservices-demo/payment/blob/master/service.go, with the following signature:

func (s *service) Authorise(amount float32) (Authorisation, error) {}
  1. Take the project path + package prefix from the top of the file: github.com/microservices-demo/payment + payment

  2. Since it's a receiver method, the full method name would be formatted as: (*service).Authorise

  3. Combine these two parts together to get the full probe path. The resulting PxL script probe is:

@pxtrace.probe("github.com/microservices-demo/payment/payment.(*service).Authorise")

Debug symbols

Note that Dynamic Go Logging works using debug symbols. By default, go build compiles your program with debug symbols, and is compatible with Dynamic Go Logging. However, if you compile with -ldflags '-w' or strip the debug symbols after compiling, then you will not be able use Dynamic Go Logging. Additionally, if your build is optimized with inlining (-gcflags '-l'), certain functions won't be traceable. For more info see the golang documentation.

Known Issues

Note that there is a known bug in which re-running the script after modifying the probe_func definition will cause the tracepoint to fail to deploy. To get around this bug, whenever you modify the probe_func definition, please rename the table_name (and update the table_name in the df = px.DataFrame(table_name) line as well.

This site uses cookies to provide you with a better user experience. By using Pixie, you consent to our use of cookies.