Dynamic Logging In Go (Alpha)

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 one to debug 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:

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, return values and latency, without this slow process. Since we use new kernel technologies like eBPF, we can safely insert these logs without stopping execution of you program, and with minimal overhead.

Note: Dynamic logging is an alpha feature. Limitations are listed at the end of this page.

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-io/pixie-demos.git
cd pixie-demos/simple-gotracing

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:

sed -i'.orig' "s/replace-me-with-upid/$(px run -o json px/upids -- --namespace px-demo-gotracing  | jq -r '.upid' | head -n 1)/g" capture_args.pxl

Run the PxL script:

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.

To delete the demo from the cluster just run:

kubectl delete namespace px-demo-gotracing

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.

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.

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")

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")

Dynamic logging is an alpha feature. It is currently only supports logging of Go binaries.

Dynamic Go Logging works using debug information. By default, go build compiles your program with debug information and is compatible with Dynamic Go Logging. However, if you compile with -ldflags '-w -s' or strip the debug symbols after compiling, then you will not be able use Dynamic Go Logging.

Additionally, Dynamic logging works for Golang versions up to 1.16 only (the go compiler for 1.17 changed the calling convention, and the Dynamic Logging feature has not yet been updated to support those changes).

Dynamic Logging can currently be used to trace only certain types of arguments and return values:

If your build is optimized with inlining (-gcflags '-l'), certain functions won't be traceable. For more info see the golang documentation.

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.

Distributed bpftrace DeploymentReference