DEV Community: Cheng Pan

Buildkite Agent - fork/exec ... operation not permitted

Cheng Pan — Thu, 23 May 2024 01:44:01 +0000

The Problem

In the past months, I was working on tracking down a bug caused by the dependency PTY package that the Buildkite agent depends on. The following are the symptoms:

Symptom 1 - operation not permitted for git checkout:

2024-05-20 11:15:52 PDT $ git clone -v -- ssh...
...
...
2024-05-20 11:15:52 PDT 🚨 Error: Failed to checkout plugin docker: error running "/usr/bin/git checkout -f e9efccb": error starting pty: fork/exec /usr/bin/git: operation not permitted
2024-05-20 11:15:52 PDT Running global pre-exit hook

Symptom 2 - operation not permitted for git clean:

2024-05-21 09:28:12 PDT ⚠️ Warning: Checkout failed! cleaning repository post-checkout: error running "/usr/bin/git clean -ffxdq": error starting pty: fork/exec /usr/bin/git: operation not permitted (Attempt 1/3 Retrying in 2s)

Symptom 3 - operation not permitted fork/exec bash:

2024-05-20 10:37:40 PDT 🚨 Error: error running "/bin/bash -e -c \"trap 'kill -- $$' INT TERM QUIT; if [ -n \\\"$(git diff HEAD~1 --exit-code 'cruise/ai_platform/search')\\\" ]; then\\n  cat <<- ...\"": error starting pty: fork/exec /bin/bash: operation not permitted

The Investigation

After further investigation, I made following observations:

this doesn’t happen consistently for a single step. If a step failed once, the next step is likely going to pass the next time
this happens at low frequency. At Cruise, we run over 100k build steps on daily basis. And it only occurs about <10 times a day.
this happen among different pipelines. This means the likelihood is only 0.01%.
the git operation failed even after the previous git operation succeeded (eg. git clone in the previous hooks within the same step worked without the permission issue)
it has nothing to do with the +x flag on the binary being executed, both git and bash has the proper permission flag set.
the machine status or installed package is not mutated by the CI job in any malicious way. This is guaranteed by how we run CI infra at Cruise, each time a CI job is created, we spin up a branch new ephemeral VM to handle the job, and the job is terminated right after the job finishes. This guarantees that machine is not messed up.

(If you are interested in learning how we design ephemeral CI infrastructure, please comment below :D )

Given all the observation above, this lead me to believe the bug is not specific to any build step, or any pipeline. Hence the build is likely somewhere at the VM level. The next thing come into my radar is the buildkite agent binary itself.

The Buildkite Agent

I've been doing Buildkite agent upgrade from time to time. One thing I noticed is that I recently made an upgrade to the Buildkit agent from v3.36.1 to v3.59.0. From our log, it showed that the bug started showing up after the v3.59.0 upgrade. Hence, the bug must be lying between the difference of two version. I'm close to the truth.

Buildkite Support is very helpful

After reported the problem to Bulidkite support, and working with their support engineers. We decided to compare the strace output between the Buildkite agent version v3.36.1 and v3.59.0. There is a specific line that the Buildkite support pointed out that's interesting:

ioctl(0, TIOCSCTTY, 1)            = -1 EPERM (Operation not permitted)"

According to the Buildkite support:

By default the agent runs the command process inside a pseudo-terminal, which leads to this particular ioctl call. A possible workaround would be to disable PTY mode (buildkite-agent start --no-pty or BUILDKITE_NO_PTY=1).

Then, I tested turning off the PTY. Unfortunately, this is not a backward compatible change we can easily adapt at infrastructure level. Because some of the workloads that depends on the PTY will break, eg docker run -ti.

So the remaining option is to fix the PTY itself. And more digging shows it's the github.com/creack/pty package that Buildkite agent depends on that's doing the setup of PTY for the Buildkite agent. And we found Agent v3.36.1 used v1.1.12 of ptyPTY and Agent v3.59.0 used v1.1.20. The latest is v1.1.21, which is used in Agent v3.60.0 and later. And recently there is a fix for a race condition on Linux in the v1.1.21 release notes.

Testing Buildkite Agent v3.60.0

The next immediate fix is to valid the fix within PTY package by upgrading Buildkite agent to v3.60.0. Although the upgrade helped, it doesn't fully resolve the issue. As shown in the follow graph, the frequency reduced from ~10 times per day to <1 time per day. And it still happens.

Finding the breaking change

Then question becomes which version of the PTY package introduce the bug. In order to find the breaking change, I did a binary search on the PTY package version. We know v1.1.12 works without the issue, and v1.1.21 doesn't work. So the bug must be lying within the range. And there are about 10 release between v1.1.12 and v1.1.21. I tested v1.1.17, v1.19, and couldn't reproduce the problem is any of the versions. So we concluded that the breaking change is v1.1.20+

What we did was simply path the OSS buildkite agent's go.mod with a downgraded PTY package version as v1.1.19. And we noticed for any Buildkite agent v3.58.0+, they all uses the PTY v1.1.20+. So if you running into the same issue, downgrading the PTY package is likely what you need.

Cheers

Updates

2024-05-23: Buildkite already fix the issue in the main branch.

Learning Linux - splice

Cheng Pan — Tue, 20 Feb 2024 07:27:03 +0000

The Simple Problem

I'm recently working on a project that requires concatenating many small files (~100k) into a large file. The file size ranges from 32KB to 1MB. At first glance, the problem is pretty straight forward, I simply read the content of each file into memory and write the content into the destination file. The following is my initial implementation:

package main

import (
    "io"
    "os"
)

func main() {
    for i := 1; i < len(os.Args); i++ {
        f, err := os.Open(os.Args[i])
        if err != nil {
            panic(err)
        }
        defer f.Close()

        _, err = io.Copy(os.Stdout, f)
        if err != nil {
            panic(err)
        }
    }
}

What the above program does is almost identical to what the cat command does. Since the program simply reads the data from underlying device (whichever backs the file) and write back to another file. I started to wonder is there a more performant way to implement it? Because the files are read and written as is, there is not need to do this extra hop of reading the data into user space!

After a bit of digging, it turned out that you can copy files without reading its content. The answer is splice.

What's splice?

The following is from Linux man page.

splice() moves data between two file descriptors without copying between kernel address space and user address space. It transfers up to len bytes of data from the file descriptor fd_in to the file descriptor fd_out, where one of the file descriptors must refer to a pipe.

That's exactly what we want!

By reading at it's function definition:

ssize_t splice(int fd_in, off64_t *off_in, int fd_out, off64_t *off_out, size_t len, unsigned int flags);

The splice function takes a fd_in at offset off_int, and writes data of given length len into fd_out at offset off_out. Pretty straight forward. However, one interesting part is one of the file descriptor must be a pipe. For reason why, please refer to Linus's comment at here.

After more Googles, I couldn't find a good post talk about how to implement it in Golang (hence the creation of this post), but I found this post about a implementation in Rust. Now we have a good start point.

First Attempt

My first attempt is simply translating the Rust implementation into Golang. Here is what I got:

const BUF_SIZE = 16 * 1024 // Using the same 16 KB

// splice file with zero-copy to speed up resembling process
// https://man7.org/linux/man-pages/man2/splice.2.html
func SpliceTo(src, dst *os.File) error {
    // create the pipe
    rp, wp, err := os.Pipe()
    if err != nil {
        return errors.Wrap(err, "pipe failed")
    }
    defer rp.Close()
    defer wp.Close()

    var (
        inFd  = int(src.Fd())
        outFd = int(dst.Fd())
        wpFd  = int(wp.Fd())
        rpFd  = int(rp.Fd())
    )

    for {
        nr, err := syscall.Splice(inFd, nil, wpFd, nil, BUF_SIZE, 0)
        if err != nil {
            return errors.Wrap(err, "failed to splice to the inFd")
        }
        if nr <= 0 {
            break
        }

        _, err = syscall.Splice(rpFd, nil, outFd, nil, BUF_SIZE, 0)
        if err != nil {
            return errors.Wrap(err, "failed to splice to the outFd")
        }
    }

    return nil
}

func main() {
    in, err := os.Open(os.Args[1])
    if err != nil {
        panic("failed to open the file")
    }
    defer in.Close()

    err = SpliceTo(in, os.Stdout)
    if err != nil {
        panic(fmt.Sprintf("failed to splice the file: %v", err))
    }
}

Now let's test out the program, I first created the random file with urandom and I got 2.02GiB/s:

head -c 2G </dev/urandom > large-file

go run main.go large-file | pv -r >/dev/null
[2.02GiB/s]

And I'm using cat as the benchmark, I got 1.78GiB/s. It's similar to the result that I got from the other post:

cat large-file| pv -r > /dev/null
[1.78GiB/s]

It's a surprising to me that the result using splice is not as good as what I expected, and it's much lower than the 5.90GiB/s in the other post.

Second Attempt

I was puzzled by what might be the reason. The first thinking was the buffer size might be too small, so that I increased the buffer size from 16KB to 160KB, which is 10 times more:

const BUF_SIZE = 16 * 1024 * 10 // 160 KB

Now, let's run the program again:

go run main.go large-file | pv -r >/dev/null
[3.63GiB/s]

The throughput jumps right to 3.63GiB/s. That's much better!

As an engineer, I'd like proving the theory with experimentation. Although I'm getting a much better results than the benchmark, I was wondering the correctness of the program. So I tested the spliced output using a hash program, eg sha256sum. If I can get the same hash between the benchmark and my program, than the result is correct.

Here is what I did:

# Get the hash using cat
cat large-file| sha256sum
86df6afa07b75faab97cf0a3021f884e10783d6f1e2f2447f65f2c644c969009  -

# Get the hash using splice
go run main.go large-file | sha256sum
cbdf56b4cf4e4c8b1d254c4ec937ba26fe9b64a2cf9acc3a0ae8122f52d143aa  -

Hmmm... The hash doesn't match!

Third Attempt

I was puzzled again about what might be wrong. And there is one thing that caught my eye. If you are a careful reader, you might already noticed, the Go Splice syscall returns not only an error, but also the number of bytes that's got spliced. What if the number of bytes is not the same as the buffer size? If you have dealt with I/O, it's a common pattern that the kernel uses to signal back pressure to user space program. Sometimes kernel could be busy or limited by some other factors, so that I might not also fulfill the requested I/O, which is 160KB BUFF_SIZE in this case. And when this happens, it will only return the number of bytes that actually got written (or spliced in our case).

Let's first prove the theory by printing out the number of bytes nr in the first splice call:

    for {
        nr, err := syscall.Splice(inFd, nil, wpFd, nil, BUF_SIZE, 0)
        if err != nil {
            return errors.Wrap(err, "failed to splice to the inFd")
        }
        if nr <= 0 {
            break
        }
        fmt.Fprintf(os.Stderr, "nr: %v\n", nr)

        _, err = syscall.Splice(rpFd, nil, outFd, nil, &nr, 0)
        if err != nil {
            return errors.Wrap(err, "failed to splice to the outFd")
        }
    }

and here is what I got after running the program:

nr: 65536
...
nr: 65536

It turned out that although we requested for 160KB, but there is only 64KB got spliced. And the following is the final implementation that I got:

const BUF_SIZE = 16 * 10240 // 160 KB

// splice file with zero-copy to speed up resembling process
// https://man7.org/linux/man-pages/man2/splice.2.html
func SpliceTo(src, dst *os.File) error {
    // create the pipe
    rp, wp, err := os.Pipe()
    if err != nil {
        return errors.Wrap(err, "pipe failed")
    }
    defer rp.Close()
    defer wp.Close()

    var (
        inFd  = int(src.Fd())
        outFd = int(dst.Fd())
        wpFd  = int(wp.Fd())
        rpFd  = int(rp.Fd())
    )

    for {
        nr, err := syscall.Splice(inFd, nil, wpFd, nil, BUF_SIZE, 0)
        if err != nil {
            return errors.Wrap(err, "failed to splice to the inFd")
        }
        if nr <= 0 {
            break
        }

        // safe to convert int64 to int since the BUFF_SIZE is int
        toWrite := int(nr)
        // toWrite might not be fulfilled, so need a for loop for splice
        // to make sure all the toWrite are spliced
        for toWrite > 0 {
            nw, err := syscall.Splice(rpFd, nil, outFd, nil, toWrite, 0)
            if err != nil {
                return errors.Wrap(err, "failed to splice to the outFd")
            }
            toWrite -= int(nw)
        }
    }

    return nil
}

Make sure the hash is correct:

go run main.go large-file | sha256sum
86df6afa07b75faab97cf0a3021f884e10783d6f1e2f2447f65f2c644c969009  -
cat large-file| sha256sum
86df6afa07b75faab97cf0a3021f884e10783d6f1e2f2447f65f2c644c969009  -

And make sure the throughput is performant:

go run main.go large-file | pv -r >/dev/null
[3.40GiB/s]

Summary

Splice is a powerful zero-copy optimization technique that could be used to speed up I/O when dealing with file bytes across kernal space and user space. However, there are caveat that you need to careful about to implement a both performance and correct program. Here is what I learnt:

If the buffer size is too small, it could limit the throughput of the splice performance.
Splice returns the number of bytes that actually got written, and it could be smaller than the requested size, and the user program need to handle the case to get correct results.

Tricks of declaring dynamic variables in Bash

Cheng Pan — Sun, 25 Apr 2021 06:22:14 +0000

In any programming languages, it is a common practice to define a variable with the result of some computation and refer to it later when needed. In Bash, it's pretty straight forward to define variables as follows:

> FOO=bar
> echo $FOO
bar

But what if you want to define a variable, of which name is dynamic? This could be useful when the variable name is only known during runtime, as user input. Something like this:

# bash variables names are stored in variables.txt
# as user input
> cat > variables.txt <<EOF
FOO1=bar1
FOO2=bar2
FOO3=bar3
EOF

> do_some_magic

> echo $FOO1
bar1

> echo $FOO2
bar2

> echo $FOO3
bar3

Trick 1 `declare` dynamic variables

declare is a built function within Bash. It is the magic here to define variables with dynamic names. A peak of declare's man output:

declare: declare [-aAfFgiIlnrtux] [-p] [name[=value] ...]
    Set variable values and attributes.

    Declare variables and give them attributes.  If no NAMEs are given,
    display the attributes and values of all variables.

This is what you need to do:

> var_name=FOO1
> declare $var_name="bar1"
> echo $FOO1
bar1

If you replace the above do_some_magic function with:


while IFS='=' read -ra line; do
  key=${line[0]}
  value=${line[1]}
  declare "$key"="$value"
done < variables.txt

you will get:

> echo $FOO1
bar1

> echo $FOO2
bar2

> echo $FOO3
bar3

Super cool, right?

But thing gets tricky when you want to modulerize the above while loop as a function for usage in multiple places of your code. The following is what I did:

function define_dynamic_variables() {
  while IFS='=' read -ra line; do
    key=${line[0]}
    value=${line[1]}
    declare "$key"="$value"
  done < variables.txt 
}

But when I run the above function, the result is totally unexpected:

> define_dynamic_variables
> echo $FOO1
bash: FOO1: unbound variable

What's going on?

Trick 2 declare is local when inside function

Why the same piece code works without a function but not when inside a function?

A dive deep into the output of help declare shows:

When used in a function, `declare' makes NAMEs local, as with the `local'
    command.  The `-g' option suppresses this behavior.

The nuance is clearly explained by the help output. It basically says if you need to define a variable that live outside of the function scope, the -g option is needed, otherwise, the variable is defined local to the function scope and hence invisible after the function runs.

After fixing the function to be:

function define_dynamic_variables() {
  while IFS='=' read -ra line; do
    key=${line[0]}
    value=${line[1]}
    declare -g "$key"="$value"
  done < variables.txt 
}

Everything back to normal:

> define_dynamic_variables
> echo $FOO1
bar1

Trick 3 export dynamic variables as environment variable

Sometimes you might want to define the dynamic variable and export it as environment variable at the same time. You might come up with:

declare FOO=bar
export FOO

While it works, a more idiomatic why is to use the -x option:

declare -x FOO=bar  #when define the variable outside function
declare -gx FOO=bar #when define the variable inside function

Summary

Today, we learned 3 tricks related to defining dynamic variables in Bash:

define dynamic variables with declare
variable defined by declare is local when inside function
export dynamic variables as environment variable

Last but not least, as RTFM stands, always refer to manual when something unexpected happens and this sometimes turns out to be more useful than simply googling online.

DEV Community: Cheng Pan

Buildkite Agent - fork/exec ... operation not permitted

The Problem

Symptom 1 - operation not permitted for git checkout:

Symptom 2 - operation not permitted for git clean:

Symptom 3 - operation not permitted fork/exec bash:

The Investigation

The Buildkite Agent

Buildkite Support is very helpful

Testing Buildkite Agent v3.60.0

Finding the breaking change

Updates

Learning Linux - splice

The Simple Problem

What's splice?

First Attempt

Second Attempt

Third Attempt

Summary

Tricks of declaring dynamic variables in Bash

Trick 1 declare dynamic variables

Trick 2 declare is local when inside function

Trick 3 export dynamic variables as environment variable

Summary

Trick 1 `declare` dynamic variables