github.com/openshift/origin/pkg/cmd/server/admin times out generating server certificate

[dcbw]

https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin/8658/console

ok github.com/openshift/origin/pkg/cmd/cli/describe 1.765s coverage: 59.4% of statements
ok github.com/openshift/origin/pkg/cmd/cli/secrets 0.261s coverage: 19.8% of statements
ok github.com/openshift/origin/pkg/cmd/flagtypes 0.061s coverage: 58.9% of statements
ok github.com/openshift/origin/pkg/cmd/infra/deployer 0.228s coverage: 51.5% of statements
ok github.com/openshift/origin/pkg/cmd/openshift 0.569s coverage: 65.5% of statements
ok github.com/openshift/origin/pkg/cmd/recycle 0.141s coverage: 69.6% of statements
panic: test timed out after 1m0s

goroutine 43 [running]:
testing.func·008()
/usr/lib/golang/src/testing/testing.go:681 +0x168
created by time.goFunc
/usr/lib/golang/src/time/sleep.go:129 +0x59

goroutine 1 [chan receive]:
testing.RunTests(0x19b2d60, 0x204b260, 0x2, 0x2, 0xc208059e01)
/usr/lib/golang/src/testing/testing.go:556 +0xdc3
testing.(*M).Run(0xc208179720, 0x2a015e0)
/usr/lib/golang/src/testing/testing.go:485 +0xe1
main.main()
github.com/openshift/origin/pkg/cmd/server/admin/_test/_testmain.go:126 +0x382

goroutine 9 [syscall, 1 minutes]:
os/signal.loop()
/usr/lib/golang/src/os/signal/signal_unix.go:21 +0x2d
created by os/signal.init·1
/usr/lib/golang/src/os/signal/signal_unix.go:27 +0x43

goroutine 42 [runnable]:
math/big.nat.norm(0xc2084c5400, 0x11, 0x25, 0xc20818b0e0, 0x21, 0x24)
/usr/lib/golang/src/math/big/nat.go:61
math/big.nat.divLarge(0xc2084c5400, 0x10, 0x25, 0xc20818b0e0, 0x21, 0x24, 0xc20818afc0, 0x20, 0x24, 0xc2082ee000, ...)
/usr/lib/golang/src/math/big/nat.go:594 +0xfa0
math/big.nat.div(0xc2084c5400, 0x10, 0x25, 0xc20818b0e0, 0x20, 0x24, 0xc20818afc0, 0x20, 0x24, 0xc2082ee000, ...)
/usr/lib/golang/src/math/big/nat.go:519 +0x3cc
math/big.nat.expNNWindowed(0xc20818afc0, 0x20, 0x24, 0xc2082ef4a0, 0x10, 0x14, 0xc2082ef040, 0x10, 0x14, 0xc2082ee000, ...)
/usr/lib/golang/src/math/big/nat.go:1372 +0xa3a
math/big.nat.expNN(0xc2082ef540, 0x10, 0x14, 0xc2082ef4a0, 0x10, 0x14, 0xc2082ef040, 0x10, 0x14, 0xc2082ee000, ...)
/usr/lib/golang/src/math/big/nat.go:1260 +0x4f1
math/big.nat.probablyPrime(0xc2082ee000, 0x10, 0x14, 0x14, 0x14)
/usr/lib/golang/src/math/big/nat.go:1445 +0x9d4
math/big.(_Int).ProbablyPrime(0xc208284000, 0x14, 0xc208284020)
/usr/lib/golang/src/math/big/int.go:741 +0x7c
crypto/rand.Prime(0x7fb0417e1678, 0xc20803cd20, 0x400, 0xc208284000, 0x0, 0x0)
/usr/lib/golang/src/crypto/rand/util.go:99 +0x654
crypto/rsa.GenerateMultiPrimeKey(0x7fb0417e1678, 0xc20803cd20, 0x2, 0x800, 0xc20837aea0, 0x0, 0x0)
/usr/lib/golang/src/crypto/rsa/rsa.go:187 +0x2c9
crypto/rsa.GenerateKey(0x7fb0417e1678, 0xc20803cd20, 0x800, 0xc2081d4e20, 0x0, 0x0)
/usr/lib/golang/src/crypto/rsa/rsa.go:145 +0x65
github.com/openshift/origin/pkg/cmd/server/crypto.NewKeyPair(0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/data/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/cmd/server/crypto/crypto.go:338 +0xa6
github.com/openshift/origin/pkg/cmd/server/crypto.(_CA).MakeServerCert(0xc208174e70, 0xc2083def60, 0x29, 0xc2083defc0, 0x29, 0xc2081f56b0, 0x7fb0417f3100, 0x0, 0x0)
/data/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/cmd/server/crypto/crypto.go:251 +0x22d
github.com/openshift/origin/pkg/cmd/server/crypto.(_CA).EnsureServerCert(0xc208174e70, 0xc2083def60, 0x29, 0xc2083defc0, 0x29, 0xc2081f56b0, 0x46d08c, 0x4ad4a0, 0x0, 0x0)
/data/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/cmd/server/crypto/crypto.go:223 +0xe5
github.com/openshift/origin/pkg/cmd/server/admin.CreateServerCertOptions.CreateServerCert(0xc2083db0c0, 0xc2083def60, 0x29, 0xc2083defc0, 0x29, 0xc2081d58b0, 0x1, 0x1, 0x0, 0x7fb0417e0400, ...)
github.com/openshift/origin/pkg/cmd/server/admin/_test/_obj_test/create_servercert.go:143 +0x756
github.com/openshift/origin/pkg/cmd/server/admin.CreateNodeConfigOptions.MakeServerCert(0xc2083db0c0, 0xc2083de99b, 0x1e, 0x1665457, 0x7, 0xc2081d58b0, 0x1, 0x1, 0x1711730, 0x17, ...)
github.com/openshift/origin/pkg/cmd/server/admin/_test/_obj_test/create_nodeconfig.go:386 +0x235
github.com/openshift/origin/pkg/cmd/server/admin.CreateNodeConfigOptions.CreateNodeFolder(0xc2083db0c0, 0xc2083de99b, 0x1e, 0x1665457, 0x7, 0xc2081d58b0, 0x1, 0x1, 0x1711730, 0x17, ...)
github.com/openshift/origin/pkg/cmd/server/admin/_test/_obj_test/create_nodeconfig.go:285 +0x62a
github.com/openshift/origin/pkg/cmd/server/admin.func·014(0xc20817e200, 0xc20846d3b0, 0x0, 0x9)
github.com/openshift/origin/pkg/cmd/server/admin/_test/_obj_test/create_nodeconfig.go:73 +0x221
github.com/spf13/cobra.(_Command).execute(0xc20817e200, 0xc20846d200, 0x9, 0x9, 0x0, 0x0)
/data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/spf13/cobra/command.go:572 +0xb41
github.com/spf13/cobra.(_Command).ExecuteC(0xc20817e000, 0xc20817e200, 0x0, 0x0)
/data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/spf13/cobra/command.go:662 +0x635
github.com/spf13/cobra.(_Command).Execute(0xc20817e000, 0x0, 0x0)
/data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/spf13/cobra/command.go:618 +0x48
github.com/openshift/origin/pkg/cmd/server/admin.executeNodeConfig(0xc2084cfe58, 0x8, 0x8, 0x0, 0x0)
/data/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/cmd/server/admin/create_nodeconfig_test.go:107 +0x721
github.com/openshift/origin/pkg/cmd/server/admin.TestNodeConfigTLS(0xc20842bcb0)
/data/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/cmd/server/admin/create_nodeconfig_test.go:45 +0x402
testing.tRunner(0xc20842bcb0, 0x204b278)
/usr/lib/golang/src/testing/testing.go:447 +0x134
created by testing.RunTests
/usr/lib/golang/src/testing/testing.go:555 +0xd4e

goroutine 25 [chan receive]:
github.com/golang/glog.(*loggingT).flushDaemon(0x29f5700)
/data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/golang/glog/glog.go:879 +0x99
created by github.com/golang/glog.init·1
/data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/golang/glog/glog.go:410 +0x2ca

goroutine 33 [syscall, 1 minutes, locked to thread]:
runtime.goexit()
/usr/lib/golang/src/runtime/asm_amd64.s:2232 +0x1
FAIL github.com/openshift/origin/pkg/cmd/server/admin 60.391s
ok github.com/openshift/origin/pkg/cmd/server/api 0.217s coverage: 15.6% of statements
ok github.com/openshift/origin/pkg/cmd/server/api/v1 0.284s coverage: 20.3% of statements

[liggitt]

Appears to be the race detection (https://golang.org/doc/articles/race_detector.html - "The cost of race detection varies by program, but for a typical program, memory usage may increase by 5-10x and execution time by 2-20x.")

With KUBE_RACE="":
4 seconds locally (wall clock time 10 seconds)
4 seconds in a m4.large devenv (wall clock time 30 seconds)

With KUBE_RACE="-race":
9 seconds locally (wall clock time 25 seconds)
18 seconds in a m4.large devenv (wall clock time 52 seconds)

[liggitt]

Other tests are struggling as well:

FAIL github.com/openshift/origin/pkg/generate/app/cmd 60.212s

[liggitt]

Maybe not race detection... the recorded time appears to be what is subject to the timeout, and 18 seconds is a long way from 60... there's nothing in the admin package test that makes network calls. It's doing key generation, which is likely CPU bound, but still... @danmcp, are you running anything in parallel with the unit tests that could be consuming lots of CPU on the devenvs?

[liggitt]

Hmm... looking at test runs that passed, that package is taking 30-45 seconds. Not sure how I'm seeing 18 second times on an identical machine

[danmcp]

@liggitt It's just running make test with options:

https://github.com/openshift/vagrant-openshift/blob/master/lib/vagrant-openshift/action/run_origin_tests.rb

[liggitt]

dupe of #6384