Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update circleci docker image #2041

Merged
merged 2 commits into from Jul 30, 2021
Merged

Update circleci docker image #2041

merged 2 commits into from Jul 30, 2021

Conversation

rjoleary
Copy link
Contributor

@rjoleary rjoleary commented Jun 8, 2021

The big change is the switch to Go 1.15 and QEMU 6.0.0.

Signed-off-by: Ryan O'Leary ryanoleary@google.com

@rjoleary
Copy link
Contributor Author

rjoleary commented Jun 8, 2021

It looks like the arm64 Docker container does not build anymore. Some issue in the qemu configure script (logs are sparse).

rminnich
rminnich previously approved these changes Jun 9, 2021
@rminnich rminnich added the automerge Applying this label auto-merges the PR when ready label Jun 9, 2021
@rjoleary rjoleary force-pushed the circleci branch 2 times, most recently from 90b2288 to 2176c3a Compare June 10, 2021 03:00
@rjoleary rjoleary added Awaiting reviewer Waiting for a reviewer. and removed automerge Applying this label auto-merges the PR when ready labels Jun 10, 2021
@rminnich rminnich added Awaiting author Waiting for new changes or feedback for author. and removed Awaiting reviewer Waiting for a reviewer. labels Jun 10, 2021
@rjoleary rjoleary force-pushed the circleci branch 2 times, most recently from 4f8b9c1 to 363eb8b Compare June 10, 2021 19:51
@rjoleary
Copy link
Contributor Author

        qemu-system-x86_64: -device ide-drive,drive=disk,bus=ahci.0: 'ide-drive' is not a valid device model name

Maybe we should switch to SATA.

@rjoleary
Copy link
Contributor Author

@rjoleary
Copy link
Contributor Author

@hugelgupf I think this might be a bug in how we're parsing the output of go test from the QEMU serial?

See:

    integration.go:146: 2021/07/26 20:45:35 serial: === RUN   TestOpenSignedFile
    integration.go:146: 2021/07/26 20:46:00 serial: testing: warning: no tests to run
    integration.go:146: 2021/07/26 20:46:00 serial: PASS

Which seems fine.

And then further down:

    gotest.go:127: Test github.com/u-root/u-root/pkg/vfile.TestOpenSignedFile left in state running:
        === RUN   TestOpenSignedFile

Why only arm64? Is the output of go test stable across Go versions?

@rjoleary
Copy link
Contributor Author

=== RUN TestOpenSignedFile

Hmmmm, this log output isn't making much sense. There should be a line after this like "--- PASS: TestOpenSignedFile (0.02s)"

@thanm
Copy link
Contributor

thanm commented Jul 27, 2021

Why only arm64? Is the output of go test stable across Go versions?

[From the peanut gallery]

FWIW, the output of "go test" is not stable from release to release; the Go team does periodically make changes to the output format to improve clarity and readability. In this CL you are moving from Go 1.13 to Go 1.15; in that range there were 27 commits to the Go testing package, including

https://go-review.googlesource.com/c/go/+/127120
https://go-review.googlesource.com/c/go/+/179599
https://go-review.googlesource.com/c/go/+/229085
https://go-review.googlesource.com/c/go/+/235997

all of which change test output in some way. From the test log it looks as though maybe you are parsing the output of "go test -test.v" ?

@thanm
Copy link
Contributor

thanm commented Jul 27, 2021

the output of "go test" is not stable from release to release

With that said, I agree that it does seem as though the "Pass: TestOpenSignedFile" is missing. Don't have a good theory there.

@rjoleary
Copy link
Contributor Author

I reran the circleci and this seems to be consistent.

    integration.go:146: 2021/07/28 02:58:02 serial: === RUN   TestFromZip
    integration.go:146: 2021/07/28 02:58:02 serial: --- PASS: TestFromZip (0.15s)
    integration.go:146: 2021/07/28 02:58:02 serial: PASS
    integration.go:146: 2021/07/28 02:58:03 serial: === RUN   TestOpenSignedFile
    integration.go:146: 2021/07/28 02:58:28 serial: testing: warning: no tests to run
    integration.go:146: 2021/07/28 02:58:28 serial: PASS
    integration.go:146: 2021/07/28 02:58:28 serial: testing: warning: no tests to run
    integration.go:146: 2021/07/28 02:58:28 serial: PASS

@rjoleary
Copy link
Contributor Author

I ran the qemu command by hand and here's an excerpt:

=== RUN   TestFromZip
{"Time":"1970-01-01T00:01:54.763375072Z","Action":"run","Package":"github.com/u-root/u-root/pkg/uzip","Test":"TestFromZip"}
{"Time":"1970-01-01T00:01:54.767613056Z","Action":"output","Package":"github.com/u-root/u-root/pkg/uzip","Test":"TestFromZip","Output":"=== RUN   TestFromZip\n"}
--- PASS: TestFromZip (0.20s)
{"Time":"1970-01-01T00:01:54.9710296Z","Action":"output","Package":"github.com/u-root/u-root/pkg/uzip","Test":"TestFromZip","Output":"--- PASS: TestFromZip (0.20s)\n"}
PASS
{"Time":"1970-01-01T00:01:54.97549864Z","Action":"pass","Package":"github.com/u-root/u-root/pkg/uzip","Test":"TestFromZip","Elapsed":0.2}
{"Time":"1970-01-01T00:01:54.976421296Z","Action":"output","Package":"github.com/u-root/u-root/pkg/uzip","Output":"PASS\n"}
{"Time":"1970-01-01T00:01:54.982704064Z","Action":"pass","Package":"github.com/u-root/u-root/pkg/uzip","Elapsed":0.584}
=== RUN   TestOpenSignedFile
{"Time":"1970-01-01T00:01:55.202000416Z","Action":"run","Package":"github.com/u-root/u-root/pkg/vfile","Test":"TestOpenSignedFile"}
{"Time":"1970-01-01T00:01:55.205167792Z","Action":"output","Package":"github.com/u-root/u-root/pkg/vfile","Test":"TestOpenSignedFile","Output":"=== RUN   TestOpenSignedFile\n"}
testing: warning: no tests to run
PASS
{"Time":"1970-01-01T00:02:20.287836304Z","Action":"output","Package":"github.com/u-root/u-root/pkg/vmtest/internal/json2test","Output":"PASS\n"}
{"Time":"1970-01-01T00:02:20.295709504Z","Action":"pass","Package":"github.com/u-root/u-root/pkg/vmtest/internal/json2test","Elapsed":0.213}
testing: warning: no tests to run
PASS
{"Time":"1970-01-01T00:02:20.705040624Z","Action":"output","Package":"github.com/u-root/u-root/pkg/vmtest","Output":"PASS\n"}
{"Time":"1970-01-01T00:02:20.71245112Z","Action":"pass","Package":"github.com/u-root/u-root/pkg/vmtest","Elapsed":0.369}
=== RUN   TestGetReadOnly

Still there is no sign of the "--- PASS" for TestOpenSignedFile...

@rjoleary
Copy link
Contributor Author

If I only run the tests in the vfile package, it works:

    integration.go:146: 2021/07/28 04:32:41 serial: === RUN   TestOpenSignedFile~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/signed_file~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/signed_file_w/_two_signatures_(key1_ring)~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/signed_file_w/_two_signatures_(key2_ring)~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/nil_keyring~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/non-nil_empty_keyring~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/signed_file_does_not_match_keyring~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/unsigned_file~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenSignedFile/file_does_not_exist~
    integration.go:146: 2021/07/28 04:32:48 serial: --- PASS: TestOpenSignedFile (6.59s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/signed_file (0.02s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/signed_file_w/_two_signatures_(key1_ring) (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/signed_file_w/_two_signatures_(key2_ring) (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/nil_keyring (0.01s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/non-nil_empty_keyring (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/signed_file_does_not_match_keyring (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/unsigned_file (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenSignedFile/file_does_not_exist (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile/correct_hash~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile/wrong_hash~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile/no_hash~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile/empty_file~
    integration.go:146: 2021/07/28 04:32:48 serial: === RUN   TestOpenHashedFile/nonexistent_file~
    integration.go:146: 2021/07/28 04:32:48 serial: --- PASS: TestOpenHashedFile (0.03s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenHashedFile/correct_hash (0.01s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenHashedFile/wrong_hash (0.01s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenHashedFile/no_hash (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenHashedFile/empty_file (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial:     --- PASS: TestOpenHashedFile/nonexistent_file (0.00s)~
    integration.go:146: 2021/07/28 04:32:48 serial: PASS~
    integration.go:146: 2021/07/28 04:32:48 serial: 1970/01/01 00:00:08 Not collecting kernel coverage because "/sys/kernel/debug/gcov" does not exist~
    integration.go:146: 2021/07/28 04:32:48 serial: 1970/01/01 00:00:08 TESTS PASSED MARKER~

@rjoleary
Copy link
Contributor Author

I was able to reproduce the error with testing only two packages in the gotest vm test:

cmd := exec.Command("go", "list",
        "github.com/u-root/u-root/pkg/uzip",
        "github.com/u-root/u-root/pkg/vfile",
)

It is flaky and fails 9/10 times. When it passes, the logs look normal as expected.

On the other hand:

        cmd := exec.Command("go", "list",
                "github.com/u-root/u-root/pkg/vfile",
        )

Passes 10/10 times.

@rjoleary
Copy link
Contributor Author

For the record, it also passes 10/10 times when run on the x86 host outside of qemu:

for i in $(seq 10); do go test -count=1 -v github.com/u-root/u-root/pkg/uzip github.com/u-root/u-root/pkg/vfile; done

@rjoleary
Copy link
Contributor Author

I improved the logging for the gotest vmtest. Previously, the exit status was ignored and the context was cancelled without enough time to get the stack trace out.

When it fails, it is timing out. I tried increasing the timeout to 40s to no avail:

    integration.go:146: 2021/07/28 05:52:49 serial: === RUN   TestOpenSignedFile~
    integration.go:146: 2021/07/28 05:53:29 serial: panic: test timed out after 40s~
    integration.go:146: 2021/07/28 05:53:29 serial: ~
    integration.go:146: 2021/07/28 05:53:29 serial: goroutine 7 [running]:~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.(*M).startAlarm.func1()~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1618 +0xc8~
    integration.go:146: 2021/07/28 05:53:29 serial: created by time.goFunc~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/time/sleep.go:167 +0x40~
    integration.go:146: 2021/07/28 05:53:29 serial: ~
    integration.go:146: 2021/07/28 05:53:29 serial: goroutine 1 [chan receive]:~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.(*T).Run(0x4000001080, 0x1b0f66, 0x12, 0x1baaf0, 0x2)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1169 +0x234~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.runTests.func1(0x4000000f00)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1439 +0x74~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.tRunner(0x4000000f00, 0x4000050dc8)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1123 +0xec~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.runTests(0x400000c1e0, 0x2a7640, 0x2, 0x2, 0xa7f81dea99dc43c0, 0x955b0f151, 0x2af680, 0x7f840838f0)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1437 +0x20c~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.(*M).Run(0x4000084000, 0x0)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1345 +0x1ac~
    integration.go:146: 2021/07/28 05:53:29 serial: main.main()~
    integration.go:146: 2021/07/28 05:53:29 serial: 	_testmain.go:45 +0xd4~
    integration.go:146: 2021/07/28 05:53:29 serial: ~
    integration.go:146: 2021/07/28 05:53:29 serial: goroutine 6 [runnable]:~
    integration.go:146: 2021/07/28 05:53:29 serial: math/big.nat.montgomery(0x40002c2900, 0x20, 0x24, 0x40002b4640, 0x10, 0x26, 0x40002b4640, 0x10, 0x26, 0x40001b3680, ...)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/math/big/nat.go:226 +0x160~
    integration.go:146: 2021/07/28 05:53:29 serial: math/big.nat.expNNMontgomery(0x40002b4640, 0x10, 0x26, 0x40002b2dc0, 0x10, 0x14, 0x40002b2c80, 0x10, 0x14, 0x40001b3680, ...)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/math/big/nat.go:1447 +0x5d0~
    integration.go:146: 2021/07/28 05:53:29 serial: math/big.nat.expNN(0x40002b2e60, 0x10, 0x14, 0x40002b2dc0, 0x10, 0x14, 0x40002b2c80, 0x10, 0x14, 0x40001b3680, ...)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/math/big/nat.go:1261 +0x650~
    integration.go:146: 2021/07/28 05:53:29 serial: math/big.nat.probablyPrimeMillerRabin(0x40001b3680, 0x10, 0x14, 0x15, 0x5a4dd0c2a1bf6501, 0x5a4dd0c2a1bf6500)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/math/big/prime.go:106 +0x348~
    integration.go:146: 2021/07/28 05:53:29 serial: math/big.(*Int).ProbablyPrime(0x400000c280, 0x14, 0x4000037838)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/math/big/prime.go:78 +0x2d0~
    integration.go:146: 2021/07/28 05:53:29 serial: crypto/rand.Prime(0x1c76a0, 0x40000581e0, 0x400, 0x400000c200, 0x0, 0x0)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/crypto/rand/util.go:99 +0x120~
    integration.go:146: 2021/07/28 05:53:29 serial: crypto/rsa.GenerateMultiPrimeKey(0x1c76a0, 0x40000581e0, 0x2, 0x800, 0x1, 0x4000018120, 0x17)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/crypto/rsa/rsa.go:302 +0x118~
    integration.go:146: 2021/07/28 05:53:29 serial: crypto/rsa.GenerateKey(0x1c76a0, 0x40000581e0, 0x800, 0x4, 0x1aed2f, 0x9)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/crypto/rsa/rsa.go:242 +0x40~
    integration.go:146: 2021/07/28 05:53:29 serial: github.com/u-root/u-root/vendor/golang.org/x/crypto/openpgp.NewEntity(0x1adf26, 0x4, 0x1adf26, 0x4, 0x1aed2f, 0x9, 0x0, 0x0, 0x0, 0x0)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/home/circleci/go/src/github.com/u-root/u-root/vendor/golang.org/x/crypto/openpgp/keys.go:518 +0xbc~
    integration.go:146: 2021/07/28 05:53:29 serial: github.com/u-root/u-root/pkg/vfile.TestOpenSignedFile(0x4000001080)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/home/circleci/go/src/github.com/u-root/u-root/pkg/vfile/vfile_test.go:69 +0x6c~
    integration.go:146: 2021/07/28 05:53:29 serial: testing.tRunner(0x4000001080, 0x1baaf0)~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1123 +0xec~
    integration.go:146: 2021/07/28 05:53:29 serial: created by testing.(*T).Run~
    integration.go:146: 2021/07/28 05:53:29 serial: 	/usr/local/go/src/testing/testing.go:1168 +0x218~
    integration.go:146: 2021/07/28 05:53:29 serial: 1970/01/01 00:00:42 Not collecting kernel coverage because "/sys/kernel/debug/gcov" does not exist~
    gotest.go:127: Test github.com/u-root/u-root/pkg/vfile.TestOpenSignedFile left in state running:
        === RUN   TestOpenSignedFile
        Error: test for "github.com/u-root/u-root/pkg/vfile" exited early: exit status 2

It seems to be stuck doing some math crypto stuff.

@rjoleary
Copy link
Contributor Author

Oh no, amd64 is failing now too!

@rjoleary
Copy link
Contributor Author

Perhaps this has something to do with virtio-rng?

@hugelgupf
Copy link
Member

Why only arm64? Is the output of go test stable across Go versions?

[From the peanut gallery]

FWIW, the output of "go test" is not stable from release to release; the Go team does periodically make changes to the output format to improve clarity and readability. In this CL you are moving from Go 1.13 to Go 1.15; in that range there were 27 commits to the Go testing package, including

https://go-review.googlesource.com/c/go/+/127120
https://go-review.googlesource.com/c/go/+/179599
https://go-review.googlesource.com/c/go/+/229085
https://go-review.googlesource.com/c/go/+/235997

all of which change test output in some way. From the test log it looks as though maybe you are parsing the output of "go test -test.v" ?

@thanm we use Go's very own cmd/test2json to parse the output of go test -test.v. The tests are compiled as binaries, shared with the VM, and run in the VM basically as ./testbinary -test.v | test2json -t -p as seen here:

cmd := exec.CommandContext(ctx, path, "-test.v")

I'm checking out the failure.

@hugelgupf
Copy link
Member

Running locally with Go 1.15 and my pre-installed QEMU passes. Checking out qemu 6.0.0 now.

@hugelgupf
Copy link
Member

hugelgupf commented Jul 29, 2021

I used:

  • go1.15.14,
  • qemu from HEAD (slightly ahead of v6.0.0)
  • kernel built exactly like the one in docker image (although built with gcc-6, and I don't know what the Docker image builds it with)

I ran

  • without -enable-kvm or -m 1G or any of the things I usually locally add that don't work on circleci.

and I can't repro the issue locally yet. I'll switch to sshing into circleci and checking that out. Maybe it just runs out of memory or nearly runs out of memory and spends a lot of time swapping around.

@hugelgupf
Copy link
Member

Something peculiar about running the test locally, however, is that it takes 8 seconds to run, and that time is not attributed to any individual test:

    integration.go:146: 2021/07/28 18:04:41 serial: === RUN   TestOpenSignedFile~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/signed_file~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/signed_file_w/_two_signatures_(key1_ring)~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/signed_file_w/_two_signatures_(key2_ring)~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/nil_keyring~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/non-nil_empty_keyring~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/signed_file_does_not_match_keyring~
    integration.go:146: 2021/07/28 18:04:49 serial: === RUN   TestOpenSignedFile/unsigned_file~
    integration.go:146: 2021/07/28 18:04:50 serial: === RUN   TestOpenSignedFile/file_does_not_exist~
    integration.go:146: 2021/07/28 18:04:50 serial: --- PASS: TestOpenSignedFile (8.10s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/signed_file (0.03s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/signed_file_w/_two_signatures_(key1_ring) (0.01s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/signed_file_w/_two_signatures_(key2_ring) (0.00s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/nil_keyring (0.03s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/non-nil_empty_keyring (0.00s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/signed_file_does_not_match_keyring (0.00s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/unsigned_file (0.00s)~
    integration.go:146: 2021/07/28 18:04:50 serial:     --- PASS: TestOpenSignedFile/file_does_not_exist (0.00s)~

On circleci, a timeout after 25 seconds is the issue.

@hugelgupf
Copy link
Member

I think it's quite possible that QEMU emulation is just 3x slower on circleci, and that causes the timeout to happen. However, even on Go 1.13, the test takes 8-12 seconds to run. (But let me make sure that it actually uses Go 1.13 to compile the tests -- checking that out.)

@hugelgupf
Copy link
Member

I think it's quite possible that QEMU emulation is just 3x slower on circleci, and that causes the timeout to happen. However, even on Go 1.13, the test takes 8-12 seconds to run. (But let me make sure that it actually uses Go 1.13 to compile the tests -- checking that out.)

Of course it doesn't, that part is here:

cmd := exec.Command("go", "test",

I'll fix that to look for the compiler in GOROOT/bin/go.

@codecov
Copy link

codecov bot commented Jul 29, 2021

Codecov Report

Merging #2041 (d8f0bd8) into master (287af15) will increase coverage by 0.01%.
The diff coverage is 0.00%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #2041      +/-   ##
==========================================
+ Coverage   54.70%   54.72%   +0.01%     
==========================================
  Files         570      570              
  Lines       49704    49695       -9     
==========================================
+ Hits        27191    27196       +5     
+ Misses      21420    21406      -14     
  Partials     1093     1093              
Impacted Files Coverage Δ
pkg/qemu/devices.go 26.82% <0.00%> (ø)
pkg/strace/tracer.go 58.87% <0.00%> (+2.33%) ⬆️
pkg/namespace/syzcall_string.go 52.94% <0.00%> (+18.32%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 287af15...d8f0bd8. Read the comment docs.

@hugelgupf
Copy link
Member

Posted #2076 for that, but it actually didn't change anything.

Go 1.15.14 (+ qemu-v6 + kernel-v4.17 + no KVM) with only pkg/{vfile,uzip}:

--- PASS: TestOpenSignedFile (10.18s)~

Go 1.13 (+ all the same):

 --- PASS: TestOpenSignedFile (14.05s)

If anything, the runtime got better...

@rjoleary
Copy link
Contributor Author

Ron wrote us a time command. I'm going to ssh into circleci to see if most the time is sys time or user time.

If it's mostly user time, then it's probably just slow. If it's most sys time, then it's probably blocked on something.

@rjoleary
Copy link
Contributor Author

Looks like it's just slow:

    integration.go:146: 2021/07/29 22:45:35 serial: real 32.925~
    integration.go:146: 2021/07/29 22:45:35 serial: user 32.645~
    integration.go:146: 2021/07/29 22:45:35 serial: sys 0.104~

@rjoleary
Copy link
Contributor Author

I increased the timeout to 100s and ran it a few times:

    integration.go:146: 2021/07/29 22:46:49 serial: real 30.957~
    integration.go:146: 2021/07/29 22:46:49 serial: user 30.740~
    integration.go:146: 2021/07/29 22:46:49 serial: sys 0.100~
    integration.go:146: 2021/07/29 22:47:18 serial: real 14.848~
    integration.go:146: 2021/07/29 22:47:18 serial: user 14.665~
    integration.go:146: 2021/07/29 22:47:18 serial: sys 0.084~
    integration.go:146: 2021/07/29 22:48:05 serial: real 33.682~
    integration.go:146: 2021/07/29 22:48:05 serial: user 33.508~
    integration.go:146: 2021/07/29 22:48:05 serial: sys 0.076~
    integration.go:146: 2021/07/29 22:48:57 serial: real 36.836~
    integration.go:146: 2021/07/29 22:48:57 serial: user 36.629~
    integration.go:146: 2021/07/29 22:48:57 serial: sys 0.100~
    integration.go:146: 2021/07/29 22:49:58 serial: real 46.793~
    integration.go:146: 2021/07/29 22:49:58 serial: user 46.520~
    integration.go:146: 2021/07/29 22:49:58 serial: sys 0.112~
    integration.go:146: 2021/07/29 22:50:54 serial: real 41.832~
    integration.go:146: 2021/07/29 22:50:54 serial: user 41.653~
    integration.go:146: 2021/07/29 22:50:54 serial: sys 0.080~
    integration.go:146: 2021/07/29 22:51:45 serial: real 35.567~
    integration.go:146: 2021/07/29 22:51:45 serial: user 35.374~
    integration.go:146: 2021/07/29 22:51:45 serial: sys 0.080~

I wonder why is fluctuates so much? Sometimes it is less than 25s, sometimes 10s of seconds more.

@rjoleary
Copy link
Contributor Author

rjoleary commented Jul 30, 2021

Any ideas besides these two options?

  • Generate the entity once and load it from a file on all subsequent tests.
  • Disable this test from running inside qemu.

The big change is the switch to Go 1.15 and QEMU 6.0.0. This change
fixes issues arising from this migration.

This change also improves the logging of the gotest vmtest to help debug
issues with this migration.

Signed-off-by: Ryan O'Leary <ryanoleary@google.com>
@rjoleary
Copy link
Contributor Author

Any ideas besides these two options?

  • Generate the entity once and load it from a file on all subsequent tests.
  • Disable this test from running inside qemu.

I went with the first option.

@rjoleary rjoleary added Awaiting reviewer Waiting for a reviewer. and removed Awaiting author Waiting for new changes or feedback for author. labels Jul 30, 2021
@rminnich rminnich added automerge Applying this label auto-merges the PR when ready Awaiting author Waiting for new changes or feedback for author. and removed Awaiting reviewer Waiting for a reviewer. labels Jul 30, 2021
@rminnich rminnich merged commit add088c into u-root:master Jul 30, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
automerge Applying this label auto-merges the PR when ready Awaiting author Waiting for new changes or feedback for author.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants